Geoff Brown [:gbrown] Assignee
	Description • 6 years ago

Some Android test logs include a logcat dump, typically at the end of a test run. These logcats appear to be missing newlines, making them hard to read.

Also, I notice many recent timeout failures in bug 1411358 appear to happen "during" the logcat dump: The last thing dumped is part of a logcat, then the test log goes silent until timeout. Perhaps logging too much data at once, or too long of a line (log write?), hangs something...?

Anyway, let's sanitize the logcat.

	Geoff Brown [:gbrown] Assignee
	Comment 1 • 6 years ago

Timeout example

https://treeherder.mozilla.org/logviewer.html#?job_id=172703057&repo=autoland&lineNumber=4640

[task 2018-04-09T18:03:14.341Z] 18:03:14     INFO -  leakcheck | refcount logging is off, so leaks can't be detected!
[task 2018-04-09T18:03:14.742Z] 18:03:14     INFO -  04-09 11:01:56.163 I/Gecko   (  772): 04-09 11:01:56.163 I/Gecko   (  772): {"action":"test_end","time":1523296916168,"thread":null,"pid":null,"source":"reftest","test":"http://10.0.2.2:8888/jsreftest/tests/jsreftest.html?test=test262/language/statements/for-await-of/async-gen-dstr-let-obj-init-undefined.js","status":"OK"}04-09 11:01:56.163 I/Gecko   (  772): 04-09 11:01:56.163 I/Gecko   (  772): {"action":"log","time":1523296916170,"thread":null,"pid":null,"source":"reftest","level":"DEBUG","message":"Loading a blank page"}04-09 11:01:56.573 I/Gecko   (  772): 04-09 11:01:56.573 I/Gecko   (  772): {"action":"test_start","time":1523296916577,"thread":null,"pid":null,"source":"reftest","test":"http://10.0.2.2:8888/jsreftest/tests/jsreftest.html?test=test262/language/statements/for-await-of/async-gen-dstr-let-obj-ptrn-empty.js"}04-09 11:01:56.583 I/Gecko   (  772): REFTEST TEST-LOAD | http://10.0.2.2:8888/jsreftest/tests/jsreftest.html?test=test262/language/statements/for-await-of/async-gen-dstr-let-obj-ptrn-empty.js | 751 / 763 (98%)04-09 11:01:56.593 I/Gecko   (  772): 04-09 11:01:56.593 I/Gecko   (  772): {"action":"log","time":1523296916592,"thread":null,"pid":null,"source":"reftest","level":"DEBUG","message":"START http://10.0.2.2:8888/jsreftest/tests/jsreftest.html?test=test262/language/statements/for-await-of/async-gen-dstr-let-obj-ptrn-empty.js"}04-09 11:01:58.283 I/Gecko   (  772): 04-09 11:01:58.283 I/Gecko   (  772): {"action":"log","time":1523296918286,"thread":null,"pid":null,"source":"reftest","level":"DEBUG","message":"[CONTENT] OnDocumentLoad triggering AfterOnLoadScripts"}04-09 11:01:58.333 

<snip - truncated tens of thousands of characters>

{"action":"log","time":1523296952753,"thread":null,"pid":null,"source":"reftest","level":"DEBUG","message":"Loading a blank page"}04-09 11:02:33.363 I/Gecko   (  772): 04-09 11:02:33.363 I/Gecko   (  772): {"action":"suite_end","time":1523296953367,"thread":null,"pid":null,"source":"reftest","extra":{"results":{"Pass":0,"LoadOnly":763,"Exception":0,"FailedLoad":0,"UnexpectedFail":0,"UnexpectedPass":0,"AssertionUnexpected":0,"AssertionUnexpectedFixed":0,"KnownFail":0,"AssertionKnown":0,"Random":0,"Skip":0,"Slow":0}}}04-09 11:02:33.363 I/Gecko   (  772): 04-09 11:02:33.363 I/Gecko   (  772): {"action":"log","time":1523296953370,"thread":null,"pid":null,"source":"reftest","level":"INFO","message":"Slowest test took 4985ms (http://10.0.2.2:8888/jsreftest/tests/jsreftest.html?test=test262/language/statements/for-await-of/async-gen-dstr-let-obj-ptrn-id-init-skipped.js)"}04-09 11:02:33.383 I/Gecko   (  772): 04-09 11:02:33.383 I/Gecko   (  772): {"action":"log","time":1523296953379,"thread":null,"pid":null,"source":"reftest","level":"INFO","message":"Total canvas count = 0"}04-09 11:02:33.603 I/GeckoConsole(  772): 1523296953567	addons.xpi	WARN	Exception running bootstrap method shutdown on reftest@mozilla.org: TypeError: Cm.removedBootstrappedManifestLocation is not a function (resource://gre/modules/addons/XPIProvider.jsm -> file:///storage/sdcard/tests/reftest/profile/extensions/reftest@mozilla.org/bootstrap.js:63:5) JS Stack trace: shutdown@resource://gre/modules/addons/XPIProvider.jsm -> file:///storage/sdcard/tests/reftest/profile/extensions/reftest@bootstrap.js:63:504-09 11:02:33.603 I/GeckoConsole(  772): callBootstrapMethod@XPIProvider.jsm:3969:2004-09 11:02:33.603 I/GeckoConsole(  772): observe@XPIProvider.jsm:2214:1304-09 11:02:33.603 I/GeckoConsole(  772): onStopped@reftest.jsm:762:904-09 11:02:33.603 I/GeckoConsole(  772): DoneTests@reftest.jsm:768:904-09 11:02:33.603 I/GeckoConsole(  772): StartCurrentTest@reftest.jsm:618:904-09 11:02:33.603 I/GeckoConsole(  772): DoAssertionCheck@reftest.jsm:1338:504-09 11:02:33.603 I/GeckoConsole(  772): RecvAssertionCount@reftest.jsm:1445:504-09 11:02:33.603 I/GeckoConsole(  772): RegisterMessageLis[taskcluster 2018-04-09 19:17:35.589Z] === Task Finished ===
[taskcluster 2018-04-09 19:17:35.590Z] Unsuccessful task run with exit code: -1 completed in 7201.281 seconds

	Geoff Brown [:gbrown] Assignee
	Comment 2 • 6 years ago

Regression from bug 1440714.

	Geoff Brown [:gbrown] Assignee
	Comment 3 • 6 years ago

Looks much better:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=23f5d192787e12a308970090b52dc9923262d270

https://treeherder.mozilla.org/logviewer.html#?job_id=172891860&repo=try&lineNumber=2250-2259

[task 2018-04-10T16:09:44.864Z] 16:09:44     INFO -  5 INFO SimpleTest FINISHED
[task 2018-04-10T16:09:45.171Z] 16:09:45     INFO -  04-10 16:09:24.345 D/GeckoToolbar( 3210): onTabChanged: LOCATION_CHANGE
[task 2018-04-10T16:09:45.171Z] 16:09:45     INFO -  04-10 16:09:24.345 D/GeckoBrowserApp( 3210): BrowserApp.onTabChanged: 0: LOCATION_CHANGE
[task 2018-04-10T16:09:45.172Z] 16:09:45     INFO -  04-10 16:09:24.755 D/GeckoToolbar( 3210): onTabChanged: LOCATION_CHANGE
[task 2018-04-10T16:09:45.173Z] 16:09:45     INFO -  04-10 16:09:24.765 D/GeckoBrowserApp( 3210): BrowserApp.onTabChanged: 0: LOCATION_CHANGE
[task 2018-04-10T16:09:45.174Z] 16:09:45     INFO -  04-10 16:09:24.795 D/GeckoToolbar( 3210): onTabChanged: LOCATION_CHANGE
[task 2018-04-10T16:09:45.174Z] 16:09:45     INFO -  04-10 16:09:24.795 D/GeckoBrowserApp( 3210): BrowserApp.onTabChanged: 0: LOCATION_CHANGE
[task 2018-04-10T16:09:45.174Z] 16:09:45     INFO -  04-10 16:09:26.455 I/GeckoTabs( 3210): zerdatime 1020457 - page load stop
[task 2018-04-10T16:09:45.174Z] 16:09:45     INFO -  04-10 16:09:26.455 D/GeckoToolbar( 3210): onTabChanged: STOP
[task 2018-04-10T16:09:45.174Z] 16:09:45     INFO -  04-10 16:09:26.465 D/GeckoBrowserApp( 3210): BrowserApp.onTabChanged: 0: STOP

	Joel Maher ( :jmaher ) (UTC -8)
	Comment 4 • 6 years ago

Comment on attachment 8966647 [details] [diff] [review]
fix logcat logging

Review of attachment 8966647 [details] [diff] [review]:
-----------------------------------------------------------------

nice cleanup

	Pulsebot
	Comment 5 • 6 years ago

Pushed by gbrown@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/6d07dcc83134
Use newlines when dumping Android logcat to test log; r=jmaher

	Cristina Coroiu [:ccoroiu]
	Comment 6 • 6 years ago
bugherder

https://hg.mozilla.org/mozilla-central/rev/6d07dcc83134