1570881 - Perma (tier2) /builds/worker/workspace/build/tests/jit-test/jit-test/tests/debug/Script-startColumn.js:11:13 Error: Assertion failed: got 9, expected 11

Status: RESOLVED FIXED

(Core :: JavaScript Engine, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: nerli [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=259522143&repo=mozilla-central
Full log: https://queue.taskcluster.net/v1/task/RbfvTp5TSRWrFs7l6vrOZQ/runs/0/artifacts/public/logs/live_backing.log

---

[task 2019-08-02T05:12:55.098Z] 05:12:55 INFO - TEST-PASS | tests/jit-test/jit-test/tests/debug/Script-sourceStart-04.js | Success (code 0, args "--blinterp-eager") [0.6 s]
[task 2019-08-02T05:12:55.106Z] 05:12:55 INFO - object name: f1
[task 2019-08-02T05:12:55.107Z] 05:12:55 INFO - [CodeCoverage] Setting handlers for process 878.
[task 2019-08-02T05:12:55.107Z] 05:12:55 INFO - /builds/worker/workspace/build/tests/jit-test/jit-test/tests/debug/Script-startColumn.js:11:13 Error: Assertion failed: got 9, expected 11
[task 2019-08-02T05:12:55.108Z] 05:12:55 INFO - Stack:
[task 2019-08-02T05:12:55.108Z] 05:12:55 INFO - test@/builds/worker/workspace/build/tests/jit-test/jit-test/tests/debug/Script-startColumn.js:11:13
[task 2019-08-02T05:12:55.110Z] 05:12:55 INFO - @/builds/worker/workspace/build/tests/jit-test/jit-test/tests/debug/Script-startColumn.js:18:5
[task 2019-08-02T05:12:55.111Z] 05:12:55 INFO - Exit code: 3
[task 2019-08-02T05:12:55.112Z] 05:12:55 INFO - FAIL - debug/Script-startColumn.js
[task 2019-08-02T05:12:55.114Z] 05:12:55 WARNING - TEST-UNEXPECTED-FAIL | tests/jit-test/jit-test/tests/debug/Script-startColumn.js | [CodeCoverage] Setting handlers for process 878. (code 3, args "") [0.5 s]
[task 2019-08-02T05:12:55.115Z] 05:12:55 INFO - INFO exit-status : 3
[task 2019-08-02T05:12:55.116Z] 05:12:55 INFO - INFO timed-out : False
[task 2019-08-02T05:12:55.117Z] 05:12:55 INFO - INFO stdout > object name: f1
[task 2019-08-02T05:12:55.119Z] 05:12:55 INFO - INFO stderr 2> [CodeCoverage] Setting handlers for process 878.
[task 2019-08-02T05:12:55.120Z] 05:12:55 INFO - INFO stderr 2> /builds/worker/workspace/build/tests/jit-test/jit-test/tests/debug/Script-startColumn.js:11:13 Error: Assertion failed: got 9, expected 11
[task 2019-08-02T05:12:55.122Z] 05:12:55 INFO - INFO stderr 2> Stack:
[task 2019-08-02T05:12:55.123Z] 05:12:55 INFO - INFO stderr 2> test@/builds/worker/workspace/build/tests/jit-test/jit-test/tests/debug/Script-startColumn.js:11:13
[task 2019-08-02T05:12:55.124Z] 05:12:55 INFO - INFO stderr 2> @/builds/worker/workspace/build/tests/jit-test/jit-test/tests/debug/Script-startColumn.js:18:5
[task 2019-08-02T05:12:55.488Z] 05:12:55 INFO - object name: f1
[task 2019-08-02T05:12:55.489Z] 05:12:55 INFO - [CodeCoverage] Setting handlers for process 884.
[task 2019-08-02T05:12:55.489Z] 05:12:55 INFO - /builds/worker/workspace/build/tests/jit-test/jit-test/tests/debug/Script-startColumn.js:11:13 Error: Assertion failed: got 9, expected 11
[task 2019-08-02T05:12:55.489Z] 05:12:55 INFO - Stack:
[task 2019-08-02T05:12:55.489Z] 05:12:55 INFO - test@/builds/worker/workspace/build/tests/jit-test/jit-test/tests/debug/Script-startColumn.js:11:13
[task 2019-08-02T05:12:55.490Z] 05:12:55 INFO - @/builds/worker/workspace/build/tests/jit-test/jit-test/tests/debug/Script-startColumn.js:18:5
[task 2019-08-02T05:12:55.490Z] 05:12:55 INFO - Exit code: 3
[task 2019-08-02T05:12:55.490Z] 05:12:55 INFO - FAIL - debug/Script-startColumn.js
[task 2019-08-02T05:12:55.491Z] 05:12:55 WARNING - TEST-UNEXPECTED-FAIL | tests/jit-test/jit-test/tests/debug/Script-startColumn.js | [CodeCoverage] Setting handlers for process 884. (code 3, args "--ion-eager --ion-offthread-compile=off --more-compartments") [0.7 s]
[task 2019-08-02T05:12:55.491Z] 05:12:55 INFO - INFO exit-status : 3
[task 2019-08-02T05:12:55.491Z] 05:12:55 INFO - INFO timed-out : False
[task 2019-08-02T05:12:55.491Z] 05:12:55 INFO - INFO stdout > object name: f1
[task 2019-08-02T05:12:55.492Z] 05:12:55 INFO - INFO stderr 2> [CodeCoverage] Setting handlers for process 884.

Comment 1

[Noemi Erli[:noemi_erli]]

This started to perma fail on central since https://bugzilla.mozilla.org/show_bug.cgi?id=901138 landed.
https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&resultStatus=testfailed%2Cbusted%2Cexception&classifiedState=unclassified&searchStr=debug-jittest-1proc-3%2C%28jit3%29&selectedJob=259528015

:mattheww could you please take a look at this?

Comment 2

[Intermittent Failures Robot]

26 failures in 866 pushes (0.03 failures/push) were associated with this bug yesterday.

Repository breakdown:

• mozilla-central: 26

Platform breakdown:

• linux64-ccov: 11
• windows10-64-ccov: 15

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1570881&startday=2019-08-02&endday=2019-08-02&tree=all

Comment 3

[mattheww]

I'm taking a look, I'm sorry about this.
Locally (win64, revision 37229c, debug assertions) the test still seems to be passing.
Column 9 corresponds to the start of the function name rather than the opening parenthesis. Could something about my settings or how I'm running it affect parsing in that way? (It could also be a coincidence and the offset is from something else.)

Comment 4

[Intermittent Failures Robot]

34 failures in 231 pushes (0.147 failures/push) were associated with this bug yesterday.

Repository breakdown:

• mozilla-central: 34

Platform breakdown:

• linux64-ccov: 18
• windows10-64-ccov: 16

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1570881&startday=2019-08-03&endday=2019-08-03&tree=all

Comment 5

[Razvan Maries]

Retriggers / backout: https://treeherder.mozilla.org/#/jobs?repo=autoland&searchStr=linux%2Cx64%2Cccov%2Cdebug%2Ctest-linux64-ccov%2Fdebug-jittest-1proc-3%2C%28jit3%29&fromchange=df552dfeb2d32a3847315f6da9e1aae1b4b25e65&tochange=22bda3da7ce3439a1ccafce4753ad59ad098bddc

https://hg.mozilla.org/mozilla-central/rev/07052ce569c3 is the only revision that touched Script-startColumn.js

Comment 6

[Intermittent Failures Robot]

77 failures in 4439 pushes (0.017 failures/push) were associated with this bug in the last 7 days.

This is the #18 most frequent failure this week.

** This failure happened more than 75 times this week! Resolving this bug is a very high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 1 week, the affected test(s) may be disabled. **

Repository breakdown:

• mozilla-central: 64
• autoland: 13

Platform breakdown:

• linux64-ccov: 44
• windows10-64-ccov: 33

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1570881&startday=2019-07-29&endday=2019-08-04&tree=all

Comment 7

[Jim Blandy :jimb]

Status update: I downloaded the shell built from one of the failing jobs, and ran the test on my machine; it passes. I'm trying a try push of that single job now, based on changeset 4748c006ae7b, to see if that also fails.

It's very odd that only the coverage test fails. It suggests that the patch might be hitting some undefined behavior, which is bad.

Comment 8

[Intermittent Failures Robot]

60 failures in 4666 pushes (0.013 failures/push) were associated with this bug in the last 7 days.

This is the #24 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• mozilla-central: 60

Platform breakdown:

• linux64-ccov: 30
• windows10-64-ccov: 30

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1570881&startday=2019-08-05&endday=2019-08-11&tree=all

Comment 9

[Dorel Luca [:dluca]]

This bug failed 60 times in the last 7 days. Occurs on Ccov platforms on debug build types.

Recent log:
https://treeherder.mozilla.org/logviewer.html#?job_id=262195656&repo=mozilla-central

Comment 10

[mattheww]

I'm still not sure why this is happening, and I support backing out the startColumn patch.
I believe the property getter is working correctly, and is reading a bogus value that was written to the script. In the failing test, the script's value is copied from the LazyScript here and asserted equal to it here. If the LazyScript's position were wrong, other tests would fail, so it must be going wrong after the assertion. I'd like to add more assertions and see the output of the other tests, but I don't think it would narrow it down enough to matter.
Is it possible to access the binaries that are failing, or get an exact copy of the build environment? I haven't been able to reproduce the failure locally. The try server wiki article suggests you can download their build output, but all the files on the linked FTP site are from 2018.

Comment 11

[Intermittent Failures Robot]

60 failures in 4839 pushes (0.012 failures/push) were associated with this bug in the last 7 days.

This is the #40 most frequent failure this week.

** This test has failed more than 150 times in the last 21 days. It should be disabled until it can be fixed. **

Repository breakdown:

• mozilla-central: 60

Platform breakdown:

• linux64-ccov: 30
• windows10-64-ccov: 30

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1570881&startday=2019-08-12&endday=2019-08-18&tree=all

Comment 12

[Arthur Iakab [arthur_iakab]]

Joel what are your thoughts, should we backout startColumn patch from Bug 901138?

Comment 13

[Joel Maher ( :jmaher ) (UTC -8)]

MatthewW- it is possible to download the build/test/binaries. Keep in mind this is on linux (ubuntu 16.04), probably not a requirement to use our docker image.

As for running the test, you can look at a raw log [1] and see:
[task 2019-08-04T10:56:26.220Z] 10:56:26 INFO - Downloading and extracting to /builds/worker/workspace/build/tests these dirs * from https://queue.taskcluster.net/v1/task/H2BnddiMQ9GmGz8rqyHSRA/artifacts/public/build/target.common.tests.tar.gz

[task 2019-08-04T10:57:08.562Z] 10:57:08 INFO - Downloading and extracting to /builds/worker/workspace/build/tests/bin these dirs * from https://queue.taskcluster.net/v1/task/H2BnddiMQ9GmGz8rqyHSRA/artifacts/public/build/target.jsshell.zip

[task 2019-08-04T10:57:39.728Z] 10:57:39 INFO - Downloading https://queue.taskcluster.net/v1/task/H2BnddiMQ9GmGz8rqyHSRA/artifacts/public/build/target.tar.bz2 to /builds/worker/workspace/build/installer.tar.bz2

and then the command:
[task 2019-08-04T11:01:37.434Z] 11:01:37 INFO - Copy/paste: /builds/worker/workspace/build/venv/bin/python -u /builds/worker/workspace/build/tests/jit-test/jit-test/jit_test.py --total-chunks 6 --this-chunk 3 tests/bin/js --no-slow --no-progress --format=automation --jitflags=all --timeout=970

This can also be tweaked and tested on try.

As for backing out, I agree this is a good path forward while MatthewW reproduces/fixes this.

[1] https://taskcluster-artifacts.net/HpWWvcmESnW_8_nNZHxVdw/0/public/logs/live_backing.log

Comment 14

[mattheww]

Thank you for pointing that out! I thought the artifact links in treeherder were all that were available.
I still can't recreate the bug, using the linked binaries and that command, in ubuntu 18.04 or the docker image. I don't know how it can be so consistent and so elusive. I need to read up on docker so I can run it properly.

Comment 15

[mattheww]

I found it, and there was never any undefined behavior. One of the places setting startColumn was simply wrong and my tests never reached it normally.
FunctionBox and LazyScript consistently use their function's opening parenthesis for their position. All of my tests used lazily parsed functions and in non-ccov tests those positions were always used. However, BytecodeEmitter::emitFunction() instead uses the FunctionNode's position, which is usually the "function" keyword or the function's name.
Having the environment variable JS_CODE_COVERAGE_OUTPUT_DIR set causes the functions in the test to be parsed non-lazily, which leads to them calling emitFunction() and seeing its incorrect (?) output.

Comment 16

[mattheww]

Attachment: Update remaining BytecodeEmitter constructor to use FunctionBox line/column

Comment 17

[Intermittent Failures Robot]

74 failures in 5073 pushes (0.015 failures/push) were associated with this bug in the last 7 days.

This is the #25 most frequent failure this week.

** This test has failed more than 150 times in the last 21 days. It should be disabled until it can be fixed. **

Repository breakdown:

• mozilla-central: 74

Platform breakdown:

• linux64-ccov: 35
• windows10-64-ccov: 39

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1570881&startday=2019-08-19&endday=2019-08-25&tree=all

Comment 18

[Intermittent Failures Robot]

59 failures in 5047 pushes (0.012 failures/push) were associated with this bug in the last 7 days.

This is the #29 most frequent failure this week.

** This test has failed more than 150 times in the last 21 days. It should be disabled until it can be fixed. **

Repository breakdown:

• mozilla-central: 59

Platform breakdown:

• linux64-ccov: 30
• windows10-64-ccov: 29

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1570881&startday=2019-08-26&endday=2019-09-01&tree=all

Comment 19

[Razvan Maries]

There are 65 total failures in the last 7 days: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-08-27&endday=2019-09-03&tree=trunk&bug=1570881

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=264709943&repo=mozilla-central&lineNumber=7403

Comment 20

[Jim Blandy :jimb]

(In reply to mattheww from comment #15)

Having the environment variable JS_CODE_COVERAGE_OUTPUT_DIR set causes the functions in the test to be parsed non-lazily, which leads to them calling emitFunction() and seeing its incorrect (?) output.

Holy cow, that's a smoking gun that I never expected.

Comment 21

[Andreea Pavel [:apavel]]

Hi mattheww , are there updates here?

There are 70 total failures in the last 7 days on linux64-ccov, windows10-64-ccov both debug

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=265245153&repo=mozilla-central&lineNumber=7485

[task 2019-09-05T23:22:11.229Z] 23:22:11 INFO - TEST-PASS | tests/jit-test/jit-test/tests/debug/Script-sourceStart-04.js | Success (code 0, args "") [0.6 s]
[task 2019-09-05T23:22:11.573Z] 23:22:11 INFO - TEST-PASS | tests/jit-test/jit-test/tests/debug/Script-sourceStart-04.js | Success (code 0, args "--ion-eager --ion-offthread-compile=off --more-compartments") [0.7 s]
[task 2019-09-05T23:22:11.595Z] 23:22:11 INFO - TEST-PASS | tests/jit-test/jit-test/tests/debug/Script-sourceStart-04.js | Success (code 0, args "--ion-eager --ion-offthread-compile=off --ion-check-range-analysis --ion-extra-checks --no-sse3 --no-threads") [0.6 s]
[task 2019-09-05T23:22:11.772Z] 23:22:11 INFO - TEST-PASS | tests/jit-test/jit-test/tests/debug/Script-sourceStart-04.js | Success (code 0, args "--baseline-eager") [0.6 s]
[task 2019-09-05T23:22:11.817Z] 23:22:11 INFO - TEST-PASS | tests/jit-test/jit-test/tests/debug/Script-sourceStart-04.js | Success (code 0, args "--no-blinterp --no-baseline --no-ion --more-compartments") [0.6 s]
[task 2019-09-05T23:22:12.148Z] 23:22:12 INFO - TEST-PASS | tests/jit-test/jit-test/tests/debug/Script-sourceStart-04.js | Success (code 0, args "--blinterp-eager") [0.6 s]
[task 2019-09-05T23:22:12.164Z] 23:22:12 INFO - object name: f1
[task 2019-09-05T23:22:12.164Z] 23:22:12 INFO - [CodeCoverage] Setting handlers for process 867.
[task 2019-09-05T23:22:12.166Z] 23:22:12 INFO - /builds/worker/workspace/build/tests/jit-test/jit-test/tests/debug/Script-startColumn.js:11:13 Error: Assertion failed: got 9, expected 11
[task 2019-09-05T23:22:12.167Z] 23:22:12 INFO - Stack:
[task 2019-09-05T23:22:12.167Z] 23:22:12 INFO - test@/builds/worker/workspace/build/tests/jit-test/jit-test/tests/debug/Script-startColumn.js:11:13
[task 2019-09-05T23:22:12.168Z] 23:22:12 INFO - @/builds/worker/workspace/build/tests/jit-test/jit-test/tests/debug/Script-startColumn.js:18:5
[task 2019-09-05T23:22:12.169Z] 23:22:12 INFO - Exit code: 3
[task 2019-09-05T23:22:12.171Z] 23:22:12 INFO - FAIL - debug/Script-startColumn.js
[task 2019-09-05T23:22:12.171Z] 23:22:12 WARNING - TEST-UNEXPECTED-FAIL | tests/jit-test/jit-test/tests/debug/Script-startColumn.js | [CodeCoverage] Setting handlers for process 867. (code 3, args "") [0.6 s]
[task 2019-09-05T23:22:12.172Z] 23:22:12 INFO - INFO exit-status : 3
[task 2019-09-05T23:22:12.173Z] 23:22:12 INFO - INFO timed-out : False
[task 2019-09-05T23:22:12.174Z] 23:22:12 INFO - INFO stdout > object name: f1
[task 2019-09-05T23:22:12.175Z] 23:22:12 INFO - INFO stderr 2> [CodeCoverage] Setting handlers for process 867.
[task 2019-09-05T23:22:12.175Z] 23:22:12 INFO - INFO stderr 2> /builds/worker/workspace/build/tests/jit-test/jit-test/tests/debug/Script-startColumn.js:11:13 Error: Assertion failed: got 9, expected 11
[task 2019-09-05T23:22:12.176Z] 23:22:12 INFO - INFO stderr 2> Stack:
[task 2019-09-05T23:22:12.177Z] 23:22:12 INFO - INFO stderr 2> test@/builds/worker/workspace/build/tests/jit-test/jit-test/tests/debug/Script-startColumn.js:11:13
[task 2019-09-05T23:22:12.178Z] 23:22:12 INFO - INFO stderr 2> @/builds/worker/workspace/build/tests/jit-test/jit-test/tests/debug/Script-startColumn.js:18:5
[task 2019-09-05T23:22:12.489Z] 23:22:12 INFO - object name: f1
[task 2019-09-05T23:22:12.489Z] 23:22:12 INFO - [CodeCoverage] Setting handlers for process 877.
[task 2019-09-05T23:22:12.490Z] 23:22:12 INFO - /builds/worker/workspace/build/tests/jit-test/jit-test/tests/debug/Script-startColumn.js:11:13 Error: Assertion failed: got 9, expected 11
[task 2019-09-05T23:22:12.492Z] 23:22:12 INFO - Stack:
[task 2019-09-05T23:22:12.494Z] 23:22:12 INFO - test@/builds/worker/workspace/build/tests/jit-test/jit-test/tests/debug/Script-startColumn.js:11:13
[task 2019-09-05T23:22:12.496Z] 23:22:12 INFO - @/builds/worker/workspace/build/tests/jit-test/jit-test/tests/debug/Script-startColumn.js:18:5
[task 2019-09-05T23:22:12.497Z] 23:22:12 INFO - Exit code: 3
[task 2019-09-05T23:22:12.499Z] 23:22:12 INFO - FAIL - debug/Script-startColumn.js

Comment 22

[mattheww]

I'm hammering out a fix right now. I hope to have it done by next week, but I'm okay with whatever has to be done to stop it failing.

Comment 23

[Andreea Pavel [:apavel]]

Thank you.
There are 267 total failures in the last 30 days, Geoff, can this be disabled?

Comment 24

[Intermittent Failures Robot]

61 failures in 4408 pushes (0.014 failures/push) were associated with this bug in the last 7 days.

This is the #24 most frequent failure this week.

** This test has failed more than 150 times in the last 21 days. It should be disabled until it can be fixed. **

Repository breakdown:

• mozilla-central: 60
• try: 1

Platform breakdown:

• linux64-ccov: 31
• windows10-64-ccov: 30

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1570881&startday=2019-09-02&endday=2019-09-08&tree=all

Comment 25

[Geoff Brown [:gbrown]]

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

Thank you.
There are 267 total failures in the last 30 days, Geoff, can this be disabled?

Yes. I think you can skip on ccov by adding this test to:

https://searchfox.org/mozilla-central/rev/8ecd15049c11eb753717a6631213ba5ecc90e123/js/src/jit-test/jit_test.py#259-279

Comment 26

[Bogdan Tara[:bogdan_tara | bogdant]]

Attachment: Bug 1570881 - disable Script-startColumn.js for frequent failures r=#intermittent-reviewers

Comment 27

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/9f48d7135ec3
disable Script-startColumn.js for frequent failures r=gbrown

Comment 28

[Oana Pop-Rus]

https://hg.mozilla.org/mozilla-central/rev/9f48d7135ec3

Comment 29

[Intermittent Failures Robot]

17 failures in 955 pushes (0.018 failures/push) were associated with this bug yesterday.

Repository breakdown:

• mozilla-central: 16
• try: 1

Platform breakdown:

• linux64-ccov: 8
• windows10-64-ccov: 9

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1570881&startday=2019-09-10&endday=2019-09-10&tree=all

Comment 30

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 25
• try: 2

Platform breakdown:

• linux64-ccov: 13
• windows10-64-ccov: 14

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1570881&startday=2019-09-09&endday=2019-09-15&tree=all

Comment 31

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/7edc6f28197b
Update remaining BytecodeEmitter constructor to use FunctionBox line/column r=jimb

Comment 32

[Cosmin Sabou [:CosminS]]

https://hg.mozilla.org/mozilla-central/rev/7edc6f28197b