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

Status: RESOLVED FIXED

(Thunderbird :: Message Compose Window, defect)

Description

[Jorg K (GMT+1) (no longer working on Thunderbird)]

This started with bug 1243760.

See 1243760 comment #52

Comment 1

[Jorg K (GMT+1) (no longer working on Thunderbird)]

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.

Comment 2

[Jorg K (GMT+1) (no longer working on Thunderbird)]

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.

Comment 3

[Jorg K (GMT+1) (no longer working on Thunderbird)]

Do you guys have experience with double clicking on an image to bring up the properties dialogue? I see that Neil wrote the test.

Comment 4

[:aceman]

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.

Comment 5

[Jorg K (GMT+1) (no longer working on Thunderbird)]

(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.

Comment 6

[Intermittent Failures Robot]

5 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* comm-central: 5

Platform breakdown:
* windowsxp: 2
* linux64: 2
* windows7-32: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1246094&startday=2016-02-01&endday=2016-02-07&tree=all

Comment 7

[Jorg K (GMT+1) (no longer working on Thunderbird)]

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.

Comment 8

[Jorg K (GMT+1) (no longer working on Thunderbird)]

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

Comment 9

[:aceman]

I'm debugging it and this is the current problem.
Consider a message body like this:
<body text="#000000" bgcolor="#FFFFFF">
    <img src="cid:[e-mail]" 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.

Comment 10

[Jorg K (GMT+1) (no longer working on Thunderbird)]

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!

Comment 11

[Jorg K (GMT+1) (no longer working on Thunderbird)]

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 ;-)

Comment 12

[Jorg K (GMT+1) (no longer working on Thunderbird)]

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.

Comment 13

[Jorg K (GMT+1) (no longer working on Thunderbird)]

Try for this suggestion by Aceman:
https://treeherder.mozilla.org/#/jobs?repo=try-comm-central&revision=a87223f2a32a

Comment 14

[:aceman]

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).

Comment 15

[Jorg K (GMT+1) (no longer working on Thunderbird)]

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 ;-)

Comment 16

[Jorg K (GMT+1) (no longer working on Thunderbird)]

(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 ;-)

Comment 17

[:aceman]

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 :)

Comment 18

[Jorg K (GMT+1) (no longer working on Thunderbird)]

Moved the double-click failure to bug 1143744.
My feeling is that bug 1143744 will also fix the test failure here.

Comment 19

[Jorg K (GMT+1) (no longer working on Thunderbird)]

I landed bug 1143744 so let's see whether it fixes the test failure.

Comment 20

[Jorg K (GMT+1) (no longer working on Thunderbird)]

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.

Comment 21

[aleth [:aleth]]

Attachment: Wait before double-click in test-image-insertion-dialog.js

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

Comment 22

[Jorg K (GMT+1) (no longer working on Thunderbird)]

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.

Comment 23

[aleth [:aleth]]

(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 ;)

Comment 24

[Jorg K (GMT+1) (no longer working on Thunderbird)]

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.

Comment 25

[aleth [:aleth]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=2a60b6a9b5b0

Comment 26

[Jorg K (GMT+1) (no longer working on Thunderbird)]

You mean:
https://treeherder.mozilla.org/#/jobs?repo=try-comm-central&revision=e6003b5c0349ddd0a3eee6eb52f19349cfe32331

Comment 27

[aleth [:aleth]]

(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.

Comment 28

[:aceman]

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.

Comment 29

[aleth [:aleth]]

Gentle review ping ;)

Comment 30

[:aceman]

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?

Comment 31

[aleth [:aleth]]

(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

Comment 32

[:aceman]

Does sleep(0) work? Or have you determined that 400 is some number where it seems to work?

Comment 33

[aleth [:aleth]]

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...

Comment 34

[Jorg K (GMT+1) (no longer working on Thunderbird)]

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

Comment 35

[aleth [:aleth]]

https://hg.mozilla.org/comm-central/rev/3260863b6c3506a0c96e2134984b1ae4447423c2
Bug 1246094 - Wait before double-click in test-image-insertion-dialog.js. r=jorgk

Comment 36

[aleth [:aleth]]

> 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.

Comment 37

[aleth [:aleth]]

From treeherder, looks like this failure is gone for now.

Comment 38

[Jorg K (GMT+1) (no longer working on Thunderbird)]

Haha, it's back, this time on Windows:
https://treeherder.mozilla.org/#/jobs?repo=comm-central&selectedJob=42044

Comment 39

[Jorg K (GMT+1) (no longer working on Thunderbird)]

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 ;-(

Comment 40

[Jorg K (GMT+1) (no longer working on Thunderbird)]

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.

Comment 41

[Jorg K (GMT+1) (no longer working on Thunderbird)]

TB 49 (Aurora):
https://hg.mozilla.org/releases/comm-aurora/rev/8667c168bc24

Comment 42

[Jorg K (GMT+1) (no longer working on Thunderbird)]

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);

Comment 43

[Wayne Mery (:wsmwk)]

aceman?  :)

Comment 44

[Jorg K (GMT+1) (no longer working on Thunderbird)]

Yes, this has been failing for a long time, but we have hotter fires :-(

Comment 45

[Jorg K (GMT+1) (no longer working on Thunderbird)]

Let's close this, I haven't seen it for a while.

Comment 46

[ISHIKAWA, Chiaki (may be slow to respond until Jan 4.)]

Attachment: The screen: test seems to wait for something (a dialog presumably).

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

Comment 47

[ISHIKAWA, Chiaki (may be slow to respond until Jan 4.)]

Attachment: A dialog appears AFTER the timeout error is recorded.

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.)

Comment 48

[ISHIKAWA, Chiaki (may be slow to respond until Jan 4.)]

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.

Comment 49

[ISHIKAWA, Chiaki (may be slow to respond until Jan 4.)]

Attachment: Failure log when the screens were captured.

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.