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.

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

Regression from bug 1440714.

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

Comment on attachment 8966647 [details] [diff] [review] fix logcat logging Review of attachment 8966647 [details] [diff] [review]: ----------------------------------------------------------------- nice cleanup

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