1603038 - ubuntu1804 - remote/test/browser/input/browser_dispatchKeyEvent_events.js | Test timed out -

Reporter

Description

•

5 years ago

treeherder

Filed by: egao [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=280628876&repo=try
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/a0spCWBkQXSMJvtUN4jtBQ/runs/0/artifacts/public/logs/live_backing.log

suite: mochitest-remote
extra: fission

context:
[task 2019-12-11T08:03:55.015Z] 08:03:55 [task 2019-12-11T08:04:40.027Z] 08:04:40 [task 2019-12-11T08:04:40.371Z] 08:04:40 [task 2019-12-11T08:04:40.371Z] 08:04:40 [task 2019-12-11T08:04:40.371Z] 08:04:40 [task 2019-12-11T08:04:40.371Z] 08:04:40 [task 2019-12-11T08:04:40.371Z] 08:04:40 [task 2019-12-11T08:04:40.371Z] 08:04:40 [task 2019-12-11T08:04:40.371Z] 08:04:40 [task 2019-12-11T08:04:40.371Z] 08:04:40 [task 2019-12-11T08:04:40.371Z] 08:04:40 [task 2019-12-11T08:04:40.371Z] 08:04:40 [task 2019-12-11T08:04:40.371Z] 08:04:40 [task 2019-12-11T08:04:40.371Z] 08:04:40 [task 2019-12-11T08:04:40.371Z] 08:04:40 [task 2019-12-11T08:04:40.375Z] 08:04:40 [task 2019-12-11T08:04:40.375Z] 08:04:40 [task 2019-12-11T08:04:40.375Z] 08:04:40 [task 2019-12-11T08:04:40.375Z] 08:04:40 [task 2019-12-11T08:04:40.375Z] 08:04:40 [task 2019-12-11T08:04:40.375Z] 08:04:40 INFO - TEST-START | remote/test/browser/input/browser_dispatchKeyEvent_events.js
INFO - TEST-INFO | started process screentopng
INFO - TEST-INFO | screentopng: exit 0
INFO - Buffered messages logged at 08:03:55
INFO - Entering test bound
INFO - CDP server started
INFO - CDP client instantiated
INFO - Buffered messages logged at 08:03:56
INFO - Focus the input on the page
INFO - TEST-PASS | remote/test/browser/input/browser_dispatchKeyEvent_events.js | Input should be focused - {} == {} -
INFO - TEST-PASS | remote/test/browser/input/browser_dispatchKeyEvent_events.js | Check input content - "" == "" -
INFO - TEST-PASS | remote/test/browser/input/browser_dispatchKeyEvent_events.js | Check position of input caret - 0 == 0 -
INFO - TEST-PASS | remote/test/browser/input/browser_dispatchKeyEvent_events.js | List of events should be empty - 0 == 0 -
INFO - Send rawKeyDown for key Shift
INFO - Buffered messages finished
INFO - TEST-UNEXPECTED-FAIL | remote/test/browser/input/browser_dispatchKeyEvent_events.js | Test timed out -
INFO - GECKO(2092) | MEMORY STAT | vsize 3038MB | residentFast 316MB | heapAllocated 102MB
INFO - TEST-OK | remote/test/browser/input/browser_dispatchKeyEvent_events.js | took 45018ms
INFO - Not taking screenshot here: see the one that was previously logged
INFO - TEST-UNEXPECTED-FAIL | remote/test/browser/input/browser_dispatchKeyEvent_events.js | Found a tab after previous test timed out: http://example.com/browser/remote/test/browser/input/doc_events.html -
INFO - checking window state

Edwin Takahashi (:egao | infrequent contributor)

Comment 1

•

5 years ago

:maja - I've needinfo'd you after looking at the file changelog on searchfox.

This is a permafail on ubuntu1804 only when run with fission. The ubuntu1804-test image is planned to replace the current desktop1604-test image that is in use.

To push to try with ubuntu1804-test, use ./mach try fuzzy --ubuntu-bionic and select test-linux64 jobs as normal.

Blocks: 1572247

Flags: needinfo?(mjzffr)

Edwin Takahashi (:egao | infrequent contributor)

Updated

•

5 years ago

See Also: → https://bugzilla.mozilla.org/show_bug.cgi?id=1603040

Henrik Skupin [:whimboo][⌚️UTC+2]

Comment 2

•

5 years ago

Edwin, do you see this locally too? Could you run the test with `--setpref="remote.log.level=Trace"? It would be good to know which command that actually is.

Maja Frydrychowicz :impossibus (was :maja_zf) (needinfo me)

Comment 3

•

5 years ago

Looks like I can reproduce this and Bug 1603040 locally.

Edwin Takahashi (:egao | infrequent contributor)

Comment 4

•

5 years ago

Do you still want me to reproduce this on my ubuntu1804 VM?

Flags: needinfo?(mjzffr)

Maja Frydrychowicz :impossibus (was :maja_zf) (needinfo me)

Comment 5

•

5 years ago

Yeah, could you run the following commands in your VM against revision 79a88a2, please? The tests pass for me at 79a88a2, but start failing intermittently (or with --verify) a few revisions later (e.g. d9d678e7422e).

./mach test --headless remote/test/browser/browser_cdp.js && ./mach mochitest --headless --enable-fission remote/test/browser/input/browser_dispatchKeyEvent_race.js 
./mach mochitest --headless --enable-fission remote/test/browser/input --verify --verify-max-time 108000

From what I can tell so far, this has something to do with tests that depend on files served by the test harness, some interaction between that and the remote agent command dispatcher maybe? After loading a support file URL (as opposed to a data URL), any call to a remote agent command times out. By support file URL I mean, in this case, an HTML document served by the test harness. This and Bug 1603040 are the only two tests under remote/ that involve such resources.

Flags: needinfo?(egao)

Edwin Takahashi (:egao | infrequent contributor)

Comment 6

•

5 years ago

I checked out 79a88a2, performed an artifact build, then ran the two commands you posted.

The logs are long so I will omit them, but as far as I can tell it ran 3 test commands.
Each command ran a suite of tests, and all of them turned out OK.

Flags: needinfo?(egao)

Comment hidden (Intermittent Failures Robot)

Maja Frydrychowicz :impossibus (was :maja_zf) (needinfo me)

Comment 8

•

5 years ago

Thanks, and do the commands fail at d9d678e7422e?

Flags: needinfo?(egao)

Edwin Takahashi (:egao | infrequent contributor)

Comment 9

•

5 years ago

Sorry I had not tested it at d9d678e7422e - I will report back and edit this comment once the runs finish.

EDIT: I have results:

The first pair of commands pass.

The second line of command fails:

mochitest-browser
~~~~~~~~~~~~~~~~~
Ran 2027 checks (1972 subtests, 55 tests)
Expected results: 2026
Unexpected results: 1
  subtest: 1 (1 fail)

Unexpected Results
------------------
remote/test/browser/input/browser_dispatchKeyEvent.js
  FAIL This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. -

The test that failed:

14:24.12 TEST_START: remote/test/browser/input/browser_dispatchKeyEvent.js
14:24.13 INFO Entering test bound 
14:26.72 GECKO(21182) DevTools listening on ws://localhost:9222/devtools/browser/0017f4a1-1822-441f-8d34-3538126b2ec7
14:31.42 INFO CDP client instantiated
14:31.42 INFO Focus the input on the page
14:32.21 INFO Write 'h'
14:32.22 INFO Send keyDown for key h
14:32.56 INFO Console message: [JavaScript Warning: "Key event not available on some keyboard layouts: key=“r” modifiers=“accel,alt” id=“key_toggleReaderMode”" {file: "chrome://remote/content/external/EventUtils.js" line: 870}]
14:32.56 INFO Console message: [JavaScript Warning: "Key event not available on some keyboard layouts: key=“r” modifiers=“accel,alt” id=“key_quickRestart”" {file: "chrome://remote/content/external/EventUtils.js" line: 870}]
14:32.56 INFO Console message: [JavaScript Warning: "Key event not available on some keyboard layouts: key=“i” modifiers=“accel,alt,shift” id=“key_browserToolbox”" {file: "chrome://remote/content/external/EventUtils.js" line: 870}]
14:32.57 INFO Send keyUp for key h
14:32.82 INFO Write 'H'
14:32.82 INFO Send keyDown for key H
14:32.87 INFO Send keyUp for key H
14:33.11 INFO Send char type event for char [’]
14:33.86 GECKO(21182) 1576525905153	RemoteAgent	INFO	Stopped listening
14:33.86 INFO Leaving test bound 
14:33.86 INFO Entering test bound 
14:35.26 GECKO(21182) DevTools listening on ws://localhost:9222/devtools/browser/2b05f506-57d9-4f7a-8825-03dcf463e3e2
14:37.62 INFO CDP client instantiated
14:37.62 INFO Focus the input on the page
14:37.91 INFO Send keyDown for key h
14:38.22 INFO Send keyUp for key h
14:39.16 INFO Send keyDown for key H
14:43.26 INFO Send keyUp for key H
14:45.11 INFO Send keyDown for key ’
14:45.55 INFO Send keyUp for key ’
14:45.96 INFO Send Left
14:45.96 INFO Send rawKeyDown for key ArrowLeft
14:46.41 INFO Send keyUp for key ArrowLeft
14:46.86 INFO Write 'a'
14:46.86 INFO Send keyDown for key a
14:47.06 INFO Send keyUp for key a
14:47.25 INFO Send Left
14:47.26 INFO Send rawKeyDown for key ArrowLeft
14:47.31 INFO Send keyUp for key ArrowLeft
14:47.46 INFO Send Left
14:47.46 INFO Send rawKeyDown for key ArrowLeft
14:47.50 INFO Send keyUp for key ArrowLeft
14:47.51 INFO Write 'a'
14:47.51 INFO Send keyDown for key a
14:47.56 INFO Send keyUp for key a
14:47.60 INFO Send ALT/CONTROL + Right
14:47.60 INFO Send rawKeyDown for key Control
14:47.61 INFO Send rawKeyDown for key ArrowRight
14:47.66 INFO Send keyUp for key ArrowRight
14:47.75 INFO Send keyUp for key Control
14:48.40 GECKO(21182) 1576525919649	RemoteAgent	INFO	Stopped listening
14:48.36 INFO Leaving test bound 
14:48.36 INFO Entering test bound 
14:49.50 GECKO(21182) DevTools listening on ws://localhost:9222/devtools/browser/f245ec2e-fb9d-4b11-94ce-052a783683c1
14:52.40 INFO CDP client instantiated
14:52.40 INFO Focus the input on the page
14:52.61 INFO Send keyDown for key h
14:52.86 INFO Send keyUp for key h
14:52.86 INFO Send keyDown for key a
14:53.00 INFO Send keyUp for key a
14:53.11 INFO Send keyDown for key H
14:53.11 INFO Send keyUp for key H
14:53.25 INFO Send keyDown for key a
14:53.31 INFO Send keyUp for key a
14:53.35 INFO Send keyDown for key ’
14:53.36 INFO Send keyUp for key ’
14:53.50 INFO Delete every character in the input
14:53.50 INFO Send Backspace
14:53.50 INFO Send rawKeyDown for key Backspace
14:53.51 INFO Send keyUp for key Backspace
14:53.56 INFO Send Backspace
14:53.56 INFO Send rawKeyDown for key Backspace
14:53.71 INFO Send keyUp for key Backspace
14:53.80 INFO Send Backspace
14:53.81 INFO Send rawKeyDown for key Backspace
14:53.95 INFO Send keyUp for key Backspace
14:53.96 INFO Send Backspace
14:53.96 INFO Send rawKeyDown for key Backspace
14:54.10 INFO Send keyUp for key Backspace
14:54.11 INFO Send Backspace
14:54.20 INFO Send rawKeyDown for key Backspace
14:54.20 INFO Send keyUp for key Backspace
14:54.90 GECKO(21182) 1576525926191	RemoteAgent	INFO	Stopped listening
14:54.90 INFO Leaving test bound 
14:54.90 INFO Entering test bound 
14:55.86 GECKO(21182) DevTools listening on ws://localhost:9222/devtools/browser/e7d1af37-61ec-4b73-989c-8ca459475828
14:59.21 INFO CDP client instantiated
14:59.21 INFO Focus the input on the page
14:59.50 INFO Send Shift + Left (select one char to the left)
14:59.50 INFO Send rawKeyDown for key Shift
14:59.55 INFO Send rawKeyDown for key ArrowLeft
14:59.60 INFO Send keyUp for key ArrowLeft
14:59.61 INFO Send rawKeyDown for key ArrowLeft
14:59.71 INFO Send keyUp for key ArrowLeft
14:59.75 INFO Send rawKeyDown for key ArrowLeft
14:59.85 INFO Send keyUp for key ArrowLeft
14:59.86 INFO (deleteContentBackward)
14:59.90 INFO Send Backspace
14:59.90 INFO Send rawKeyDown for key Backspace
14:60.00 INFO Send keyUp for key Backspace
15:00.11 INFO Send keyUp for key Shift
15:00.15 INFO Send Shift + Left (select one char to the left)
15:00.15 INFO Send rawKeyDown for key Shift
15:00.16 INFO Send rawKeyDown for key ArrowLeft
15:00.25 INFO Send keyUp for key ArrowLeft
15:00.25 INFO Send rawKeyDown for key ArrowLeft
15:00.35 INFO Send keyUp for key ArrowLeft
15:00.35 INFO Send keyDown for key H
15:00.36 INFO Send keyUp for key H
15:00.46 INFO Send keyUp for key Shift
15:01.06 GECKO(21182) 1576525932348	RemoteAgent	INFO	Stopped listening
15:01.06 INFO Leaving test bound 
15:01.06 INFO Entering test bound 
15:03.14 GECKO(21182) DevTools listening on ws://localhost:9222/devtools/browser/b99e6692-d671-4b83-a07a-d3f58d1087fb
15:05.49 INFO CDP client instantiated
15:05.49 INFO Focus the input on the page
15:05.74 INFO Send Shift + Ctrl/Alt + Left (select one word to the left)
15:05.74 INFO Send rawKeyDown for key Shift
15:05.80 INFO Send rawKeyDown for key Control
15:05.84 INFO Send rawKeyDown for key ArrowLeft
15:05.85 INFO Send keyUp for key ArrowLeft
15:05.95 INFO Send rawKeyDown for key ArrowLeft
15:06.00 INFO Send keyUp for key ArrowLeft
15:06.05 INFO Send keyUp for key Shift
15:06.05 INFO Send keyUp for key Control
15:06.14 INFO (deleteContentBackward)
15:06.14 INFO Send Backspace
15:06.14 INFO Send rawKeyDown for key Backspace
15:06.15 INFO Send keyUp for key Backspace
15:06.94 GECKO(21182) 1576525938231	RemoteAgent	INFO	Stopped listening
15:06.94 INFO Leaving test bound 
15:06.94 INFO Entering test bound 
15:07.80 GECKO(21182) DevTools listening on ws://localhost:9222/devtools/browser/2d688b8f-40f8-4c31-9af0-fb9ccd39a0e1
15:10.29 INFO CDP client instantiated
15:10.29 INFO Focus the input on the page
15:10.50 INFO Send Ctrl/Alt + Backspace (deleteWordBackward)
15:10.50 INFO Send rawKeyDown for key Control
15:10.59 INFO Send Backspace
15:10.59 INFO Send rawKeyDown for key Backspace
15:10.65 INFO Send keyUp for key Backspace
15:10.75 INFO Send keyUp for key Control
15:10.79 INFO Send keyDown for key w
15:10.89 INFO Send keyUp for key w
15:10.89 INFO Send keyDown for key o
15:10.89 INFO Send keyUp for key o
15:10.90 INFO Send keyDown for key r
15:11.19 INFO Send keyUp for key r
15:11.35 INFO Send keyDown for key d
15:11.54 INFO Send keyUp for key d
15:11.55 INFO Send keyDown for key 4
15:11.60 INFO Send keyUp for key 4
15:11.74 INFO Send rawKeyDown for key ArrowLeft
15:11.74 INFO Send keyUp for key ArrowLeft
15:11.75 INFO Send rawKeyDown for key ArrowLeft
15:11.75 INFO Send keyUp for key ArrowLeft
15:12.44 GECKO(21182) 1576525943735	RemoteAgent	INFO	Stopped listening
15:12.44 INFO Leaving test bound 
15:12.44 INFO Entering test bound 
15:13.24 GECKO(21182) DevTools listening on ws://localhost:9222/devtools/browser/1e2bfb8f-d43d-4f5f-be18-aec128442a11
15:15.25 INFO CDP client instantiated
15:15.29 INFO Send rawKeyDown for key Control
15:15.49 INFO Send rawKeyDown for key Shift
15:15.50 INFO Send rawKeyDown for key ArrowDown
15:15.55 INFO Send keyUp for key ArrowDown
15:15.60 INFO Send keyUp for key Control
15:15.70 INFO Send keyUp for key Shift
15:16.29 GECKO(21182) 1576525947585	RemoteAgent	INFO	Stopped listening
15:16.29 INFO Leaving test bound 
15:16.40 GECKO(21182) MEMORY STAT vsizeMaxContiguous not supported in this build configuration.
15:16.40 GECKO(21182) MEMORY STAT | vsize 2704MB | residentFast 266MB | heapAllocated 126MB
15:16.39 TEST_END: Test OK. Subtests passed 73/74. Unexpected 1
FAIL This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. -

Flags: needinfo?(egao)

Edwin Takahashi (:egao | infrequent contributor)

Comment 10

•

5 years ago

This test has been running fine on autoland for the last day or so:
https://treeherder.mozilla.org/#/jobs?repo=autoland&group_state=expanded&tier=1%2C2%2C3&searchStr=remote%2Clinux&fromchange=23842b70efd78e634a91afb5a823fa945e89e722

Closing the bug as fixed.

Status: NEW → RESOLVED

Closed: 5 years ago

Resolution: --- → FIXED

Henrik Skupin [:whimboo][⌚️UTC+2]

Comment 11

•

5 years ago

No patch => WFM.

Resolution: FIXED → WORKSFORME

Bugzilla

ubuntu1804 - remote/test/browser/input/browser_dispatchKeyEvent_events.js | Test timed out -

Categories

(Remote Protocol :: Agent, defect, P5)

Tracking

(Not tracked)

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

Crash Data

Security

(public)

User Story

Description

Comment 1

Updated

Comment 2

Comment 3

Comment 4

Comment 5

Comment 6

Comment 7

Comment 8

Comment 9

Comment 10

Comment 11