759792 - Robocop: "key dispatching timed out sending to" awesomebar

Status: RESOLVED DUPLICATE of bug 771189

(Testing :: General, defect)

Description

[Geoff Brown [:gbrown]]

With recent improvements to Robocop, I can run testCheck2/3, in Talos, on my Galaxy S with good success (sometimes as many as 50 cycles without a failure). Most of the remaining failures are characterized by the logcat error message "Key dispatching timed out sending..." This message is seen 30 to 90 seconds before the test fails; sometimes it even occurs during a previous test cycle.

The talos test logs on my Galaxy S look similar to current testCheck2/3 failures on tbpl (bug 756817), but there is no sign of the "Key dispatching..." message on the tegras.

Comment 1

[Geoff Brown [:gbrown]]

This seemed to occur much more frequently before bug 764147 was resolved. Now watching to see if it recurs at all with bug 764147 fixed.

Comment 2

[Geoff Brown [:gbrown]]

See also bug 766059.

Comment 3

[Geoff Brown [:gbrown]]

This does still happen on my Galaxy S, but very infrequently, and I don't know how to reproduce it.

Comment 4

[Geoff Brown [:gbrown]]

Latest logcat:

06-25 13:53:01.904 W/InputConnectionWrapper.ICC( 3216): Timed out waiting on IInputContextCallback
06-25 13:53:03.062 I/PowerManagerService( 3098): Ulight 3->7|0
06-25 13:53:03.066 V/WindowManager( 3098): Dsptch to Window{484d7b68 org.mozilla.fennec_mozdev/org.mozilla.gecko.AwesomeBar paused=false}
06-25 13:53:03.906 W/InputConnectionWrapper.ICC( 3216): Timed out waiting on IInputContextCallback
06-25 13:53:03.906 E/AxT9IME ( 3216): ERROR : getTextBeforeCursor return null!!!
06-25 13:53:04.156 D/dalvikvm( 3216): GC_EXTERNAL_ALLOC freed 3723 objects / 271696 bytes in 56ms
06-25 13:53:06.064 W/PowerManagerService( 3098): Timer 0x7->0x3|0x0
06-25 13:53:06.064 I/PowerManagerService( 3098): Ulight 7->3|0
06-25 13:53:08.070 W/WindowManager( 3098): Key dispatching timed out sending to org.mozilla.fennec_mozdev/org.mozilla.gecko.AwesomeBar
06-25 13:53:08.072 W/WindowManager( 3098): Previous dispatch state: {{KeyEvent{action=0 code=36 repeat=0 meta=0 scancode=0 mFlags=8} to Window{484d7b68 org.mozilla.fennec_mozdev/org.mozilla.gecko.AwesomeBar paused=false} @ 1340653983067 lw=Window{484d7b68 org.mozilla.fennec_mozdev/org.mozilla.gecko.AwesomeBar paused=false} lb=android.os.BinderProxy@484d7a08 fin=false gfw=true ed=true tts=0 wf=false fp=false mcf=Window{484d7b68 org.mozilla.fennec_mozdev/org.mozilla.gecko.AwesomeBar paused=false}}}
06-25 13:53:08.076 W/WindowManager( 3098): Current dispatch state: {{null to Window{484d7b68 org.mozilla.fennec_mozdev/org.mozilla.gecko.AwesomeBar paused=false} @ 1340653988074 lw=Window{484d7b68 org.mozilla.fennec_mozdev/org.mozilla.gecko.AwesomeBar paused=false} lb=android.os.BinderProxy@484d7a08 fin=false gfw=true ed=true tts=0 wf=false fp=false mcf=Window{484d7b68 org.mozilla.fennec_mozdev/org.mozilla.gecko.AwesomeBar paused=false}}}

Note the InputConnectionWrapper and AxT9IME messages preceding the "Key dispatching" message; are these significant?

Comment 5

[Geoff Brown [:gbrown]]

Another "Key dispatching...", another InputConnectionWrapper/AxT9IME message:

06-25 14:58:06.082 W/InputConnectionWrapper.ICC( 3216): Timed out waiting on IInputContextCallback
06-25 14:58:07.182 I/PowerManagerService( 3098): Ulight 3->7|0
06-25 14:58:07.188 V/WindowManager( 3098): Dsptch to Window{48387bc0 org.mozilla.fennec_mozdev/org.mozilla.gecko.AwesomeBar paused=false}
06-25 14:58:07.452 D/BatteryService( 3098): update start
06-25 14:58:07.482 D/BatteryService( 3098): updateBattery level:100 scale:100 status:5 health:2 present:true voltage: 4242 temperature: 370 technology: Li-ion AC powered:false USB powered:true icon:17302163
06-25 14:58:07.584 I/StatusBarPolicy( 3098): BAT. status:5 health:2
06-25 14:58:07.584 D/WifiService( 3098): ACTION_BATTERY_CHANGED pluggedType: 2
06-25 14:58:08.084 W/InputConnectionWrapper.ICC( 3216): Timed out waiting on IInputContextCallback
06-25 14:58:08.084 E/AxT9IME ( 3216): ERROR : getTextBeforeCursor return null!!!
06-25 14:58:10.183 W/PowerManagerService( 3098): Timer 0x7->0x3|0x0
06-25 14:58:10.184 I/PowerManagerService( 3098): Ulight 7->3|0
06-25 14:58:12.191 W/WindowManager( 3098): Key dispatching timed out sending to org.mozilla.fennec_mozdev/org.mozilla.gecko.AwesomeBar
06-25 14:58:12.194 W/WindowManager( 3098): Previous dispatch state: {{KeyEvent{action=0 code=36 repeat=0 meta=0 scancode=0 mFlags=8} to Window{48387bc0 org.mozilla.fennec_mozdev/org.mozilla.gecko.AwesomeBar paused=false} @ 1340657887186 lw=Window{48387bc0 org.mozilla.fennec_mozdev/org.mozilla.gecko.AwesomeBar paused=false} lb=android.os.BinderProxy@4860fef8 fin=false gfw=true ed=true tts=0 wf=false fp=false mcf=Window{48387bc0 org.mozilla.fennec_mozdev/org.mozilla.gecko.AwesomeBar paused=false}}}
06-25 14:58:12.196 W/WindowManager( 3098): Current dispatch state: {{null to Window{48387bc0 org.mozilla.fennec_mozdev/org.mozilla.gecko.AwesomeBar paused=false} @ 1340657892195 lw=Window{48387bc0 org.mozilla.fennec_mozdev/org.mozilla.gecko.AwesomeBar paused=false} lb=android.os.BinderProxy@4860fef8 fin=false gfw=true ed=true tts=0 wf=false fp=false mcf=Window{48387bc0 org.mozilla.fennec_mozdev/org.mozilla.gecko.AwesomeBar paused=false}}}
06-25 14:58:13.157 W/ActivityManager( 3098): Launch timeout has expired, giving up wake lock!
06-25 14:58:13.212 W/ActivityManager( 3098): Activity idle timeout for HistoryRecord{484e2c00 org.mozilla.fennec_mozdev/org.mozilla.gecko.AwesomeBar}

Comment 6

[Geoff Brown [:gbrown]]

I have confirmed that this bug has the same cause as bug 766059. See  https://bugzilla.mozilla.org/show_bug.cgi?id=766059#c24.

Comment 7

[Geoff Brown [:gbrown]]

Recent discussion on bug 766059 suggests this might be handled better as its own bug.

Comment 8

[Geoff Brown [:gbrown]]

blassey suggested that the patch on bug 680311 could be adapted to help here.

Comment 9

[Geoff Brown [:gbrown]]

Probable dup of 771189 -- just marking as a dependency for now.