1469825 - Intermittent browser/components/places/tests/browser/browser_bookmarkProperties_newFolder.js | Test timed out -

Status: RESOLVED FIXED

(Firefox :: Bookmarks & History, defect, P1)

Description

[Treeherder Bug Filer]

Filed by: apavel [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=183926707&repo=autoland

https://queue.taskcluster.net/v1/task/NBPegR6xQY27r1iwAB8HcA/runs/0/artifacts/public/logs/live_backing.log

[task 2018-06-20T06:54:57.763Z] 06:54:57     INFO - GECKO(1022) | [Parent 1022, StreamTrans #26] WARNING: 'NS_FAILED(rv)', file /builds/worker/workspace/build/src/modules/libjar/nsJARChannel.cpp, line 417
[task 2018-06-20T06:54:57.913Z] 06:54:57     INFO - GECKO(1022) | --DOMWINDOW == 20 (0x7f7fded5d000) [pid = 1022] [serial = 15] [outer = (nil)] [url = about:blank]
[task 2018-06-20T06:54:57.913Z] 06:54:57     INFO - GECKO(1022) | --DOMWINDOW == 19 (0x7f7ff27c0400) [pid = 1022] [serial = 2] [outer = (nil)] [url = about:blank]
[task 2018-06-20T06:54:57.913Z] 06:54:57     INFO - GECKO(1022) | --DOMWINDOW == 18 (0x7f8010923800) [pid = 1022] [serial = 12] [outer = (nil)] [url = about:blank]
[task 2018-06-20T06:54:57.914Z] 06:54:57     INFO - GECKO(1022) | --DOMWINDOW == 17 (0x7f801091ec00) [pid = 1022] [serial = 11] [outer = (nil)] [url = about:blank]
[task 2018-06-20T06:55:01.238Z] 06:55:01     INFO - GECKO(1022) | --DOMWINDOW == 16 (0x7f7fe916b600) [pid = 1022] [serial = 7] [outer = (nil)] [url = about:blank]
[task 2018-06-20T06:55:07.055Z] 06:55:07     INFO - GECKO(1022) | --DOMWINDOW == 15 (0x7f7fe6655800) [pid = 1022] [serial = 8] [outer = (nil)] [url = about:blank]
[task 2018-06-20T06:55:07.056Z] 06:55:07     INFO - GECKO(1022) | --DOMWINDOW == 14 (0x7f7fe63c9800) [pid = 1022] [serial = 20] [outer = (nil)] [url = about:blank]
[task 2018-06-20T06:56:12.078Z] 06:56:12     INFO - TEST-INFO | started process screentopng
[task 2018-06-20T06:56:12.492Z] 06:56:12     INFO - TEST-INFO | screentopng: exit 0
[task 2018-06-20T06:56:12.493Z] 06:56:12     INFO - Buffered messages logged at 06:54:42
[task 2018-06-20T06:56:12.493Z] 06:56:12     INFO - Entering test bound setup
[task 2018-06-20T06:56:12.493Z] 06:56:12     INFO - Console message: [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "resource://gre/modules/FileUtils.jsm" line: 170}]
[task 2018-06-20T06:56:12.493Z] 06:56:12     INFO - Buffered messages logged at 06:54:43
[task 2018-06-20T06:56:12.493Z] 06:56:12     INFO - Leaving test bound setup
[task 2018-06-20T06:56:12.495Z] 06:56:12     INFO - Entering test bound test_newFolder
[task 2018-06-20T06:56:12.496Z] 06:56:12     INFO - Buffered messages logged at 06:54:45
[task 2018-06-20T06:56:12.498Z] 06:56:12     INFO - Global property added while loading chrome://browser/content/places/treeView.js: makeNodeDetailsKey
[task 2018-06-20T06:56:12.499Z] 06:56:12     INFO - TEST-PASS | browser/components/places/tests/browser/browser_bookmarkProperties_newFolder.js | Should have the new folder selected by default - "New Folder" == "New Folder" - 
[task 2018-06-20T06:56:12.500Z] 06:56:12     INFO - Console message: [JavaScript Warning: "Key event not available on some keyboard layouts: key=“r” modifiers=“accel,alt” id=“key_toggleReaderMode”" {file: "chrome://mochikit/content/tests/SimpleTest/EventUtils.js" line: 946}]
[task 2018-06-20T06:56:12.501Z] 06:56:12     INFO - Console message: [JavaScript Warning: "Key event not available on some keyboard layouts: key=“i” modifiers=“accel,alt,shift” id=“key_browserToolbox”" {file: "chrome://mochikit/content/tests/SimpleTest/EventUtils.js" line: 946}]
[task 2018-06-20T06:56:12.502Z] 06:56:12     INFO - Buffered messages finished
[task 2018-06-20T06:56:12.503Z] 06:56:12     INFO - TEST-UNEXPECTED-FAIL | browser/components/places/tests/browser/browser_bookmarkProperties_newFolder.js | Test timed out - 
[task 2018-06-20T06:56:12.885Z] 06:56:12     INFO - GECKO(1022) | MEMORY STAT vsizeMaxContiguous not supported in this build configuration.
[task 2018-06-20T06:56:12.885Z] 06:56:12     INFO - GECKO(1022) | MEMORY STAT | vsize 2162MB | residentFast 293MB | heapAllocated 89MB
[task 2018-06-20T06:56:12.887Z] 06:56:12     INFO - TEST-OK | browser/components/places/tests/browser/browser_bookmarkProperties_newFolder.js | took 90829ms
[task 2018-06-20T06:56:12.904Z] 06:56:12     INFO - GECKO(1022) | ++DOCSHELL 0x7fa537fc0000 == 1 [pid = 1162] [id = {99fa3da5-369d-4c78-abc4-257f981b30dc}]
[task 2018-06-20T06:56:13.015Z] 06:56:13     INFO - GECKO(1022) | ++DOMWINDOW == 1 (0x7fa55329cc00) [pid = 1162] [serial = 1] [outer = (nil)]
[task 2018-06-20T06:56:13.015Z] 06:56:13     INFO - checking window state
[task 2018-06-20T06:56:13.112Z] 06:56:13     INFO - GECKO(1022) | ++DOMWINDOW == 15 (0x7f7fd4775400) [pid = 1022] [serial = 22] [outer = 0x7f7fe916b400]
[task 2018-06-20T06:56:13.169Z] 06:56:13     INFO - GECKO(1022) | ++DOMWINDOW == 16 (0x7f7fd5ba5c00) [pid = 1022] [serial = 23] [outer = 0x7f7fe916b400]

Comment 1

[Cosmin Sabou [:CosminS]]

This started with this push https://hg.mozilla.org/integration/autoland/rev/1cb216fe137810622b41c19d1c3bf6d9937e6fe2 
Retriggered here http://tinyurl.com/y8uo9y65 and here http://tinyurl.com/y7lzzjhf but no such failures occured. So far it's only failling on coverage and on test-verify.

Comment 2

[Intermittent Failures Robot]

33 failures in 521 pushes (0.063 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 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: 27
* autoland: 5
* try: 1

Platform breakdown:
* windows10-64-ccov: 22
* linux64-ccov: 5
* linux64: 5
* linux32: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1469825&startday=2018-06-18&endday=2018-06-24&tree=trunk

Comment 3

[Mark Banner (:standard8)]

I'm at a bit of a loss here. I've been doing lots of try pushes today to try and figure this out, and I'm not sure what's going on.

The test is attempting to edit an item within the folder tree in the star UI. It sends a key for the title, and then VK_RETURN to accept the key.

In the broken cases, I see the folder tree receiving only the VK_RETURN. It doesn't receive a change of the value of the field. Hence when it processes the return, there's no change, so we never get notification of onItemChanged and the test times out.

More Info:

- Seems to be happening on debug builds (ccov win & linux, and also linux64 debug), hence probably timing.
- The popup definitely has focus, as does the folder tree view itself.
- The folder tree is in edit mode.
- I've tried a mixture of EventUtils.sendString and EventUtils.synthesizeKey.


So if anyone has any ideas, I'd welcome them...



Last try push:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=ff6cdcdb593dbc1db7b46bc6d7af1976f0fc45e6&selectedJob=184710153

Comment 4

[Intermittent Failures Robot]

40 failures in 718 pushes (0.056 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 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: 32
* try: 3
* autoland: 3
* mozilla-beta: 2

Platform breakdown:
* windows10-64-ccov: 28
* linux32: 5
* linux64-ccov: 4
* linux64: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1469825&startday=2018-06-25&endday=2018-07-01&tree=trunk

Comment 5

[:Gijs (he/him)]

(In reply to Mark Banner (:standard8) from comment #3)
> I'm at a bit of a loss here. I've been doing lots of try pushes today to try
> and figure this out, and I'm not sure what's going on.
> 
> The test is attempting to edit an item within the folder tree in the star
> UI. It sends a key for the title, and then VK_RETURN to accept the key.
> 
> In the broken cases, I see the folder tree receiving only the VK_RETURN. It
> doesn't receive a change of the value of the field. Hence when it processes
> the return, there's no change, so we never get notification of onItemChanged
> and the test times out.
> 
> More Info:
> 
> - Seems to be happening on debug builds (ccov win & linux, and also linux64
> debug), hence probably timing.
> - The popup definitely has focus, as does the folder tree view itself.
> - The folder tree is in edit mode.
> - I've tried a mixture of EventUtils.sendString and EventUtils.synthesizeKey.

I don't really have any good ideas. Have you added logging to the event code in the tree that would be processing these key codes, and does it really just never see the right events, rather than discard them for some reason? I guess I don't see a reason why an element would have focus but still doesn't get key events fired at it, unless either one of those 2 things is not true, or the code that implements sendString or synthesizeKey doesn't determine focus correctly (and sends the events to the wrong place).

Comment 6

[Intermittent Failures Robot]

20 failures in 112 pushes (0.179 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* mozilla-central: 13
* try: 3
* autoland: 3
* mozilla-inbound: 1

Platform breakdown:
* windows10-64-ccov: 13
* linux32: 3
* linux64-ccov: 2
* macosx64-ccov: 1
* linux64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1469825&startday=2018-07-02&endday=2018-07-02&tree=trunk

Comment 7

[Mike Conley (:mconley) (:⚙️)]

During the Joy of Coding today, I decided to dip into some intermittent oranges, and stumbled on this one. I instrumented a try build to dump the focused element.

When the test passes, the focused element is an html:input with a textbox-input class applied to it.

When the test fails, the focused element is a tree, with a placesTree class applied to it.

I suspect this might be the cause:

https://searchfox.org/mozilla-central/rev/403038737ba75af3842ba6b43b6e2fb47eb06609/toolkit/content/widgets/tree.xml#372-377

We're using a setTimeout to focus the text input on the next tick of the event loop, but the editing attribute is added before that setTimeout function fires.

I'm not certain why the setTimeout is required, but I suspect that's what's burning us here.

Comment 8

[Mark Banner (:standard8)]

Thank you Mike. Very interesting.

I took a look at history, and bug 201499 comment 12 says:

> > Is this timeout needed because the element was originally hidden rather than
> > collapsed? If so, would it be too expensive to collapse it?
> The timeout is needed because the input needs to do some initialization before text can be selected. Collapsed doesn't work either.

So I'm not sure that we can get rid of it. I've done a try push to experiment with setting the attribute within the timeout:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=47a5a021d00b4ec9ce4c46b208828c1c38df047e

Comment 9

[Mark Banner (:standard8)]

So the good news is, that seems to have worked :-)

Comment 10

[Mike Conley (:mconley) (:⚙️)]

\o/

Comment 11

[Mark Banner (:standard8)]

Attachment: Bug 1469825 - The tree component no longer needs to wait before selecting and setting focus when starting editing.

MozReview-Commit-ID: 1bQEn0yfg63

Comment 12

[Andreea Pavel [:apavel]]

:standard8 This failure shifted from TV to browser chrome failures right after Cosmin's comment above (comment 1). It recently started perma-failing on tier2 browser-chrome, starting from this merge: https://tinyurl.com/y94ftrkb (simulated the job with Joel's tool, before this push the bc job is green)

The initial bc failure on tier2 appears to be from here: https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&revision=e09fbaee1456a373382d2d5bf6ab7321e26e3710&selectedJob=184085135

There is also one tier1 failure for this issue: https://tinyurl.com/yb4tukqr - on tier1 it's intermittent, retriggers are green. 

The initial failure appears to have started due to this Bug 1469418: https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=1cb216fe137810622b41c19d1c3bf6d9937e6fe2&selectedJob=183926707

Hope this helps. Let me know if i can provide any other info.

Comment 13

[Intermittent Failures Robot]

72 failures in 622 pushes (0.116 failures/push) were associated with this bug in the last 7 days. 

This is the #8 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: 58
* autoland: 7
* try: 4
* mozilla-inbound: 3

Platform breakdown:
* windows10-64-ccov: 50
* linux32: 10
* linux64-ccov: 8
* linux64: 2
* osx-10-10: 1
* macosx64-ccov: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1469825&startday=2018-07-02&endday=2018-07-08&tree=trunk

Comment 14

[Mark Banner (:standard8)]

(In reply to Andreea Pavel [:apavel] from comment #12)
> The initial failure appears to have started due to this Bug 1469418:
> https://treeherder.mozilla.org/#/
> jobs?repo=autoland&revision=1cb216fe137810622b41c19d1c3bf6d9937e6fe2&selected
> Job=183926707

That's the bug that added the test...

> Hope this helps. Let me know if i can provide any other info.

To clarify the status here: we have a patch it just needs review (note: phabricator review requests don't show in bugzilla until they are granted).

The cause appears to be down to a timing issue, there's lots of different things that could have caused that to show up, so I don't think it is worth trying to figure out things further.

Comment 15

[Mark Banner (:standard8)]

Hi Neil, did you see the review request in phabricator?

Comment 16

[Phabricator Automation]

Comment on attachment 8990313 [details]
Bug 1469825 - The tree component no longer needs to wait before selecting and setting focus when starting editing.

Neil Deakin has approved the revision.

https://phabricator.services.mozilla.com/D2001

Comment 17

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/c64603aec7e5
The tree component should only set the editing attribute after the input field is ready.

Comment 18

[Andreea Pavel [:apavel]]

Baked out for failing mochitest chrome at toolkit/content/tests/chrome/test_tree.xul

Push that started the failures: https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&revision=c64603aec7e5273838fd20671f15a2c6a425d938

Failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=187968213&repo=mozilla-inbound&lineNumber=5183

Backout: https://hg.mozilla.org/integration/mozilla-inbound/rev/b5152aa87782ebe527e0b6cb80fe11ff750509d4

Comment 19

[Mark Banner (:standard8)]

Bah, I forgot a full try run. Looking...

Comment 20

[Mark Banner (:standard8)]

I took a look at the test failures here. They're all basically the same thing as we're looking at one file - tree_shared.js.

There are a couple of places in that file where we initiate start editing:

https://searchfox.org/mozilla-central/rev/46292b1212d2d61d7b5a7df184406774727085b8/toolkit/content/tests/widgets/tree_shared.js#81
https://searchfox.org/mozilla-central/rev/46292b1212d2d61d7b5a7df184406774727085b8/toolkit/content/tests/widgets/tree_shared.js#631

The one on line 631 actually happens before the one on line 81.

I've tried changing both of those to use `await TestUtils.waitForCondition(() => tree.getAttribute("editing") == "true", "Should have selected the cell to edit");`

(after having changed the relevant functions to be defined as async).

Having done that, the test still fails. So far the only way I can make it work is to add a non-zero delay before the first editing happens (the one on line 631, I was trying 500ms).

So far the flow seems to be:

- startEditing is called
-> it runs, and so setTimeout(..., 0); is queued
-> Before the setTimeout happens, there's a handler kicks in for tree.xml which stops editing:

https://searchfox.org/mozilla-central/rev/46292b1212d2d61d7b5a7df184406774727085b8/toolkit/content/widgets/tree.xml#740-741

- Hence the wait for editing never succeeds as it is cancelled before it is started.

My best guess is there's some select event handling that is queued up from the previous tests that finally gets a chance to run. 

I've run out of time this week, and I'm afk for the next week, so unassigning. If there's someone who's curious about what's going on here, please feel free to take the over.

Comment 21

[Noemi Erli[:noemi_erli]]

Attachment: Disabled for frequent failures on Windows and Linux

Since Mark is off for the next week, I've made a patch to disable this if necessary. This can be re-enabled when needed.

Comment 22

[Intermittent Failures Robot]

50 failures in 623 pushes (0.08 failures/push) were associated with this bug in the last 7 days. 

This is the #19 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: 36
* autoland: 8
* mozilla-inbound: 4
* try: 2

Platform breakdown:
* windows10-64-ccov: 28
* linux32: 10
* linux64-ccov: 8
* linux64: 4

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1469825&startday=2018-07-09&endday=2018-07-15&tree=trunk

Comment 23

[Geoff Brown [:gbrown]]

Comment on attachment 8992216 [details] [diff] [review]
Disabled for frequent failures on Windows and Linux

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

Temporarily disabling while Mark is away seems reasonable.

Comment 24

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/4f6dddb432da
Disable browser_bookmarkProperties_newFolder.js for frequent failures on Widnows and Linux. r=gbrown

Comment 25

[Bogdan Tara[:bogdan_tara | bogdant]]

https://hg.mozilla.org/mozilla-central/rev/4f6dddb432da

Comment 26

[Intermittent Failures Robot]

7 failures in 653 pushes (0.011 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 3
* try: 2
* mozilla-central: 2

Platform breakdown:
* windows10-64-ccov: 2
* linux32: 2
* windows7-32: 1
* macosx64-ccov: 1
* linux64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1469825&startday=2018-07-16&endday=2018-07-22&tree=trunk

Comment 27

[Intermittent Failures Robot]

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

Repository breakdown:
* mozilla-beta: 2

Platform breakdown:
* linux64: 2

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

Comment 28

[Intermittent Failures Robot]

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

Repository breakdown:
* mozilla-beta: 2

Platform breakdown:
* linux32: 2

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

Comment 29

[Intermittent Failures Robot]

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

Repository breakdown:
* mozilla-beta: 1
* autoland: 2

Platform breakdown:
* linux64: 1
* osx-10-10: 1
* linux32: 1

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

Comment 30

[Intermittent Failures Robot]

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

Repository breakdown:
* mozilla-inbound: 1
* autoland: 1

Platform breakdown:
* osx-10-10: 2

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

Comment 31

[Mark Banner (:standard8)]

Neil, any thoughts on what we could do to fix the issues raised in comment 20?

Comment 32

[Neil Deakin]

The timeout in startEditing was originally added as select() didn't work immediately after showing the input field, but that issue doesn't seem to exist anymore. 

I'd suggest just removing the timeout entirely from startEditing.

Comment 33

[Mark Banner (:standard8)]

Try push for the new patch: https://treeherder.mozilla.org/#/jobs?repo=try&revision=a50be777a10efb00f5fea668d51ff6dfec989b86

Comment 34

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/5d0c236ebd7b
The tree component no longer needs to wait before selecting and setting focus when starting editing. r=NeilDeakin

Comment 35

[Bogdan Tara[:bogdan_tara | bogdant]]

https://hg.mozilla.org/mozilla-central/rev/5d0c236ebd7b

Comment 36

[Intermittent Failures Robot]

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

Repository breakdown:
* autoland: 1

Platform breakdown:
* osx-10-10: 1

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

Comment 37

[Mark Banner (:standard8)]

Forgot to drop the leave-open. No more instances since this landed, so it is looking reasonable that it is fixed now :-)

Comment 38

[Ryan VanderMeulen [:RyanVM]]

Did you want to request Beta uplift on this?

Comment 39

[Mark Banner (:standard8)]

(In reply to Ryan VanderMeulen [:RyanVM] from comment #38)
> Did you want to request Beta uplift on this?

I think this is better to ride the trains. There shouldn't be any obvious impact from the user not having the patch, I believe this is really test-only affecting.

Comment 40

[Intermittent Failures Robot]

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

Repository breakdown:
* try: 1

Platform breakdown:
* linux64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1469825&startday=2018-09-17&endday=2018-09-23&tree=all

Comment 41

[Intermittent Failures Robot]

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

Repository breakdown:
* mozilla-beta: 1

Platform breakdown:
* linux64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1469825&startday=2018-10-08&endday=2018-10-14&tree=all