Too long restart on rpi2, 3

[a-x-]

Apprx. 1 munite restart via systemctl

Happened between 1.1.1-23-gd65b8e8 (i'm not sure) and 3.1.7 versions

[a-x-]

my build instruction:
https://github.com/a-x-/tg-rpi-smart-home-bot/wiki/Installation-everything-DRAFT#setup-airplay-iphone-stream

[a-x-]

shairport-sync -V
3.1.7-OpenSSL-Avahi-ALSA-soxr-metadata-sysconfdir:/etc

[a-x-]

I'm not sure how to show systemd logs

journalctl 
No journal files were found.

I reconfigure it right now:
/etc/systemd/journald.conf:

[Journal]
Storage=persistent

[mikebrady]

Thans for the post, but it's rather hard to work out what the issue is. What is 1.1.1-23-gd65b8e8?

BTW, you need to be privileged to read the journal, and you don't need to alter its setting. Try, e.g:

$sudo journalctl…

[Alphakilo]

@a-x- :
Try journalctl --system or sudo journalctl --system.
The output of systemd-analyze blame --no-pager --system would be interesting as well.

[davidhq]

I also noticed this on RaspberryPi, I'm on latest commit:

commit d2713a40a7833cf1ef74f6691561fc8c77534e07
Author: Mike Brady <mikebrady@eircom.net>
Date:   Sat May 19 09:39:25 2018 +0100

Also, when it works, works great, but lot of times, streaming from iPhone produces no sound and also forked-daapd cannot stream (checking the speaker immediately unchecks it).

The only solution is to restart the whole device since sudo systemctl restart shairport-sync hangs......

May 20 12:35:05 ela systemd[1]: shairport-sync.service: State 'stop-sigterm' timed out. Killing.
May 20 12:35:05 ela systemd[1]: shairport-sync.service: Killing process 477 (shairport-sync) with signal SIGKILL.
May 20 12:35:05 ela systemd[1]: shairport-sync.service: Main process exited, code=killed, status=9/KILL
May 20 12:35:05 ela systemd[1]: shairport-sync.service: Unit entered failed state.
May 20 12:35:05 ela systemd[1]: shairport-sync.service: Failed with result 'timeout'.

[mikebrady]

Thanks for the report. Would you be kind enough to set the log_verbosity to 2 in the settings file and try to capture a log while this problem is occurring? That should make it easier to track down. Also, if you could say what kind of Pi and what versions of the OS, if would be very helpful.

[Update] Also, the output of $ systemd-analyze blame --no-pager --system, as suggested by @Alphakilo, would be useful too! Thanks.

[davidhq]

Linux living-room 4.14.34-v7+ #1110 SMP Mon Apr 16 15:18:51 BST 2018 armv7l GNU/Linux
2018-04-18-raspbian-stretch-lite

Both RPi 3B and 3B+ instances

I set log level to 2 on one of them, since then I could restart shairport-sync (!!)... so no report from this one, it just happened on another, couldn't restart again, I then set verbosity to 2 and rebooted the machine (it also took some time)...

I think shairport gets stuck probably somehow because I noticed the issue again by trying to set the output of forked-daapd to this instance and it immediately turned off..

Something is not the best with shairport besides this restarting issue, this is probably connected...

So, again, I noticed: cannot send output from forked-daapd, cannot play from iPhone (seems to be playing and the song progresses, but nothing plays).

Report after reboot:

$ systemd-analyze blame --no-pager --system
          6.907s dhcpcd.service
          4.653s hciuart.service
          3.101s apt-daily.service
          2.769s dev-mmcblk0p2.device
          1.271s raspi-config.service
           769ms networking.service
           676ms lighttpd.service
           659ms keyboard-setup.service
           482ms ssh.service
           433ms dphys-swapfile.service
           338ms ntp.service
           313ms systemd-fsck@dev-disk-by\x2dpartuuid-c7cb7e34\x2d01.service
           301ms systemd-udev-trigger.service
           265ms systemd-fsck-root.service
           234ms systemd-logind.service
           234ms systemd-udevd.service
           198ms systemd-tmpfiles-setup-dev.service
           191ms rsyslog.service
           177ms fake-hwclock.service
           163ms systemd-journald.service
           149ms avahi-daemon.service
           148ms plymouth-start.service
           129ms sys-kernel-debug.mount
           125ms bluetooth.service
           111ms systemd-remount-fs.service
           108ms dev-mqueue.mount
           100ms run-rpc_pipefs.mount
            94ms wifi-country.service
            88ms systemd-tmpfiles-setup.service
            82ms systemd-sysctl.service
            79ms kmod-static-nodes.service
            70ms triggerhappy.service
            69ms systemd-update-utmp.service
            69ms systemd-modules-load.service
            69ms systemd-journal-flush.service
            67ms alsa-restore.service
            63ms rc-local.service
            57ms nfs-config.service
            55ms plymouth-read-write.service
            53ms console-setup.service
            47ms systemd-user-sessions.service
            47ms sys-kernel-config.mount
            39ms systemd-rfkill.service
            37ms systemd-random-seed.service
            35ms plymouth-quit.service
            32ms systemd-update-utmp-runlevel.service
            31ms plymouth-quit-wait.service
            22ms boot.mount

[mikebrady]

Thanks for this. All that seems fine. I have it running on a 3B here on Stretch Lite 4.14.41-v7+ #1113 without problems, so I wonder, what other applications do you have running on the Pi?

Something that might be worth trying is to delay automatic startup for a few seconds -- see here in the TROUBLESHOTING.md page.

Is it possible to get the output of $ sudo systemctl status shairport-sync?

[davidhq]

You are right, I forgot to turn off wifi power management, after 1 day of testing with power management turned off, for now no issues with shairtport-sync — Thank you!

I have an update for your document (I can make a pull request if you want), so this:

Alternatively, (also for the Raspberry Pi), add the following line:

wireless-power off
to the file /etc/network/interfaces.

was never working for me, tried again, power management=on after reboot again (so it didn't work)...

What works:

sudo nano /etc/network/if-up.d/off-power-manager

Type:

#!/bin/sh
/sbin/iwconfig wlan0 power off

sudo chmod +x /etc/network/if-up.d/off-power-manager

[davidhq]

UPDATE:

The problem still present but much less frequently... I managed to confuse shairport by trying to rewing a track streaming from iPhone Music app directly to shairport instance.. it became unresponsive, I sshed into pi, tried to stop the service, it hung... then I rebooted (it also took a minute or two). Power management is off, unfortunately logging was disabled on this instance.. I enabled it, waiting for this to happen again, then I'll send the logs

[davidhq]

UPDATE:

Problem is present with forked-daapd source as well (so not just streaming from iPhone)

I managed to capture the logs:

May 27 20:20:28 lab shairport-sync[494]: Already playing.
May 27 20:20:28 lab shairport-sync[494]: Connection 13: RTSP thread terminated.
May 27 20:31:58 lab shairport-sync[494]: New RTSP connection from 192.168.0.10:36868 to self at 192.168.0.92:5000 on conversation thread 14.
May 27 20:31:59 lab shairport-sync[494]: Connection 14: ANNOUNCE
May 27 20:31:59 lab shairport-sync[494]: RTSP Conversation thread 8 already playing when asked by thread 14.
May 27 20:31:59 lab shairport-sync[494]: ANNOUNCE failed to get the player
May 27 20:31:59 lab shairport-sync[494]: Already playing.
May 27 20:31:59 lab shairport-sync[494]: Connection 14: RTSP thread terminated.

I don't think "Already playing." part is true... because nothing was playing for a long time. Maybe what is different with my setup is that I have three different forked-daapd libraries as source and I play from different ones at different times... of course I have to stop the play from some forked-daapd source before starting from another.

After service stop issued:

May 27 20:36:32 lab shairport-sync[494]: Request to shut down all rtsp conversation threads
May 27 20:36:32 lab shairport-sync[494]: asking playing threads to stop
May 27 20:38:02 lab systemd[1]: shairport-sync.service: State 'stop-sigterm' timed out. Killing.
May 27 20:38:02 lab systemd[1]: shairport-sync.service: Killing process 494 (shairport-sync) with signal SIGKILL.
May 27 20:38:02 lab systemd[1]: shairport-sync.service: Main process exited, code=killed, status=9/KILL
May 27 20:38:02 lab systemd[1]: shairport-sync.service: Unit entered failed state.
May 27 20:38:02 lab systemd[1]: shairport-sync.service: Failed with result 'timeout'.

So as you can see - 2 min delay before anything happens...

Hope something can be seen from this?

Tried attaching gdb but I already issued stop command and I didn't manage to find anything in 2 minutes because I don't really know how to use gdb correctly in this case (should I try with something else when it happens again?).

[mikebrady]

Many thanks for your great work and for your patience. It seems that, for some reason, Shairport Sync is hanging up in certain circumstances -- not correctly terminating a session.

As you'll have seen from recent comments in the development branch, some bugs have recently been fixed. The version you are using incorporates these fixes, so it would be very interesting for me to see if we could catch Shairport Sync [still] locking up. Of course, it may be unrelated.

So, if you could update to the latest development version, please, and set the log verbosity to 2, it would be a big help. The amount of output on log level 2 has been modified so that it will print RTSP messages coming from the sources (all except for one very common one), so we should be able to see the requests for a play session and for the termination of a session coming in, and get an idea what's happening. It shouldn't be too chatty. The idea is that if it happens again, you would have a history in the log of all the calls to set up and terminate the now-hung-up session and of the session that was refused because the hung-up session was already playing.

Using gdb for this would be very difficult -- effectively impossible IMHO -- because it would require manual intervention from time to time.

[mikebrady]

As a matter of interest, what output device are you using please?

[davidhq]

Hi,

Raspberry Pi B and B+ via mostly USB soundcard (hw1,0) and one RPi uses HifiBerry Digi+.

I have new report with development version:

May 29 10:01:03 lab shairport-sync[504]:   Type: "CSeq", content: "2"
May 29 10:01:03 lab shairport-sync[504]:   Type: "Server", content: "AirTunes/105.1"
May 29 10:01:03 lab shairport-sync[504]: Connection 7: RTSP thread terminated.
May 29 10:01:20 lab shairport-sync[504]: New RTSP connection from 192.168.0.60:58298 to self at 192.168.0.92:5000 on conversation thread 8.
May 29 10:01:20 lab shairport-sync[504]: RTSP thread 8 received an RTSP Packet of type "ANNOUNCE":
May 29 10:01:20 lab shairport-sync[504]:   Type: "CSeq", content: "2"
May 29 10:01:20 lab shairport-sync[504]:   Type: "User-Agent", content: "forked-daapd/26.0"
May 29 10:01:20 lab shairport-sync[504]:   Type: "Client-Instance", content: "5AFCFBF5BBCE89AD"
May 29 10:01:20 lab shairport-sync[504]:   Type: "DACP-ID", content: "5AFCFBF5BBCE89AD"
May 29 10:01:20 lab shairport-sync[504]:   Type: "Content-Type", content: "application/sdp"
May 29 10:01:20 lab shairport-sync[504]:   Type: "Apple-Challenge", content: "KXjVZVPPIWLWw5Ja841Rpw"
May 29 10:01:20 lab shairport-sync[504]:   Type: "Content-Length", content: "570"
May 29 10:01:20 lab shairport-sync[504]: Connection 8: ANNOUNCE
May 29 10:01:20 lab shairport-sync[504]: RTSP Conversation thread 6 already playing when asked by thread 8.
May 29 10:01:20 lab shairport-sync[504]: ANNOUNCE failed to get the player
May 29 10:01:20 lab shairport-sync[504]: Already playing.
May 29 10:01:20 lab shairport-sync[504]: RTSP thread 8: RTSP Response:
May 29 10:01:20 lab shairport-sync[504]:   Type: "Apple-Response", content: "26aZ0SBsS5PBTr1E75XX+cG6yScNT2pvI/G0CqGM5mmb6+/Pbx/iUvpcvPpKK0TBzVLn2L2+Ju72SGfVw4UAk13qx6k1K0JpIudUVAghOcjQmV6j680euJZTMGHH0f/mRBKV5cSmAgec6ll6DCJgo5azLrnJdeOeAFmh7jkt1KbpfDncftn1559jA3GrIDICpaJmIiMSgoaSrxhuZDyYAzUGfbW0f3SzOPRt1mkiZEOZkzUsxYVz9muW6Xg1SShv25vGHCCsoL9FYtK1pc5arryj6R5851qz8KaMrjkq38pr9Xx9kZtR0dw/2KoXyy4pH0G41eylAzJiYiZ0+xd5kw"
May 29 10:01:20 lab shairport-sync[504]:   Type: "CSeq", content: "2"
May 29 10:01:20 lab shairport-sync[504]:   Type: "Server", content: "AirTunes/105.1"
May 29 10:01:20 lab shairport-sync[504]: Connection 8: RTSP thread terminated.

So on one of the devices I cannot play again, It's loading the connection to speaker in mobile app (Remote), then fails... Again Already playing. ...