mikebrady
commented
1 year ago Thanks for the post. I'll take a look. That "Connection 0" stuff looks very interesting, because there is no connection numbered 0.
Closed aaronk6 closed 1 year ago
mikebrady
commented
1 year ago Thanks for the post. I'll take a look. That "Connection 0" stuff looks very interesting, because there is no connection numbered 0.
aaronk6
commented
1 year ago Interesting indeed. I just checked if it also logs “Asking Connection 0 to stop playing.” when I reproduce the issue by setting allow_session_interruption to yes. It does!
aaronk6
commented
1 year ago Minor correction though: It only seems to happen when OwnTone interrupts a connection from iOS, not the other way around. It’s maybe worth noting that iOS is using AirPlay 2 while OwnTone is using AirPlay 1.
mikebrady
commented
1 year ago I'm having a little trouble reproducing this fault, but will keep trying...
mikebrady
commented
1 year ago I can't get this problem to occur, I'm afraid, though I am on the latest development version and not using the pa backend. I wonder if you'd be kind enough to try this with the latest development version?
Version String: "4.2.1d0-55-g8821ec28-AirPlay2-smi9-OpenSSL-Avahi-...`That way, we'd be on the same page, as it were. Meanwhile, I'll try including the pa backend.
aaronk6
commented
1 year ago OK, I’ve updated my Docker container to use the development tag:
4.2.1d0-55-g8821ec28-dirty-AirPlay2-smi9-alac-OpenSSL-Avahi-ALSA-pa-dummy-stdout-pipe-soxr-convolution-metadata-mqtt-dbus-mpris-sysconfdir:/etcAnd I can still reproduce the issue by having OwnTone interrupt a playing iOS device:
2023-08-25T16:18:52.646124177Z 0.001571278 "rtsp.c:5212" Connection 6: Received an RTSP Packet of type "ANNOUNCE":
2023-08-25T16:18:52.646308064Z 0.000068889 "rtsp.c:5214" Type: "CSeq", content: "2"
2023-08-25T16:18:52.646371229Z 0.000024519 "rtsp.c:5214" Type: "User-Agent", content: "owntone/28.6"
2023-08-25T16:18:52.646428173Z 0.000027611 "rtsp.c:5214" Type: "Client-Instance", content: "68906BCA5356CD45"
2023-08-25T16:18:52.646482894Z 0.000030240 "rtsp.c:5214" Type: "DACP-ID", content: "68906BCA5356CD45"
2023-08-25T16:18:52.646536431Z 0.000029500 "rtsp.c:5214" Type: "Active-Remote", content: "3232258056"
2023-08-25T16:18:52.646589782Z 0.000028889 "rtsp.c:5214" Type: "Content-Type", content: "application/sdp"
2023-08-25T16:18:52.646643022Z 0.000029019 "rtsp.c:5214" Type: "Content-Length", content: "184"
2023-08-25T16:18:52.646696095Z 0.000022889 "rtsp.c:5214" No Content Plist. Content length: 184.
2023-08-25T16:18:52.646747187Z 0.000027833 "rtsp.c:567" Connection 6: request play lock.
2023-08-25T16:18:52.646798520Z 0.000022685 "rtsp.c:596" Asking Connection 0 to stop playing.
2023-08-25T16:18:52.746725244Z Segmentation fault (core dumped)Let me know if there’s anything else I should try to narrow it down. I’m happy to help.
Edit: I did this with the pa backend.
mikebrady
commented
1 year ago Super, thanks.
aaronk6
commented
1 year ago I believe it’s unrelated to the pa backend. I could just reproduce the issue with the standard ALSA config.
I started the Docker container like this on a fresh Raspberry Pi OS (running as root):
docker run -d --restart unless-stopped --net host --device /dev/snd \
mikebrady/shairport-sync:developmentChanges to shairport-sync.conf:
allow_session_interruption = "yes";log_verbosity = 2;I then did the following:
mikebrady
commented
1 year ago Thanks for this — I’ve not been using Docker. I’ll try that.
spammads
commented
1 year ago I also get a segfault running a slightly different configuration with version 4.2. and the development-branch. Both in docker. Maybe the dmesg from my host helps you in finding something. Maybe its Musl-related?!
192.168.2.25: kern: info: [2023-08-26T07:18:33.586907785Z]: shairport-sync[194339]: segfault at 7f4d64b75b6c ip 00007f4d6b067674 sp 00007fff463d1470 error 6 in ld-musl-x86_64.so.1[7f4d6b027000+4b000] likely on CPU 6 (core 0, socket 0)
mikebrady
commented
1 year ago Thanks again. My guess -- that's all it is right now -- is that there is a race condition associated with closing a connection and opening another.
aaronk6
commented
1 year ago Confirming that I don’t get the segfault when running without Docker on a plain Raspberry Pi OS with shairport-sync built from source. However, I reproducibly managed to have two connections playing at the same time, causing heavily distorted audio and repeated log entries that look like this:
0.007977864 "audio_alsa.c:1751" alsa: recovering from a previous underrun.
0.020097396 "player.c:2884" Large negative (i.e. early) sync error of -8495 frames (-0.192630 seconds), at frame: 389854971.
0.000716771 "audio_alsa.c:1751" alsa: recovering from a previous underrun.
0.009303229 "audio_alsa.c:1769" alsa: SND_PCM_STATE_* 3, error -32 ("Broken pipe") writing 352 samples to alsa device.
0.009953438 "audio_alsa.c:1751" alsa: recovering from a previous underrun.
0.019967604 "audio_alsa.c:1751" alsa: recovering from a previous underrun.
0.010306823 "audio_alsa.c:1769" alsa: SND_PCM_STATE_* 3, error -32 ("Broken pipe") writing 352 samples to alsa device.
0.009677708 "audio_alsa.c:1751" alsa: recovering from a previous underrun.
0.040073698 "player.c:2884" Large negative (i.e. early) sync error of -8440 frames (-0.191383 seconds), at frame: 389859547.
0.130216406 "player.c:2859" Large positive (i.e. late) sync error of 3864 frames (0.087619 seconds), at frame: 389865179.
0.020226146 "player.c:2884" Large negative (i.e. early) sync error of -7935 frames (-0.179932 seconds), at frame: 3883373246.
0.260723750 "player.c:2859" Large positive (i.e. late) sync error of 2684 frames (0.060862 seconds), at frame: 3883385566.
0.018773958 "player.c:2884" Large negative (i.e. early) sync error of -8709 frames (-0.197483 seconds), at frame: 389878555.
0.233094479 "player.c:2859" Large positive (i.e. late) sync error of 3767 frames (0.085420 seconds), at frame: 389888763.
0.012052084 "player.c:2884" Large negative (i.e. early) sync error of -8382 frames (-0.190068 seconds), at frame: 3883396830.
0.274323489 "player.c:2859" Large positive (i.e. late) sync error of 3281 frames (0.074399 seconds), at frame: 3883409150.
0.010813334 "audio_alsa.c:1751" alsa: recovering from a previous underrun.
0.009878072 "player.c:2884" Large negative (i.e. early) sync error of -8472 frames (-0.192109 seconds), at frame: 389902139.
0.240093386 "player.c:2859" Large positive (i.e. late) sync error of 2461 frames (0.055805 seconds), at frame: 389913051.
0.021731094 "player.c:2884" Large negative (i.e. early) sync error of -8114 frames (-0.183991 seconds), at frame: 3883421118.
0.204783593 "player.c:2859" Large positive (i.e. late) sync error of 2621 frames (0.059433 seconds), at frame: 3883430622.
0.013433177 "player.c:2689" Delay error -32 when checking running latency.
0.000321250 "audio_alsa.c:1751" alsa: recovering from a previous underrun.
0.009489636 "player.c:2689" Delay error -32 when checking running latency.
0.000219531 "audio_alsa.c:1751" alsa: recovering from a previous underrun.I’ll create a screencast with the exact steps that I performed to get in this state.
mikebrady
commented
1 year ago Thanks again. The code for ensuring only one connection has control of the player is a mess, I’m afraid. It might take a little time to straighten it out. I believe that this is what’s causing the problem you have identified.
aaronk6
commented
1 year ago OK, in case it helps, here is how I can reproduce it reliably:
https://github.com/mikebrady/shairport-sync/assets/446063/534d0b82-4b9b-4f0c-b594-e3e0570e2a75
(Note that the screencast has audio.)
mikebrady
commented
1 year ago Thanks again. I'm making a little progress on this, I think, by re-doing the code handling the preemption (interruption) of a session.
aaronk6
commented
1 year ago Cool. Happy to do some testing on my end once you have something working.
mikebrady
commented
1 year ago Still working on this!
mikebrady
commented
1 year ago Just pushed an update to the development branch with a fix for this, as far as I can tell. If you got a chance to check it out, it would be appreciated.
aaronk6
commented
1 year ago Looks very promising on my test system (the one I took the screencast on). I switched back and forth between iOS and OwnTone several times and it never crashed. I’ll update my “production” setup tomorrow (the Pi running 4 shairport-sync Docker containers) and will monitor it in real-world scenarios over the following weeks. Thanks for the fix, really appreciate the effort you’re putting into this project!
aaronk6
commented
1 year ago I encountered another crash today (using build Docker image mikebrady/shairport-sync@sha256:7e620052d263a2f0ba9a8be832427f84d39acbfa8c69620f2af6a21378a4943e).
This again happened after sending a stream from OwnTone while something was playing from iOS (allow_session_interruption is set to yes).
gaeste_wc_1 | 2023-09-16T16:51:16.702861350Z 60.060879872 "rtsp.c:723" Airplay Volume for new connections is -5.357144.
gaeste_wc_1 | 2023-09-16T16:52:16.763050866Z 60.060882464 "rtsp.c:723" Airplay Volume for new connections is -5.357144.
gaeste_wc_1 | 2023-09-16T16:53:16.818135135Z 60.055739409 "rtsp.c:723" Airplay Volume for new connections is -5.357144.
gaeste_wc_1 | 2023-09-16T16:53:20.340510287Z 3.522515090 "rtsp.c:723" Airplay Volume for new connections is -5.357144.
gaeste_wc_1 | 2023-09-16T16:53:20.340943059Z 0.000475204 "rtsp.c:5598" Connection 31: New connection from 192.168.88.150:50336 to self at 192.168.88.6:7000.
gaeste_wc_1 | 2023-09-16T16:53:20.341818900Z 0.000997167 "rtsp.c:5182" Connection 31: Received an RTSP Packet of type "OPTIONS":
gaeste_wc_1 | 2023-09-16T16:53:20.341986713Z 0.000074074 "rtsp.c:5184" Type: "CSeq", content: "1"
gaeste_wc_1 | 2023-09-16T16:53:20.342348560Z 0.000031814 "rtsp.c:5184" Type: "User-Agent", content: "owntone/28.8"
gaeste_wc_1 | 2023-09-16T16:53:20.342448707Z 0.000037315 "rtsp.c:5184" Type: "Client-Instance", content: "68906BCA5356CD45"
gaeste_wc_1 | 2023-09-16T16:53:20.342516058Z 0.000036500 "rtsp.c:5184" Type: "DACP-ID", content: "68906BCA5356CD45"
gaeste_wc_1 | 2023-09-16T16:53:20.342579131Z 0.000034815 "rtsp.c:5184" Type: "Active-Remote", content: "3232258049"
gaeste_wc_1 | 2023-09-16T16:53:20.342639001Z 0.000034944 "rtsp.c:5184" No Content Plist. Content length: 0.
gaeste_wc_1 | 2023-09-16T16:53:20.342697778Z 0.000032241 "rtsp.c:2615" OPTIONS request
gaeste_wc_1 | 2023-09-16T16:53:20.342757777Z 0.000061334 "rtsp.c:2615" Type: "CSeq", content: "1"
gaeste_wc_1 | 2023-09-16T16:53:20.342817999Z 0.000034685 "rtsp.c:2615" Type: "User-Agent", content: "owntone/28.8"
gaeste_wc_1 | 2023-09-16T16:53:20.342878202Z 0.000032278 "rtsp.c:2615" Type: "Client-Instance", content: "68906BCA5356CD45"
gaeste_wc_1 | 2023-09-16T16:53:20.342937645Z 0.000035037 "rtsp.c:2615" Type: "DACP-ID", content: "68906BCA5356CD45"
gaeste_wc_1 | 2023-09-16T16:53:20.342995756Z 0.000034037 "rtsp.c:2615" Type: "Active-Remote", content: "3232258049"
gaeste_wc_1 | 2023-09-16T16:53:20.343054200Z 0.000033944 "rtsp.c:2615" No Content Plist. Content length: 0.
gaeste_wc_1 | 2023-09-16T16:53:20.343112477Z 0.000029648 "rtsp.c:5243" Connection 31: RTSP Response:
gaeste_wc_1 | 2023-09-16T16:53:20.343170865Z 0.000026000 "rtsp.c:5244" Response Code: 200.
gaeste_wc_1 | 2023-09-16T16:53:20.343229197Z 0.000025241 "rtsp.c:5244" Type: "CSeq", content: "1"
gaeste_wc_1 | 2023-09-16T16:53:20.343287882Z 0.000029648 "rtsp.c:5244" Type: "Server", content: "AirTunes/366.0"
gaeste_wc_1 | 2023-09-16T16:53:20.343346715Z 0.000026296 "rtsp.c:5244" Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, FLUSHBUFFERED, TEARDOWN, OPTIONS, POST, GET, PUT"
gaeste_wc_1 | 2023-09-16T16:53:20.343406529Z 0.000038667 "rtsp.c:5244" No Content Plist. Content length: 0.
gaeste_wc_1 | 2023-09-16T16:53:20.343767987Z 0.001318204 "rtsp.c:5182" Connection 31: Received an RTSP Packet of type "ANNOUNCE":
gaeste_wc_1 | 2023-09-16T16:53:20.343904930Z 0.000059518 "rtsp.c:5184" Type: "CSeq", content: "2"
gaeste_wc_1 | 2023-09-16T16:53:20.344229352Z 0.000028241 "rtsp.c:5184" Type: "User-Agent", content: "owntone/28.8"
gaeste_wc_1 | 2023-09-16T16:53:20.344308814Z 0.000048074 "rtsp.c:5184" Type: "Client-Instance", content: "68906BCA5356CD45"
gaeste_wc_1 | 2023-09-16T16:53:20.344370406Z 0.000034667 "rtsp.c:5184" Type: "DACP-ID", content: "68906BCA5356CD45"
gaeste_wc_1 | 2023-09-16T16:53:20.344429849Z 0.000033370 "rtsp.c:5184" Type: "Active-Remote", content: "3232258049"
gaeste_wc_1 | 2023-09-16T16:53:20.344488589Z 0.000033333 "rtsp.c:5184" Type: "Content-Type", content: "application/sdp"
gaeste_wc_1 | 2023-09-16T16:53:20.344547274Z 0.000032889 "rtsp.c:5184" Type: "Content-Length", content: "184"
gaeste_wc_1 | 2023-09-16T16:53:20.344606032Z 0.000026445 "rtsp.c:5184" No Content Plist. Content length: 184.
gaeste_wc_1 | 2023-09-16T16:53:20.344663939Z 0.000031574 "rtsp.c:4454" Connection 31: ANNOUNCE
gaeste_wc_1 | 2023-09-16T16:53:20.344722438Z 0.000028629 "rtsp.c:583" Connection 0: is requested to relinquish principal_conn.
gaeste_wc_1 | 2023-09-16T16:53:20.344780808Z 0.000034204 "rtsp.c:586" Connection 31: request to acquire principal_conn.
gaeste_wc_1 | 2023-09-16T16:53:20.344839585Z 0.000034352 "player.c:3650" Connection 0: player_stop.
gaeste_wc_1 | 2023-09-16T16:53:20.344897695Z 0.000056352 "player.c:3670" Connection 0: no player thread.
gaeste_wc_1 | 2023-09-16T16:53:20.344956769Z 0.000032241 "rtsp.c:597" Connection 0: termination requested.
gaeste_wc_1 | 2023-09-16T16:53:20.514669544Z Segmentation fault (core dumped)My config:
/ # shairport-sync -X
0.001333870 "shairport.c:1470" default metadata_pipename is "/tmp/shairport-sync-metadata".
0.000283833 "shairport.c:2113" >> Display Config Start.
0.003713797 "shairport.c:2113"
0.000099925 "shairport.c:2113" From "uname -a":
0.000065704 "shairport.c:2113" Linux 8dfb9a4aefe5 6.1.21-v8+ #1642 SMP PREEMPT Mon Apr 3 17:24:16 BST 2023 aarch64 Linux
0.007842945 "shairport.c:2113"
0.000108629 "shairport.c:2113" From /etc/os-release:
0.000065315 "shairport.c:2113" Alpine Linux v3.17
0.004434019 "shairport.c:2113"
0.000102500 "shairport.c:2113" Shairport Sync Version String:
0.000205240 "shairport.c:2113" 4.2.1d0-70-g73af29c8-dirty-AirPlay2-smi10-alac-OpenSSL-Avahi-ALSA-pa-dummy-stdout-pipe-soxr-convolution-metadata-mqtt-dbus-mpris-sysconfdir:/etc
0.000359074 "shairport.c:2113"
0.000452963 "shairport.c:2113" Command Line:
0.000038000 "shairport.c:2113" shairport-sync -X
0.000290056 "shairport.c:2113"
0.000467444 "shairport.c:2113" Configuration File:
0.000041056 "shairport.c:2113" /etc/shairport-sync.conf
0.000262037 "shairport.c:2113"
0.001155055 "shairport.c:2113" Configuration File Settings:
0.000090741 "shairport.c:2113" general :
0.000032259 "shairport.c:2113" {
0.000076130 "shairport.c:2113" name = "Gäste-WC";
0.000823111 "shairport.c:2113" output_backend = "pa";
0.000105500 "shairport.c:2113" airplay_device_id = 0x242C0A85801L;
0.000036315 "shairport.c:2113" };
0.000315796 "shairport.c:2113" sessioncontrol :
0.000208130 "shairport.c:2113" {
0.000106463 "shairport.c:2113" allow_session_interruption = "yes";
0.000210037 "shairport.c:2113" };
0.000233704 "shairport.c:2113" pa :
0.000256037 "shairport.c:2113" {
0.000311907 "shairport.c:2113" sink = "gaeste_wc";
0.000117537 "shairport.c:2113" };
0.000431722 "shairport.c:2113" diagnostics :
0.000126445 "shairport.c:2113" {
0.000307352 "shairport.c:2113" log_verbosity = 2;
0.000085203 "shairport.c:2113" };
0.000034334 "shairport.c:2113"
0.000077074 "shairport.c:2113" >> Display Config End.
0.000074129 "shairport.c:2115" >> Goodbye!
0.000034667 "shairport.c:1588" exit function called...
0.000411463 "shairport.c:1598" Stopping the activity monitor.
0.000108889 "shairport.c:1600" Stopping the activity monitor done.
0.000031463 "shairport.c:1603" Stopping DACP Monitor
0.000305352 "shairport.c:1605" Stopping DACP Monitor Done
0.000115074 "shairport.c:1616" Stopping D-Bus service
0.000150500 "dbus-service.c:1218" stopping dbus service
0.000106907 "shairport.c:1618" Stopping D-Bus service done
0.000355297 "shairport.c:1634" Stopping metadata hub
0.000119166 "shairport.c:1636" Stopping metadata done
0.000303148 "shairport.c:1640" Stopping metadata
0.000084556 "shairport.c:1642" Stopping metadata done
0.000096018 "shairport.c:1725" normal exitI’ll make sure to upgrade to the stable 4.3 version and see if I can get a solid repro.
For now, I’ve reopened this issue, but let me know if you prefer to handle this in a new bug report.
mikebrady
commented
1 year ago Thanks. Let me think about it some more. FWIW the code for doing this is a lot cleaner, so it should be easier to locate the problem.
mikebrady
commented
1 year ago Just pushed an update to get a little more information on this. It should notice when a connection with number 0 shows up and give its address. Whenever you got a chance, it would be good to see an occurrence. I am mystified by this -- did some valgrind checking yesterday to no avail.
aaronk6
commented
1 year ago I’ve just updated my Docker containers to the latest development version and will post the logs once I see the crash again! Thanks!
mikebrady
commented
1 year ago Yikes 😊! Give it about 30 minutes to pull the latest one! It's still being built 😊.
aaronk6
commented
1 year ago Oops. Now using sha256:b33c3ec56dc0a3e8d11ef79c2b597582a277ff51651f3b726c13314402fef3b6 identifying as 4.3.2-dev-5-gc8d186db-dirty-AirPlay2-smi10-alac-OpenSSL-Avahi-ALSA-pa-dummy-stdout-pipe-soxr-convolution-metadata-mqtt-dbus-mpris-sysconfdir:/etc.
mikebrady
commented
1 year ago Yeah, that'll do! ✅
mikebrady
commented
1 year ago Just FYI, I'm doing some checking with various sanitizer tools on Clang/FreeBSD and some data races are surfacing. I'll keep you posted with any updates.
iVolt1
commented
1 year ago Hi Mike. Thanks for looking into this. I have had this issue with Owntone for quite a while but could never get a useful debug log. I don't think I have seen it happen on my 2 32 bit pi instances but I have for both debian amd64 on an amd system and debian aarch65 on a pi 4.
mikebrady
commented
1 year ago Thanks. I've just pushed an update with those data races fixed -- it just might make a difference... Whenever you got a chance to try it, it would be great to get some feedback.
iVolt1
commented
1 year ago I have 4.3.2-dev-20-gb3986ed6-OpenSSL-Avahi-ALSA-pa-pipe-soxr-sysconfdir:/etc running on the debian bookwork pi4 now. It may be a while before there is a long enough disconnect and reconnect to trigger the segfault. Thanks for the quick update.
aaronk6
commented
1 year ago I was able to reproduce the issue with 4.3.2-dev-5-gc8d186db.
Here is what I did:
hauptbad_1 | 2023-09-24T08:49:51.743107492Z 0.000028277 "rtsp.c:5256" Connection 15: RTSP Response:
hauptbad_1 | 2023-09-24T08:49:51.743176676Z 0.000025463 "rtsp.c:5257" Response Code: 200.
hauptbad_1 | 2023-09-24T08:49:51.743236471Z 0.000027371 "rtsp.c:5257" Type: "CSeq", content: "907"
hauptbad_1 | 2023-09-24T08:49:51.743295341Z 0.000037203 "rtsp.c:5257" Type: "Server", content: "AirTunes/366.0"
hauptbad_1 | 2023-09-24T08:49:51.743353970Z 0.000031519 "rtsp.c:5257" No Content Plist. Content length: 0.
hauptbad_1 | 2023-09-24T08:49:59.822607348Z 8.079909402 "dacp.c:623" metadata_store.dacp_server_active set to 0.
hauptbad_1 | 2023-09-24T08:49:59.822752901Z 0.000265186 "dbus-service.c:226" Build metadata
hauptbad_1 | 2023-09-24T08:49:59.823896052Z 0.001164277 "mpris-service.c:167" Build metadata
hauptbad_1 | 2023-09-24T08:50:07.857553680Z 8.033755496 "rtsp.c:708" Airplay Volume for connection 15 is 0.000000.
hauptbad_1 | 2023-09-24T08:50:07.857707401Z 0.000081166 "rtsp.c:724" Airplay Volume for new connections is 0.000000.
hauptbad_1 | 2023-09-24T08:50:52.846707017Z 44.989463251 "rtsp.c:1339" Connection 15: ETIMEDOUT -- keepalive timeout.
hauptbad_1 | 2023-09-24T08:50:52.846938958Z 0.000225056 "rtsp.c:5011" Connection 15: PTP stream rtsp_conversation_thread_func_cleanup_function called.
hauptbad_1 | 2023-09-24T08:50:52.847008013Z 0.000048963 "rtsp.c:2642" Connection 15: TEARDOWN PTP stream connection.
hauptbad_1 | 2023-09-24T08:50:52.847069030Z 0.000042852 "rtsp.c:2662" Connection 15: TEARDOWN PTP stream Delete Event Thread.
hauptbad_1 | 2023-09-24T08:50:52.847190455Z 0.000328314 "rtp.c:1567" Connection 15: AP2 Event Receiver Cleanup.
hauptbad_1 | 2023-09-24T08:50:52.847647671Z 0.000641000 "rtsp.c:2670" Connection 15: TEARDOWN PTP stream Close Event Socket.
hauptbad_1 | 2023-09-24T08:50:52.848602510Z 0.001005482 "rtsp.c:2690" Connection 15: TEARDOWN mdns_update on PTP stream.
hauptbad_1 | 2023-09-24T08:50:52.850956533Z 0.002241426 "ptp-utilities.c:223" Send control message to NQPTP: "/nqptp T"
hauptbad_1 | 2023-09-24T08:50:52.851590339Z 0.000733407 "rtsp.c:5043" Connection 15: terminating -- closing RTSP connection socket 19: from 192.168.88.19:55253 to self at 192.168.88.7:7000.
hauptbad_1 | 2023-09-24T08:50:52.852411087Z 0.000797815 "rtsp.c:5110" Connection 15: Closed.
hauptbad_1 | 2023-09-24T08:50:52.853253242Z 0.000052500 "rtsp.c:5333" Connection 15: RTSP thread exit.
hauptbad_1 | 2023-09-24T08:50:53.905716083Z 1.053083518 "rtsp.c:700" Found RTSP connection thread 15 in a non-running state.
hauptbad_1 | 2023-09-24T08:50:53.906042893Z 0.000240685 "rtsp.c:703" Connection 15: deleted.
hauptbad_1 | 2023-09-24T08:50:53.906143818Z 0.000122537 "rtsp.c:717" No active connections.
hauptbad_1 | 2023-09-24T08:50:53.906206558Z 0.000038463 "rtsp.c:724" Airplay Volume for new connections is 0.000000.
hauptbad_1 | 2023-09-24T08:50:53.907086249Z 0.001117815 "rtsp.c:5533" Connection 17 is at: 0xf0b8c610.
hauptbad_1 | 2023-09-24T08:50:53.907201600Z 0.000173167 "rtsp.c:5615" Connection 17: New connection from 192.168.88.150:41902 to self at 192.168.88.7:7000.
hauptbad_1 | 2023-09-24T08:50:53.908510748Z 0.000798277 "rtsp.c:1322" Connection 17: Connection closed by client.
hauptbad_1 | 2023-09-24T08:50:53.908622173Z 0.000188908 "rtsp.c:5011" Connection 17: unspecified stream rtsp_conversation_thread_func_cleanup_function called.
hauptbad_1 | 2023-09-24T08:50:53.908687357Z 0.000046574 "rtsp.c:2642" Connection 17: TEARDOWN unspecified stream connection.
hauptbad_1 | 2023-09-24T08:50:53.908749245Z 0.000038629 "rtsp.c:5043" Connection 17: terminating -- closing RTSP connection socket 15: from 192.168.88.150:41902 to self at 192.168.88.7:7000.
hauptbad_1 | 2023-09-24T08:50:53.909343274Z 0.000911982 "rtsp.c:5110" Connection 17: Closed.
hauptbad_1 | 2023-09-24T08:50:53.909436884Z 0.000063259 "rtsp.c:5333" Connection 17: RTSP thread exit.
hauptbad_1 | 2023-09-24T08:51:53.951974407Z 60.043269742 "rtsp.c:700" Found RTSP connection thread 17 in a non-running state.
hauptbad_1 | 2023-09-24T08:51:53.952133442Z 0.000242334 "rtsp.c:703" Connection 17: deleted.
hauptbad_1 | 2023-09-24T08:51:53.952197071Z 0.000115314 "rtsp.c:724" Airplay Volume for new connections is 0.000000.
hauptbad_1 | 2023-09-24T08:52:53.997876522Z 60.046254242 "rtsp.c:724" Airplay Volume for new connections is 0.000000.
hauptbad_1 | 2023-09-24T08:53:54.057611491Z 60.060785687 "rtsp.c:724" Airplay Volume for new connections is 0.000000.
hauptbad_1 | 2023-09-24T08:54:54.117887688Z 60.061068316 "rtsp.c:724" Airplay Volume for new connections is 0.000000.
hauptbad_1 | 2023-09-24T08:55:54.119156259Z 60.002070038 "rtsp.c:724" Airplay Volume for new connections is 0.000000.
hauptbad_1 | 2023-09-24T08:56:54.179470007Z 60.060983983 "rtsp.c:724" Airplay Volume for new connections is 0.000000.
hauptbad_1 | 2023-09-24T08:57:54.239436744Z 60.060878853 "rtsp.c:724" Airplay Volume for new connections is 0.000000.
hauptbad_1 | 2023-09-24T08:58:54.299619569Z 60.060979223 "rtsp.c:724" Airplay Volume for new connections is 0.000000.
hauptbad_1 | 2023-09-24T08:59:54.336319021Z 60.037520798 "rtsp.c:724" Airplay Volume for new connections is 0.000000.
hauptbad_1 | 2023-09-24T09:00:54.396439902Z 60.060979205 "rtsp.c:724" Airplay Volume for new connections is 0.000000.
hauptbad_1 | 2023-09-24T09:01:40.057465346Z 45.661651102 "rtsp.c:724" Airplay Volume for new connections is 0.000000.
hauptbad_1 | 2023-09-24T09:01:40.057633362Z 0.000352537 "rtsp.c:5533" Connection 18 is at: 0xf0b8c630.
hauptbad_1 | 2023-09-24T09:01:40.057765379Z 0.000146556 "rtsp.c:5615" Connection 18: New connection from 192.168.88.150:60422 to self at 192.168.88.7:7000.
hauptbad_1 | 2023-09-24T09:01:40.058664218Z 0.000852333 "rtsp.c:5195" Connection 18: Received an RTSP Packet of type "OPTIONS":
hauptbad_1 | 2023-09-24T09:01:40.058778642Z 0.000079463 "rtsp.c:5197" Type: "CSeq", content: "1"
hauptbad_1 | 2023-09-24T09:01:40.058843086Z 0.000033074 "rtsp.c:5197" Type: "User-Agent", content: "owntone/28.8"
hauptbad_1 | 2023-09-24T09:01:40.058906733Z 0.000034297 "rtsp.c:5197" Type: "Client-Instance", content: "68906BCA5356CD45"
hauptbad_1 | 2023-09-24T09:01:40.058969047Z 0.000039888 "rtsp.c:5197" Type: "DACP-ID", content: "68906BCA5356CD45"
hauptbad_1 | 2023-09-24T09:01:40.059030046Z 0.000038167 "rtsp.c:5197" Type: "Active-Remote", content: "3232258050"
hauptbad_1 | 2023-09-24T09:01:40.059091453Z 0.000041000 "rtsp.c:5197" No Content Plist. Content length: 0.
hauptbad_1 | 2023-09-24T09:01:40.059152489Z 0.000034648 "rtsp.c:2616" OPTIONS request
hauptbad_1 | 2023-09-24T09:01:40.059236988Z 0.000027463 "rtsp.c:2616" Type: "CSeq", content: "1"
hauptbad_1 | 2023-09-24T09:01:40.059301024Z 0.000028297 "rtsp.c:2616" Type: "User-Agent", content: "owntone/28.8"
hauptbad_1 | 2023-09-24T09:01:40.059362671Z 0.000033425 "rtsp.c:2616" Type: "Client-Instance", content: "68906BCA5356CD45"
hauptbad_1 | 2023-09-24T09:01:40.059423041Z 0.000037649 "rtsp.c:2616" Type: "DACP-ID", content: "68906BCA5356CD45"
hauptbad_1 | 2023-09-24T09:01:40.059482040Z 0.000036629 "rtsp.c:2616" Type: "Active-Remote", content: "3232258050"
hauptbad_1 | 2023-09-24T09:01:40.059541650Z 0.000038389 "rtsp.c:2616" No Content Plist. Content length: 0.
hauptbad_1 | 2023-09-24T09:01:40.059600853Z 0.000030926 "rtsp.c:5256" Connection 18: RTSP Response:
hauptbad_1 | 2023-09-24T09:01:40.059724129Z 0.000027945 "rtsp.c:5257" Response Code: 200.
hauptbad_1 | 2023-09-24T09:01:40.059789610Z 0.000027037 "rtsp.c:5257" Type: "CSeq", content: "1"
hauptbad_1 | 2023-09-24T09:01:40.059852294Z 0.000029740 "rtsp.c:5257" Type: "Server", content: "AirTunes/366.0"
hauptbad_1 | 2023-09-24T09:01:40.059913108Z 0.000027945 "rtsp.c:5257" Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, FLUSHBUFFERED, TEARDOWN, OPTIONS, POST, GET, PUT"
hauptbad_1 | 2023-09-24T09:01:40.059974052Z 0.000039648 "rtsp.c:5257" No Content Plist. Content length: 0.
hauptbad_1 | 2023-09-24T09:01:40.060608062Z 0.001244037 "rtsp.c:5195" Connection 18: Received an RTSP Packet of type "ANNOUNCE":
hauptbad_1 | 2023-09-24T09:01:40.060735690Z 0.000068389 "rtsp.c:5197" Type: "CSeq", content: "2"
hauptbad_1 | 2023-09-24T09:01:40.060802244Z 0.000027481 "rtsp.c:5197" Type: "User-Agent", content: "owntone/28.8"
hauptbad_1 | 2023-09-24T09:01:40.060865188Z 0.000030852 "rtsp.c:5197" Type: "Client-Instance", content: "68906BCA5356CD45"
hauptbad_1 | 2023-09-24T09:01:40.060924983Z 0.000036056 "rtsp.c:5197" Type: "DACP-ID", content: "68906BCA5356CD45"
hauptbad_1 | 2023-09-24T09:01:40.060984520Z 0.000033074 "rtsp.c:5197" Type: "Active-Remote", content: "3232258050"
hauptbad_1 | 2023-09-24T09:01:40.061044852Z 0.000037111 "rtsp.c:5197" Type: "Content-Type", content: "application/sdp"
hauptbad_1 | 2023-09-24T09:01:40.061104833Z 0.000034796 "rtsp.c:5197" Type: "Content-Length", content: "184"
hauptbad_1 | 2023-09-24T09:01:40.061164073Z 0.000028593 "rtsp.c:5197" No Content Plist. Content length: 184.
hauptbad_1 | 2023-09-24T09:01:40.061221553Z 0.000030759 "rtsp.c:4455" Connection 18: ANNOUNCE
hauptbad_1 | 2023-09-24T09:01:40.136141599Z Segmentation fault (core dumped)I’ll update to the latest build today and see if this fixes the issue.
aaronk6
commented
1 year ago I can still reproduce it with the latest build (4.3.2-dev-20-gb3986ed6-dirty-AirPlay2-smi10-alac-OpenSSL-Avahi-ALSA-pa-dummy-stdout-pipe-soxr-convolution-metadata-mqtt-dbus-mpris-sysconfdir:/etc).
bad_dg_1 | 2023-09-24T11:14:40.277077240Z 0.000027444 "rtsp.c:5310" Connection 6: RTSP Response:
bad_dg_1 | 2023-09-24T11:14:40.277143462Z 0.000028852 "rtsp.c:5311" Response Code: 200.
bad_dg_1 | 2023-09-24T11:14:40.277202646Z 0.000026407 "rtsp.c:5311" Type: "CSeq", content: "349"
bad_dg_1 | 2023-09-24T11:14:40.277262849Z 0.000028056 "rtsp.c:5311" Type: "Server", content: "AirTunes/366.0"
bad_dg_1 | 2023-09-24T11:14:40.277322904Z 0.000029148 "rtsp.c:5311" No Content Plist. Content length: 0.
bad_dg_1 | 2023-09-24T11:14:41.434618919Z 1.158418666 "mdns_avahi.c:160" (Browser) REMOVE: service 'iTunes_Ctrl_DA5CD61B809033E0' of type '_dacp._tcp' in domain 'local'.
bad_dg_1 | 2023-09-24T11:14:41.838830547Z 0.404145129 "dacp.c:464" dacp_monitor_port_update_callback with Remote ID "DA5CD61B809033E0", target ID "DA5CD61B809033E0" and port number 0.
bad_dg_1 | 2023-09-24T11:14:42.839272652Z 1.000171222 "dbus-service.c:226" Build metadata
bad_dg_1 | 2023-09-24T11:14:42.840093437Z 0.000817074 "mpris-service.c:167" Build metadata
bad_dg_1 | 2023-09-24T11:15:31.656597759Z 48.817592823 "rtsp.c:707" Airplay Volume for connection 6 is -8.625001.
bad_dg_1 | 2023-09-24T11:15:31.656729164Z 0.000041407 "rtsp.c:723" Airplay Volume for new connections is -8.625001.
bad_dg_1 | 2023-09-24T11:15:40.974570761Z 9.317871680 "rtsp.c:1348" Connection 6: ETIMEDOUT -- keepalive timeout.
bad_dg_1 | 2023-09-24T11:15:40.974752092Z 0.000182833 "rtsp.c:5066" Connection 6: PTP stream rtsp_conversation_thread_func_cleanup_function called.
bad_dg_1 | 2023-09-24T11:15:40.974821498Z 0.000067537 "rtsp.c:2656" Connection 6: TEARDOWN PTP stream connection.
bad_dg_1 | 2023-09-24T11:15:40.974884405Z 0.000039130 "rtsp.c:2676" Connection 6: TEARDOWN PTP stream Delete Event Thread.
bad_dg_1 | 2023-09-24T11:15:40.975358602Z 0.000362500 "rtp.c:1564" Connection 6: AP2 Event Receiver Cleanup.
bad_dg_1 | 2023-09-24T11:15:40.976806341Z 0.000236944 "rtsp.c:2684" Connection 6: TEARDOWN PTP stream Close Event Socket.
bad_dg_1 | 2023-09-24T11:15:40.976890303Z 0.000209334 "ptp-utilities.c:223" Send control message to NQPTP: "/nqptp T"
bad_dg_1 | 2023-09-24T11:15:40.976980172Z 0.000312018 "rtsp.c:5098" Connection 6: terminating -- closing RTSP connection socket 19: from 192.168.88.19:55632 to self at 192.168.88.8:7000.
bad_dg_1 | 2023-09-24T11:15:40.977049134Z 0.000426204 "rtsp.c:5165" Connection 6: Closed.
bad_dg_1 | 2023-09-24T11:15:40.977130781Z 0.000046352 "rtsp.c:5387" Connection 6: RTSP thread exit.
bad_dg_1 | 2023-09-24T11:16:31.716933478Z 50.740879025 "rtsp.c:699" Found RTSP connection thread 6 in a non-running state.
bad_dg_1 | 2023-09-24T11:16:31.717124568Z 0.000273889 "rtsp.c:702" Connection 6: deleted.
bad_dg_1 | 2023-09-24T11:16:31.717193197Z 0.000215741 "rtsp.c:716" No active connections.
bad_dg_1 | 2023-09-24T11:16:31.717255307Z 0.000038796 "rtsp.c:723" Airplay Volume for new connections is -8.625001.
bad_dg_1 | 2023-09-24T11:17:31.745773922Z 60.029696909 "rtsp.c:723" Airplay Volume for new connections is -8.625001.
bad_dg_1 | 2023-09-24T11:18:31.785039601Z 60.039800445 "rtsp.c:723" Airplay Volume for new connections is -8.625001.
bad_dg_1 | 2023-09-24T11:19:31.824746265Z 60.040819168 "rtsp.c:723" Airplay Volume for new connections is -8.625001.
bad_dg_1 | 2023-09-24T11:20:31.829773120Z 60.005801057 "rtsp.c:723" Airplay Volume for new connections is -8.625001.
bad_dg_1 | 2023-09-24T11:21:31.831253187Z 60.002380835 "rtsp.c:723" Airplay Volume for new connections is -8.625001.
bad_dg_1 | 2023-09-24T11:22:31.891379605Z 60.061128334 "rtsp.c:723" Airplay Volume for new connections is -8.625001.
bad_dg_1 | 2023-09-24T11:23:31.909116066Z 60.018698316 "rtsp.c:723" Airplay Volume for new connections is -8.625001.
bad_dg_1 | 2023-09-24T11:24:31.910966255Z 60.002777372 "rtsp.c:723" Airplay Volume for new connections is -8.625001.
bad_dg_1 | 2023-09-24T11:25:31.959665811Z 60.049599594 "rtsp.c:723" Airplay Volume for new connections is -8.625001.
bad_dg_1 | 2023-09-24T11:26:31.992918969Z 60.034223242 "rtsp.c:723" Airplay Volume for new connections is -8.625001.
bad_dg_1 | 2023-09-24T11:27:32.019017026Z 60.026982631 "rtsp.c:723" Airplay Volume for new connections is -8.625001.
bad_dg_1 | 2023-09-24T11:28:32.079221659Z 60.061052242 "rtsp.c:723" Airplay Volume for new connections is -8.625001.
bad_dg_1 | 2023-09-24T11:29:32.129975200Z 60.051676575 "rtsp.c:723" Airplay Volume for new connections is -8.625001.
bad_dg_1 | 2023-09-24T11:30:31.731927658Z 59.602551205 "rtsp.c:723" Airplay Volume for new connections is -8.625001.
bad_dg_1 | 2023-09-24T11:30:31.732105545Z 0.000364519 "rtsp.c:5586" Connection 8 is at: 0xf0aa13c0.
bad_dg_1 | 2023-09-24T11:30:31.732944588Z 0.000141463 "rtsp.c:5668" Connection 8: New connection from 192.168.88.150:53906 to self at 192.168.88.8:7000.
bad_dg_1 | 2023-09-24T11:30:31.733056679Z 0.000793277 "rtsp.c:5249" Connection 8: Received an RTSP Packet of type "OPTIONS":
bad_dg_1 | 2023-09-24T11:30:31.733119715Z 0.000079149 "rtsp.c:5251" Type: "CSeq", content: "1"
bad_dg_1 | 2023-09-24T11:30:31.733181733Z 0.000034148 "rtsp.c:5251" Type: "User-Agent", content: "owntone/28.8"
bad_dg_1 | 2023-09-24T11:30:31.733242232Z 0.000037963 "rtsp.c:5251" Type: "Client-Instance", content: "68906BCA5356CD45"
bad_dg_1 | 2023-09-24T11:30:31.734725506Z 0.000043055 "rtsp.c:5251" Type: "DACP-ID", content: "68906BCA5356CD45"
bad_dg_1 | 2023-09-24T11:30:31.734856097Z 0.000675982 "rtsp.c:5251" Type: "Active-Remote", content: "3232258051"
bad_dg_1 | 2023-09-24T11:30:31.734924410Z 0.000055185 "rtsp.c:5251" No Content Plist. Content length: 0.
bad_dg_1 | 2023-09-24T11:30:31.734987928Z 0.000038055 "rtsp.c:2630" OPTIONS request
bad_dg_1 | 2023-09-24T11:30:31.735050927Z 0.000028630 "rtsp.c:2630" Type: "CSeq", content: "1"
bad_dg_1 | 2023-09-24T11:30:31.735112593Z 0.000028982 "rtsp.c:2630" Type: "User-Agent", content: "owntone/28.8"
bad_dg_1 | 2023-09-24T11:30:31.735174833Z 0.000033148 "rtsp.c:2630" Type: "Client-Instance", content: "68906BCA5356CD45"
bad_dg_1 | 2023-09-24T11:30:31.735304683Z 0.000036314 "rtsp.c:2630" Type: "DACP-ID", content: "68906BCA5356CD45"
bad_dg_1 | 2023-09-24T11:30:31.735371126Z 0.000035426 "rtsp.c:2630" Type: "Active-Remote", content: "3232258051"
bad_dg_1 | 2023-09-24T11:30:31.735432625Z 0.000035130 "rtsp.c:2630" No Content Plist. Content length: 0.
bad_dg_1 | 2023-09-24T11:30:31.735492495Z 0.000029889 "rtsp.c:5310" Connection 8: RTSP Response:
bad_dg_1 | 2023-09-24T11:30:31.735552605Z 0.000026074 "rtsp.c:5311" Response Code: 200.
bad_dg_1 | 2023-09-24T11:30:31.735611308Z 0.000025815 "rtsp.c:5311" Type: "CSeq", content: "1"
bad_dg_1 | 2023-09-24T11:30:31.735670992Z 0.000026129 "rtsp.c:5311" Type: "Server", content: "AirTunes/366.0"
bad_dg_1 | 2023-09-24T11:30:31.735732510Z 0.000027223 "rtsp.c:5311" Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, FLUSHBUFFERED, TEARDOWN, OPTIONS, POST, GET, PUT"
bad_dg_1 | 2023-09-24T11:30:31.735837360Z 0.000036166 "rtsp.c:5311" No Content Plist. Content length: 0.
bad_dg_1 | 2023-09-24T11:30:31.736248298Z 0.001509111 "rtsp.c:5249" Connection 8: Received an RTSP Packet of type "ANNOUNCE":
bad_dg_1 | 2023-09-24T11:30:31.736350741Z 0.000077575 "rtsp.c:5251" Type: "CSeq", content: "2"
bad_dg_1 | 2023-09-24T11:30:31.736415574Z 0.000029888 "rtsp.c:5251" Type: "User-Agent", content: "owntone/28.8"
bad_dg_1 | 2023-09-24T11:30:31.736477832Z 0.000033204 "rtsp.c:5251" Type: "Client-Instance", content: "68906BCA5356CD45"
bad_dg_1 | 2023-09-24T11:30:31.736843197Z 0.000036074 "rtsp.c:5251" Type: "DACP-ID", content: "68906BCA5356CD45"
bad_dg_1 | 2023-09-24T11:30:31.736920825Z 0.000034741 "rtsp.c:5251" Type: "Active-Remote", content: "3232258051"
bad_dg_1 | 2023-09-24T11:30:31.736983380Z 0.000034241 "rtsp.c:5251" Type: "Content-Type", content: "application/sdp"
bad_dg_1 | 2023-09-24T11:30:31.737045916Z 0.000034333 "rtsp.c:5251" Type: "Content-Length", content: "184"
bad_dg_1 | 2023-09-24T11:30:31.737107878Z 0.000027444 "rtsp.c:5251" No Content Plist. Content length: 184.
bad_dg_1 | 2023-09-24T11:30:31.737167766Z 0.000031852 "rtsp.c:4495" Connection 8: ANNOUNCE
bad_dg_1 | 2023-09-24T11:30:31.808714079Z Segmentation fault (core dumped)Many thanks!
mikebrady
commented
1 year ago Could you post the version string please? e.g:
$ shairport-sync -V
4.3.2-dev-20-gb3986ed6-AirPlay2-smi10-OpenSSL-Avahi-ALSA-dummy-stdout-pipe-soxr-metadata-mqtt-dbus-mpris-sysconfdir:/etcThanks!
iVolt1
commented
1 year ago I captured these two errors under similar circumstances using 4.3.2-dev-20-gb3986ed6-OpenSSL-Avahi-ALSA-pa-pipe-soxr-sysconfdir:/etc.
aaronk6
commented
1 year ago My version string from the latest seg fault is 4.3.2-dev-20-gb3986ed6-dirty-AirPlay2-smi10-alac-OpenSSL-Avahi-ALSA-pa-dummy-stdout-pipe-soxr-convolution-metadata-mqtt-dbus-mpris-sysconfdir:/etc (also edited into my previous message). This is docker image sha256:8e7cd26c4433834ef81015dffa41cc93449f0ebc88a3fa81dea5ddcdc9ef5a9e.
mikebrady
commented
1 year ago Here is what I did:
Play something from iOS Pause playback on iOS without disconnecting from shairport-sync Wait some time (was probably 30 minutes, I also left the house, so my phone disconnected from WiFi) Start playback from OwnTone
Thanks again for you patience. This time your procedure for causing the problem did yield an anomaly, which led to a real, definite, bug. This was that if a connection stopped abruptly, the pointer to its data structure would not always be reset, causing Shairport Sync to get confused between the stopped (and deleted) connection and a new one.
Fixed and pushed into the development branch as 4.3.2-dev-22-gd236cfc5. As ever, if you got a chance to test and report back, it would be appreciated. At your leisure, of course.
aaronk6
commented
1 year ago Great! I’ve updated and will test this today. I already had a hunch that this issue might be a different one, as it wasn’t printing anything related to Connection 0. Again, thanks for the quick fix and I’ll report back once I’ve tried this a couple of times.
mikebrady
commented
1 year ago Thanks. What’s interesting about it is that is might also explain how the Connection 0 phenomenon occurs.
iVolt1
commented
1 year ago Seg faulted this morning with 4.3.2-dev-24-g6bba7e0e-OpenSSL-Avahi-ALSA-pa-pw-soxr-sysconfdir:/etc.
Steps I took:
0.020062666 "player.c:2906" Large negative (i.e. early) sync error of -11406 frames (-0.129320 seconds), at frame: 3664174490.
1263.243180525 "player.c:1171" Aliasing of buffer index -- reset.
4.040129518 "audio_alsa.c:1754" alsa: underrun while writing 705 samples to alsa device.
0.020080833 "audio_alsa.c:1754" alsa: underrun while writing 705 samples to alsa device.
0.000176907 "player.c:2906" Large negative (i.e. early) sync error of -17588 frames (-0.199410 seconds), at frame: 3719973882.
1231.452016359 "player.c:1171" Aliasing of buffer index -- reset.
0.170542000 "rtp.c:962" Time ping turnaround time: 1019836203 ns -- it looks like a timing ping was lost.
1.879374036 "audio_alsa.c:1754" alsa: underrun while writing 705 samples to alsa device.
0.020064703 "player.c:2906" Large negative (i.e. early) sync error of -12847 frames (-0.145658 seconds), at frame: 3774371610.
1031.361377182 "player.c:2881" Large positive (i.e. late) sync error of 4444 frames (0.050385 seconds), at frame: 3819854234.
0.238596037 "player.c:2906" Large negative (i.e. early) sync error of -12120 frames (-0.137415 seconds), at frame: 3819864794.
5.328294368 "player.c:2906" Large negative (i.e. early) sync error of -4498 frames (-0.050998 seconds), at frame: 3820055578.
14.123962991 "mdns_avahi.c:296" avahi: client failure: Daemon connection failed
0.000139056 "mdns_avahi.c:299" avahi client -- we have been disconnected, so let's reconnect.
Segmentation fault
root@DietPi:/# shairport-sync -V
4.3.2-dev-24-g6bba7e0e-OpenSSL-Avahi-ALSA-pa-pw-soxr-sysconfdir:/etc
root@DietPi:/# Thanks again.
mikebrady
commented
1 year ago Thanks. This looks somewhat different -- not sure if it's progress yet 🤷♂️, though it might be...
Could I just get a better idea what you did, please, to try to reproduce it. Is the following right?
aaronk6
commented
1 year ago I can report that the seg fault isn’t reproducible for me anymore (using 4.3.2-dev-26-gbe488771-dirty-AirPlay2-smi10-alac-OpenSSL-Avahi-ALSA-pa-dummy-stdout-pipe-soxr-convolution-metadata-mqtt-dbus-mpris-sysconfdir:/etc).
However, I did notice that I now frequently get the following error on iOS, even if I don’t attempt to connect to the respective speaker. Simply bringing up the list of AirPlay speakers will trigger this error for each speaker that OwnTone is currently streaming to:
(Translates to “Connection not possible.”)
I’m wondering if this could be related to the connection handling refactoring? I’ll revert my setup back to master and see if this changes anything.
mikebrady
commented
1 year ago That's good new indeed! Have you moved to iOS 17? If so, I've been getting the same messages since moving to iOS 17. Annoying, but harmless.
aaronk6
commented
1 year ago Yes, I’m on iOS 17. So it can very well be related to that. I noticed that there are some AirPlay-related changes in there, for example, it proactively asks to connect to a speaker which can be quite handy. Regarding the error, I also found that it doesn’t break anything. As you say, just a little annoying, especially when there are multiple shairport-sync instances. I’ll file a separate issue for this.
iVolt1
commented
1 year ago Thanks. This looks somewhat different -- not sure if it's progress yet 🤷♂️, though it might be...
Could I just get a better idea what you did, please, to try to reproduce it. Is the following right?
1. OwnTone was connected to Shairport Sync. 2. Some material was played from Owntone's Spotify client. 3. The music stopped and everything was left idling overnight. 4. The volume on the OwnTone Spotify client was modified a few times. 5. Play was resumed from OwnTone's Spotify client. 6. The full sequence above occurred, i.e. Shairport Sync played for a bit less than an hour and then it segfaulted?
Correct except for #6. The segfault was immediate when play was resumed from OwnTone's Spotify client. More specifically, the client is and always been librespot-java spotify connect server piped into owntone with metadata. Music was restarted from the windows spotify client that is connected to librespot-java.
mikebrady
commented
1 year ago Yes, I’m on iOS 17. So it can very well be related to that. I noticed that there are some AirPlay-related changes in there, for example, it proactively asks to connect to a speaker which can be quite handy. Regarding the error, I also found that it doesn’t break anything. As you say, just a little annoying, especially when there are multiple shairport-sync instances. I’ll file a separate issue for this.
Thanks. Not sure what can be done about these messages -- we'd really have to get to know something about the control signals and protocols used, and right now we know very little. 😕
mikebrady
commented
1 year ago Thanks. This looks somewhat different -- not sure if it's progress yet 🤷♂️, though it might be... Could I just get a better idea what you did, please, to try to reproduce it. Is the following right?
1. OwnTone was connected to Shairport Sync. 2. Some material was played from Owntone's Spotify client. 3. The music stopped and everything was left idling overnight. 4. The volume on the OwnTone Spotify client was modified a few times. 5. Play was resumed from OwnTone's Spotify client. 6. The full sequence above occurred, i.e. Shairport Sync played for a bit less than an hour and then it segfaulted?Correct except for #6. The segfault was immediate when play was resumed from OwnTone's Spotify client. More specifically, the client is and always been librespot-java spotify connect server piped into owntone with metadata. Music was restarted from the windows spotify client that is connected to librespot-java.
Thanks. I'm curious about when this occurred:
14.123962991 "mdns_avahi.c:296" avahi: client failure: Daemon connection failedFrom your account above, it must have happened right around the time the music stopped. Of course we don't know what caused it, but the suggestion is that the avahi daemon stopped running, which would be very unusual. Does your system have a low-power sleep mode or anything like that? If you're using WiFi, is WiFi power management off?
iVolt1
commented
1 year ago I have power savings pretty much off. It is a wired GB connection on the pi 4. I was having some dropouts until I disabled all power savings, but have had none since.
I am pretty sure the two avahi messages appeared immediately on the reconnect attempt. I should have captured the before and after.
Just curious, where does the avahi client that failed run?
Is there way I capture more detailed information that might help?
root@DietPi:/# avahi-daemon -V avahi-daemon 0.8
Thanks for investigating.
mikebrady
commented
1 year ago That's useful, thanks. The avahi daemon runs on the same system as Shairport Sync and provides the Bonjour (aka "Zeroconf") service that allows apps like Shairport Sync to advertise their services (e.g. AirPlay 2) without any setup on the part of the user. Apps communicate with the Avahi daemon via the system's D-Bus service.
Shairport Sync asks it to run a client function to advertise its services and that's what seems to have failed.
The reason I thought the message might have been sent just after the music stopped was the first number:
14.123962991 "mdns_avahi.c:296" avahi: client failure: Daemon connection failedThat 14.123962991 should be the elapsed time since the last debug message was sent, but who knows what might have happened to it.
It seems to be entirely possible that this crash is because Shairport Sync could not recover from the Avahi client failure -- it's so unusual in my experience that its recovery code has not been tested with any degree of thoroughness. I'll see if I can cause it to happen artificially and maybe check what it does then...
mikebrady
commented
1 year ago So, I took a look at this, and sure enough, if I kill the Avahi daemon, Shairport Sync will fail in a fairly short time. At the moment, it isn't clear if the Avahi API will allow a clean recovery; trying to clean up seems to lead to a crash.
So, a question for me is whether the Avahi daemon (and also the D-Bus daemon) have indeed disappeared from your system overnight. Perhaps if you repeated the experiment, just before you resume play from Spotify/OwnTone, could you check to see if avahi-daemon and dbus are still running? It would also be interesting to get their PIDs while the music is playing and compare them with their PIDs if they are still running in the morning.
You could use something like:
ps aux | grep 'avahi-daemon\|dbus' -v grepand if they are there, you should get something like:
message+ 398 0.0 0.4 8372 3796 ? Ss Sep16 0:12 /usr/bin/dbus-daemon --system --address=systemd: --nofork --nopidfile --systemd-activation --syslog-only
avahi 172158 1.2 0.3 7176 3316 ? Ss 17:57 0:01 avahi-daemon: running [RaspberryPi3B.local]
avahi 172159 0.0 0.0 6892 320 ? S 17:57 0:00 avahi-daemon: chroot helperThe PIDs are 398, 172158 and 172159.
If the Avahi and/or D-Bus daemons are disappearing overnight, there's something about your system that isn't right, so it would be good to find out.
What happened?
I’m using multiple Shairport Sync instances to receive AirPlay streams from iOS devices and an OwnTone server. Sometimes, when attempting to start playback from iOS, shairport-sync crashes with a segmentation fault.
This occurs every now and then. However, I can reproduce this behavior reliably with the following steps:
Therefore, I decided to disable
allow_session_interruption(which is also the default) and manually stop playback on OwnTone when I want to stream from iOS. This works most of the time, but occasionally, I also get the segmentation fault withallow_session_interruption = "no".The log output provided below is from when
allow_session_interruptionwas set to"no".This sounds similar to https://github.com/mikebrady/shairport-sync/issues/1548, but since I’m running the latest version, it’s probably something new.
I’m unsure if it’s related to this issue, but I’m running four Docker containers on the same machine, following the guide at https://github.com/noelhibbard/shairport-sync-docker that was mentioned in https://github.com/mikebrady/shairport-sync/discussions/1444. So PulseAudio is running on the host and is being made available to the container via a Unix socket.
Relevant log output
Configuration Information.
How did you install Shairport Sync?
Docker
Check previous issues