Closed Bug 1599109 Opened 4 years ago Closed 4 years ago

Intermittent java.lang.IllegalArgumentException: Requested window android.os.BinderProxy@806bdf0 does not exist

Categories

(Testing :: General, defect, P3)

defect

Tracking

(firefox81 fixed)

RESOLVED FIXED
81 Branch
Tracking Status
firefox81 --- fixed

People

(Reporter: malexandru, Assigned: gbrown)

Details

Attachments

(1 file)

Failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=278013711&repo=autoland&lineNumber=18067

Raw log: https://firefoxci.taskcluster-artifacts.net/NuxXr8-0QQqmoD46XTuxGA/0/public/logs/live_backing.log

[task 2019-11-25T14:40:12.788Z] 14:40:12 INFO - 11-25 14:40:00.218 D/GeckoThread( 8942): State changed to EXITED
[task 2019-11-25T14:40:12.788Z] 14:40:12 INFO - 11-25 14:40:00.240 D/gralloc_ranchu( 1346): gralloc_alloc: Creating ashmem region of size 1421312
[task 2019-11-25T14:40:12.788Z] 14:40:12 INFO - 11-25 14:40:00.241 E/EGL_emulation( 1346): tid 1346: eglCreateSyncKHR(1901): error 0x3004 (EGL_BAD_ATTRIBUTE)
[task 2019-11-25T14:40:12.788Z] 14:40:12 INFO - 11-25 14:40:00.276 D/EGL_emulation( 2025): eglMakeCurrent: 0x751c8504a720: ver 2 0 (tinfo 0x751c8500c900)
[task 2019-11-25T14:40:12.788Z] 14:40:12 INFO - 11-25 14:40:00.284 I/Gecko ( 8942): [Parent 8942, Unnamed thread 751c85432780] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/workspace/build/src/xpcom/base/nsTraceRefcnt.cpp, line 198
[task 2019-11-25T14:40:12.788Z] 14:40:12 INFO - 11-25 14:40:00.284 I/Gecko ( 8942): [Parent 8942, Unnamed thread 751c85432780] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/workspace/build/src/xpcom/base/nsTraceRefcnt.cpp, line 198
[task 2019-11-25T14:40:12.788Z] 14:40:12 INFO - 11-25 14:40:00.284 I/Gecko ( 8942): [Parent 8942, Unnamed thread 751c85432780] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/workspace/build/src/xpcom/base/nsTraceRefcnt.cpp, line 198
[task 2019-11-25T14:40:12.788Z] 14:40:12 INFO - 11-25 14:40:00.284 I/Gecko ( 8942): [Parent 8942, Unnamed thread 751c85432780] WARNING: Called GetMainThread but there isn't a main thread and we're not the main thread.: file /builds/worker/workspace/build/src/xpcom/threads/nsThreadManager.cpp, line 579
[task 2019-11-25T14:40:12.788Z] 14:40:12 INFO - 11-25 14:40:00.284 I/Gecko ( 8942): [Parent 8942, Unnamed thread 751c85432780] WARNING: 'NS_FAILED(rv)', file /builds/worker/workspace/build/src/xpcom/threads/nsThreadUtils.cpp, line 241
[task 2019-11-25T14:40:12.788Z] 14:40:12 INFO - 11-25 14:40:00.284 I/Gecko ( 8942): [Parent 8942, Unnamed thread 751c85432780] ###!!! ASSERTION: Failed NS_DispatchToMainThread() in shutdown; leaking: 'false', file /builds/worker/workspace/build/src/xpcom/threads/nsThreadUtils.cpp, line 243
[task 2019-11-25T14:40:12.791Z] 14:40:12 INFO - 11-25 14:40:00.291 I/Gecko ( 8942): [Parent 8942, Unnamed thread 751c85432780] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/workspace/build/src/xpcom/base/nsTraceRefcnt.cpp, line 198
[task 2019-11-25T14:40:12.792Z] 14:40:12 INFO - 11-25 14:40:00.291 I/Gecko ( 8942): [Parent 8942, Unnamed thread 751c85432780] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/workspace/build/src/xpcom/base/nsTraceRefcnt.cpp, line 198
[task 2019-11-25T14:40:12.792Z] 14:40:12 INFO - 11-25 14:40:00.291 I/Gecko ( 8942): [Parent 8942, Unnamed thread 751c85432780] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/workspace/build/src/xpcom/base/nsTraceRefcnt.cpp, line 198
[task 2019-11-25T14:40:12.792Z] 14:40:12 INFO - 11-25 14:40:00.291 I/Gecko ( 8942): [Parent 8942, Unnamed thread 751c85432780] WARNING: Called GetMainThread but there isn't a main thread and we're not the main thread.: file /builds/worker/workspace/build/src/xpcom/threads/nsThreadManager.cpp, line 579
[task 2019-11-25T14:40:12.792Z] 14:40:12 INFO - 11-25 14:40:00.291 I/Gecko ( 8942): [Parent 8942, Unnamed thread 751c85432780] WARNING: 'NS_FAILED(rv)', file /builds/worker/workspace/build/src/xpcom/threads/nsThreadUtils.cpp, line 241
[task 2019-11-25T14:40:12.792Z] 14:40:12 INFO - 11-25 14:40:00.291 I/Gecko ( 8942): [Parent 8942, Unnamed thread 751c85432780] ###!!! ASSERTION: Failed NS_DispatchToMainThread() in shutdown; leaking: 'false', file /builds/worker/workspace/build/src/xpcom/threads/nsThreadUtils.cpp, line 243
[task 2019-11-25T14:40:12.792Z] 14:40:12 INFO - 11-25 14:40:00.291 I/Gecko ( 8942): [Parent 8942, Unnamed thread 751c85432780] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/workspace/build/src/xpcom/base/nsTraceRefcnt.cpp, line 198
[task 2019-11-25T14:40:12.792Z] 14:40:12 INFO - 11-25 14:40:00.291 I/Gecko ( 8942): [Parent 8942, Unnamed thread 751c85432780] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/workspace/build/src/xpcom/base/nsTraceRefcnt.cpp, line 198
[task 2019-11-25T14:40:12.792Z] 14:40:12 INFO - 11-25 14:40:00.291 W/GeckoEventDispatcher( 8942): No listener for GeckoView:FlushSessionState
[task 2019-11-25T14:40:12.792Z] 14:40:12 INFO - 11-25 14:40:00.293 D/EGL_emulation( 8942): eglMakeCurrent: 0x751c85049640: ver 2 0 (tinfo 0x751c8500c780)
[task 2019-11-25T14:40:12.792Z] 14:40:12 INFO - 11-25 14:40:00.305 I/Process ( 8942): Sending signal. PID: 8942 SIG: 9
[task 2019-11-25T14:40:12.792Z] 14:40:12 INFO - 11-25 14:40:00.349 D/skia ( 1696): --- SkAndroidCodec::NewFromStream returned null
[task 2019-11-25T14:40:12.792Z] 14:40:12 INFO - 11-25 14:40:00.379 D/GraphicsStats( 1617): Buffer count: 4
[task 2019-11-25T14:40:12.792Z] 14:40:12 INFO - 11-25 14:40:00.379 I/WindowManager( 1617): WIN DEATH: Window{9ebe633 u0 org.mozilla.geckoview.test/org.mozilla.geckoview.test.TestRunnerActivity}
[task 2019-11-25T14:40:12.792Z] 14:40:12 INFO - 11-25 14:40:00.379 W/WindowManager( 1617): Force-removing child win Window{3a4c4d9 u0 SurfaceView - org.mozilla.geckoview.test/org.mozilla.geckoview.test.TestRunnerActivity} from container Window{9ebe633 u0 org.mozilla.geckoview.test/org.mozilla.geckoview.test.TestRunnerActivity}
[task 2019-11-25T14:40:12.792Z] 14:40:12 INFO - 11-25 14:40:00.379 I/ActivityManager( 1617): Process org.mozilla.geckoview.test (pid 8942) has died
[task 2019-11-25T14:40:12.792Z] 14:40:12 INFO - 11-25 14:40:00.379 D/ActivityManager( 1617): cleanUpApplicationRecord -- 8942
[task 2019-11-25T14:40:12.792Z] 14:40:12 INFO - 11-25 14:40:00.379 I/WindowManager( 1617): Destroying surface Surface(name=SurfaceView - org.mozilla.geckoview.test/org.mozilla.geckoview.test.TestRunnerActivity) called by com.android.server.wm.WindowStateAnimator.destroySurface:2014 com.android.server.wm.WindowStateAnimator.destroySurfaceLocked:881 com.android.server.wm.WindowState.removeLocked:1449 com.android.server.wm.WindowManagerService.removeWindowInnerLocked:2478 com.android.server.wm.WindowManagerService.removeWindowInnerLocked:2457 com.android.server.wm.WindowManagerService.removeWindowLocked:2436 com.android.server.wm.WindowState$DeathRecipient.binderDied:1780 android.os.BinderProxy.sendDeathNotice:688
[task 2019-11-25T14:40:12.792Z] 14:40:12 INFO - 11-25 14:40:00.380 I/ServiceChildProcess( 9012): Service has been unbound. Stopping.
[task 2019-11-25T14:40:12.792Z] 14:40:12 INFO - 11-25 14:40:00.380 I/WindowManager( 1617): Destroying surface Surface(name=org.mozilla.geckoview.test/org.mozilla.geckoview.test.TestRunnerActivity) called by com.android.server.wm.WindowStateAnimator.destroySurface:2014 com.android.server.wm.WindowStateAnimator.destroySurfaceLocked:881 com.android.server.wm.WindowState.removeLocked:1449 com.android.server.wm.WindowManagerService.removeWindowInnerLocked:2478 com.android.server.wm.WindowManagerService.removeWindowLocked:2436 com.android.server.wm.WindowState$DeathRecipient.binderDied:1780 android.os.BinderProxy.sendDeathNotice:688 <bottom of call stack>
[task 2019-11-25T14:40:12.792Z] 14:40:12 INFO - 11-25 14:40:00.381 W/WindowManager( 1617): Failed looking up window
[task 2019-11-25T14:40:12.792Z] 14:40:12 INFO - 11-25 14:40:00.381 W/WindowManager( 1617): java.lang.IllegalArgumentException: Requested window android.os.BinderProxy@806bdf0 does not exist
[task 2019-11-25T14:40:12.792Z] 14:40:12 INFO - 11-25 14:40:00.381 W/WindowManager( 1617): at com.android.server.wm.WindowManagerService.windowForClientLocked(WindowManagerService.java:9100)
[task 2019-11-25T14:40:12.792Z] 14:40:12 INFO - 11-25 14:40:00.381 W/WindowManager( 1617): at com.android.server.wm.WindowManagerService.windowForClientLocked(WindowManagerService.java:9091)
[task 2019-11-25T14:40:12.793Z] 14:40:12 INFO - 11-25 14:40:00.381 W/WindowManager( 1617): at com.android.server.wm.WindowState$DeathRecipient.binderDied(WindowState.java:1777)
[task 2019-11-25T14:40:12.793Z] 14:40:12 INFO - 11-25 14:40:00.381 W/WindowManager( 1617): at android.os.BinderProxy.sendDeathNotice(Binder.java:688)
[task 2019-11-25T14:40:12.793Z] 14:40:12 INFO - 11-25 14:40:00.381 I/WindowManager( 1617): WIN DEATH: null
[task 2019-11-25T14:40:12.793Z] 14:40:12 INFO - 11-25 14:40:00.382 I/Process ( 9012): Sending signal. PID: 9012 SIG: 9
[task 2019-11-25T14:40:12.793Z] 14:40:12 INFO - 11-25 14:40:00.384 W/SurfaceFlinger( 1346): couldn't log to binary event log: overflow.
[task 2019-11-25T14:40:12.793Z] 14:40:12 INFO - 11-25 14:40:00.458 I/ActivityManager( 1617): Process org.mozilla.geckoview.test:tab (pid 9012) has died
[task 2019-11-25T14:40:12.794Z] 14:40:12 INFO - 11-25 14:40:00.458 D/ActivityManager( 1617): cleanUpApplicationRecord -- 9012
[task 2019-11-25T14:40:12.794Z] 14:40:12 INFO - 11-25 14:40:00.784 W/OpenGLRenderer( 2025): Incorrectly called buildLayer on View: ShortcutAndWidgetContainer, destroying layer...

Please re-open if this still happens.

Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → WONTFIX
Status: RESOLVED → REOPENED
Resolution: WONTFIX → ---
Status: REOPENED → RESOLVED
Closed: 4 years ago4 years ago
Resolution: --- → WONTFIX
Status: RESOLVED → REOPENED
Resolution: WONTFIX → ---

Bugbug thinks this bug should belong to this component, but please revert this change in case of error.

Component: General → Testing
Priority: -- → P3

(In reply to Intermittent Failures Robot from comment #10)

This failure was:

[task 2020-03-24T15:26:07.371Z] 15:26:07     INFO -  1811 ERROR /tests/dom/tests/mochitest/general/test_selectevents.html logged result after SimpleTest.finish(): The original target of selectionchange should be the document
...
[task 2020-03-24T15:26:17.728Z] 15:26:17     INFO -  1831 INFO Passed:  6238
[task 2020-03-24T15:26:17.729Z] 15:26:17  WARNING -  1832 INFO Failed:  1
[task 2020-03-24T15:26:17.729Z] 15:26:17  WARNING -  One or more unittests failed.
...
[task 2020-03-24T15:33:20.060Z] 15:33:20    ERROR - Return code: 1
[task 2020-03-24T15:33:20.061Z] 15:33:20     INFO - TinderboxPrint: mochitest-plain<br/>96224/<em class="testfail">1</em>/197
[task 2020-03-24T15:33:20.061Z] 15:33:20     INFO - ##### mochitest-plain log ends
[task 2020-03-24T15:33:20.061Z] 15:33:20  WARNING - # TBPL WARNING #
[task 2020-03-24T15:33:20.061Z] 15:33:20  WARNING - setting return code to 1

These failed tasks are not related to the bug title. "Requested window ... does not exist" is a relatively normal message issued by the Android WindowManager and sometimes found in the logcat.

Closing this bug in hopes that similar failures in future will be classified against a relevant bug title.

Assignee: nobody → gbrown
Status: REOPENED → RESOLVED
Closed: 4 years ago4 years ago
Resolution: --- → INVALID
Component: Testing → General
Product: Firefox for Android → Testing
Status: RESOLVED → REOPENED
Resolution: INVALID → ---

++(comment 11)

In this case the real error is:

[task 2020-07-27T21:37:21.352Z] 21:37:21     INFO -  486 INFO TEST-OK | dom/security/test/csp/test_sandbox.html | took 789ms
[task 2020-07-27T21:37:21.352Z] 21:37:21     INFO -  487 ERROR /tests/dom/security/test/csp/test_sandbox.html logged result after SimpleTest.finish(): documents sandboxed with allow-scripts should be able to run script from javascript: URLs
[task 2020-07-27T21:37:21.352Z] 21:37:21     INFO -  488 INFO TEST-START | dom/security/test/csp/test_sandbox_allow_scripts.html

:aryx -- Do you know what needs to change so that treeherder

  1. Recognizes these errors (should mochitest log "TEST-UNEXPECTED-FAIL" instead of "ERROR"?), and;
  2. Does not blame java.lang.IllegalArgumentException?
Flags: needinfo?(aryx.bugmail)
  1. ERROR keyword: Yes, Treeherder doesn't look for it, TEST-UNEXPECTED-FAIL would fit and be the standardized failure message.
  2. Ignoring Java exceptions: This will need modification of this regexp. Use case for exposing exceptions seem to be setup and tooling scripts.
Flags: needinfo?(aryx.bugmail)

Perfect - thanks!

Follow-up on part 1 of https://bugzilla.mozilla.org/show_bug.cgi?id=1599109#c16: preface
more mochitest error messages with TEST-UNEXPECTED-FAIL so that treeherder and especially
the log viewer will recognize the errors.

I'm not sure about following up on (2) from comment 16: I suppose some tasks may want to flag such exceptions. I would like to remove the logcat from test logs, but that idea has met with resistance in the past. Possibly just (1) will be good enough: the log viewer will usually find the appropriate error first and the android exception won't be noticed.

Pushed by gbrown@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/c338925bb4f3
Make a few more mochitest error messages visible to treeherder; r=jmaher
Status: REOPENED → RESOLVED
Closed: 4 years ago4 years ago
Resolution: --- → FIXED
Target Milestone: --- → 81 Branch
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: