Closed Bug 1400808 Opened 7 years ago Closed 7 years ago

Intermittent testJavascriptBridge | java-exception java.util.concurrent.TimeoutException: com.android.internal.os.BinderInternal$GcWatcher.finalize() timed out after 10 seconds at com.android.internal.os.BinderInternal$GcWatcher.finalize(BinderInternal

Categories

(Firefox for Android Graveyard :: Testing, defect, P5)

Product:
Firefox for Android Graveyard
Component:
Testing
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED DUPLICATE of bug 1321464

People

(Reporter: intermittent-bug-filer, Assigned: gbrown)

Details

(Keywords: intermittent-failure) 

Filed by: archaeopteryx [at] coole-files.de

https://treeherder.mozilla.org/logviewer.html#?job_id=131694412&repo=autoland

https://queue.taskcluster.net/v1/task/QI6UegvSRNmizHwe4NapdQ/runs/0/artifacts/public/logs/live_backing.log

[task 2017-09-18T08:19:09.754Z] 08:19:09     INFO -  MochitestServer : launching [u'/builds/worker/workspace/build/hostutils/host-utils-50.0a1.en-US.linux-x86_64/xpcshell', '-g', '/builds/worker/workspace/build/hostutils/host-utils-50.0a1.en-US.linux-x86_64', '-v', '170', '-f', '/builds/worker/workspace/build/hostutils/host-utils-50.0a1.en-US.linux-x86_64/components/httpd.js', '-e', "const _PROFILE_PATH = '/tmp/tmpAMiDhL.mozrunner'; const _SERVER_PORT = '8854'; const _SERVER_ADDR = '10.0.2.2'; const _TEST_PREFIX = undefined; const _DISPLAY_RESULTS = false;", '-f', '/builds/worker/workspace/build/tests/mochitest/server.js']
[task 2017-09-18T08:19:09.754Z] 08:19:09     INFO -  runtests.py | Server pid: 1139
[task 2017-09-18T08:19:09.759Z] 08:19:09     INFO -  runtests.py | Websocket server pid: 1142
[task 2017-09-18T08:19:09.786Z] 08:19:09     INFO -  runtests.py | SSL tunnel pid: 1145
[task 2017-09-18T08:19:09.941Z] 08:19:09     INFO -  TEST-INFO | skipping src/org/mozilla/gecko/tests/testStumblerSetting.java | skip-if: android_version == "18"
[task 2017-09-18T08:19:09.942Z] 08:19:09     INFO -  SUITE-START | Running 14 tests
[task 2017-09-18T08:22:43.155Z] 08:22:43     INFO -  INFO | automation.py | Application pid: 0
[task 2017-09-18T08:22:43.595Z] 08:22:43     INFO -  SimpleTest START
[task 2017-09-18T08:22:43.595Z] 08:22:43     INFO -  TEST-START | testInputConnection
[task 2017-09-18T08:22:43.596Z] 08:22:43     INFO -  GECKO | EventExpecter: no longer listening for Gecko:Ready
[task 2017-09-18T08:22:43.597Z] 08:22:43     INFO -  GECKO | EventExpecter: no longer listening for Content:DOMContentLoaded
[task 2017-09-18T08:22:43.597Z] 08:22:43     INFO -  GECKO | EventExpecter: no longer listening for Content:DOMTitleChanged
[task 2017-09-18T08:22:43.662Z] 08:22:43     INFO -  GECKO | EventExpecter: no longer listening for Robocop:Java
[task 2017-09-18T08:22:43.663Z] 08:22:43     INFO -  TEST-OK | testInputConnection | took 203939ms
[task 2017-09-18T08:22:43.666Z] 08:22:43     INFO -  TEST-START | Shutdown
[task 2017-09-18T08:22:43.666Z] 08:22:43     INFO -  Passed: 1418
[task 2017-09-18T08:22:43.666Z] 08:22:43     INFO -  Failed: 0
[task 2017-09-18T08:22:43.666Z] 08:22:43     INFO -  Todo: 0
[task 2017-09-18T08:22:43.666Z] 08:22:43     INFO -  SimpleTest FINISHED
[task 2017-09-18T08:23:05.182Z] 08:23:05     INFO -  INFO | automation.py | Application ran for: 0:03:54.258182
[task 2017-09-18T08:23:05.183Z] 08:23:05     INFO -  INFO | zombiecheck | Reading PID log: /tmp/tmpcmoSvnpidlog
[task 2017-09-18T08:23:05.824Z] 08:23:05     INFO -  /data/tombstones does not exist; tombstone check skipped
[task 2017-09-18T08:24:27.795Z] 08:24:27     INFO -  INFO | automation.py | Application pid: 0
[task 2017-09-18T08:24:28.084Z] 08:24:28     INFO -  SimpleTest START
[task 2017-09-18T08:24:28.084Z] 08:24:28     INFO -  TEST-START | testJavascriptBridge
[task 2017-09-18T08:24:28.086Z] 08:24:28     INFO -  GECKO | EventExpecter: no longer listening for Content:DOMContentLoaded
[task 2017-09-18T08:24:28.086Z] 08:24:28     INFO -  GECKO | EventExpecter: no longer listening for Content:DOMTitleChanged
[task 2017-09-18T08:24:28.090Z] 08:24:28     INFO -  GECKO | EventExpecter: no longer listening for Robocop:Java
[task 2017-09-18T08:24:28.091Z] 08:24:28     INFO -  TEST-OK | testJavascriptBridge | took 64976ms
[task 2017-09-18T08:24:28.091Z] 08:24:28     INFO -  TEST-START | Shutdown
[task 2017-09-18T08:24:28.091Z] 08:24:28     INFO -  Passed: 51
[task 2017-09-18T08:24:28.091Z] 08:24:28     INFO -  Failed: 0
[task 2017-09-18T08:24:28.092Z] 08:24:28     INFO -  Todo: 0
[task 2017-09-18T08:24:28.092Z] 08:24:28     INFO -  SimpleTest FINISHED
[task 2017-09-18T08:24:49.315Z] 08:24:49     INFO -  INFO | automation.py | Application ran for: 0:01:41.074783
[task 2017-09-18T08:24:49.316Z] 08:24:49     INFO -  INFO | zombiecheck | Reading PID log: /tmp/tmpu2p65opidlog
[task 2017-09-18T08:24:51.210Z] 08:24:51  WARNING -  PROCESS-CRASH | testJavascriptBridge | java-exception java.util.concurrent.TimeoutException: com.android.internal.os.BinderInternal$GcWatcher.finalize() timed out after 10 seconds at com.android.internal.os.BinderInternal$GcWatcher.finalize(BinderInternal.java:47)
[task 2017-09-18T08:24:51.211Z] 08:24:51     INFO -  0 ERROR runApp() exited with code 1

[task 2017-09-18T08:24:52.279Z] 08:24:52     INFO -  09-18 01:24:14.888 D/Robocop ( 1030): handleMessage called for: Robocop:Java; expecting: Robocop:Java
[task 2017-09-18T08:24:52.280Z] 08:24:52     INFO -  09-18 01:24:14.888 D/Robocop ( 1030): unblocked on expecter for Robocop:Java
[task 2017-09-18T08:24:52.280Z] 08:24:52     INFO -  09-18 01:24:14.898 I/Robocop ( 1030): {"action":"log","message":"(xpcshell\/head.js) | exiting test","time":1505723054896,"pid":null,"level":"info","source":"robocop","thread":null}
[task 2017-09-18T08:24:52.281Z] 08:24:52     INFO -  09-18 01:24:14.908 I/Robocop ( 1030): {"message":"Robocop:Java should equal Robocop:Java","time":1505723054904,"source":"robocop","status":"PASS","test":"testJavascriptBridge","thread":null,"subtest":"Given message occurred for registered event: {method=check_js_sync_call, innerType=sync-reply, args={length=0}}","action":"test_status","pid":null}
[task 2017-09-18T08:24:52.281Z] 08:24:52     INFO -  09-18 01:24:14.908 D/Robocop ( 1030): received event Robocop:Java
[task 2017-09-18T08:24:52.282Z] 08:24:52     INFO -  09-18 01:24:14.908 D/Robocop ( 1030): unblocked on expecter for Robocop:Java
[task 2017-09-18T08:24:52.282Z] 08:24:52     INFO -  09-18 01:24:14.918 D/Robocop ( 1030): blockForEvent timeout: Robocop:Java
[task 2017-09-18T08:24:52.283Z] 08:24:52     INFO -  09-18 01:24:14.918 I/Robocop ( 1030): {"message":"","time":1505723054921,"source":"robocop","status":"PASS","test":"testJavascriptBridge","thread":null,"subtest":"Received sync call before end of test","action":"test_status","pid":null}
[task 2017-09-18T08:24:52.283Z] 08:24:52     INFO -  09-18 01:24:14.928 D/Robocop ( 1030): blockForEvent timeout: Robocop:Java
[task 2017-09-18T08:24:52.284Z] 08:24:52     INFO -  09-18 01:24:14.928 I/Robocop ( 1030): EventExpecter: no longer listening for Robocop:Java
[task 2017-09-18T08:24:52.284Z] 08:24:52     INFO -  09-18 01:24:14.928 I/Robocop ( 1030): {"message":"finished in 64975ms","time":1505723054935,"source":"robocop","status":"OK","test":"testJavascriptBridge","thread":null,"action":"test_end","pid":null}
[task 2017-09-18T08:24:52.285Z] 08:24:52     INFO -  09-18 01:24:14.948 I/Robocop ( 1030): {"action":"log","message":"TEST-START | Shutdown","time":1505723054940,"pid":null,"level":"info","source":"robocop","thread":null}
[task 2017-09-18T08:24:52.285Z] 08:24:52     INFO -  09-18 01:24:14.948 I/Robocop ( 1030): {"action":"log","message":"Passed: 51","time":1505723054950,"pid":null,"level":"info","source":"robocop","thread":null}
[task 2017-09-18T08:24:52.285Z] 08:24:52     INFO -  09-18 01:24:14.958 I/Robocop ( 1030): {"action":"log","message":"Failed: 0","time":1505723054963,"pid":null,"level":"info","source":"robocop","thread":null}
[task 2017-09-18T08:24:52.286Z] 08:24:52     INFO -  09-18 01:24:14.968 I/Robocop ( 1030): {"action":"log","message":"Todo: 0","time":1505723054967,"pid":null,"level":"info","source":"robocop","thread":null}
[task 2017-09-18T08:24:52.286Z] 08:24:52     INFO -  09-18 01:24:14.978 I/Robocop ( 1030): {"action":"log","message":"SimpleTest FINISHED","time":1505723054971,"pid":null,"level":"info","source":"robocop","thread":null}
[task 2017-09-18T08:24:52.287Z] 08:24:52     INFO -  09-18 01:24:14.978 I/BaseTest( 1030): Requesting force quit.
[task 2017-09-18T08:24:52.287Z] 08:24:52     INFO -  09-18 01:24:15.108 I/GeckoDump( 1030): Robocop:Quit received -- requesting quit
[task 2017-09-18T08:24:52.288Z] 08:24:52     INFO -  09-18 01:24:15.569 I/nsScreenManagerAndroid( 1030): nsWindow[0x61311eb0]::Show 0
[task 2017-09-18T08:24:52.288Z] 08:24:52     INFO -  09-18 01:24:15.738 D/GeckoNetworkManager( 1030): Incoming event disableNotifications for state OnWithListeners -> OnNoListeners
[task 2017-09-18T08:24:52.289Z] 08:24:52     INFO -  09-18 01:24:16.988 I/nsScreenManagerAndroid( 1030): nsWindow[0x62ed6bc0]::Show 0
[task 2017-09-18T08:24:52.289Z] 08:24:52     INFO -  09-18 01:24:16.988 I/nsScreenManagerAndroid( 1030): trying to show invisible window! ignoring..
[task 2017-09-18T08:24:52.290Z] 08:24:52     INFO -  09-18 01:24:20.198 E/GeckoConsole( 1030): [JavaScript Error: "1505723060182	Toolkit.Telemetry	ERROR	TelemetryEnvironment::EnvironmentCache - error while initializing: Error: Unable to fetch oldest profile entry: Error: OS.File has been shut down. Rejecting request to DirectoryIterator_prototype_next (resource://gre/modules/ProfileAge.jsm:176:13) JS Stack trace: onFailure@ProfileAge.jsm:176:13 < observe@AsyncShutdown.jsm:534:9" {file: "resource://gre/modules/Log.jsm" line: 752}]
[task 2017-09-18T08:24:52.290Z] 08:24:52     INFO -  09-18 01:24:20.198 E/GeckoConsole( 1030): App_append@resource://gre/modules/Log.jsm:752:9
[task 2017-09-18T08:24:52.291Z] 08:24:52     INFO -  09-18 01:24:20.198 E/GeckoConsole( 1030): log@resource://gre/modules/Log.jsm:390:7
[task 2017-09-18T08:24:52.291Z] 08:24:52     INFO -  09-18 01:24:20.198 E/GeckoConsole( 1030): getLoggerWithMessagePrefix/proxy.log@resource://gre/modules/Log.jsm:505:44
[task 2017-09-18T08:24:52.292Z] 08:24:52     INFO -  09-18 01:24:20.198 E/GeckoConsole( 1030): error@resource://gre/modules/Log.jsm:398:5
[task 2017-09-18T08:24:52.292Z] 08:24:52     INFO -  09-18 01:24:20.198 E/GeckoConsole( 1030): EnvironmentCache/this._initTask<@resource://gre/modules/TelemetryEnvironment.jsm:891:9
[task 2017-09-18T08:24:52.292Z] 08:24:52     INFO -  09-18 01:24:20.198 E/GeckoConsole( 1030): observe@resource://gre/modules/AsyncShutdown.jsm:534:9
[task 2017-09-18T08:24:52.293Z] 08:24:52     INFO -  09-18 01:24:20.609 E/GeckoConsole( 1030): [JavaScript Error: "Error: OS.File has been shut down. Rejecting post to DirectoryIterator_prototype_close" {file: "resource://gre/modules/osfile/osfile_async_front.jsm" line: 410}]
[task 2017-09-18T08:24:52.293Z] 08:24:52     INFO -  09-18 01:24:21.078 E/GeckoCrashHandler( 1030): >>> REPORTING UNCAUGHT EXCEPTION FROM THREAD 54 ("FinalizerWatchdogDaemon")
[task 2017-09-18T08:24:52.293Z] 08:24:52     INFO -  09-18 01:24:21.078 E/GeckoCrashHandler( 1030): java.util.concurrent.TimeoutException: com.android.internal.os.BinderInternal$GcWatcher.finalize() timed out after 10 seconds
[task 2017-09-18T08:24:52.293Z] 08:24:52     INFO -  09-18 01:24:21.078 E/GeckoCrashHandler( 1030): 	at com.android.internal.os.BinderInternal$GcWatcher.finalize(BinderInternal.java:47)
[task 2017-09-18T08:24:52.294Z] 08:24:52     INFO -  09-18 01:24:21.078 E/GeckoCrashHandler( 1030): 	at java.lang.Daemons$FinalizerDaemon.doFinalize(Daemons.java:187)
[task 2017-09-18T08:24:52.294Z] 08:24:52     INFO -  09-18 01:24:21.078 E/GeckoCrashHandler( 1030): 	at java.lang.Daemons$FinalizerDaemon.run(Daemons.java:170)
[task 2017-09-18T08:24:52.294Z] 08:24:52     INFO -  09-18 01:24:21.078 E/GeckoCrashHandler( 1030): 	at java.lang.Thread.run(Thread.java:841)
[task 2017-09-18T08:24:52.295Z] 08:24:52     INFO -  09-18 01:24:21.078 E/GeckoCrashHandler( 1030): Main thread (1) stack:
[task 2017-09-18T08:24:52.295Z] 08:24:52     INFO -  09-18 01:24:21.078 E/GeckoCrashHandler( 1030):     android.os.MessageQueue.nativePollOnce(Native Method)
[task 2017-09-18T08:24:52.295Z] 08:24:52     INFO -  09-18 01:24:21.088 E/GeckoCrashHandler( 1030):     android.os.MessageQueue.next(MessageQueue.java:132)
[task 2017-09-18T08:24:52.296Z] 08:24:52     INFO -  09-18 01:24:21.088 E/GeckoCrashHandler( 1030):     android.os.Looper.loop(Looper.java:124)
[task 2017-09-18T08:24:52.296Z] 08:24:52     INFO -  09-18 01:24:21.088 E/GeckoCrashHandler( 1030):     android.app.ActivityThread.main(ActivityThread.java:5103)
[task 2017-09-18T08:24:52.296Z] 08:24:52     INFO -  09-18 01:24:21.088 E/GeckoCrashHandler( 1030):     java.lang.reflect.Method.invokeNative(Native Method)
[task 2017-09-18T08:24:52.297Z] 08:24:52     INFO -  09-18 01:24:21.088 E/GeckoCrashHandler( 1030):     java.lang.reflect.Method.invoke(Method.java:525)
[task 2017-09-18T08:24:52.297Z] 08:24:52     INFO -  09-18 01:24:21.088 E/GeckoCrashHandler( 1030):     com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:737)
[task 2017-09-18T08:24:52.298Z] 08:24:52     INFO -  09-18 01:24:21.088 E/GeckoCrashHandler( 1030):     com.android.internal.os.ZygoteInit.main(ZygoteInit.java:553)
[task 2017-09-18T08:24:52.298Z] 08:24:52     INFO -  09-18 01:24:21.098 E/GeckoCrashHandler( 1030):     dalvik.system.NativeStart.main(Native Method)
Assignee: nobody → gbrown
Status: NEW → RESOLVED
Closed: 7 years ago
Resolution: --- → DUPLICATE
Product: Firefox for Android → Firefox for Android Graveyard
You need to log in before you can comment on or make changes to this bug.