1619753 - Intermittent TEST-UNEXPECTED-TIMEOUT | browser/components/extensions/test/browser/browser_ext_browserAction_telemetry.js | application timed out after 370 seconds with no output

Status: RESOLVED INCOMPLETE

(WebExtensions :: Untriaged, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: apavel [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=291458347&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/RvY7iU1RT8meP_D1-bRmlQ/runs/0/artifacts/public/logs/live_backing.log

---

[task 2020-03-03T16:30:22.826Z] 16:30:22 INFO - TEST-START | browser/components/extensions/test/browser/browser_ext_browserAction_telemetry.js
[task 2020-03-03T16:36:33.028Z] 16:36:33 INFO - Buffered messages logged at 16:30:22
[task 2020-03-03T16:36:33.029Z] 16:36:33 INFO - Entering test bound testBrowserActionTelemetryTiming
[task 2020-03-03T16:36:33.030Z] 16:36:33 INFO - Extension loaded
[task 2020-03-03T16:36:33.030Z] 16:36:33 INFO - Extension loaded
[task 2020-03-03T16:36:33.031Z] 16:36:33 INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_browserAction_telemetry.js | No data recorded for histogram: WEBEXT_BROWSERACTION_POPUP_OPEN_MS. -
[task 2020-03-03T16:36:33.032Z] 16:36:33 INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_browserAction_telemetry.js | No data recorded for histogram: WEBEXT_BROWSERACTION_POPUP_OPEN_MS_BY_ADDONID. -
[task 2020-03-03T16:36:33.032Z] 16:36:33 INFO - Console message: Warning: attempting to write 4339 bytes to preference extensions.webextensions.uuids. This is bad for general performance and memory usage. Such an amount of data should rather be written to an external file. This preference will not be sent to any content processes.
[task 2020-03-03T16:36:33.032Z] 16:36:33 INFO - Console message: Warning: attempting to write 4397 bytes to preference extensions.webextensions.uuids. This is bad for general performance and memory usage. Such an amount of data should rather be written to an external file. This preference will not be sent to any content processes.
[task 2020-03-03T16:36:33.033Z] 16:36:33 INFO - Console message: Warning: attempting to write 4805 bytes to preference browser.uiCustomization.state. This is bad for general performance and memory usage. Such an amount of data should rather be written to an external file. This preference will not be sent to any content processes.
[task 2020-03-03T16:36:33.033Z] 16:36:33 INFO - Buffered messages logged at 16:30:23
[task 2020-03-03T16:36:33.033Z] 16:36:33 INFO - Console message: Warning: attempting to write 4873 bytes to preference browser.uiCustomization.state. This is bad for general performance and memory usage. Such an amount of data should rather be written to an external file. This preference will not be sent to any content processes.
[task 2020-03-03T16:36:33.033Z] 16:36:33 INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_browserAction_telemetry.js | No data recorded for histogram after startup: WEBEXT_BROWSERACTION_POPUP_OPEN_MS. -
[task 2020-03-03T16:36:33.033Z] 16:36:33 INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_browserAction_telemetry.js | No data recorded for histogram after startup: WEBEXT_BROWSERACTION_POPUP_OPEN_MS_BY_ADDONID. -
[task 2020-03-03T16:36:33.033Z] 16:36:33 INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_browserAction_telemetry.js | Expect widget not to be overflowed -
[task 2020-03-03T16:36:33.033Z] 16:36:33 INFO - Buffered messages finished
[task 2020-03-03T16:36:33.033Z] 16:36:33 ERROR - TEST-UNEXPECTED-TIMEOUT | browser/components/extensions/test/browser/browser_ext_browserAction_telemetry.js | application timed out after 370 seconds with no output
[task 2020-03-03T16:36:33.034Z] 16:36:33 ERROR - Force-terminating active process(es).
[task 2020-03-03T16:36:33.034Z] 16:36:33 INFO - Determining child pids from psutil...
[task 2020-03-03T16:36:33.036Z] 16:36:33 INFO - [2948]
[task 2020-03-03T16:36:33.036Z] 16:36:33 INFO - ==> process 2948 launched child process 7536 ("Z:\task_1583251856\build\application\firefox\firefox.exe" -contentproc --channel="2948.0.1608719956\778176162" -parentBuildID 20200303144615 -prefsHandle 2280 -prefMapHandle 2268 -prefsLen 1 -prefMapSize 229777 -appdir "Z:\task_1583251856\build\application\firefox\browser" - 2948 gpu)
[task 2020-03-03T16:36:33.037Z] 16:36:33 INFO - ==> process 2948 launched child process 6980 ("Z:\task_1583251856\build\application\firefox\firefox.exe" -contentproc --channel="2948.6.403909500\1731371763" -childID 1 -isForBrowser -prefsHandle 2460 -prefMapHandle 2892 -prefsLen 1391 -prefMapSize 229777 -parentBuildID 20200303144615 -appdir "Z:\task_1583251856\build\application\firefox\browser" - 2948 tab)
[task 2020-03-03T16:36:33.037Z] 16:36:33 INFO - ==> process 2948 launched child process 2984 ("Z:\task_1583251856\build\application\firefox\firefox.exe" -contentproc --channel="2948.13.1006395534\756882811" -childID 2 -isForBrowser -prefsHandle 3096 -prefMapHandle 2892 -prefsLen 1488 -prefMapSize 229777 -parentBuildID 20200303144615 -appdir "Z:\task_1583251856\build\application\firefox\browser" - 2948 tab)
[task 2020-03-03T16:36:33.038Z] 16:36:33 INFO - ==> process 2948 launched child process 7664 ("Z:\task_1583251856\build\application\firefox\firefox.exe" -contentproc --channel="2948.20.1924273468\1141163012" -childID 3 -isForBrowser -prefsHandle 4896 -prefMapHandle 4892 -prefsLen 1549 -prefMapSize 229777 -parentBuildID 20200303144615 -appdir "Z:\task_1583251856\build\application\firefox\browser" - 2948 tab)
[task 2020-03-03T16:36:33.038Z] 16:36:33 INFO - ==> process 2948 launched child process 8108 ("Z:\task_1583251856\build\application\firefox\firefox.exe" -contentproc --channel="2948.27.562598732\1422447954" -childID 4 -isForBrowser -prefsHandle 4544 -prefMapHandle 4520 -prefsLen 11378 -prefMapSize 229777 -parentBuildID 20200303144615 -appdir "Z:\task_1583251856\build\application\firefox\browser" - 2948 tab)
[task 2020-03-03T16:36:33.039Z] 16:36:33 INFO - ==> process 2948 launched child process 7108 ("Z:\task_1583251856\build\application\firefox\firefox.exe" -contentproc --channel="2948.34.611138680\1004619411" -childID 5 -isForBrowser -prefsHandle 3312 -prefMapHandle 4524 -prefsLen 11379 -prefMapSize 229777 -parentBuildID 20200303144615 -appdir "Z:\task_1583251856\build\application\firefox\browser" - 2948 tab)
[task 2020-03-03T16:36:33.039Z] 16:36:33 INFO - Found child pids: set([7664, 6980, 2984, 8108, 7536, 2948, 7108])
[task 2020-03-03T16:36:33.039Z] 16:36:33 INFO - Killing process: 7664
[task 2020-03-03T16:36:33.039Z] 16:36:33 INFO - TEST-INFO | started process screenshot
[task 2020-03-03T16:36:33.281Z] 16:36:33 INFO - TEST-INFO | screenshot: exit 0
[task 2020-03-03T16:36:33.281Z] 16:36:33 INFO - Can't trigger Breakpad, just killing process
[task 2020-03-03T16:36:33.387Z] 16:36:33 INFO - psutil found pid 7664 dead
[task 2020-03-03T16:36:33.387Z] 16:36:33 INFO - Killing process: 6980
[task 2020-03-03T16:36:33.387Z] 16:36:33 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-03-03T16:36:33.387Z] 16:36:33 INFO - Can't trigger Breakpad, just killing process
[task 2020-03-03T16:36:33.486Z] 16:36:33 INFO - psutil found pid 6980 dead
[task 2020-03-03T16:36:33.486Z] 16:36:33 INFO - Killing process: 2984
[task 2020-03-03T16:36:33.486Z] 16:36:33 INFO - Not taking screenshot here: see the one that was previously logged

Comment 1

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

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

Comment 2

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform breakdown:

• windows10-64: 1

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

Comment 3

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform breakdown:

• windows10-64: 1

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

Comment 4

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

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

Comment 5

[Andreea Pavel [:apavel]]

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=316656974&repo=mozilla-central&lineNumber=2572

[task 2020-09-24T23:50:37.897Z] 23:50:37 INFO - TEST-START | browser/components/extensions/test/browser/browser_ext_browserAction_telemetry.js
[task 2020-09-24T23:50:37.897Z] 23:50:37 INFO - GECKO(10116) | [SimpleTest.requestLongerTimeout()] ignoring request, maybe you meant to call the global requestLongerTimeout instead?
[task 2020-09-24T23:56:48.430Z] 23:56:48 INFO - Buffered messages logged at 23:50:37
[task 2020-09-24T23:56:48.431Z] 23:56:48 INFO - Entering test bound testBrowserActionTelemetryTiming
[task 2020-09-24T23:56:48.431Z] 23:56:48 INFO - Extension loaded
[task 2020-09-24T23:56:48.432Z] 23:56:48 INFO - Extension loaded
[task 2020-09-24T23:56:48.432Z] 23:56:48 INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_browserAction_telemetry.js | No data recorded for histogram: WEBEXT_BROWSERACTION_POPUP_OPEN_MS. -
[task 2020-09-24T23:56:48.433Z] 23:56:48 INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_browserAction_telemetry.js | No data recorded for histogram: WEBEXT_BROWSERACTION_POPUP_OPEN_MS_BY_ADDONID. -
[task 2020-09-24T23:56:48.433Z] 23:56:48 INFO - Console message: Warning: attempting to write 4271 bytes to preference extensions.webextensions.uuids. This is bad for general performance and memory usage. Such an amount of data should rather be written to an external file. This preference will not be sent to any content processes.
[task 2020-09-24T23:56:48.434Z] 23:56:48 INFO - Console message: Warning: attempting to write 4329 bytes to preference extensions.webextensions.uuids. This is bad for general performance and memory usage. Such an amount of data should rather be written to an external file. This preference will not be sent to any content processes.
[task 2020-09-24T23:56:48.434Z] 23:56:48 INFO - Buffered messages logged at 23:50:38
[task 2020-09-24T23:56:48.435Z] 23:56:48 INFO - Console message: Warning: attempting to write 4842 bytes to preference browser.uiCustomization.state. This is bad for general performance and memory usage. Such an amount of data should rather be written to an external file. This preference will not be sent to any content processes.
[task 2020-09-24T23:56:48.435Z] 23:56:48 INFO - Console message: Warning: attempting to write 4910 bytes to preference browser.uiCustomization.state. This is bad for general performance and memory usage. Such an amount of data should rather be written to an external file. This preference will not be sent to any content processes.
[task 2020-09-24T23:56:48.436Z] 23:56:48 INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_browserAction_telemetry.js | No data recorded for histogram after startup: WEBEXT_BROWSERACTION_POPUP_OPEN_MS. -
[task 2020-09-24T23:56:48.436Z] 23:56:48 INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_browserAction_telemetry.js | No data recorded for histogram after startup: WEBEXT_BROWSERACTION_POPUP_OPEN_MS_BY_ADDONID. -
[task 2020-09-24T23:56:48.436Z] 23:56:48 INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_browserAction_telemetry.js | Expect widget not to be overflowed -
[task 2020-09-24T23:56:48.436Z] 23:56:48 INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_browserAction_telemetry.js | Data recorded for first extension for histogram: WEBEXT_BROWSERACTION_POPUP_OPEN_MS. -
[task 2020-09-24T23:56:48.437Z] 23:56:48 INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_browserAction_telemetry.js | Data recorded for first extension for histogram: WEBEXT_BROWSERACTION_POPUP_OPEN_MS_BY_ADDONID. - ["@test-extension1"] deepEqual ["@test-extension1"] -
[task 2020-09-24T23:56:48.437Z] 23:56:48 INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_browserAction_telemetry.js | Data recorded for first extension for histogram: WEBEXT_BROWSERACTION_POPUP_OPEN_MS_BY_ADDONID. -
[task 2020-09-24T23:56:48.437Z] 23:56:48 INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_browserAction_telemetry.js | Expect widget not to be overflowed -
[task 2020-09-24T23:56:48.437Z] 23:56:48 INFO - Buffered messages finished
[task 2020-09-24T23:56:48.437Z] 23:56:48 ERROR - TEST-UNEXPECTED-TIMEOUT | browser/components/extensions/test/browser/browser_ext_browserAction_telemetry.js | application timed out after 370 seconds with no output
[task 2020-09-24T23:56:48.437Z] 23:56:48 ERROR - Force-terminating active process(es).
[task 2020-09-24T23:56:48.437Z] 23:56:48 INFO - Determining child pids from psutil...
[task 2020-09-24T23:56:48.439Z] 23:56:48 INFO - [5144]
[task 2020-09-24T23:56:48.439Z] 23:56:48 INFO - ==> process 5144 launched child process 11176 ("Z:\task_1600988392\build\application\firefox\firefox.exe" -contentproc --channel="5144.0.492792661\1768817240" -parentBuildID 20200924215348 -prefsHandle 2212 -prefMapHandle 2200 -prefsLen 1 -prefMapSize 241800 -appdir "Z:\task_1600988392\build\application\firefox\browser" - 5144 gpu)
[task 2020-09-24T23:56:48.440Z] 23:56:48 INFO - ==> process 5144 launched child process 488 ("Z:\task_1600988392\build\application\firefox\firefox.exe" -contentproc --channel="5144.6.1573217328\1769397405" -childID 1 -isForBrowser -prefsHandle 2184 -prefMapHandle 2180 -prefsLen 1744 -prefMapSize 241800 -parentBuildID 20200924215348 -appdir "Z:\task_1600988392\build\application\firefox\browser" - 5144 tab)
[task 2020-09-24T23:56:48.440Z] 23:56:48 INFO - ==> process 5144 launched child process 7288 ("Z:\task_1600988392\build\application\firefox\firefox.exe" -contentproc --channel="5144.13.1148623007\2072972832" -childID 2 -isForBrowser -prefsHandle 4988 -prefMapHandle 4984 -prefsLen 1789 -prefMapSize 241800 -parentBuildID 20200924215348 -appdir "Z:\task_1600988392\build\application\firefox\browser" - 5144 tab)
[task 2020-09-24T23:56:48.441Z] 23:56:48 INFO - ==> process 5144 launched child process 8156 ("Z:\task_1600988392\build\application\firefox\firefox.exe" -contentproc --channel="5144.20.1326825649\1769050424" -childID 3 -isForBrowser -prefsHandle 5128 -prefMapHandle 5132 -prefsLen 1829 -prefMapSize 241800 -parentBuildID 20200924215348 -appdir "Z:\task_1600988392\build\application\firefox\browser" - 5144 tab)
[task 2020-09-24T23:56:48.441Z] 23:56:48 INFO - ==> process 5144 launched child process 4292 ("Z:\task_1600988392\build\application\firefox\firefox.exe" -contentproc --channel="5144.27.77727055\503015160" -childID 4 -isForBrowser -prefsHandle 3140 -prefMapHandle 3320 -prefsLen 10331 -prefMapSize 241800 -parentBuildID 20200924215348 -appdir "Z:\task_1600988392\build\application\firefox\browser" - 5144 tab)
[task 2020-09-24T23:56:48.441Z] 23:56:48 INFO - ==> process 5144 launched child process 8436 ("Z:\task_1600988392\build\application\firefox\firefox.exe" -contentproc --channel="5144.34.2058221215\2127481023" -childID 5 -isForBrowser -prefsHandle 4576 -prefMapHandle 3736 -prefsLen 11385 -prefMapSize 241800 -parentBuildID 20200924215348 -appdir "Z:\task_1600988392\build\application\firefox\browser" - 5144 tab)
[task 2020-09-24T23:56:48.441Z] 23:56:48 INFO - ==> process 5144 launched child process 10688 ("Z:\task_1600988392\build\application\firefox\firefox.exe" -contentproc --channel="5144.41.1974911040\1361116510" -childID 6 -isForBrowser -prefsHandle 1976 -prefMapHandle 5520 -prefsLen 16454 -prefMapSize 241800 -parentBuildID 20200924215348 -appdir "Z:\task_1600988392\build\application\firefox\browser" - 5144 tab)
[task 2020-09-24T23:56:48.442Z] 23:56:48 INFO - Found child pids: set([10688, 4292, 488, 11176, 7288, 8436, 5144, 8156])
[task 2020-09-24T23:56:48.442Z] 23:56:48 INFO - Killing process: 10688
[task 2020-09-24T23:56:48.442Z] 23:56:48 INFO - TEST-INFO | started process screenshot
[task 2020-09-24T23:56:48.664Z] 23:56:48 INFO - TEST-INFO | screenshot: exit 0

Comment 6

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• windows10-64: 1

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

Comment 7

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

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