1163325 - Alarm not working if screen is off

Status: RESOLVED INCOMPLETE

(Firefox OS Graveyard :: Gaia::Clock, defect)

Description

[Michael Monreal [:micmon]]

I am using a Flame with v18D base image and latest-mozilla-b2g37_v2_2-flame-kk from today (may 9) shallow-flashed.

Problem: my configured alarm does not work while the screen is off. Once I activate the screen after the alarm should have happened the alarm actually sounds but that is no use to me obviously.

Comment 1

[Michael Monreal [:micmon]]

Turns out the alarms do work, but they sound at the wrong (unpredictable) time. Sometimes one minute too late, sometimes 10 minutes , sometimes 30 minutes...

Comment 2

[Andrew Sutherland [:asuth] (he/him)]

This sounds a lot like bug 1118272 which should be fixed on v2.2.  (Noting that there are a family of potentially related issues involving the real-time clock, but that's mainly for when the device was powered-off.)

There has been relatively extensive logging added to the clock application, so it would be great if you could provide a logcat from when this happens.  Two steps, both detailed at https://developer.mozilla.org/en-US/Firefox_OS/Debugging/On-device_console_logging
1) Enable console logging.
2) Grab a logcat.  Since it's quite possible the alarms would ring fine if you left the device tethered to a computer with USB connected, you might need to take advantage of the "shake to save system log" functionality described on that page.  That itself may cause the alarms to work okay (since we may not enter as deep a sleep-state because of the accelerometer.)  The VolumeUp+Sleep could work better but is v3/trunk only, so you'd have to use a more recent build for that.

Comment 3

[Michael Monreal [:micmon]]

(In reply to Andrew Sutherland [:asuth] from comment #2)
> This sounds a lot like bug 1118272 which should be fixed on v2.2.
I am running latest 2.2 ontop the 18D base image, based on Android 4.4, but read somewhere that 2.2 is supposed to be released with Android 5.1-based Gonk. So, is the combination I run even "valid" or is there a way to update to 5.1 on the Flame yet? Sorry for asking, I am really new to this.

> Since it's quite possible the alarms would ring fine if
> you left the device tethered to a computer with USB connected
I set an alarm to ring at 8:00 AM but it did not work. I connected it to USB at 8:39 and it began to ring. I made a logcat after that, it shows something about the alarm being configured for 8:00 but I am not sure if it is of use, please have a look.




, you might
> need to take advantage of the "shake to save system log" functionality
> described on that page.  That itself may cause the alarms to work okay
> (since we may not enter as deep a sleep-state because of the accelerometer.)
> The VolumeUp+Sleep could work better but is v3/trunk only, so you'd have to
> use a more recent build for that.

Comment 4

[Michael Monreal [:micmon]]

Attachment: logcat.txt

Comment 5

[Michael Monreal [:micmon]]

Attachment: logs.zip

Here is full set of logs I did after the last logcat.

- first log: before
- second log: just after setting alarm
- third log: after alarm ringed (again it only worked when I turned on the screen)

Note that I shook the device in between the second and third log after the alarm was supposed to sound but the shake-to-create-log does only seem to work when the screen is on as well...

Comment 6

[Andrew Sutherland [:asuth] (he/him)]

Thanks for the logs!

The first log attachment 8603799 [details] contains the following that indicates that only fired at 8:46a.  This suggests a failure in the mozAlarms API and/or system message delivery at first glance.  (Note: if manually gathering a logcat "-v time" is good to pass to get timestamps include, although it doesn't particularly matter in this case since there's not a lot of useful context.)

BUT!  There is no "### ALARM FIRED! ### Details" string, however, which differs from the next log.
===
I/Clock   (13401): Content JS LOG: [Clock] =====================================
I/Clock   (13401):  
I/Clock   (13401):     at logForAlarmDebugging (app://clock.gaiamobile.org/js/startup.js:5299:4)
I/Clock   (13401): Content JS LOG: [Clock] Alarm Debug: {"now":"2015-05-10T06:46:46.896Z","tz":-120} 
I/Clock   (13401):     at logForAlarmDebugging (app://clock.gaiamobile.org/js/startup.js:5300:0)
I/Clock   (13401): Content JS LOG: [Clock] ======= Remaining mozAlarms: ========
I/Clock   (13401):  
I/Clock   (13401):     at logForAlarmDebugging/request.onsuccess (app://clock.gaiamobile.org/js/startup.js:5316:6)
I/Clock   (13401): Content JS LOG: [Clock] -------------------------------------
I/Clock   (13401):  
I/Clock   (13401):     at logForAlarmDebugging/request.onsuccess (app://clock.gaiamobile.org/js/startup.js:5326:6)
I/Clock   (13401): Content JS LOG: [Clock] ===== Raw IndexedDB Alarm Data: =====
I/Clock   (13401):  
I/Clock   (13401):     at logForAlarmDebugging/< (app://clock.gaiamobile.org/js/startup.js:5306:6)
I/Clock   (13401): Content JS LOG: [Clock]    {"id":4,"registeredAlarms":{},"repeat":{},"hour":"08","minute":"00","label":"","sound":"ac_awake.opus","vibrate":false,"snooze":10} 
I/Clock   (13401):     at logForAlarmDebugging/</< (app://clock.gaiamobile.org/js/startup.js:5309:8)
I/Clock   (13401): Content JS LOG: [Clock] -------------------------------------
I/Clock   (13401):  
I/Clock   (13401):     at logForAlarmDebugging/< (app://clock.gaiamobile.org/js/startup.js:5311:6)
===


The third log contains the following and it looks like it worked from a clock app perspective based on the excerpt since it fired at 9:10a.  EXCEPT, the next set of log entries is at 9:14am, where the display says it turned off and then immediately turned on.  It seems like it's possible that the device went into a deep sleep so that display off (and perhaps redundant?) message was in the queue but only got logged once you turned the display on.

In this case it would suggest that clock is not holding its wake-lock long enough or not acquiring it early enough.

Is it the case that you turned the screen on at 9:14:27 and that's when the alarm fired?

===
05-10 09:10:00.087 13401 13401 I Clock   : Content JS LOG: [Clock] ### ALARM FIRED! ### Details: {"id":16,"date":"2015-05-10T07:10:00.000Z","respe
ctTimezone":"ignoreTimezone","data":{"id":4,"type":"normal","date":"2015-05-10T07:10:00.000Z"}} 
05-10 09:10:00.087 13401 13401 I Clock   :     at ActiveAlarm.prototype.onMozAlarm (app://clock.gaiamobile.org/js/startup.js:5353:0)
05-10 09:10:00.087 13401 13401 I Clock   : Content JS LOG: [Clock] =====================================
05-10 09:10:00.087 13401 13401 I Clock   :  
05-10 09:10:00.087 13401 13401 I Clock   :     at logForAlarmDebugging (app://clock.gaiamobile.org/js/startup.js:5299:4)
05-10 09:10:00.087 13401 13401 I Clock   : Content JS LOG: [Clock] Alarm Debug: {"now":"2015-05-10T07:10:00.042Z","tz":-120} 
05-10 09:10:00.087 13401 13401 I Clock   :     at logForAlarmDebugging (app://clock.gaiamobile.org/js/startup.js:5300:0)
05-10 09:10:00.337 13401 13401 I Gecko   : ###################################### forms.js loaded
05-10 09:10:00.347 13401 13401 I Gecko   : ############################### browserElementPanning.js loaded
05-10 09:10:00.377 13401 13401 I Gecko   : ######################## BrowserElementChildPreload.js loaded
05-10 09:10:00.597 13401 13401 I Clock   : Content JS LOG: [Clock] ======= Remaining mozAlarms: ========
05-10 09:10:00.597 13401 13401 I Clock   :  
05-10 09:10:00.597 13401 13401 I Clock   :     at logForAlarmDebugging/request.onsuccess (app://clock.gaiamobile.org/js/startup.js:5316:6)
05-10 09:10:00.597 13401 13401 I Clock   : Content JS LOG: [Clock] -------------------------------------
05-10 09:10:00.597 13401 13401 I Clock   :  
05-10 09:10:00.597 13401 13401 I Clock   :     at logForAlarmDebugging/request.onsuccess (app://clock.gaiamobile.org/js/startup.js:5326:6)
05-10 09:10:00.597 13401 13401 I Clock   : Content JS LOG: [Clock] ===== Raw IndexedDB Alarm Data: =====
05-10 09:10:00.597 13401 13401 I Clock   :  
05-10 09:10:00.597 13401 13401 I Clock   :     at logForAlarmDebugging/< (app://clock.gaiamobile.org/js/startup.js:5306:6)
05-10 09:10:00.597 13401 13401 I Clock   : Content JS LOG: [Clock]    {"id":4,"registeredAlarms":{"normal":16},"repeat":{},"hour":"09","minute":"1
0","label":"","sound":"ac_awake.opus","vibrate":false,"snooze":10} 
05-10 09:10:00.597 13401 13401 I Clock   :     at logForAlarmDebugging/</< (app://clock.gaiamobile.org/js/startup.js:5309:8)
05-10 09:10:00.597 13401 13401 I Clock   : Content JS LOG: [Clock] -------------------------------------
05-10 09:10:00.597 13401 13401 I Clock   :  
05-10 09:10:00.597 13401 13401 I Clock   :     at logForAlarmDebugging/< (app://clock.gaiamobile.org/js/startup.js:5311:6)
05-10 09:14:27.018   209   898 I qdhwcomposer: handle_blank_event: dpy:0 panel power state: 0
05-10 09:14:27.018   209   209 I QCOM PowerHAL: Got set_interactive hint
05-10 09:14:27.018   209   209 D qdhwcomposer: hwc_blank: Unblanking display: 0
05-10 09:14:27.248   309   309 E QCALOG  : [MessageQ] ProcessNewMessage: [XT-CS] unknown deliver target [OS-Agent]
05-10 09:14:27.268   309   309 E QCALOG  : [MessageQ] ProcessNewMessage: [XTWWAN-PE] unknown deliver target [OS-Agent]
05-10 09:14:27.368   209   898 I qdhwcomposer: handle_blank_event: dpy:0 panel power state: 1
05-10 09:14:27.548   209   209 D qdhwcomposer: hwc_blank: Done unblanking display: 0
===

I'm needinfo-ing the clock owner, :mcav, to take over from here since this seems like very useful information you're provided (thanks!) and he is now back from PTO and much more informed about how this bit of clock stuff works.  (Although I'm happy to help diagnose various control flows if you want another set of eyes on this, :mcav)

Comment 7

[Michael Monreal [:micmon]]

(In reply to Andrew Sutherland [:asuth] from comment #6)
> In this case it would suggest that clock is not holding its wake-lock long
> enough or not acquiring it early enough.
> 
> Is it the case that you turned the screen on at 9:14:27 and that's when the
> alarm fired?
> 

Yes I waited some time after the alarm should have fired (4:27 minutes in this case I guess) and then turned on the display at which point the alarm sounded. I tried this at least 20 times and in rare occasions it actually worked fine, in some the alarm sounded about 2 to 10 minutes later but most of the time it only ever sounded after I manually turned on the display (which means theoretically the alarm could have sounded at some point but more than half an hour too late).

I am happy to provide more feedback. Note that I do not use this device as my main phone so resetting it or installing unstable stuff would be no problem - I mainly bought the Flame to play around with it and find bugs like this one :)

Comment 12

[daniel.rocher]

I confirm this bug.

Comment 13

[Michael Monreal [:micmon]]

No longer relevant.