Closed Bug 1290114 Opened 4 years ago Closed 4 years ago

Android test harnesses buffer log content, sometimes for a long time

Categories

(Firefox for Android :: Testing, defect)

49 Branch
defect
Not set

Tracking

()

RESOLVED FIXED
Firefox 50
Tracking Status
firefox50 --- fixed

People

(Reporter: gbrown, Assigned: gbrown)

References

Details

Attachments

(1 file)

All the Android test harnesses use code in remoteautomation.py to collect and display content from a remote log while tests are running. That code always buffers the most recent line, even when the line is complete, and sometimes it keeps several lines buffered. The buffering scheme mostly works, but often causes a slight lag between what the test is doing and what the log reports. Occasionally, this lag causes intermittent failures, as in bug 1284362.
It took me a while to see the problem here, so here's a long-winded explanation.

In remoteautomation, in read_stdout(), we currently pull new content, chop it into newline-separated lines, and then:

             self.logBuffer = lines[-1]
             del lines[-1]

We keep the last line in logBuffer for future processing, remove that line from lines, and go on to display lines. That guards against the possibility of having an incomplete line at the end of the new content -- a sensible precaution.

In my observations, the common case is for the new content to be one or more complete structured log records, with a newline at the end of each record.

Suppose we receive, in batches, content such as:

<record 1>\n
<record 2>\n

<record 3>\n

<record 4>\n

<record 5>\n
<record 6>\n

When records 1 and 2 are received, record 1 is displayed and record 2 is placed in logBuffer. Note however that the trailing \n is removed: logBuffer = lines[-1] == "<record 2>".

When record 3 is received, it is appended to logBuffer, producing "<record 2><record 3>\n" -- just one line, which is again buffered with the newline stripped, logBuffer == "<record 2><record 3>". Nothing is displayed.

Same for record 4: logBuffer == "<record 2><record 3><record 4>" and still <record 1> is the only line that has been displayed.

When record 5 and record 6 are received, logBuffer == "<record 2><record 3><record 4><record 5>\n<record 6>\n" produces 2 lines, so 2, 3, 4, and 5 are finally displayed, with only record 6 buffered.

We can avoid the loss of newline by immediately displaying a complete line, only buffering when the new content does not end in a \n.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=e1358b89c25a shows that tests are not broken by this change. At a glance, logs look the same. Looking closer at mochitest-chrome, I see:

19:29:23     INFO -  267 INFO TEST-START | mobile/android/tests/browser/chrome/test_awsy_lite.html
19:29:36     INFO -  268 INFO Fresh start | Resident Memory: 209670144
19:30:10     INFO -  269 INFO Fresh start [+30s] | Resident Memory: 205434880
19:30:10     INFO -  270 INFO opening tab with url [http://mochi.test:8888/chrome/mobile/android/tests/browser/chrome/tp5/baidu.com/www.baidu.com/s@wd=mozilla.html]
19:31:16     INFO -  271 INFO opening tab with url [http://mochi.test:8888/chrome/mobile/android/tests/browser/chrome/tp5/twitter.com/twitter.com/ICHCheezburger.html]
19:32:48     INFO -  272 INFO opening tab with url [http://mochi.test:8888/chrome/mobile/android/tests/browser/chrome/tp5/msn.com/www.msn.com/index.html]
19:34:09     INFO -  273 INFO opening tab with url [http://mochi.test:8888/chrome/mobile/android/tests/browser/chrome/tp5/163.com/www.163.com/index.html]
19:36:35     INFO -  274 INFO opening tab with url [http://mochi.test:8888/chrome/mobile/android/tests/browser/chrome/tp5/bbc.co.uk/www.bbc.co.uk/news/index.html]
19:37:58     INFO -  275 INFO After tabs | Resident Memory: 257241088
19:38:23     INFO -  276 INFO After tabs [+30s] | Resident Memory: 268365824
19:38:23     INFO -  277 INFO After tabs [+30s, forced GC] | Resident Memory: 268365824
19:38:35     INFO -  278 INFO Tabs closed | Resident Memory: 251637760
19:39:01     INFO -  279 INFO Tabs closed [+30s] | Resident Memory: 231686144
19:39:01     INFO -  280 INFO Tabs closed [+30s, forced GC] | Resident Memory: 231686144

This timing is much better (fewer big lags) than that seen on mozilla-central:

10:13:23     INFO -  267 INFO TEST-START | mobile/android/tests/browser/chrome/test_awsy_lite.html
10:13:53     INFO -  268 INFO Fresh start | Resident Memory: 212008960
10:13:53     INFO -  269 INFO Fresh start [+30s] | Resident Memory: 203902976
10:21:16     INFO -  270 INFO opening tab with url [http://mochi.test:8888/chrome/mobile/android/tests/browser/chrome/tp5/baidu.com/www.baidu.com/s@wd=mozilla.html]
10:21:16     INFO -  271 INFO opening tab with url [http://mochi.test:8888/chrome/mobile/android/tests/browser/chrome/tp5/twitter.com/twitter.com/ICHCheezburger.html]
10:21:16     INFO -  272 INFO opening tab with url [http://mochi.test:8888/chrome/mobile/android/tests/browser/chrome/tp5/msn.com/www.msn.com/index.html]
10:21:16     INFO -  273 INFO opening tab with url [http://mochi.test:8888/chrome/mobile/android/tests/browser/chrome/tp5/163.com/www.163.com/index.html]
10:21:16     INFO -  274 INFO opening tab with url [http://mochi.test:8888/chrome/mobile/android/tests/browser/chrome/tp5/bbc.co.uk/www.bbc.co.uk/news/index.html]
10:21:16     INFO -  275 INFO After tabs | Resident Memory: 257601536
10:21:16     INFO -  276 INFO After tabs [+30s] | Resident Memory: 267972608
10:21:53     INFO -  277 INFO After tabs [+30s, forced GC] | Resident Memory: 267972608
10:21:53     INFO -  278 INFO Tabs closed | Resident Memory: 249585664
10:21:53     INFO -  279 INFO Tabs closed [+30s] | Resident Memory: 232140800
10:22:06     INFO -  280 INFO Tabs closed [+30s, forced GC] | Resident Memory: 232140800
Attachment #8775592 - Flags: review?(ahalberstadt)
Comment on attachment 8775592 [details] [diff] [review]
make android logging more responsive

Review of attachment 8775592 [details] [diff] [review]:
-----------------------------------------------------------------

Thanks for the detailed explanation! This makes sense. So does that mean logs are currently being displayed on the same line? I guess I'm just confused how this wasn't noticed until now and how it wasn't causing mayhem with the automation. Was it just rare for the situation you described to happen in practice?

::: build/mobile/remoteautomation.py
@@ +350,5 @@
> +                    self.logBuffer = ""
> +                else:
> +                    # keep the last (unfinished) line in the buffer
> +                    self.logBuffer = lines[-1]
> +                    del lines[-1]

Correct me if I'm wrong, but wouldn't prepending "\n" to self.logBuffer also work? I guess this way the last line is printed a bit faster, so it's better.
Attachment #8775592 - Flags: review?(ahalberstadt) → review+
(In reply to Andrew Halberstadt [:ahal] from comment #2)
> Thanks for the detailed explanation! This makes sense. So does that mean
> logs are currently being displayed on the same line? I guess I'm just
> confused how this wasn't noticed until now and how it wasn't causing mayhem
> with the automation. Was it just rare for the situation you described to
> happen in practice?

The situation I described is common for some long-running tests that produce sparse output, like test_awsy_lite, but most tests produce at least a couple of lines of output per "adb pull", and that moderates the impact significantly. When the \n is lost and lines are buffered, we still eventually pass all the records to the structured logging message logger and that seems to display everything correctly in the final test log -- so everything looks okay, it's just the timing that is off.

> Correct me if I'm wrong, but wouldn't prepending "\n" to self.logBuffer also
> work? I guess this way the last line is printed a bit faster, so it's better.

Yes! That was my first fix and it worked okay, but then I realized I could do a little better this way.
Pushed by gbrown@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/e5ae984c685b
Make Android test logging more responsive; r=ahal
https://hg.mozilla.org/mozilla-central/rev/e5ae984c685b
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 50
Duplicate of this bug: 1284362
You need to log in before you can comment on or make changes to this bug.