PDA

View Full Version : Radio audio pop before alarm fade-in



Marc
2010-01-24, 09:02
I've caught the pattern that manifests in this case.

Note that in the properly functioning scenario the server seems to send the request to start the alarm audio stream after the playerLoaded and/or playerModeChange notifications are disseminated by SqueezeOS. In the bad cases the decoder is initialized and stream fetched prior to the playerLoaded and/or playerModeChange notifications.

I don't have a development setup here to rebuild the SqueezeOS C language components, so I can't modify decode_start_handler(...) to output more detailed information (for example, the transition_type and other metadata settings that are read via mqueue... operations and then qualify the audio output). It's my guess that the transition setting may be getting improperly passed (as in not to fade-in) to decode_start_handler(...) at this stage, only to be properly updated at some later point by another SqueezeOS entity when the playerLoaded and/or playerModeChange notifications are disseminated in the context of alarms. I do not believe the AlarmSnooze applet is involved in any operation that influences server audio transition type (or other stream qualifying metadata)... I also don't see anyplace that immediately jumps out at me in the SqueezeOS Lua code where the transition is being manipulated...

I would think that the Logitech guys should be able to locate the cause fairly quickly in light of the log output below.

Note the good (properly faded-in alarm audio) and bad (audio at high volume heard for short period prior to faded-in alarm audio) log output below. Also note that sometimes the playerLoaded notification occurs and sometimes it does not.

See the next post for log output. The forum is complaining the post is too long with it included here...

Marc

Marc
2010-01-24, 09:09
More good and bad cases are included in the attached file (forum says they're too long to post directly here):

---------------------------------

Good:

Jan 24 09:05:59 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:238 notify_playerModeChange: player (LocalPlayer {Chief}) mode has been changed to play
Jan 24 09:05:59 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:240 notify_playerModeChange: - audioState is 0
Jan 24 09:05:59 squeezeplay: INFO applet.ScreenSavers - ScreenSaversApplet.lua:243 activating Clock screensaver
Jan 24 09:05:59 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:91 notify_playerAlarmState received for LocalPlayer {Chief} with alarmState of active
Jan 24 09:05:59 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:93 **************************** notify_playerAlarmState received: active 0
Jan 24 09:05:59 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:573 _stopTimer: stopping RTC fallback alarm timer
Jan 24 09:05:59 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:363 openAlarmWindow()server true
Jan 24 09:05:59 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:406 openAlarmWindow: called with `server` - audioState is 0
Jan 24 09:06:00 squeezeplay: INFO audio.decode - decode_start_handler:274 init decoder mp3
Jan 24 09:06:00 squeezeplay: INFO audio.decode - Playback.lua:413 connect 209.94.184.9:8000 GET /amstream.mp3 HTTP/1.0^M
Jan 24 09:06:00 squeezeplay: debug_pagefaults:192 Pagefaults, Major:0 Minor:1
Jan 24 09:06:05 squeezeplay: INFO squeezeplay.applets - AppletManager.lua:705 store settings: Playback
Jan 24 09:06:09 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:197 alarm_sledgehammerRearm(_pollDecodeState): server alarm in progress - audioState is 1 and isconnected is true


Good:

Jan 24 09:08:59 squeezeplay: INFO applet.SlimMenus - SlimMenusApplet.lua:420 _menuSink(1) nil menuDirective: add isCurrentServer:true
Jan 24 09:08:59 squeezeplay: INFO applet.SlimMenus - SlimMenusApplet.lua:691 hiding any 'connecting to server' popup after menu response from current server, SlimServer {mysqueezebox.com}
Jan 24 09:08:59 squeezeplay: INFO applet.AlarmSnooze - AlarmSnoozeApplet.lua:217 notify_playerLoaded(LocalPlayer {Chief})
Jan 24 09:08:59 squeezeplay: INFO applet.ChooseMusicSource - ChooseMusicSourceApplet.lua:540 Hiding popup, exists?: nil
Jan 24 09:08:59 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:238 notify_playerModeChange: player (LocalPlayer {Chief}) mode has been changed to play
Jan 24 09:08:59 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:240 notify_playerModeChange: - audioState is 0
Jan 24 09:08:59 squeezeplay: INFO applet.ScreenSavers - ScreenSaversApplet.lua:243 activating Clock screensaver
Jan 24 09:08:59 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:91 notify_playerAlarmState received for LocalPlayer {Chief} with alarmState of active
Jan 24 09:08:59 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:93 **************************** notify_playerAlarmState received: active 0
Jan 24 09:08:59 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:573 _stopTimer: stopping RTC fallback alarm timer
Jan 24 09:08:59 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:363 openAlarmWindow()server true
Jan 24 09:08:59 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:406 openAlarmWindow: called with `server` - audioState is 0
Jan 24 09:09:00 squeezeplay: INFO audio.decode - decode_start_handler:274 init decoder mp3
Jan 24 09:09:00 squeezeplay: INFO audio.decode - Playback.lua:413 connect 209.94.184.9:8000 GET /amstream.mp3 HTTP/1.0^M
Jan 24 09:09:00 squeezeplay: debug_pagefaults:192 Pagefaults, Major:0 Minor:1
Jan 24 09:09:05 squeezeplay: INFO squeezeplay.applets - AppletManager.lua:705 store settings: Playback
Jan 24 09:09:09 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:197 alarm_sledgehammerRearm(_pollDecodeState): server alarm in progress - audioState is 1 and isconnected is true



Bad (pop first!):

Jan 24 10:12:58 squeezeplay: INFO audio.decode - decode_start_handler:274 init decoder mp3
Jan 24 10:12:58 squeezeplay: INFO audio.decode - Playback.lua:413 connect 66.150.114.115:80 GET /static/sounds/musical/barn_fire.mp3 HTTP/1.0^M
Jan 24 10:12:58 squeezeplay: INFO applet.SlimMenus - SlimMenusApplet.lua:420 _menuSink(1) nil menuDirective: add isCurrentServer:true
Jan 24 10:12:58 squeezeplay: INFO applet.SlimMenus - SlimMenusApplet.lua:691 hiding any 'connecting to server' popup after menu response from current server, SlimServer {Office}
Jan 24 10:12:58 squeezeplay: INFO applet.AlarmSnooze - AlarmSnoozeApplet.lua:217 notify_playerLoaded(LocalPlayer {Chief})
Jan 24 10:12:58 squeezeplay: INFO applet.ChooseMusicSource - ChooseMusicSourceApplet.lua:540 Hiding popup, exists?: nil
Jan 24 10:12:58 squeezeplay: debug_pagefaults:192 Pagefaults, Major:0 Minor:1
Jan 24 10:12:58 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:238 notify_playerModeChange: player (LocalPlayer {Chief}) mode has been changed to play
Jan 24 10:12:58 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:240 notify_playerModeChange: - audioState is 1
Jan 24 10:12:58 squeezeplay: debug_pagefaults:192 Pagefaults, Major:0 Minor:1
Jan 24 10:12:59 squeezeplay: INFO applet.ScreenSavers - ScreenSaversApplet.lua:243 activating Clock screensaver
Jan 24 10:12:59 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:91 notify_playerAlarmState received for LocalPlayer {Chief} with alarmState of active
Jan 24 10:12:59 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:93 **************************** notify_playerAlarmState received: active 0
Jan 24 10:12:59 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:573 _stopTimer: stopping RTC fallback alarm timer
Jan 24 10:12:59 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:363 openAlarmWindow()server true
Jan 24 10:12:59 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:406 openAlarmWindow: called with `server` - audioState is 1
Jan 24 10:13:04 squeezeplay: INFO squeezeplay.applets - AppletManager.lua:705 store settings: Playback
Jan 24 10:13:09 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:197 alarm_sledgehammerRearm(_pollDecodeState): server alarm in progress - audioState is 1 and isconnected is true


Bad again (pop first!):

Jan 24 10:17:58 squeezeplay: INFO audio.decode - decode_start_handler:274 init decoder mp3
Jan 24 10:17:58 squeezeplay: INFO audio.decode - Playback.lua:413 connect 66.150.114.115:80 GET /static/sounds/musical/barn_fire.mp3 HTTP/1.0^M
Jan 24 10:17:58 squeezeplay: INFO applet.SlimMenus - SlimMenusApplet.lua:420 _menuSink(1) nil menuDirective: add isCurrentServer:true
Jan 24 10:17:58 squeezeplay: INFO applet.SlimMenus - SlimMenusApplet.lua:691 hiding any 'connecting to server' popup after menu response from current server, SlimServer {Office}
Jan 24 10:17:58 squeezeplay: INFO applet.AlarmSnooze - AlarmSnoozeApplet.lua:217 notify_playerLoaded(LocalPlayer {Chief})
Jan 24 10:17:58 squeezeplay: INFO applet.ChooseMusicSource - ChooseMusicSourceApplet.lua:540 Hiding popup, exists?: nil
Jan 24 10:17:58 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:238 notify_playerModeChange: player (LocalPlayer {Chief}) mode has been changed to play
Jan 24 10:17:58 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:240 notify_playerModeChange: - audioState is 0
Jan 24 10:17:59 squeezeplay: INFO applet.ScreenSavers - ScreenSaversApplet.lua:243 activating Clock screensaver
Jan 24 10:17:59 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:91 notify_playerAlarmState received for LocalPlayer {Chief} with alarmState of active
Jan 24 10:17:59 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:93 **************************** notify_playerAlarmState received: active 0
Jan 24 10:17:59 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:573 _stopTimer: stopping RTC fallback alarm timer
Jan 24 10:17:59 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:363 openAlarmWindow()server true
Jan 24 10:17:59 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:406 openAlarmWindow: called with `server` - audioState is 0
Jan 24 10:18:04 squeezeplay: INFO squeezeplay.applets - AppletManager.lua:705 store settings: Playback

jmpage2
2010-01-24, 10:15
I believe you've hit on it, let me know if there are additional diagnostics I can perform on my setup since I am experiencing the issue also.

I am running FW 7.4.1-r7915 with WHS hosted Squeezebox server 7.4.1 - r28947.

I have two alarms, one is a Mon-Friday alarm set for 7AM. It plays my "greatest hits" playlist which is about 2,000 tracks located on the Windows Home Server.

2nd Alarm is Sat/Sun at 8AM. This alarm plays the same playlist.

In both alarms I periodically get a full volume "blast" of the 1st track to play for the alarm, followed by a moment of silence and then the volume fade up that I should be getting with the same track.

bluegaspode
2010-01-24, 11:31
So this is a random effect for you both (and as Marc could somehow reproduce it as well even with the latest firmware) ?

Marc
2010-01-24, 18:19
I believe you've hit on it, let me know if there are additional diagnostics I can perform on my setup since I am experiencing the issue also.

I am running FW 7.4.1-r7915 with WHS hosted Squeezebox server 7.4.1 - r28947.

I have two alarms, one is a Mon-Friday alarm set for 7AM. It plays my "greatest hits" playlist which is about 2,000 tracks located on the Windows Home Server.

2nd Alarm is Sat/Sun at 8AM. This alarm plays the same playlist.

In both alarms I periodically get a full volume "blast" of the 1st track to play for the alarm, followed by a moment of silence and then the volume fade up that I should be getting with the same track.

Since you're running 7.4.1 you shouldn't use the latest AlarmSnooze applet I've posted, as it relates to 7.4.2.

If you had the applet (or an earlier version related to 7.4.1), though, then you'd see the germane player notifications interspersed with the decoder information spit out to the log by the AlarmSnoozeApplet. It would be interesting to see if you get the same pattern as I see here (I strongly suspect you will).

It appears that since the audio is pushed from the server at alarm trigger time, but is not synchronized in lockstep with the alarm state control/messaging protocol that the fade-in transition configuration isn't setup as quickly as it should be to impact the inbound audio stream. The audio should not be sent (read: stream set up) until the appropriate metadata (including transition type, if any) has been applied locally at the Radio. As I've mentioned in other alarm related threads, the systemic operation/synchronization of alarms needs to be refined...

Marc

bluegaspode
2010-01-30, 03:04
Just for reference - this is the corresponding bug-report
https://bugs.slimdevices.com/show_bug.cgi?id=15239