after a while service stops without being restarted

[klauskobald]

Nov 14 18:18:19 sfinxhome systemd[1]: Started Shairport Sync - AirPlay Audio Receiver.
Nov 14 22:42:37 sfinxhome systemd[1]: shairport-sync.service: Main process exited, code=killed, status=8/FPE
Nov 14 22:42:37 sfinxhome systemd[1]: shairport-sync.service: Failed with result 'signal'.

any idea why this is happening? It's mostly occurring during playback.

[klauskobald]

I added

Restart=always
RestartSec=1

into the service file. Let's see, if that helps.

[mikebrady]

Thanks. It should not be exiting though. It seems to be a floating point exception. A wild guess is possible divide by zero, so I'll have a look and see what I can find. Can you get it to happen regularly at all?

[klauskobald]

it happend twice yesterday. Last night I started it from CLI with the -vvv option. It worked till this morning. These are the last lines before I did ctrl-c it. Looks normal. Is there a possibility to turn on vvv in the service?

Today service did not quit.

        0.063380342 "player.c:2288" first frame sync error (positive --> late): 38 frames, 0.862 mS at 44100 frames per second output.
         0.115457623 "rtsp.c:475" msg_init message 2793
         0.002543013 "rtsp.c:580" RTSP Message Received: "OPTIONS * RTSP/1.0".
         0.003460019 "rtsp.c:610"     CSeq: 9.
         0.001598009 "rtsp.c:610"     DACP-ID: 1E770D116B023E7E.
         0.000191001 "rtsp.c:610"     Active-Remote: 949141239.
         0.000110000 "rtsp.c:610"     User-Agent: AirPlay/595.13.1.
         0.000117001 "rtsp.c:475" msg_init message 2794
         0.002595014 "rtsp.c:2663" Connection 2: Received an RTSP Packet of type "OPTIONS":
         0.000224001 "rtsp.c:507"   Type: "CSeq", content: "9"
         0.000068001 "rtsp.c:507"   Type: "DACP-ID", content: "1E770D116B023E7E"
         0.000183001 "rtsp.c:507"   Type: "Active-Remote", content: "949141239"
         0.000066000 "rtsp.c:507"   Type: "User-Agent", content: "AirPlay/595.13.1"
         0.000107001 "rtsp.c:901" Connection 2: OPTIONS
         0.000098000 "rtsp.c:2706" Connection 2: RTSP Response:
         0.000060000 "rtsp.c:507"   Type: "CSeq", content: "9"
         0.000086001 "rtsp.c:507"   Type: "Server", content: "AirTunes/105.1"
         0.000086000 "rtsp.c:507"   Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER"
         0.000402002 "rtsp.c:556" msg_free freed message 2794
         0.000147001 "rtsp.c:556" msg_free freed message 2793
         0.397696147 "rtsp.c:475" msg_init message 2795
         0.002303012 "rtsp.c:580" RTSP Message Received: "TEARDOWN rtsp://fd71:287a:a319:3:e274:ba53:b76a:2542/1151954350952432517 RTSP/1.0".
         0.002227012 "rtsp.c:610"     CSeq: 10.
         0.002476013 "rtsp.c:610"     DACP-ID: 1E770D116B023E7E.
         0.001251007 "rtsp.c:610"     Active-Remote: 949141239.
         0.001298007 "rtsp.c:610"     User-Agent: AirPlay/595.13.1.
         0.000288002 "rtsp.c:475" msg_init message 2796
         0.000180001 "rtsp.c:2663" Connection 2: Received an RTSP Packet of type "TEARDOWN":
         0.000069000 "rtsp.c:507"   Type: "CSeq", content: "10"
         0.000091000 "rtsp.c:507"   Type: "DACP-ID", content: "1E770D116B023E7E"
         0.000088001 "rtsp.c:507"   Type: "Active-Remote", content: "949141239"
         0.000059000 "rtsp.c:507"   Type: "User-Agent", content: "AirPlay/595.13.1"
         0.000099001 "rtsp.c:911" Connection 2: TEARDOWN
         0.000102000 "common.c:1390" mutex_lock "&playing_conn_lock" at "rtsp.c:304".
         0.000178001 "common.c:1413" mutex_unlock "&playing_conn_lock" at "rtsp.c:307".
         0.000125001 "rtsp.c:918" TEARDOWN: synchronously terminating the player thread of RTSP conversation thread 2 (2).
         0.000172001 "player.c:3130" player_stop
         0.000063000 "player.c:3132" player_thread cancel...
         0.000092001 "player.c:3134" player_thread join...
         0.002238012 "player.c:1632" Connection 2: player thread main loop exit via player_thread_cleanup_handler.
         0.002313012 "common.c:1390" mutex_lock "&alsa_mutex" at "audio_alsa.c:1851".
         0.004858027 "audio_alsa.c:1861" alsa: flush() -- closing the output device
         0.005953032 "audio_alsa.c:1779" alsa: do_close() -- closing alsa handle
         0.002351012 "audio_alsa.c:1863" alsa: flush() -- alsa_backend_state => abm_disconnected.
         0.000171001 "common.c:1413" mutex_unlock "&alsa_mutex" at "audio_alsa.c:1867".
         0.001361008 "player.c:1658" Cancelling timing, control and audio threads...
         0.002530013 "player.c:1659" Cancel timing thread.
         0.002015011 "rtp.c:526" Timing Receiver Cleanup.
         0.001119006 "rtp.c:551" Cancel Timing Requester.
         0.000389002 "rtp.c:555" Join Timing Requester.
         0.001216007 "rtp.c:457" Connection 2: Timing Sender Cleanup.
         0.002534014 "rtp.c:557" Timing Receiver Cleanup Successful.
         0.001496008 "player.c:1661" Join timing thread.
         0.000360002 "player.c:1663" Timing thread terminated.
         0.001818009 "player.c:1664" Cancel control thread.
         0.003052017 "rtp.c:232" Control Receiver Cleanup Done.
         0.001622009 "player.c:1666" Join control thread.
         0.000280001 "player.c:1668" Control thread terminated.
         0.000979005 "player.c:1669" Cancel audio thread.
         0.000483003 "rtp.c:97" Audio Receiver Cleanup Done.
         0.001402008 "player.c:1671" Join audio thread.
         0.000740004 "player.c:1673" Audio thread terminated.
         0.001824009 "common.c:1390" mutex_lock "&conn->reference_time_mutex" at "rtp.c:1052".
         0.001025006 "common.c:1413" mutex_unlock "&conn->reference_time_mutex" at "rtp.c:1055".
         0.001376007 "player.c:3141" player_thread joined.
         0.001114006 "player.c:3146" pend
         0.000925005 "common.c:1390" mutex_lock "&activity_monitor_mutex" at "activity_monitor.c:115".
         0.000555003 "rtsp.c:289" metadata queue- "pipe" 0/500.
         0.003813021 "rtsp.c:1531"      pipe: type 73736e63, code 70656e64, length 0.
         0.000432002 "rtsp.c:1534"      pipe: done.
         0.000134001 "rtsp.c:289" metadata queue- "multicast" 0/500.
         0.001307007 "rtsp.c:1568"                                                                     multicast: type 73736e63, code 70656e64, length 0.
         0.001174006 "rtsp.c:1572"                                                                     multicast: done.
         0.000572003 "rtsp.c:921" TEARDOWN: successful termination of playing thread of RTSP conversation thread 2.
         0.001961011 "rtsp.c:2706" Connection 2: RTSP Response:
         0.000188001 "rtsp.c:507"   Type: "CSeq", content: "10"
         0.000939005 "rtsp.c:507"   Type: "Server", content: "AirTunes/105.1"
         0.000246001 "rtsp.c:507"   Type: "Connection", content: "close"
         0.001318008 "rtsp.c:556" msg_free freed message 2796
         0.000320001 "rtsp.c:556" msg_free freed message 2795
         0.022285121 "rtsp.c:655" Connection 2: -- connection closed.
         0.000433002 "rtsp.c:2778" Connection 2: Terminate RTSP connection.
         0.001121006 "rtsp.c:2533" Connection 2: rtsp_conversation_thread_func_cleanup_function called.
         0.000082000 "rtsp.c:2537" Closing timing, control and audio sockets...
         0.000229002 "rtsp.c:2546" Connection 2: closing fd 8.
         0.000312001 "rtsp.c:2548" Connection 2: closed fd 8.
         0.000126001 "rtsp.c:2582" Cancel watchdog thread.
         0.001266007 "rtsp.c:313" Connection 2: Watchdog Exit.
         0.001445008 "rtsp.c:2584" Join watchdog thread.
         0.001069005 "rtsp.c:2586" Delete watchdog mutex.
         0.001121006 "rtsp.c:2589" Connection 2: Checking play lock.
         0.000902005 "common.c:1390" mutex_lock "&playing_conn_lock" at "rtsp.c:2590".
         0.000769004 "rtsp.c:2592" Connection 2: Unlocking play lock.
         0.000988006 "common.c:1413" mutex_unlock "&playing_conn_lock" at "rtsp.c:2595".
         0.000268001 "rtsp.c:2597" Connection 2: terminated.
         9.957957560 "activity_monitor.c:91" aend
         0.002376013 "rtsp.c:289" metadata queue- "pipe" 0/500.
         0.000885005 "rtsp.c:289" metadata queue- "multicast" 0/500.
         0.003796021 "rtsp.c:1568"                                                                     multicast: type 73736e63, code 61656e64, length 0.
         0.002869016 "rtsp.c:1572"                                                                     multicast: done.
         0.000911005 "rtsp.c:1531"      pipe: type 73736e63, code 61656e64, length 0.
         0.002157012 "rtsp.c:1534"      pipe: done.
        46.831019044 "rtsp.c:397" found RTSP connection thread 2 in a non-running state.
         0.002490693 "rtsp.c:399" RTSP connection thread 2 deleted...

You could put a try-catch block around the main loop and simply restart then quickly.

[mikebrady]

Thanks -- that log looks normal.

The try-catch thing would be okay, but it would be much better to find the problem and fix it.

A really useful thing would be to run Shairport Sync from the command line under gdb, maybe inside a detached screen session. Then, when the FPE occurred, one could do a gdb backtrace using bt and find the code that caused the exception.

Can I ask what kind of equipment/app you are using for the source?

[mikebrady]

I see that you are already able to run it from the CLI for a long period, so I could give you the instructions for running it under gdb. (It would probably also be good to rebuild it with compiler optimisations turned off.)

[klauskobald]

it's raspberry pi zero W. connected to USB is a native instrument K6 audio device. before doing that, I will let it run on cli again. maybe when it terminates it shows some more info.

[mikebrady]

Thanks. And could you say what you're playing from? Is it iOS or macOS or AppleTV? What apps are you using? (The reason I'm asking is in case I might be able to replicate the situation here.)

[mikebrady]

Another question -- could you post the version string for the Shairport Sync you are using please?

$ shairport-sync -V

It might look something like this:

$ shairport-sync -V
4.1-dev-20-gfb1b2e9d-AirPlay2-OpenSSL-Avahi-ALSA-soxr-sysconfdir:/etc

[klauskobald]

oh shit - that looks old! 3.3.8-OpenSSL-Avahi-ALSA-metadata-sysconfdir:/usr/local/etc I followed this tutorial: https://appcodelabs.com/7-easy-steps-to-apple-airplay-on-raspberry-pi but the link there points to the "latest", doesn't it?

[mikebrady]

Thanks! It's actually the latest release. I have not come across the FPE exception before -- so it's really quite interesting -- and I'll look in the master branch, which is where the release code is, to see what can be found. However, if I make changes, they'll likely be in the development branch.

[mikebrady]

Hi there. I've added code to the latest development version to check (I think!) all division and modulus calls that might possibly have a divide by zero in them. The checks might cause Shairport Sync to exit but it should leave a message in the log. So if you got a chance to try it out, that would be great.

[mikebrady]

See also #1398 -- this might have been fixed.

[github-actions[bot]]

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