[PROBLEM] Moode unresponsive for 3-5 Minutes

[ghoeher]

Dear all,

I'm facing an issue with my moOde 5.3.1 installation. I don't know when this started exactly, but almost after every reboot, when I try to start radio playback, moOde gets unresponsive for several minutes.
I checked the moOde log, the mpd log and the messages log. The only entry I can always find when this happens is:

pcm512x 1-004d: No SCLK, using BCLK: -2

After this entry appears in the log, playback starts immediately.

My current configuration is a Pi 3a+ with a Justboom Amp Zero but I have the same issue, if I put the AMP on a Pi Zero WH.

In the beginning (I started with moOde 5.1 if I remember correctly) I did not have such issues.

Does anyone have an idea, what might be wrong?


Kind regards
Georg

[Tim Curtis]

I would just burn a fresh 5.3.1 image onto a known good SDCard then connect via Ethernet and before doing any configuration verify that radio stations play without issue. You don't have to have the Pi connected to an audio system to perform this test.

If no issues then connect your audio board and configure moOde then retest.

-Tim

[ghoeher]

Dear Tim,

thanks for your quick response.
I made several tests and had the same issue with a new installation.
I again checked the logs and most probably found the reason - most probably, I missed the lines when I checked them the last time:

Jul 13 13:20:41 moode kernel: [   49.068667] Bluetooth: HCI UART protocol Three-wire (H5) registered
Jul 13 13:20:41 moode kernel: [   49.068797] Bluetooth: HCI UART protocol Broadcom registered
Jul 13 13:20:41 moode kernel: [   49.200347] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
Jul 13 13:20:41 moode kernel: [   49.200358] Bluetooth: BNEP filters: protocol multicast
Jul 13 13:20:41 moode kernel: [   49.200374] Bluetooth: BNEP socket layer initialized
Jul 13 13:27:51 moode kernel: [  267.586233] random: crng init done
Jul 13 13:27:51 moode kernel: [  267.586281] random: 7 urandom warning(s) missed due to ratelimiting
Jul 13 13:27:51 moode kernel: [  268.318166] pcm512x 1-004d: No SCLK, using BCLK: -

It's looks like a problem with "random" - it takes more them 200 sec to initialize it.
I digged a little bit around and found some interesting posts regarding this - one pointed to a workaroud:

Code:

sudo apt install haveged
sudo systemctl enable haveged

After installing haveged and enabling it, my issue seems to be solved. I made several reboots without facing the delay again.

Now I'm happy again with my moOde installation!
Many thanks to the moOde-team for all your effords creating and maintaining it!

Kind regards
Georg

[Tim Curtis]

Thats really interesting: a low entropy condition.

You can check how much system entropy is available by the command below. I think if its < 1000 then haveged needs to be installed.

Code:

cat /proc/sys/kernel/random/entropy_avail

I'll have to investgate :-)

[TheOldPresbyope]

Very strange.

On both a moOde 5.3.1 and a moOde 5.4b2 player here, random reports "crng init done" within 5 seconds. 

Regards,
Kent

[TheOldPresbyope]

To expand a bit, I thought low entropy was a problem for cryptographic modules *after* random had initialized.

[Tim Curtis]

Here's some data from one of my Buster systems running on a Pi-3A+

Code:

Time to crng init done = 6.9 secs

pi@rp3:~ $ dmesg | grep crng
[    0.000000] random: get_random_bytes called from start_kernel+0xac/0x4b0 with crng_init=0
.
.
.
[    6.888897] random: crng init done

RNG tools running

pi@rp3:~ $ sudo systemctl status rng-tools
● rng-tools.service
  Loaded: loaded (/etc/init.d/rng-tools; generated)
  Active: active (running) since Sat 2019-07-13 09:20:40 EDT; 29min ago
    Docs: man:systemd-sysv-generator(8)
   Tasks: 4 (limit: 1012)
  Memory: 532.0K
  CGroup: /system.slice/rng-tools.service
          └─322 /usr/sbin/rngd -r /dev/hwrng

Jul 13 09:20:40 rp3 systemd[1]: Starting rng-tools.service...
Jul 13 09:20:40 rp3 rngd[322]: rngd 2-unofficial-mt.14 starting up...
Jul 13 09:20:40 rp3 rng-tools[315]: Starting Hardware RNG entropy gatherer daemon: rngd.
Jul 13 09:20:40 rp3 rngd[322]: entropy feed to the kernel ready
Jul 13 09:20:40 rp3 systemd[1]: Started rng-tools.service.

Entropy at worker.php start = 2152

20190713 095608 worker: - Start
20190713 095608 worker: Successfully daemonized
20190713 095608 2152

[TheOldPresbyope]

Looks pretty much the same for my moOde 5.3.1 (Stretch) and moOde 5.4b2 (Buster) on RPi3B+s. Both come in around 4.5s.

I'm not running RNG tools on either host. Oops, I should have said I didn't explicitly enable RNG Tools. I see the service is running on Buster but not on Stretch.

[ghoeher]

without haveged:
pi@moode:~ $ cat /proc/sys/kernel/random/entropy_avail
10

[    0.000000] random: get_random_bytes called from start_kernel+0xac/0x4b4 with crng_init=0
[  401.699034] random: crng init done





with haveged:
pi@moode:~ $ cat /proc/sys/kernel/random/entropy_avail
2053

pi@moode:~ $ dmesg | grep crng
[    0.000000] random: get_random_bytes called from start_kernel+0xac/0x4b4 with crng_init=0
[   24.113324] random: crng init done

[TheOldPresbyope]

Yeah, but I just rebooted my moOde 5.3.1 (Stretch) and radio started playing as soon as the moOde UI came back up again in my web browser and I could click "play".

pi@moodeLR:~ $ dmesg|grep crng
[    0.000000] random: get_random_bytes called from start_kernel+0xac/0x4b4 with crng_init=0
[    4.479809] random: crng init done
pi@moodeLR:~ $ cat /proc/sys/kernel/random/entropy_avail
15

So, while I don't doubt that haveged pumps up entropy on headless systems, I do doubt that low entropy is the root cause of your long delay time.

This is a puzzler for sure.

Regards,
Kent

FYI - I'm running the moOde player in WiFi client mode.