1613597 - Perma tier2 toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | Test timed out.

Status: REOPENED

(WebExtensions :: General, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: cbrindusan [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=287696652&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/RtlpZzC0SO-OuxAAnzed-w/runs/0/artifacts/public/logs/live_backing.log

---

[task 2020-02-06T06:33:56.857Z] 06:33:56 INFO - TEST-START | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html
[task 2020-02-06T06:33:56.982Z] 06:33:56 INFO - GECKO(15162) | Console message: [JavaScript Warning: "The character encoding of a framed document was not declared. The document may appear different if viewed without the document framing it." {file: "http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/test_ext_activityLog.html" line: 0}]
[task 2020-02-06T06:33:57.271Z] 06:33:57 INFO - GECKO(15162) | 1580970837265 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: activityLog
[task 2020-02-06T06:33:57.272Z] 06:33:57 INFO - GECKO(15162) | Console message: 1580970837265 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: activityLog
[task 2020-02-06T06:33:58.203Z] 06:33:58 INFO - GECKO(15162) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-02-06T06:33:58.203Z] 06:33:58 INFO - GECKO(15162) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-02-06T06:33:58.509Z] 06:33:58 INFO - GECKO(15162) | [CodeCoverage] Setting handlers for process 15436.
[task 2020-02-06T06:33:58.707Z] 06:33:58 INFO - GECKO(15162) | [CodeCoverage] Requested flush for 15162.
[task 2020-02-06T06:33:58.944Z] 06:33:58 INFO - GECKO(15162) | [CodeCoverage] flush completed.
[task 2020-02-06T06:33:59.555Z] 06:33:59 INFO - GECKO(15162) | [CodeCoverage] JS flush completed.
[task 2020-02-06T06:33:59.555Z] 06:33:59 INFO - GECKO(15162) | [CodeCoverage] Requested flush for 15236.
[task 2020-02-06T06:33:59.555Z] 06:33:59 INFO - GECKO(15162) | [CodeCoverage] Requested flush for 15259.
[task 2020-02-06T06:33:59.555Z] 06:33:59 INFO - GECKO(15162) | [CodeCoverage] Requested flush for 15436.
[task 2020-02-06T06:33:59.812Z] 06:33:59 INFO - GECKO(15162) | [CodeCoverage] flush completed.
[task 2020-02-06T06:33:59.888Z] 06:33:59 INFO - GECKO(15162) | [CodeCoverage] JS flush completed.
[task 2020-02-06T06:34:00.138Z] 06:34:00 INFO - GECKO(15162) | [CodeCoverage] flush completed.
[task 2020-02-06T06:34:00.286Z] 06:34:00 INFO - GECKO(15162) | [CodeCoverage] JS flush completed.
[task 2020-02-06T06:34:00.536Z] 06:34:00 INFO - GECKO(15162) | [CodeCoverage] flush completed.
[task 2020-02-06T06:34:00.563Z] 06:34:00 INFO - GECKO(15162) | [CodeCoverage] JS flush completed.
[task 2020-02-06T06:34:00.571Z] 06:34:00 INFO - GECKO(15162) | JavaScript error: resource://testing-common/PerTestCoverageUtils.jsm, line 76: NS_ERROR_FILE_DIR_NOT_EMPTY: Component returned failure code: 0x80520014 (NS_ERROR_FILE_DIR_NOT_EMPTY) [nsIFile.moveTo]
[task 2020-02-06T06:39:21.509Z] 06:39:21 INFO - TEST-INFO | started process screentopng
[task 2020-02-06T06:39:21.672Z] 06:39:21 INFO - TEST-INFO | screentopng: exit 0
[task 2020-02-06T06:39:21.672Z] 06:39:21 INFO - Buffered messages logged at 06:33:56
[task 2020-02-06T06:39:21.672Z] 06:39:21 INFO - add_task | Entering test test_api
[task 2020-02-06T06:39:21.672Z] 06:39:21 INFO - Extension loaded
[task 2020-02-06T06:39:21.672Z] 06:39:21 INFO - Buffered messages logged at 06:33:57
[task 2020-02-06T06:39:21.674Z] 06:39:21 INFO - Extension loaded
[task 2020-02-06T06:39:21.674Z] 06:39:21 INFO - Extension loaded
[task 2020-02-06T06:39:21.674Z] 06:39:21 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | activityLog is privileged
[task 2020-02-06T06:39:21.674Z] 06:39:21 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | runtest
[task 2020-02-06T06:39:21.675Z] 06:39:21 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | activityLog requires permission - Expected: undefined, Actual: undefined
[task 2020-02-06T06:39:21.675Z] 06:39:21 INFO - onExtensionActivity {"id":"[e-mail]","viewType":"background","timeStamp":"2020-02-06T06:33:57.369Z","type":"api_call","name":"test.assertTrue","data":{"args":[true,"runtest"]}}
[task 2020-02-06T06:39:21.675Z] 06:39:21 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | type matches - Expected: api_call, Actual: api_call
[task 2020-02-06T06:39:21.677Z] 06:39:21 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | name matches - Expected: test.assertTrue, Actual: test.assertTrue [task 2020-02-06T06:39:21.677Z] 06:39:21 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | message matches - Expected: {"args":[true,"runtest"]}, Actual: {"args":[true,"runtest"]}
[task 2020-02-06T06:39:21.677Z] 06:39:21 INFO - onExtensionActivity {"id":"[e-mail]","viewType":"background","timeStamp":"2020-02-06T06:33:57.371Z","type":"api_call","name":"test.assertEq","data":{"args":[null,null,"activityLog requires permission"]}}
[task 2020-02-06T06:39:21.678Z] 06:39:21 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | type matches - Expected: api_call, Actual: api_call
[task 2020-02-06T06:39:21.678Z] 06:39:21 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | name matches - Expected: test.assertEq, Actual: test.assertEq
[task 2020-02-06T06:39:21.679Z] 06:39:21 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | message matches - Expected: {"args":[null,null,"activityLog requires permission"]}, Actual: {"args":[null,null,"activityLog requires permission"]}
[task 2020-02-06T06:39:21.679Z] 06:39:21 INFO - onExtensionActivity {"id":"[e-mail]","viewType":"background","timeStamp":"2020-02-06T06:33:57.373Z","type":"api_call","name":"test.onMessage.addListener","data":{"args":[]}}
[task 2020-02-06T06:39:21.680Z] 06:39:21 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | type matches - Expected: api_call, Actual: api_call
[task 2020-02-06T06:39:21.680Z] 06:39:21 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | name matches - Expected: test.onMessage.addListener, Actual: test.onMessage.addListener
[task 2020-02-06T06:39:21.681Z] 06:39:21 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | message matches - Expected: {"args":[]}, Actual: {"args":[]}
[task 2020-02-06T06:39:21.682Z] 06:39:21 INFO - onExtensionActivity {"id":"[e-mail]","viewType":"background","timeStamp":"2020-02-06T06:33:57.388Z","type":"api_call","name":"webRequest.onBeforeRequest.addListener","data":{"args":[{"incognito":null,"tabId":null,"types":null,"urls":["http://mochi.test//file_sample.html"],"windowId":null},["blocking"]]}}
[task 2020-02-06T06:39:21.682Z] 06:39:21 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | type matches - Expected: api_call, Actual: api_call
[task 2020-02-06T06:39:21.682Z] 06:39:21 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | name matches - Expected: webRequest.onBeforeRequest.addListener, Actual: webRequest.onBeforeRequest.addListener
[task 2020-02-06T06:39:21.684Z] 06:39:21 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | message matches - Expected: {"args":[{"incognito":null,"tabId":null,"types":null,"urls":["http://mochi.test//file_sample.html"],"windowId":null},["blocking"]]}, Actual: {"args":[{"incognito":null,"tabId":null,"types":null,"urls":["http://mochi.test//file_sample.html"],"windowId":null},["blocking"]]}
[task 2020-02-06T06:39:21.684Z] 06:39:21 INFO - onExtensionActivity {"id":"[e-mail]","viewType":"background","timeStamp":"2020-02-06T06:33:57.386Z","type":"api_call","name":"contentScripts.register","data":{"args":[{"allFrames":null,"css":null,"excludeGlobs":null,"excludeMatches":null,"includeGlobs":null,"js":[{"file":"moz-extension://20744ecc-464d-4a97-8e42-a5fa868c4147/registered_script.js"}],"matchAboutBlank":null,"matches":["http://mochi.test//file_sample.html"],"runAt":"document_start"}]}}
[task 2020-02-06T06:39:21.684Z] 06:39:21 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | type matches - Expected: api_call, Actual: api_call
[task 2020-02-06T06:39:21.685Z] 06:39:21 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | name matches - Expected: contentScripts.register, Actual: contentScripts.register
[task 2020-02-06T06:39:21.686Z] 06:39:21 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | message matches - Expected: {"args":[{"allFrames":null,"css":null,"excludeGlobs":null,"excludeMatches":null,"includeGlobs":null,"js":[{"file":"moz-extension://20744ecc-464d-4a97-8e42-a5fa868c4147/registered_script.js"}],"matchAboutBlank":null,"matches":["http://mochi.test//file_sample.html"],"runAt":"document_start"}]}, Actual: {"args":[{"allFrames":null,"css":null,"excludeGlobs":null,"excludeMatches":null,"includeGlobs":null,"js":[{"file":"moz-extension://20744ecc-464d-4a97-8e42-a5fa868c4147/registered_script.js"}],"matchAboutBlank":null,"matches":["http://mochi.test//file_sample.html"],"runAt":"document_start"}]}
[task 2020-02-06T06:39:21.686Z] 06:39:21 INFO - onExtensionActivity {"id":"[e-mail]","viewType":"background","timeStamp":"2020-02-06T06:33:57.387Z","type":"api_event","name":"test.onMessage","data":{"args":["runtest"]}}
[task 2020-02-06T06:39:21.687Z] 06:39:21 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | type matches - Expected: api_event, Actual: api_event
[task 2020-02-06T06:39:21.688Z] 06:39:21 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | name matches - Expected: test.onMessage, Actual: test.onMessage
[task 2020-02-06T06:39:21.688Z] 06:39:21 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | message matches - Expected: {"args":["runtest"]}, Actual: {"args":["runtest"]}
[task 2020-02-06T06:39:21.688Z] 06:39:21 INFO - onExtensionActivity {"id":"[e-mail]","viewType":"background","timeStamp":"2020-02-06T06:33:57.425Z","type":"api_call","name":"test.sendMessage","data":{"args":["ready"]}}
[task 2020-02-06T06:39:21.688Z] 06:39:21 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | type matches - Expected: api_call, Actual: api_call
[task 2020-02-06T06:39:21.690Z] 06:39:21 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | name matches - Expected: test.sendMessage, Actual: test.sendMessage
[task 2020-02-06T06:39:21.690Z] 06:39:21 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | message matches - Expected: {"args":["ready"]}, Actual: {"args":["ready"]}
[task 2020-02-06T06:39:21.690Z] 06:39:21 INFO - onExtensionActivity {"id":"[e-mail]","viewType":"background","timeStamp":"2020-02-06T06:33:57.720Z","type":"api_event","name":"webRequest.onBeforeRequest","data":{"args":[{"requestId":"33","url":"http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/file_sample.html","originUrl":"moz-extension://ccd2112c-69a5-489d-b423-848109079364/","method":"GET","type":"main_frame","timeStamp":1580970837711,"frameId":0,"parentFrameId":-1,"thirdParty":false,"proxyInfo":{"connectionIsolationKey":"","failoverTimeout":1800,"host":"127.0.0.1","port":8888,"proxyAuthorizationHeader":"","proxyDNS":false,"type":"http","username":""},"ip":null,"frameAncestors":[],"urlClassification":{"firstParty":[],"thirdParty":[]},"requestSize":0,"responseSize":0,"tabId":3,"incognito":false}],"result":{"cancel":false}}}
[task 2020-02-06T06:39:21.691Z] 06:39:21 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | type matches - Expected: api_event, Actual: api_event
[task 2020-02-06T06:39:21.692Z] 06:39:21 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | name matches - Expected: webRequest.onBeforeRequest, Actual: webRequest.onBeforeRequest
[task 2020-02-06T06:39:21.692Z] 06:39:21 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | message matches - Expected: {"args":[{"url":"http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/file_sample.html","method":"GET","type":"main_frame","frameId":0,"parentFrameId":-1,"thirdParty":false,"ip":null,"frameAncestors":[],"urlClassification":{"firstParty":[],"thirdParty":[]},"requestSize":0,"responseSize":0,"incognito":false}],"result":{"cancel":false}}, Actual: {"args":[{"url":"http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/file_sample.html","method":"GET","type":"main_frame","frameId":0,"parentFrameId":-1,"thirdParty":false,"ip":null,"frameAncestors":[],"urlClassification":{"firstParty":[],"thirdParty":[]},"requestSize":0,"responseSize":0,"incognito":false}],"result":{"cancel":false}}
[task 2020-02-06T06:39:21.693Z] 06:39:21 INFO - onExtensionActivity {"id":"[e-mail]","timeStamp":"2020-02-06T06:33:57.772Z","type":"content_script","name":"moz-extension://20744ecc-464d-4a97-8e42-a5fa868c4147/content_script.js","data":{"url":"http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/file_sample.html","tabId":3}}
[task 2020-02-06T06:39:21.694Z] 06:39:21 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | type matches - Expected: content_script, Actual: content_script
[task 2020-02-06T06:39:21.694Z] 06:39:21 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | content script name matches
[task 2020-02-06T06:39:21.694Z] 06:39:21 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | message matches - Expected: {"url":"http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/file_sample.html","tabId":3}, Actual: {"url":"http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/file_sample.html","tabId":3}
[task 2020-02-06T06:39:21.695Z] 06:39:21 INFO - onExtensionActivity {"id":"[e-mail]","timeStamp":"2020-02-06T06:33:57.774Z","type":"content_script","name":"moz-extension://20744ecc-464d-4a97-8e42-a5fa868c4147/registered_script.js","data":{"url":"http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/file_sample.html","tabId":3}}
[task 2020-02-06T06:39:21.696Z] 06:39:21 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | type matches - Expected: content_script, Actual: content_script
[task 2020-02-06T06:39:21.696Z] 06:39:21 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | content script name matches [task 2020-02-06T06:39:21.696Z] 06:39:21 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | message matches - Expected: {"url":"http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/file_sample.html","tabId":3}, Actual: {"url":"http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/file_sample.html","tabId":3}
[task 2020-02-06T06:39:21.697Z] 06:39:21 INFO - onExtensionActivity {"id":"[e-mail]","timeStamp":"2020-02-06T06:33:57.822Z","type":"api_call","name":"test.sendMessage","data":{"args":["registered_script"],"tabId":3}}
[task 2020-02-06T06:39:21.698Z] 06:39:21 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | type matches - Expected: api_call, Actual: api_call
[task 2020-02-06T06:39:21.698Z] 06:39:21 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | name matches - Expected: test.sendMessage, Actual: test.sendMessage
[task 2020-02-06T06:39:21.698Z] 06:39:21 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | message matches - Expected: {"args":["registered_script"],"tabId":3}, Actual: {"args":["registered_script"],"tabId":3}
[task 2020-02-06T06:39:21.698Z] 06:39:21 INFO - onExtensionActivity {"id":"[e-mail]","timeStamp":"2020-02-06T06:33:57.876Z","type":"api_call","name":"test.sendMessage","data":{"args":["content_script"],"tabId":3}}
[task 2020-02-06T06:39:21.699Z] 06:39:21 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | type matches - Expected: api_call, Actual: api_call
[task 2020-02-06T06:39:21.700Z] 06:39:21 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | name matches - Expected: test.sendMessage, Actual: test.sendMessage
[task 2020-02-06T06:39:21.700Z] 06:39:21 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | message matches - Expected: {"args":["content_script"],"tabId":3}, Actual: {"args":["content_script"],"tabId":3}
[task 2020-02-06T06:39:21.700Z] 06:39:21 INFO - Buffered messages logged at 06:33:58
[task 2020-02-06T06:39:21.700Z] 06:39:21 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | activity
[task 2020-02-06T06:39:21.701Z] 06:39:21 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | test result correct
[task 2020-02-06T06:39:21.701Z] 06:39:21 INFO - add_task | Leaving test test_api
[task 2020-02-06T06:39:21.702Z] 06:39:21 INFO - Buffered messages finished
[task 2020-02-06T06:39:21.703Z] 06:39:21 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_activityLog.html | Test timed out.

Comment 1

[Intermittent Failures Robot]

6 failures in 3364 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 6

Platform breakdown:

• linux1804-64-ccov: 6

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1613597&startday=2020-02-03&endday=2020-02-09&tree=all

Comment 2

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Comment 3

[Cristian Brindusan [:cbrindusan]]

New occurrence:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=293453475&repo=mozilla-central&lineNumber=5105

Comment 4

[Intermittent Failures Robot]

6 failures in 4955 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 4
• try: 2

Platform breakdown:

• linux1804-64-ccov: 4
• linux1804-64-qr: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1613597&startday=2020-03-16&endday=2020-03-22&tree=all

Comment 5

[Intermittent Failures Robot]

5 failures in 4773 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 5

Platform breakdown:

• linux1804-64: 5

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1613597&startday=2020-03-23&endday=2020-03-29&tree=all

Comment 6

[Intermittent Failures Robot]

1 failures in 5582 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 1

Platform breakdown:

• linux1804-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1613597&startday=2020-04-20&endday=2020-04-26&tree=all