alarm time not set correctly after power-down (RPi 3b)?

Volumio Development Bug reports
1

for some reason Volumio, from being idle, repeatedly starts playing a playlist without any user interaction at seemingly random times every couple of hours. Has anyone else experienced this?

System: RPi3 Volumio version 2.175, also experienced this behavior with previous versions.

I have an alarm set for 6:00 for that very playlist which also doesn’t go off as expected.

Sorry if this has been reported already, I did look in the forum but couldn’t find anything similar.

not sure, if this helps:

volumio@volumio2:/home$ date
Thu May 18 21:10:33 UTC 2017
(when I have 23:10 CEST, so time set correctly)

Could volspotconnect2 be the trigger for this? (see log below, playlist starts playing @20:08:55)?
$ sudo journalctl > /home/volumio/log.log
…
May 18 19:52:41 volumio2 wpa_supplicant[811]: wlan0: Cancelling authentication timeout
May 18 19:52:41 volumio2 wpa_supplicant[811]: wlan0: State: GROUP_HANDSHAKE -> COMPLETED
May 18 20:06:35 volumio2 systemd[1]: Starting Volspotconnect2 remove cache service…
May 18 20:06:35 volumio2 systemd[1]: Started Volspotconnect2 remove cache service.
May 18 20:06:35 volumio2 volumio[4972]: cache not full, nothing do
May 18 20:08:55 volumio2 volumio[887]: info: [1495138135027] Play playlist Radio Paradise
May 18 20:08:55 volumio2 volumio[887]: info: [1495138135034] Play playlist Radio Paradise
May 18 20:08:55 volumio2 volumio[887]: info: CoreCommandRouter::volumioClearQueue
May 18 20:08:55 volumio2 volumio[887]: info: [1495138135041] CoreStateMachine::ClearQueue
May 18 20:08:55 volumio2 volumio[887]: info: [1495138135041] CoreStateMachine::stop
May 18 20:08:55 volumio2 volumio[887]: info: [1495138135042] CoreStateMachine::setConsumeUpdateService undefined
May 18 20:08:55 volumio2 volumio[887]: UNSET VOLATILE
May 18 20:08:55 volumio2 volumio[887]: info: [1495138135043] CorePlayQueue::clearPlayQueue
May 18 20:08:55 volumio2 volumio[887]: info: [1495138135044] CorePlayQueue::saveQueue
May 18 20:08:55 volumio2 volumio[887]: info: [1495138135045] CoreStateMachine::pushEmptyState
May 18 20:08:55 volumio2 volumio[887]: info: CoreCommandRouter::volumioPushState
May 18 20:08:55 volumio2 volumio[887]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 18 20:08:55 volumio2 volumio[887]: info: [1495138135047] interfaceApi::pushState
May 18 20:08:55 volumio2 volumio[887]: info: [1495138135048] InterfaceWebUI::pushState
May 18 20:08:55 volumio2 volumio[887]: info: CoreCommandRouter::volumioPushQueue
May 18 20:08:55 volumio2 volumio[887]: info: [1495138135063] interfaceApi::pushQueue
May 18 20:08:55 volumio2 volumio[887]: info: [1495138135064] InterfaceWebUI::pushQueue
May 18 20:08:55 volumio2 volumio[887]: info: CoreCommandRouter::volumioAddQueueItems
May 18 20:08:55 volumio2 volumio[887]: info: [1495138135070] CoreStateMachine::addQueueItems
May 18 20:08:55 volumio2 volumio[887]: info: [1495138135070] CorePlayQueue::addQueueItems
May 18 20:08:55 volumio2 volumio[887]: info: uri=http://stream-dc1.radioparadise.com/rp_192m.ogg, service=webradio
May 18 20:08:55 volumio2 volumio[887]: info: First index is 0
May 18 20:08:55 volumio2 volumio[887]: info: ADDING THIS ITEM TO QUEUE: {“uri”:“http://stream-dc1.radioparadise.com/rp_192m.ogg",“service”:"webradio”}
May 18 20:08:55 volumio2 volumio[887]: info: [1495138135076] CorePlayQueue::saveQueue
May 18 20:08:55 volumio2 volumio[887]: info: Adding item to queue: {“uri”:“http://stream-dc1.radioparadise.com/rp_192m.ogg",“service”:“webradio”,“albumart”:"/albumart",“samplerate”:"",“bitdepth”:0,"channels”:0}
…

2

I don’t think volspotconnect is related to this.

Does the playlist start playing at reproducible or random times? There is a problem with the alarm function here.

I have just tried the alarm on a RPi3 installation, and it worked ok (started playing at correct time). I can’t see any logging info though about the alarm initiation (nor in your volumio.log), which makes things a little tricky.

Would you mind editing your topic title to better reflect the content (helps people search)?

3

chsims1 - thanks for your reply

I have spent some more time on this and analyzed the complete log file in more detail.

I now think, that I know what’s going on.

During the initial startup-phase the log shows a time that is incorrect. At a later point during startup the system seems to pick up and change to the correct time, possibly sourced from the network. As far as I am aware, RPi3 does not have a built in real time clock which would preserve time-settings during power-down, so as long as there is no time information from the network, the time will always be incorrect during start-up?

I would assume that the problem only occurs, if the system is powered down and powered up again, if an alarm was set beforehand.

I include a reduced number of log lines at the bottom.

Here is what I think happens and how the system came to play the playlist at that specific time. It would be very odd, if the numbers were just coincidence:

07:36:04 (wrong) time @ initial startup phase
-15:27:09 real startup time

=16:08:55 difference

04:00:00 user-specified alarm time UTC (=06:00:00 CEST)
+16:08:55 assumed adjustment to time difference

=20:08:55 time alarm went off and started playing playlist

Is there a reason for the adjustment of the alarm time?

################## Log - alarm is set @ 4:0 (=06:00 CEST)

…
May 16 15:27:03 volumio2 volumio[887]: info: Loading plugin “alarm-clock”…
May 16 15:27:03 volumio2 sudo[925]: pam_unix(sudo:session): session opened for user root by (uid=0)
May 16 15:27:03 volumio2 sudo[936]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t nfs -o ro,soft,noauto ddoo.redirectme.net:/volume1/music/Other /mnt/NAS/Other
May 16 15:27:03 volumio2 sudo[936]: pam_unix(sudo:session): session opened for user root by (uid=0)
May 16 15:27:03 volumio2 volumio[887]: info: Alarm: Scheduling <Anonymous Job 1> at 4:0
May 16 15:27:03 volumio2 volumio[887]: info: Loading plugin “airplay_emulation”…
…

################## Log - Switch of system time during startup 15:27:09 -> 07:36:04

…
May 16 15:27:09 volumio2 systemd[1]: Configuration file /lib/systemd/system/spop.service is marked executable. Please remove executable permission bits. Proceeding anyway.
May 16 15:27:09 volumio2 systemd[1]: Configuration file /lib/systemd/system/spop.service is marked world-writable. Please remove world writability permission bits. Proceeding anyway.
May 16 15:27:09 volumio2 systemd[1]: Starting Spotify Daemon…
May 18 07:36:04 volumio2 volumio[887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
May 18 07:36:04 volumio2 systemd[1]: Started Spotify Daemon.
May 18 07:36:04 volumio2 volumio[887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
May 18 07:36:04 volumio2 volumio[887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
May 18 07:36:04 volumio2 volumio[887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
May 18 07:36:04 volumio2 volumio[887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
May 18 07:36:04 volumio2 volumio[887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
May 18 07:36:04 volumio2 volumio[887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
May 18 07:36:04 volumio2 volumio[887]: info: BOOT COMPLETED
May 18 07:36:04 volumio2 volumio[887]: Express server listening on port 3000
May 18 07:36:04 volumio2 volumio[887]: Volumio Calling Home
May 18 07:36:04 volumio2 sudo[987]: pam_unix(sudo:session): session closed for user root
May 18 07:36:04 volumio2 systemd[1]: Time has been changed
May 18 07:36:04 volumio2 systemd[1]: Starting Volspotconnect2 Daemon…
…

################## Log - alarm goes off @ 20:08:55 UTC although set to 04:00 UTC (=06:00 CEST)

May 18 20:08:55 volumio2 volumio[887]: info: [1495138135027] Play playlist Radio Paradise
May 18 20:08:55 volumio2 volumio[887]: info: [1495138135034] Play playlist Radio Paradise
May 18 20:08:55 volumio2 volumio[887]: info: CoreCommandRouter::volumioClearQueue
May 18 20:08:55 volumio2 volumio[887]: info: [1495138135041] CoreStateMachine::ClearQueue

4

Is this problem reproducible? Again, I tried setting an alarm and rebooted … the alarm was fine.

5

On my setup the alarm functionality reproducibly doesn’t work - as described in my previous posts.

The problem is noticeable if I simply unplug the power supply and leave the RPi sit for a while (i.e. at least a couple of minutes to make a noticeable difference).

When examining the log, the problem also seems to be there if the system is restarted, but as the time difference is only a few seconds, one will not notice.

What I haven’t mentioned before is the fact that I am using Volumio with wireless only. There is no LAN connection.

As I have just found out, the alarm will work as expected if a LAN connection is present.

Possibly it takes too long for the wireless connection to be established and subsequently NTP to be queried (in my network?) which results in the alarm triggers being read out and set by Volumio back end when the system time is still incorrect?

6

Exacly: this is the clue, NTP is somehow not working on wireless.

Probably the npt service starts before a network connection has been established with wifi…

7

Quite old discussion, but I see that the related github issue is still open without any comment. Do we still have affected users ready for testing? :wink:

The ntp can be delayed. There is a handy ntp.conf miscellaneous calldelay option which controls the delay in seconds between the first and second packets sent in burst or iburst mode to allow additional time for a modem or ISDN call to complete. My proposal is to test Iburst option in combination with calldelay e.g 10 sec:

/etc/ntp.conf ... server 0.debian.pool.ntp.org iburst server 1.debian.pool.ntp.org iburst ... calldelay 10
just to be sure, enable NTP based network time synchronization:

# sudo timedatectl set-ntp true

looking forward for test results