After Powerup sound sometimes not initialized

[Feuer-sturm]

Hello,

sometimes after power on the sound is not working with the phoniebox software. Actually I can't reproduce this behavior.

When there is no sound it looks like this in the web interface:

After rebooting the pi everything is fine and I can start playing music:

I have this behavior with a Pi 3b+ and Phoniebox SW 1.1.8-rc2 and with a Pi 3b and Phoniebox SW 1.1.8
I use this external USB sound card https://www.amazon.de/gp/product/B00C7LXUDY/ref=oh_aui_detailpage_o04_s00?ie=UTF8&psc=1 which is direktly plugged in the USB port of the Pi

Perhaps anybody can help me :-)

[Feuer-sturm]

Yesterday I put an extension calbe to the USB soundcard because there ist not much space when for the sound card when three USB Ports are used. After this I powered up the phoniebox for 20 times and everything was fine.
Today in the morning (it was the second power up today) there was once again the problem that I can't hear music and the Volume stayed at 0% in the circle. After a reboot everything was fine.

Do other users have the same problems?
Can I enable degub flags to see some informations in the log files?
What is the condition for the volume grafic to go from 0% to e.g. 30% (Value for the standard sound level after power up)?

[MiczFlor]

Not sure where the audio service log files would be and what they would look like. The only thing I can think of that might also be the reason: a "mute" / sound off GPIO button that's dodgy or gets pressed accidently alongside the power off button - or is wired wrong?
It might be a mute RFID chip card that's been used twice? If the same ID is used for the mute function and a folder / stream or the like: the mute overrides the playout - and then it would be muted.
...?
if you find this, please share what it is.

[Feuer-sturm]

Thanks for the note with "muting". I don't use the feature "muting". I will check my wiring if I have a problem with BCM13 and GND.
Is there a possibility to see in some log files if the mute command was triggered?
I addition to this I will comment out the lines for "vol0" and "shut" in the file gpio-buttons.py and have a look if the problem is still present.

[Berdsen]

Hi there.
I got the same issue with the Spotify version and the same USB sound card as SpookyFishes mentioned.
A look into the mopidy.log file shows an error, that reads like:
ERROR: mopidy.audio.gst: Could not open audio device for playback. (6)
I can also not reproduce the error regularly. Sometimes it just happens. But when it happens, also the startup sound is missing.

I furthermore don't pull the power cable but use the button method to turn the device off. Perhaps there is a problem with the sound card not turning off correctly or beeing in a hibernate mode. I will check again this week, if the problem will also come up with the onboard sound.

[Feuer-sturm]

When I have this error I hear the startup sound. I will check my mopidy.log if there are any errors.

[Berdsen]

So I made a fresh install multiple times and I again had sometimes this error. But after reordering the sound cards like already mentioned in here it seems to work. I'm not quite sure but perhaps also forgetting to scan the library after adding new files could lead into this. I have forgotten it sometimes.

[Feuer-sturm]

Thanks for the link. I just made the reordering of the soundcard. I will have a look if the problem is fixed with this adaption.

[Feuer-sturm]

After doing the reordering there was no startup sound and there was no music when I swiped a RFID card. I used my backup of the sd card to get the phoniebox working. At the end of the week I will have some time to try once again the reordering.

@Berdsen : Did you just do the reording as described in the docs or did you do anything more?

[Berdsen]

Reordering will not fix this issue. As I said, I set up a complete new sd card and the following setup:
RPi 3B+, Micro SDHX 128GB, latest Raspbian, latest RPi Jukebox Spotify Edition (did a pip install pylast==2.4.0 before for fixing #436).
I uploaded two audiobooks and I added a spotify user with around 30 playlists. I turned on mopidy debug log and added one playlist from spotify with around 80 tracks.
After the next reboot, the same issue appeared. In the mopidy debug log you can see, that the mopidy-spotify will load all playlists into cache. That took around 5 minutes. After finishing that, the sound was set up to the initial 30% value and everything worked as expected. That seemed to happen not just only once, so I activated in the mopidy.conf the cache and playlist switches (uncommented). In the docs it is said, that it is the default, but after setting these explicit, I had now two days (and a lot of reboots) where it worked @SpookyFishes can you try and confirm this behaviour?

See also here

[Feuer-sturm]

I hope I will have some time on next weekend for testing your steps.

[Feuer-sturm]

@Berdsen :
Is this the way you enabled the debug mode?

Can you please give the path where I can find the log file you looked at?

[Berdsen]

@SpookyFishes
After setting up the box up I connected to the webinterface and started the Iris spotify part and connected one plalist to a rfid chip.

After doing this I started a terminal and changed the loglevel in the logging section of the mopidy.conf from INFO to debug. Then I deleted the current logfile and rebooted the system.

sudo nano /etc/mopidy/mopidy.conf
Change loglevel and save with Ctrl + X - > y - > Enter
sudo rm /var/log/mopidy/mopid.log ( filename was perhaps error.log, can't check it now)
reboot

After the next start you have a new log file and you can check what is done, when the box is initialized.

[Feuer-sturm]

Hello @Berdsen
I just installed on a new sd card phoniebox software 1.1.9-rc6 with mopidy 3.31.8

The debug level I changed in /etc/mopidy/logging.conf with this new value
level = DEBUG

The logfile will be stored here:
/var/log/mopidy/mopidy.log

In file /etc/mopidy/mopidy.conf it looks like this:

[core]
cache_dir = /var/cache/mopidy
config_dir = /etc/mopidy
data_dir = /var/lib/mopidy

How did you activate the cache in mopidy.conf? Or did your mopidy.conf looked different?
What do you mean with 'I activated in the mopidy.conf the cache and playlist switches (uncommented).'

At the moment I added one playlist with 50 songs to one rfid card. I will have a look if the problem is still there in the next days. If everything is fine I will add more spotify playlists to the accounts and to some new rfid cards.

[iwishitwassummer]

Hi
I have the same problem with the Classic Edition 1.1.8-rc and the identical Sound Card.
Where can I get logs?
Thanks

[Feuer-sturm]

Hello @iwishitwassummer ,
what do you mean with "Where can I get logs".
Please check my last posting

The logfile will be stored here:
/var/log/mopidy/mopidy.log

At the moment I have just one spotify playlist integrated in my phoniebox. The rest of the music is stored as mp3s. I just made a fresh install 7 days ago with 1.1.9-rc6 and mopidy 3.31.8 and at the moment I didn't have the problem. In the next days I will add some more spotify playlist and I will have a look if the problem is will come back again.

[iwishitwassummer]

@SpookyFishes thanks, I wanted to check my logs but I have the classic edition, hence it's mpd.

[mangenehm]

I'm using the + Spotify version of Phoniebox 1.1.9 and I'm gonna add my two cents to this issue. Please see section "Debugging" for additional information that might be helpful to pin this down.

Current behavior

1. Boot Phoniebox
2. Hear startup sound
3. Swipe a card connected to a Spotify playlist/song or an MP3 file
4. Delay of 1-2 minutes
5. Spotify playlist/song or an MP3 is played
6. Swipe another card connected to the same or another Spotify playlist/song or MP3 file
7. Spotify playlist/song or MP3 file is played immediately

Hint: It doesn't matter how long I wait between step 2 and 3. Every first swipe is followed by the delay in step 4.

Debugging

Instead of swiping a card I've tried to start the rfid_trigger_play.sh script via SSH after hearing the startup sound. This throws the following error messages:

pi@raspberrypi:~ $ /home/pi/RPi-Jukebox-RFID/scripts/rfid_trigger_play.sh --cardid=0000243241
/home/pi/RPi-Jukebox-RFID/scripts/rfid_trigger_play.sh: line 358: [: -eq: unary operator expected
/home/pi/RPi-Jukebox-RFID/scripts/rfid_trigger_play.sh: line 362: [: too many arguments`

After 1-2 minutes the following messages appear and the sound is played.

volume: 30%   repeat: off   random: off   single: off   consume: off
volume: 30%   repeat: off   random: off   single: off   consume: off
volume: 30%   repeat: off   random: off   single: off   consume: off
loading: Piano C
OK MPD 0.19.0
OK

After this the sounds are immediately played and executing the script doesn't throw any errors any more:

pi@raspberrypi:~ $ /home/pi/RPi-Jukebox-RFID/scripts/rfid_trigger_play.sh --cardid=0000243241
volume: 30%   repeat: off   random: off   single: off   consume: off
volume: 30%   repeat: off   random: off   single: off   consume: off
volume: 30%   repeat: off   random: off   single: off   consume: off
loading: Piano C
OK MPD 0.19.0
OK

I don't have any coding experience hence I'm not able to use the error messages above to look at the code. But maybe it does ring a bell to anyone else?

[MemanSH]

Hi, did you find a solution for that issue? Unfortunately I have the same problem.

[mangenehm]

Unfortunately not.

[maddin78]

Ich habe das gleiche Problem, und bemerkt dass mopidy in dem Moment wo der Sound nicht geht nicht verbunden ist. Und glaube es liegt daran das die Zeit und das Datum nicht richtig sind. Evt kann man noch eine RTC nutzen. Bin mir aber noch nicht zu 100% sicher,

[mangenehm]

Thanks for the update, @maddin78! Keep us posted if you find something out. Would be great if we could solve this issue. My 2 year old is understandably too impatient to wait for so long after the box has booted and has crashed the box several times now. 😬

[domu83]

I agree with @maddin78 finding assuming we are on the Spotify version.
Sometimes it takes 5-8min till mopidy successfully connect
As soon as mopidy is connected, local MP3 as well as Spotify works.

[maddin78]

got it,

i installed a ds3231 rtc (other should work also) and now mopidy only takes a few seconds to connect

[mangenehm]

Great news! Thank you for sharing this. Now I have to wrap my head about how to add an rtc on top of the on/off shim. I will share my results once I have tested it.

[maddin78]

that is not a big deal, i use an on/off shim also. you only need to connect the rtc to pin 1-3-5-9
3.3v-SDA-SDL-Ground.

[mangenehm]

I have issues connecting the DS3231 to the Pi. I used the same pins you've mentioned and followed instructions on https://pimylifeup.com/raspberry-pi-rtc/ to configure the RTC. Unfortunately it doesn't show any ID when running sudo i2cdetect -y 1. Oddly it does show the ID when I use a freshly formatted SD card with a clean Raspbian Stretch on it.

I still have the feeling that the On/Off-Shim prevents the RTC from working. How did you install the On/Off-Shim @maddin78? Did you use the official software from Pimoroni? And did you do anything else to get the RTC running?

Thanks for your help!

[maddin78]

I use the original softtware from pimoroni. Did you try it on the same pi? I have first installed the on off shim and then the rtc.

[mangenehm]

Yes, I used the same Pi. I did run a few more tests and it doesn't seem to be connected to the Shim though. On a fresh Stretch system the RTC and the Shim work perfectly together. Once I install the Jukebox, the RTC stops working.

Did you do anything special to get the RTC running? Did you follow a tutorial on the web?

[maddin78]

Nothing special

In the next days i will set up a new jukebox and write down the steps

[swissmaster1]

Yes, I used the same Pi. I did run a few more tests and it doesn't seem to be connected to the Shim though. On a fresh Stretch system the RTC and the Shim work perfectly together. Once I install the Jukebox, the RTC stops working.

Did you do anything special to get the RTC running? Did you follow a tutorial on the web?

I think it has something to do with i2c. I installed yesterday a new raspberry pi 3 with 2 i2c devices attached. After the fresh install of raspian stretch i2cdetect found the the devices. After installing the jukebox software i2cdetect was not able to detect any devices anymore. I tried the same with a new raspberry pi 4 with the same result. The same happened with raspian buster. I then used a backup from a old raspian installation where I had installed the jukebox already. i2cdetect found the devices with that without any problems. It looks for me that something get installed which prevents i2c from working.

[dbffm]

I have both 3,3V Pins (1 & 17) used by the Hifiberry Miniamp and a KY040 Rotary Encoder. Is there any other possibility to wire a DS3231 without Pin1?

[domu83]

@swissmaster1 have you managed to solve this issue? I think I can confirm the same behaviour. I have also attached a LCD display to I2C port. Interesting enough it seems to be initilized with date and time when the box is booted up. When I run I2C detect it does not show any device, so my guess is, that one of the phoniebox services blocks the I2C from working

[swissmaster1]

No. I got it running again when I installed the backup of an microSD Card with older raspian and phoniebox version. But I still have problems with Spotify. After startup I have to restart the mopidy server over the Iris interface. After that spotify works in my case.

[drybx]

Thanks for all your helpful comments. I'm experience the issue with the lengthy connection times as well and have two questions for you:

1. Can you recommand an RTC module? I did some research on Amazon and - according to the reviews - all of the modules seem to have some issues.
2. Would it help if I enabled time synchronization via NTP (as descriped here)? Can't test it myself right now.
3. Is there a way to configure the whole thing so that offline files play right away even if mopidy isn't connected yet, @MiczFlor?

[domu83]

@JuliH29 apologize for late answer...
I have used this AZDelivery Real Time Clock RTC DS3231 I2C Echtzeituhr
So after I have overcome the blockage of I2C bus by the GPIO script (shutdown) the RTC seems to
work properly but unfortunately it does not solve the connection issue on my end. Also the 'wait for Network to boot' seems not solving it as well. I'm bit stuck currently.
@maddin78 have you done any special coding? I have just followed the guide here https://pimylifeup.com/raspberry-pi-rtc/

Agree with your point 3)

[thomas-wolf]

Can anyone be more specific about the root cause of the issue? If it is the lack of an exact system time, then running ntp should help, shouldn't it?

[dbffm]

I dont know the root because; but from my point of view it is not the system time. I installed a RTC DS3231 and the issue is still present.
My solution is the same as the one from @swissmaster1

After startup I have to restart the mopidy server over the Iris interface. After that spotify works in my case.

[domu83]

@dbffm I agree, same with me. Unfortunately I do not have a working backup anymore, so I cannot restore 🙁
on my end, neither the RTC nor the boot when network is available nor the restart of the mopidy server through IRIS works. So it takes up to 8 min worst case till mopidy is connected and is ready to play. Really annoying for my kids as they are not patient!

by the way... I started a moneypool to fund a spotify prem accout for @MiczFlor with #737 to help debug spotify issues

[thomas-wolf]

Mine is connecting mostly in no time. In seldom cases, it takes up to 10 minutes or so.

I don't believe in the RTC thing. I guess it might only help if your rasp does not sync its time using ntp. System time might be of importance for SSL handshake, but the source of the system time does not matter in my opinion. Your laptop, personal computer, mobile phone do not have a RTC built in neither (asfaik) and SSL is working out just nicely.

To me, this is somehow network related. I observe increased probability of occurence when WLAN signal is bad. I find the following in mopidy log files:

2020-01-31 19:27:58,413 ERROR [261:SpotifyEventLoop] spotify.session: Spotify login error: <ErrorType.OTHER_PERMANENT: 10>
2020-01-31 19:28:00,079 ERROR [261:SpotifyBackend-3] mopidy_spotify.web: OAuth token refresh failed: Unknown error.

ErrorType.OTHER_PERMANENT seems to occur when spotify host cannot be resolved due to dns, proxy or connectivity issue. Mopidy-spotify has some retry logic with exponential backoff strategy in place, but this logic does only jump in in case of some particular http error codes.

So there does not seem to be an immediate retry in case of network failures. I still wonder which meachnism makes it work after 10 minutes or so.

[domu83]

@thomas-wolf totally agree with your observation. I have just bought a usb wifi stick with external antenna and going to build this into my box in the next couple of days. I'll do some testing and feedback into the group again.

[thomas-wolf]

@domu83: Did the external wifi antenna help? Really looking forward to learning from your experience.

[domu83]

@thomas-wolf thanks for the reminder. Actually not. I've done some further tweaks, I thought, which finally ended into unreliable boot of the pi at all. I have done a fresh buster lite install
just yesterday. Out of the box, the long connection time seems gone. After several boots it most more or less instant connected. I'm now starting to do
my custom stuff like lcd, rotary encoder, rtc and going through some issues I at least face and see if this customization leds to the old behavior again, but as said. Out of the box, it seems the issue is not persistent.

[AnnaHerbstkind]

Hey everyone. I just recently installed the phoniebox with the newest one liner on raspi OS and have the same problem (4 minutes waiting). Could anyone solve this yet? Why do I need mopidy at all to play mp3 files?

[s-martin]

Unfortunately there's no final solution yet.

You have Mopidy only installed, when you chose the Spotify edition. If you have installed the classic edition only MPD is used.

[larsboth]

I have some input towards this, although it's probably not really helpful. Using Phoniebox with Mopidy/Spotify I've also observed the issue that swiping any rfid card after the startup sound played did not work for quite some time.

I did find the reason, but no satisfying solution. Issue is that mopidy will log into spotify and refresh playlists that are linked to that account. In my case this resulted in a 44 second delay:

Snippet from output for journalctl -u mopidy

Sep 10 11:11:12 raspberrypi mopidy[497]: INFO     [SpotifyEventLoop] mopidy_spotify.backend Logged in to Spotify in online mode
Sep 10 11:11:56 raspberrypi mopidy[497]: INFO     [SpotifyBackend-6] mopidy_spotify.playlists Refreshed 73 Spotify playlists

The really not satisfying "solution" for me was to disable spotify since for my use case it's a nice to have feature. Now, Mopidy only takes 2-3 seconds to be ready which is barely recognizable.

So - in my case it would be smart to reinstall without spotify support, I'm probably to lazy to do that. To fix the issue and use spotify it will be necessary to somehow adress this issue. Use a "blank" user without personal or saved playlists? Request a feature for mopidy service?

[s-martin]

Spotify (and mopidy) integration has been rewritten in the latest release and this should be improved: https://github.com/MiczFlor/RPi-Jukebox-RFID/releases/tag/v2.7.0

closing now. Feel free to reopen, if the issue persists.