Owntone intermittent Airplay to Shairport-sync

kevocl commented 2 years ago

What happened?

Not sure where the issue lies with this one, as it is regarding Owntone (latest docker image from linuxserver.io - forked-daapd) and Shairport-Sync (latest developement docker image from mikebrady)

When I try to play from Owntone to Shairport-Sync using Airplay 1, it plays for about 2 seconds and then stops for 20 seconds. This behaviour then repeats.

I've used Owntone in Docker before and everything was perfect, but then my HDD crashed and I had to rebuild everything. Playback from iOS devices to the same shairport-sync device is perfect.

I realise this could well be an Owntone/Linuxserver.io issue.

Thanks

Relevant log output

0.008598854 "rtsp.c:2543" Connection 28: Unhandled POST /auth-setup Content-Length 33
         0.005410834 "rtsp.c:4407" Connection 28. AirPlay 1 Audio Stream Detected.
         0.006442760 "rtsp.c:1622" Connection 28: AP1 ALAC Stream, from 10.0.0.100:50658 to self at 10.0.0.71:7000.
         2.157125781 "player.c:2734" Connection 28: Playback Started -- AirPlay 1 Compatible.
         3.940485936 "rtsp.c:1281" Connection 28: RTSP connection is idle.
        18.942753742 "rtsp.c:1294" Connection 28: RTSP connection traffic has resumed.
         0.221557917 "audio_alsa.c:1776" alsa: recovering from a previous underrun.
         3.795490832 "rtsp.c:1281" Connection 28: RTSP connection is idle.
^[[A        18.704218951 "rtsp.c:1341" Connection 25: Closed by client: from fe80::452:bfd8:4:d9:52163 to self at fe80::aff0:992a:1f08:ca2e:7000.
         2.289117395 "rtsp.c:1294" Connection 28: RTSP connection traffic has resumed.
         0.421116510 "audio_alsa.c:1776" alsa: recovering from a previous underrun.
         3.625384999 "rtsp.c:1281" Connection 28: RTSP connection is idle.
         0.000108906 "player.c:2574" Sync Error ms | Net Sync PPM | All Sync PPM | Missing |   Late | Too Late | Resend Reqs | Min DAC Queue | Min Buffers | Max Buffers | Nominal FPS | Received FPS | Output FPS (r) | Output FPS (c) | Source Drift PPM | Drift Samples
         0.000122708 "player.c:2574"         -0.06            0.0            0.0         0        0          0             0            8190           255           256      44100.00           0.00              N/A              N/A               0.00               0
         0.000178594 "rtp.c:1125" no anchor information
        20.963263482 "rtsp.c:1294" Connection 28: RTSP connection traffic has resumed.
         0.631375833 "audio_alsa.c:1776" alsa: recovering from a previous underrun.
         3.444795571 "rtsp.c:1281" Connection 28: RTSP connection is idle.
         6.806196664 "rtsp.c:1294" Connection 28: RTSP connection traffic has resumed.
         4.073747864 "rtsp.c:1281" Connection 28: RTSP connection is idle.
         5.934214268 "rtsp.c:1294" Connection 28: RTSP connection traffic has resumed.
         0.014510313 "player.c:1730" Connection 28: Playback Stopped. Total playing time 00:01:33.
         0.008411718 "rtsp.c:1341" Connection 28: Closed by client: from 10.0.0.100:50658 to self at 10.0.0.71:7000.

Operating System?

Owntone is on - Linux Alfred 5.15.49-v7l+ #1566 SMP Fri Jun 24 19:02:20 BST 2022 armv7l GNU/Linux Shairport is on - Linux Kitchen 5.10.103-v7+ #1529 SMP Tue Mar 8 12:21:37 GMT 2022 armv7l GNU/Linux

Version?

4.1-dev-533-g694c9f5a-dirty-AirPlay2-alac-OpenSSL-Avahi-ALSA-dummy-stdout-pipe-soxr-convolution-metadata-mqtt-dbus-mpris-sysconfdir:/etc

How did you install Shairport Sync?

Docker

Check previous issues

[X] Confirm

mikebrady commented 2 years ago

Thanks. I think you should check with OwnTone, but I’m pretty sure that it is not compatible with the versions of AirPlay 2 that Shairport Sync supports. If you build Shairport Sync without AirPlay 2 support, does it work normally with OwnTone?

kevocl commented 2 years ago

Thanks Mike,

I pulled the Airplay 1 shairport-sync docker image and Owntone plays perfectly to it. I know if I disable RAOP in the owntone.conf, effectively forcing Airplay 2, it won't play to shairport-sync because it uses 'NTP streams'.

mikebrady commented 2 years ago

Thanks -- that's right. AirPlay 2 seems to be capable of using NTP-based or PTP-based timing, but most clients seem to use PTP. While Shairport Sync only has to use PTP signals, an application like OwnTone would have to generate the right signals, and figuring those out is challenging.

kevocl commented 2 years ago

I've contacted the Owntone project about this today.

Interestingly I updated Shairport-Sync - trying both docker and building/running natively - to 4.1-dev-540-g40654624-AirPlay2-OpenSSL-Avahi-ALSA-soxr-sysconfdir:/etc and the music plays for 24 seconds now, and then drops for 2. Which is an improvement, but still not ideal.

ejurgensen commented 2 years ago

Owntone will default to Airplay 1 if it is available, and I suppose SPS AP1 is about the same in the development branch as in master, right?

The logs seems to indicate the connection is idle and there is an alsa underrum. Is that a correct interpretation @mikebrady?

mikebrady commented 2 years ago

Owntone will default to Airplay 1 if it is available, and I suppose SPS AP1 is about the same in the development branch as in master, right?

Yes, SPS AP1 is substantially the same in the development branch as in the master branch, but with bug fixes and changes to accommodate the AirPlay 2 extensions.

The logs seems to indicate the connection is idle and there is an alsa underrum. Is that a correct interpretation @mikebrady?

Yes, the lines:

         3.444795571 "rtsp.c:1281" Connection 28: RTSP connection is idle.
         6.806196664 "rtsp.c:1294" Connection 28: RTSP connection traffic has resumed.

indicate that the RTSP TCP link that governs the connection between the client and the Shairport Sync player has had no traffic on it for about five seconds. It seems to be the case that there should be traffic on it every few seconds, so this might (?) indicate that the client is sleeping; for example, it might be a Mac that has gone to sleep. TBH I'm not sure if it's a reliable indicator. If only we had a specification... 😔.

iVolt1 commented 2 years ago

I am seeing a similar issue with any SPS version greater than 3.3.8. That version works fine on Pi zer0 W and a Pi 4.

The symptoms for SPS versions greater than 3.3.8 is random one or two second dropouts when playing from OwnTone.

I can provide logs from SPS or OwnTone, but I don't know what would the best type of logging to provide so I would appreciate any guidance with that. I can also compile any new code to test as needed.

Thanks for the two great projects that I use every day together.

mikebrady commented 2 years ago

Thanks for the information. Yeah, to begin with, logs from when the problem is occurring from SPS with a verbosity of 1 and statistics enabled would be a good starting point, as well as the Shairport Sync version string ($ shairport-sync -V).

Many thanks.

iVolt1 commented 2 years ago

Hi Mike. Here are my logs. Thanks for looking into this.

3.3.8-OpenSSL-Avahi-ALSA-pipe-metadata-sysconfdir:/etc. I changed vlume a couple of times during this run.

I don't have version info for 4.1 rco but here are the compile flags. 4-1-rc0 ./configure --sysconfdir=/etc --with-alsa --with-soxr --with-avahi --with-ssl=openssl --with-systemd --with-metadata

3-3-8_log.txt 4-1-rc0_log.txt

mikebrady commented 2 years ago

There is some weirdness with the latencies. To explore it, would you be kind enough to add in an extra debug line after line 470 in rip.c, so that it looks like this:

                  if (la != conn->latency) {
                    conn->latency = la;
                    debug(1,"sync_rtp_timestamp: %" PRIu32 ", rtp_timestamp_less_latency: %" PRIu32 ", latency: %u.", sync_rtp_timestamp, rtp_timestamp_less_latency, la);
                    debug(2,
                          "New latency: %" PRIu32 ", sync latency: %" PRIu32

and then build and run it and see what comes back?

iVolt1 commented 2 years ago

Here is the log with the new debug line. I tested owntone with a local music file and it had the same drop outs as is happening from the usual music piped in from librespotjava.

4-1-rc0_rtpc_debug_log.txt

mikebrady commented 2 years ago

Thanks. This is it with the Music app in iOS as a client:

       15.576271713 "rtsp.c:5463" Connection 3: New connection from fe80::be:f12e:7cd5:dfd6:55092 to self at fe80::6e9:be61:2641:855a:5000.
         0.007730208 "rtsp.c:2595" OPTIONS request
         0.000106771 "rtsp.c:2595"   Type: "CSeq", content: "0"
         0.000041094 "rtsp.c:2595"   Type: "DACP-ID", content: "CABA097D6433EFBC"
         0.000036146 "rtsp.c:2595"   Type: "Active-Remote", content: "4255191847"
         0.000034531 "rtsp.c:2595"   Type: "User-Agent", content: "AirPlay/635.87.3"
         0.000034896 "rtsp.c:2595"   No Content Plist. Content length: 0.
         0.009231041 "rtsp.c:2595" OPTIONS request
         0.000088073 "rtsp.c:2595"   Type: "CSeq", content: "1"
         0.000055521 "rtsp.c:2595"   Type: "DACP-ID", content: "CABA097D6433EFBC"
         0.000037240 "rtsp.c:2595"   Type: "Active-Remote", content: "4255191847"
         0.000034843 "rtsp.c:2595"   Type: "User-Agent", content: "AirPlay/635.87.3"
         0.000036927 "rtsp.c:2595"   No Content Plist. Content length: 0.
         0.037941355 "rtsp.c:2595" OPTIONS request
         0.000081979 "rtsp.c:2595"   Type: "Apple-Challenge", content: "B5KdOhgLe+dyF5k1Ur9sQQ=="
         0.000043750 "rtsp.c:2595"   Type: "CSeq", content: "2"
         0.000035156 "rtsp.c:2595"   Type: "DACP-ID", content: "CABA097D6433EFBC"
         0.000034740 "rtsp.c:2595"   Type: "Active-Remote", content: "4255191847"
         0.000034375 "rtsp.c:2595"   Type: "User-Agent", content: "AirPlay/635.87.3"
         0.000037395 "rtsp.c:2595"   No Content Plist. Content length: 0.
         0.016816823 "rtsp.c:557" Connection 3: request play lock.
         0.000114115 "rtsp.c:624" Connection 3: Got player lock.
         0.029250052 "rtsp.c:4598" Play connection from user agent "AirPlay/635.87.3" on RTSP conversation thread 3.
         0.000090365 "rtsp.c:4608" AirPlay version 635 detected.
         0.011727031 "rtsp.c:3368" Connection 3: SETUP: Active-Remote string seen: "4255191847".
         0.000298385 "rtsp.c:3388" Connection 3: SETUP: DACP-ID string seen: "CABA097D6433EFBC".
         0.000471459 "rtp.c:1037" Connection 3: SETUP -- Connection from fe80::be:f12e:7cd5:dfd6 to self at fe80::6e9:be61:2641:855a.
         0.000207864 "rtsp.c:3450" Connection 3: SETUP DACP-ID "CABA097D6433EFBC" from fe80::be:f12e:7cd5:dfd6 to fe80::6e9:be61:2641:855a with UDP ports Control: 6007, Timing: 6008 and Audio: 6009.
         0.008211198 "rtsp.c:1620" Connection 3: RECORD
         0.000064688 "rtsp.c:1625" Connection 3: AP1 ALAC Stream, from fe80::be:f12e:7cd5:dfd6:55092 to self at fe80::6e9:be61:2641:855a:5000.
         0.004124948 "activity_monitor.c:64" abeg
         0.001781510 "activity_monitor.c:175" am_state: am_active
         0.000584583 "player.c:3461" pbeg
         0.007025990 "rtp.c:324" rtp_control_receiver start
         0.000054531 "player.c:2182" Set initial volume to -20.000000.
         0.000297188 "player.c:3317" Software attenuation set to -3150.000000, i.e 1743.732775 out of 65,536, for airplay volume of -20.000000
         0.000054739 "loudness.c:47" Volume: -31.5 dB - Loudness gain @10Hz: 5.8 dB
         0.000089896 "player.c:3358" player_volume_without_notification: volume mode is 0, airplay volume is -20.00, software_attenuation dB: -31.50, hardware_attenuation dB: 0.00, muting is disabled.
         0.000035417 "player.c:2185" Play begin
         0.000443073 "rtp.c:587" rtp_timing_sender start
         0.000060729 "rtp.c:613" AP1 clock sender thread: initialised.
         0.004760781 "rtp.c:540" Sync packet received before we got a timing packet back.
         0.002169792 "rtp.c:754" AP1 clock receiver thread: initialised.
         0.000078073 "rtp.c:775" clock synchronisation request: return time is    6.985 milliseconds.
         0.021693281 "player.c:435" Connection 3: synced by first packet, seqno 24980.
         0.000071719 "player.c:169" Hammerton Decoder used on encrypted audio.
         0.015503593 "rtsp.c:2774" FLUSH request
         0.000052917 "rtsp.c:2774"   Type: "RTP-Info", content: "seq=24980;rtptime=210068874"
         0.000027969 "rtsp.c:2774"   Type: "CSeq", content: "6"
         0.000023125 "rtsp.c:2774"   Type: "DACP-ID", content: "CABA097D6433EFBC"
         0.000022500 "rtsp.c:2774"   Type: "Active-Remote", content: "4255191847"
         0.000021979 "rtsp.c:2774"   Type: "User-Agent", content: "AirPlay/635.87.3"
         0.000022344 "rtsp.c:2774"   No Content Plist. Content length: 0.
         0.000029270 "rtsp.c:2790" RTSP Flush Requested: 210068874.
         0.260127917 "rtp.c:775" clock synchronisation request: return time is    4.413 milliseconds.
         0.302753802 "rtp.c:775" clock synchronisation request: return time is    7.022 milliseconds.
         0.299105833 "rtp.c:775" clock synchronisation request: return time is    5.981 milliseconds.
         0.397780573 "rtp.c:471" sync_rtp_timestamp: 210124147, rtp_timestamp_less_latency: 210046972, latency: 88200.
         0.000114844 "rtp.c:472" New latency: 88200, sync latency: 77175, minimum latency: 11025, maximum latency: 88200, fixed offset: 11025, audio_backend_latency_offset: 0.000000.
         0.000052083 "rtp.c:519" AP1 control thread: set_ntp_anchor_info: rtptime: 210035947, networktime: 1ea8e3c3f7867ab5.
         0.003806146 "player.c:907" flush request: flush output device.
         0.000065521 "player.c:1023" flush request: flush frame 210068874 expired -- buffer contains 56672 frames, from 210068874 to 210125545
         0.000055208 "player.c:1082" Accepting packet 24980 with timestamp 210068874. Lead time is 0.740113 seconds.
         0.000051875 "player.c:1156" Connection 3: Lead time for first frame 210068874: 0.740100 seconds.
         0.000045417 "player.c:1160" pffr
         0.069041510 "metadata_hub.c:514" MH Picture received, length 86663 bytes.
         0.008245469 "metadata_hub.c:551" MH Progress String set to: "208993752/210040866/214134232"
         0.008538385 "metadata_hub.c:506" MH Metadata stream processing start.
         0.000075834 "metadata_hub.c:353" MH Item ID seen: "214eb5a54c3b933b" of length 8.
         0.000589270 "metadata_hub.c:364" MH Song Time seen: "116564" of length 4.
         0.000058073 "metadata_hub.c:510" MH Metadata stream processing end.
         0.473120156 "player.c:1306" prsm
         0.068204323 "player.c:2695" first frame sync error (positive --> late): -4 frames, -0.091 mS at 44100 frames per second output.
         0.000108855 "player.c:2714" final sync adjustment: 12 silent frames added with a bias of 8 frames.
         0.000346875 "player.c:2744" Connection 3: Playback Started -- AirPlay 1.
         0.102091718 "rtsp.c:2595" OPTIONS request
         0.000085886 "rtsp.c:2595"   Type: "CSeq", content: "10"
         0.000044739 "rtsp.c:2595"   Type: "DACP-ID", content: "CABA097D6433EFBC"
         0.000040104 "rtsp.c:2595"   Type: "Active-Remote", content: "4255191847"
         0.000039063 "rtsp.c:2595"   Type: "User-Agent", content: "AirPlay/635.87.3"
         0.000039896 "rtsp.c:2595"   No Content Plist. Content length: 0.
         0.273912343 "rtp.c:517" AP1 control thread: set_ntp_anchor_info: rtptime: 210080128, networktime: 1ea8e3c4333d5065, frame adjustment:  -0.056.
         1.593677552 "rtp.c:775" clock synchronisation request: return time is    6.057 milliseconds.
         0.147409375 "rtsp.c:2595" OPTIONS request
         0.000096458 "rtsp.c:2595"   Type: "CSeq", content: "11"
         0.000044427 "rtsp.c:2595"   Type: "DACP-ID", content: "CABA097D6433EFBC"
         0.000037344 "rtsp.c:2595"   Type: "Active-Remote", content: "4255191847"
         0.000038437 "rtsp.c:2595"   Type: "User-Agent", content: "AirPlay/635.87.3"
         0.000041250 "rtsp.c:2595"   No Content Plist. Content length: 0.
         0.250600313 "rtp.c:517" AP1 control thread: set_ntp_anchor_info: rtptime: 210168289, networktime: 1ea8e3c4aa659990, frame adjustment:  -0.583.
         1.767406041 "rtsp.c:2595" OPTIONS request
         0.000097292 "rtsp.c:2595"   Type: "CSeq", content: "12"
         0.000049375 "rtsp.c:2595"   Type: "DACP-ID", content: "CABA097D6433EFBC"
         0.000040000 "rtsp.c:2595"   Type: "Active-Remote", content: "4255191847"
         0.000040625 "rtsp.c:2595"   Type: "User-Agent", content: "AirPlay/635.87.3"
         0.000039947 "rtsp.c:2595"   No Content Plist. Content length: 0.
         0.250182605 "rtp.c:517" AP1 control thread: set_ntp_anchor_info: rtptime: 210257244, networktime: 1ea8e3c522a024b1, frame adjustment:   0.774.
         0.583502447 "rtp.c:775" clock synchronisation request: return time is    5.521 milliseconds.
         0.437887760 "rtp.c:517" AP1 control thread: set_ntp_anchor_info: rtptime: 210302096, networktime: 1ea8e3c55f3f1265, frame adjustment:   0.161.
         0.728133177 "rtsp.c:2595" OPTIONS request
         0.000100573 "rtsp.c:2595"   Type: "CSeq", content: "13"
         0.000044844 "rtsp.c:2595"   Type: "DACP-ID", content: "CABA097D6433EFBC"
         0.000040000 "rtsp.c:2595"   Type: "Active-Remote", content: "4255191847"
         0.000038698 "rtsp.c:2595"   Type: "User-Agent", content: "AirPlay/635.87.3"
         0.000040781 "rtsp.c:2595"   No Content Plist. Content length: 0.
         1.249747916 "rtp.c:517" AP1 control thread: set_ntp_anchor_info: rtptime: 210389547, networktime: 1ea8e3c5d5718963, frame adjustment:  -0.127.
         0.533654063 "player.c:2574" Sync Error ms | Net Sync PPM | All Sync PPM | Missing |   Late | Too Late | Resend Reqs | Min DAC Queue | Min Buffers | Max Buffers | Nominal FPS | Received FPS | Output FPS (r) | Output FPS (c) | Source Drift PPM | Drift Samples
         0.000168958 "player.c:2574"          0.04            0.0            0.0         0        0          0             0            7480           226           232      44100.05       44139.68              N/A              N/A               0.00               0
         0.051833021 "rtp.c:775" clock synchronisation request: return time is    7.045 milliseconds.
         0.264868437 "rtsp.c:2595" OPTIONS request
         0.000094688 "rtsp.c:2595"   Type: "CSeq", content: "14"
         0.000044010 "rtsp.c:2595"   Type: "DACP-ID", content: "CABA097D6433EFBC"
         0.000036250 "rtsp.c:2595"   Type: "Active-Remote", content: "4255191847"
         0.000035938 "rtsp.c:2595"   Type: "User-Agent", content: "AirPlay/635.87.3"
         0.000035000 "rtsp.c:2595"   No Content Plist. Content length: 0.
         0.149928124 "rtp.c:517" AP1 control thread: set_ntp_anchor_info: rtptime: 210433654, networktime: 1ea8e3c6110ecbb6, frame adjustment:  -0.139.
         0.999436511 "rtp.c:517" AP1 control thread: set_ntp_anchor_info: rtptime: 210477755, networktime: 1ea8e3c64ca9ef11, frame adjustment:  -0.009.
         0.867421926 "rtsp.c:2595" OPTIONS request
         0.000098594 "rtsp.c:2595"   Type: "CSeq", content: "15"
         0.000047604 "rtsp.c:2595"   Type: "DACP-ID", content: "CABA097D6433EFBC"
         0.000041146 "rtsp.c:2595"   Type: "Active-Remote", content: "4255191847"
         0.000037813 "rtsp.c:2595"   Type: "User-Agent", content: "AirPlay/635.87.3"
         0.000038333 "rtsp.c:2595"   No Content Plist. Content length: 0.
         0.149732604 "rtp.c:517" AP1 control thread: set_ntp_anchor_info: rtptime: 210522600, networktime: 1ea8e3c68946879a, frame adjustment:  -0.097.
         0.567905260 "rtp.c:775" clock synchronisation request: return time is    6.614 milliseconds.
         1.244820677 "rtsp.c:2595" OPTIONS request
         0.000097500 "rtsp.c:2595"   Type: "CSeq", content: "16"
         0.000047187 "rtsp.c:2595"   Type: "DACP-ID", content: "CABA097D6433EFBC"
         0.000040417 "rtsp.c:2595"   Type: "Active-Remote", content: "4255191847"
         0.000040156 "rtsp.c:2595"   Type: "User-Agent", content: "AirPlay/635.87.3"
         0.000039063 "rtsp.c:2595"   No Content Plist. Content length: 0.
         0.039625260 "rtp.c:517" AP1 control thread: set_ntp_anchor_info: rtptime: 210604313, networktime: 1ea8e3c6f7b78f99, frame adjustment:   0.049.
         0.000758386 "rtsp.c:2774" FLUSH request
         0.000057343 "rtsp.c:2774"   Type: "RTP-Info", content: "seq=26754;rtptime=210699026"
         0.000043177 "rtsp.c:2774"   Type: "CSeq", content: "17"
         0.000037969 "rtsp.c:2774"   Type: "DACP-ID", content: "CABA097D6433EFBC"
         0.000113594 "rtsp.c:2774"   Type: "Active-Remote", content: "4255191847"
         0.000102969 "rtsp.c:2774"   Type: "User-Agent", content: "AirPlay/635.87.3"
         0.000158281 "rtsp.c:2774"   No Content Plist. Content length: 0.
         0.000103958 "rtsp.c:2790" RTSP Flush Requested: 210699026.
         0.000158490 "player.c:3391" pfls
         0.000319427 "player.c:907" flush request: flush output device.
         0.000056667 "player.c:1012" flush request: flush frame 210699026 pending -- buffer contains 81856 frames, from 210612362 to 210694217
         0.000047604 "player.c:1045" flush request: flush done.
         0.029954323 "player.c:435" Connection 3: synced by first packet, seqno 26756.
         0.001055833 "player.c:1012" flush request: flush frame 210699026 pending -- buffer contains 1056 frames, from 210694218 to 210695273
         0.000080781 "player.c:1045" flush request: flush done.
         0.009590886 "metadata_hub.c:514" MH Picture received, length 86663 bytes.
         0.004151875 "player.c:435" Connection 3: synced by first packet, seqno 26759.
         0.001156927 "player.c:1012" flush request: flush frame 210699026 pending -- buffer contains 1056 frames, from 210695274 to 210696329
         0.000061510 "player.c:1045" flush request: flush done.
         0.005996250 "metadata_hub.c:551" MH Progress String set to: "208994452/210608130/214134932"
         0.006981042 "metadata_hub.c:506" MH Metadata stream processing start.
         0.000430312 "metadata_hub.c:353" MH Item ID seen: "214eb5a54c3b933b" of length 8.
         0.001768959 "metadata_hub.c:364" MH Song Time seen: "116564" of length 4.
         0.000387604 "metadata_hub.c:510" MH Metadata stream processing end.
         0.006375885 "player.c:435" Connection 3: synced by first packet, seqno 26762.
         0.000960313 "player.c:1012" flush request: flush frame 210699026 pending -- buffer contains 1056 frames, from 210696330 to 210697385
         0.000063125 "player.c:1045" flush request: flush done.
         0.001189687 "metadata_hub.c:506" MH Metadata stream processing start.
         0.000383958 "metadata_hub.c:353" MH Item ID seen: "214eb5a54c3b933b" of length 8.
         0.001355678 "metadata_hub.c:510" MH Metadata stream processing end.
         0.018884218 "player.c:435" Connection 3: synced by first packet, seqno 26765.
         0.000968542 "player.c:1012" flush request: flush frame 210699026 pending -- buffer contains 1056 frames, from 210697386 to 210698441
         0.000064375 "player.c:1045" flush request: flush done.
         0.023404062 "player.c:435" Connection 3: synced by first packet, seqno 26768.
         0.000945990 "player.c:947" flush request: flush frame 210699026 active -- buffer contains 1056 frames, from 210698442 to 210699497.
         0.000062292 "player.c:966" flush to 210699026 request: flush buffer 26768, from 210698442 to 210698793. ab_write is: 26771.
         0.000043385 "player.c:983" 232 frames to remove from current buffer
         0.000036875 "player.c:991" flush request: flush frame 210699026 complete -- buffer contains 1056 frames, from 210698442 to 210699497 -- flushed to 210699026 in buffer 26769, with 472 frames remaining.
         0.000050990 "player.c:1082" Accepting packet 26769 with timestamp 210699026. Lead time is 2.026803 seconds.
         0.000046458 "player.c:1156" Connection 3: Lead time for first frame 210699026: 2.026781 seconds.
         0.000041146 "player.c:1160" pffr
         1.012275677 "rtp.c:517" AP1 control thread: set_ntp_anchor_info: rtptime: 210654167, networktime: 1ea8e3c73b196930, frame adjustment:  -0.440.
         0.008649114 "player.c:1190" Change in estimated first_packet_time: 0.009977 milliseconds for first_packet .
         0.574444792 "rtp.c:775" clock synchronisation request: return time is    4.909 milliseconds.
         0.261666718 "player.c:1306" prsm
         0.038476875 "rtsp.c:2595" OPTIONS request
         0.000543959 "rtsp.c:2595"   Type: "CSeq", content: "22"
         0.000424791 "rtsp.c:2595"   Type: "DACP-ID", content: "CABA097D6433EFBC"
         0.000488698 "rtsp.c:2595"   Type: "Active-Remote", content: "4255191847"
         0.000420261 "rtsp.c:2595"   Type: "User-Agent", content: "AirPlay/635.87.3"
         0.000387083 "rtsp.c:2595"   No Content Plist. Content length: 0.
         1.130880416 "rtp.c:517" AP1 control thread: set_ntp_anchor_info: rtptime: 210743110, networktime: 1ea8e3c7b34fe323, frame adjustment:   0.529.
         0.850804687 "rtsp.c:2595" OPTIONS request
         0.000621979 "rtsp.c:2595"   Type: "CSeq", content: "23"
         0.000448959 "rtsp.c:2595"   Type: "DACP-ID", content: "CABA097D6433EFBC"
         0.000455885 "rtsp.c:2595"   Type: "Active-Remote", content: "4255191847"
         0.000414740 "rtsp.c:2595"   Type: "User-Agent", content: "AirPlay/635.87.3"
         0.000374635 "rtsp.c:2595"   No Content Plist. Content length: 0.
         0.713677083 "rtp.c:775" clock synchronisation request: return time is    4.704 milliseconds.
         0.422505417 "rtp.c:517" AP1 control thread: set_ntp_anchor_info: rtptime: 210830582, networktime: 1ea8e3c82989aa5d, frame adjustment:  -0.264.
         0.485338229 "player.c:2574"          2.20          -48.2           48.2         0        0          0             0            7752           227           232      44100.26       44423.51         44100.04         44100.10               0.00               0
         0.163295416 "rtp.c:220" Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.6,     9890.8,    46425.2.
         0.281131927 "rtsp.c:2595" OPTIONS request
         0.000604427 "rtsp.c:2595"   Type: "CSeq", content: "24"
         0.000425625 "rtsp.c:2595"   Type: "DACP-ID", content: "CABA097D6433EFBC"
         0.000410261 "rtsp.c:2595"   Type: "Active-Remote", content: "4255191847"
         0.000410417 "rtsp.c:2595"   Type: "User-Agent", content: "AirPlay/635.87.3"
         0.000369270 "rtsp.c:2595"   No Content Plist. Content length: 0.
         0.062702813 "rtp.c:517" AP1 control thread: set_ntp_anchor_info: rtptime: 210874702, networktime: 1ea8e3c8652b6702, frame adjustment:  -0.080.
         1.016416458 "rtp.c:517" AP1 control thread: set_ntp_anchor_info: rtptime: 210919526, networktime: 1ea8e3c8a1c083b1, frame adjustment:   0.532.
         0.053474166 "rtsp.c:2751" TEARDOWN request
         0.000105886 "rtsp.c:2751"   Type: "CSeq", content: "25"
         0.000039687 "rtsp.c:2751"   Type: "DACP-ID", content: "CABA097D6433EFBC"
         0.000036146 "rtsp.c:2751"   Type: "Active-Remote", content: "4255191847"
         0.000036459 "rtsp.c:2751"   Type: "User-Agent", content: "AirPlay/635.87.3"
         0.000034427 "rtsp.c:2751"   No Content Plist. Content length: 0.
         0.000033541 "rtsp.c:2752" Connection 3: TEARDOWN
         0.005339844 "player.c:1723" Connection 3: Playback Stopped. Total playing time 00:00:19. Output: 44100.04 (raw), 44100.10 (corrected) frames per second.
         0.000100729 "player.c:1774" Cancelling AP1 timing, control and audio threads...
         0.000581094 "rtp.c:320" Control Receiver Cleanup Done.
         0.000741250 "player.c:1822" Connection 3: player terminated.
         0.000293437 "player.c:3487" pend
         0.000076615 "rtsp.c:540" Connection 3: release play lock.
         0.000030417 "rtsp.c:546" Connection 3: play lock released.
         0.008883541 "rtsp.c:1344" Connection 3: Closed by client: from fe80::be:f12e:7cd5:dfd6:55092 to self at fe80::6e9:be61:2641:855a:5000.
         0.000079896 "rtsp.c:4927" Connection 3: rtsp_conversation_thread_func_cleanup_function called.
         0.000602604 "rtsp.c:5017" Connection 3: Closed.
         9.994493122 "activity_monitor.c:88" aend
         0.000778802 "activity_monitor.c:171" am_state: am_inactive

You'll see that the latency is set once (search "New latency"). When the source is OT, the latency seems to keep changing. I don't know why it should be okay on 3.3.8 but not okay on 4.1, as the code is practically the same, in that SPS looks for the two figures sync_rtp_timestamp and rtp_timestamp_less_latency in the same part of the packet. Maybe I'm missing something. Perhaps @ejurgensen of OwnTone can comment.

iVolt1 commented 2 years ago

Yes, ios spotify to the 4.1 shairport-sync works fine for me. I'll keep trying some things and let you know if find anything.

iVolt1 commented 2 years ago

Hi Mike. I compiled this version and it seems to be working without skips. I will let you know if I have any other details

4.1-dev-620-g0970df78-OpenSSL-Avahi-ALSA-sysconfdir:/etc

mikebrady commented 2 years ago

I've just been playing with this too, and the varying latencies are not the problem -- they are odd, but they are not causing the problem. The problem is that Shairport Sync now watches for a "heartbeat" from the player, mainly to see if it has gone to sleep, and it seems as if OwnTone doesn't provide one. So what I'll do is (temporarily) remove the heartbeat requirement timeout until something can be figured out.

mikebrady commented 2 years ago

Just pushed an update to the development branch with that heartbeat check disabled. If you got a chance to try it out and report back, that would be great. The build numbers are somehow out of sequence, I'm afraid.

ejurgensen commented 2 years ago

What's the heartbeat method? I couldn't see it from the commit, and I'm away so don't have the option of testing.

mikebrady commented 2 years ago

This heartbeat idea is to try to solve the problem of knowing when a client goes to sleep. Consider a scenario where the user is playing a YouTube video in a browser on a Mac laptop, on battery power only, with the Sound Output of the system directed to a Shairport Sync player. If the user closes the laptop, the system will eventually sleep and AirPlay transmission will cease. When it is opened up again, the video may resume, but getting AirPlay to resume properly is difficult because of outdated packets and changes in clock timing (I think). I haven't been able to find any warning or signal that the player has gone to sleep or that it has just woken up. This is where the heartbeat idea comes in.

In classic AirPlay and in AirPlay 2, there is always some traffic on the RTSP connection. In classic AirPlay, an "OPTIONS" message is sent every few seconds by the player, while in AP2, a "FEEDBACK" message is sent every few seconds. Both of these stop when the player goes to sleep, so I figured that their presence or absence would work as a heartbeat. So I added code to wait for long enough to get one of these messages, and if it timed out, it would be a signal that the player had stopped.

ejurgensen commented 2 years ago

In classic AirPlay, an "OPTIONS" message is sent every few seconds by the player, while in AP2, a "FEEDBACK" message is sent every few seconds

Yes, Owntone also can do this, but for AP1 it is only enabled for ATVs, since I only saw them requiring it at some point. Sending heartbeat OPTIONS wasn't originally part of AirPlay, but maybe I should now enable it for all speakers?

mikebrady commented 2 years ago

Yes, Owntone also can do this, but for AP1 it is only enabled for ATVs, since I only saw them requiring it at some point. Sending heartbeat OPTIONS wasn't originally part of AirPlay, but maybe I should now enable it for all speakers?

Very interesting, thanks. If it wasn’t inconvenient, I think it would be useful.

ejurgensen commented 2 years ago

I think old versions of iTunes also don't send heartbeats. I have an old mac with such a version, I will try with that later this week.

ejurgensen commented 2 years ago

Checked Owntone's code and it seems I misremembered. With AP1, Owntone uses SET_PARAMETER with progress metadata as heartbeat, not OPTIONS. It is also looks to be enabled for all speakers, not just the ATV.

mikebrady commented 2 years ago

Checked Owntone's code and it seems I misremembered. With AP1, Owntone uses SET_PARAMETER with progress metadata as heartbeat, not OPTIONS. It is also looks to be enabled for all speakers, not just the ATV.

Thanks for checking, and please don't go to any further trouble. I'll experiment with trying to make the heartbeat detection a bit smarter.

iVolt1 commented 2 years ago

Hi Mike. I am still getting this version with the below git command. Is there a newer one I should get a different command?

4.1-dev-602-gf70d9a0f-OpenSSL-Avahi-ALSA-pipe-metadata-sysconfdir:/etc

Thanks.

mikebrady commented 2 years ago

Yes, that's the right version. Here is a log from my system. I restarted SPS, clicked play three times -- finger trouble -- and played one track from OwnTone on a Linux VM on a Mac to a Raspberry Pi 3B running Shairport Sync.

Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.002480208 "shairport.c:2025" startup in AirPlay 2 mode, with features 0x405fca00,0x1c340 on device "b8:27:eb:d7:85:d2".
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000278073 "shairport.c:2068" software version: "4.1-dev-602-gf70d9a0f-AirPlay2-OpenSSL-Avahi-ALSA-sndio-jack-ao-pa-soundio-dummy-stdout-pipe-soxr-metadata-mqtt-dbus-mpris-sysconfdir:/etc"
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000035313 "shairport.c:2074" log verbosity is 1.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000112916 "audio_alsa.c:1029" alsa: alsa_maximum_stall_time of 0.200000 sec.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000077188 "audio_alsa.c:1318" alsa: disable_standby_mode is "always".
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000027083 "audio_alsa.c:1322" alsa: disable_standby_mode_silence_threshold is 0.040000 seconds.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000027396 "audio_alsa.c:1324" alsa: disable_standby_mode_silence_scan_interval is 0.004000 seconds.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000037344 "audio_alsa.c:1364" alsa: output device name is "hw:sndrpihifiberry".
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000325573 "shairport.c:2103" libsodium initialised.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000049635 "shairport.c:2131" disable resend requests is off.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000035729 "shairport.c:2132" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000034219 "shairport.c:2136" statistics_requester status is 1.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000027448 "shairport.c:2141" rtsp listening port is 7000.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000025833 "shairport.c:2142" udp base port is 6001.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000025781 "shairport.c:2143" udp port range is 10.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000025730 "shairport.c:2144" player name is "Speakers!".
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000025260 "shairport.c:2145" backend is "alsa".
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000025417 "shairport.c:2146" run_this_before_play_begins action is "(null)".
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000029114 "shairport.c:2147" run_this_after_play_ends action is "(null)".
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000025573 "shairport.c:2148" wait-cmd status is 0.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000025729 "shairport.c:2149" run_this_before_play_begins may return output is 0.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000025729 "shairport.c:2150" run_this_if_an_unfixable_error_is_detected action is "(null)".
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000025625 "shairport.c:2152" run_this_before_entering_active_state action is  "/usr/bin/logger "Active Start"".
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000029323 "shairport.c:2154" run_this_after_exiting_active_state action is  "/usr/bin/logger "Active End"".
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000026771 "shairport.c:2156" active_state_timeout is  10.000000 seconds.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000031198 "shairport.c:2157" mdns backend "(null)".
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000026563 "shairport.c:2159" interpolation setting is "auto".
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000025729 "shairport.c:2163" interpolation soxr_delay_threshold is 30000000.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000025625 "shairport.c:2164" resync time is 0.050000 seconds.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000026927 "shairport.c:2165" allow a session to be interrupted: 0.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000025469 "shairport.c:2166" busy timeout time is 0.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000025833 "shairport.c:2167" drift tolerance is 0.001995 seconds.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000029375 "shairport.c:2168" password is "(null)".
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000026302 "shairport.c:2169" ignore_volume_control is 0.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000025833 "shairport.c:2173" volume_max_db is not set
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000026146 "shairport.c:2174" volume range in dB (zero means use the range specified by the mixer): 70.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000026927 "shairport.c:2176" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000025729 "shairport.c:2180" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000025730 "shairport.c:2182" disable_synchronization is 0.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000025000 "shairport.c:2183" use_mmap_if_available is 1.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000025104 "shairport.c:2184" output_format automatic selection is enabled.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000025937 "shairport.c:2188" output_rate automatic selection is enabled.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000025677 "shairport.c:2192" audio backend desired buffer length is 0.200000 seconds.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000026980 "shairport.c:2194" audio_backend_buffer_interpolation_threshold_in_seconds is 0.120000 seconds.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000030104 "shairport.c:2196" audio backend latency offset is 0.000000 seconds.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000027656 "shairport.c:2198" audio backend silence lead-in time is "auto".
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000025365 "shairport.c:2202" zeroconf regtype is "_raop._tcp".
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000025416 "shairport.c:2203" decoders_supported field is 1.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000028177 "shairport.c:2204" use_apple_decoder is 0.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000025573 "shairport.c:2205" alsa_use_hardware_mute is 0.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000025209 "shairport.c:2209" no special mdns service interface was requested.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000047708 "shairport.c:2212" configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000030937 "shairport.c:2219" metadata enabled is 1.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000026094 "shairport.c:2220" metadata pipename is "/tmp/shairport-sync-metadata".
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000025625 "shairport.c:2221" metadata socket address is "(null)" port 0.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000025833 "shairport.c:2223" metadata socket packet size is "500".
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000025209 "shairport.c:2224" get-coverart is 1.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000025104 "shairport.c:2227" mqtt is disabled.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000024792 "shairport.c:2228" mqtt hostname is (null), port is 1883.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000025416 "shairport.c:2229" mqtt topic is /Speakers!.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000024896 "shairport.c:2230" mqtt will not publish raw metadata.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000025104 "shairport.c:2231" mqtt will not publish parsed metadata.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000025104 "shairport.c:2232" mqtt will not publish cover Art.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000025157 "shairport.c:2233" mqtt remote control is disabled.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000027968 "shairport.c:2242" loudness is 0.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000028646 "shairport.c:2243" loudness reference level is -20.000000
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000256875 "rtsp.c:4086" metadata pipe name is "/tmp/shairport-sync-metadata".
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.009662552 "shairport.c:2326" NQPTP is online.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.004767657 "dbus-service.c:552" >> setting loudness threshold to -20.000000.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000156354 "dbus-service.c:565" >> setting drift tolerance to 0.001995 seconds.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000106302 "dbus-service.c:945" >> ALACDecoder set to "hammerton"
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000056198 "dbus-service.c:950" >> Active set to "false"
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000055625 "dbus-service.c:959" >> disable standby mode set to "always"
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000053229 "dbus-service.c:976" >> interpolation set to "auto" (soxr support built in)
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000067292 "dbus-service.c:457" >> activating disable standby
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000053593 "dbus-service.c:542" >> deactivating loudness
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000142448 "dbus-service.c:445" >> log verbosity set to 1.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000055417 "dbus-service.c:425" >> start logging statistics
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000046198 "dbus-service.c:390" >> stop including elapsed time in logs
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000048594 "dbus-service.c:400" >> start including delta time in logs
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000046250 "dbus-service.c:413" >> start including file and line in logs
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.000116041 "dbus-service.c:1087" Shairport Sync native D-Bus service started at "org.gnome.ShairportSync" on the system bus.
Oct 03 09:43:53 RaspberryPi3B shairport-sync[5939]:          0.001703959 "mpris-service.c:341" MPRIS service started at "org.mpris.MediaPlayer2.ShairportSync" on the system bus.
Oct 03 09:43:54 RaspberryPi3B shairport-sync[5939]:          0.989968749 "rtsp.c:5465" Connection 1: New connection from 192.168.50.69:41978 to self at 192.168.50.93:7000.
Oct 03 09:43:54 RaspberryPi3B shairport-sync[5939]:          0.000562500 "rtsp.c:1346" Connection 1: Closed by client: from 192.168.50.69:41978 to self at 192.168.50.93:7000.
Oct 03 09:43:54 RaspberryPi3B shairport-sync[5939]:          0.004488542 "rtsp.c:5465" Connection 2: New connection from 192.168.50.69:41988 to self at 192.168.50.93:7000.
Oct 03 09:43:54 RaspberryPi3B shairport-sync[5939]:          0.004598698 "rtsp.c:1346" Connection 2: Closed by client: from 192.168.50.69:41988 to self at 192.168.50.93:7000.
Oct 03 09:43:55 RaspberryPi3B shairport-sync[5939]:          0.486661823 "shairport.c:249" "soxr" interpolation has been chosen.
Oct 03 09:44:38 RaspberryPi3B shairport-sync[5939]:         43.692435347 "rtsp.c:5465" Connection 3: New connection from 192.168.50.69:55528 to self at 192.168.50.93:7000.
Oct 03 09:44:38 RaspberryPi3B shairport-sync[5939]:          0.008350730 "rtsp.c:2548" Connection 3: Unhandled POST /auth-setup Content-Length 33
Oct 03 09:44:38 RaspberryPi3B shairport-sync[5939]:          0.003832708 "rtsp.c:4412" Connection 3. AirPlay 1 Audio Stream Detected.
Oct 03 09:44:38 RaspberryPi3B shairport-sync[5939]:          0.006925260 "rtsp.c:1627" Connection 3: AP1 ALAC Stream, from 192.168.50.69:55528 to self at 192.168.50.93:7000.
Oct 03 09:44:38 RaspberryPi3B shairport-sync[5964]: Active Start
Oct 03 09:44:43 RaspberryPi3B shairport-sync[5939]:          4.420131249 "player.c:2734" Connection 3: Playback Started -- AirPlay 1 Compatible.
Oct 03 09:44:51 RaspberryPi3B shairport-sync[5939]:          7.909686507 "player.c:2574" Sync Error ms | Net Sync PPM | All Sync PPM | Missing |   Late | Too Late | Resend Reqs | Min DAC Queue | Min Buffers | Max Buffers | Nominal FPS | Received FPS | Output FPS (r) | Output FPS (c) | Source Drift PPM | Drift Samples
Oct 03 09:44:51 RaspberryPi3B shairport-sync[5939]:          0.000188125 "player.c:2574"          0.03            0.0            0.0         0        0          0             0            7588           253           257      44100.00       44102.67              N/A              N/A               0.00               0
Oct 03 09:44:59 RaspberryPi3B shairport-sync[5939]:          8.007056820 "player.c:2574"         -0.09            0.0            0.0         0        0          0             0            8052           254           256      44100.00       44094.50         44100.12         44101.79               0.00               0
Oct 03 09:45:07 RaspberryPi3B shairport-sync[5939]:          8.004011612 "player.c:2574"         -0.18            0.0            0.0         0        0          0             0            7768           253           257      44100.00       44101.60         44099.99         44101.67               0.00               0
Oct 03 09:45:15 RaspberryPi3B shairport-sync[5939]:          8.006463903 "player.c:2574"         -0.18            0.0            0.0         0        0          0             0            7732           254           256      44100.00       44099.09         44100.12         44101.80               0.00               0
Oct 03 09:45:23 RaspberryPi3B shairport-sync[5939]:          8.009975049 "player.c:2574"         -0.14            0.0            0.0         0        0          0             0            8048           254           256      44100.00       44103.69         44100.08         44101.76               0.00               0
Oct 03 09:45:31 RaspberryPi3B shairport-sync[5939]:          8.000467236 "player.c:2574"         -0.24            0.0            0.0         0        0          0             0            7753           253           257      44100.00       44101.26         44100.06         44101.74               0.00               0
Oct 03 09:45:39 RaspberryPi3B shairport-sync[5939]:          8.009844372 "player.c:2574"         -0.29            0.0            0.0         0        0          0             0            8102           254           256      44100.00       44097.15         44100.09         44101.77               0.00               0
Oct 03 09:45:47 RaspberryPi3B shairport-sync[5939]:          8.009583226 "player.c:2574"         -0.35            0.0            0.0         0        0          0             0            8216           254           256      44100.00       44100.51         44100.03         44101.71               0.00               1
Oct 03 09:45:55 RaspberryPi3B shairport-sync[5939]:          8.000155831 "player.c:2574"         -0.32            0.0            0.0         0        0          0             0            8112           254           256      44100.00       44098.98         44100.04         44101.72               0.00               2
Oct 03 09:46:03 RaspberryPi3B shairport-sync[5939]:          8.010398903 "player.c:2574"         -0.29            0.0            0.0         0        0          0             0            7676           251           256      44100.00       44101.00         44100.06         44101.74               0.00               2
Oct 03 09:46:11 RaspberryPi3B shairport-sync[5939]:          8.000882549 "player.c:2574"         -0.39            0.0            0.0         0        0          0             0            7648           254           257      44100.00       44099.74         44100.06         44101.74               0.00               4
Oct 03 09:46:19 RaspberryPi3B shairport-sync[5939]:          8.006088591 "player.c:2574"         -0.48            0.0            0.0         0        0          0             0            7996           254           256      44100.00       44095.92         44100.05         44101.73               0.00               4
Oct 03 09:46:27 RaspberryPi3B shairport-sync[5939]:          8.013203538 "player.c:2574"         -0.48            2.8            2.8         0        0          0             0            8117           254           256      44100.00       44099.57         44100.07         44101.75               0.00               5
Oct 03 09:46:35 RaspberryPi3B shairport-sync[5939]:          8.000316039 "player.c:2574"         -0.52            0.0            0.0         0        0          0             0            8011           254           256      44100.00       44101.80         44100.04         44101.72               0.00               5
Oct 03 09:46:43 RaspberryPi3B shairport-sync[5939]:          8.009836507 "player.c:2574"         -0.54            0.0            0.0         0        0          0             0            8189           254           256      44100.00       44100.18         44100.06         44101.74               0.00               6
Oct 03 09:46:51 RaspberryPi3B shairport-sync[5939]:          7.999795518 "player.c:2574"         -0.60            0.0            0.0         0        0          0             0            8169           254           256      44100.00       44099.51         44100.03         44101.71               0.00               7
Oct 03 09:46:59 RaspberryPi3B shairport-sync[5939]:          8.012375518 "player.c:2574"         -0.70            0.0            0.0         0        0          0             0            8125           254           256      44100.00       44099.97         44100.05         44101.73               0.00               8
Oct 03 09:47:07 RaspberryPi3B shairport-sync[5939]:          7.998447965 "player.c:2574"         -0.72            0.0            0.0         0        0          0             0            7711           253           256      44100.00       44100.04         44100.04         44101.72               0.00               8
Oct 03 09:47:15 RaspberryPi3B shairport-sync[5939]:          8.010426560 "player.c:2574"         -0.72            0.0            0.0         0        0          0             0            8033           254           256      44100.00       44098.44         44100.06         44101.74               0.00               8
Oct 03 09:47:23 RaspberryPi3B shairport-sync[5939]:          8.008859945 "player.c:2574"         -0.73            0.0            0.0         0        0          0             0            8189           254           256      44100.00       44099.88         44100.05         44101.73               0.00               8
Oct 03 09:47:31 RaspberryPi3B shairport-sync[5939]:          8.000111247 "player.c:2574"         -0.74            0.0            0.0         0        0          0             0            8073           254           256      44100.00       44099.31         44100.07         44101.75               0.00               8
Oct 03 09:47:39 RaspberryPi3B shairport-sync[5939]:          8.009887132 "player.c:2574"         -0.75            0.0            0.0         0        0          0             0            7869           254           256      44100.00       44100.30         44100.04         44101.72               0.00               8
Oct 03 09:47:47 RaspberryPi3B shairport-sync[5939]:          8.000886664 "player.c:2574"         -0.93            0.0            0.0         0        0          0             0            7997           254           256      44100.00       44099.73         44100.04         44101.72              -4.68               9
Oct 03 09:47:55 RaspberryPi3B shairport-sync[5939]:          8.009252080 "player.c:2574"         -0.99            0.0            0.0         0        0          0             0            7457           251           256      44100.00       44100.62         44100.04         44101.72              -4.68               9
Oct 03 09:48:03 RaspberryPi3B shairport-sync[5939]:          8.001029476 "player.c:2574"         -1.03            0.0            0.0         0        0          0             0            7361           249           256      44100.00       44100.06         44100.03         44101.71              -4.68               9
Oct 03 09:48:11 RaspberryPi3B shairport-sync[5939]:          8.009146143 "player.c:2574"         -1.07            0.0            0.0         0        0          0             0            7441           251           256      44100.00       44100.87         44100.03         44101.72              -4.65              10
Oct 03 09:48:19 RaspberryPi3B shairport-sync[5939]:          8.009790986 "player.c:2574"         -1.12            0.0            0.0         0        0          0             0            8209           254           256      44100.00       44100.02         44100.04         44101.72              -4.65              11
Oct 03 09:48:27 RaspberryPi3B shairport-sync[5939]:          8.000323643 "player.c:2574"         -1.14            2.8            2.8         0        0          0             0            8078           254           256      44100.00       44099.53         44100.04         44101.72              -4.65              11
Oct 03 09:48:35 RaspberryPi3B shairport-sync[5939]:          8.009710518 "player.c:2574"         -1.18            2.8            2.8         0        0          0             0            7759           252           256      44100.00       44100.32         44100.04         44101.72              -4.80              12
Oct 03 09:48:43 RaspberryPi3B shairport-sync[5939]:          8.001135570 "player.c:2574"         -1.23            0.0            0.0         0        0          0             0            7979           254           256      44100.00       44099.84         44100.05         44101.73              -4.80              12
Oct 03 09:48:51 RaspberryPi3B shairport-sync[5939]:          8.010374320 "player.c:2574"         -1.27            0.0            0.0         0        0          0             0            7675           254           256      44100.00       44098.91         44100.04         44101.72              -4.80              12
Oct 03 09:48:59 RaspberryPi3B shairport-sync[5939]:          8.008855257 "player.c:2574"         -1.32            0.0            0.0         0        0          0             0            8143           254           256      44100.00       44099.78         44100.04         44101.72              -4.85              13
Oct 03 09:49:07 RaspberryPi3B shairport-sync[5939]:          8.000095257 "player.c:2574"         -1.36            0.0            0.0         0        0          0             0            8147           254           256      44100.00       44099.41         44100.04         44101.72              -4.85              13
Oct 03 09:49:15 RaspberryPi3B shairport-sync[5939]:          8.003083903 "player.c:2574"         -1.42            0.0            0.0         0        0          0             0            8063           254           256      44100.00       44099.99         44100.04         44101.72              -4.85              13
Oct 03 09:49:23 RaspberryPi3B shairport-sync[5939]:          8.006564216 "player.c:2574"         -1.46            0.0            0.0         0        0          0             0            7519           254           258      44100.00       44099.75         44100.05         44101.73              -4.85              13
Oct 03 09:49:31 RaspberryPi3B shairport-sync[5939]:          8.004906351 "player.c:2574"         -1.52            0.0            0.0         0        0          0             0            7494           253           256      44100.00       44100.03         44100.04         44101.73              -5.00              14
Oct 03 09:49:38 RaspberryPi3B shairport-sync[5939]:          7.347288591 "player.c:1723" Connection 3: Playback Stopped. Total playing time 00:04:57. Output: 44100.04 (raw), 44101.73 (corrected) frames per second.
Oct 03 09:49:38 RaspberryPi3B shairport-sync[5939]:          0.005708125 "rtsp.c:1346" Connection 3: Closed by client: from 192.168.50.69:55528 to self at 192.168.50.93:7000.
Oct 03 09:49:48 RaspberryPi3B shairport-sync[5981]: Active End

Is it possible that you got the version string from the just-built Shairport Sync, but that an older version of Shairport Sync is actually running? (I ask because I do this sometimes!)

iVolt1 commented 2 years ago

Hi Mike. Everything continues to work well with 4.1-dev-602-gf70d9a0f-OpenSSL-Avahi-ALSA-pipe-metadata-sysconfdir:/etc. Thanks for fixing it so quickly.

I have done this before also, but I am positive 4.1-dev-602 is running: Is it possible that you got the version string from the just-built Shairport Sync, but that an older version of Shairport Sync is actually running? (I ask because I do this sometimes!)

ejurgensen commented 2 years ago

Congratulations with 4.1, Mike. I have tried it with OwnTone, and it worked fine with Airplay 1. So I suppose this issue and the OwnTone one can be closed?

mikebrady commented 2 years ago

Congratulations with 4.1, Mike. I have tried it with OwnTone, and it worked fine with Airplay 1. So I suppose this issue and the OwnTone one can be closed?

Thanks! Yes, I guess so.

mikebrady / shairport-sync