1045861 - Android mochitest logcat dominated by hard to read GeckoDump messages

Status: NEW

(Testing :: Mozbase, defect)

Description

[Geoff Brown [:gbrown] (pto Apr 11-18)]

The logcats for Android mochitest jobs now contain a lot of messages that look like:

07-29 07:36:22.578 I/GeckoDump( 2247): ⰲ겿{"action":"test_status","time":1406619382582,"thread":null,"pid":null,"source":"mochitest","test":"/tests/caps/tests/mochitest/test_app_principal_equality.html","subtest":"should be able to access the first frame","status":"PASS"}ⰲ겿

I assume this is fallout from structured logging -- surely we can make a more readable log!


This seems to apply to any Android mochitest. For example, consider https://tbpl.mozilla.org/php/getParsedLog.php?id=44800678&tree=Mozilla-Central&full=1, which has logcat http://mozilla-releng-blobs.s3.amazonaws.com/blobs/mozilla-central/sha512/92122e1c89bb36989abf91cb5732638ac053bad1aed8457a0aebf6478c7ec7ab576ac5e04177d50883140c6393bfee3d41e715ab12d8d9ee6448db6b9b663ee4 with, for instance:

07-29 07:36:22.578 I/GeckoDump( 2247): ⰲ겿{"action":"test_status","time":1406619382582,"thread":null,"pid":null,"source":"mochitest","test":"/tests/caps/tests/mochitest/test_app_principal_equality.html","subtest":"should be able to access the first frame","status":"PASS"}ⰲ겿
07-29 07:36:22.585 I/GeckoDump( 2247): ⰲ겿{"action":"test_status","time":1406619382587,"thread":null,"pid":null,"source":"mochitest","test":"/tests/caps/tests/mochitest/test_app_principal_equality.html","subtest":"should not be able to access the other frames","status":"PASS"}ⰲ겿
07-29 07:36:22.585 I/GeckoDump( 2247): ⰲ겿{"action":"test_status","time":1406619382588,"thread":null,"pid":null,"source":"mochitest","test":"/tests/caps/tests/mochitest/test_app_principal_equality.html","subtest":"should not be able to access the other frames","status":"PASS"}ⰲ겿
07-29 07:36:22.617 I/GeckoDump( 2247): ⰲ겿{"action":"log","time":1406619382623,"thread":null,"pid":null,"source":"mochitest","level":"INFO","message":"MEMORY STAT vsize after test: 800395264"}ⰲ겿
07-29 07:36:22.617 I/GeckoDump( 2247): ⰲ겿{"action":"log","time":1406619382625,"thread":null,"pid":null,"source":"mochitest","level":"INFO","message":"MEMORY STAT vsizeMaxContiguous not supported in this build configuration."}ⰲ겿
07-29 07:36:22.617 I/GeckoDump( 2247): ⰲ겿{"action":"log","time":1406619382627,"thread":null,"pid":null,"source":"mochitest","level":"INFO","message":"MEMORY STAT residentFast after test: 174071808"}ⰲ겿
07-29 07:36:22.617 I/GeckoDump( 2247): ⰲ겿{"action":"log","time":1406619382631,"thread":null,"pid":null,"source":"mochitest","level":"INFO","message":"MEMORY STAT heapAllocated after test: 30980836"}ⰲ겿
07-29 07:36:22.640 I/GeckoDump( 2247): ⰲ겿{"action":"test_end","time":1406619382645,"thread":null,"pid":null,"source":"mochitest","test":"/tests/caps/tests/mochitest/test_app_principal_equality.html","status":"OK","message":"Finished in 2862ms","extra":{"runtime":2862}}ⰲ겿

Comment 1

[Ahmed Kachkach [:akachkach]]

We currently use logcat to get logs from the JS side. Switching to structured logs means we have to pass JSON so it can be analyzed by the test harness; this is also the case for desktop mochitests, the difference is we don't store the JS logs in a file (only the ones formatted by the Python side).

One thing we could do I guess is log structured logs to a different file, and log formatted logs (formatted in the JS side, with the patch we landed in bug 1041706) in logcat. I'm unsure how we can handle multiple files with LogController though (I just reused the code that used to set those up and changed unstructured logs by JSON).

Comment 2

[Ed Morley [:emorley]]

Or could we use a different logcat log level to filter these out from the logcat dump at end of run?