Android mochitest logcat dominated by hard to read GeckoDump messages

NEW
Unassigned

Status

Testing
Mozbase
4 years ago
4 years ago

People

(Reporter: gbrown, Unassigned)

Tracking

Trunk
x86_64
Linux
Points:
---

Firefox Tracking Flags

(Not tracked)

Details

(Reporter)

Description

4 years ago
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}}ⰲ겿
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

4 years ago
Or could we use a different logcat log level to filter these out from the logcat dump at end of run?
You need to log in before you can comment on or make changes to this bug.