search

mikebrady / shairport-sync

AirPlay and AirPlay 2 audio player
Other
7.2k stars 571 forks source link

shairport-sync (dev) stops when client comes back after network failure #1398

Closed th0u closed 2 years ago

th0u commented 2 years ago

Hello, I run this version of shairport-sync 4.1-dev-147-g636ccf98-alac-OpenSSL-Avahi-ALSA-soxr-metadata-sysconfdir:/etc on an Raspberry Pi 3B Linux raspberry 5.10.63-v7+ #1488 SMP Thu Nov 18 16:14:44 GMT 2021 armv7l GNU/Linux

The raspi is connected via LAN only to my network. The Client ist a MBP2020 macOS 12.1 connected via WIFI to my Network. It runs Apple Music App. The playing content is located in iCloud Music.

I can reproduce that shairport-sync stops on this conditions:

  1. Connect MBP via WIFI only to local Network
  2. Start Music App.
  3. Select Shairport Sync as Airplay Target in Music App
  4. Use Music app to play content to Shaiport sync
  5. Listen a while to the played content. 30sec or so.
  6. Switch off WIFI AT the wifi router. Not on MBP).
  7. Wait about a minute and turn WIFI on at the Router. Wait until MBP reconnects to WIFI.
  8. There is now an "!" in Airplay Icon on Music App. Click on it and unselect "Shaiport Sync".
  9. Check process list on shairport-sync host. It is not running any more.

Times of events: 14:46:12+: Playing music via WIFI (actually startet much earlier) 14:46.50: Send Command to Router to turn off WIFI (gathered from router log) 14:47:25: Send command to Router to turn on WIFI (gathered from router log) 14:47:51: last log entry from shairport sync. No running shairport-sync process.

Shairport-log

The shairport-sync logs do not show any crash (log level 3)

Jan  2 14:46:12 traspberry shairport-sync:          0.727276406 "rtp.c:680" clock synchronisation request: return time is    3.867 milliseconds.
Jan  2 14:46:12 traspberry shairport-sync:          0.000156771 "rtp.c:863" not enough samples to estimate drift -- remaining at 0.00 ppm.
Jan  2 14:46:15 traspberry shairport-sync:          3.000785936 "rtp.c:680" clock synchronisation request: return time is    4.579 milliseconds.
Jan  2 14:46:15 traspberry shairport-sync:          0.000152761 "rtp.c:863" not enough samples to estimate drift -- remaining at 0.00 ppm.
Jan  2 14:46:18 traspberry shairport-sync:          2.999594217 "rtp.c:680" clock synchronisation request: return time is    4.091 milliseconds.
Jan  2 14:46:18 traspberry shairport-sync:          0.000153490 "rtp.c:863" not enough samples to estimate drift -- remaining at 0.00 ppm.
Jan  2 14:46:20 traspberry shairport-sync:          1.192874531 "rtsp.c:785" msg_init message 19
Jan  2 14:46:20 traspberry shairport-sync:          0.000125469 "rtsp.c:890" RTSP Message Received: "OPTIONS * RTSP/1.0".
Jan  2 14:46:20 traspberry shairport-sync:          0.000060104 "rtsp.c:921"     CSeq: 9.
Jan  2 14:46:20 traspberry shairport-sync:          0.000048333 "rtsp.c:921"     User-Agent: Music/1.2.1 (Macintosh; OS X 12.1) AppleWebKit/612.3.6.1.6.
Jan  2 14:46:20 traspberry shairport-sync:          0.000046250 "rtsp.c:921"     Client-Instance: 7195852668DCD350.
Jan  2 14:46:20 traspberry shairport-sync:          0.000068750 "rtsp.c:921"     DACP-ID: 7195852668DCD350.
Jan  2 14:46:20 traspberry shairport-sync:          0.000051823 "rtsp.c:921"     Active-Remote: 2471609022.
Jan  2 14:46:20 traspberry shairport-sync:          0.000076354 "rtsp.c:785" msg_init message 20
Jan  2 14:46:20 traspberry shairport-sync:          0.000051667 "rtsp.c:1053" OPTIONS request
Jan  2 14:46:20 traspberry shairport-sync:          0.000055312 "rtsp.c:1063"   No Content Plist. Content length: 0.
Jan  2 14:46:20 traspberry shairport-sync:          0.000044115 "rtsp.c:2425" Connection 4: OPTIONS
Jan  2 14:46:20 traspberry shairport-sync:          0.000047292 "rtsp.c:4899" Connection 4: RTSP Response:
Jan  2 14:46:20 traspberry shairport-sync:          0.000043125 "rtsp.c:817"   Type: "CSeq", content: "9"
Jan  2 14:46:20 traspberry shairport-sync:          0.000045729 "rtsp.c:817"   Type: "Server", content: "AirTunes/105.1"
Jan  2 14:46:20 traspberry shairport-sync:          0.000061562 "rtsp.c:817"   Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER"
Jan  2 14:46:20 traspberry shairport-sync:          0.000254792 "rtsp.c:866" msg_free freed message 20
Jan  2 14:46:20 traspberry shairport-sync:          0.000058489 "rtsp.c:866" msg_free freed message 19
Jan  2 14:46:21 traspberry shairport-sync:          1.805897604 "rtp.c:680" clock synchronisation request: return time is    3.911 milliseconds.
Jan  2 14:46:21 traspberry shairport-sync:          0.000174844 "rtp.c:863" not enough samples to estimate drift -- remaining at 0.00 ppm.
Jan  2 14:46:22 traspberry shairport-sync:          0.249585572 "player.c:1534" soxr_oneshot execution time in nanoseconds: mean, standard deviation and max for 0 interpolations in the last 1250 packets.   0.000000,   0.000000,   0.000000.
Jan  2 14:46:24 traspberry shairport-sync:          2.750668437 "rtp.c:680" clock synchronisation request: return time is    4.091 milliseconds.
Jan  2 14:46:24 traspberry shairport-sync:          0.000154896 "rtp.c:863" not enough samples to estimate drift -- remaining at 0.00 ppm.
Jan  2 14:46:27 traspberry shairport-sync:          2.999773644 "rtp.c:680" clock synchronisation request: return time is    3.789 milliseconds.
Jan  2 14:46:27 traspberry shairport-sync:          0.000155261 "rtp.c:863" not enough samples to estimate drift -- remaining at 0.00 ppm.
Jan  2 14:46:30 traspberry shairport-sync:          2.241214947 "rtp.c:158" Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7982.5,     2973.5,   108275.9.
Jan  2 14:46:30 traspberry shairport-sync:          0.757349427 "rtp.c:680" clock synchronisation request: return time is    2.274 milliseconds.
Jan  2 14:46:30 traspberry shairport-sync:          0.000156979 "rtp.c:863" not enough samples to estimate drift -- remaining at 0.00 ppm.
Jan  2 14:46:32 traspberry shairport-sync:          1.228719739 "player.c:1534" soxr_oneshot execution time in nanoseconds: mean, standard deviation and max for 17 interpolations in the last 1250 packets.   0.012165,   0.000852,   0.013668.
Jan  2 14:46:33 traspberry shairport-sync:          1.774163906 "rtp.c:680" clock synchronisation request: return time is    5.073 milliseconds.
Jan  2 14:46:34 traspberry shairport-sync:          0.000146979 "rtp.c:863" not enough samples to estimate drift -- remaining at 0.00 ppm.
Jan  2 14:46:36 traspberry shairport-sync:          2.997244113 "rtp.c:680" clock synchronisation request: return time is    2.222 milliseconds.
Jan  2 14:46:36 traspberry shairport-sync:          0.000173334 "rtp.c:863" not enough samples to estimate drift -- remaining at 0.00 ppm.
Jan  2 14:46:39 traspberry shairport-sync:          3.001479530 "rtp.c:680" clock synchronisation request: return time is    3.623 milliseconds.
Jan  2 14:46:39 traspberry shairport-sync:          0.000175208 "rtp.c:863" not enough samples to estimate drift -- remaining at 0.00 ppm.
Jan  2 14:46:42 traspberry shairport-sync:          2.204548228 "player.c:1534" soxr_oneshot execution time in nanoseconds: mean, standard deviation and max for 23 interpolations in the last 1250 packets.   0.012264,   0.000880,   0.013631.
Jan  2 14:46:42 traspberry shairport-sync:          0.794573542 "rtp.c:680" clock synchronisation request: return time is    2.676 milliseconds.
Jan  2 14:46:42 traspberry shairport-sync:          0.000159479 "rtp.c:863" not enough samples to estimate drift -- remaining at 0.00 ppm.
Jan  2 14:46:45 traspberry shairport-sync:          3.003117395 "rtp.c:680" clock synchronisation request: return time is    5.714 milliseconds.
Jan  2 14:46:46 traspberry shairport-sync:          0.000155104 "rtp.c:863" not enough samples to estimate drift -- remaining at 0.00 ppm.
Jan  2 14:46:48 traspberry shairport-sync:          2.998946457 "rtp.c:680" clock synchronisation request: return time is    4.579 milliseconds.
Jan  2 14:46:48 traspberry shairport-sync:          0.000158542 "rtp.c:863" not enough samples to estimate drift -- remaining at 0.00 ppm.
Jan  2 14:46:50 traspberry shairport-sync:          1.106595989 "common.c:1600" mutex_lock "&conns_lock" at "rtsp.c:724".
Jan  2 14:46:50 traspberry shairport-sync:          0.000143906 "common.c:1623" mutex_unlock "&conns_lock" at "rtsp.c:735".
Jan  2 14:46:50 traspberry shairport-sync:          0.080803333 "rtsp.c:785" msg_init message 21
Jan  2 14:46:50 traspberry shairport-sync:          0.000265417 "rtsp.c:890" RTSP Message Received: "OPTIONS * RTSP/1.0".
Jan  2 14:46:50 traspberry shairport-sync:          0.000061667 "rtsp.c:921"     CSeq: 10.
Jan  2 14:46:50 traspberry shairport-sync:          0.000052968 "rtsp.c:921"     User-Agent: Music/1.2.1 (Macintosh; OS X 12.1) AppleWebKit/612.3.6.1.6.
Jan  2 14:46:50 traspberry shairport-sync:          0.000048021 "rtsp.c:921"     Client-Instance: 7195852668DCD350.
Jan  2 14:46:50 traspberry shairport-sync:          0.000046198 "rtsp.c:921"     DACP-ID: 7195852668DCD350.
Jan  2 14:46:50 traspberry shairport-sync:          0.000045677 "rtsp.c:921"     Active-Remote: 2471609022.
Jan  2 14:46:50 traspberry shairport-sync:          0.000050417 "rtsp.c:785" msg_init message 22
Jan  2 14:46:50 traspberry shairport-sync:          0.000069635 "rtsp.c:1053" OPTIONS request
Jan  2 14:46:50 traspberry shairport-sync:          0.000044063 "rtsp.c:1063"   No Content Plist. Content length: 0.
Jan  2 14:46:50 traspberry shairport-sync:          0.000043385 "rtsp.c:2425" Connection 4: OPTIONS
Jan  2 14:46:50 traspberry shairport-sync:          0.000044271 "rtsp.c:4899" Connection 4: RTSP Response:
Jan  2 14:46:50 traspberry shairport-sync:          0.000042969 "rtsp.c:817"   Type: "CSeq", content: "10"
Jan  2 14:46:50 traspberry shairport-sync:          0.000042916 "rtsp.c:817"   Type: "Server", content: "AirTunes/105.1"
Jan  2 14:46:50 traspberry shairport-sync:          0.000042709 "rtsp.c:817"   Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER"
Jan  2 14:46:50 traspberry shairport-sync:          0.000298385 "rtsp.c:866" msg_free freed message 22
Jan  2 14:46:50 traspberry shairport-sync:          0.000096823 "rtsp.c:866" msg_free freed message 21
Jan  2 14:46:50 traspberry shairport-sync:          0.013291458 "rtp.c:158" Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7981.7,     1289.0,    30932.6.
Jan  2 14:46:51 traspberry shairport-sync:          1.797651093 "rtp.c:680" clock synchronisation request: return time is    4.280 milliseconds.
Jan  2 14:46:51 traspberry shairport-sync:          0.000153386 "rtp.c:863" not enough samples to estimate drift -- remaining at 0.00 ppm.
Jan  2 14:46:52 traspberry shairport-sync:          0.194791666 "player.c:1534" soxr_oneshot execution time in nanoseconds: mean, standard deviation and max for 33 interpolations in the last 1250 packets.   0.012328,   0.000815,   0.013756.
Jan  2 14:46:54 traspberry shairport-sync:          2.239724583 "player.c:1294" Buffers exhausted.
Jan  2 14:47:49 traspberry shairport-sync:         55.277182114 "rtp.c:680" clock synchronisation request: return time is  712.350 milliseconds.
Jan  2 14:47:49 traspberry shairport-sync:          0.003185573 "rtp.c:871" Time ping turnaround time: 712350365 ns -- it looks like a timing ping was lost.
Jan  2 14:47:50 traspberry shairport-sync:          0.374817031 "rtsp.c:785" msg_init message 23
Jan  2 14:47:50 traspberry shairport-sync:          0.000201250 "rtsp.c:890" RTSP Message Received: "OPTIONS * RTSP/1.0".
Jan  2 14:47:50 traspberry shairport-sync:          0.000128542 "rtsp.c:921"     CSeq: 11.
Jan  2 14:47:50 traspberry shairport-sync:          0.000122187 "rtsp.c:921"     User-Agent: Music/1.2.1 (Macintosh; OS X 12.1) AppleWebKit/612.3.6.1.6.
Jan  2 14:47:50 traspberry shairport-sync:          0.000118907 "rtsp.c:921"     Client-Instance: 7195852668DCD350.
Jan  2 14:47:50 traspberry shairport-sync:          0.000113541 "rtsp.c:921"     DACP-ID: 7195852668DCD350.
Jan  2 14:47:50 traspberry shairport-sync:          0.000107136 "rtsp.c:921"     Active-Remote: 2471609022.
Jan  2 14:47:50 traspberry shairport-sync:          0.000121719 "rtsp.c:785" msg_init message 24
Jan  2 14:47:50 traspberry shairport-sync:          0.000141770 "rtsp.c:1053" OPTIONS request
Jan  2 14:47:50 traspberry shairport-sync:          0.000112761 "rtsp.c:1063"   No Content Plist. Content length: 237.
Jan  2 14:47:50 traspberry shairport-sync:          0.000105729 "rtsp.c:2425" Connection 4: OPTIONS
Jan  2 14:47:50 traspberry shairport-sync:          0.000103281 "rtsp.c:4899" Connection 4: RTSP Response:
Jan  2 14:47:50 traspberry shairport-sync:          0.000052188 "rtsp.c:817"   Type: "CSeq", content: "11"
Jan  2 14:47:50 traspberry shairport-sync:          0.000097968 "rtsp.c:817"   Type: "Server", content: "AirTunes/105.1"
Jan  2 14:47:50 traspberry shairport-sync:          0.000101094 "rtsp.c:817"   Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER"
Jan  2 14:47:50 traspberry shairport-sync:          0.000437552 "rtsp.c:866" msg_free freed message 24
Jan  2 14:47:50 traspberry shairport-sync:          0.000152657 "rtsp.c:866" msg_free freed message 23
Jan  2 14:47:50 traspberry shairport-sync:          0.000234843 "rtsp.c:1203" Connection 4: -- connection closed.
Jan  2 14:47:50 traspberry shairport-sync:          0.000120990 "rtsp.c:4971" Connection 4: Terminate RTSP connection.
Jan  2 14:47:50 traspberry shairport-sync:          0.000108698 "rtsp.c:4698" Connection 4: rtsp_conversation_thread_func_cleanup_function called.
Jan  2 14:47:50 traspberry shairport-sync:          0.000107083 "rtsp.c:4705" Connection 4 terminating:Closing timing, control and audio sockets...
Jan  2 14:47:50 raspberry shairport-sync:          0.000116875 "rtsp.c:4718" Connection 4 terminating: closing fd 9.
Jan  2 14:47:50 raspberry shairport-sync:          0.000472188 "rtsp.c:4720" Connection 4 terminating: closed fd 9.
Jan  2 14:47:50 raspberry shairport-sync:          0.000124218 "rtsp.c:4722" Connection 4: terminating connection from 192.168.178.29:64718 to self at 192.168.178.39:5000.
Jan  2 14:47:50 raspberry shairport-sync:          0.068827344 "common.c:1600" mutex_lock "&conns_lock" at "rtsp.c:724".
Jan  2 14:47:50 raspberry shairport-sync:          0.000099531 "common.c:1623" mutex_unlock "&conns_lock" at "rtsp.c:735".
Jan  2 14:47:50 raspberry shairport-sync:          0.519680781 "rtsp.c:4766" Connection 4: error 16 destroying ab_mutex.
Jan  2 14:47:50 raspberry shairport-sync:          0.000095678 "rtsp.c:4771" Cancel watchdog thread.
Jan  2 14:47:50 raspberry shairport-sync:          0.000091718 "rtsp.c:4773" Join watchdog thread.
Jan  2 14:47:50 raspberry shairport-sync:          0.000125261 "rtsp.c:612" Connection 4: Watchdog Exit.
Jan  2 14:47:50 raspberry shairport-sync:          0.000169479 "rtsp.c:4775" Delete watchdog mutex.
Jan  2 14:47:50 raspberry shairport-sync:          0.000107135 "rtsp.c:4781" Connection 4: Closed.
Jan  2 14:47:51 raspberry shairport-sync:          0.874931667 "common.c:1600" mutex_lock "&conns_lock" at "rtsp.c:724".
Jan  2 14:47:51 raspberry shairport-sync:          0.000108854 "rtsp.c:727" found RTSP connection thread 4 in a non-running state.
Jan  2 14:47:51 raspberry shairport-sync:          0.000038073 "rtsp.c:730" Connection 4: deleted in cleanup.
Jan  2 14:47:51 raspberry shairport-sync:          0.000030781 "common.c:1623" mutex_unlock "&conns_lock" at "rtsp.c:735".
Jan  2 14:47:51 raspberry shairport-sync:          0.000100573 "rtsp.c:5217" Connection 5: new connection from 192.168.178.29:64790 to self at 192.168.178.39:5000.
Jan  2 14:47:51 raspberry shairport-sync:          0.000144948 "rtsp.c:5232" Successfully created RTSP receiver thread 5.
Jan  2 14:47:51 raspberry shairport-sync:          0.000038021 "common.c:1600" mutex_lock "&conns_lock" at "rtsp.c:664".
Jan  2 14:47:51 raspberry shairport-sync:          0.000032864 "common.c:1623" mutex_unlock "&conns_lock" at "rtsp.c:686".
Jan  2 14:47:51 raspberry shairport-sync:          0.000070781 "rtsp.c:785" msg_init message 25
Jan  2 14:47:51 raspberry shairport-sync:          0.000043646 "rtsp.c:890" RTSP Message Received: "OPTIONS * RTSP/1.0".
Jan  2 14:47:51 raspberry shairport-sync:          0.000035052 "rtsp.c:921"     CSeq: 1.
Jan  2 14:47:51 raspberry shairport-sync:          0.000027500 "rtsp.c:921"     User-Agent: Music/1.2.1 (Macintosh; OS X 12.1) AppleWebKit/612.3.6.1.6.
Jan  2 14:47:51 raspberry shairport-sync:          0.000026511 "rtsp.c:921"     Client-Instance: 7195852668DCD350.
Jan  2 14:47:51 raspberry shairport-sync:          0.000027031 "rtsp.c:921"     DACP-ID: 7195852668DCD350.
Jan  2 14:47:51 raspberry shairport-sync:          0.000029010 "rtsp.c:921"     Active-Remote: 2961985464.
Jan  2 14:47:51 raspberry shairport-sync:          0.000046146 "rtsp.c:785" msg_init message 26
Jan  2 14:47:51 raspberry shairport-sync:          0.000038125 "rtsp.c:1053" OPTIONS request
Jan  2 14:47:51 raspberry shairport-sync:          0.000026042 "rtsp.c:1063"   No Content Plist. Content length: 0.
Jan  2 14:47:51 raspberry shairport-sync:          0.000027656 "rtsp.c:2425" Connection 5: OPTIONS
Jan  2 14:47:51 raspberry shairport-sync:          0.000026094 "rtsp.c:4899" Connection 5: RTSP Response:
Jan  2 14:47:51 raspberry shairport-sync:          0.000024531 "rtsp.c:817"   Type: "CSeq", content: "1"
Jan  2 14:47:51 raspberry shairport-sync:          0.000025365 "rtsp.c:817"   Type: "Server", content: "AirTunes/105.1"
Jan  2 14:47:51 raspberry shairport-sync:          0.000053281 "rtsp.c:817"   Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER"
Jan  2 14:47:51 raspberry shairport-sync:          0.000198698 "rtsp.c:866" msg_free freed message 26
Jan  2 14:47:51 raspberry shairport-sync:          0.000033281 "rtsp.c:866" msg_free freed message 25
/*  */
mikebrady commented 2 years ago

Thanks for the report. I’ll see if I can reproduce it.

[Update] I think I can reproduce it alright! 🙂

mikebrady commented 2 years ago

I certainly found a bug, fixed it and pushed an update. If you would be kind enough to try it out, that would be great.

th0u commented 2 years ago

Excellent, version 4.1-dev-163-g7212504c-AirPlay2-alac-OpenSSL-Avahi-ALSA-soxr-metadata-sysconfdir:/etc fixes this.

Thank you.

mikebrady commented 2 years ago

Thanks to you for your very thorough directions for reproducing the bug!

github-actions[bot] commented 2 years ago

This issue has been inactive for 45 days so will be closed 7 days from now. To prevent this, please remove the "stale" label or post a comment.