balbuze/volumio-plugins

Volumio stays not visible for API

Opened this issue · 26 comments

Hi,

I want to build an automation in homeassistant with Node-Red to start a playlist with a button or automatically later if I am able to :-)

My problem is that "Volumio" doesn't stay visible for the Spotify API.

So wenn I do an
https://api.spotify.com/v1/me/player/devices
while playing on Volumio the player Volumio is visible and stays so for maybe 24h or so and then it disappears so I cannot access him via the API.

I tried disabling the multiuser support in your plugin but unfortunately that doesn't do the trick.

Do you have an idea to solve this?

Thank you!

Greets
/Artaxx

As I think that was a problem with the home assistant integration of Spotify.

Since HA introduced the new integration the connection to the Spotify API won't be lost if you turn off multiuser support.

If that solves the problem at all I can report the next few days but at the moment it looks good.

OK, after some testing the situation hasn't changed. Accessing Volumio through the API is only possible ~ 24h after connecting.

Is there a chance to restart the plugin via cron? That might solve the problem.

@artaxx81 could you check the uptime the next time it goes missing?
If it is indeed 24 hours, then might need to re-authenticate at that mark..
PS: currently at I'm at 16 hours, its still visible from the API - will check again tomorrow!

volumio@volumio:~$ systemctl status volspotconnect2.service
● volspotconnect2.service - Volspotconnect2 Daemon
   Loaded: loaded (/etc/systemd/system/volspotconnect2.service; disabled; vendor preset: enabled)
   Active: active (running) since Wed 2020-04-29 17:31:42 UTC; 16h ago
 Main PID: 1382 (bash)
    Tasks: 5 (limit: 4550)
   Memory: 24.2M
   CGroup: /system.slice/volspotconnect2.service
           ├─1382 /bin/bash /data/plugins/music_service/volspotconnect2/startconnect.sh
           └─1384 ./vollibrespot -c volspotify.toml

Apr 30 01:17:56 volumio volumio[1382]: [Vollibrespot] : API Token expired, refreshing...
Apr 30 02:15:56 volumio volumio[1382]: [Vollibrespot] : API Token expired, refreshing...
Apr 30 03:13:57 volumio volumio[1382]: [Vollibrespot] : API Token expired, refreshing...
Apr 30 04:11:57 volumio volumio[1382]: [Vollibrespot] : API Token expired, refreshing...
Apr 30 05:09:57 volumio volumio[1382]: [Vollibrespot] : API Token expired, refreshing...
Apr 30 06:07:57 volumio volumio[1382]: [Vollibrespot] : API Token expired, refreshing...
Apr 30 07:05:58 volumio volumio[1382]: [Vollibrespot] : API Token expired, refreshing...
Apr 30 08:03:58 volumio volumio[1382]: [Vollibrespot] : API Token expired, refreshing...
Apr 30 09:01:58 volumio volumio[1382]: [Vollibrespot] : API Token expired, refreshing...
Apr 30 09:59:58 volumio volumio[1382]: [Vollibrespot] : API Token expired, refreshing...

Ah OK, I see. Then this is a normal beaviour that the API token has to be refreshed?

This is my output (but I do not listen to music on volumio every day):

volumio@volumio:~$ systemctl status volspotconnect2.service
● volspotconnect2.service - Volspotconnect2 Daemon
   Loaded: loaded (/etc/systemd/system/volspotconnect2.service; disabled)
   Active: active (running) since Di 2020-04-28 10:42:14 UTC; 2 days ago
 Main PID: 1390 (bash)
   CGroup: /system.slice/volspotconnect2.service
           ├─1390 /bin/bash /data/plugins/music_service/volspotconnect2/startconnect.sh
           └─1392 ./vollibrespot -c volspotify.toml

Warning: Journal has been rotated since unit was started. Log output is incomplete or unavailable.
volumio@volumio:~$

Thank you!

Ah, are some recent logs available with journalctl -fu volspotconnect2.service ?

Unfortunately not :-(

Hmm, can't do much without logs :-( How about a simple journalctl | grep '[Voll\|Spotif]'

I guess volumiologrotate enabled for you as well?

Also nothing with the last journalctl.

I didn't changed anything due to the logs.

@artaxx81 no issues from my tests. I am not sure what is going on your side without the logs!
image

May you tell me how to disable volumiologrotate?

I might be wrong here - looking at the script, it is cleaning up only files in /var/log while journalctl should be storing them in /var/run/log but give it a shot!

# Check if it is running
systemctl status volumiologrotate.service
# Stop it until next boot
systemctl stop volumiologrotate.service

OK, thank you. It was active.

I am coming back with some logs.

On further inspection, it would seem the volumiologrotate service doesn't touch the systemmd log files. May I ask what device are you on?

I am on a RPi 3 Mod. B

And what is the size of your sd card, and also current log files journalctl --disk-usage

volumio@volumio:~$ journalctl --disk-usage
No journal files were found.
Journals take up 0B on disk.
volumio@volumio:~$ df -h
Filesystem           Size  Used Avail Use% Mounted on
/dev/mmcblk0p2       2,2G  1,1G  966M  54% /imgpart
/dev/loop0           340M  340M     0 100% /static
overlay              5,0G  1,2G  3,6G  24% /
devtmpfs             471M     0  471M   0% /dev
tmpfs                485M  142M  344M  30% /dev/shm
tmpfs                485M   33M  453M   7% /run
tmpfs                5,0M  4,0K  5,0M   1% /run/lock
tmpfs                485M     0  485M   0% /sys/fs/cgroup
tmpfs                485M   18M  468M   4% /tmp
tmpfs                485M     0  485M   0% /var/spool/cups
tmpfs                 20M  6,2M   14M  31% /var/log
tmpfs                485M     0  485M   0% /var/spool/cups/tmp
/dev/mmcblk0p1        61M   59M  1,9M  97% /boot
192.168.0.100:Music  3,7T  3,2T  458G  88% /mnt/NAS/iTunes
tmpfs                 97M     0   97M   0% /run/user/1000
volumio@volumio:~$ 

@artaxx81 I just realised that the issue is probably cause the user doesn't have the right permission.

groups volumio
# should show that the volumio user isn't a member of systemd-journal

So just do a sudo journalctl -fu volspotconnect2.service to check the logs..

Ah OK, so here are some logs:

Mai 02 01:53:39 volumio volumio[1390]: stack backtrace:
Mai 02 01:53:39 volumio volumio[1390]: [Vollibrespot] : SessionError: Connection reset by peer (os error 104)
Mai 02 01:53:42 volumio systemd[1]: volspotconnect2.service holdoff time over, scheduling restart.
Mai 02 01:53:42 volumio systemd[1]: Stopping Volspotconnect2 Daemon...
Mai 02 01:53:42 volumio systemd[1]: Starting Volspotconnect2 Daemon...
Mai 02 01:53:42 volumio systemd[1]: Started Volspotconnect2 Daemon.
Mai 02 01:53:42 volumio volumio[728]: vollibrespot v0.2.0 0c51076 2020-04-17 (librespot 8d65d82 2020-03-10) -- Built On 2020-04-17
Mai 02 01:53:42 volumio volumio[728]: Reading Config from "volspotify.toml"
Mai 02 01:53:42 volumio volumio[728]: [Vollibrespot] : Using Alsa backend with device: plughw:1
Mai 02 01:53:42 volumio volumio[728]: [Vollibrespot] : Failed to register IPv6 receiver: Os { code: 19, kind: Other, message: "No such device" }

So that's the reason - Connection reset by peer shows that Spotify reset your connection, and as you have it setup as a multiuser account, it restarts and waits for someone to re-auth..
If this happens often, then as you pointed out earlier, you can disable the multiuser and add your credentials, so that it always reconnects with the same user.

PS: please start back your logrotate service!

OK, I disabled multiuser. I will see if this works.

Unfortunately volumio was gone after a few hours without playing although multiuser was disabled.

I decided to restart the volspotconnect2 plugin every time when my Pre-Amp turns on to get my project with the playlist playing depending on which person is in the room going.

I think this is the only reliable solution for my project here.

Unfortunately volumio was gone after a few hours without playing although multiuser was disabled.

Did you happen to look into the logs to see why?

No, I haven't ... I am using Node-Red for my project and I have to have perfect conditions for that. Without them I cannot even start my project. That remote SSH restart was my 100% constructive solution. As I see there are no other people having the same problem so I decided to solve this on my side and not to bother others with my specific problems.

That was unfair ... sorry!

I see if I can reproduce the this with another installation. I am not sure why only my installation has that problem. For me it is essentially necessary that the player stays visible.

I will report!

No issues ;-) I was just wondering if it was something trivial like a network drop that was causing your troubles. Cause then you can just use systemd to restart the service...

Restarting the service before start playing the playlist is constructive for me because the only problem with the plugin is the visibility for the API.

I do not wan't to explain my plans to much because I wan't to get that going before I publish it.

Your plugin is a more than essential part of that so I opened that issue.

Thanks a lot for your work and the opportunities you give us small "developers" (I would not even say that I am a developer)