1768061 - Intermittent raptor-browsertime Critical: VisualMetrics failed to run SyntaxError: Unexpected end of JSON input | raptor-browsertime Error: Browsertime failed to run

Status: RESOLVED FIXED

(Testing :: Raptor, defect, P5)

Description

[Treeherder Bug Filer]

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

---

INFO -  raptor-browsertime Info: Browsertime pageload ended.
[task 2022-05-05T18:35:59.245Z] 18:35:53     INFO -  raptor-browsertime Info: Thu, 05 May 2022 18:35:53 GMT adb:command Send '001Bhost:transport:HT86B1A00738'
[task 2022-05-05T18:35:59.245Z] 18:35:53     INFO -  raptor-browsertime Info: Thu, 05 May 2022 18:35:53 GMT adb:command Send '0040shell:dumpsys battery | grep temperature | grep -Eo '[0-9]{1,3}''
[task 2022-05-05T18:35:59.245Z] 18:35:53     INFO -  raptor-browsertime Info: Get visual metrics from the video
[task 2022-05-05T18:35:59.245Z] 18:35:53    ERROR -  raptor-browsertime Error: Browsertime failed to run
[task 2022-05-05T18:35:59.245Z] 18:35:53     INFO -  raptor-browsertime Info:     at JSON.parse (<anonymous>)
[task 2022-05-05T18:35:59.245Z] 18:35:53     INFO -  raptor-browsertime Info:     at Object.run (/builds/task_165177458143528/fetches/browsertime/node_modules/browsertime/lib/video/postprocessing/visualmetrics/visualMetrics.js:149:19)
[task 2022-05-05T18:35:59.245Z] 18:35:53     INFO -  raptor-browsertime Info:     at async module.exports (/builds/task_165177458143528/fetches/browsertime/node_modules/browsertime/lib/video/postprocessing/visualmetrics/getVideoMetrics.js:34:21)
[task 2022-05-05T18:35:59.245Z] 18:35:53     INFO -  raptor-browsertime Info:     at async Video.postProcessing (/builds/task_165177458143528/fetches/browsertime/node_modules/browsertime/lib/video/video.js:94:22)
[task 2022-05-05T18:35:59.245Z] 18:35:53     INFO -  raptor-browsertime Info:     at async Iteration.run (/builds/task_165177458143528/fetches/browsertime/node_modules/browsertime/lib/core/engine/iteration.js:261:34)
[task 2022-05-05T18:35:59.245Z] 18:35:53     INFO -  raptor-browsertime Info:     at async Engine.runByScript (/builds/task_165177458143528/fetches/browsertime/node_modules/browsertime/lib/core/engine/index.js:266:20)
[task 2022-05-05T18:35:59.245Z] 18:35:53     INFO -  raptor-browsertime Info:     at async run (/builds/task_165177458143528/fetches/browsertime/node_modules/browsertime/bin/browsertime.js:71:22)
[task 2022-05-05T18:35:59.245Z] 18:35:53    ERROR -  raptor-browsertime Critical: VisualMetrics failed to run SyntaxError: Unexpected end of JSON input
[task 2022-05-05T18:35:59.245Z] 18:35:53     INFO -  raptor-browsertime-android Info: removing reverse socket connections
[task 2022-05-05T18:35:59.245Z] 18:35:53     INFO -  adb command_output: adb -s HT86B1A00738 wait-for-device reverse --remove-all, timeout: None, timedout: None, exitcode: 0, output:
[task 2022-05-05T18:35:59.245Z] 18:35:53     INFO -  adb shell_bool: adb -s HT86B1A00738 wait-for-device shell test -d /sdcard/Android/data/org.mozilla.geckoview_example/files/test_root/org.mozilla.geckoview_example-geckodriver-profile/minidumps, timeout: None, timedout: None, exitcode: 1, output:
[task 2022-05-05T18:35:59.245Z] 18:35:53     INFO -  raptor-mitmproxy Info: Mitmproxy stop!!
[task 2022-05-05T18:35:59.245Z] 18:35:53     INFO -  raptor-mitmproxy Info: Stopping mitmproxy playback, killing process 1487
[task 2022-05-05T18:35:59.245Z] 18:35:54     INFO -  raptor-mitmproxy Info: Successfully killed the mitmproxy playback process
[task 2022-05-05T18:35:59.245Z] 18:35:54     INFO -  raptor-perftest Info: Removing temporary directory: /tmp/tmpk8iawc2z
[task 2022-05-05T18:35:59.245Z] 18:35:54    ERROR -  Traceback (most recent call last):
[task 2022-05-05T18:35:59.245Z] 18:35:54     INFO -    File "/builds/task_165177458143528/workspace/build/tests/raptor/raptor/raptor.py", line 215, in <module>
[task 2022-05-05T18:35:59.245Z] 18:35:54     INFO -      main()
[task 2022-05-05T18:35:59.245Z] 18:35:54     INFO -    File "/builds/task_165177458143528/workspace/build/tests/raptor/raptor/raptor.py", line 161, in main
[task 2022-05-05T18:35:59.245Z] 18:35:54     INFO -      success = raptor.run_tests(raptor_test_list, raptor_test_names)
[task 2022-05-05T18:35:59.245Z] 18:35:54     INFO -    File "/builds/task_165177458143528/workspace/build/tests/raptor/raptor/browsertime/android.py", line 242, in run_tests
[task 2022-05-05T18:35:59.245Z] 18:35:54     INFO -      return super(BrowsertimeAndroid, self).run_tests(tests, test_names)
[task 2022-05-05T18:35:59.245Z] 18:35:54     INFO -    File "/builds/task_165177458143528/workspace/build/tests/raptor/raptor/perftest.py", line 457, in run_tests
[task 2022-05-05T18:35:59.245Z] 18:35:54     INFO -      self.run_test(test, timeout=int(test.get("page_timeout")))
[task 2022-05-05T18:35:59.245Z] 18:35:54     INFO -    File "/builds/task_165177458143528/workspace/build/tests/raptor/raptor/browsertime/base.py", line 596, in run_test
[task 2022-05-05T18:35:59.245Z] 18:35:54     INFO -      raise Exception(self.browsertime_failure)
[task 2022-05-05T18:35:59.245Z] 18:35:54    ERROR -  Exception: VisualMetrics failed to run SyntaxError: Unexpected end of JSON input
[task 2022-05-05T18:35:59.245Z] 18:35:54    ERROR - Return code: 1
[task 2022-05-05T18:35:59.245Z] 18:35:54  WARNING - setting return code to 1

Comment 1

[Marian-Vasile Laza]

Retriggers/backfills - 1st appearance: https://treeherder.mozilla.org/jobs?repo=autoland&searchStr=Android%2C8.0%2CPixel2%2CAArch64%2CShippable%2CWebRender%2Copt%2CBrowsertime%2Cperformance%2Ctests%2Con%2CFirefox%2Ctest-android-hw-p2-8-0-android-aarch64-shippable-qr%2Fopt-browsertime-tp6m-geckoview-stackoverflow-e10s%2Cstacko&tochange=089ee3fa51ea95feebc5915415edfcd2a08b79d5&fromchange=cef7cb4d90ab7320fac4e599a6f27d2e0e67b4ca&selectedTaskRun=a0cPT0LlRpexiVUy-tW7cg.0

Comment 2

[Andreea Pavel [:apavel]]

Hi Greg, can this be a regression of bug 1767436?

Comment 3

[BugBot [:suhaib / :marco/ :calixte]]

Set release status flags based on info from the regressing bug 1767436

Comment 4

[Intermittent Failures Robot]

8 failures in 3540 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 2
• autoland: 5
• fenix: 1

Platform and build breakdown:

• android-hw-p2-8-0-android-aarch64-shippable-qr: 7
  • opt: 7
• windows10-64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1768061&startday=2022-05-02&endday=2022-05-08&tree=all

Comment 5

[Greg Mierzwinski [:sparky]]

(In reply to Andreea Pavel [:apavel] from comment #2)

Hi Greg, can this be a regression of bug 1767436?

Hi, yes it certainly looks like it. Thanks for the backfills!

Comment 6

[Intermittent Failures Robot]

14 failures in 3317 pushes (0.004 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 9
• mozilla-central: 3
• fenix: 2

Platform and build breakdown:

• windows10-64-shippable-qr: 1
  • opt: 1
• android-hw-g5-7-0-arm7-shippable-qr: 2
  • opt: 2
• android-hw-p2-8-0-android-aarch64-shippable-qr: 11
  • opt: 11

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

Comment 7

[Intermittent Failures Robot]

22 failures in 2694 pushes (0.008 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 16
• fenix: 2
• mozilla-central: 4

Platform and build breakdown:

• android-hw-p2-8-0-android-aarch64-shippable-qr: 18
  • opt: 18
• android-hw-g5-7-0-arm7-shippable-qr: 3
  • opt: 3
• windows10-64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1768061&startday=2022-05-16&endday=2022-05-22&tree=all

Comment 8

[Greg Mierzwinski [:sparky]]

Peter, have you seen this kind of error before when processing visual metrics?

Comment 9

[Peter Hedenskog]

No, but looking at the code I think that error code happen if Visual Metrics do not produce any JSON. I think I can fix so that we log the output from Visual Metrics if it happens, so its easier to understand what's going on.

Comment 10

[Peter Hedenskog]

Actually it should already log the output from Visual Metrics if it fails, it should be on error level and start with: Log from VisualMetrics but I couldn't see that in https://firefoxci.taskcluster-artifacts.net/fvgiYioaSKGgxNHaixen_Q/0/public/logs/live_backing.log - is that the right place to look?

Comment 11

[Greg Mierzwinski [:sparky]]

That's the right place to look, but I'm not sure what's happening to the logs but here is the video it failed on: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/VNKrAclRQ7KPWseEe_Zbrg/runs/0/artifacts/public/test_info/browsertime-results/booking/pages/www_booking_com/data/video/12.mp4.failed.mp4

If you haven't seen it before, then I'll look into it now. Thanks for the prompt response Peter!

Comment 12

[Greg Mierzwinski [:sparky]]

Ah so the video is corrupted. This isn't something related to visual metrics processing but rather with video generation. We've seen this elsewhere as well and the best idea we have right now is to replace the MP4 encoding with one that doesn't write important information at the end of the stream.

Comment 13

[Peter Hedenskog]

Yeah but I wonder why the video is corrupt. It's on a mobile phone right? I think we need to increase the time between where we stop the video and then transfer it over from the memory card to the computer. That is 5 seconds now but you can configure it with --videoParams.androidVideoWaitTime (in ms sorry). Try to increase it I'm pretty sure it will fix the problem :)

Comment 14

[Greg Mierzwinski [:sparky]]

(In reply to Peter Hedenskog from comment #13)

Yeah but I wonder why the video is corrupt. It's on a mobile phone right? I think we need to increase the time between where we stop the video and then transfer it over from the memory card to the computer. That is 5 seconds now but you can configure it with --videoParams.androidVideoWaitTime (in ms sorry). Try to increase it I'm pretty sure it will fix the problem :)

I think it's something in the firefox window recorder that is causing it last time I checked. This isn't the first time we've had issues with it either, see bug 1708940 for an example. We'll try increasing the wait time though just in case, thanks! :andrej, could you look into this further?

Comment 15

[Intermittent Failures Robot]

17 failures in 2624 pushes (0.006 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 11
• mozilla-central: 5
• fenix: 1

Platform and build breakdown:

• android-hw-p2-8-0-android-aarch64-shippable-qr: 14
  • opt: 14
• android-hw-g5-7-0-arm7-api-16-shippable-qr: 1
  • opt: 1
• windows10-64-shippable-qr: 1
  • opt: 1
• android-hw-p2-8-0-arm7-shippable-qr: 1
  • opt: 1

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

Comment 16

[Andrej (:aglavic)]

Sure I can take a look into this

Comment 17

[Andrej (:aglavic)]

Attachment: Bug 1768061 - Increase wait time for obtaining video from android device, to resolve intermittent raptor-browsertime unexpected end of JSON input. r?#perftest

Comment 18

[Intermittent Failures Robot]

22 failures in 2917 pushes (0.008 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 4
• mozilla-beta: 4
• fenix: 5
• autoland: 9

Platform and build breakdown:

• android-hw-p2-8-0-android-aarch64-shippable-qr: 20
  • opt: 20
• android-hw-p2-8-0-arm7-shippable-qr: 1
  • opt: 1
• android-hw-g5-7-0-arm7-shippable-qr: 1
  • opt: 1

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

Comment 19

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/8c940ab86a87
Increase wait time for obtaining video from android device, to resolve intermittent raptor-browsertime unexpected end of JSON input. r=perftest-reviewers,sparky

Comment 20

[Norisz Fay [:noriszfay]]

https://hg.mozilla.org/mozilla-central/rev/8c940ab86a87

Comment 21

[BugBot [:suhaib / :marco/ :calixte]]

The patch landed in nightly and beta is affected.
:andrej, is this bug important enough to require an uplift?
If not please set status_beta to wontfix.

For more information, please visit auto_nag documentation.

Comment 22

[Alexandru Ionescu (needinfo me) [:alexandrui]]

(In reply to Pulsebot from comment #19)

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/8c940ab86a87
Increase wait time for obtaining video from android device, to resolve
intermittent raptor-browsertime unexpected end of JSON input.
r=perftest-reviewers,sparky

== Change summary for alert #34356 (as of Wed, 08 Jun 2022 23:39:35 GMT) ==

Improvements:

Ratio	Test	Platform	Options	Absolute values (old vs new)
18%	facebook fcp	android-hw-p2-8-0-android-aarch64-shippable-qr	warm webrender	317.96 -> 259.96
16%	facebook-cristiano fcp	android-hw-p2-8-0-android-aarch64-shippable-qr	warm webrender	314.90 -> 263.08
14%	facebook FirstVisualChange	android-hw-p2-8-0-android-aarch64-shippable-qr	warm webrender	334.12 -> 287.42
12%	facebook PerceptualSpeedIndex	android-hw-p2-8-0-android-aarch64-shippable-qr	warm webrender	373.50 -> 330.08

For up to date results, see: https://treeherder.mozilla.org/perfherder/alerts?id=34356

Comment 23

[Intermittent Failures Robot]

15 failures in 3336 pushes (0.004 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 10
• mozilla-beta: 5

Platform and build breakdown:

• android-hw-p2-8-0-android-aarch64-shippable-qr: 13
  • opt: 13
• android-hw-p2-8-0-arm7-shippable-qr: 2
  • opt: 2

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

Comment 24

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• android-hw-p2-8-0-android-aarch64-shippable-qr: 1
  • opt: 1

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