🐛 | Phoniebox doesn't play local files after upgrade to spotify edition

[comdoxx]

Bug

What I did

I updated the legacy non-spotify version I had installed to the current spotify version

What happened

Local files (all of them contain spaces in filename) don't work any more.

I expected this to happen

They do play...

Further information that might help

syslog:

Dec 20 16:36:05 pi3 lighttpd[16465]: /home/pi/RPi-Jukebox-RFID/scripts/single_play.sh: line 71: [: ==: unary operator expected
[...]
Dec 20 16:36:14 pi3 lighttpd[16465]: error adding /home/pi/RPi-Jukebox-RFID/shared/audiofolders/Musik/Pop/Alvaro Soler - Sofia.mp3: directory or file not found

and Iris tells me the following (other title):
Could not find playlist with URI "m3u%3ARadiogeschichten%2520%25%2520Angsthase%2C%2520Pfeffernase.m3u"
when calling http://pi3.intern.mydomain.de:6680/iris/playlist/m3u%3ARadiogeschichten%20%25%20Angsthase%2C%20Pfeffernase.m3u

Observe the double replacement: quoting a space = %20, quoting the % = %25, therefore quoting "%20" again becomes "%2520"!

Software

Base image and version

Raspbian GNU/Linux 10 (buster)

Branch / Release

origin/master

Hardware

Should be irrelevant.

[s-martin]

Does the file /home/pi/RPi-Jukebox-RFID/shared/audiofolders/Musik/Pop/Alvaro Soler - Sofia.mp3 exist?

indeed %2520 looks strange

[s-martin]

I wonder which Iris version you have, because a similar issue was fixed in 2019:
jaedb/Iris#381

Could you please post the result of journalctl -u mopidy?

[comdoxx]

Hi @s-martin

That's presumably it. The box is standing at my daughters room right now, but I upgraded iris from 3.45.0 to current 3.55.4 and a short test revealed a manual trigger from the phoniebox' own website seemed to work (it was at least displayed as current title...). However, 3.45.0 should've been newer (21 Feb 2020) as the fix (jaedb closed this on 10 Apr 2019)?

To answer the other questions:

• The file exists at the given folder.
• journalctl -u mopidy only shows this:

Dec 21 21:38:19 pi3 mopidy[15956]: INFO     [MpdSession-210633] mopidy_mpd.session New MPD connection from [127.0.0.1]:35782
Dec 21 21:38:19 pi3 mopidy[15956]: INFO     [MpdSession-210634] mopidy_mpd.session New MPD connection from [127.0.0.1]:35784
Dec 21 21:38:19 pi3 mopidy[15956]: INFO     [MpdSession-210635] mopidy_mpd.session New MPD connection from [127.0.0.1]:35786
Dec 21 21:38:19 pi3 mopidy[15956]: INFO     [MpdSession-210636] mopidy_mpd.session New MPD connection from [127.0.0.1]:35788
Dec 21 21:38:19 pi3 mopidy[15956]: INFO     [MpdSession-210637] mopidy_mpd.session New MPD connection from [127.0.0.1]:35790
Dec 21 21:38:24 pi3 mopidy[15956]: INFO     [MpdSession-210638] mopidy_mpd.session New MPD connection from [127.0.0.1]:35792
Dec 21 21:38:25 pi3 mopidy[15956]: INFO     [MpdSession-210639] mopidy_mpd.session New MPD connection from [127.0.0.1]:35794
Dec 21 21:38:25 pi3 mopidy[15956]: INFO     [MpdSession-210640] mopidy_mpd.session New MPD connection from [127.0.0.1]:35796
Dec 21 21:38:25 pi3 mopidy[15956]: INFO     [MpdSession-210641] mopidy_mpd.session New MPD connection from [127.0.0.1]:35798
Dec 21 21:38:25 pi3 mopidy[15956]: INFO     [MpdSession-210642] mopidy_mpd.session New MPD connection from [127.0.0.1]:35800
Dec 21 21:38:25 pi3 mopidy[15956]: INFO     [MpdSession-210643] mopidy_mpd.session New MPD connection from [127.0.0.1]:35802
Dec 21 21:38:25 pi3 mopidy[15956]: INFO     [MpdSession-210644] mopidy_mpd.session New MPD connection from [127.0.0.1]:35804
Dec 21 21:38:25 pi3 mopidy[15956]: INFO     [MpdSession-210645] mopidy_mpd.session New MPD connection from [127.0.0.1]:35806
Dec 21 21:38:30 pi3 mopidy[15956]: INFO     [MpdSession-210646] mopidy_mpd.session New MPD connection from [127.0.0.1]:35808

However: Thanks for your effort. Case closed!

[comdoxx]

Hmm. Now some cards do work and some (most) don't. I have no idea why:
"Bibi und Tina" does work, "Stadtdschungel" does not:

The shortcuts:

pi@pi3:~/RPi-Jukebox-RFID/shared/shortcuts $ cat 0001303768
Hörspiele/Bibi und Tina - K04 - Tohuwabohu Total
pi@pi3:~/RPi-Jukebox-RFID/shared/shortcuts $ cat 0016705753
Radiogeschichten/Im Stadtdschungel - Wilde Tiere mitten unter uns

The playlists folder:

pi@pi3:~/RPi-Jukebox-RFID/playlists $ ll
total 104
[...]
-rw-r--r-- 1 pi pi 2645 Jan  3 11:35 'Hörspiele % Bibi und Tina - K04 - Tohuwabohu Total.m3u'
[...]
-rw-r--r-- 1 pi pi  159 Jan  3 11:35 'Radiogeschichten % Im Stadtdschungel - Wilde Tiere mitten unter uns.m3u'
[...]

Their file contents:

pi@pi3:~/RPi-Jukebox-RFID/playlists $ cat Hörspiele\ %\ Bibi\ und\ Tina\ -\ K04\ -\ Tohuwabohu\ Total.m3u
local:track:H%C3%B6rspiele/Bibi%20und%20Tina%20-%20K04%20-%20Tohuwabohu%20Total/01%20%C3%9Cberraschung%20Am%20Flu%C3%9F.mp3
local:track:H%C3%B6rspiele/Bibi%20und%20Tina%20-%20K04%20-%20Tohuwabohu%20Total/02%20Bauarbeiten.mp3
[...]
local:track:H%C3%B6rspiele/Bibi%20und%20Tina%20-%20K04%20-%20Tohuwabohu%20Total/23%20Addi%20Wird%20Verhext.mp3
local:track:H%C3%B6rspiele/Bibi%20und%20Tina%20-%20K04%20-%20Tohuwabohu%20Total/24%20Sieg%20Der%20Vernunft.mp3

pi@pi3:~/RPi-Jukebox-RFID/playlists $ cat Radiogeschichten\ %\ Im\ Stadtdschungel\ -\ Wilde\ Tiere\ mitten\ unter\ uns.m3u
local:track:Radiogeschichten/Im%20Stadtdschungel%20-%20Wilde%20Tiere%20mitten%20unter%20uns/Im%20Stadtdschungel%20-%20Wilde%20Tiere%20mitten%20unter%20uns.mp3

The audiofolder-path and contents:

pi@pi3:~/RPi-Jukebox-RFID/shared/audiofolders/Hörspiele/Bibi und Tina - K04 - Tohuwabohu Total $ ll
total 97016
-rwxrwxrwx 1 pi www-data 5380824 Dec 14 12:49 '01 Überraschung Am Fluß.mp3'
-rwxrwxrwx 1 pi www-data 3467142 Dec 14 12:49 '02 Bauarbeiten.mp3'
[...]
-rwxrwxrwx 1 pi www-data 5514788 Dec 14 12:49 '23 Addi Wird Verhext.mp3'
-rwxrwxrwx 1 pi www-data 4421792 Dec 14 12:50 '24 Sieg Der Vernunft.mp3'
-rwxrwxrwx 1 pi www-data      97 Dec 14 12:49  folder.conf

pi@pi3:~/RPi-Jukebox-RFID/shared/audiofolders/Radiogeschichten/Im Stadtdschungel - Wilde Tiere mitten unter uns $ ll
total 60684
-rwxrwxrwx 1 pi www-data       98 Dec 14 12:53  folder.conf
-rwxrwxrwx 1 pi www-data 62130412 Dec 14 12:53 'Im Stadtdschungel - Wilde Tiere mitten unter uns.mp3'

journalctl -u mopidy does not show anything (but the 'new connection' entries). First I thought, the slash to percent ('/' -> '%') replacement could be the issue, but it's the same on both items.

[s-martin]

Could you check, if the German Umlaute are causing the problem?

[comdoxx]

They don't. As you see, working "Hörspiele/Bibi..." contains Umlaute both in folder name as well as in the first file name ("Überraschung am Fluß"). On the other hand: The NOT working card doesn't contain a single Umlaut. s-martin <[email protected]> schrieb am So., 3. Jan. 2021, 21:11:

…

Could you check, if the German Umlaute are causing the problem? — You are receiving this because you modified the open/close state. Reply to this email directly, view it on GitHub <#1219 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ABVN3AKRS7TXRUKFKWB6HRDSYDFQVANCNFSM4VDGYG4Q> .

[pofi5000]

Have you found a solution already?

Update:
I thought I'm experiencing a similiar behaviour on my Pi Zero W after upgrading to the Spotify version.
But I checked again and now the local files play well. The only problem that persists, is that none of the initiallly installed podcasts loads.
I suspect that my problem is similar to #805 - it would be great if that could be fixed.

I'm still curious, how to interpret the reported errors given back via journalctl -u mopidy and how to re-enable podcasts. (or would you suggest as a workaround to use Spotify podcasts?)

Jan 20 23:30:38 zeropi mopidy[486]: INFO     [MpdSession-324] mopidy_mpd.session New MPD connection from [::ffff:127.0.0.1]:57192
Jan 20 23:30:38 zeropi mopidy[486]: ERROR    [IrisFrontend-13] mopidy.listener Triggering event failed: tracklist_changed()
Jan 20 23:30:38 zeropi mopidy[486]: Traceback (most recent call last):
Jan 20 23:30:38 zeropi mopidy[486]:   File "/usr/local/lib/python3.7/dist-packages/mopidy/listener.py", line 44, in on_event
Jan 20 23:30:38 zeropi mopidy[486]:     getattr(self, event)(**kwargs)
Jan 20 23:30:38 zeropi mopidy[486]:   File "/usr/local/lib/python3.7/dist-packages/mopidy_iris/frontend.py", line 29, in tracklist_changed
Jan 20 23:30:38 zeropi mopidy[486]:     iris.ioloop.add_callback(functools.partial(iris.clean_queue_metadata))
Jan 20 23:30:38 zeropi mopidy[486]: AttributeError: 'NoneType' object has no attribute 'add_callback'
Jan 20 23:30:38 zeropi mopidy[486]: INFO     [MpdSession-325] mopidy_mpd.session New MPD connection from [::ffff:127.0.0.1]:57196
Jan 20 23:30:40 zeropi mopidy[486]: ERROR    [IrisFrontend-13] mopidy.listener Triggering event failed: tracklist_changed()
Jan 20 23:30:40 zeropi mopidy[486]: Traceback (most recent call last):
Jan 20 23:30:40 zeropi mopidy[486]:   File "/usr/local/lib/python3.7/dist-packages/mopidy/listener.py", line 44, in on_event
Jan 20 23:30:40 zeropi mopidy[486]:     getattr(self, event)(**kwargs)
Jan 20 23:30:40 zeropi mopidy[486]:   File "/usr/local/lib/python3.7/dist-packages/mopidy_iris/frontend.py", line 29, in tracklist_changed
Jan 20 23:30:40 zeropi mopidy[486]:     iris.ioloop.add_callback(functools.partial(iris.clean_queue_metadata))
Jan 20 23:30:40 zeropi mopidy[486]: AttributeError: 'NoneType' object has no attribute 'add_callback'
Jan 20 23:30:40 zeropi mopidy[486]: INFO     [MpdSession-327] mopidy_mpd.session New MPD connection from [::ffff:127.0.0.1]:57200

Jan 20 23:32:38 zeropi mopidy[486]: INFO     [MpdSession-407] mopidy_mpd.session New MPD connection from [::ffff:127.0.0.1]:57510
Jan 20 23:32:38 zeropi mopidy[486]: ERROR    [IrisFrontend-13] mopidy.listener Triggering event failed: tracklist_changed()
Jan 20 23:32:38 zeropi mopidy[486]: Traceback (most recent call last):
Jan 20 23:32:38 zeropi mopidy[486]:   File "/usr/local/lib/python3.7/dist-packages/mopidy/listener.py", line 44, in on_event
Jan 20 23:32:38 zeropi mopidy[486]:     getattr(self, event)(**kwargs)
Jan 20 23:32:38 zeropi mopidy[486]:   File "/usr/local/lib/python3.7/dist-packages/mopidy_iris/frontend.py", line 29, in tracklist_changed
Jan 20 23:32:38 zeropi mopidy[486]:     iris.ioloop.add_callback(functools.partial(iris.clean_queue_metadata))
Jan 20 23:32:38 zeropi mopidy[486]: AttributeError: 'NoneType' object has no attribute 'add_callback'
Jan 20 23:32:38 zeropi mopidy[486]: INFO     [MpdSession-408] mopidy_mpd.session New MPD connection from [::ffff:127.0.0.1]:57514

...

Jan 20 23:33:15 zeropi mopidy[486]: INFO     [MpdSession-427] mopidy_mpd.session New MPD connection from [::ffff:127.0.0.1]:57662
Jan 20 23:33:16 zeropi mopidy[486]: WARNING  [MainThread] mopidy_mpd.network Rejected connection from [::ffff:127.0.0.1]:57666

After I tried to start a podcast:

Jan 20 23:35:15 zeropi mopidy[486]: WARNING  [MainThread] mopidy_mpd.network Rejected connection from [::ffff:127.0.0.1]:58390
Jan 20 23:35:15 zeropi mopidy[486]: WARNING  [MainThread] mopidy_mpd.network Rejected connection from [::ffff:127.0.0.1]:58394

and with a huge delay

Jan 20 23:39:36 zeropi mopidy[486]: WARNING  [MainThread] mopidy_mpd.network Rejected connection from [::ffff:127.0.0.1]:59802
Jan 20 23:39:37 zeropi mopidy[486]: WARNING  [StreamBackend-5] mopidy.stream.actor Problem looking up https://media.neuland.br.de/file/1801429/c/feed/mein-name-ist-karpfen-5-5-der-traum.mp3
Jan 20 23:39:42 zeropi mopidy[486]: WARNING  [MainThread] mopidy_mpd.network Rejected connection from [::ffff:127.0.0.1]:59814

Today I got another hint what could go wrong with the podcasts.

Jan 21 19:28:34 zeropi mopidy[512]: WARNING  [StreamBackend-5] mopidy.internal.http Download of 'https://media.neuland.br.de/file/1802916/c/feed/benny-baut-4-5-mist.mp3' failed due to download taking more than 4.994s
Jan 21 19:28:34 zeropi mopidy[512]: INFO     [StreamBackend-5] mopidy.stream.actor Unwrapping stream from URI (https://media.neuland.br.de/file/1802916/c/feed/benny-baut-4-5-mist.mp3) failed: error downloading URI https://media.neuland.b
Jan 21 19:28:34 zeropi mopidy[512]: WARNING  [StreamBackend-5] mopidy.stream.actor Problem looking up https://media.neuland.br.de/file/1802916/c/feed/benny-baut-4-5-mist.mp3
Jan 21 19:28:34 zeropi mopidy[512]: WARNING  [MainThread] mopidy_mpd.network Rejected connection from [::ffff:127.0.0.1]:39398

Can you give me a hint, what might be wrong with my installation?

---

Raspbian GNU/Linux 10 (buster)
Version 2.2 - 305325d - master
Edition Plus edition (feat. Spotify integration)

[s-martin]

hey @pofi5000, , please try:
sudo pip3 install --upgrade --force-reinstall Mopidy-Iris and reboot

[Borlizgaron]

I have exactly the same problem with my phoniebox.
I was hoping that reinstalling Iris would lead to success. But no change.

Some folders are played, others are not. I can activate the individual tracks via the web interface and they will play. But I can not play the entire folder.
If I add new audio tracks (folders), folders that were not working before may suddenly go. Sometimes, however, not all tracks are played.