Closed Bug 1034274 Opened 10 years ago Closed 10 years ago

Integrate Structured Logging with Gaia Unit Tests

Categories

(Testing :: Mozbase, defect)

x86
macOS
defect
Not set
normal

Tracking

(Not tracked)

RESOLVED FIXED

People

(Reporter: chmanchester, Assigned: chmanchester)

References

(Blocks 1 open bug)

Details

Attachments

(1 file)

No longer depends on: 1036427
I have a patch for this, here it is on try:

https://tbpl.mozilla.org/?tree=Try&rev=b9bd4228d651

The output changes to be a bit less verbose -- I'm hooking into different events, so each sub-suite start/end isn't logged as its own line.

Logs now:

13:38:47     INFO -  gaia-unit-tests TEST-START | keyboard/test/unit/keyboard/settings_test.js |
13:38:47     INFO -  gaia-unit-tests TEST-START | keyboard/test/unit/keyboard/settings_test.js | SettingsPromiseManager
13:38:47     INFO -  gaia-unit-tests TEST-PASS  | keyboard/test/unit/keyboard/settings_test.js | SettingsPromiseManager get one key
13:38:47     INFO -  gaia-unit-tests TEST-PASS  | keyboard/test/unit/keyboard/settings_test.js | SettingsPromiseManager get multiple keys
13:38:47     INFO -  gaia-unit-tests TEST-PASS  | keyboard/test/unit/keyboard/settings_test.js | SettingsPromiseManager get, handle error
13:38:47     INFO -  gaia-unit-tests TEST-PASS  | keyboard/test/unit/keyboard/settings_test.js | SettingsPromiseManager set one key
13:38:48     INFO -  gaia-unit-tests TEST-PASS  | keyboard/test/unit/keyboard/settings_test.js | SettingsPromiseManager set multiple keys
13:38:48     INFO -  gaia-unit-tests TEST-PASS  | keyboard/test/unit/keyboard/settings_test.js | SettingsPromiseManager set, handle error
13:38:48     INFO -  gaia-unit-tests TEST-END   | keyboard/test/unit/keyboard/settings_test.js | SettingsPromiseManager
13:38:48     INFO -  gaia-unit-tests TEST-START | keyboard/test/unit/keyboard/settings_test.js | SettingsManagerBase
13:38:48     INFO -  gaia-unit-tests TEST-PASS  | keyboard/test/unit/keyboard/settings_test.js | SettingsManagerBase initSettings, observe change, stopObserve
13:38:48     INFO -  gaia-unit-tests TEST-PASS  | keyboard/test/unit/keyboard/settings_test.js | SettingsManagerBase initSettings and returned error
13:38:48     INFO -  gaia-unit-tests TEST-END   | keyboard/test/unit/keyboard/settings_test.js | SettingsManagerBase
13:38:48     INFO -  gaia-unit-tests TEST-END   | keyboard/test/unit/keyboard/settings_test.js |
13:38:48     INFO -  gaia-unit-tests INFO       | suite results (pass/fail): 8/0


Will become:

11:45:17     INFO -  TEST-START | keyboard/test/unit/keyboard/settings_test.js
11:45:17     INFO -  TEST-PASS | keyboard/test/unit/keyboard/settings_test.js | SettingsPromiseManager get one key
11:45:17     INFO -  TEST-PASS | keyboard/test/unit/keyboard/settings_test.js | SettingsPromiseManager get multiple keys
11:45:17     INFO -  TEST-PASS | keyboard/test/unit/keyboard/settings_test.js | SettingsPromiseManager get, handle error
11:45:17     INFO -  TEST-PASS | keyboard/test/unit/keyboard/settings_test.js | SettingsPromiseManager set one key
11:45:17     INFO -  TEST-PASS | keyboard/test/unit/keyboard/settings_test.js | SettingsPromiseManager set multiple keys
11:45:17     INFO -  TEST-PASS | keyboard/test/unit/keyboard/settings_test.js | SettingsPromiseManager set, handle error
11:45:17     INFO -  TEST-PASS | keyboard/test/unit/keyboard/settings_test.js | SettingsManagerBase initSettings, observe change, stopObserve
11:45:18     INFO -  TEST-PASS | keyboard/test/unit/keyboard/settings_test.js | SettingsManagerBase initSettings and returned error
11:45:18     INFO -  TEST-OK | keyboard/test/unit/keyboard/settings_test.js | took 743ms
11:45:18     INFO -  suite results (pass/fail): 8/0
This is a recent try push: https://tbpl.mozilla.org/?tree=Try&rev=735f896f39a3

I planted some failures and timeouts in those re-triggers to test output in those scenarios.
Attachment #8472512 - Flags: review?(jgriffin)
Comment on attachment 8472512 [details] [review]
Use structured logging for gaia unit tests.

I'm concerned we might be missing some details here.

Compare this error without this patch:

18:00:27     INFO -  gaia-unit-tests TEST-UNEXPECTED-FAIL | keyboard/test/unit/worker_test.js | Latin en_us worker "before all" hook | timeout of 10000ms exceeded
18:00:27     INFO -  gaia-unit-tests INFO       | stack trace:
18:00:27     INFO -      Error: timeout of 10000ms exceeded
18:00:27     INFO -          at (anonymous) (app://keyboard.gaiamobile.org/common/vendor/mocha/mocha.js:3680:14)
18:00:27     INFO -  gaia-unit-tests INFO       | suite results (pass/fail): 0/1

to one with this patch:

17:59:46     INFO -  TEST-START | keyboard/test/unit/worker_test.js
17:59:57     INFO -  TEST-UNEXPECTED-FAIL | keyboard/test/unit/worker_test.js | Latin en_us worker "before all" hook - timeout of 10000ms exceeded
17:59:57     INFO -  TEST-INFO | expected PASS
17:59:57     INFO -  TEST-OK | keyboard/test/unit/worker_test.js | took 10371ms

We're missing the stack trace here.

I'm also a little worried by the buildbot timeout at https://tbpl.mozilla.org/php/getParsedLog.php?id=45715241&tree=Try&full=1; we should retrigger this try job a bunch more times to make sure this patch isn't responsible.
Attachment #8472512 - Flags: review?(jgriffin) → review-
Opened bug 1054114 to get the stack trace in the output (a stack is logged, but to no end as it doesn't get picked up by the formatter). Here's a new try run with seeded failures:

https://tbpl.mozilla.org/?tree=Try&rev=8edfdf7e6317

I think the prior try run coincided with the backed out patch in bug 1042105, but I'll do some re-triggers in case.
No longer depends on: 1054114
Comment on attachment 8472512 [details] [review]
Use structured logging for gaia unit tests.

Released a mozlog and confirmed exception stacks are logged in this version.
Attachment #8472512 - Flags: review- → review?(jgriffin)
Comment on attachment 8472512 [details] [review]
Use structured logging for gaia unit tests.

Great, thanks.  Just a reminder to nuke the test changes in apps/browser/test/unit/browser_db_test.js before merging.
Attachment #8472512 - Flags: review?(jgriffin) → review+
The branch is ready to merge but it looks like I don't have the appropriate permissions to do it. Jonathan, could you grant me those or merge when you have a chance? Thanks!
Flags: needinfo?(jgriffin)
(In reply to Chris Manchester [:chmanchester] from comment #7)
> The branch is ready to merge but it looks like I don't have the appropriate
> permissions to do it. Jonathan, could you grant me those or merge when you
> have a chance? Thanks!

Added to chefs group in the b2g-mozilla org; should work now :-)
Thanks Ed, merged!
Status: NEW → RESOLVED
Closed: 10 years ago
Flags: needinfo?(jgriffin)
Resolution: --- → FIXED
Assignee: nobody → cmanchester
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: