search

mikebrady / shairport-sync

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

[Problem]: Playback stops after several hours. #1927

Closed DrCWO closed 1 week ago

DrCWO commented 3 weeks ago

What happened?

Streaming from iPad9 Greatest His Radio (https://hellorayo.co.uk/greatest-hits/play/) as a premium user (no ads) Playback to shairport-sync stops after several hours. For Playback the Safari Browser of the iPad was used, iPad connected to charger.

I think the important information in the log is Oct 28 21:21:05 rooExtend shairport-sync[1422716]: 0.000043815 "rtsp.c:2769" Connection 1: TEARDOWN

But I have no idea why this happens or what it means.

Relevant log output

Oct 28 21:21:01 rooExtend shairport-sync[1422716]:          0.199649408 "rtsp.c:2612" OPTIONS request
Oct 28 21:21:01 rooExtend shairport-sync[1422716]:          0.000162296 "rtsp.c:2612"   Type: "CSeq", content: "3741"
Oct 28 21:21:01 rooExtend shairport-sync[1422716]:          0.000054685 "rtsp.c:2612"   Type: "DACP-ID", content: "32955C68D00118FF"
Oct 28 21:21:01 rooExtend shairport-sync[1422716]:          0.000048982 "rtsp.c:2612"   Type: "Active-Remote", content: "606068252"
Oct 28 21:21:01 rooExtend shairport-sync[1422716]:          0.000048481 "rtsp.c:2612"   Type: "User-Agent", content: "AirPlay/800.74.1"
Oct 28 21:21:01 rooExtend shairport-sync[1422716]:          0.000045685 "rtsp.c:2612"   No Content Plist. Content length: 0.
Oct 28 21:21:02 rooExtend shairport-sync[1422716]:          1.148742648 "rtp.c:516" AP1 control thread: set_ntp_anchor_info: rtptime: 2166127560, networktime: 1ea8e5bd0a713782, frame adjustment:   0.206.
Oct 28 21:21:02 rooExtend shairport-sync[1422716]:          0.477491481 "player.c:2497" number_of_statistics is zero!
Oct 28 21:21:03 rooExtend shairport-sync[1422716]:          0.356058629 "rtsp.c:2612" OPTIONS request
Oct 28 21:21:03 rooExtend shairport-sync[1422716]:          0.000149852 "rtsp.c:2612"   Type: "CSeq", content: "3742"
Oct 28 21:21:03 rooExtend shairport-sync[1422716]:          0.000056241 "rtsp.c:2612"   Type: "DACP-ID", content: "32955C68D00118FF"
Oct 28 21:21:03 rooExtend shairport-sync[1422716]:          0.000047852 "rtsp.c:2612"   Type: "Active-Remote", content: "606068252"
Oct 28 21:21:03 rooExtend shairport-sync[1422716]:          0.000051333 "rtsp.c:2612"   Type: "User-Agent", content: "AirPlay/800.74.1"
Oct 28 21:21:03 rooExtend shairport-sync[1422716]:          0.000050556 "rtsp.c:2612"   No Content Plist. Content length: 0.
Oct 28 21:21:03 rooExtend shairport-sync[1422716]:          0.021879685 "metadata_hub.c:509" MH Metadata stream processing start.
Oct 28 21:21:03 rooExtend shairport-sync[1422716]:          0.000132592 "metadata_hub.c:356" MH Item ID seen: "0" of length 8.
Oct 28 21:21:03 rooExtend shairport-sync[1422716]:          0.000062408 "metadata_hub.c:361" MH Item ID set to: "0"
Oct 28 21:21:03 rooExtend shairport-sync[1422716]:          0.000056092 "metadata_hub.c:378" MH Album name set to: "(null)"
Oct 28 21:21:03 rooExtend shairport-sync[1422716]:          0.000053945 "metadata_hub.c:386" MH Artist name set to: "(null)"
Oct 28 21:21:03 rooExtend shairport-sync[1422716]:          0.000055926 "metadata_hub.c:419" MH Track Name set to: "(null)"
Oct 28 21:21:03 rooExtend shairport-sync[1422716]:          0.000056037 "metadata_hub.c:514" MH Metadata stream processing end with changes.
Oct 28 21:21:03 rooExtend shairport-sync[1422716]:          0.000240092 "dbus-service.c:195" Build metadata
Oct 28 21:21:03 rooExtend shairport-sync[1422716]:          0.001712260 "metadata_hub.c:557" MH Progress String set to: "2166169552/2166169743/2166169552"
Oct 28 21:21:03 rooExtend shairport-sync[1422716]:          0.000288629 "dbus-service.c:195" Build metadata
Oct 28 21:21:03 rooExtend shairport-sync[1422716]:          0.007172445 "metadata_hub.c:520" MH Picture received, length 0 bytes.
Oct 28 21:21:03 rooExtend shairport-sync[1422716]:          0.785881555 "rtp.c:774" clock synchronisation request: return time is    1.633 milliseconds.
Oct 28 21:21:04 rooExtend shairport-sync[1422716]:          0.335931888 "rtp.c:516" AP1 control thread: set_ntp_anchor_info: rtptime: 2166215215, networktime: 1ea8e5bd80ea5323, frame adjustment:  -0.295.
Oct 28 21:21:05 rooExtend shairport-sync[1422716]:          0.900692778 "rtsp.c:2612" OPTIONS request
Oct 28 21:21:05 rooExtend shairport-sync[1422716]:          0.000173833 "rtsp.c:2612"   Type: "CSeq", content: "3746"
Oct 28 21:21:05 rooExtend shairport-sync[1422716]:          0.000055611 "rtsp.c:2612"   Type: "DACP-ID", content: "32955C68D00118FF"
Oct 28 21:21:05 rooExtend shairport-sync[1422716]:          0.000197037 "rtsp.c:2612"   Type: "Active-Remote", content: "606068252"
Oct 28 21:21:05 rooExtend shairport-sync[1422716]:          0.000066019 "rtsp.c:2612"   Type: "User-Agent", content: "AirPlay/800.74.1"
Oct 28 21:21:05 rooExtend shairport-sync[1422716]:          0.000046370 "rtsp.c:2612"   No Content Plist. Content length: 0.
Oct 28 21:21:05 rooExtend shairport-sync[1422716]:          0.110019778 "rtp.c:516" AP1 control thread: set_ntp_anchor_info: rtptime: 2166259817, networktime: 1ea8e5bdbd3296ce, frame adjustment:   0.633.
Oct 28 21:21:05 rooExtend shairport-sync[1422716]:          0.298499981 "rtsp.c:2768" TEARDOWN request
Oct 28 21:21:05 rooExtend shairport-sync[1422716]:          0.000151111 "rtsp.c:2768"   Type: "CSeq", content: "3747"
Oct 28 21:21:05 rooExtend shairport-sync[1422716]:          0.000060556 "rtsp.c:2768"   Type: "DACP-ID", content: "32955C68D00118FF"
Oct 28 21:21:05 rooExtend shairport-sync[1422716]:          0.000050166 "rtsp.c:2768"   Type: "Active-Remote", content: "606068252"
Oct 28 21:21:05 rooExtend shairport-sync[1422716]:          0.000046815 "rtsp.c:2768"   Type: "User-Agent", content: "AirPlay/800.74.1"
Oct 28 21:21:05 rooExtend shairport-sync[1422716]:          0.000044648 "rtsp.c:2768"   No Content Plist. Content length: 0.
Oct 28 21:21:05 rooExtend shairport-sync[1422716]:          0.000043815 "rtsp.c:2769" Connection 1: TEARDOWN
Oct 28 21:21:05 rooExtend shairport-sync[1422716]:          0.000404148 "player.c:1772" Cancelling AP1 timing, control and audio threads...
Oct 28 21:21:05 rooExtend shairport-sync[1422716]:          0.001098463 "rtp.c:320" Control Receiver Cleanup Done.
Oct 28 21:21:05 rooExtend shairport-sync[1422716]:          0.001163185 "player.c:1820" Connection 1: player terminated.
Oct 28 21:21:05 rooExtend shairport-sync[1422716]:          0.005650371 "rtsp.c:540" Connection 1: release play lock.
Oct 28 21:21:05 rooExtend shairport-sync[1422716]:          0.000420611 "rtsp.c:546" Connection 1: play lock released.
Oct 28 21:21:05 rooExtend shairport-sync[1422716]:          0.000212111 "dbus-service.c:195" Build metadata
Oct 28 21:21:05 rooExtend shairport-sync[1422716]:          0.003963500 "rtsp.c:1346" Connection 1: Closed by client: from 192.168.0.43:51568 to self at 192.168.0.193:5000.
Oct 28 21:21:05 rooExtend shairport-sync[1422716]:          0.000137852 "rtsp.c:4973" Connection 1: rtsp_conversation_thread_func_cleanup_function called.
Oct 28 21:21:05 rooExtend shairport-sync[1422716]:          0.000692148 "rtsp.c:5063" Connection 1: Closed.
Oct 28 21:21:05 rooExtend shairport-sync[1422716]:          0.033013833 "dacp.c:370" send_simple_dacp_command: sending command "pause".
Oct 28 21:21:15 rooExtend shairport-sync[1422716]:          9.961707013 "activity_monitor.c:82" aend
Oct 28 21:21:15 rooExtend shairport-sync[1422716]:          0.000503815 "activity_monitor.c:161" am_state: am_inactive
Oct 28 21:21:15 rooExtend shairport-sync[1422716]:          0.000097926 "dbus-service.c:195" Build metadata
Oct 28 21:22:01 rooExtend shairport-sync[1422716]:         46.162990935 "rtsp.c:752" Connection 1: deleted in cleanup.
Oct 28 21:29:07 rooExtend shairport-sync[1422716]:        426.005947839 "mdns_avahi.c:160" (Browser) REMOVE: service 'iTunes_Ctrl_32955C68D00118FF' of type '_dacp._tcp' in domain 'local'.
Oct 28 21:29:07 rooExtend shairport-sync[1422716]:          0.000161296 "dacp.c:466" dacp_monitor_port_update_callback with Remote ID "32955C68D00118FF", target ID "32955C68D00118FF" and port number 0.
Oct 28 21:29:08 rooExtend shairport-sync[1422716]:          0.924270333 "dbus-service.c:195" Build metadata

System Information.

Shairport-Sync runs on a Raspberry Pi4 under DietPi, streaming to a pipe. Configuration file attached. shairport-sync.txt

Shairport-Sync was manually started via:

shairport-sync -c ./shairport-sync.txt --log-to-syslog`

Configuration Information.

# shairport-sync -c ./shairport-sync.conf --displayConfig
         0.001390704 "shairport.c:1420" default metadata_pipename is "/tmp/shairport-sync-metadata".
         0.000157055 "shairport.c:2057" >> Display Config Start.
         0.003984093 "shairport.c:2057"
         0.000061722 "shairport.c:2057" From "uname -a":
         0.000059963 "shairport.c:2057"  Linux rooExtend 5.15.61-v8+ #1579 SMP PREEMPT Fri Aug 26 11:16:44 BST 2022 aarch64 GNU/Linux
         0.008103444 "shairport.c:2057"
         0.000107297 "shairport.c:2057" From /etc/os-release:
         0.000110444 "shairport.c:2057"  Debian GNU/Linux 11 (bullseye)
         0.004389889 "shairport.c:2057"
         0.000087352 "shairport.c:2057" From /sys/firmware/devicetree/base/model:
         0.000040833 "shairport.c:2057"  Raspberry Pi 4 Model B Rev 1.5
         0.000105056 "shairport.c:2057"
         0.000073481 "shairport.c:2057" Shairport Sync Version String:
         0.000049167 "shairport.c:2057"  4.1-rc5-OpenSSL-Avahi-stdout-pipe-soxr-metadata-dbus-sysconfdir:/etc
         0.000057796 "shairport.c:2057"
         0.000053926 "shairport.c:2057" Command Line:
         0.000048148 "shairport.c:2057"  shairport-sync -c ./shairport-sync.conf --displayConfig
         0.000125074 "shairport.c:2057"
         0.000042315 "shairport.c:2057" Configuration File:
         0.000037778 "shairport.c:2057"  /home/pi/rooExtend/shairport-sync.conf
         0.000038592 "shairport.c:2057"
         0.000168112 "shairport.c:2057" Configuration File Settings:
         0.000043685 "shairport.c:2057"  general :
         0.000037666 "shairport.c:2057"  {
         0.000037278 "shairport.c:2057"    name = "%h";
         0.000038111 "shairport.c:2057"    output_backend = "pipe";
         0.000043093 "shairport.c:2057"    ignore_volume_control = "yes";
         0.000037759 "shairport.c:2057"    run_this_when_volume_is_set = "./shairport-vol.sh ";
         0.000037296 "shairport.c:2057"  };
         0.000158482 "shairport.c:2057"  sessioncontrol :
         0.000044278 "shairport.c:2057"  {
         0.000047666 "shairport.c:2057"    run_this_before_play_begins = "./shairport-begin.sh";
         0.000039204 "shairport.c:2057"    run_this_after_play_ends = "./shairport-end.sh";
         0.000124019 "shairport.c:2057"  };
         0.000041814 "shairport.c:2057"  pipe :
         0.000037075 "shairport.c:2057"  {
         0.000036574 "shairport.c:2057"    name = "/tmp/audioAirplay.fifo";
         0.000037574 "shairport.c:2057"  };
         0.000041518 "shairport.c:2057"  diagnostics :
         0.000039426 "shairport.c:2057"  {
         0.000037537 "shairport.c:2057"    log_verbosity = 2;
         0.000037167 "shairport.c:2057"  };
         0.000037111 "shairport.c:2057"
         0.000040574 "shairport.c:2057" >> Display Config End.

PulseAudio or PipeWire installed?

How did you install Shairport Sync?

A package manager (apt, apt install, yum, pkg, etc.)

Check previous issues

mikebrady commented 2 weeks ago

Thanks for the post. It looks as if the iPad initiated the shutdown of the session.

It might be useful to enable the gathering of statistics. Sometimes the number of buffers of audio drops down, indicating that audio is no longer being received, and it would be interesting to see if anything like that is happening...

DrCWO commented 2 weeks ago

Thank you, will do this today and get back to you with results. Any additional options you like me to enable in the config file?

mikebrady commented 2 weeks ago

Thanks. At present, nothing more than log verbosity 1 and statistics enabled.

DrCWO commented 2 weeks ago

This is what I saw today in the log. Please comment...

Oct 31 12:58:17 rooExtend shairport-sync[2294432]:          7.988833680 "player.c:2572"       0        0          0             0           134           150      44100.00       44100.22               5.25
Oct 31 12:58:25 rooExtend shairport-sync[2294432]:          8.012888218 "player.c:2572"       0        0          0             0           136           150      44100.00       44099.65               5.22
Oct 31 12:58:33 rooExtend shairport-sync[2294432]:          7.990190495 "player.c:2572"       0        0          0             0           136           150      44100.00       44100.22               5.22
Oct 31 12:58:41 rooExtend shairport-sync[2294432]:          8.017247773 "player.c:2572"       0        0          0             0           136           150      44100.00       44100.19               5.22
Oct 31 12:58:49 rooExtend shairport-sync[2294432]:          8.020068440 "player.c:2572"       0        0          0             0           136           150      44100.00       44100.21               5.22
Oct 31 12:58:57 rooExtend shairport-sync[2294432]:          7.990384384 "player.c:2572"       0        0          0             0           136           150      44100.00       44100.20               5.22
Oct 31 12:59:05 rooExtend shairport-sync[2294432]:          8.010487588 "player.c:2572"       0        0          0             0           136           150      44100.00       44099.71               5.22
Oct 31 12:59:13 rooExtend shairport-sync[2294432]:          7.992441088 "player.c:2572"       0        0          0             0           136           150      44100.00       44100.20               5.30
Oct 31 12:59:21 rooExtend shairport-sync[2294432]:          8.019563661 "player.c:2572"       0        0          0             0           136           150      44100.00       44100.22               5.29
Oct 31 12:59:29 rooExtend shairport-sync[2294432]:          7.988390477 "player.c:2572"       0        0          0             0           136           150      44100.00       44100.18               5.31
Oct 31 12:59:37 rooExtend shairport-sync[2294432]:          8.017527662 "player.c:2572"       0        0          0             0           136           150      44100.00       44100.21               5.31
Oct 31 12:59:45 rooExtend shairport-sync[2294432]:          8.017463680 "player.c:2572"       0        0          0             0           136           150      44100.00       44100.08               5.31
Oct 31 12:59:53 rooExtend shairport-sync[2294432]:          7.986848051 "player.c:2572"       0        0          0             0           136           150      44100.00       44100.20               5.32
Oct 31 13:00:01 rooExtend shairport-sync[2294432]:          8.014967477 "player.c:2572"       0        0          0             0           136           150      44100.00       44100.24               5.32
Oct 31 13:00:03 rooExtend shairport-sync[2294432]:          2.110751758 "player.c:1728" Connection 1: Playback Stopped. Total playing time 01:55:42.
Oct 31 13:00:03 rooExtend shairport-sync[2294432]:          0.011247815 "rtsp.c:1346" Connection 1: Closed by client: from 192.168.0.43:52397 to self at 192.168.0.193:5000.

Thanks

mikebrady commented 2 weeks ago

Thanks for that. There isn't anything obvious there, I'm afraid -- the maximum and minimum numbers of buffers are really constant.

So, I've added a small diagnostic and pushed in into the development branch, to see when a read() returns zero, which indicates that the client has closed the connection.

If you'd be kind enough to pull and build it and run again, with the same parameters, it might give us a clue.

DrCWO commented 2 weeks ago

Thanks' so much for your support :-) Maybe tomorrow. Tonight I will retry with the same configuration BUT iPad screen staying on so no chance for power saving...

DrCWO commented 2 weeks ago

Now I got this after 19 minutes. Buffer "0"???

Oct 31 19:23:33 rooExtend shairport-sync[2400299]:          7.986305625 "player.c:2572"       0      244          0             4           136           150      44100.00       44100.46               6.03
Oct 31 19:23:41 rooExtend shairport-sync[2400299]:          8.021998421 "player.c:2572"       0      244          0             4           136           150      44100.00       44100.14               6.03
Oct 31 19:23:49 rooExtend shairport-sync[2400299]:          8.017196607 "player.c:2572"       0      244          0             4           138           150      44100.00       44100.32               6.06
Oct 31 19:23:57 rooExtend shairport-sync[2400299]:          7.987925236 "player.c:2572"       0      244          0             4           136           150      44100.00       44100.41               6.01
Oct 31 19:24:05 rooExtend shairport-sync[2400299]:          8.015693069 "player.c:2572"       0      244          0             4           136           150      44100.00       44100.30               6.01
Oct 31 19:24:14 rooExtend shairport-sync[2400299]:          9.381677124 "player.c:2572"       0      278          0             5             0           150      44100.00       44100.18               6.01
Oct 31 19:24:22 rooExtend shairport-sync[2400299]:          8.020764032 "player.c:2572"       0      278          0             5           136           150      44099.87       44100.23               6.02
Oct 31 19:24:30 rooExtend shairport-sync[2400299]:          8.018633070 "player.c:2572"       0      278          0             5           136           150      44099.99       44100.37               6.00
Oct 31 19:24:38 rooExtend shairport-sync[2400299]:          7.988252347 "player.c:2572"       0      278          0             5           138           150      44099.97       44100.43               5.94
Oct 31 19:24:46 rooExtend shairport-sync[2400299]:          8.014383569 "player.c:2572"       0      278          0             5           136           150      44099.98       44097.31               5.92
Oct 31 19:24:52 rooExtend shairport-sync[2400299]:          6.226851496 "player.c:1728" Connection 1: Playback Stopped. Total playing time 00:19:19.
Oct 31 19:24:52 rooExtend shairport-sync[2400299]:          0.013354889 "rtsp.c:1346" Connection 1: Closed by client: from 192.168.0.43:52838 to self at 192.168.0.193:5000.
Oct 31 19:27:09 rooExtend shairport-sync[2400299]:        136.916663770 "rtsp.c:1628" Connection 2: Classic AirPlay connection from 192.168.0.43:52854 to self at 192.168.0.193:5000.

You see the zero? [2400299]: 9.381677124 "player.c:2572" 0 278 0 5 0 150 44100.00 44100.18 6.01

DrCWO commented 2 weeks ago

Happened again, Bufferzize Min = zero!!

Oct 31 19:36:15 rooExtend shairport-sync[2400299]:          8.016320662 "player.c:2572"       0       23          0             1           136           150      44100.00       44099.58               5.72
Oct 31 19:36:25 rooExtend shairport-sync[2400299]:          9.782191790 "player.c:2572"       0       23          0             1             0           150      44100.00       44099.90               5.72
Oct 31 19:36:32 rooExtend shairport-sync[2400299]:          7.038601959 "player.c:1728" Connection 2: Playback Stopped. Total playing time 00:09:20.
mikebrady commented 2 weeks ago

Thanks. That buffer count of zero means that during that approximately 8-second period, the number of buffers -- packets of 352 frames of audio -- went down to zero at some stage. In other words, Shairport Sync was starved of audio for a time. You might not have heard it because the packets eventually arrived and were decoded and put into the output pipe.

Those packets were definitely lost somewhere and had to be retransmitted -- you can see that the number of retransmission requests went up quite a bit. It's not unusual for some packets to be lost, but it is unusual for that many to be lost at one time.

Anyway, it didn't stop the play session, and that's what we are trying to zero in on.

DrCWO commented 2 weeks ago

Well, but the second time it stops after 9:20. Another stop right now:

Oct 31 20:27:07 rooExtend shairport-sync[2400299]:          7.989689829 "player.c:2572"       0     1328          0            27           136           150      44100.00       44100.29               5.40
Oct 31 20:27:15 rooExtend shairport-sync[2400299]:          8.021334254 "player.c:2572"       0     1410          0            28            57           150      44100.00       44100.17               5.40
Oct 31 20:27:23 rooExtend shairport-sync[2400299]:          7.987134588 "player.c:2572"       0     1410          0            28           136           150      44100.00       44100.22               5.37
Oct 31 20:27:31 rooExtend shairport-sync[2400299]:          8.013956217 "player.c:2572"       0     1457          0            30           102           150      44100.00       44100.20               5.32
Oct 31 20:27:39 rooExtend shairport-sync[2400299]:          8.022459866 "player.c:2572"       0     1457          0            30           136           150      44100.00       44100.19               5.32
Oct 31 20:27:47 rooExtend shairport-sync[2400299]:          7.988684754 "player.c:2572"       0     1457          0            30           136           150      44100.00       44100.21               5.32
Oct 31 20:27:55 rooExtend shairport-sync[2400299]:          8.020200644 "player.c:2572"       0     1514          0            32            91           150      44100.00       44100.24               5.32
Oct 31 20:28:03 rooExtend shairport-sync[2400299]:          7.986119458 "player.c:2572"       0     1514          0            32           138           150      44100.00       44100.18               5.35
Oct 31 20:28:11 rooExtend shairport-sync[2400299]:          8.016259069 "player.c:2572"       0     1514          0            32           138           150      44100.00       44100.25               5.31
Oct 31 20:28:20 rooExtend shairport-sync[2400299]:          8.017516533 "player.c:2572"       0     1514          0            32           136           150      44100.00       44100.19               5.31
Oct 31 20:28:27 rooExtend shairport-sync[2400299]:          7.989965865 "player.c:2572"       0     1537          0            33           114           150      44100.00       44100.19               5.31
Oct 31 20:28:36 rooExtend shairport-sync[2400299]:          8.017547755 "player.c:2572"       0     1537          0            33           136           150      44100.00       44100.26               5.35
Oct 31 20:28:45 rooExtend shairport-sync[2400299]:          9.848397512 "player.c:2572"       0     1607          0            34             0           150      44100.00       44100.16               5.37
Oct 31 20:28:53 rooExtend shairport-sync[2400299]:          8.015561884 "player.c:2572"       0     1676          0            35            66           150      44100.06       44100.24               5.37
Oct 31 20:28:57 rooExtend shairport-sync[2400299]:          3.908634165 "player.c:1728" Connection 4: Playback Stopped. Total playing time 00:50:07.
DrCWO commented 2 weeks ago

Is there a chance to increase the buffer to get more safe space for retransmissions?

DrCWO commented 2 weeks ago

... or fill the gap by low level dithered packages?

DrCWO commented 2 weeks ago

One more observation: if I use the Quobuz app on the iPad the disconnect happens every few minutes as Quobuz strems hires FLAC. I am away 1.5 meters from the WiFi Router, so best you can get...


8.016099865 "player.c:2572"       0      221          0             3           118           150      44100.00           0.00               5.58
Oct 31 20:51:35 rooExtend shairport-sync[2400299]:          8.019641106 "player.c:2572"       0      221          0             3           136           150      44100.00           0.00               5.58
Oct 31 20:51:43 rooExtend shairport-sync[2400299]:          7.989351218 "player.c:2572"       0      221          0             3           114           150      44100.00           0.00               5.58
Oct 31 20:51:51 rooExtend shairport-sync[2400299]:          8.019728106 "player.c:2572"       0      326          0             5            65           150      44100.00           0.00               5.58
Oct 31 20:51:54 rooExtend shairport-sync[2400299]:          2.775886684 "rtp.c:965" Time ping turnaround time: 226541500 ns -- it looks like a timing ping was lost.
Oct 31 20:51:59 rooExtend shairport-sync[2400299]:          5.210765774 "player.c:2572"       0      326          0             5           109           149      44100.00           0.00               5.54
Oct 31 20:52:07 rooExtend shairport-sync[2400299]:          8.019412107 "player.c:2572"       0      326          0             5           118           150      44100.00           0.00               5.54
Oct 31 20:52:15 rooExtend shairport-sync[2400299]:          8.016140088 "player.c:2572"       0      326          0             5           118           150      44100.00           0.00               5.59
Oct 31 20:52:23 rooExtend shairport-sync[2400299]:          7.987747699 "player.c:2572"       0      326          0             5           119           150      44100.00           0.00               5.59
Oct 31 20:52:31 rooExtend shairport-sync[2400299]:          8.020016884 "player.c:2572"       0      326          0             5           112           150      44100.00           0.00               5.57
Oct 31 20:52:39 rooExtend shairport-sync[2400299]:          7.987673625 "player.c:2572"       0      361          0             6           102           150      44100.00           0.00               5.58
Oct 31 20:52:47 rooExtend shairport-sync[2400299]:          8.014669624 "player.c:2572"       0      361          0             6           135           150      44100.00           0.00               5.69
Oct 31 20:52:55 rooExtend shairport-sync[2400299]:          8.020744996 "player.c:2572"       0      361          0             6           114           150      44100.00           0.00               5.69
Oct 31 20:53:03 rooExtend shairport-sync[2400299]:          7.988953365 "player.c:2572"       0      361          0             6           136           150      44100.00           0.00               5.69
Oct 31 20:53:12 rooExtend shairport-sync[2400299]:          9.101244384 "player.c:2572"       0      361        116             7            21           150      44100.00           0.00               5.76
Oct 31 20:53:20 rooExtend shairport-sync[2400299]:          8.023329532 "player.c:2572"       0      396        116             8           102           150      44100.00           0.00               5.76
Oct 31 20:53:28 rooExtend shairport-sync[2400299]:          8.012205347 "player.c:2572"       0      396        116             8           118           150      44100.00           0.00               5.76
Oct 31 20:53:38 rooExtend shairport-sync[2400299]:          9.474055902 "player.c:2572"       0      431        116             9             0           150      44100.00           0.00               5.78
Oct 31 20:53:46 rooExtend shairport-sync[2400299]:          8.023162014 "player.c:2572"       0      431        116             9            98           150      44099.99           0.00               5.78
Oct 31 20:53:55 rooExtend shairport-sync[2400299]:          9.378479994 "player.c:2572"       0      547        116            11             9           150      44099.94           0.00               5.78
Oct 31 20:54:02 rooExtend shairport-sync[2400299]:          6.217004830 "player.c:1728" Connection 6: Playback Stopped. Total playing time 00:06:09.
Oct 31 20:54:02 rooExtend shairport-sync[2400299]:          0.011164222 "rtsp.c:1346" Connection 6: Closed by client: from 192.168.0.43:52926 to self at 192.168.0.193:5000.
mikebrady commented 2 weeks ago

Thanks for the updates. It would be interesting to try to work out why those packets seem to be disappearing. If there is a great deal of electronic noise, e.g. from microwave ovens, it might explain it.

I have not used Quoboz, so can't comment, I'm afraid.

There aren't any settings on the pipe or stdout backends that you can vary. However, the output player you use (e.g. aplay) is probably buffering for a second or two, so even if Shairport Sync's buffers are exhausted, the audio may well still play uninterrupted.

It will be interesting to see what the updated development branch, with that extra diagnostic, can see.

DrCWO commented 2 weeks ago

Hi again, I'm sorry, but git is not my very best friend ;-) I used this to clone: git clone https://github.com/mikebrady/shairport-sync.git But I believe this is the current release. How to get the release from the development branch?

DrCWO commented 2 weeks ago

Aaaah, google helped. Did this now: git clone -b development https://github.com/mikebrady/shairport-sync.git Hope this is the right one.

# ./shairport-sync -V
4.3.5-dev-54-g50d51993-OpenSSL-Avahi-stdout-pipe-soxr-metadata-dbus-sysconfdir:/etc
mikebrady commented 2 weeks ago

Thanks -- yes, 4.3.5-dev-54-g50d51993 is the current development version.

Just for reference, your original idea was also correct, but needed one extra step, as follows:

$ git clone https://github.com/mikebrady/shairport-sync.git
$ git checkout development

Thanks for making the effort to get to the bottom of this issue.

DrCWO commented 2 weeks ago

I have to thank you for your support 👍 👍👍

I run the dev release now with the Quobuz App that never played for a long time yesterday but now it ran for approx. one hour and I only see some few resends. Looks quite good but also a bit strange to me compared to the results I got yesterday!? Are there other changes included that might make it more stable?

Regarding my backend: I output to a Fifo and at the end of it my own rooPlay Roon extension which is part of my rooExtend suite for Roon. rooPlay grabs the audio off the Fifo, encodes it to FLAC and offers a FLAC HTTP stream consumed by Roon. I first looked for the issue in my node.js code but the pipelines were well filled and if the issue occurred I get a stop message from shairport-sync.

mikebrady commented 2 weeks ago

Are there other changes included that might make it more stable?

There have been a few changes since 4.1 alright, but nothing huge. Most of them were to do with AirPlay 2 operation, and since you're using the classic AirPlay build, these wouldn't apply.

Maybe other environmental changes could be responsible for Quobuz's better performance, e.g. network conditions, (including the Internet if you are streaming).

DrCWO commented 2 weeks ago

This is the result of my latest try. Can't see any additional debug output. iPad screen still on, browser open, power connected. Stopped after two hours and this was again Greatest Hits Radio, no Quobuz. Any ideas?

Nov 01 17:04:45 rooExtend shairport-sync[202176]:          7.985510551 "player.c:2656"       0       27          0             5           136           150      44100.00       44100.27               5.75
Nov 01 17:04:53 rooExtend shairport-sync[202176]:          8.017083106 "player.c:2656"       0       27          0             5           136           150      44100.00       44100.24               5.75
Nov 01 17:05:01 rooExtend shairport-sync[202176]:          8.016750681 "player.c:2656"       0       27          0             5           135           150      44100.00       44100.27               5.75
Nov 01 17:05:09 rooExtend shairport-sync[202176]:          7.989337717 "player.c:2656"       0       27          0             5           136           150      44100.00       44100.23               5.81
Nov 01 17:05:17 rooExtend shairport-sync[202176]:          8.020542569 "player.c:2656"       0       27          0             5           136           150      44100.00       44100.24               5.81
Nov 01 17:05:25 rooExtend shairport-sync[202176]:          7.986861940 "player.c:2656"       0       27          0             5           135           150      44100.00       44100.26               5.79
Nov 01 17:05:33 rooExtend shairport-sync[202176]:          8.014264625 "player.c:2656"       0       27          0             5           134           150      44100.00       44100.25               5.79
Nov 01 17:05:41 rooExtend shairport-sync[202176]:          8.022042921 "player.c:2656"       0       27          0             5           136           150      44100.00       44100.25               5.78
Nov 01 17:05:49 rooExtend shairport-sync[202176]:          7.988784329 "player.c:2656"       0       27          0             5           136           150      44100.00       44100.25               5.88
Nov 01 17:05:57 rooExtend shairport-sync[202176]:          8.017482124 "player.c:2656"       0       27          0             5           136           150      44100.00       44100.23               5.89
Nov 01 17:06:05 rooExtend shairport-sync[202176]:          7.989277348 "player.c:2656"       0       27          0             5           136           150      44100.00       44100.24               5.89
Nov 01 17:06:13 rooExtend shairport-sync[202176]:          8.014749402 "player.c:2656"       0       27          0             5           136           150      44100.00       44100.27               5.89
Nov 01 17:06:21 rooExtend shairport-sync[202176]:          7.988588662 "player.c:2656"       0       27          0             5           138           150      44100.00       44100.23               5.90
Nov 01 17:06:29 rooExtend shairport-sync[202176]:          7.808080551 "player.c:1807" Connection 5: Playback stopped. Total playing time 01:59:56.
Nov 01 17:06:29 rooExtend shairport-sync[202176]:          0.012012037 "rtsp.c:1188" AP1 read result 0, for a request count of 262144.
mikebrady commented 2 weeks ago

Thanks for this. The new diagnostic is here:

Nov 01 17:06:29 rooExtend shairport-sync[202176]: 0.012012037 "rtsp.c:1188" AP1 read result 0, for a request count of 262144.

This means that a socket read() returned with a result of 0 bytes read. That normally means that the client, i.e. the iPad, has closed the connection.

On reading the man entry, I see that there is a possibility that an error code is returned when 0 bytes are returned as read, and this is not catered for in the code. So, I'll change it to check for and handle a potential error. As soon as that's done, I'll post an update and let you know.

mikebrady commented 2 weeks ago

OK, so I've added a little extra code to see if an error has been reported when read() returns 0 bytes read.

If there is no error with 0 bytes read, then it means that the client did indeed close the connection.

If it's an EAGAIN or EWOULDBLOCK error, the code will continue to try to perform the read(); otherwise it'll return 0 bytes read as before and this will be interpreted as the client closing the connection.

(To update, just do a $ git pull followed by a $ make and # make install.)

DrCWO commented 2 weeks ago

Will do 👍 Today I started playback from the Qubuz App at 11:15. Now at 16:34 still running 💯 Maybe the safari browser closes after a certain time or number of bytes?

Thanks' for the instructions. Will do the update now and report the result again with Greatest His Radio...

DrCWO commented 2 weeks ago

This is what I saw now with Greatest Hits Radio:

Nov 02 17:34:17 rooExtend shairport-sync[573867]:          7.990955292 "player.c:2656"       0        0          0             0           136           150      44100.00       44100.04               5.63
Nov 02 17:34:25 rooExtend shairport-sync[573867]:          8.018248125 "player.c:2656"       0        0          0             0           136           150      44100.00       44100.21               5.63
Nov 02 17:34:33 rooExtend shairport-sync[573867]:          7.986167310 "player.c:2656"       0        0          0             0           136           150      44100.00       44100.39               5.62
Nov 02 17:34:41 rooExtend shairport-sync[573867]:          8.017883439 "player.c:2656"       0        0          0             0           136           150      44100.00       44100.17               5.57
Nov 02 17:34:49 rooExtend shairport-sync[573867]:          7.988198422 "player.c:2656"       0        0          0             0           138           150      44100.00       44100.25               5.57
Nov 02 17:34:57 rooExtend shairport-sync[573867]:          8.015465902 "player.c:2656"       0        0          0             0           138           150      44100.00       44100.53               5.57
Nov 02 17:35:03 rooExtend shairport-sync[573867]:          6.482923978 "player.c:1807" Connection 2: Playback stopped. Total playing time 00:16:54.
Nov 02 17:35:03 rooExtend shairport-sync[573867]:          0.012514389 "rtsp.c:1189" AP1 read result 0, for a request count of 262144.
Nov 02 17:35:03 rooExtend shairport-sync[573867]:          0.000660259 "rtsp.c:1196" Connection 2: read result 0, error 11: "Resource temporarily unavailable".

What does it mean? Did Aiplay in the iPad not send data if requested?

mikebrady commented 2 weeks ago

Fantastic stuff. I’ll need to have a think about this overnight. Many thanks.

mikebrady commented 2 weeks ago

Thanks for your patience. I think that Shairport Sync is dropping the connection after a timeout period during which no traffic is seen on the controlling RTSP connection. This timeout is set at 120 seconds and can be altered with the session_timeout setting in the sessioncontrol part of the configuration file.

Thus, a quick check to see if I'm right is to set the session_timeout to, say, 300, i.e. 300 seconds or five minutes.

session_timeout = 300; // wait for this number of seconds after a source disappears before terminating the session and becoming available again.
};

This should make is less likely that the timeout will occur. (BTW, if you do this, please remember to uncomment the line by removing the leading // present in the sample configuration file. Also, you'll have to restart Shairport Sync for the new setting to take effect.)

If my idea is right, there are couple of things about this:

  1. This timeout business is a rather ancient part of Shairport Sync and may need some cleaning up in terms of error handling.
  2. Having a gap of even 120 seconds seems to me to be a very long time indeed during which no control information is sent by the client, but I have no real data to back up this hunch, so I may add some code to try to gather some information about it.
DrCWO commented 2 weeks ago

Hi again, I started playback with session_timeout = 300 and will report back. Thanks' for your support 👍

DrCWO commented 2 weeks ago

test started 8:13... Shows no improvement for me.

Nov 04 10:13:42 rooExtend shairport-sync[1116982]:          8.021130033 "player.c:2656"       0        0          0             0           136           150      44100.00       44100.30               5.40
Nov 04 10:13:50 rooExtend shairport-sync[1116982]:          7.986789106 "player.c:2656"       0        0          0             0           138           150      44100.00       44100.27               5.40
Nov 04 10:13:58 rooExtend shairport-sync[1116982]:          8.017723643 "player.c:2656"       0        0          0             0           136           150      44100.00       44100.28               5.38
Nov 04 10:14:00 rooExtend shairport-sync[1116982]:          2.325624591 "player.c:1807" Connection 1: Playback stopped. Total playing time 01:57:43.
Nov 04 10:14:00 rooExtend shairport-sync[1116982]:          0.014481038 "rtsp.c:1189" AP1 read result 0, for a request count of 262144.
DrCWO commented 2 weeks ago

Sorry this was the prod release. Will redo with the development...

mikebrady commented 2 weeks ago

Hello again. Looking at the logs once again, it seems that the connection is dropped after playback is stopped. This is important:

What I had been concerned about was that Shairport Sync was seeing the connection being dropped -- potentially due to network problems -- and was performing the TEARDOWN to clean up afterwards. But it appears that the connection is dropped after TEARDOWN, making that scenario unlikely.

Looking at the new logs, the order of events seems to be:

  1. The client requests that the connection be terminated by sending a TEARDOWN request.
  2. The TEARDOWN request is processed by Shairport Sync, logging the Connection <n>: Playback stopped... message as it does so.
  3. Having completed the teardown, Shairport Sync sends an acknowledgement back to the client.
  4. In response, the client closes the connection at its own (client) end.
  5. Shairport Sync notices that the connection has been closed by the client, logs the message AP1 read result 0, for a request count of .... and closes the connection at its (server) end.

On the face of it, this means that, for some reason, the client is stopping the play session. The reason for this remains a mystery!

DrCWO commented 2 weeks ago

Ok, I understand. Seems the browser stops playback after approx. two hours. This is the latest result starting at 10:43 with the dev release.

Any futther ideas what can be done?

I will try with Google Chrome on the iPad now...

Nov 04 12:11:50 rooExtend shairport-sync[1151906]:          8.016564996 "player.c:2656"       0      105          0             2           136           150      44100.00       44100.28               3.27
Nov 04 12:11:58 rooExtend shairport-sync[1151906]:          7.985581421 "player.c:2656"       0      105          0             2           136           150      44100.00       44100.25               3.27
Nov 04 12:12:06 rooExtend shairport-sync[1151906]:          8.023895032 "player.c:2656"       0      105          0             2           136           150      44100.00       44100.24               3.23
Nov 04 12:12:14 rooExtend shairport-sync[1151906]:          7.984811625 "player.c:2656"       0      105          0             2           136           150      44100.00       44100.28               3.05
Nov 04 12:12:22 rooExtend shairport-sync[1151906]:          8.022409014 "player.c:2656"       0      105          0             2           136           150      44100.00       44100.28               3.09
Nov 04 12:12:30 rooExtend shairport-sync[1151906]:          7.988007865 "player.c:2656"       0      105          0             2           136           150      44100.00       44100.23               3.09
Nov 04 12:12:38 rooExtend shairport-sync[1151906]:          8.013603662 "player.c:2656"       0      105          0             2           136           150      44100.00       44100.29               3.09
Nov 04 12:12:46 rooExtend shairport-sync[1151906]:          8.018942070 "player.c:2656"       0      105          0             2           136           150      44100.00       44100.25               3.04
Nov 04 12:12:54 rooExtend shairport-sync[1151906]:          7.323373384 "player.c:1807" Connection 1: Playback stopped. Total playing time 01:29:14.
Nov 04 12:12:54 rooExtend shairport-sync[1151906]:          0.014327889 "rtsp.c:1189" AP1 read result 0, for a request count of 262144.
Nov 04 12:12:54 rooExtend shairport-sync[1151906]:          0.000607167 "rtsp.c:1196" Connection 1: read result 0, error 11: "Resource temporarily unavailable".
DrCWO commented 2 weeks ago

Chrome Browser is even worse. Next try with firefox...

Nov 04 13:31:24 rooExtend shairport-sync[1151906]:          0.000198871 "rtsp.c:1196" Connection 3: read result 0, error 11: "Resource temporarily unavailable".
Nov 04 13:31:43 rooExtend shairport-sync[1151906]:         19.809802488 "player.c:2656" Missing |   Late | Too Late | Resend Reqs | Min Buffers | Max Buffers | Nominal FPS | Received FPS | Source Drift PPM
Nov 04 13:31:43 rooExtend shairport-sync[1151906]:          0.002810296 "player.c:2656"       0        0          0             0           138           234      44099.89       44392.94               3.04
Nov 04 13:31:51 rooExtend shairport-sync[1151906]:          7.986708366 "player.c:2656"       0        0          0             0           136           150      44100.00       44189.38               3.04
Nov 04 13:31:59 rooExtend shairport-sync[1151906]:          8.022106180 "player.c:2656"       0        0          0             0           136           150      44099.97       44155.42               3.04
Nov 04 13:32:07 rooExtend shairport-sync[1151906]:          8.019166329 "player.c:2656"       0        0          0             0           136           150      44099.97       44144.30               3.04
Nov 04 13:32:15 rooExtend shairport-sync[1151906]:          7.987262439 "player.c:2656"       0       70          0             2            90           150      44100.00       44128.63               3.04
Nov 04 13:32:23 rooExtend shairport-sync[1151906]:          8.011604422 "player.c:2656"       0       70          0             2           136           150      44099.98       44046.86               3.04
Nov 04 13:32:31 rooExtend shairport-sync[1151906]:          7.992409458 "player.c:2656"       0       70          0             2           136           150      44099.99       44125.65               3.04
Nov 04 13:32:39 rooExtend shairport-sync[1151906]:          8.015396273 "player.c:2656"       0      195          0             4            46           150      44100.00       44121.06               3.04
Nov 04 13:32:48 rooExtend shairport-sync[1151906]:          8.022319699 "player.c:2656"       0      323          0             6            46           150      44099.99       44118.60               3.04
Nov 04 13:32:55 rooExtend shairport-sync[1151906]:          7.989878069 "player.c:2656"       0      440          0             8            57           150      44099.99       44116.83               3.04
Nov 04 13:33:04 rooExtend shairport-sync[1151906]:          8.013264477 "player.c:2656"       0      440          0             8           138           150      44100.00       44115.05               3.04
Nov 04 13:33:12 rooExtend shairport-sync[1151906]:          7.987519791 "player.c:2656"       0      440          0             8           136           150      44100.00       44114.91               3.04
Nov 04 13:33:20 rooExtend shairport-sync[1151906]:          8.020543421 "player.c:2656"       0      440          0             8           138           150      44099.99       44114.35               3.04
Nov 04 13:33:28 rooExtend shairport-sync[1151906]:          8.018611014 "player.c:2656"       0      475          0             9           102           150      44099.99       44111.50               3.04
Nov 04 13:33:36 rooExtend shairport-sync[1151906]:          7.987702162 "player.c:2656"       0      475          0             9           136           149      44099.99       44111.52               3.04
Nov 04 13:33:44 rooExtend shairport-sync[1151906]:          8.017402273 "player.c:2656"       0      533          0            10            78           150      44100.00       44106.47               3.04
Nov 04 13:33:52 rooExtend shairport-sync[1151906]:          7.989841329 "player.c:2656"       0      533          0            10           136           150      44100.00       44108.75               3.04
Nov 04 13:34:00 rooExtend shairport-sync[1151906]:          8.018617495 "player.c:2656"       0      650          0            12            57           150      44100.00       44109.33               3.04
Nov 04 13:34:08 rooExtend shairport-sync[1151906]:          7.987647736 "player.c:2656"       0      650          0            12           136           149      44099.99       44109.53               3.04
Nov 04 13:34:16 rooExtend shairport-sync[1151906]:          8.018278180 "player.c:2656"       0      650          0            12           136           150      44100.00       44107.84               3.04
Nov 04 13:34:24 rooExtend shairport-sync[1151906]:          7.989856421 "player.c:2656"       0      650          0            12           136           150      44100.00       44107.49               3.04
Nov 04 13:34:33 rooExtend shairport-sync[1151906]:          9.592666291 "player.c:2656"       0      650          0            12             0           150      44100.13       44087.17               3.04
Nov 04 13:34:39 rooExtend shairport-sync[1151906]:          6.313058311 "player.c:1807" Connection 4: Playback stopped. Total playing time 00:03:03.
Nov 04 13:34:39 rooExtend shairport-sync[1151906]:          0.012161944 "rtsp.c:1189" AP1 read result 0, for a request count of 262144.
Nov 04 13:34:39 rooExtend shairport-sync[1151906]:          0.000198223 "rtsp.c:1196" Connection 4: read result 0, error 11: "Resource temporarily unavailable".
mikebrady commented 2 weeks ago

Thanks. The most recent log is in line with what I expect, and it suggests again that the client is stopping the session for some reason.

One wonders if the same thing happens with other clients. I have used a number different radio clients, including "Broadcasts" by Steven Troughton-Smith and of course the Apple Music app. They have worked for me over long periods, including overnight, on stations such as "RTÉ Gold", "Radio Svizzera Classica", "Radio Swiss Jazz". Occasionally, they do stop unexpectedly, but it's not a common occurrence. It might be worth a try.

DrCWO commented 2 weeks ago

This is what I get with firefox, not much better :-(


Nov 04 13:50:55 rooExtend shairport-sync[1151906]:          7.985735773 "player.c:2656"       0      105          0             4           136           150      44100.00       44100.58               4.30
Nov 04 13:51:03 rooExtend shairport-sync[1151906]:          8.018985014 "player.c:2656"       0      105          0             4           136           150      44100.00       44100.32               4.30
Nov 04 13:51:11 rooExtend shairport-sync[1151906]:          8.017932051 "player.c:2656"       0      105          0             4           136           150      44100.00       44100.49               4.24
Nov 04 13:51:19 rooExtend shairport-sync[1151906]:          7.987139792 "player.c:2656"       0      105          0             4           136           150      44100.00       44100.21               4.21
Nov 04 13:51:27 rooExtend shairport-sync[1151906]:          8.017315384 "player.c:2656"       0      105          0             4           135           150      44100.00       44100.45               4.21
Nov 04 13:51:35 rooExtend shairport-sync[1151906]:          7.990830865 "player.c:2656"       0      105          0             4           138           150      44100.00       44100.41               4.18
Nov 04 13:51:43 rooExtend shairport-sync[1151906]:          8.020171644 "player.c:2656"       0      105          0             4           136           150      44100.00       44100.49               4.18
Nov 04 13:51:51 rooExtend shairport-sync[1151906]:          7.987205217 "player.c:2656"       0      199          0             5            45           150      44100.00       44100.24               4.05
Nov 04 13:51:59 rooExtend shairport-sync[1151906]:          8.015723662 "player.c:2656"       0      199          0             5           136           150      44100.00       44100.49               4.11
Nov 04 13:52:07 rooExtend shairport-sync[1151906]:          8.020689273 "player.c:2656"       0      199          0             5           136           150      44100.00       44100.16               4.11
Nov 04 13:52:15 rooExtend shairport-sync[1151906]:          7.986757514 "player.c:2656"       0      199          0             5           134           150      44100.00       44100.31               4.11
Nov 04 13:52:24 rooExtend shairport-sync[1151906]:          9.599834327 "player.c:2656"       0      269          0             6             0           150      44100.06       44100.44               4.13
Nov 04 13:52:32 rooExtend shairport-sync[1151906]:          7.982910125 "player.c:2656"       0      269          0             6           136           150      44100.01       44100.38               4.13
Nov 04 13:52:33 rooExtend shairport-sync[1151906]:          1.073502740 "player.c:1807" Connection 5: Playback stopped. Total playing time 00:15:46.
Nov 04 13:52:33 rooExtend shairport-sync[1151906]:          0.009928204 "rtsp.c:1189" AP1 read result 0, for a request count of 262144.
Nov 04 13:52:33 rooExtend shairport-sync[1151906]:          0.000226389 "rtsp.c:1196" Connection 5: read result 0, error 11: "Resource temporarily unavailable".
mikebrady commented 2 weeks ago

This is what I get with firefox, not much better :-(

Yeah, not very promising...

mikebrady commented 2 weeks ago

Hmm, another thing I'd expect to see if the network was a problem for Shairport Sync would be diagnostics indicating that UDP-based timing packets were being lost or delayed, like this:

0.635820463 "rtp.c:1085" Time ping turnaround time: 342387093 ns -- it looks like a timing ping was lost.
DrCWO commented 2 weeks ago

Never saw this. I will try to run Qobuz over the night. But I saw this client works different. It downloads the whole track at the beginning so there will be no issues regarding internet to the radio station. Seems to be much more stable. I also think ALAC is sent ...

DrCWO commented 2 weeks ago

Maybe this is an important observation 👍

If I look at the last line of all my latest tests I always see this: ...for a request count of 262144. Does this mean that after 262144 requests the connection breaks? 262144 = 2^18! Maybe a counter overflows after that number of requests?

EDIT: I also found this nubmer inside a JSON on this page: https://github.com/mikebrady/shairport-sync/issues/1634 an on this page: https://github.com/mikebrady/shairport-sync/issues/1551

EDIT2: No idea if this might have any connection to the issue...

root@rooExtend:/home/pi# dmesg | grep 262144
[    0.000000] Dentry cache hash table entries: 262144 (order: 9, 2097152 bytes, linear)
[    0.137223] IP idents hash table entries: 32768 (order: 6, 262144 bytes, linear)
[    0.138105] Table-perturb hash table entries: 65536 (order: 6, 262144 bytes, linear)
[    0.138209] TCP bind hash table entries: 16384 (order: 6, 262144 bytes, linear)
mikebrady commented 2 weeks ago

Thanks for your updates. The number 262144 is just the size of the RAM buffer that the read() function can copy bytes into, nothing more.

I believe that the issues you refer to are not relevant to this situation: The first issue seems to have been a problem with a router, and the second had to do with Shairport Sync crashing if an expected item of information was missing. That crashing behaviour has been fixed, and in any case it not a feature of your situation.

The dmesg entries don't originate from Shairport Sync.

DrCWO commented 1 week ago

Yesterday I listened to Radio Swiss Jazz with the PlaySrf app for over six hours. There was no interruption.

To sum it up:

  1. I now believe the problem is caused by WiFi and/or streaming from the source app to Airplay.
  2. Another reason could be internet delays from the radio server to the app on the iPad.
  3. I don't think shairport-sync or rooPlay are the reason for interrupted radio streams.

@mikebrady: Is that your opinion too?

If so, I think we should close this issue.

What I now plan to do on the rooPlay side is adding an optional setting to automatically re-start dropped streams 👍

mikebrady commented 1 week ago

Thanks for the update. I am inclined to agree with your conclusions, yes.

DrCWO commented 1 week ago

I'm sorry to have bothered you with this but I really thought it was an issue in Shairport-Sync. Thank you very much for this outstanding software and all the work you put into it 🥇 💯 👍

If you are a Roon user and would like to try rooExtend, please contact me at info@definiteaudio.de. Of course, I will provide you with all the licenses you need free of charge 👍

Best DrCWO

mikebrady commented 1 week ago

Many thanks!

mikebrady commented 1 week ago

Is it okay to close this issue now?

DrCWO commented 1 week ago

Yes please 👍