Closed Bug 1454671 Opened 4 years ago Closed 4 years ago

Combine default log and gecko.log in automation on Android


(Testing :: Marionette, defect, P2)



(firefox60 fixed, firefox61 fixed)

Tracking Status
firefox60 --- fixed
firefox61 --- fixed


(Reporter: whimboo, Assigned: whimboo)




(1 file)

Currently we create two distinct files on Android which make it really hard to correlate the lines between the default log, and gecko.log.

To be in sync with desktop we should use `--gecko-log -` to print everything to stdout, and include it in the default log file.
Hm, we have different levels of logging when we combine that:

> [task 2018-04-17T15:20:11.818Z] 15:20:11     INFO -  04-17 08:20:11.802 I/Gecko   (  744): 1523978411807	Marionette	TRACE	19 -> [0,42,"WebDriver:DeleteSession",{}]
> [task 2018-04-17T15:20:11.874Z] 15:20:11     INFO -  04-17 08:20:11.853 I/Gecko   (  744): 1523978411856	Marionette	TRACE	19 <- [1,42,null,{}]
> [task 2018-04-17T15:20:11.954Z] 15:20:11     INFO -  TEST-PASS | testing/marionette/harness/marionette_harness/tests/unit/ TestNoSuchWindowContent.test_closed_tab | took 21965ms

All the logging as coming from Gecko get a double formatting applied. James, you have more knowledge in logging than I have, do you have any idea why this could happen? With my patch I just pass `--gecko-log=-` to the `` script.
Flags: needinfo?(james)
I'm not sure I follow. Isn't this double log-level thing normal in mozrunner? I'm probably misunderstanding something.
Flags: needinfo?(james)
Hm, only partly as it seem then. See the following log from a Mn job as run on desktop:

> [task 2018-04-18T08:03:55.527Z] 08:03:55     INFO -  1524038635523	Marionette	TRACE	10 <- [1,2,null,{}]
> [task 2018-04-18T08:03:55.532Z] 08:03:55     INFO - TEST-PASS | testing/marionette/harness/marionette_harness/tests/unit/ TestSession.test_new_session_returns_capabilities | took 72ms

I wonder what adds the `04-17 08:20:11.802 I/Gecko   (  744): ` on Android.
Oh, it's indeed special-cased for Android. The gecko logging is read via logcat:

I think that I don't want to fiddle with this, and leave what I have right now.
Attachment #8968544 - Flags: review?(ato)
Comment on attachment 8968544 [details]
Bug 1454671 - Combine default log and gecko.log in automation on Android.
Attachment #8968544 - Flags: review?(ato) → review+
Pushed by
Combine default log and gecko.log in automation on Android. r=ato
Closed: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla61
Test-only change which helps in investigating test failures for Mn jobs on Android. Please uplift to mozilla-beta.
Whiteboard: [checkin-needed-beta]
Strangely with this change the log level has been decreased from TRACE to INFO, even I didn't touch the `-vv` option. I even cannot see it being used at all on Android before and how we got the trace log:

> /builds/worker/workspace/build/venv/bin/python -u /builds/worker/workspace/build/tests/marionette/harness/marionette_harness/ --emulator --app=fennec --package=org.mozilla.fennec_aurora --address=localhost:2828 /builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit-tests.ini --disable-e10s --gecko-log=/builds/worker/workspace/build/blobber_upload_dir/gecko.log --log-raw=/builds/worker/workspace/build/blobber_upload_dir/marionette_raw.log --log-errorsummary=/builds/worker/workspace/build/blobber_upload_dir/marionette_errorsummary.log --symbols-path=/builds/worker/workspace/build/symbols --startup-timeout=300 --this-chunk 1 --total-chunks 10

I will file a follow-up to officially enable the `-vv` options.
You need to log in before you can comment on or make changes to this bug.