1685757 - xpcshell failure parsing doesn't include salient errors

Status: NEW

(Testing :: XPCShell Harness, defect, P3)

Description

[:Gijs (he/him)]

e.g.: https://firefoxci.taskcluster-artifacts.net/WZEReZ4tRjGS2QNeqBHreA/0/public/logs/live_backing.log

from https://treeherder.mozilla.org/jobs?repo=autoland&revision=ac1a9dda65ed0923ad363f63a3ba55c2bf94b293&searchStr=xpcshell&group_state=expanded&selectedTaskRun=WZEReZ4tRjGS2QNeqBHreA.0

fails 3 tests with errors along the lines of:

[task 2021-01-08T16:17:57.773Z] 16:17:57  WARNING -  TEST-UNEXPECTED-FAIL | browser/components/downloads/test/unit/test_DownloadsCommon_isFileOfType.js | xpcshell return code: 0
[task 2021-01-08T16:17:57.773Z] 16:17:57     INFO -  TEST-INFO took 296ms
[task 2021-01-08T16:17:57.773Z] 16:17:57     INFO -  >>>>>>>
[task 2021-01-08T16:17:57.773Z] 16:17:57     INFO -  PID 7624 | [Parent 7624, Main Thread] WARNING: Failed to get directory to cache.: file /builds/worker/checkouts/gecko/security/sandbox/win/src/sandboxbroker/sandboxBroker.cpp:119
[task 2021-01-08T16:17:57.773Z] 16:17:57     INFO -  PID 7624 | [Parent 7624, Main Thread] WARNING: Failed to get directory to cache.: file /builds/worker/checkouts/gecko/security/sandbox/win/src/sandboxbroker/sandboxBroker.cpp:119
[task 2021-01-08T16:17:57.773Z] 16:17:57     INFO -  PID 7624 | [Parent 7624, Main Thread] WARNING: Failed to get directory to cache.: file /builds/worker/checkouts/gecko/security/sandbox/win/src/sandboxbroker/sandboxBroker.cpp:119
[task 2021-01-08T16:17:57.773Z] 16:17:57     INFO -  PID 7624 | [Parent 7624, Main Thread] WARNING: Failed to get directory to cache.: file /builds/worker/checkouts/gecko/security/sandbox/win/src/sandboxbroker/sandboxBroker.cpp:119
[task 2021-01-08T16:17:57.773Z] 16:17:57     INFO -  PID 7624 | [Parent 7624, Main Thread] WARNING: Failed to get directory to cache.: file /builds/worker/checkouts/gecko/security/sandbox/win/src/sandboxbroker/sandboxBroker.cpp:119
[task 2021-01-08T16:17:57.774Z] 16:17:57     INFO -  PID 7624 | [Parent 7624, Main Thread] WARNING: Couldn't get the user appdata directory. Crash events may not be produced.: file /builds/worker/checkouts/gecko/toolkit/crashreporter/nsExceptionHandler.cpp:2916
[task 2021-01-08T16:17:57.774Z] 16:17:57     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2021-01-08T16:17:57.774Z] 16:17:57     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2021-01-08T16:17:57.774Z] 16:17:57     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2021-01-08T16:17:57.774Z] 16:17:57     INFO -  running event loop
[task 2021-01-08T16:17:57.774Z] 16:17:57     INFO -  browser/components/downloads/test/unit/test_DownloadsCommon_isFileOfType.js | Starting test_common_initialize
[task 2021-01-08T16:17:57.774Z] 16:17:57     INFO -  (xpcshell/head.js) | test test_common_initialize pending (2)
[task 2021-01-08T16:17:57.774Z] 16:17:57     INFO -  (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2021-01-08T16:17:57.774Z] 16:17:57     INFO -  Unexpected exception NS_ERROR_FAILURE:
[task 2021-01-08T16:17:57.774Z] 16:17:57     INFO -  _do_main@Z:\task_1610121329\build\tests\xpcshell\head.js:239:6
[task 2021-01-08T16:17:57.774Z] 16:17:57     INFO -  _execute_test@Z:\task_1610121329\build\tests\xpcshell\head.js:567:5
[task 2021-01-08T16:17:57.774Z] 16:17:57     INFO -  @-e:1:1
[task 2021-01-08T16:17:57.774Z] 16:17:57     INFO -  exiting test
[task 2021-01-08T16:17:57.775Z] 16:17:57     INFO -  PID 7624 | [Parent 7624, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, kKnownEsrVersion) failed with result 0x80004002 (NS_NOINTERFACE): file /builds/worker/checkouts/gecko/toolkit/components/resistfingerprinting/nsRFPService.cpp:744
[task 2021-01-08T16:17:57.775Z] 16:17:57     INFO -  PID 7624 | [Parent 7624, Main Thread] WARNING: unable to post SHUTDOWN message: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnectionMgr.cpp:182
[task 2021-01-08T16:17:57.775Z] 16:17:57     INFO -  PID 7624 | [Parent 7624, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3364
[task 2021-01-08T16:17:57.775Z] 16:17:57     INFO -  PID 7624 | [Parent 7624, Main Thread] WARNING: OOPDeinit() without successful OOPInit(): file /builds/worker/checkouts/gecko/toolkit/crashreporter/nsExceptionHandler.cpp:3362
[task 2021-01-08T16:17:57.775Z] 16:17:57     INFO -  PID 7624 | [Parent 7624, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4378
[task 2021-01-08T16:17:57.775Z] 16:17:57     INFO -  PID 7624 | [Parent 7624, Main Thread] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/checkouts/gecko/xpcom/base/nsTraceRefcnt.cpp:202
[task 2021-01-08T16:17:57.775Z] 16:17:57     INFO -  PID 7624 | [Parent 7624, Main Thread] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/checkouts/gecko/xpcom/base/nsTraceRefcnt.cpp:202
[task 2021-01-08T16:17:57.775Z] 16:17:57     INFO -  <<<<<<<

But all treeherder shows is:

TEST-UNEXPECTED-FAIL | browser/components/downloads/test/unit/test_DownloadsCommon_isFileOfType.js | xpcshell return code: 0 Logviewer

The "unexpected exception" and stack should be considered more important, so that we get useful intermittent bug summaries etc.

Comment 1

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

The Unexpected exception gets emitted with logging level INFO and also doesn't match the other keywords treeherder looks for. How common is this failure and can it be changed to get logged with the appropriate log level?

Handling stacks would be a challenge, e.g. getting the test path, failure message + stack into the 255 characters of the bugzilla summary. What summary do you have in mind?
Intermittent browser/components/downloads/test/unit/test_DownloadsCommon_isFileOfType.js | Unexpected exception NS_ERROR_FAILURE: | [e-mail] | [e-mail] ?

Comment 2

[:Gijs (he/him)]

(In reply to Sebastian Hengst [:aryx] (needinfo on intermittent or backout) from comment #1)

The Unexpected exception gets emitted with logging level INFO and also doesn't match the other keywords treeherder looks for. How common is this failure

I don't know how to find out - I'd need a way of grepping a representative sample of xpcshell failure logs; I can't be confident that bugs would be filed with useful summaries. This failure in particular, it caused me to get backed out and I relanded with the issue fixed. But I spent longer than necessary working out what broke. Note that the stack trace printed in the log is in fact also useless. The cause of the problem was this line: https://hg.mozilla.org/integration/autoland/rev/ac1a9dda65ed0923ad363f63a3ba55c2bf94b293#l2.24 (the promise is rejected which causes the await to throw an exception) which does not appear to be referenced in the log at all.

and can it be changed to get logged with the appropriate log level?

Probably. I think we'd need to fix exception processing in xpcshell and then update code in the harness so it logs correctly.

Handling stacks would be a challenge, e.g. getting the test path, failure message + stack into the 255 characters of the bugzilla summary. What summary do you have in mind?

Including the exception message (once we get something more useful than NS_ERROR_FAILURE) and a line number seems like a good start.

Comment 3

[:Gijs (he/him)]

(In reply to Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout) from comment #1)

The Unexpected exception gets emitted with logging level INFO and also doesn't match the other keywords treeherder looks for. How common is this failure and can it be changed to get logged with the appropriate log level?

https://searchfox.org/mozilla-central/rev/6d3bc9da27904dbf6f6defda81019916235b8dd5/testing/xpcshell/head.js#919-922 suggests it's trying to emit it at log level error. Do you know why that isn't happening?

Comment 4

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

The log for XPCshell tests has the detailed log for a failing test embedded between >>>>> and <<<<<. Does the log level not persist when it gets logged with that loop?

Comment 5

[:Gijs (he/him)]

(In reply to Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout) from comment #4)

The log for XPCshell tests has the detailed log for a failing test embedded between >>>>> and <<<<<. Does the log level not persist when it gets logged with that loop?

I'm sorry, I'm too far out of my depth here. It doesn't look like the python code you linked to has any concept of log levels. Maybe gbrown can help, based on the annotate for some of the python involved here?

Comment 6

[Geoff Brown [:gbrown]]

I'm a bit rusty here too, but afaik, the python code has no knowledge of the log levels used in js -- it just dumps whatever the js reported. You would need to introduce some new mechanism for passing (parsing?) the log level to improve here.