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

Status: RESOLVED FIXED

(Testing :: Mozbase, defect)

Description

[Treeherder Bug Filer]

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```

Comment 8

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

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

Comment 9

[Jonathan Almeida [:jonalmeida]]

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

Comment 10

[Intermittent Failures Robot]

1 failures in 3737 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• android-em-7-0-x86_64: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1692900&startday=2021-02-15&endday=2021-02-21&tree=all

Comment 11

[[ex-Mozilla] Agi Sferro | :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

Comment 12

[[ex-Mozilla] Agi Sferro | :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

Comment 13

[[ex-Mozilla] Agi Sferro | :agi]

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

Comment 14

[[ex-Mozilla] Agi Sferro | :agi]

We get this garbled line here: https://searchfox.org/mozilla-central/rev/c8ce16e4299a3afd560320d8d094556f2b5504cd/testing/mochitest/runjunit.py#275

and this callback gets called straight from adb.py here: https://searchfox.org/mozilla-central/rev/c8ce16e4299a3afd560320d8d094556f2b5504cd/testing/mochitest/runjunit.py#361-363

Comment 15

[Intermittent Failures Robot]

1 failures in 3967 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• android-em-7-0-x86_64: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1692900&startday=2021-03-22&endday=2021-03-28&tree=all

Comment 17

[Intermittent Failures Robot]

1 failures in 3854 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• android-em-7-0-x86_64: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1692900&startday=2021-04-05&endday=2021-04-11&tree=all

Comment 19

[Intermittent Failures Robot]

4 failures in 3279 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 4

Platform and build breakdown:

• android-em-7-0-x86_64: 3
  • debug: 3
• android-em-7-0-x86_64-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1692900&startday=2021-05-03&endday=2021-05-09&tree=all

Comment 21

[Intermittent Failures Robot]

2 failures in 3061 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1
• mozilla-central: 1

Platform and build breakdown:

• android-em-7-0-x86_64: 2
  • debug: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1692900&startday=2021-05-17&endday=2021-05-23&tree=all

Comment 22

[Intermittent Failures Robot]

3 failures in 2908 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 2
• autoland: 1

Platform and build breakdown:

• android-em-7-0-x86_64-qr: 1
  • debug: 1
• android-em-7-0-x86_64-shippable: 1
  • opt: 1
• android-em-7-0-x86_64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1692900&startday=2021-05-24&endday=2021-05-30&tree=all

Comment 23

[Intermittent Failures Robot]

1 failures in 3502 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• android-em-7-0-x86_64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1692900&startday=2021-06-07&endday=2021-06-13&tree=all

Comment 24

[Intermittent Failures Robot]

2 failures in 2888 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 2

Platform and build breakdown:

• android-em-7-0-x86_64-qr: 1
  • debug: 1
• android-em-7-0-x86_64: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1692900&startday=2021-06-14&endday=2021-06-20&tree=all

Comment 25

[Intermittent Failures Robot]

2 failures in 2387 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 2

Platform and build breakdown:

• android-em-7-0-x86_64-qr: 1
  • opt: 1
• android-em-7-0-x86_64: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1692900&startday=2021-07-05&endday=2021-07-11&tree=all

Comment 26

[Intermittent Failures Robot]

2 failures in 2940 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1
• mozilla-central: 1

Platform and build breakdown:

• android-em-7-0-x86_64-qr: 1
  • debug: 1
• android-em-7-0-x86_64-shippable-lite-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1692900&startday=2021-07-19&endday=2021-07-25&tree=all

Comment 27

[Intermittent Failures Robot]

1 failures in 2580 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• android-em-7-0-x86_64-qr: 1
  • debug-isolated-process: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1692900&startday=2021-08-23&endday=2021-08-29&tree=all

Comment 28

[Intermittent Failures Robot]

1 failures in 3084 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• android-em-7-0-x86_64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1692900&startday=2021-08-30&endday=2021-09-05&tree=all

Comment 29

[Intermittent Failures Robot]

2 failures in 3266 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 2

Platform and build breakdown:

• android-em-7-0-x86_64-lite-qr: 1
  • opt: 1
• android-em-7-0-x86_64-qr: 1
  • debug-isolated-process: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1692900&startday=2021-09-06&endday=2021-09-12&tree=all

Comment 30

[Intermittent Failures Robot]

1 failures in 3375 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• android-em-7-0-x86_64-qr: 1
  • debug-isolated-process: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1692900&startday=2021-09-13&endday=2021-09-19&tree=all

Comment 31

[Intermittent Failures Robot]

2 failures in 3376 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 2

Platform and build breakdown:

• android-em-7-0-x86_64-qr: 1
  • opt: 1
• android-em-7-0-x86_64-lite-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1692900&startday=2021-09-27&endday=2021-10-03&tree=all

Comment 32

[Intermittent Failures Robot]

1 failures in 3626 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• android-em-7-0-x86_64-qr: 1
  • debug-isolated-process: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1692900&startday=2021-10-04&endday=2021-10-10&tree=all

Comment 35

[Intermittent Failures Robot]

1 failures in 2845 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• android-em-7-0-x86_64-qr: 1
  • debug-isolated-process: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1692900&startday=2021-10-25&endday=2021-10-31&tree=all

Comment 36

[Intermittent Failures Robot]

1 failures in 3030 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• android-em-7-0-x86_64-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1692900&startday=2021-11-01&endday=2021-11-07&tree=all

Comment 37

[Intermittent Failures Robot]

4 failures in 3170 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 3
• autoland: 1

Platform and build breakdown:

• android-em-7-0-x86_64-lite-qr: 1
  • debug: 1
• android-em-7-0-x86_64-shippable-lite-qr: 1
  • opt: 1
• android-em-7-0-x86_64-qr: 2
  • opt: 1
  • debug-isolated-process: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1692900&startday=2021-11-29&endday=2021-12-05&tree=all

Comment 38

[Geoff Brown [: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.

Comment 39

[Geoff Brown [:gbrown]]

Attachment: Bug 1692900 - [mozdevice] Handle partial lines in stdout callback; r=

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

Comment 40

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/a4a5c0d81e55
[mozdevice] Handle partial lines in stdout callback; r=jmaher

Comment 41

[Norisz Fay [:noriszfay]]

https://hg.mozilla.org/mozilla-central/rev/a4a5c0d81e55

Comment 42

[Geoff Brown [:gbrown]]

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

Comment 43

[Intermittent Failures Robot]

1 failures in 3319 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• android-em-7-0-x86_64-lite-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1692900&startday=2021-12-06&endday=2021-12-12&tree=all