Rpi-jukebox-rfid: dev. version not working with mpd

Created on 5 May 2020 · 14Comments · Source: MiczFlor/RPi-Jukebox-RFID

Bug

After a clean install, doing only the needed configuration. After reboot:
May 5 21:50:22 raspberrypi mpd[1775]: exception: failed to open log file "/var/log/mpd/mpd.log" (config line 40): Permission denied
May 5 21:50:22 raspberrypi systemd[1762]: mpd.service: Main process exited, code=exited, status=1/FAILURE
May 5 21:50:22 raspberrypi systemd[1762]: mpd.service: Failed with result 'exit-code'.
May 5 21:50:22 raspberrypi systemd[1762]: Failed to start Music Player Daemon.

What I did

so that the error does not occur anymore:
sudo chmod 777 -R /var/log/mpd

What happened

May 5 21:56:46 raspberrypi mpd[818]: May 05 21:56 : exception: Failed to set group 0: Operation not permitted
May 5 21:56:47 raspberrypi systemd[793]: mpd.service: Main process exited, code=exited, status=1/FAILURE
May 5 21:56:47 raspberrypi systemd[793]: mpd.service: Failed with result 'exit-code'.
May 5 21:56:47 raspberrypi systemd[793]: Failed to start Music Player Daemon.

I expected this to happen

That mpd is working now. But it doesnt

Further information that might help

Got this the second time now (did a new clean install and the same error again)

Further info (mopidy seems to have also href="pi@raspberrypi">pi@raspberrypi:~ $ journalctl -u mopidy
BST, end at Tue 2020-05-05 21:58:51 BST. --
Starting Mopidy music server...
Started Mopidy music server.
[MainThread] mopidy.__main__ Starting Mopidy 3.0.2
[MainThread] mopidy.config Loading config from builtin defaults
[MainThread] mopidy.config Loading config from file:///usr/share/mopidy/conf.d/mopidy.conf
[MainThread] mopidy.config Loading config from file:///usr/share/mopidy/conf.d/mopidy-local.conf
[MainThread] mopidy.config Loading config from file:///etc/mopidy/mopidy.conf
[MainThread] mopidy.config Loading config from command line options
[MainThread] mopidy.config Ignoring config section 'iris' because no matching extension was found
[MainThread] mopidy.internal.log Loading logging config '/etc/mopidy/logging.conf' failed. 'formatters'
[MainThread] mopidy.__main__ Enabled extensions: softwaremixer, mpd, file, m3u, stream, spotify, local, http
[MainThread] mopidy.__main__ Disabled extensions: none
[MainThread] mopidy.commands Starting Mopidy mixer: SoftwareMixer
[MainThread] mopidy.commands Mixer volume set to 30
[MainThread] mopidy.commands Starting Mopidy audio
[MainThread] mopidy.commands Starting Mopidy backends: FileBackend, M3UBackend, StreamBackend, SpotifyBackend, LocalBackend
[Audio-2] mopidy.audio.actor Audio output set to "alsasink"
[SpotifyEventLoop] mopidy_spotify.backend Logged in to Spotify in online mode
[SpotifyBackend-6] mopidy_spotify.web Logged into Spotify Web API as htpzc
[SpotifyBackend-6] mopidy_spotify.playlists Refreshed 48 Spotify playlists
[MainThread] mopidy.commands Starting Mopidy core
[MainThread] mopidy.commands Starting Mopidy frontends: HttpFrontend, MpdFrontend
[HttpFrontend-12] mopidy.http.actor HTTP server running at [::ffff:0.0.0.0]:6680
[MainThread] mopidy_mpd.actor MPD server running at [::ffff:0.0.0.0]:6600
[MainThread] mopidy.commands Starting GLib mainloop

Rebooting - even more errors occure - httpd deamon, mpd, mopidy ... :-(

May 5 22:16:08 raspberrypi systemd[800]: Starting Music Player Daemon...
May 5 22:16:08 raspberrypi systemd[1]: Started Session c2 of user pi.
May 5 22:16:08 raspberrypi systemd[1]: Started Session c1 of user pi.
May 5 22:16:08 raspberrypi systemd[1]: Startup finished in 2.301s (kernel) + 56.834s (userspace) = 59.136s.
May 5 22:16:12 raspberrypi lighttpd[756]: echo: write error: Broken pipe
May 5 22:16:14 raspberrypi systemd[1]: systemd-hostnamed.service: Succeeded.
May 5 22:16:18 raspberrypi lighttpd[756]: echo: write error: Broken pipe
May 5 22:16:22 raspberrypi mopidy[452]: INFO [MainThread] mopidy.__main__ Starting Mopidy 3.0.2
May 5 22:16:22 raspberrypi mopidy[452]: INFO [MainThread] mopidy.config Loading config from builtin defaults
May 5 22:16:22 raspberrypi mopidy[452]: INFO [MainThread] mopidy.config Loading config from file:///usr/share/mopidy/conf.d/mopidy.conf
May 5 22:16:22 raspberrypi mopidy[452]: INFO [MainThread] mopidy.config Loading config from file:///usr/share/mopidy/conf.d/mopidy-local.conf
May 5 22:16:22 raspberrypi mopidy[452]: INFO [MainThread] mopidy.config Loading config from file:///etc/mopidy/mopidy.conf
May 5 22:16:22 raspberrypi mopidy[452]: INFO [MainThread] mopidy.config Loading config from command line options
May 5 22:16:22 raspberrypi mopidy[452]: WARNING [MainThread] mopidy.config Ignoring config section 'iris' because no matching extension was found
May 5 22:16:22 raspberrypi mopidy[452]: ERROR [MainThread] mopidy.internal.log Loading logging config '/etc/mopidy/logging.conf' failed. 'formatters'
May 5 22:16:23 raspberrypi mpd[823]: May 05 22:16 : exception: Failed to set group 0: Operation not permitted
May 5 22:16:23 raspberrypi systemd[800]: mpd.service: Main process exited, code=exited, status=1/FAILURE
May 5 22:16:23 raspberrypi systemd[800]: mpd.service: Failed with result 'exit-code'.
May 5 22:16:23 raspberrypi systemd[800]: Failed to start Music Player Daemon.
May 5 22:16:23 raspberrypi systemd[800]: Reached target Default.
May 5 22:16:23 raspberrypi systemd[800]: Startup finished in 18.411s.
May 5 22:16:24 raspberrypi lighttpd[756]: echo: write error: Broken pipe
May 5 22:16:25 raspberrypi mopidy[452]: INFO [MainThread] mopidy.__main__ Enabled extensions: stream, http, local, softwaremixer, m3u, mpd, spotify, file
May 5 22:16:25 raspberrypi mopidy[452]: INFO [MainThread] mopidy.__main__ Disabled extensions: none
May 5 22:16:27 raspberrypi mopidy[452]: INFO [MainThread] mopidy.commands Starting Mopidy mixer: SoftwareMixer
May 5 22:16:27 raspberrypi mopidy[452]: INFO [MainThread] mopidy.commands Mixer volume set to 30
May 5 22:16:27 raspberrypi mopidy[452]: INFO [MainThread] mopidy.commands Starting Mopidy audio
May 5 22:16:27 raspberrypi mopidy[452]: INFO [MainThread] mopidy.commands Starting Mopidy backends: FileBackend, M3UBackend, StreamBackend, SpotifyBackend, LocalBackend
May 5 22:16:27 raspberrypi mopidy[452]: INFO [Audio-2] mopidy.audio.actor Audio output set to "alsasink"
May 5 22:16:30 raspberrypi mopidy[452]: INFO [SpotifyBackend-6] mopidy_spotify.web Logged into Spotify Web API as htpzc
May 5 22:16:30 raspberrypi lighttpd[756]: echo: write error: Broken pipe
May 5 22:16:30 raspberrypi mopidy[452]: INFO [SpotifyEventLoop] mopidy_spotify.backend Logged in to Spotify in online mode
May 5 22:16:36 raspberrypi lighttpd[756]: echo: write error: Broken pipe
May 5 22:16:42 raspberrypi lighttpd[756]: echo: write error: Broken pipe
May 5 22:16:48 raspberrypi lighttpd[756]: echo: write error: Broken pipe
May 5 22:16:51 raspberrypi systemd[1]: phoniebox-idle-watchdog.service: Succeeded.
May 5 22:16:54 raspberrypi lighttpd[756]: echo: write error: Broken pipe
May 5 22:17:00 raspberrypi lighttpd[756]: echo: write error: Broken pipe
May 5 22:17:02 raspberrypi CRON[988]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
May 5 22:17:06 raspberrypi lighttpd[756]: echo: write error: Broken pipe
May 5 22:17:12 raspberrypi lighttpd[756]: echo: write error: Broken pipe

Software

Base image and version

cat /etc/os-release
PRETTY_NAME="Raspbian GNU/Linux 10 (buster)"
NAME="Raspbian GNU/Linux"
VERSION_ID="10"
VERSION="10 (buster)"
VERSION_CODENAME=buster
ID=raspbian
ID_LIKE=debian
HOME_URL="http://www.raspbian.org/"
SUPPORT_URL="http://www.raspbian.org/RaspbianForums"
BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs"

Branch / Release

I did the install with GIT_BRANCH=develop
(i am sure, because i did copy and paste from my notepad++ documentation)
--> wget https://raw.githubusercontent.com/MiczFlor/RPi-Jukebox-RFID/develop/scripts/installscripts/buster-install-default.sh;
chmod +x buster-install-default.sh;
GIT_BRANCH=develop
bash ./buster-install-default.sh

But that is the output of (and i am confused now):
cd /home/pi/RPi-Jukebox-RFID/ && git status | head -2
Refresh index: 100% (309/309), done.
On branch master
Your branch is up to date with 'origin/master'.

Hardware

RaspberryPi version

sudo cat /sys/firmware/devicetree/base/model
Raspberry Pi Zero W Rev 1.1p

RFID Reader

HXGCoLtd Keyboard

Soundcard

Bus 001 Device 003: ID 0d8c:013c C-Media Electronics, Inc. CM108 Audio Controller

question

Source

htpzc

All 14 comments

Did you install the Spotify edition?

If yes, then mopidy is used, so your described behavior would be as expected.

s-martin on 6 May 2020

But why is mpd started? dont understand the logic behind that? why not just disable the service.
just in my case, booting lasts very long and every unneeded started service (which is just crashing) needs extra time.
And of course, where is mpd started. i just looked in the rc*.d start and kill links, but theres no S01mpd.
Also ther service is disabled.
Who is starting mpd?

htpzc on 6 May 2020

One more question (sorry when this is little bit offtopic), but lighttpd seems to be also broken.
May 5 22:16:18 raspberrypi lighttpd[756]: echo: write error: Broken pipe

Webfrontend is running fine, but the iris is not working. Just getting 404 not found when connecting http://...:6680/iris/ -> 404: Not Found
http://...:6680/ -> is working and showing that this is the mopidy web server

Am i right that we have two webservers running? One for the phoniebox frontend and one for the mopidy spotify integration?

How can i turn debugging on for the mopidy web server. Theres no logging saying that 404 not found or anything like that.
Only: May 6 20:20:52 raspberrypi mopidy[496]: INFO [MpdSession-313] mopidy_mpd.session New MPD connection from [::ffff:127.0.0.1]:47258

htpzc on 6 May 2020

ok, now i understand much better. I need to give everything more time.
Please forget my questions. For now, everything is running, BUT:

I know mopidy needs a long time to start but nearly 2,5 minutes is to long ...
The longest part is the reading of my spotify playlist with 128 seconds
See this:
May 07 21:16:26 raspberrypi mopidy[488]: INFO [SpotifyEventLoop] mopidy_spotify.backend Logged in to Spotify in online mode
May 07 21:18:34 raspberrypi mopidy[488]: INFO [SpotifyBackend-6] mopidy_spotify.playlists Refreshed 48 Spotify playlists

You have written that when i scan the library this should be not the problem anymore.
Do you have any suggestions what i can do to fasten things up?

I dont need 30 seconds startup, but till i can start music i have nearly 4 minutes gone. Maybe we can get this to 2 minutes ;-)

Please say me what you need. i am very conform in linux and will do my very best also to make things better if possible.

Thanks in advance.

htpzc on 7 May 2020

ok, more information because the local scan is not working:
$ mopidy local scan
Traceback (most recent call last):
File "/usr/local/bin/mopidy", line 6, in
from pkg_resources import load_entry_point
File "/usr/lib/python2.7/dist-packages/pkg_resources/__init__.py", line 3191, in
@_call_aside
File "/usr/lib/python2.7/dist-packages/pkg_resources/__init__.py", line 3175, in _call_aside
f(args, *kwargs)
File "/usr/lib/python2.7/dist-packages/pkg_resources/__init__.py", line 3204, in _initialize_master_working_set
working_set = WorkingSet._build_master()
File "/usr/lib/python2.7/dist-packages/pkg_resources/__init__.py", line 583, in _build_master
ws.require(__requires__)
File "/usr/lib/python2.7/dist-packages/pkg_resources/__init__.py", line 900, in require
needed = self.resolve(parse_requirements(requirements))
File "/usr/lib/python2.7/dist-packages/pkg_resources/__init__.py", line 786, in resolve
raise DistributionNotFound(req, requirers)
pkg_resources.DistributionNotFound: The 'Mopidy==2.2.2' distribution was not found and is required by the application

htpzc on 7 May 2020

This is the biggest issue with the Spotify edition that it takes a very long time to boot up.

Nevertheless 4 minutes sounds extremely long, but I have no experience with the Pi Zero.

s-martin on 7 May 2020

ok, more information because the local scan is not working:
$ mopidy local scan
Traceback (most recent call last):
File "/usr/local/bin/mopidy", line 6, in
from pkg_resources import load_entry_point
File "/usr/lib/python2.7/dist-packages/pkg_resources/init.py", line 3191, in
@_call_aside
File "/usr/lib/python2.7/dist-packages/pkg_resources/init.py", line 3175, in _call_aside
f(args, kwargs)
File "/usr/lib/python2.7/dist-packages/pkg_resources/init.py", line 3204, in _initialize_master_working_set
working_set = WorkingSet._build_master()
File "/usr/lib/python2.7/dist-packages/pkg_resources/init.py", line 583, in _build_master
ws.require(requires)
File "/usr/lib/python2.7/dist-packages/pkg_resources/init.py", line 900, in require
needed = self.resolve(parse_requirements(requirements))
File "/usr/lib/python2.7/dist-packages/pkg_resources/init*.py", line 786, in resolve
raise DistributionNotFound(req, requirers)
pkg_resources.DistributionNotFound: The 'Mopidy==2.2.2' distribution was not found and is required by the application

That's pretty weird. In your logs above mopidy 3 was found and now mopidy 2 seems to be still used (and python 2).

Please perform the steps in #852 although you said you installed develop.

s-martin on 7 May 2020

sorry, between this time i installed also the master branch and executed everything which got listed in #852 .
Everything worked fine except the mopidy local scan

htpzc on 7 May 2020

should i reinstall again the developer branch? but there i got the same time problems (except that i dont know if the local scan would work)

htpzc on 7 May 2020

Master branch with manual fix #852 was pretty stable recently.

Maybe you should start with a fresh SD card installation, because we don't have a thorough deinstallation process, so you now may have a mixture of services and configurations from master and develop.

s-martin on 7 May 2020

i did a fresh complete fresh install.

ok, think i found the problem. the binary seems to be wrong.

Service runs under
mopidy 491 1 18 21:46 ? 00:02:07 /usr/bin/python3 /usr/bin/mopidy

But: $ which mopidy
/usr/local/bin/mopidy

ls -al
usr/bin/mopidy has a symlink to /usr/share/mopidy/mopidy-cmd

i've mv the /usr/bin/mopidy to /usr/bin/mopidy_org and symlinked it to the /usr/share/mopidy/mopidy-cmd

now the scan works. testing further. give you response when i got more

htpzc on 7 May 2020

🎉1

ok, now i can scan. also i scanned the library through the webfrontend.
Afterwards rebooted. 130 seconds for loading 48 playlists. Same as before.

Now additional i have more error message when playing something.
May 7 22:15:47 raspberrypi mopidy[496]: INFO [MpdSession-30] mopidy_mpd.session New MPD connection from [::ffff:127.0.0.1]:43306
May 7 22:15:47 raspberrypi mopidy[496]: ERROR [IrisFrontend-11] mopidy.listener Triggering event failed: tracklist_changed()
May 7 22:15:47 raspberrypi mopidy[496]: Traceback (most recent call last):
May 7 22:15:47 raspberrypi mopidy[496]: File "/usr/lib/python3/dist-packages/mopidy/listener.py", line 40, in on_event
May 7 22:15:47 raspberrypi mopidy[496]: getattr(self, event)(kwargs)
May 7 22:15:47 raspberrypi mopidy[496]: File "/usr/local/lib/python3.7/dist-packages/mopidy_iris/frontend.py", line 29, in tracklist_changed
May 7 22:15:47 raspberrypi mopidy[496]: iris.ioloop.add_callback(functools.partial(iris.clean_queue_metadata))
May 7 22:15:47 raspberrypi mopidy[496]: AttributeError: 'NoneType' object has no attribute 'add_callback'
May 7 22:15:48 raspberrypi daemon_rfid_reader.py[482]: volume: 30% repeat: off random: off single: off consume: off
May 7 22:15:48 raspberrypi mopidy[496]: INFO [MpdSession-31] mopidy_mpd.session New MPD connection from [::ffff:127.0.0.1]:43310
May 7 22:15:48 raspberrypi daemon_rfid_reader.py[482]: loading: Dschungelbuch
May 7 22:15:48 raspberrypi mopidy[496]: ERROR [IrisFrontend-11] mopidy.listener Triggering event failed: tracklist_changed()
May 7 22:15:48 raspberrypi mopidy[496]: Traceback (most recent call last):
May 7 22:15:48 raspberrypi mopidy[496]: File "/usr/lib/python3/dist-packages/mopidy/listener.py", line 40, in on_event
May 7 22:15:48 raspberrypi mopidy[496]: getattr(self, event)(kwargs)
May 7 22:15:48 raspberrypi mopidy[496]: File "/usr/local/lib/python3.7/dist-packages/mopidy_iris/frontend.py", line 29, in tracklist_changed
May 7 22:15:48 raspberrypi mopidy[496]: iris.ioloop.add_callback(functools.partial(iris.clean_queue_metadata))
May 7 22:15:48 raspberrypi mopidy[496]: AttributeError: 'NoneType' object has no attribute 'add_callback'

i think i will use the phoniebox for the first time without the spotify integration.
The waiting time is long, but the instability is not ok (because i have to use the developer version to run it).
when we are in holidays i dont have any notebook to ssh to the pi and check all day long logs.

Of course maybe a pi4 will do this faster, but the battery will also drain faster. So my son has to take the local playback for the first time ;-)
Maybe the next time when this is more stable and maybe more faster.

But i have to say thank you for doing this great project and of course the master branch version without spotify is running realy stable and smooth AND fast.

Thanks

htpzc on 7 May 2020

👍1

So if this works for you now, you could close the issue.

s-martin on 8 May 2020

Thanks @s-martin, this was service as good as it gets!
@htpzc could you close this issue, if it works for you now?