Rpi-jukebox-rfid: Something wrong after commit "install script libspotify-dev"?

[JoeyRamone]

Hello Everybody,

could it be, that the libspotify-dev in the sudo apt-get... part lead to an failure of the other packages? If I use the one-line installation, I got error messages, that php7.3 is not working, pip is unknown, git is unknown... and so on.

Best regards

[FloMrFrei]

Hi there,

I experienced the same issue. libspotify-dev cannot be found, this causes an error and stops the installation. If you install libspotify-dev before running the 1-line installation script, it should work:

I was able to install libspotify-dev by following https://docs.mopidy.com/en/latest/installation/debian/:

wget -q -O - https://apt.mopidy.com/mopidy.gpg | sudo apt-key add -
sudo wget -q -O /etc/apt/sources.list.d/mopidy.list https://apt.mopidy.com/buster.list
sudo apt update
sudo apt-get install libspotify-dev

It does however, not solve the problem reported here: https://github.com/MiczFlor/RPi-Jukebox-RFID/issues/688

Kind regards

[splitti]

I think there are different problems, some of them caused by the workarounds. One is Python and the modules of Python. Also the existing scripts are mostly written for Python 2.0, but there are modules gone and these scripts should be updated. Sometimes it is something easy like missing ().
I will investigate some time in the future to help Micz. I must get well first ;-)

[patrickweigelt]

That would be great @splitti. I set up two jukeboxes from scratch on Monday and Tuesday (due to mopidy connection problems) using the one-line install sript for buster and the workarounds to install libspotify-dev (https://github.com/MiczFlor/RPi-Jukebox-RFID/issues/700#issuecomment-570956201) and to downgrade mopidy and tornado (https://github.com/MiczFlor/RPi-Jukebox-RFID/issues/688#issuecomment-571129900). Interestingly It worked fine right after setting them up (much better than previously with my old setup and the connection problems) but after a day mopidy wouldn't connect to spotify anymore. Installing mopidy 2.3.1-1 yet again setting up the etc/mopidy config file and enabling the mopidy service plus renewing the music library via the webapp makes it run fine for a day again but then at some point it suddenly doesn't connect any more again and I need to rerun the steps above to make it run again. Any idea what could be going on?
I am using two raspi 3B, one with a Hifiberry dac and one with an usb soundcard, gpio buttons and a rotary encoder.

[splitti]

That sound really strange, like loosing a token or something. I will buy a third box just for developing, so please wait a few days.

But try to check the status of the mopidy service after restarting and after trying to play a file:
sudo service mopidy status

[patrickweigelt]

@splitti As long as it is working, the mopidy status looks fine I think. It is active (running) and in the log section there are a lot of things loaded and Spotify is logged in with my username:

Jan 11 19:42:45 JukeboxM mopidy[4756]: INFO Loading config from /etc/mopidy/mopidy.conf
Jan 11 19:42:45 JukeboxM mopidy[4756]: INFO Loading config from command line options
Jan 11 19:42:45 JukeboxM mopidy[4756]: INFO Enabled extensions: iris, mpd, http, stream, spotify, m3u, softwaremixer, file,
Jan 11 19:42:45 JukeboxM mopidy[4756]: INFO Disabled extensions: none
Jan 11 19:42:46 JukeboxM mopidy[4756]: INFO Starting Mopidy mixer: SoftwareMixer
Jan 11 19:42:46 JukeboxM mopidy[4756]: INFO Mixer volume set to 30
Jan 11 19:42:46 JukeboxM mopidy[4756]: INFO Starting Mopidy audio
Jan 11 19:42:46 JukeboxM mopidy[4756]: INFO Starting Mopidy backends: StreamBackend, M3UBackend, FileBackend, LocalBackend,
Jan 11 19:42:46 JukeboxM mopidy[4756]: INFO Audio output set to "alsasink"
Jan 11 19:42:46 JukeboxM mopidy[4756]: INFO Loaded 6 local tracks using json
Jan 11 19:42:47 JukeboxM mopidy[4756]: INFO Logged in to Spotify in online mode
Jan 11 19:42:47 JukeboxM mopidy[4756]: INFO Logged into Spotify Web API as myusername
Jan 11 19:42:47 JukeboxM mopidy[4756]: INFO Started spotify backend
Jan 11 19:42:47 JukeboxM mopidy[4756]: INFO Starting Mopidy core
Jan 11 19:42:47 JukeboxM mopidy[4756]: INFO Starting Mopidy frontends: MpdFrontend, HttpFrontend, IrisFrontend
Jan 11 19:42:47 JukeboxM mopidy[4756]: INFO MPD server running at [::ffff:0.0.0.0]:6600
Jan 11 19:42:47 JukeboxM mopidy[4756]: INFO HTTP server running at [::ffff:0.0.0.0]:6680
Jan 11 19:42:47 JukeboxM mopidy[4756]: INFO Starting Iris 3.43.0
Jan 11 19:42:47 JukeboxM mopidy[4756]: INFO Starting GLib mainloop
Jan 11 19:43:22 JukeboxM mopidy[454]: INFO New MPD connection from [::ffff:127.0.0.1]:47164
Jan 11 19:43:22 JukeboxM mopidy[454]: INFO New MPD connection from [::ffff:127.0.0.1]:47168
Jan 11 19:43:25 JukeboxM mopidy[454]: INFO Loaded 46 playlists
Jan 11 19:43:27 JukeboxM mopidy[454]: INFO Refresh Playlists took 15965ms
Jan 11 19:43:50 JukeboxM mopidy[454]: INFO New MPD connection from [::ffff:127.0.0.1]:47172
Jan 11 19:43:55 JukeboxM mopidy[454]: INFO New MPD connection from [::ffff:127.0.0.1]:47176

One of my Jukeboxes always has connection problems after booting. When it is not working, I think (from looking at the log file) the problem is that:

2020-01-11 15:14:34,819 ERROR [456:SpotifyEventLoop] spotify.session: Spotify login error:
2020-01-11 15:14:34,822 INFO [456:SpotifyEventLoop] spotify.session: Spotify logged out
2020-01-11 15:14:37,347 INFO [456:SpotifyBackend-7] mopidy_spotify.web: Logged into Spotify Web API as myusername

When I then swipe a card it adds this to the log file:

Jan 11 19:53:24 JukeboxM mopidy[455]: INFO Failed to lookup "spotify:album:7yvYdDAsjPZNkavntJUOYh": Session must be logged in and online to load objects

I also found this on the log file:

2020-01-11 19:42:47,610 WARNING [4756:SpotifyBackend-7] py.warnings: /usr/lib/python2.7/dist-packages/spotify/session.py:239: UserWarning: Spotify broke the libspotify playlists API 2018-05-24 and never restored it. Please use the Spotify Web API to work with playlists.
"Spotify broke the libspotify playlists API 2018-05-24 "

Anyways, the problem above, I can fix by scanning the music library via the web app. Afterwards it works and the log looks good. Usually when I power on the jukebox it doesn't work and then after scanning the music library it works. In the beginning (first day) it worked totally fine.

However, sometimes (once per day last week), both Jukeboxes completely stop working. Then, the service as shown on the webapp is dead, IRIS webapp doesn't load and also when I check the status via systemctl it says the mopidy service doesn't extist. The log file doesn't show anything new. scanning the music library doesn't help. This is when I reinstall mopidy 2.3.1-1 to make it run again. Interestingly it tells me that it needs to downgrade mopidy as if it has updated to mopidy 3 in the background (autoupdates are turned off though). It also told me that there are a lot of packages that are not required any more after downgrading and that I can uninstall them. I ignored this the first couple of times but did run sudo apt autoremove the last time. After that the problem appeared once again so far and again I needed to downgrade and a few packages were left that I needed to uninstall. I did so (yesterday on one jukebox and today on the other). So far the severe problem has not appeared again yet (let's see) but the connection problems of the one Jukebox as described further up persist. What I also noted and what's curious is that in IRIS the Jukebox without connection problems shows anonymous as spotify user and the other one with connection problems shows the actual username. Also the design of both webapps looks a bit different although it is IRIS 3.43.0 on both boxes. Oh my, it is so confusing.

[MiczFlor]

Hi @splitti @patrickweigelt @FloMrFrei
I link @FloMrFrei comment here:
https://github.com/MiczFlor/RPi-Jukebox-RFID/issues/718#issuecomment-574416729
Would be great if the three of you could create a pull request against the buster install script and test it.
:)
Team work on that scale would be a first in the Phoniebox community.

[patrickweigelt]

Hi @MiczFlor @splitti @FloMrFrei. I did: https://github.com/MiczFlor/RPi-Jukebox-RFID/pull/720

Maybe you could review it. The installation worked for me like this but I had to try it a couple of time due to problems with wget. The wget part is in there twice now which should be unnessecary and I am also not sure we actually need the two lines sudo python2.7 -m pip install Mopidy==2.3.* and sudo pip install 'tornado==5.0' if we don't install mopidy 3 but 2.3 in the first place, probably not. Also, we could add apt-mark hold mopidy to make sure mopidy isn't ugraded later on (from https://github.com/MiczFlor/RPi-Jukebox-RFID/issues/688#issuecomment-572978950).

[s-martin]

The PRs #789 and #793 have been merged to master and develop.

Could you please check, if the issue is fixed now?

[s-martin]

We are upgrading to Mopidy 3 #803, which should fix some issues. PR #804 has been merged. Please try Mopidy 3 by using
cd; rm buster-install-*; wget https://raw.githubusercontent.com/MiczFlor/RPi-Jukebox-RFID/develop/scripts/installscripts/buster-install-mopidy3.sh; chmod +x buster-install-mopidy3.sh; GIT_BRANCH=develop bash ./buster-install-mopidy3.sh

[kuesimon]

hi @s-martin. I used your install lines for mopidy 3 and there were no errors in my installation.
Also Mopidy and Iris seem to be running smoothly. Spotify Integration is also working fine.

One thing i realized but i don't know if i can expect it for the spotify version to run is that local mp3s are not played in this installation - is this an unexpected behaviour?

kind Regards!

[s-martin]

One thing i realized but i don't know if i can expect it for the spotify version to run is that local mp3s are not played in this installation - is this an unexpected behaviour?

Local mp3 should work also with the Spotify version.

You could try to play a mp3 file and post the logs again.

[kuesimon]

Mar 6 21:45:17 raspberrypi rsyslogd: [origin software="rsyslogd" swVersion="8.1901.0" x-pid="332" x-info="https://www.rsyslog.com"] rsyslogd was HUPed
Mar 6 21:45:17 raspberrypi systemd[1]: logrotate.service: Succeeded.
Mar 6 21:45:17 raspberrypi systemd[1]: Started Rotate log files.
Mar 6 21:45:18 raspberrypi systemd[1]: phpsessionclean.service: Succeeded.
Mar 6 21:45:18 raspberrypi systemd[1]: Started Clean php session files.
Mar 6 21:45:20 raspberrypi systemd[1]: man-db.service: Succeeded.
Mar 6 21:45:20 raspberrypi systemd[1]: Started Daily man-db regeneration.
Mar 6 21:45:21 raspberrypi systemd[1]: apt-daily.service: Succeeded.
Mar 6 21:45:21 raspberrypi systemd[1]: Started Daily apt download activities.
Mar 6 21:45:21 raspberrypi systemd[1]: Starting Daily apt upgrade and clean activities...
Mar 6 21:45:22 raspberrypi systemd[1]: systemd-hostnamed.service: Succeeded.
Mar 6 21:45:23 raspberrypi systemd[1]: apt-daily-upgrade.service: Succeeded.
Mar 6 21:45:23 raspberrypi systemd[1]: Started Daily apt upgrade and clean activities.
Mar 6 21:45:56 raspberrypi systemd[1]: phoniebox-idle-watchdog.service: Succeeded.
Mar 6 21:48:22 raspberrypi systemd[1]: Created slice User Slice of UID 1000.
Mar 6 21:48:22 raspberrypi systemd[1]: Starting User Runtime Directory /run/user/1000...
Mar 6 21:48:22 raspberrypi systemd[1]: Started User Runtime Directory /run/user/1000.
Mar 6 21:48:22 raspberrypi systemd[1]: Starting User Manager for UID 1000...
Mar 6 21:48:22 raspberrypi systemd[1801]: Listening on GnuPG cryptographic agent and passphrase cache (access for web browsers).
Mar 6 21:48:22 raspberrypi systemd[1801]: Reached target Timers.
Mar 6 21:48:22 raspberrypi systemd[1801]: Listening on GnuPG cryptographic agent and passphrase cache (restricted).
Mar 6 21:48:22 raspberrypi systemd[1801]: Starting D-Bus User Message Bus Socket.
Mar 6 21:48:22 raspberrypi systemd[1801]: Reached target Paths.
Mar 6 21:48:22 raspberrypi systemd[1801]: Listening on GnuPG cryptographic agent (ssh-agent emulation).
Mar 6 21:48:22 raspberrypi systemd[1801]: Listening on GnuPG network certificate management daemon.
Mar 6 21:48:22 raspberrypi systemd[1801]: Listening on GnuPG cryptographic agent and passphrase cache.
Mar 6 21:48:22 raspberrypi systemd[1801]: Listening on D-Bus User Message Bus Socket.
Mar 6 21:48:22 raspberrypi systemd[1801]: Reached target Sockets.
Mar 6 21:48:22 raspberrypi systemd[1801]: Reached target Basic System.
Mar 6 21:48:22 raspberrypi systemd[1]: Started User Manager for UID 1000.
Mar 6 21:48:22 raspberrypi systemd[1801]: Starting Music Player Daemon...
Mar 6 21:48:22 raspberrypi systemd[1]: Started Session c1 of user pi.
Mar 6 21:48:24 raspberrypi mpd[1814]: exception: failed to open log file "/var/log/mpd/mpd.log" (config line 40): Permission denied
Mar 6 21:48:25 raspberrypi systemd[1801]: mpd.service: Main process exited, code=exited, status=1/FAILURE
Mar 6 21:48:25 raspberrypi systemd[1801]: mpd.service: Failed with result 'exit-code'.
Mar 6 21:48:25 raspberrypi systemd[1801]: Failed to start Music Player Daemon.
Mar 6 21:48:25 raspberrypi systemd[1801]: Reached target Default.
Mar 6 21:48:25 raspberrypi systemd[1801]: Startup finished in 2.559s.
Mar 6 21:49:09 raspberrypi python3[591]: 2020-03-06 21:49:09,664 - root - INFO - Trigger Play Cardid=0006414375
Mar 6 21:49:09 raspberrypi mopidy[595]: INFO [MpdSession-15] mopidy_mpd.session New MPD connection from [::ffff:127.0.0.1]:45678
Mar 6 21:49:10 raspberrypi mopidy[595]: INFO [MpdSession-16] mopidy_mpd.session New MPD connection from [::ffff:127.0.0.1]:45682
Mar 6 21:49:10 raspberrypi python3[591]: volume: 30% repeat: off random: off single: off consume: off
Mar 6 21:49:10 raspberrypi mopidy[595]: INFO [MpdSession-17] mopidy_mpd.session New MPD connection from [::ffff:127.0.0.1]:45686
Mar 6 21:49:10 raspberrypi python3[591]: volume: 30% repeat: off random: off single: off consume: off
Mar 6 21:49:10 raspberrypi mopidy[595]: ERROR [IrisFrontend-11] mopidy.listener Triggering event failed: tracklist_changed()
Mar 6 21:49:10 raspberrypi mopidy[595]: Traceback (most recent call last):
Mar 6 21:49:10 raspberrypi mopidy[595]: File "/usr/lib/python3/dist-packages/mopidy/listener.py", line 40, in on_event
Mar 6 21:49:10 raspberrypi mopidy[595]: getattr(self, event)(**kwargs)
Mar 6 21:49:10 raspberrypi mopidy[595]: File "/usr/local/lib/python3.7/dist-packages/mopidy_iris/frontend.py", line 29, in tracklist_changed
Mar 6 21:49:10 raspberrypi mopidy[595]: iris.ioloop.add_callback(functools.partial(iris.clean_queue_metadata))
Mar 6 21:49:10 raspberrypi mopidy[595]: AttributeError: 'NoneType' object has no attribute 'add_callback'
Mar 6 21:49:10 raspberrypi mopidy[595]: INFO [MpdSession-18] mopidy_mpd.session New MPD connection from [::ffff:127.0.0.1]:45690
Mar 6 21:49:10 raspberrypi mopidy[595]: ERROR [LocalBackend-7] mopidy_local.library Lookup error for local:track:benjaminBluemchen/imKrankenhaus/Benjamin%20Bl%C3%BCmchen%20-%20Im%20Krankenhaus%20%28Folge%2013%29%20%20%20H%C3%96RSPIEL%20DES%20MONATS%20FEBRUAR.mp3: no such table: tracks
Mar 6 21:49:10 raspberrypi python3[591]: loading: benjaminBluemchen % imKrankenhaus
Mar 6 21:49:10 raspberrypi mopidy[595]: INFO [MpdSession-19] mopidy_mpd.session New MPD connection from [::ffff:127.0.0.1]:45694
Mar 6 21:49:10 raspberrypi python3[591]: volume: 30% repeat: off random: off single: off consume: off
Mar 6 21:49:10 raspberrypi mopidy[595]: INFO [MpdSession-20] mopidy_mpd.session New MPD connection from [::ffff:127.0.0.1]:45698
Mar 6 21:49:10 raspberrypi python3[591]: volume: 30% repeat: off random: off single: off consume: off
Mar 6 21:49:10 raspberrypi mopidy[595]: INFO [MpdSession-21] mopidy_mpd.session New MPD connection from [::ffff:127.0.0.1]:45702
Mar 6 21:49:10 raspberrypi python3[591]: OK MPD 0.19.0
Mar 6 21:49:10 raspberrypi python3[591]: OK

This is thelog of tail -n 500 /var/log/syslog after scanning an id for a local file.

[s-martin]

What does pip3 show mopidy-iris show?

[kuesimon]

What does pip3 show mopidy-iris show?

Name: Mopidy-Iris
Version: 3.45.1
Summary: Fully-featured Mopidy frontend client
Home-page: https://github.com/jaedb/iris
Author: James Barnsley
Author-email: [email protected]
License: Apache License, Version 2.0
Location: /usr/local/lib/python3.7/dist-packages
Requires: setuptools, Pykka, Mopidy
Required-by:

[kuesimon]

It seems to be my mistake. After scanning the lib again and restart of mopidy also the local file is played - it seems that i have finally a fully functional box!
Regards of a happy kuesimon :-)

[ZyanKLee]

@JoeyRamone do you still encounter this problem?

[JoeyRamone]

@ZyanKLee Last Installation worked finde. I'll test it this weekend again with the current repository.

[s-martin]

Issues were fixed, so I close this now.

If any similar problems occur, please open a new issue.