problem with service after shutdown

Hello!

I have experienced problem with several version of dietpi and services fails to start after shutdown/reboot of raspberry pis.

First of all I dont know if this is dietpiproblem or snapcastproblem I asked for help at github in snapcast, but there was not much help to get
so I make a try here.

Enviroment: RPi 3 Model B (armv7l)

OS: DietPi v7.1.2

Problem: Snapclient fails to start after shutdown of rpi, Note, on a clean install of dietpi and snapclient the snapclient runs
as it should, it is when I shut the rpi down and start it up again the snapclient fails to start, Note also proftpd service fails to start.


Here are some commands i have run and results.

root@Hallwaysound:~# sudo systemctl status snapclient
● snapclient.service - Snapcast client
   Loaded: loaded (/lib/systemd/system/snapclient.service; enabled; vendor preset: enabled)
   Active: failed (Result: exit-code) since Sun 2021-05-23 14:04:00 CEST; 1min 19s ago
     Docs: man:snapclient(1)
  Process: 446 ExecStart=/usr/bin/snapclient --logsink=system $SNAPCLIENT_OPTS (code=exited, status=1/FAILURE)
 Main PID: 446 (code=exited, status=1/FAILURE)

May 23 14:04:00 Hallwaysound systemd[1]: snapclient.service: Service RestartSec=100ms expired, scheduling restart.
May 23 14:04:00 Hallwaysound systemd[1]: snapclient.service: Scheduled restart job, restart counter is at 5.
May 23 14:04:00 Hallwaysound systemd[1]: Stopped Snapcast client.
May 23 14:04:00 Hallwaysound systemd[1]: snapclient.service: Start request repeated too quickly.
May 23 14:04:00 Hallwaysound systemd[1]: snapclient.service: Failed with result 'exit-code'.
May 23 14:04:00 Hallwaysound systemd[1]: Failed to start Snapcast client.

And log from
journalctl -u snapclient

May 23 14:03:59 Hallwaysound systemd[1]: snapclient.service: Main process exited, code=exited, status=1/FAILURE
May 23 14:03:59 Hallwaysound systemd[1]: snapclient.service: Failed with result 'exit-code'.
May 23 14:03:59 Hallwaysound systemd[1]: snapclient.service: Service RestartSec=100ms expired, scheduling restart.
May 23 14:03:59 Hallwaysound systemd[1]: snapclient.service: Scheduled restart job, restart counter is at 4.
May 23 14:03:59 Hallwaysound systemd[1]: Stopped Snapcast client.
May 23 14:03:59 Hallwaysound systemd[1]: Started Snapcast client.
May 23 14:03:59 Hallwaysound snapclient[446]: Version 0.25.0, revision 2af5292f
May 23 14:03:59 Hallwaysound snapclient[446]: Resolving host IP for: 192.168.8.115
May 23 14:03:59 Hallwaysound snapclient[446]: Connecting
May 23 14:03:59 Hallwaysound snapclient[446]: Connected to 192.168.8.115
May 23 14:03:59 Hallwaysound snapclient[446]: My MAC: "b8:27:eb:bb:b8:8b", socket: 9
May 23 14:03:59 Hallwaysound snapclient[446]: ServerSettings - buffer: 1000, latency: 1000, volume: 8, muted: 0
May 23 14:03:59 Hallwaysound snapclient[446]: Codec: flac, sampleformat: 48000:16:2
May 23 14:03:59 Hallwaysound snapclient[446]: metadata:{"STREAM":"default"}
May 23 14:03:59 Hallwaysound snapclient[446]: Player name: alsa, device: default, description: <none>, idx: 1, sharing mode: unspecified, parameters: <none>
May 23 14:03:59 Hallwaysound snapclient[446]: Mixer mode: software, parameters: <none>
May 23 14:03:59 Hallwaysound snapclient[446]: Sampleformat: 48000:16:2, stream: 48000:16:2
May 23 14:03:59 Hallwaysound snapclient[446]: Using default buffer_time: 80 ms, default fragments: 4
May 23 14:03:59 Hallwaysound snapclient[446]: Exception: Can't open default, error: Operation not permitted, code: -1
May 23 14:03:59 Hallwaysound snapclient[446]: Exception: Can't open default, error: Operation not permitted
May 23 14:03:59 Hallwaysound snapclient[446]: Snapclient terminated.
May 23 14:03:59 Hallwaysound systemd[1]: snapclient.service: Main process exited, code=exited, status=1/FAILURE
May 23 14:03:59 Hallwaysound systemd[1]: snapclient.service: Failed with result 'exit-code'.
May 23 14:04:00 Hallwaysound systemd[1]: snapclient.service: Service RestartSec=100ms expired, scheduling restart.
May 23 14:04:00 Hallwaysound systemd[1]: snapclient.service: Scheduled restart job, restart counter is at 5.
May 23 14:04:00 Hallwaysound systemd[1]: Stopped Snapcast client.
May 23 14:04:00 Hallwaysound systemd[1]: snapclient.service: Start request repeated too quickly.
May 23 14:04:00 Hallwaysound systemd[1]: snapclient.service: Failed with result 'exit-code'.
May 23 14:04:00 Hallwaysound systemd[1]: Failed to start Snapcast client.



I have files in /run ,

root@Hallwaysound:~# ls -ls /run
total 20
0 -rw-------  1 root root      0 May 23 14:03 agetty.reload
0 drwxr-xr-x  2 root root     60 May 23 14:03 blkid
0 drwxr-xr-x  2 root root     80 May 23 14:03 console-setup
4 -rw-r--r--  1 root root      4 May 23 14:04 crond.pid
0 ----------  1 root root      0 May 23 14:04 crond.reboot
0 drwxrwxrwx  2 root root    100 May 23 14:05 dietpi
4 -rw-r--r--  1 root root      4 May 23 14:03 dropbear.pid
0 prw-------  1 root root      0 Feb 14  2019 initctl
0 drwxrwxrwt  3 root root     80 May 23 14:03 lock
0 drwxr-xr-x  3 root root     60 Feb 14  2019 log
0 drwxr-xr-x  2 root root     40 Feb 14  2019 mount
0 drwxr-xr-x  2 root root    120 May 23 14:03 network
0 drwxr-xr-x  2 root root     40 May 23 14:03 proftpd
0 srwxrwxrwx  1 root root      0 May 23 14:03 proftpd.sock
4 -rw-r--r--  1 root root      4 May 23 14:03 rngd.pid
0 drwxr-xr-x  2 root root     60 May 23 14:03 sendsigs.omit.d
0 lrwxrwxrwx  1 root root      8 May 23 14:03 shm -> /dev/shm
0 drwx--x--x  3 root root     60 May 23 14:03 sudo
0 drwxr-xr-x 16 root root    380 May 23 14:04 systemd
0 drwxr-xr-x  2 root root     60 Feb 14  2019 tmpfiles.d
0 drwxr-xr-x  7 root root    160 May 23 14:03 udev
0 drwxr-xr-x  2 root root     40 May 23 14:03 user
4 -rw-rw-r--  1 root utmp   1536 May 23 14:05 utmp
0 drwxr-x---  2 root netdev   80 May 23 14:03 wpa_supplicant
4 -rw-r--r--  1 root root      4 May 23 14:03 wpa_supplicant.wlan0.pid

and here is directories

root@Hallwaysound:~# df -h
Filesystem      Size  Used Avail Use% Mounted on
/dev/root        15G  1.7G   13G  13% /
devtmpfs        455M     0  455M   0% /dev
tmpfs           487M     0  487M   0% /dev/shm
tmpfs           487M   13M  475M   3% /run
tmpfs           5.0M  4.0K  5.0M   1% /run/lock
tmpfs           487M     0  487M   0% /sys/fs/cgroup
tmpfs           1.0G     0  1.0G   0% /tmp
tmpfs            50M     0   50M   0% /var/log
/dev/mmcblk0p1  253M   50M  203M  20% /boot

So anyone now how to solve this problem, make snapclient start again after reboot.

Hi,

can you share following

systemctl cat snapclient
journalctl -u snapclient
ls -la /var/log

Yes of course

systemctl cat snapclient

 
# /lib/systemd/system/snapclient.service
[Unit]
Description=Snapcast client
Documentation=man:snapclient(1)
Wants=avahi-daemon.service
After=network-online.target time-sync.target sound.target avahi-daemon.service

[Service]
EnvironmentFile=-/etc/default/snapclient
ExecStart=/usr/bin/snapclient --logsink=system $SNAPCLIENT_OPTS
User=snapclient
Group=snapclient
Restart=on-failure

journalctl -u snapclient

May 23 21:55:20 Hallwaysound systemd[1]: Started Snapcast client.
May 23 21:55:20 Hallwaysound snapclient[1420]: Version 0.25.0, revision 2af5292f
May 23 21:55:20 Hallwaysound snapclient[1420]: Resolving host IP for: 192.168.8.115
May 23 21:55:20 Hallwaysound snapclient[1420]: Connecting
May 23 21:55:20 Hallwaysound snapclient[1420]: Connected to 192.168.8.115
May 23 21:55:20 Hallwaysound snapclient[1420]: My MAC: "b8:27:eb:bb:b8:8b", socket: 9
May 23 21:55:20 Hallwaysound snapclient[1420]: ServerSettings - buffer: 1000, latency: 0, volume: 36, muted: 0
May 23 21:55:20 Hallwaysound snapclient[1420]: Codec: flac, sampleformat: 48000:16:2
May 23 21:55:20 Hallwaysound snapclient[1420]: metadata:{"STREAM":"default"}
May 23 21:55:20 Hallwaysound snapclient[1420]: Player name: alsa, device: default, description: <none>, idx: 1, sharing mode: unspecified, parameters: <none>
May 23 21:55:20 Hallwaysound snapclient[1420]: Mixer mode: software, parameters: <none>
May 23 21:55:20 Hallwaysound snapclient[1420]: Sampleformat: 48000:16:2, stream: 48000:16:2
May 23 21:55:20 Hallwaysound snapclient[1420]: Using default buffer_time: 80 ms, default fragments: 4
May 23 21:55:20 Hallwaysound snapclient[1420]: Exception: Can't open default, error: Operation not permitted, code: -1
May 23 21:55:20 Hallwaysound snapclient[1420]: Exception: Can't open default, error: Operation not permitted
May 23 21:55:20 Hallwaysound snapclient[1420]: Snapclient terminated.
May 23 21:55:20 Hallwaysound systemd[1]: snapclient.service: Main process exited, code=exited, status=1/FAILURE
May 23 21:55:20 Hallwaysound systemd[1]: snapclient.service: Failed with result 'exit-code'.
May 23 21:55:20 Hallwaysound systemd[1]: snapclient.service: Service RestartSec=100ms expired, scheduling restart.
May 23 21:55:20 Hallwaysound systemd[1]: snapclient.service: Scheduled restart job, restart counter is at 3.
May 23 21:55:20 Hallwaysound systemd[1]: Stopped Snapcast client.
May 23 21:55:20 Hallwaysound systemd[1]: Started Snapcast client.
May 23 21:55:20 Hallwaysound snapclient[1426]: Version 0.25.0, revision 2af5292f
May 23 21:55:20 Hallwaysound snapclient[1426]: Resolving host IP for: 192.168.8.115
May 23 21:55:20 Hallwaysound snapclient[1426]: Connecting
May 23 21:55:20 Hallwaysound snapclient[1426]: Connected to 192.168.8.115
May 23 21:55:20 Hallwaysound snapclient[1426]: My MAC: "b8:27:eb:bb:b8:8b", socket: 9
May 23 21:55:20 Hallwaysound snapclient[1426]: ServerSettings - buffer: 1000, latency: 0, volume: 36, muted: 0
May 23 21:55:20 Hallwaysound snapclient[1426]: metadata:{"STREAM":"default"}
May 23 21:55:20 Hallwaysound snapclient[1426]: Codec: flac, sampleformat: 48000:16:2
May 23 21:55:20 Hallwaysound snapclient[1426]: Player name: alsa, device: default, description: <none>, idx: 1, sharing mode: unspecified, parameters: <none>
May 23 21:55:20 Hallwaysound snapclient[1426]: Mixer mode: software, parameters: <none>
May 23 21:55:20 Hallwaysound snapclient[1426]: Sampleformat: 48000:16:2, stream: 48000:16:2
May 23 21:55:20 Hallwaysound snapclient[1426]: Using default buffer_time: 80 ms, default fragments: 4
May 23 21:55:20 Hallwaysound snapclient[1426]: Exception: Can't open default, error: Operation not permitted, code: -1
May 23 21:55:20 Hallwaysound snapclient[1426]: Exception: Can't open default, error: Operation not permitted
May 23 21:55:20 Hallwaysound snapclient[1426]: Snapclient terminated.
May 23 21:55:20 Hallwaysound systemd[1]: snapclient.service: Main process exited, code=exited, status=1/FAILURE
May 23 21:55:20 Hallwaysound systemd[1]: snapclient.service: Failed with result 'exit-code'.
May 23 21:55:21 Hallwaysound systemd[1]: snapclient.service: Service RestartSec=100ms expired, scheduling restart.
May 23 21:55:21 Hallwaysound systemd[1]: snapclient.service: Scheduled restart job, restart counter is at 4.
May 23 21:55:21 Hallwaysound systemd[1]: Stopped Snapcast client.
May 23 21:55:21 Hallwaysound systemd[1]: Started Snapcast client.
May 23 21:55:21 Hallwaysound snapclient[1432]: Version 0.25.0, revision 2af5292f
May 23 21:55:21 Hallwaysound snapclient[1432]: Resolving host IP for: 192.168.8.115
May 23 21:55:21 Hallwaysound snapclient[1432]: Connecting
May 23 21:55:21 Hallwaysound snapclient[1432]: Connected to 192.168.8.115
May 23 21:55:21 Hallwaysound snapclient[1432]: My MAC: "b8:27:eb:bb:b8:8b", socket: 9
May 23 21:55:21 Hallwaysound snapclient[1432]: ServerSettings - buffer: 1000, latency: 0, volume: 36, muted: 0
May 23 21:55:21 Hallwaysound snapclient[1432]: metadata:{"STREAM":"default"}
May 23 21:55:21 Hallwaysound snapclient[1432]: Codec: flac, sampleformat: 48000:16:2
May 23 21:55:21 Hallwaysound snapclient[1432]: Player name: alsa, device: default, description: <none>, idx: 1, sharing mode: unspecified, parameters: <none>
May 23 21:55:21 Hallwaysound snapclient[1432]: Mixer mode: software, parameters: <none>
May 23 21:55:21 Hallwaysound snapclient[1432]: Sampleformat: 48000:16:2, stream: 48000:16:2
May 23 21:55:21 Hallwaysound snapclient[1432]: Using default buffer_time: 80 ms, default fragments: 4
May 23 21:55:21 Hallwaysound snapclient[1432]: Exception: Can't open default, error: Operation not permitted, code: -1
May 23 21:55:21 Hallwaysound snapclient[1432]: Exception: Can't open default, error: Operation not permitted
May 23 21:55:21 Hallwaysound snapclient[1432]: Snapclient terminated.
May 23 21:55:21 Hallwaysound systemd[1]: snapclient.service: Main process exited, code=exited, status=1/FAILURE
May 23 21:55:21 Hallwaysound systemd[1]: snapclient.service: Failed with result 'exit-code'.
May 23 21:55:21 Hallwaysound systemd[1]: snapclient.service: Service RestartSec=100ms expired, scheduling restart.
May 23 21:55:21 Hallwaysound systemd[1]: snapclient.service: Scheduled restart job, restart counter is at 5.
May 23 21:55:21 Hallwaysound systemd[1]: Stopped Snapcast client.
May 23 21:55:21 Hallwaysound systemd[1]: snapclient.service: Start request repeated too quickly.
May 23 21:55:21 Hallwaysound systemd[1]: snapclient.service: Failed with result 'exit-code'.
May 23 21:55:21 Hallwaysound systemd[1]: Failed to start Snapcast client.

AND: ls -la /var/log

total 12
drwxr-xr-x  4 root root  160 May 23 21:59 .
drwxr-xr-x 12 root root 4096 May 23 22:02 ..
drwxr-xr-x  2 root root  100 May 23 21:02 apt
-rw-rw----  1 root utmp    0 May 23 21:02 btmp
-rw-r--r--  1 root root    0 May 23 21:02 dpkg.log
-rw-rw-r--  1 root utmp  292 May 23 22:03 lastlog
drwx------  2 root root   40 Sep 10  2020 private
-rw-rw-r--  1 root utmp 1536 May 23 22:03 wtmp

some extra sidenotes, snapcast server works, I have other snapclients running all day.
I have changed from static IP to DHCP at rpi running the this problem, when changed from static to dhcp snapclient went from failed to active in systemctl. but after a while it went back to failed.

looks like the client is trying to open some default “device” I guess which is failing, causing snapclient to terminate

May 23 21:55:21 Hallwaysound snapclient[1432]: Exception: Can't open default, error: Operation not permitted, code: -1
May 23 21:55:21 Hallwaysound snapclient[1432]: Exception: Can't open default, error: Operation not permitted
May 23 21:55:21 Hallwaysound snapclient[1432]: Snapclient terminated.

Well! pretty much mindblown over here, I kind of did a guess and changed soundcard options from

rpi-bcm2835-3.5mm                 : Onboard: 3.5mm forced output

to

hw:0,0 : Headphones bcm2835 Headphones

and turn auto conversion to off

and restarted snapclient , and voila snapclient is running again.

aaaaand rpi and ssh lost connection, connected again made a sudo reboot and snapclient failed to start again,
changed back from hw0,0 to : [rpi-bcm2835-3.5mm]

saved rebooted again and now snapclient working.

It´s a mystery.

does it survive another reboot?

Yes, in fact, snapclient service survived after a sudo shutdown and wallwart unplugged and 30sec waiting.

Can´t explain why it works and suddenly it fails to work, maybe a wifi/network problem maybe snapclient hangs in a loop if it cant reach
the server but that does´nt explain why it starts after I fiddling around with rpis soundcards settings.

But now it works, and I know how (maybe) to fix it next time.