Open Bug 1692900 Opened 2 years ago Updated 8 months ago

Intermittent Geckoview random test | missing test completion status because of characters missing in test name

Categories

(Testing :: Mozbase, defect)

Unspecified
All
defect

Tracking

(Not tracked)

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

Filed by: csabou [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=330026819&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/IUr23S5kSfufhyDgBUSsVw/runs/0/artifacts/public/logs/live_backing.log


[task 2021-02-15T18:22:14.750Z] 18:22:14     INFO -  TEST-PASS | org.mozilla.geckoview.test.ContentDelegateTest.downloadOneRequest | took 474ms
[task 2021-02-15T18:22:14.751Z] 18:22:14     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=780
[task 2021-02-15T18:22:14.751Z] 18:22:14     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2021-02-15T18:22:14.751Z] 18:22:14     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2021-02-15T18:22:14.751Z] 18:22:14     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=windowOpenClose
[task 2021-02-15T18:22:14.752Z] 18:22:14     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.gec
[task 2021-02-15T18:22:14.752Z] 18:22:14     INFO -  org.mozilla.geckoview.test | koview.test.ContentDelegateTest
[task 2021-02-15T18:22:14.752Z] 18:22:14     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=68
[task 2021-02-15T18:22:14.752Z] 18:22:14     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: 1
[task 2021-02-15T18:22:14.753Z] 18:22:14     INFO -  TEST-START | org.mozilla.gec.windowOpenClose
[task 2021-02-15T18:22:15.426Z] 18:22:15     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=780
[task 2021-02-15T18:22:15.426Z] 18:22:15     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=.
[task 2021-02-15T18:22:15.426Z] 18:22:15     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2021-02-15T18:22:15.427Z] 18:22:15     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=windowOpenClose
[task 2021-02-15T18:22:15.427Z] 18:22:15     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.ContentDelegateTest
[task 2021-02-15T18:22:15.427Z] 18:22:15     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=68
[task 2021-02-15T18:22:15.427Z] 18:22:15     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: 0
[task 2021-02-15T18:22:15.427Z] 18:22:15  WARNING -  TEST-UNEXPECTED-FAIL | org.mozilla.gec.windowOpenClose | missing test completion status
[task 2021-02-15T18:22:15.427Z] 18:22:15     INFO -  TEST-INFO took 678ms
[task 2021-02-15T18:22:15.428Z] 18:22:15     INFO -  TEST-START | org.mozilla.geckoview.test.ContentDelegateTest.windowOpenClose
[task 2021-02-15T18:22:15.428Z] 18:22:15     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=780
[task 2021-02-15T18:22:15.429Z] 18:22:15     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2021-02-15T18:22:15.429Z] 18:22:15     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2021-02-15T18:22:15.429Z] 18:22:15     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=stopHungProcess
[task 2021-02-15T18:22:15.429Z] 18:22:15     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.ContentDelegateTest
[task 2021-02-15T18:22:15.429Z] 18:22:15     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=69
[task 2021-02-15T18:22:15.429Z] 18:22:15     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: 1
[task 2021-02-15T18:22:15.429Z] 18:22:15  WARNING -  TEST-UNEXPECTED-FAIL | org.mozilla.geckoview.test.ContentDelegateTest.windowOpenClose | missing test completion status
[task 2021-02-15T18:22:15.430Z] 18:22:15     INFO -  TEST-INFO took 2ms
[task 2021-02-15T18:22:15.430Z] 18:22:15     INFO -  TEST-START | org.mozilla.geckoview.test.ContentDelegateTest.stopHungProcess
[task 2021-02-15T18:22:18.792Z] 18:22:18     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=780
[task 2021-02-15T18:22:18.792Z] 18:22:18     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=.
[task 2021-02-15T18:22:18.793Z] 18:22:18     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2021-02-15T18:22:18.793Z] 18:22:18     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=stopHungProcess
[task 2021-02-15T18:22:18.793Z] 18:22:18     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.ContentDelegateTest
[task 2021-02-15T18:22:18.793Z] 18:22:18     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=69
[task 2021-02-15T18:22:18.793Z] 18:22:18     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: 0
[task 2021-02-15T18:22:18.793Z] 18:22:18     INFO -  TEST-PASS | org.mozilla.geckoview.test.ContentDelegateTest.stopHungProcess | took 3364ms```
Summary: Intermittent org.mozilla.gec.windowOpenClose | missing test completion status → Intermittent Geckoview random test | missing test completion status because of characters missing in test name

Jon, are you aware of the reason the test names (and more?) can be garbled and cause these random failures?

Flags: needinfo?(jonalmeida942)

I'm not familiar with this unfortunately. Maybe Agi would better know who could help here?

Flags: needinfo?(jonalmeida942) → needinfo?(agi)

It looks like we're getting a TEST-START with a garbled test name:

[task 2020-11-06T14:31:55.363Z] 14:31:55     INFO -  TEST-START | org.mozilla.geckoview.test.ScreenshotTest.screenShotScaledWithAspectPre
[task 2020-11-06T14:31:57.403Z] 14:31:57     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=765
[task 2020-11-06T14:31:57.403Z] 14:31:57     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=.
[task 2020-11-06T14:31:57.403Z] 14:31:57     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2020-11-06T14:31:57.403Z] 14:31:57     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=screenShotScaledWithAspectPreservingSize
[task 2020-11-06T14:31:57.403Z] 14:31:57     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.ScreenshotTest
[task 2020-11-06T14:31:57.404Z] 14:31:57     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=462
[task 2020-11-06T14:31:57.404Z] 14:31:57     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: 0
[task 2020-11-06T14:31:57.404Z] 14:31:57  WARNING -  TEST-UNEXPECTED-FAIL | org.mozilla.geckoview.test.ScreenshotTest.screenShotScaledWithAspectPre | missing test completion status
[task 2020-11-06T14:31:57.405Z] 14:31:57     INFO -  TEST-INFO took 2041ms
[task 2020-11-06T14:31:57.405Z] 14:31:57     INFO -  TEST-START | org.mozilla.geckoview.test.ScreenshotTest.screenShotScaledWithAspectPreservingSize

Notice the TEST-START name is screenShotScaledWithAspectPre but it should be screenShotScaledWithAspectPreservingSize

Flags: needinfo?(agi)

Ah, yeah, this is the raw ouput:

[task 2020-11-06T14:31:55.363Z] 14:31:55     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=screenShotScaledWithAspectPre
[task 2020-11-06T14:31:55.363Z] 14:31:55     INFO -  org.mozilla.geckoview.test | servingSize

(notice the newline after Pre) not sure why this is happening

This feels like a bug in adb.py or somewhere around there.

Component: General → Mozbase
Product: GeckoView → Testing
Severity: S4 → --
Priority: P5 → --
Severity: -- → S4
Flags: needinfo?(gbrown)

(In reply to Agi Sferro | :agi | ni? for questions | ⏰ PST | he/him from comment #12)

Ah, yeah, this is the raw ouput:

[task 2020-11-06T14:31:55.363Z] 14:31:55     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=screenShotScaledWithAspectPre
[task 2020-11-06T14:31:55.363Z] 14:31:55     INFO -  org.mozilla.geckoview.test | servingSize

(notice the newline after Pre) not sure why this is happening

I have a speculative fix for this case, coming shortly. However, several failures reported here are missing whole lines of expected output, which seems like a separate issue. I expect a reduction in failure rate, but let's leave-open for remaining cases.

Flags: needinfo?(gbrown)
Keywords: leave-open

If only a partial line is read, save it and concatenate with the next
line before returning the whole line to the client.

Pushed by gbrown@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/a4a5c0d81e55
[mozdevice] Handle partial lines in stdout callback; r=jmaher
Keywords: leave-open

I'm not sure my change helped.

In https://treeherder.mozilla.org/logviewer?job_id=360594086&repo=autoland&lineNumber=5249 I still see "broken lines":

[task 2021-12-09T04:22:21.098Z] 04:22:21     INFO -  TEST-START | org.mozilla.geckoview.test.GeckoSessionTestRuleTest#contentCrashIgnored
[task 2021-12-09T04:22:21.133Z] 04:22:21     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=823
[task 2021-12-09T04:22:21.133Z] 04:22:21     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2021-12-09T04:22:21.134Z] 04:22:21     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2021-12-09T04:22:21.134Z] 04:22:21     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=contentCrashIgnored
[task 2021-12-09T04:22:21.134Z] 04:22:21     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.g
[task 2021-12-09T04:22:21.135Z] 04:22:21     INFO -  org.mozilla.geckoview.test | eckoview.test.GeckoSessionTestRuleTest
You need to log in before you can comment on or make changes to this bug.