Treeherder Bug Filer Reporter
	Description • 6 years ago
treeherder

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

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

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

[task 2018-08-13T23:24:11.040Z] 23:24:11     INFO -  08-13 16:24:09.769 D/Robocop ( 1388): unblocked on expecter for Robocop:Java
[task 2018-08-13T23:24:11.040Z] 23:24:11     INFO -  08-13 16:24:09.779 I/Robocop ( 1388): {"message":"[filepicker_save : 67] Android does not support FilePicker.modeSave","time":1534202649774,"source":"robocop","status":"PASS","test":"testFilePicker","thread":null,"subtest":"testFilePicker.js","action":"test_status","pid":null}
[task 2018-08-13T23:24:11.040Z] 23:24:11     INFO -  08-13 16:24:09.799 D/GeckoToolbar( 1388): onTabChanged: PAGE_SHOW
[task 2018-08-13T23:24:11.041Z] 23:24:11     INFO -  08-13 16:24:09.799 D/GeckoBrowserApp( 1388): BrowserApp.onTabChanged: 0: PAGE_SHOW
[task 2018-08-13T23:24:11.041Z] 23:24:11     INFO -  08-13 16:24:09.829 I/GeckoTabs( 1388): zerdatime 591724 - page load stop
[task 2018-08-13T23:24:11.041Z] 23:24:11     INFO -  08-13 16:24:09.829 D/GeckoToolbar( 1388): onTabChanged: STOP
[task 2018-08-13T23:24:11.042Z] 23:24:11     INFO -  08-13 16:24:09.859 D/Robocop ( 1388): handleMessage called for: Robocop:Java; expecting: Robocop:Java
[task 2018-08-13T23:24:11.042Z] 23:24:11     INFO -  08-13 16:24:09.909 D/GeckoBrowserApp( 1388): BrowserApp.onTabChanged: 0: STOP
[task 2018-08-13T23:24:11.042Z] 23:24:11     INFO -  08-13 16:24:09.919 I/Robocop ( 1388): {"message":"Robocop:Java should equal Robocop:Java","time":1534202649869,"source":"robocop","status":"PASS","test":"testFilePicker","thread":null,"subtest":"Given message occurred for registered event: {innerType=progress, type=Robocop:Java, message=\nTEST-INFO | (xpcshell\/head.js) | test 3 pending\n}","action":"test_status","pid":null}
[task 2018-08-13T23:24:11.043Z] 23:24:11     INFO -  08-13 16:24:09.919 D/Robocop ( 1388): received event Robocop:Java
[task 2018-08-13T23:24:11.043Z] 23:24:11     INFO -  08-13 16:24:09.919 D/Robocop ( 1388): unblocked on expecter for Robocop:Java
[task 2018-08-13T23:24:11.043Z] 23:24:11     INFO -  08-13 16:24:09.939 I/Robocop ( 1388): {"action":"log","message":"(xpcshell\/head.js) | test 3 pending","time":1534202649937,"pid":null,"level":"info","source":"robocop","thread":null}
[task 2018-08-13T23:24:11.044Z] 23:24:11     INFO -  08-13 16:24:09.939 I/Choreographer( 1388): Skipped 86 frames!  The application may be doing too much work on its main thread.
[task 2018-08-13T23:24:11.044Z] 23:24:11     INFO -  08-13 16:24:09.969 D/Robocop ( 1388): handleMessage called for: Robocop:Java; expecting: Robocop:Java
[task 2018-08-13T23:24:11.045Z] 23:24:11     INFO -  08-13 16:24:10.009 I/Robocop ( 1388): {"message":"Robocop:Java should equal Robocop:Java","time":1534202649977,"source":"robocop","status":"PASS","test":"testFilePicker","thread":null,"subtest":"Given message occurred for registered event: {innerType=progress, type=Robocop:Java, message=\nTEST-INFO | (xpcshell\/head.js) | test 3 finished\n}","action":"test_status","pid":null}
[task 2018-08-13T23:24:11.045Z] 23:24:11     INFO -  08-13 16:24:10.029 D/Robocop ( 1388): received event Robocop:Java
[task 2018-08-13T23:24:11.045Z] 23:24:11     INFO -  08-13 16:24:10.039 D/Robocop ( 1388): unblocked on expecter for Robocop:Java
[task 2018-08-13T23:24:11.046Z] 23:24:11     INFO -  08-13 16:24:10.059 I/Robocop ( 1388): {"action":"log","message":"(xpcshell\/head.js) | test 3 finished","time":1534202650044,"pid":null,"level":"info","source":"robocop","thread":null}
[task 2018-08-13T23:24:11.046Z] 23:24:11     INFO -  08-13 16:24:10.079 D/Robocop ( 1388): handleMessage called for: Robocop:Java; expecting: Robocop:Java
[task 2018-08-13T23:24:11.047Z] 23:24:11     INFO -  08-13 16:24:10.179 I/Robocop ( 1388): {"message":"Robocop:Java should equal Robocop:Java","time":1534202650089,"source":"robocop","status":"PASS","test":"testFilePicker","thread":null,"subtest":"Given message occurred for registered event: {innerType=progress, type=Robocop:Java, message=\nTEST-INFO | (xpcshell\/head.js) | test 2 finished\n}","action":"test_status","pid":null}
[task 2018-08-13T23:24:11.047Z] 23:24:11     INFO -  08-13 16:24:10.179 D/Robocop ( 1388): received event Robocop:Java
[task 2018-08-13T23:24:11.047Z] 23:24:11     INFO -  08-13 16:24:10.189 D/Robocop ( 1388): unblocked on expecter for Robocop:Java
[task 2018-08-13T23:24:11.048Z] 23:24:11     INFO -  08-13 16:24:10.209 I/Robocop ( 1388): {"action":"log","message":"(xpcshell\/head.js) | test 2 finished","time":1534202650192,"pid":null,"level":"info","source":"robocop","thread":null}
[task 2018-08-13T23:24:11.048Z] 23:24:11     INFO -  08-13 16:24:10.269 W/GeckoEventDispatcher( 1388): No listener for Session:DataWritten

	Geoff Brown [:gbrown] Assignee
	Comment 1 • 6 years ago

[task 2018-08-13T23:24:11.009Z] 23:24:11     INFO -  08-13 16:24:05.899 I/ActivityManager(  277): START u0 {act=android.intent.action.CHOOSER cmp=android/com.android.internal.app.ChooserActivity (has extras)} from pid 1388

I suppose testFilePicker ultimately starts a ChooserActivity to select the file. The problem here is that if ChooserActivity is ever in the foreground (actually, if fennec is ever *not* in the foreground) when the harness checks foreground activity, the test will end prematurely, causing this failure.

I do not think it is possible to run this test reliably, unless we somehow change our definition of when a browser test ends.

	Ryan VanderMeulen [:RyanVM]
	Comment 3 • 6 years ago

This is permafailing on Beta since the Gecko 63 uplift.

	Andreea Pavel [:apavel]
	Comment 4 • 6 years ago

(In reply to Ryan VanderMeulen [:RyanVM] from comment #3)
> This is permafailing on Beta since the Gecko 63 uplift.

Looking into this, it appears it started to perma-fail with Bug 1484496:

https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&filter-resultStatus=testfailed&filter-resultStatus=busted&filter-resultStatus=exception&filter-resultStatus=success&filter-resultStatus=pending&filter-resultStatus=running&fromchange=4017bcbb799df8fc3cb8202969a1c85e5dc1cf94&group_state=expanded&filter-searchStr=rc3&selectedJob=195843291

Kris pushed a fix for it: https://hg.mozilla.org/integration/mozilla-inbound/rev/e2e9f54416db3366258a526d9c2e439fc2ee0393

Waiting to see the results.

	Andreea Pavel [:apavel]
	Comment 5 • 6 years ago

Update: job on the fix is green: https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&revision=e2e9f54416db3366258a526d9c2e439fc2ee0393&filter-resultStatus=testfailed&filter-resultStatus=busted&filter-resultStatus=exception&filter-resultStatus=success&filter-classifiedState=unclassified&filter-searchStr=rc3&selectedJob=195876048