Closed Bug 1246094 Opened 9 years ago Closed 7 years ago

TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\mozmill\composition\test-image-insertion-dialog.js

Categories

(Thunderbird :: Message Compose Window, defect)

Product:
Thunderbird
Component:
Message Compose Window
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(Not tracked)

Status:
RESOLVED FIXED
Milestone:
Thunderbird 50.0

People

(Reporter: jorgk-bmo, Assigned: aleth)

References

Details

(Keywords: intermittent-failure, Whiteboard: [Thunderbird-testfailure: Z all])

Attachments

(4 files)

Wait before double-click in test-image-insertion-dialog.js
2.16 KB, patch
jorgk-bmo
: review+
jorgk-bmo
: approval-comm-aurora+
Details | Diff | Splinter Review
The screen: test seems to wait for something (a dialog presumably).
689.64 KB, image/png
Details
A dialog appears AFTER the timeout error is recorded.
698.84 KB, image/png
Details
Failure log when the screens were captured.
20.14 KB, text/plain
Details
This started with bug 1243760. See 1243760 comment #52
This can be reproduced locally: mozmake SOLO_TEST=composition/test-image-insertion-dialog.js mozmill-one However, since it worked locally with bug 1195173 backed out (see bug 1243760 comment #54) I'm wondering whether this caused by not fixing bug 1243760 properly or by some other cause.
I've run the test https://dxr.mozilla.org/comm-central/source/mail/test/mozmill/composition/test-image-insertion-dialog.js#35 a few times manually to see what happens. The "insert image" dialog comes up three times as expected due to lines 55, 67 and 78 of the test. However, it doesn't come up when double clicking on the image: https://dxr.mozilla.org/comm-central/source/mail/test/mozmill/composition/test-image-insertion-dialog.js#90 I've manually tried double clicking on an image in TB 31, 38, TB 45 (beta) and a local build. Double clicking on an image doesn't give a consistent result. Sometimes the property dialogue comes up, more frequently it doesn't. So it's not a surprise that the test fails. It's a bigger surprise that it ever worked reliably.
Summary: TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\mozmill\composition\test-image-insertion-dialog.js | test-image-insertion-dialog.js::test_image_insertion_dialog_persist → Double clicking an image does not reliably bring up the image properties dialogue, TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\mozmill\composition\test-image-insertion-dialog.js | test-image-insertion-dialog.js::test_image_insertion_dialog_persist
Do you guys have experience with double clicking on an image to bring up the properties dialogue? I see that Neil wrote the test.
On trunk before the DOMWindow changes the test passes for me realiably (on Linux 32b). However when editing a message manually doubleclicking the image does not open the dialog every time (as you say in comment 2). But when it does open I get: Warning: ReferenceError: reference to undefined property window.outerWidth Source File: chrome://editor/content/EdDialogCommon.js Line: 545 So maybe the DOMWindow changes uncovered a problem that the dialog is unreliable and now fails more frequently, even in the test.
(In reply to :aceman from comment #4) > On trunk before the DOMWindow changes the test passes for me realiably (on > Linux 32b). Sure, the Mozmill tests were green for a long time before the dom window changes. > However when editing a message manually doubleclicking the image does not > open the dialog every time (as you say in comment 2). The puzzling thing is that I can't find a version where this works reliably: I tried 31, 38 and 45 and I don't understand why sometimes double-clicking does the trick and sometimes it doesn't. It would be nice if the test reflected reality, so what works in the test also works in real life. > So maybe the DOMWindow changes uncovered a problem that the dialog is > unreliable and now fails more frequently, even in the test. Yes, something that will need looking at once the tree is green again, at the time of writing we're waiting for bug 1245681.
While this doesn't show up in a test any more, it still doesn't work in real live. I can't work out what you need to do to get the double-click to open up the properties dialogue. Sometimes it does, other times it doesn't.
Summary: Double clicking an image does not reliably bring up the image properties dialogue, TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\mozmill\composition\test-image-insertion-dialog.js | test-image-insertion-dialog.js::test_image_insertion_dialog_persist → Double clicking an image does not reliably bring up the image properties dialogue
Changing the summary back to what it was since it has raised its ugly head again here: https://treeherder.mozilla.org/#/jobs?repo=comm-central&selectedJob=38940
Summary: Double clicking an image does not reliably bring up the image properties dialogue → TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\mozmill\composition\test-image-insertion-dialog.js - Double clicking an image does not reliably bring up the image properties dialogue
I'm debugging it and this is the current problem. Consider a message body like this: <body text="#000000" bgcolor="#FFFFFF"> <img src="cid:part1.C5DF30C3.D622AAE4@xxx.yy" alt="" width="48" height="48"><br> <br> afdfsdfsdfsdf<br> <pre class="moz-signature" cols="74">-- </pre> </body> Upon doubleclicking that image in composition the event stops in editor/ui/composer/content/editor.js::EditorDblClick() . It hits the code in the function: element = event.rangeParent.childNodes[event.rangeOffset]; // Don't fire for <br>, it counts as double-clicking text. if (element.nodeName.toLowerCase() == 'br') element = null; With null element, no dialog is shown. This, even when clicking the <img>, the <br> element after it is returned by this code. Debugging further why that is the case.
Strange. The double-click works reliably on: xxx<img src="...">zzz<br> The funny thing is that a single click selects the image, so a double-click shouldn't select the <br> after it. Thanks for looking into it!
I got it. I've you click the image in the left-most 50% of its width, the dialogue opens. If you click to the right of the centre, then the dialogue doesn't open. Can you just modify the test to click more to the left ;-)
Looks like the double-click function is here: https://dxr.mozilla.org/comm-central/source/mail/test/resources/mozmill/mozmill/extension/resource/modules/controller.js#542 MozMillController.prototype.doubleClick = function(elem, left, top, expectedEvent) { Why do we call cwc.click(cwc.eid("insertImage")); and not pass more arguments? Maybe of we don't pass left and top, is will double click at the centre and get random results?? I'd try with left==top==1 or so.
I\d have thought when top and left are not specified it clicks 0,0 which is on the edge of the element and also may be problematic. But you are right, it tries the center of the object: https://dxr.mozilla.org/comm-central/source/mail/test/resources/mozmill/mozmill/extension/resource/modules/controller.js#490 But the try run didn't work with 5,5. I should check how big the image actually is. It shows empty to me when observing the set as if it was missing (unreachable).
I had suggested left==top==1 hoping the image would be at least 4px x 4px big. It was just a suggestion with no warranty ;-)
(In reply to :aceman from comment #14) > But the try run didn't work with 5,5. I should check how big the image > actually is. It shows empty to me when observing the set as if it was > missing (unreachable). Empty (invisible, nothing there) or missing (showing place holder)? I think the test operates with non-existing images. Unrelated: When working on bug 1251408 and test test-general-content-policy.js I had the impression that I didn't always see what I should have seen, but since the test succeeded, I didn't pay much attention to it ;-)
I wanted to avoid clicking on the resizer widgets that appear around the image. I think it was the placeholder as when the image is not loaded yet. But maybe that was the image itself? I'll check :)
Moved the double-click failure to bug 1143744. My feeling is that bug 1143744 will also fix the test failure here.
Depends on: 1143744
Summary: TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\mozmill\composition\test-image-insertion-dialog.js - Double clicking an image does not reliably bring up the image properties dialogue → TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\mozmill\composition\test-image-insertion-dialog.js
I landed bug 1143744 so let's see whether it fixes the test failure.
Didn't fix the test failure but it's now more consistent ;-) It now shows up on both debug and opt on Linux. Judging by one sample, Mozmill now no longer crashes.
Keywords: intermittent-failure
Now the double click bug is fixed, looks like a few ticks of the event loop after each window close can help here. (Of course, ideally one would figure out what exactly one is waiting for...) Try run: https://treeherder.mozilla.org/#/jobs?repo=try-comm-central&revision=5c66006c6966d673d9d0483fcc284acede7efde5
Attachment #8763327 - Flags: review?(acelists)
Assignee: nobody → aleth
Status: NEW → ASSIGNED
Comment on attachment 8763327 [details] [diff] [review] Wait before double-click in test-image-insertion-dialog.js Nice. You only need to wait twice, yet there are more wait_for_window_close() calls. Isn't that strange? Does sleep(0) help? There are a few sleep(0) sprinkled through the test.
(In reply to Jorg K (GMT+2, PTO during summer, NI me) from comment #22) > Nice. You only need to wait twice, yet there are more > wait_for_window_close() calls. Isn't that strange? Does sleep(0) help? There > are a few sleep(0) sprinkled through the test. sleep(0) basically just releases once to the event loop, without any additional waiting. It's not enough here. Yeah, it would be good to know better exactly what one is waiting for here (focus or painting or...?), but I can't reproduce it locally ;)
Hmm, and 200 milliseconds aren't enough either. Thanks for trying: https://treeherder.mozilla.org/#/jobs?repo=try-comm-central&revision=9b707bed57f7b48833c26cc9c23e3e31607f75d6 I wonder whether Aceman has another idea.
(In reply to Jorg K (GMT+2, PTO during summer, NI me) from comment #26) > You mean: > https://treeherder.mozilla.org/#/jobs?repo=try-comm- > central&revision=e6003b5c0349ddd0a3eee6eb52f19349cfe32331 Ah, that's unrelated to this bug. Just still had this patch applied by accident.
The problem is I can't reproduce this on Linux locally in any way. But it is almost permanent on server. I will play with it.
Gentle review ping ;)
Well, as I can't reproduce the problem, I can't say if the patch helps. The try push pasted here does not run mozmill tests (disabled) so even there we can't see if anything improved :) Maybe just needs a re-push with proper options?
(In reply to :aceman from comment #30) > Well, as I can't reproduce the problem, I can't say if the patch helps. The > try push pasted here does not run mozmill tests (disabled) so even there we > can't see if anything improved :) > Maybe just needs a re-push with proper options? See the link in comment 21
Does sleep(0) work? Or have you determined that 400 is some number where it seems to work?
I tried 200 (comment 24) and it wasn't enough. Like I said, this isn't ideal (I don't know why 400 works). But if noone has an idea for diagnosing this...
Looks like Aceman is asking the same questions I've already asked: 1) sleep(0) - comment #22 2) 200 milliseconds - comment #24. Unless someone has a brilliant idea, I'd land this with 500 milliseconds (nice number than 400) and with a big comment saying that we don't really know why sleeping helps but it does. If you look closely you can find pushes where the test didn't even fail: https://treeherder.mozilla.org/#/jobs?repo=comm-central&revision=e98bbf436ca834a774f6ce88e8aaeb11d35c3a18
Attachment #8763327 - Flags: review+
https://hg.mozilla.org/comm-central/rev/3260863b6c3506a0c96e2134984b1ae4447423c2 Bug 1246094 - Wait before double-click in test-image-insertion-dialog.js. r=jorgk
> Unless someone has a brilliant idea, I'd land this with 500 milliseconds > (nice number than 400) and with a big comment saying that we don't really > know why sleeping helps but it does. OK. Let's leave this bug open then.
From treeherder, looks like this failure is gone for now.
Status: ASSIGNED → RESOLVED
Closed: 9 years ago
Resolution: --- → FIXED
Target Milestone: --- → Thunderbird 50.0
Comment on attachment 8763327 [details] [diff] [review] Wait before double-click in test-image-insertion-dialog.js That's been landed. So any review would come too late ;-(
Attachment #8763327 - Flags: review?(acelists)
Comment on attachment 8763327 [details] [diff] [review] Wait before double-click in test-image-insertion-dialog.js This should be uplifted to make the Aurora tree greener.
Attachment #8763327 - Flags: approval-comm-aurora+
I'm reopening this now. I guess that this accounts for 30% of our Mozmill failures on Linux and sometimes elsewhere. Aceman, what do we do? Increase the time limit? Or is this a different issue that the modal window doesn't even open? All the logs I've seen say: 04:54:13 INFO - EXCEPTION: Timeout waiting for modal dialog to open. 04:54:13 INFO - at: utils.js line 447 04:54:13 INFO - TimeoutError utils.js:447 13 04:54:13 INFO - waitFor utils.js:485 11 04:54:13 INFO - WindowWatcher_waitForModalDialog test-window-helpers.js:376 5 04:54:13 INFO - wait_for_modal_dialog test-window-helpers.js:613 3 04:54:13 INFO - test_image_insertion_dialog_persist test-image-insertion-dialog.js:91 3 Source: 90 cwc.doubleClick(new elib.Elem(img)); 91 wh.wait_for_modal_dialog(); <================= 92 wait_for_window_close(); 93 // It's not clear why we have to wait here to avoid test failures, 94 // see bug 1246094. 95 cwc.sleep(500);
Status: RESOLVED → REOPENED
Flags: needinfo?(acelists)
Resolution: FIXED → ---
Whiteboard: [Thunderbird-testfailure: Z all]
aceman? :)
Yes, this has been failing for a long time, but we have hotter fires :-(
Assignee: aleth → nobody
OS: Unspecified → All
Hardware: Unspecified → All
Let's close this, I haven't seen it for a while.
Status: REOPENED → RESOLVED
Closed: 9 years ago → 7 years ago
Resolution: --- → FIXED
Flags: needinfo?(acelists)

The bug is back.
(I noticed the bug was back from around December 2018).

The reason I am reporting today is that I can reproduce it VERY RELIABLY locally by running the single test.
(And it is ONE of the TWO test failures of my local run of |make mozmill| test. So naturally it caught my attention.)

This test seems to wait for a modal dialog, but this does not happen in allocated timeout period, it seems.

Let me report the screenshot while the test runs. This refreshes collective memory.

I am running a FULL DEBUG version of C-C TB with a bit locally added
dump statement.

Failure mode

After printing some debug dump lines, the test waits for a dialog to
appear.
Attachment-1

However, the test does not appear fast enough, and the timeout error
is recorded and
the test moves on.
Attachment-2
THEN it seems the originally expected dialog appears at last!

(Well the timeout error message was unfortunately
hidden in this capture. Murphy's law struck.
The yellow marker surrounds the following message on the console on the left:
JavaScript error: resource://testing-common/mozmill/WindowHelpers.jsm, line 402: Error: Timeout while waiting for modal dialog.

The mail compose window behind the dialog remains the same
during this interval and so I think that this dialog is indeed from the
original test and not the subsequent one.

Hmm... It SEEMS to me that the test did not finish cleanly obviously and may end up additional error messages. (I have seen strange indexedDB error since late October and I see such errors in the log.
DB error may be related to a possible sqlite3 3.30.1 issue under Debian GNU/Linux, but who knows.)

Attachment #9107699 - Attachment description: image.png → A dialog appears AFTER the timeout error is recorded.

The screen gets stuck showing the image in attachment-2 and the test does not proceed after printing out the following for a long time (I probably extended the whole mozmill timeout a bit to accommodate running it under VALGRIND sometimes.

avaScript error: resource://testing-common/mozmill/WindowHelpers.jsm, line 402: Error: Timeout while waiting for modal dialog.

TEST-UNEXPECTED-FAIL | /NEW-SSD/NREF-COMM-CENTRAL/mozilla/comm/mail/test/mozmill/composition/test-image-insertion-dialog.js | test-image-insertion-dialog.js::test_image_insertion_dialog_persist
NS_NewBufferedOutputStream: outputStream (= std::move(aOutputputStream)) =0x7f036004fb98
++DOCSHELL 0x55e326aafc20 == 21 [pid = 23665] [id = {00b7442b-75f0-4367-bb0a-14c001b5b9a7}]
++DOMWINDOW == 41 (0x55e3245a0780) [pid = 23665] [serial = 46] [outer = (nil)]
++DOMWINDOW == 42 (0x55e326acd290) [pid = 23665] [serial = 47] [outer = 0x55e3245a0780]
[23665, Main Thread] WARNING: NS_ENSURE_TRUE(root) failed: file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/layout/base/nsDocumentViewer.cpp, line 3170
--DOCSHELL 0x55e323cf8df0 == 20 [pid = 23665] [id = {f2d75ab8-1510-4dea-993c-f01e631d9e9e}] [url = chrome://messenger/content/messengercompose/EdImageProps.xul]
--DOCSHELL 0x55e327de8e40 == 19 [pid = 23665] [id = {d8f27cc1-be93-473e-a02b-19d07545a886}] [url = chrome://messenger/content/messengercompose/EdImageProps.xul]
--DOCSHELL 0x55e323fe90c0 == 18 [pid = 23665] [id = {2a2d781b-6b61-45f6-84fb-8e57a60f7825}] [url = chrome://messenger/content/messengercompose/EdImageProps.xul]
--DOCSHELL 0x55e328d167d0 == 17 [pid = 23665] [id = {acc810b0-3215-4126-88e6-f228a7d4a873}] [url = chrome://messenger/content/messengercompose/EdImageProps.xul]
--DOCSHELL 0x55e327ac6fc0 == 16 [pid = 23665] [id = {6ccef565-0e11-4f06-8134-23d3c18e60b7}] [url = chrome://messenger/content/messengercompose/EdImageProps.xul]
--DOMWINDOW == 41 (0x55e3245c74f0) [pid = 23665] [serial = 42] [outer = (nil)] [url = chrome://messenger/content/messengercompose/EdImageProps.xul]
--DOMWINDOW == 40 (0x55e3240eab20) [pid = 23665] [serial = 40] [outer = (nil)] [url = chrome://messenger/content/messengercompose/EdImageProps.xul]
--DOMWINDOW == 39 (0x55e326363280) [pid = 23665] [serial = 36] [outer = (nil)] [url = chrome://messenger/content/messengercompose/EdImageProps.xul]
--DOMWINDOW == 38 (0x55e328fa3ae0) [pid = 23665] [serial = 38] [outer = (nil)] [url = chrome://messenger/content/messengercompose/EdImageProps.xul]
--DOMWINDOW == 37 (0x55e328c0f150) [pid = 23665] [serial = 44] [outer = (nil)] [url = chrome://messenger/content/messengercompose/EdImageProps.xul]
--DOMWINDOW == 36 (0x55e328f7d6a0) [pid = 23665] [serial = 43] [outer = (nil)] [url = about:blank]
--DOMWINDOW == 35 (0x55e326a6f320) [pid = 23665] [serial = 41] [outer = (nil)] [url = about:blank]
--DOMWINDOW == 34 (0x55e327435030) [pid = 23665] [serial = 37] [outer = (nil)] [url = about:blank]
--DOMWINDOW == 33 (0x55e3268da4c0) [pid = 23665] [serial = 39] [outer = (nil)] [url = about:blank]
--DOMWINDOW == 32 (0x55e3282fb8d0) [pid = 23665] [serial = 45] [outer = (nil)] [url = about:blank]
NS_NewBufferedOutputStream: outputStream (= std::move(aOutputputStream)) =0x7f03ac004768
NS_NewBufferedOutputStream: outputStream (= std::move(aOutputputStream)) =0x55e3276e4dc8
NS_NewBufferedOutputStream: outputStream (= std::move(aOutputputStream)) =0x55e326c65fa8
NS_NewBufferedOutputStream: outputStream (= std::move(aOutputputStream)) =0x55e323a4fa58
NS_NewBufferedOutputStream: outputStream (= std::move(aOutputputStream)) =0x55e326c65fa8
NS_NewBufferedOutputStream: outputStream (= std::move(aOutputputStream)) =0x55e32325b758
NS_NewBufferedOutputStream: outputStream (= std::move(aOutputputStream)) =0x55e3256f3088
NS_NewBufferedOutputStream: outputStream (= std::move(aOutputputStream)) =0x7f03b400c418
NS_NewBufferedOutputStream: outputStream (= std::move(aOutputputStream)) =0x7f03ac00d358
NS_NewBufferedOutputStream: outputStream (= std::move(aOutputputStream)) =0x7f039800df88
console.error: services.settings:
  Message: Error: IndexedDB saveLastModified() A mutation operation in the transaction failed because a constraint was not satisfied.
console.error: services.settings:
  Message: Error: IndexedDB saveLastModified() A mutation operation in the transaction failed because a constraint was not satisfied.
NS_NewBufferedOutputStream: outputStream (= std::move(aOutputputStream)) =0x7f039800df88
NS_NewBufferedOutputStream: outputStream (= std::move(aOutputputStream)) =0x7f0338067048
NS_NewBufferedOutputStream: outputStream (= std::move(aOutputputStream)) =0x7f03ac002a38
NS_NewBufferedOutputStream: outputStream (= std::move(aOutputputStream)) =0x7f0338067048
NS_NewBufferedOutputStream: outputStream (= std::move(aOutputputStream)) =0x7f0338067048
NS_NewBufferedOutputStream: outputStream (= std::move(aOutputputStream)) =0x7f03ac010e78
NS_NewBufferedOutputStream: outputStream (= std::move(aOutputputStream)) =0x7f03a0006058
[23665, Main Thread] WARNING: NS_ENSURE_TRUE(mCacheEntry) failed: file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/netwerk/protocol/http/nsHttpChannel.cpp, line 5417
NS_NewBufferedOutputStream: outputStream (= std::move(aOutputputStream)) =0x7f03ac012f18
NS_NewBufferedOutputStream: outputStream (= std::move(aOutputputStream)) =0x7f03a0009e78
NS_NewBufferedOutputStream: outputStream (= std::move(aOutputputStream)) =0x7f03a004eed8

I will upload the full log after the final timeout kicks in and the single test run finishes completely.

I have run |make mozmill| under |time| command so at the end I can see the elapsed time,
which is 20 minute and bit more.

Assignee: nobody → aleth
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: