839452 - Add helpful logging of DOM calls resulting in reboot/poweroff

Status: RESOLVED FIXED

(Firefox OS Graveyard :: General, defect)

Description

[Benoit Jacob [:bjacob] (mostly away)]

Here's a funny story. jrmuizel and me were working on bug 834916, trying to get B2G to boot with some new gfx code. But our devices would just continuously reboot. It took us almost a week to figure why. We were running them from USB power without batteries, and B2G interpreted this absence of battery as a low-battery-level condition (isn't that a first bug?) and then decided to reboot (isn't that a second bug? i.e. shouldn't it power off in that case, like Android does?). Here's a JS stack we recorded of that happening:

I/Gecko   (  329): 0 sm_startPowerOff() ["app://system.gaiamobile.org/js/sleep_menu.js":219]
I/Gecko   (  329):     this = [object Object]
I/Gecko   (  329): 1 bm_checkBatteryDrainage() ["app://system.gaiamobile.org/js/battery_manager.js":29]
I/Gecko   (  329):     this = [object Object]
I/Gecko   (  329): 2 bm_init() ["app://system.gaiamobile.org/js/battery_manager.js":38]
I/Gecko   (  329):     this = [object Object]
I/Gecko   (  329): 3 <TOP LEVEL> ["app://system.gaiamobile.org/js/battery_manager.js":277]
I/Gecko   (  329):     this = [object Window]
I/Gecko   (  329):

Anyway, pending a discussion of whether these things are bugs, here is a patch that would at least have helped us not take too long to figure this out, by logging these calls with JS stack.

Comment 1

[Benoit Jacob [:bjacob] (mostly away)]

Attachment: add logging

Comment 2

[Chris Jones [:cjones] inactive; ni?/f?/r? if you need me]

(In reply to Benoit Jacob [:bjacob] from comment #0)
> We were running
> them from USB power without batteries, and B2G interpreted this absence of
> battery as a low-battery-level condition (isn't that a first bug?)

This is a bug, but we may be getting bad data from the APIs we're using.  Please file. 

> and then
> decided to reboot (isn't that a second bug? i.e. shouldn't it power off in
> that case, like Android does?).

Ugh, yes.  Please file.

Comment 3

[Chris Jones [:cjones] inactive; ni?/f?/r? if you need me]

Comment on attachment 711779 [details] [diff] [review]
add logging

This seems like a useful helper in general, although I would have some nits about it.

However, I'm not sure about the use case here.  Was attaching gdb not enough to debug this problem?  There are about 3 callers of this code, so I'm not convinced dumping the entire stack is all that useful in this code.

We also need to be exceeding careful about using a helper like this since it can expose user data.  (Not in this case, but in general.)

Comment 4

[Benoit Jacob [:bjacob] (mostly away)]

(In reply to Chris Jones [:cjones] [:warhammer] from comment #3)
> Comment on attachment 711779 [details] [diff] [review]
> add logging
> 
> This seems like a useful helper in general, although I would have some nits
> about it.
> 
> However, I'm not sure about the use case here.  Was attaching gdb not enough
> to debug this problem?  There are about 3 callers of this code, so I'm not
> convinced dumping the entire stack is all that useful in this code.

No, because rebooting just caused loss of the gdbserver connection.

~ 1 person-week wasted trying to figure what was causing the connection loss, and then trying to figure why we were rebooting.

> 
> We also need to be exceeding careful about using a helper like this since it
> can expose user data.  (Not in this case, but in general.)

Comment 5

[Benoit Jacob [:bjacob] (mostly away)]

(In reply to Chris Jones [:cjones] [:warhammer] from comment #2)
> (In reply to Benoit Jacob [:bjacob] from comment #0)
> > We were running
> > them from USB power without batteries, and B2G interpreted this absence of
> > battery as a low-battery-level condition (isn't that a first bug?)
> 
> This is a bug, but we may be getting bad data from the APIs we're using. 
> Please file. 

bug 844974

> 
> > and then
> > decided to reboot (isn't that a second bug? i.e. shouldn't it power off in
> > that case, like Android does?).
> 
> Ugh, yes.  Please file.


bug 844998

Comment 6

[Nicolas Silva [:nical]]

I just wasted a *lot* of time trying to understand why my phone was boot-looping (I had taken out the battery because I needed to be able to hard reboot often, and was far from imagining that it would cause my device to boot-loop).
I spent a lot of time reading code related to whatever was coming out of logcat. I would have wasted much less time if I had had something in the logcat saying "rebooting now" (or even better, "rebooting now because [...]") which would have left we with a place to start looking.

Please, please, please, let's reconsider landing Benoit's patch before someone else wastes a week on this problem.

Comment 7

[Benoit Jacob [:bjacob] (mostly away)]

Comment on attachment 711779 [details] [diff] [review]
add logging

Thank you Nical :) re-requesting review now. I think that we are better off with this patch than without it.

Comment 8

[Michael Wu [:mwu]]

Comment on attachment 711779 [details] [diff] [review]
add logging

Can you make LOG_FUNCTION_AND_JS_STACK a function-like macro? It looks pretty weird. Otherwise, this seems like a good idea.

I'm not too comfortable reviewing general code in dom though - Jonas, do you mind reviewing?

Comment 9

[Benoit Jacob [:bjacob] (mostly away)]

https://hg.mozilla.org/integration/mozilla-inbound/rev/39a388613446

Comment 10

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/39a388613446