search

mikebrady / shairport-sync

AirPlay and AirPlay 2 audio player
Other
7.29k stars 574 forks source link

Shairport-sync crash after an I2S SYNC error! #577

Closed SynthexGit closed 5 years ago

SynthexGit commented 7 years ago

Hello,

Thank you for this awesome software !

Sometimes I have this error : kernel: bcm2835-i2s 20203000.i2s: I2S SYNC error! and no more sound goes out of the DAC card !

The only way to have sound is to restart the program : sudo systemctl restart shairport-sync

My hardware : Raspberry Pi Zero W ES9023 I2S DAC Raspbian Jessie Lite 4.9.43+ Shairport-sync 3.1.1

Thank you !

mikebrady commented 7 years ago

Thanks for the kind words.

I'm afraid I don't have any leads on this. The only thing I can suggest is to increase the verbosity of logging on Shairport Sync -- set the general log_verbosity to 1. There might be some kind of association between messages from Shairport Sync and this error.

It seems as if the error causes Shairport Sync to terminate, hence the need to restart it.

Maybe some other users have more information...

SynthexGit commented 7 years ago

Hello, Thank you for your reply !

Here are logs that appear at the same time as the loss of sound : shairport-sync[368]: Error -32 in delay(): "Broken pipe". Delay reported is 0 frames. shairport-sync[368]: Buffers exhausted.

mikebrady commented 7 years ago

Thanks. Unfortunately, it's not clear whether that precedes or follows the error message. For example, here is output from a Pi 3 using an IQaudIO DAC/Amp, also an I2S device:

Aug 17 14:46:52 kitchen shairport-sync[15535]: Output frame bytes is 8.
Aug 17 14:46:52 kitchen shairport-sync[15535]: Output bit depth is 32.
Aug 17 14:46:52 kitchen shairport-sync[15535]: sync error in milliseconds, net correction in ppm, corrections in ppm, total packets, missing packets, late packets, too late packets, resend Aug 17 14:46:53 kitchen shairport-sync[15535]: Apple ALAC Decoder used on encrypted audio.
Aug 17 14:46:53 kitchen kernel: pcm512x 1-004c: No SCLK, using BCLK: -2
Aug 17 15:04:25 kitchen shairport-sync[15535]: RTSP shutdown requested.
Aug 17 15:04:25 kitchen shairport-sync[15535]: Closing down RTSP conversation thread...
Aug 17 15:04:25 kitchen shairport-sync[15535]: Playback Stopped. Total playing time 00:17:33.
Aug 17 15:04:26 kitchen shairport-sync[15535]: Shut down audio, control and timing threads
Aug 17 15:04:26 kitchen shairport-sync[15535]: Control RTP thread interrupted. terminating.
Aug 17 15:04:26 kitchen shairport-sync[15535]: Audio receiver -- Server RTP thread interrupted. terminating.
Aug 17 15:04:26 kitchen shairport-sync[15535]: Timing thread interrupted. terminating.
Aug 17 15:04:26 kitchen shairport-sync[15535]: Wait for timer requester to exit.
Aug 17 15:04:26 kitchen shairport-sync[15535]: rtp_timing_sender thread interrupted. terminating.
Aug 17 15:04:26 kitchen shairport-sync[15535]: Closed and terminated timer requester thread.
Aug 17 15:04:26 kitchen shairport-sync[15535]: Timing RTP thread terminated.
Aug 17 15:04:26 kitchen shairport-sync[15535]: timing thread joined
Aug 17 15:04:26 kitchen shairport-sync[15535]: audio thread joined
Aug 17 15:04:26 kitchen shairport-sync[15535]: control thread joined
Aug 17 15:04:26 kitchen shairport-sync[15535]: Player thread exit
Aug 17 15:04:28 kitchen shairport-sync[15535]: found a non-running thread
Aug 17 15:04:28 kitchen shairport-sync[15535]: one thread joined...

You can see that it gives timing and sequencing information. Notice that there is what appears to be a problem on the fourth line, but it seems merely to be a diagnostic.

SynthexGit commented 7 years ago

Hello,

Here are the logs of the last crash, the music stops at 20:48 : 

Aug 22 20:30:16 PiZeroW shairport-sync[375]: Buffers exhausted.
Aug 22 20:30:17 PiZeroW shairport-sync[375]: Buffers exhausted.
Aug 22 20:30:17 PiZeroW kernel: NET: Registered protocol family 38
Aug 22 20:30:40 PiZeroW shairport-sync[375]: Buffers exhausted.
Aug 22 20:30:42 PiZeroW shairport-sync[375]: Error -32 writing 352 samples in play(): "Broken pipe".
Aug 22 20:30:42 PiZeroW shairport-sync[375]: Buffers exhausted.
Aug 22 20:30:42 PiZeroW shairport-sync[375]: Buffers exhausted.
Aug 22 20:30:42 PiZeroW shairport-sync[375]: Buffers exhausted.
Aug 22 20:30:42 PiZeroW shairport-sync[375]: Buffers exhausted.
Aug 22 20:31:49 PiZeroW shairport-sync[375]: Buffers exhausted.
Aug 22 20:31:50 PiZeroW shairport-sync[375]: Buffers exhausted.
Aug 22 20:31:50 PiZeroW shairport-sync[375]: Buffers exhausted.
Aug 22 20:32:49 PiZeroW shairport-sync[375]: Buffers exhausted.
Aug 22 20:32:56 PiZeroW shairport-sync[375]: Error -32 in delay(): "Broken pipe". Delay reported is 0 frames.
Aug 22 20:38:06 PiZeroW systemd[1]: Starting Cleanup of Temporary Directories...
Aug 22 20:38:06 PiZeroW systemd[1]: Started Cleanup of Temporary Directories.
Aug 22 20:40:48 PiZeroW shairport-sync[375]: Error -32 in delay(): "Broken pipe". Delay reported is 0 frames.
Aug 22 20:48:30 PiZeroW shairport-sync[375]: Error -32 in delay(): "Broken pipe". Delay reported is 0 frames.

The service is not finished but seems to be in stand by ... The CPU load drops from 13% to 6% for the process shairport-sync ...

Thank you !!

mikebrady commented 7 years ago

Thanks. Looking at this, it seems that the problem may not be a a crash, but that the music isn't reaching your Pi Zero. The "Buffers exhausted" message means that there are no more packets of audio to send to the DAC. This is usually due to a network problem. One possibility is that WiFi power management is "on" – it should be off. There could be other issues – please see TROUBLESHOOTING.md.

SynthexGit commented 7 years ago

Thank you for your time.

Since the last time, I reinstalled the system with the new Raspbian Stretch 4.9.45+ I removed the DAC card, to replace it with an FDA amplifier (SMSL AD 18) that I plug directly into USB with the Raspberry Pi Zero W !

I have run the sound continuously for more than 48 hours .... No more problems and an unbelievable sound !!!

mikebrady commented 7 years ago

That's great that it worked out for you.

SynthexGit commented 7 years ago

For information, I just have a crash ... about 2 minutes without sound ...

Aug 26 18:47:48 PiZeroW kernel: Unable to handle kernel paging request at virtual address 00052b88
Aug 26 18:47:48 PiZeroW kernel: pgd = d44c0000
Aug 26 18:47:48 PiZeroW kernel: [00052b88] *pgd=1525f831, *pte=00000000, *ppte=00000000
Aug 26 18:47:48 PiZeroW kernel: Internal error: Oops: 17 [#1] ARM
Aug 26 18:47:48 PiZeroW kernel: Modules linked in: ecb algif_skcipher af_alg fuse rfcomm cmac bnep hci_uart btbcm bluetooth snd_usb_audio snd_hwdep snd_usbmidi_lib snd_rawmidi snd_seq_device snd_pcm snd_timer snd brcmfmac brcmutil cfg80211 rfkill bcm2835_gpiomem uio_pdrv_genirq uio fixed i2c_dev ip_tables x_tables ipv6
Aug 26 18:47:48 PiZeroW kernel: CPU: 0 PID: 700 Comm: shairport-sync Not tainted 4.9.44+ #1029
Aug 26 18:47:48 PiZeroW kernel: Hardware name: BCM2835
Aug 26 18:47:48 PiZeroW kernel: task: d47851c0 task.stack: d46ea000
Aug 26 18:47:48 PiZeroW kernel: PC is at skb_release_head_state+0x44/0x124
Aug 26 18:47:48 PiZeroW kernel: LR is at skb_release_all+0x1c/0x34
Aug 26 18:47:48 PiZeroW kernel: pc : [<c04d72c8>]    lr : [<c04d7568>]    psr: 20000013
                                sp : d46ebda8  ip : d46ebdc0  fp : d46ebdbc
Aug 26 18:47:48 PiZeroW kernel: r10: 00000000  r9 : 00000800  r8 : d46ebeb8
Aug 26 18:47:48 PiZeroW kernel: r7 : 00000000  r6 : 00000000  r5 : d71f7080  r4 : d68da240
Aug 26 18:47:48 PiZeroW kernel: r3 : c08a9760  r2 : 00000000  r1 : 00000001  r0 : 00052b88
Aug 26 18:47:48 PiZeroW kernel: Flags: nzCv  IRQs on  FIQs on  Mode SVC_32  ISA ARM  Segment user
Aug 26 18:47:48 PiZeroW kernel: Control: 00c5387d  Table: 144c0008  DAC: 00000055
Aug 26 18:47:48 PiZeroW kernel: Process shairport-sync (pid: 700, stack limit = 0xd46ea188)
Aug 26 18:47:48 PiZeroW kernel: Stack: (0xd46ebda8 to 0xd46ec000)
Aug 26 18:47:48 PiZeroW kernel: bda0:                   c08a9760 d68da240 d46ebdd4 d46ebdc0 c04d7568 c04d7290
Aug 26 18:47:48 PiZeroW kernel: bdc0: c08a9760 d68da240 d46ebdec d46ebdd8 c04d759c c04d7558 c08a9760 d68da240
Aug 26 18:47:48 PiZeroW kernel: bde0: d46ebe0c d46ebdf0 c04dea54 c04d758c d68da240 00000000 d71f7080 00000327
Aug 26 18:47:48 PiZeroW kernel: be00: d46ebe64 d46ebe10 c055a81c c04de9bc d46ebe34 00000001 00000000 00000000
Aug 26 18:47:48 PiZeroW kernel: be20: 00000327 00000000 c0047dbc 00000000 00000000 fffffff2 c004f6e8 d46ebeb8
Aug 26 18:47:48 PiZeroW kernel: be40: 00000000 00000000 00000000 00000000 d46ea000 00000000 d46ebe8c d46ebe68
Aug 26 18:47:48 PiZeroW kernel: be60: c0564fc0 c055a3b4 00000000 d46ebe74 c0161df0 00000000 00000000 d3d59580
Aug 26 18:47:48 PiZeroW kernel: be80: d46ebe9c d46ebe90 c04ce2a4 c0564f84 d46ebf8c d46ebea0 c04d0a18 c04ce288
Aug 26 18:47:48 PiZeroW kernel: bea0: d46ebec0 c08b37a8 fffffff7 00000001 b48fe4e8 00000800 00000000 00000000
Aug 26 18:47:48 PiZeroW kernel: bec0: 00000000 00000000 00000800 d46ebeb0 00000001 d44b9b40 00000000 00000000
Aug 26 18:47:48 PiZeroW kernel: bee0: d46ebf24 00000000 c0045fc8 c00bf220 d47851c0 d51681a0 00000000 c08b3778
Aug 26 18:47:48 PiZeroW kernel: bf00: d46ebf24 d47851c0 00000000 d51681a0 00001661 c08b3778 d46ebf74 d46ebf28
Aug 26 18:47:48 PiZeroW kernel: bf20: c05d1cb0 c0045f78 0025174e 0000000a 032cb64f 00000000 00000000 00000000
Aug 26 18:47:48 PiZeroW kernel: bf40: 00000001 d701e000 00000002 d46ea000 d46ea000 00000000 d46ebfb0 00000000
Aug 26 18:47:48 PiZeroW kernel: bf60: d46ea000 00000000 d46ebf8c f9f804fc 0000601f 0000032f 00000123 c000ffc4
Aug 26 18:47:48 PiZeroW kernel: bf80: d46ebfa4 d46ebf90 c04d0a9c c04d097c 00000000 00000000 00000000 d46ebfa8
Aug 26 18:47:48 PiZeroW kernel: bfa0: c000fe40 c04d0a80 f9f804fc 0000601f 00000009 b48fe4e8 00000800 00000000
Aug 26 18:47:48 PiZeroW kernel: bfc0: f9f804fc 0000601f 0000032f 00000123 f9f804fc 0000601f 006e7648 006e3648
Aug 26 18:47:48 PiZeroW kernel: bfe0: 00000000 b48fe4c8 00000000 b6af0804 80000010 00000009 17ffa861 17ffac61
Aug 26 18:47:49 PiZeroW kernel: [<c04d72c8>] (skb_release_head_state) from [<c04d7568>] (skb_release_all+0x1c/0x34)
Aug 26 18:47:49 PiZeroW kernel: [<c04d7568>] (skb_release_all) from [<c04d759c>] (__kfree_skb+0x1c/0x28)
Aug 26 18:47:49 PiZeroW kernel: [<c04d759c>] (__kfree_skb) from [<c04dea54>] (__skb_free_datagram_locked+0xa4/0x114)
Aug 26 18:47:49 PiZeroW kernel: [<c04dea54>] (__skb_free_datagram_locked) from [<c055a81c>] (udp_recvmsg+0x474/0x598)
Aug 26 18:47:49 PiZeroW kernel: [<c055a81c>] (udp_recvmsg) from [<c0564fc0>] (inet_recvmsg+0x48/0x5c)
Aug 26 18:47:49 PiZeroW kernel: [<c0564fc0>] (inet_recvmsg) from [<c04ce2a4>] (sock_recvmsg+0x28/0x2c)
Aug 26 18:47:49 PiZeroW kernel: [<c04ce2a4>] (sock_recvmsg) from [<c04d0a18>] (SyS_recvfrom+0xa8/0x104)
Aug 26 18:47:49 PiZeroW kernel: [<c04d0a18>] (SyS_recvfrom) from [<c04d0a9c>] (SyS_recv+0x28/0x30)
Aug 26 18:47:49 PiZeroW kernel: [<c04d0a9c>] (SyS_recv) from [<c000fe40>] (ret_fast_syscall+0x0/0x1c)
Aug 26 18:47:49 PiZeroW kernel: Code: e5940050 e3500000 0a000007 f5d0f000 (e1902f9f) 
Aug 26 18:47:49 PiZeroW kernel: ---[ end trace 395e1c7916fc6d72 ]---
Aug 26 18:47:50 PiZeroW shairport-sync[330]: Buffers exhausted.
Aug 26 18:49:48 PiZeroW shairport-sync[330]: As Yeats almost said, "Too long a silence / can make a stone of the heart"
Aug 26 18:49:48 PiZeroW shairport-sync[330]: Request to shut down all rtsp conversation threads
Aug 26 18:49:48 PiZeroW shairport-sync[330]: asking playing threads to stop
Aug 26 18:49:48 PiZeroW shairport-sync[330]: RTSP shutdown requested.
Aug 26 18:49:48 PiZeroW shairport-sync[330]: Closing down RTSP conversation thread...
Aug 26 18:49:49 PiZeroW shairport-sync[330]: Shut down audio, control and timing threads
Aug 26 18:49:49 PiZeroW shairport-sync[330]: Control RTP thread interrupted. terminating.
Aug 26 18:49:49 PiZeroW shairport-sync[330]: Timing thread interrupted. terminating.
Aug 26 18:49:49 PiZeroW shairport-sync[330]: Wait for timer requester to exit.
Aug 26 18:49:49 PiZeroW shairport-sync[330]: rtp_timing_sender thread interrupted. terminating.
Aug 26 18:49:49 PiZeroW shairport-sync[330]: Closed and terminated timer requester thread.
Aug 26 18:49:49 PiZeroW shairport-sync[330]: Timing RTP thread terminated.
Aug 26 18:49:49 PiZeroW shairport-sync[330]: timing thread joined
Aug 26 18:49:49 PiZeroW shairport-sync[330]: audio thread joined
Aug 26 18:49:49 PiZeroW shairport-sync[330]: control thread joined
Aug 26 18:49:49 PiZeroW shairport-sync[330]: Player thread exit
Aug 26 18:50:03 PiZeroW shairport-sync[330]: found a non-running thread
Aug 26 18:50:03 PiZeroW shairport-sync[330]: one thread joined...
Aug 26 18:50:03 PiZeroW shairport-sync[330]: New RTSP connection from 192.168.1.158:56951 to self at 192.168.1.104:5000.
Aug 26 18:50:03 PiZeroW shairport-sync[330]: Play connection from user agent "iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4".
Aug 26 18:50:03 PiZeroW shairport-sync[330]: Set up play connection from 192.168.1.158 to self at 192.168.1.104.
Aug 26 18:50:03 PiZeroW shairport-sync[330]: Output frame bytes is 4.
Aug 26 18:50:03 PiZeroW shairport-sync[330]: Output bit depth is 16.
Aug 26 18:50:04 PiZeroW shairport-sync[330]: Hammerton Decoder used on encrypted audio.
mikebrady commented 7 years ago

Thanks. If you can get it to happen reliably, it would be great!

mikebrady commented 7 years ago

Just wondering if that crash has recurred?

mikebrady commented 5 years ago

Pretty sure some of this has been addressed in more recent versions of Shairport Sync; is an I2S DAC stops responding, Shairport Sync can call a script which could, in principle, restart the device, as that is the only thing that seems to fix these I2S freezes. Closing this inactive issue. Please open a new one if necessary.