Closed Bug 1560339 Opened 1 year ago Closed 1 year ago

Extra incoherent logging when running android mochitest

Categories

(Testing :: General, defect, P2)

57 Branch
defect

Tracking

(firefox-esr60 unaffected, firefox-esr68 unaffected, firefox68 unaffected, firefox69 fixed, firefox70 fixed)

RESOLVED FIXED
mozilla70
Tracking Status
firefox-esr60 --- unaffected
firefox-esr68 --- unaffected
firefox68 --- unaffected
firefox69 --- fixed
firefox70 --- fixed

People

(Reporter: gbrown, Assigned: marauder)

References

(Regression)

Details

(Keywords: regression)

Attachments

(1 file)

When running 'mach mochitest' in an android build context, I see extra, unexpected lines logged. These are often incomplete lines, or non-ascii characters. They seem to generally be prefixed with "GECKO".

Running 'mach mochitest testing/mochitest/tests/Harness_sanity'

...
 0:38.02 TEST_START: testing/mochitest/tests/Harness_sanity/test_getweakmapkeys.html
 0:38.16 TEST_END: OK
 0:38.27 TEST_START: testing/mochitest/tests/Harness_sanity/test_importInMainProcess.html
 0:38.47 TEST_END: OK
 0:49.12 GECKO ,"subtest":"One of the keys should be x","status":"PASS","js_source":"TestRunner.js"}
 0:38.16 TEST_END: Test OK. Subtests passed 1/1. Unexpected 0
 0:38.27 TEST_START: testing/mochitest/tests/Harness_sanity/test_importInMainProcess.html
 0:38.47 TEST_END: OK
 0:38.57 TEST_START: testing/mochitest/tests/Harness_sanity/test_sanity.html
 0:38.88 TEST_END: OK
 0:39.02 TEST_START: testing/mochitest/tests/Harness_sanity/test_sanityException.html
 0:39.19 TEST_END: OK
 0:39.30 TEST_START: testing/mochitest/tests/Harness_sanity/test_sanityException2.html
 0:39.47 TEST_END: OK
 0:39.60 TEST_START: testing/mochitest/tests/Harness_sanity/test_sanityParams.html
 0:39.78 TEST_END: OK
 0:39.88 TEST_START: testing/mochitest/tests/Harness_sanity/test_sanityRegisteredServiceWorker.html
 0:40.20 TEST_END: OK
 0:40.30 TEST_START: testing/mochitest/tests/Harness_sanity/test_sanityRegisteredServiceWorker2.html
 0:40.48 TEST_END: OK
 0:40.59 TEST_START: testing/mochitest/tests/Harness_sanity/test_sanityWindowSnapshot.html
 0:40.81 TEST_END: OK
 0:40.93 TEST_START: testing/mochitest/tests/Harness_sanity/test_sanity_cleanup.html
 0:41.09 TEST_END: OK
 0:41.22 TEST_START: testing/mochitest/tests/Harness_sanity/test_sanity_cleanup2.html
 0:41.38 TEST_END: OK
 0:41.49 TEST_START: testing/mochitest/tests/Harness_sanity/test_sanity_waitForCondition.html
 0:45.85 TEST_END: OK
 0:45.92 INFO TEST-START | Shutdown
 0:45.92 INFO Passed:  153
 0:45.92 INFO Failed:  0
 0:45.92 INFO Todo:    4
 0:45.92 INFO Mode:    non-e10s
 0:45.92 INFO Slowest: 4364ms - /tests/testing/mochitest/tests/Harness_sanity/test_sanity_waitForCondition.html
 0:45.92 INFO SimpleTest FINISHED
 0:49.90 GECKO ","js_source":"TestRunner.js"}
 0:45.92 INFO Passed:  153
 0:45.92 INFO Failed:  0
 0:45.92 INFO Todo:    4
 0:45.92 INFO Mode:    non-e10s
 0:45.92 INFO Slowest: 4364ms - /tests/testing/mochitest/tests/Harness_sanity/test_sanity_waitForCondition.html
 0:45.92 INFO SimpleTest FINISHED
 0:50.65 GECKO ce":"mochitest","level":"INFO","message":"SimpleTest FINISHED","js_source":"TestRunner.js"}
 0:51.41 GECKO �ⰲ겿
 0:52.13 GECKO 겿
 0:52.89 GECKO �
wait for org.mozilla.fennec_gbrown complete; top activity=com.android.launcher3
remoteautomation.py | Application ran for: 0:00:29.392929
...

Are other test types affected? Are desktop tests affected? I'll look into that....

I have to wonder if this is related to the changes for bug 1526752.

Summary: Extra incoherent logging when run 'mach mochitest' on android → Extra incoherent logging when running 'mach mochitest' on android

Also happens in continuous integration:

https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=253869506&repo=mozilla-central&lineNumber=1873-1892

[task 2019-06-28T06:10:41.550Z] 06:10:41     INFO -  365 INFO TEST-START | dom/base/test/test_bug682592.html
[task 2019-06-28T06:10:55.366Z] 06:10:55     INFO -  GECKO | ml","subtest":"bidi is not detected correctly","status":"PASS","js_source":"TestRunner.js"}
[task 2019-06-28T06:11:09.191Z] 06:11:09     INFO -  GECKO | /dom/base/test/test_bug682592.html","subtest":"bidi is not detected correctly","status":"PASS","js_source":"TestRunner.js"}
[task 2019-06-28T06:11:23.006Z] 06:11:23     INFO -  GECKO | est_bug682592.html","subtest":"bidi is not detected correctly","status":"PASS","js_source":"TestRunner.js"}
[task 2019-06-28T06:11:36.831Z] 06:11:36     INFO -  GECKO | est_bug682592.html","subtest":"bidi is not detected correctly","status":"PASS","js_source":"TestRunner.js"}
[task 2019-06-28T06:11:50.646Z] 06:11:50     INFO -  GECKO | /dom/base/test/test_bug682592.html","subtest":"bidi is not detected correctly","status":"PASS","js_source":"TestRunner.js"}
[task 2019-06-28T06:12:04.462Z] 06:12:04     INFO -  GECKO | est_bug682592.html","subtest":"bidi is not detected correctly","status":"PASS","js_source":"TestRunner.js"}
[task 2019-06-28T06:12:18.282Z] 06:12:18     INFO -  GECKO | /dom/base/test/test_bug682592.html","subtest":"bidi is not detected correctly","status":"PASS","js_source":"TestRunner.js"}
[task 2019-06-28T06:12:32.107Z] 06:12:32     INFO -  GECKO | est_bug682592.html","subtest":"bidi is not detected correctly","status":"PASS","js_source":"TestRunner.js"}
[task 2019-06-28T06:12:45.929Z] 06:12:45     INFO -  GECKO | /dom/base/test/test_bug682592.html","subtest":"bidi is not detected correctly","status":"PASS","js_source":"TestRunner.js"}
[task 2019-06-28T06:12:59.753Z] 06:12:59     INFO -  GECKO | est_bug682592.html","subtest":"bidi is not detected correctly","status":"PASS","js_source":"TestRunner.js"}
[task 2019-06-28T06:13:13.570Z] 06:13:13     INFO -  GECKO | est_bug682592.html","subtest":"bidi is not detected correctly","status":"PASS","js_source":"TestRunner.js"}
[task 2019-06-28T06:13:27.388Z] 06:13:27     INFO -  GECKO | /dom/base/test/test_bug682592.html","subtest":"bidi is not detected correctly","status":"PASS","js_source":"TestRunner.js"}
[task 2019-06-28T06:13:41.204Z] 06:13:41     INFO -  GECKO | /dom/base/test/test_bug682592.html","subtest":"bidi is not detected correctly","status":"PASS","js_source":"TestRunner.js"}
[task 2019-06-28T06:13:55.028Z] 06:13:55     INFO -  GECKO | est_bug682592.html","subtest":"bidi is not detected correctly","status":"PASS","js_source":"TestRunner.js"}
[task 2019-06-28T06:14:08.844Z] 06:14:08     INFO -  GECKO | ","test":"/tests/dom/base/test/test_bug682592.html","subtest":"bidi is not detected correctly","status":"PASS","js_source":"TestRunner.js"}
[task 2019-06-28T06:14:22.763Z] 06:14:22     INFO -  GECKO | est_bug682592.html","subtest":"bidi is not detected correctly","status":"PASS","js_source":"TestRunner.js"}
[task 2019-06-28T06:14:36.586Z] 06:14:36     INFO -  GECKO | est_bug682592.html","subtest":"bidi is not detected correctly","status":"PASS","js_source":"TestRunner.js"}
[task 2019-06-28T06:14:50.409Z] 06:14:50     INFO -  GECKO | /dom/base/test/test_bug682592.html","subtest":"bidi is not detected correctly","status":"PASS","js_source":"TestRunner.js"}
[task 2019-06-28T06:14:50.409Z] 06:14:50     INFO -  366 INFO TEST-OK | dom/base/test/test_bug682592.html | took 257344ms
Summary: Extra incoherent logging when running 'mach mochitest' on android → Extra incoherent logging when running android mochitest

Other platforms (windows, linux) seem to be okay.

Android reftests seem to be okay.

This is a regression from bug 1526752.

https://treeherder.mozilla.org/#/jobs?repo=autoland&searchStr=android%2Cmochitest&tochange=36c3d348039ec835db4f82c171e5823ab82b740e&fromchange=f97628b002de486bdb6f47b1ca3bfc7871afc73f&selectedJob=251858857

Android mochitest logs before bug 1526752 are "clean", like
https://treeherder.mozilla.org/logviewer.html#?job_id=251858857&repo=autoland

After that change, partial, unformatted GECKO lines are introduced:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=251859586&repo=autoland&lineNumber=3067

[task 2019-06-14T10:18:42.046Z] 10:18:42 INFO - GECKO | read":null,"pid":null,"source":"mochitest","test":"/tests/dom/webauthn/tests/test_webauthn_get_assertion.html","subtest":"Expecting an AbortError","status":"PASS","js_source":"TestRunner.js"}

:marauder - Can you have a look (take this bug if you like)?

Flags: needinfo?(marian.raiciof)
Regressed by: 1526752
Priority: -- → P2

I have not investigated further.

I think we need to get this fixed or bug 1526752 backed out soon -- clean, accurate logging is important.

Assignee: gbrown → nobody
Flags: needinfo?(dave.hunt)

Hi Geoff,
I was in PTO, now i'm back and i'm working on it.

Duplicate of this bug: 1564211

Geoff - what command do you use to install the kvm for android environment ?

./mach android-emulator --version x86-7.0
(On Linux, the x86 emulator requires that kvm is installed. The resulting emulator is much faster than the arm emulator.)

I tried "$ sudo apt install qemu-kvm" but it doesn't work for me.
Thanks!

Bob, can you answer Marian's question in comment 9 while Geoff is away? Thank you.

Flags: needinfo?(bob)
Flags: needinfo?(dave.hunt)

Hi everyone,
in the meantime i managed to make the emulator to work , but there are problems running GeckoView Test Runner and mochitests locally
so i will use "mach try fuzzy --full" for now to select the mochitests for android.
Thanks!

./mach android-emulator --version x86-7.0 --force-update should do it

Flags: needinfo?(bob)

(In reply to Marian Raiciof [:marauder] from comment #9)

Geoff - what command do you use to install the kvm for android environment ?

./mach android-emulator --version x86-7.0
(On Linux, the x86 emulator requires that kvm is installed. The resulting emulator is much faster than the arm emulator.)

I tried "$ sudo apt install qemu-kvm" but it doesn't work for me.
Thanks!

I haven't had any trouble with kvm, but of course there is variation depending on your OS and configuration.

https://developer.android.com/studio/run/emulator-acceleration suggests

sudo apt-get install qemu-kvm libvirt-bin ubuntu-vm-builder bridge-utils ia32-libs-multiarch

Thanks Bob!

I did that on my end and i get this :

$ ./mach android-emulator --version x86-7.0 --force-update

0:00.49 Fetching and installing AVD. This may take a few minutes...
INFO - untarring "AVDs-x86-android-7.0-build-2019-04-23.tar.gz"
0:22.14 Starting Android emulator running Android 7.0 x86/x86_64...
Running the x86 emulator; be sure to install an x86 APK!
0:35.93 Android emulator is running.
0:35.93 Use 'mach install' to install or update Firefox on your emulator.

$ ./mach install

0:00.63 /usr/bin/make -C . -j8 -s -w install
0:00.66 make: Entering directory '/home/marian.raiciof/MozillaProject/mozilla-central/obj-x86_64-unknown-linux-android'
0:00.67 adb: failed to stat dist/fennec-70.0a1.en-US.android-x86_64.apk: No such file or directory
0:00.67 Performing Streamed Install
0:00.67 /home/marian.raiciof/MozillaProject/mozilla-central/mobile/android/build.mk:42: recipe for target 'install' failed
0:00.67 make: *** [install] Error 1
0:00.68 make: Leaving directory '/home/marian.raiciof/MozillaProject/mozilla-central/obj-x86_64-unknown-linux-android'

I think i have to download from taskcluster (or somewhere) the apk for :
fennec-70.0a1.en-US.android-x86_64.apk
and copy it in obj-x86_64-unknown-linux-android.

Thanks Geoff - i managed to fix the kvm, i had to add myself to the group and then restarted the computer.

To avoid all these issues i checked my changes on try.

I tried several approaches to fix the logging issue.

If i remove my changes from https://bugzilla.mozilla.org/show_bug.cgi?id=1526752
the tests will fail with UnicodeDecodeError/UnicodeEncodeError.

I tried to use a larger codec to remove those chinese characters:

  • so i replaced utf-8 with utf-16 but that generated even more chinese letters:

08:30:57 INFO - GECKO | 藮놸냢뾲≻捡楴湯㨢琢獥彴瑳瑡獵Ⱒ琢浩≥ㄺ㘵ㄳ㤷㔴〵㐲∬桴敲摡㨢畮汬∬楰≤渺汵ⱬ猢畯捲≥∺潭档瑩獥≴∬整瑳㨢⼢整瑳⽳潤⽭敳畣楲祴琯獥⽴獣⽰整瑳江慥楤杮睟汩捤牡⹤瑨汭Ⱒ猢扵整瑳㨢䌢偓猠潨汵⁤污潬⁷楦敬江慥楤杮睟汩捤牡彤污潬敷⹤獪∡∬瑳瑡獵㨢倢十≓∬獪獟畯捲≥∺敔瑳畒湮牥樮≳떅룮늰닪�
08:31:00 INFO - GECKO | 杮睟
etc.

Then i used ascii in all places where i used utf-8:

  • the chinese characters were replaced by question marks.
    INFO - GECKO | ????????????{"action":"test_status","time":1563184434697,"thread":null,"pid":null,"source":"mochitest","test":"/tests/dom/canvas/test/test_imagebitmap.html","subtest":"createImageBitmap should throw with corrupted blob","status":"PASS","js_source":"TestRunner.js"}????????????
    INFO - GECKO | ?????????
    INFO - GECKO | ???
    INFO - GECKO | ???

I searched for a solution to detect the encodings of the byte strings and to use that as a codec.
I found that mozilla has "chardet" package and i used that:

import chardet
detected_codec = chardet.detect(line)['encoding']
line = line.rstrip().decode(detected_codec, "replace")

The result was still bad:
10:45:40 INFO - GECKO | s"}
10:45:41 INFO - GECKO | �ⰲ겿
10:45:41 INFO - GECKO | 겿
10:45:42 INFO - GECKO | �

When i tested the ascii codec i saw a pattern in the logs - those question marks were seen everywhere GECKO word appeared.
Another thing that kept appearing in those log lines was TestRunner.js

In the file mozilla-central/testing/mochitest/tests/SimpleTest/TestRunner.js
i saw that we have on line 223, a LOG_DELIMITER variable:
var LOG_DELIMITER = String.fromCharCode(0xe175) + String.fromCharCode(0xee31) + String.fromCharCode(0x2c32) + String.fromCharCode(0xacbf);
(https://searchfox.org/mozilla-central/source/testing/mochitest/tests/SimpleTest/TestRunner.js#223)

I changed the variable to this:
var LOG_DELIMITER = "YYY";
and i reverted the changes on decodings to use "utf-8" as in my patch.

The result:
INFO - GECKO | YYY{"action":"test_status","time":1563270222564,"thread":null,"pid":null,"source":"mochitest","test":"/tests/dom/tests/mochitest/dom-level2-html/test_HTMLTableCellElement20.html","subtest":"Asize","status":"PASS","js_source":"TestRunner.js"}YYY
etc.

So it seems that the line
var LOG_DELIMITER = String.fromCharCode(0xe175) + String.fromCharCode(0xee31) + String.fromCharCode(0x2c32) + String.fromCharCode(0xacbf);
from TestRunner.js is causing these issues.
Can we use something else there, what options do we have ?

As a side note, i checked the clean logs from https://treeherder.mozilla.org/logviewer.html#?job_id=251858857&repo=autoland
that does not include my patch, but there we don't have any line that displays "GECKO |".

Flags: needinfo?(marian.raiciof)
Flags: needinfo?(gbrown)
Flags: needinfo?(aryx.bugmail)

(In reply to Marian Raiciof [:marauder] from comment #15)

As a side note, i checked the clean logs from https://treeherder.mozilla.org/logviewer.html#?job_id=251858857&repo=autoland
that does not include my patch, but there we don't have any line that displays "GECKO |".

Agreed: Traditionally, android mochitests do not display any GECKO lines -- only TEST-START/TEST-OK. I think that is okay.

(In reply to Marian Raiciof [:marauder] from comment #15)

So it seems that the line
var LOG_DELIMITER = String.fromCharCode(0xe175) + String.fromCharCode(0xee31) + String.fromCharCode(0x2c32) + String.fromCharCode(0xacbf);
from TestRunner.js is causing these issues.
Can we use something else there, what options do we have ?

My understanding is that LOG_DELIMITER was chosen as a byte sequence that was unlikely to otherwise occur in mochitest log data, a distinct sequence to indicate the start/end of log records. I don't particularly like it, but I would be cautious about changing it.

It seems to me that we should not be trying to encode/decode LOG_DELIMITER -- it should be treated as a sequence of bytes if possible.

I also found

https://searchfox.org/mozilla-central/rev/da855d65d1fbdd714190cab2c46130f7422f3699/testing/mochitest/runtests.py#215

    for fragment in line.split(MessageLogger.DELIMITER):

where MessageLogger.DELIMITER appears to be the same as LOG_DELIMITER.

The problem is the change to adb.py's get_file():

https://hg.mozilla.org/mozilla-central/rev/36c3d348039ec835db4f82c171e5823ab82b740e#l3.187

remote_automation.py uses multiple calls to get_file() to read the remote test log while it is being created: It reads as much as possible, processes most of what was read, then after a pause tries to read again, this time with an offset equal to the length of the file read so far. eg, maybe 200 characters are read on the first call, then the next call tries to read the file from offset 200.

The utf-8-decoded text may have a different length than the original text, which throws off the offset: Now remoteautomation might see 197 characters returned instead of 200, so it requests an offset of 197, so the next get_file returns a little bit of data that has already been processed.

I hope this will demonstrate correct operation:

https://treeherder.mozilla.org/#/jobs?repo=try&tier=1%2C2%2C3&revision=69266b98af97b7ab66c5b2b5c6c678940006ebc9

Flags: needinfo?(gbrown)

Do not decode data returned by get_file() in adb.py

Thanks for the detailed info, Geoff.
I created a patch with your changes and did a push to try:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=ae5ac293f061b22f36606309436f44ed25bdec91

Flags: needinfo?(aryx.bugmail)
Pushed by mraiciof@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/1286d491193d
Extra incoherent logging when running android mochitest r=gbrown
Status: NEW → RESOLVED
Closed: 1 year ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla70
Assignee: nobody → marian.raiciof
You need to log in before you can comment on or make changes to this bug.