1609841 - Intermittent toolkit/components/extensions/test/xpcshell/test_ext_native_messaging_unresponsive.js | test_unresponsive_native_app - [test_unresponsive_native_app : 265] A promise chain failed to handle a rejection: Invalid process ID: 0 - stack:

Status: RESOLVED FIXED

(WebExtensions :: General, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: nerli [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=285306800&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/IaeiZsetQ9y_mA7Hfr-aVA/runs/1/artifacts/public/logs/live_backing.log

---

[task 2020-01-17T03:34:58.976Z] 03:34:58 INFO - TEST-START | toolkit/components/extensions/test/xpcshell/test_ext_native_messaging_unresponsive.js
[task 2020-01-17T03:35:02.655Z] 03:35:02 WARNING - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/xpcshell/test_ext_native_messaging_unresponsive.js | xpcshell return code: 0
[task 2020-01-17T03:35:02.655Z] 03:35:02 INFO - TEST-INFO took 3679ms
[task 2020-01-17T03:35:02.656Z] 03:35:02 INFO - >>>>>>>
[task 2020-01-17T03:35:02.656Z] 03:35:02 INFO - (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2020-01-17T03:35:02.656Z] 03:35:02 INFO - (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2020-01-17T03:35:02.657Z] 03:35:02 INFO - (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2020-01-17T03:35:02.657Z] 03:35:02 INFO - running event loop
[task 2020-01-17T03:35:02.657Z] 03:35:02 INFO - toolkit/components/extensions/test/xpcshell/test_ext_native_messaging_unresponsive.js | Starting check_remote
[task 2020-01-17T03:35:02.658Z] 03:35:02 INFO - (xpcshell/head.js) | test check_remote pending (2)
[task 2020-01-17T03:35:02.658Z] 03:35:02 INFO - TEST-PASS | toolkit/components/extensions/test/xpcshell/test_ext_native_messaging_unresponsive.js | check_remote - [check_remote : 1] useRemoteWebExtensions matches - false == false
[task 2020-01-17T03:35:02.658Z] 03:35:02 INFO - TEST-PASS | toolkit/components/extensions/test/xpcshell/test_ext_native_messaging_unresponsive.js | check_remote - [check_remote : 1] testing from extension process - true == true
[task 2020-01-17T03:35:02.658Z] 03:35:02 INFO - (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2020-01-17T03:35:02.658Z] 03:35:02 INFO - (xpcshell/head.js) | test run_next_test 1 pending (2)
[task 2020-01-17T03:35:02.658Z] 03:35:02 INFO - (xpcshell/head.js) | test check_remote finished (2)
[task 2020-01-17T03:35:02.658Z] 03:35:02 INFO - toolkit/components/extensions/test/xpcshell/test_ext_native_messaging_unresponsive.js | Starting setup
[task 2020-01-17T03:35:02.658Z] 03:35:02 INFO - (xpcshell/head.js) | test setup pending (2)
[task 2020-01-17T03:35:02.659Z] 03:35:02 INFO - (xpcshell/head.js) | test run_next_test 1 finished (2)
[task 2020-01-17T03:35:02.659Z] 03:35:02 INFO - (xpcshell/head.js) | test run_next_test 2 pending (2)
[task 2020-01-17T03:35:02.659Z] 03:35:02 INFO - (xpcshell/head.js) | test setup finished (2)
[task 2020-01-17T03:35:02.659Z] 03:35:02 INFO - toolkit/components/extensions/test/xpcshell/test_ext_native_messaging_unresponsive.js | Starting test_unresponsive_native_app
[task 2020-01-17T03:35:02.659Z] 03:35:02 INFO - (xpcshell/head.js) | test test_unresponsive_native_app pending (2)
[task 2020-01-17T03:35:02.659Z] 03:35:02 INFO - "Extension attached"
[task 2020-01-17T03:35:02.659Z] 03:35:02 INFO - (xpcshell/head.js) | test run_next_test 2 finished (2)
[task 2020-01-17T03:35:02.659Z] 03:35:02 INFO - TEST-PASS | toolkit/components/extensions/test/xpcshell/test_ext_native_messaging_unresponsive.js | test_unresponsive_native_app - [test_unresponsive_native_app : 405] Received echoed message - Expected: echo me, Actual: echo me - true == true
[task 2020-01-17T03:35:02.660Z] 03:35:02 INFO - TEST-PASS | toolkit/components/extensions/test/xpcshell/test_ext_native_messaging_unresponsive.js | test_unresponsive_native_app - [test_unresponsive_native_app : 74] subprocess is running - 1 == 1
[task 2020-01-17T03:35:02.660Z] 03:35:02 INFO - PID 7544 | JavaScript error: Z:\task_1579228037\build\tests\xpcshell\head.js, line 246: uncaught exception: Object
[task 2020-01-17T03:35:02.660Z] 03:35:02 INFO - TEST-PASS | toolkit/components/extensions/test/xpcshell/test_ext_native_messaging_unresponsive.js | test_unresponsive_native_app - [test_unresponsive_native_app : 81] subprocess was successfully killed - 0 == 0
[task 2020-01-17T03:35:02.660Z] 03:35:02 INFO - (xpcshell/head.js) | test run_next_test 3 pending (2)
[task 2020-01-17T03:35:02.660Z] 03:35:02 INFO - (xpcshell/head.js) | test test_unresponsive_native_app finished (2)
[task 2020-01-17T03:35:02.660Z] 03:35:02 INFO - "CONSOLE_MESSAGE: (error) [JavaScript Error: "uncaught exception: Object" {file: "Z:\task_1579228037\build\tests\xpcshell\head.js" line: 246}]"
[task 2020-01-17T03:35:02.660Z] 03:35:02 INFO - (xpcshell/head.js) | test run_next_test 3 finished (1)
[task 2020-01-17T03:35:02.660Z] 03:35:02 INFO - exiting test
[task 2020-01-17T03:35:02.660Z] 03:35:02 WARNING - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/xpcshell/test_ext_native_messaging_unresponsive.js | test_unresponsive_native_app - [test_unresponsive_native_app : 265] A promise chain failed to handle a rejection: Invalid process ID: 0 - stack: getProcess@resource://gre/modules/subprocess/subprocess_worker_win.js:716:13
[task 2020-01-17T03:35:02.661Z] 03:35:02 INFO - kill@resource://gre/modules/subprocess/subprocess_worker_common.js:137:22
[task 2020-01-17T03:35:02.661Z] 03:35:02 INFO - onmessage/<@resource://gre/modules/subprocess/subprocess_worker_common.js:200:26
[task 2020-01-17T03:35:02.661Z] 03:35:02 INFO - onmessage@resource://gre/modules/subprocess/subprocess_worker_common.js:199:3
[task 2020-01-17T03:35:02.661Z] 03:35:02 INFO - EventHandlerNonNull*@resource://gre/modules/subprocess/subprocess_worker_common.js:194:1
[task 2020-01-17T03:35:02.661Z] 03:35:02 INFO - @resource://gre/modules/subprocess/subprocess_worker_win.js:13:14
[task 2020-01-17T03:35:02.661Z] 03:35:02 INFO - Rejection date: Fri Jan 17 2020 03:35:02 GMT+0000 (Greenwich Mean Time) - false == true
[task 2020-01-17T03:35:02.661Z] 03:35:02 INFO - resource://testing-common/PromiseTestUtils.jsm:assertNoUncaughtRejections:265
[task 2020-01-17T03:35:02.661Z] 03:35:02 INFO - Z:\task_1579228037\build\tests\xpcshell\head.js:_execute_test:574
[task 2020-01-17T03:35:02.661Z] 03:35:02 INFO - -e:null:1
[task 2020-01-17T03:35:02.661Z] 03:35:02 INFO - exiting test
[task 2020-01-17T03:35:02.662Z] 03:35:02 INFO - <<<<<<<
[task 2020-01-17T03:35:02.689Z] 03:35:02 INFO - TEST-START | xpcshell-legacyconfig.ini:toolkit/components/search/tests/xpcshell/test_remove_profile_engine.js
[task 2020-01-17T03:35:05.272Z] 03:35:05 INFO - TEST-PASS | xpcshell-legacyconfig.ini:toolkit/components/search/tests/xpcshell/test_remove_profile_engine.js | took 2584ms

Comment 1

[Intermittent Failures Robot]

17 failures in 659 pushes (0.026 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 8
• mozilla-central: 4
• try: 5

Platform breakdown:

• windows7-32-shippable: 7
• windows7-32: 5
• windows7-32-devedition: 2
• windows10-64-shippable: 1
• windows10-64: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1609841&startday=2020-01-17&endday=2020-01-17&tree=all

Comment 2

[Tomislav Jovanovic :zombie]

Doesn't reproduce locally. From a quick look, it doesn't seem to be a new bug introduced in 1602639, but that did change timings, so perhaps it just exposed something.

Gonna wait for bug 1443544 to land, since that will change the timings again, and we can just disable on Windows if it becomes too frequent.

Comment 3

[Andreea Pavel [:apavel]]

So far there are 24 total failures since the 16th of January, on windows7-32-shippable opt, windows7-32 opt and debug, windows10-64-shippable
opt and windows10-64 opt and debug.

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

[task 2020-01-19T00:17:02.287Z] 00:17:02 INFO - TEST-START | toolkit/components/extensions/test/xpcshell/test_ext_native_messaging_unresponsive.js
[task 2020-01-19T00:17:05.962Z] 00:17:05 WARNING - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/xpcshell/test_ext_native_messaging_unresponsive.js | xpcshell return code: 0
[task 2020-01-19T00:17:05.962Z] 00:17:05 INFO - TEST-INFO took 3668ms
[task 2020-01-19T00:17:05.962Z] 00:17:05 INFO - >>>>>>>
[task 2020-01-19T00:17:05.962Z] 00:17:05 INFO - (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2020-01-19T00:17:05.962Z] 00:17:05 INFO - (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2020-01-19T00:17:05.962Z] 00:17:05 INFO - (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2020-01-19T00:17:05.963Z] 00:17:05 INFO - running event loop
[task 2020-01-19T00:17:05.963Z] 00:17:05 INFO - toolkit/components/extensions/test/xpcshell/test_ext_native_messaging_unresponsive.js | Starting check_remote
[task 2020-01-19T00:17:05.963Z] 00:17:05 INFO - (xpcshell/head.js) | test check_remote pending (2)
[task 2020-01-19T00:17:05.963Z] 00:17:05 INFO - TEST-PASS | toolkit/components/extensions/test/xpcshell/test_ext_native_messaging_unresponsive.js | check_remote - [check_remote : 1] useRemoteWebExtensions matches - false == false
[task 2020-01-19T00:17:05.963Z] 00:17:05 INFO - TEST-PASS | toolkit/components/extensions/test/xpcshell/test_ext_native_messaging_unresponsive.js | check_remote - [check_remote : 1] testing from extension process - true == true
[task 2020-01-19T00:17:05.963Z] 00:17:05 INFO - (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2020-01-19T00:17:05.963Z] 00:17:05 INFO - (xpcshell/head.js) | test run_next_test 1 pending (2)
[task 2020-01-19T00:17:05.963Z] 00:17:05 INFO - (xpcshell/head.js) | test check_remote finished (2)
[task 2020-01-19T00:17:05.963Z] 00:17:05 INFO - toolkit/components/extensions/test/xpcshell/test_ext_native_messaging_unresponsive.js | Starting setup
[task 2020-01-19T00:17:05.963Z] 00:17:05 INFO - (xpcshell/head.js) | test setup pending (2)
[task 2020-01-19T00:17:05.963Z] 00:17:05 INFO - (xpcshell/head.js) | test run_next_test 1 finished (2)
[task 2020-01-19T00:17:05.963Z] 00:17:05 INFO - (xpcshell/head.js) | test run_next_test 2 pending (2)
[task 2020-01-19T00:17:05.963Z] 00:17:05 INFO - (xpcshell/head.js) | test setup finished (2)
[task 2020-01-19T00:17:05.963Z] 00:17:05 INFO - toolkit/components/extensions/test/xpcshell/test_ext_native_messaging_unresponsive.js | Starting test_unresponsive_native_app
[task 2020-01-19T00:17:05.964Z] 00:17:05 INFO - (xpcshell/head.js) | test test_unresponsive_native_app pending (2)
[task 2020-01-19T00:17:05.964Z] 00:17:05 INFO - "Extension attached"
[task 2020-01-19T00:17:05.964Z] 00:17:05 INFO - (xpcshell/head.js) | test run_next_test 2 finished (2)
[task 2020-01-19T00:17:05.964Z] 00:17:05 INFO - TEST-PASS | toolkit/components/extensions/test/xpcshell/test_ext_native_messaging_unresponsive.js | test_unresponsive_native_app - [test_unresponsive_native_app : 405] Received echoed message - Expected: echo me, Actual: echo me - true == true
[task 2020-01-19T00:17:05.964Z] 00:17:05 INFO - TEST-PASS | toolkit/components/extensions/test/xpcshell/test_ext_native_messaging_unresponsive.js | test_unresponsive_native_app - [test_unresponsive_native_app : 74] subprocess is running - 1 == 1
[task 2020-01-19T00:17:05.964Z] 00:17:05 INFO - PID 7664 | JavaScript error: Z:\task_1579391366\build\tests\xpcshell\head.js, line 246: uncaught exception: Object
[task 2020-01-19T00:17:05.964Z] 00:17:05 INFO - TEST-PASS | toolkit/components/extensions/test/xpcshell/test_ext_native_messaging_unresponsive.js | test_unresponsive_native_app - [test_unresponsive_native_app : 81] subprocess was successfully killed - 0 == 0
[task 2020-01-19T00:17:05.964Z] 00:17:05 INFO - (xpcshell/head.js) | test run_next_test 3 pending (2)
[task 2020-01-19T00:17:05.964Z] 00:17:05 INFO - (xpcshell/head.js) | test test_unresponsive_native_app finished (2)
[task 2020-01-19T00:17:05.964Z] 00:17:05 INFO - "CONSOLE_MESSAGE: (error) [JavaScript Error: "uncaught exception: Object" {file: "Z:\task_1579391366\build\tests\xpcshell\head.js" line: 246}]"
[task 2020-01-19T00:17:05.964Z] 00:17:05 INFO - (xpcshell/head.js) | test run_next_test 3 finished (1)
[task 2020-01-19T00:17:05.965Z] 00:17:05 INFO - exiting test
[task 2020-01-19T00:17:05.965Z] 00:17:05 WARNING - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/xpcshell/test_ext_native_messaging_unresponsive.js | test_unresponsive_native_app - [test_unresponsive_native_app : 265] A promise chain failed to handle a rejection: Invalid process ID: 0 - stack: getProcess@resource://gre/modules/subprocess/subprocess_worker_win.js:716:13
[task 2020-01-19T00:17:05.965Z] 00:17:05 INFO - kill@resource://gre/modules/subprocess/subprocess_worker_common.js:137:22
[task 2020-01-19T00:17:05.965Z] 00:17:05 INFO - onmessage/<@resource://gre/modules/subprocess/subprocess_worker_common.js:200:26
[task 2020-01-19T00:17:05.965Z] 00:17:05 INFO - onmessage@resource://gre/modules/subprocess/subprocess_worker_common.js:199:3
[task 2020-01-19T00:17:05.965Z] 00:17:05 INFO - EventHandlerNonNull*@resource://gre/modules/subprocess/subprocess_worker_common.js:194:1
[task 2020-01-19T00:17:05.965Z] 00:17:05 INFO - @resource://gre/modules/subprocess/subprocess_worker_win.js:13:14
[task 2020-01-19T00:17:05.965Z] 00:17:05 INFO - Rejection date: Sun Jan 19 2020 00:17:05 GMT+0000 (Greenwich Mean Time) - false == true
[task 2020-01-19T00:17:05.965Z] 00:17:05 INFO - resource://testing-common/PromiseTestUtils.jsm:assertNoUncaughtRejections:265
[task 2020-01-19T00:17:05.965Z] 00:17:05 INFO - Z:\task_1579391366\build\tests\xpcshell\head.js:_execute_test:574
[task 2020-01-19T00:17:05.965Z] 00:17:05 INFO - -e:null:1
[task 2020-01-19T00:17:05.965Z] 00:17:05 INFO - exiting test
[task 2020-01-19T00:17:05.966Z] 00:17:05 INFO - <<<<<<<

Comment 4

[Intermittent Failures Robot]

35 failures in 3773 pushes (0.009 failures/push) were associated with this bug in the last 7 days.

This is the #44 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• autoland: 17
• mozilla-central: 12
• try: 6

Platform breakdown:

• windows7-32-shippable: 18
• windows7-32: 8
• windows7-32-devedition: 2
• windows10-64-shippable: 3
• windows10-64: 3
• windows10-64-devedition: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1609841&startday=2020-01-13&endday=2020-01-19&tree=all

Comment 5

[Intermittent Failures Robot]

16 failures in 732 pushes (0.022 failures/push) were associated with this bug yesterday.

Repository breakdown:

• mozilla-central: 7
• autoland: 9

Platform breakdown:

• windows7-32-shippable: 10
• windows10-64-shippable: 4
• windows10-64: 2

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

Comment 6

[Intermittent Failures Robot]

25 failures in 827 pushes (0.03 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 9
• mozilla-central: 6
• try: 10

Platform breakdown:

• macosx1014-64: 1
• windows7-32-shippable: 10
• windows10-64: 2
• windows10-64-shippable: 5
• windows10-64-devedition: 1
• windows7-32-devedition: 5
• windows7-32: 1

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

Comment 7

[Intermittent Failures Robot]

18 failures in 838 pushes (0.021 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 13
• try: 3
• mozilla-central: 2

Platform breakdown:

• windows10-64-shippable: 2
• windows10-64: 5
• windows7-32-shippable: 10
• windows7-32: 1

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

Comment 8

[Andreea Pavel [:apavel]]

Patch in bug 1443544 seems to have fixed this too https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2020-01-19&endday=2020-01-26&tree=trunk&bug=1609841

Comment 9

[Intermittent Failures Robot]

84 failures in 4004 pushes (0.021 failures/push) were associated with this bug in the last 7 days.

This is the #8 most frequent failure this week.

** This failure happened more than 75 times this week! Resolving this bug is a very high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 1 week, the affected test(s) may be disabled. **

Repository breakdown:

• autoland: 44
• try: 18
• mozilla-central: 22

Platform breakdown:

• windows7-32-shippable: 40
• windows7-32: 7
• windows10-64-shippable: 14
• windows10-64: 14
• macosx1014-64: 1
• windows7-32-devedition: 6
• windows10-64-devedition: 2

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