1597071 - time out during |make mozmill| : mozilla/comm/mail/test/mozmill/folder-widget/test-message-filters.js | test_can_quit_on_filter_changes

Status: RESOLVED WORKSFORME

(Thunderbird :: Testing Infrastructure, defect)

Description

[ISHIKAWA, Chiaki]

Attachment: Stuck dialog from test_can_quit_on_filter_changes

During |make mozmill| test suite run of C-C TB locally (I use FULL DEBUG version of C-C DB), I noticed a timeout.

I noticed a stuck dialog that was shown until timeout occurs.
(The screen capture is attached.)

What irks me, though, is that it seems that mozmill seems to PASS this test as success.

Something in the test is wrong and is not handling this dialog correctly.

I wonder if this problem is universal across all the platform, but I restrict this to my
platform (x86_64, linux AMD64).

Comment 1

[ISHIKAWA, Chiaki]

Attachment: Excerpt from |make mozmill| run.

Excerpt from the local log of |make mozmill| (running FULL DEBUG version of C-C TB).

I noticed that there is a backend database error, but obviously the stuck dialog is related to the UI issue that is not handled properly by the test, I think.

TIA

Comment 2

[ISHIKAWA, Chiaki]

The problem appears even if I run the single test file
make mozmill SOLO_TEST=folder-widget/test-message-filters.js

So I think it is very specific to the test file in question.

Comment 3

[Jorg K (CEST = GMT+2)]

That doesn't fail in automation, does it?

Comment 4

[ISHIKAWA, Chiaki]

(In reply to Jorg K (GMT+2) from comment #3)

That doesn't fail in automation, does it?

The problem is that the test seems to ignore the stuck dialog or is not handling the simulated user interaction correctly at all.

Yet, it PASSES.

Something is wrong.

Let me see if the timeout is recorded on tryserver.

Comment 5

[ISHIKAWA, Chiaki]

It seems to happen on tryserver as well.

https://firefoxci.taskcluster-artifacts.net/d8ZOcPfhRJu0urftPIDDzg/0/public/logs/live_backing.log

I put a "*" at the beginning of the error line.

[task 2019-11-17T02:51:55.598Z] 02:51:55     INFO -  TEST-PASS | /builds/worker/workspace/build/tests/mozmill/folder-widget/test-message-filters.js | test-message-filters.js::test_can_cancel_quit_on_filter_changes
[task 2019-11-17T02:51:55.598Z] 02:51:55     INFO -  TEST-START | /builds/worker/workspace/build/tests/mozmill/folder-widget/test-message-filters.js | test_can_quit_on_filter_changes
[task 2019-11-17T02:51:55.598Z] 02:51:55     INFO -  TEST-PASS | /builds/worker/workspace/build/tests/mozmill/folder-widget/test-message-filters.js | test-message-filters.js::test_can_quit_on_filter_changes
[task 2019-11-17T02:51:55.598Z] 02:51:55     INFO -  --DOMWINDOW == 43 (0x7f5c9ea33c00) [pid = 1227] [serial = 2] [outer = (nil)] [url = about:blank]
[task 2019-11-17T02:51:55.621Z] 02:51:55     INFO -  --DOMWINDOW == 42 (0x7f5c986ca000) [pid = 1227] [serial = 21] [outer = (nil)] [url = about:blank]
[task 2019-11-17T02:51:55.622Z] 02:51:55     INFO -  --DOMWINDOW == 41 (0x7f5cbc727400) [pid = 1227] [serial = 7] [outer = (nil)] [url = about:blank]
[task 2019-11-17T02:51:55.625Z] 02:51:55     INFO -  --DOMWINDOW == 40 (0x7f5c99b4e400) [pid = 1227] [serial = 10] [outer = (nil)] [url = about:blank]
[task 2019-11-17T02:51:58.130Z] 02:51:58     INFO -  ++DOCSHELL 0x7f5c8e62a000 == 20 [pid = 1227] [id = {7a15f4f7-b512-403a-b84d-ecb41ac61562}]
[task 2019-11-17T02:51:58.131Z] 02:51:58     INFO -  ++DOMWINDOW == 41 (0x7f5ca008a100) [pid = 1227] [serial = 45] [outer = (nil)]
[task 2019-11-17T02:51:58.131Z] 02:51:58     INFO -  ++DOMWINDOW == 42 (0x7f5c921d4400) [pid = 1227] [serial = 46] [outer = 0x7f5ca008a100]
[task 2019-11-17T02:51:58.194Z] 02:51:58     INFO -  [1227, Main Thread] WARNING: NS_ENSURE_TRUE(root) failed: file /builds/worker/workspace/build/src/layout/base/nsDocumentViewer.cpp, line 3170
[task 2019-11-17T02:52:00.062Z] 02:52:00     INFO -  --DOMWINDOW == 41 (0x7f5c9531a000) [pid = 1227] [serial = 29] [outer = (nil)] [url = chrome://messenger/content/multimessageview.xhtml]
[task 2019-11-17T02:52:00.062Z] 02:52:00     INFO -  --DOMWINDOW == 40 (0x7f5c986cd000) [pid = 1227] [serial = 22] [outer = (nil)] [url = about:blank]
[task 2019-11-17T02:52:11.365Z] 02:52:11     INFO -  [1227, Main Thread] WARNING: NS_ENSURE_TRUE(mCacheEntry) failed: file /builds/worker/workspace/build/src/netwerk/protocol/http/nsHttpChannel.cpp, line 5427
[task 2019-11-17T02:52:16.715Z] 02:52:16     INFO -  --DOCSHELL 0x7f5c8e62b800 == 19 [pid = 1227] [id = {02ea4113-00e9-4d29-9da7-b157ba01f557}] [url = chrome://messenger/content/FilterListDialog.xul]
[task 2019-11-17T02:52:16.716Z] 02:52:16     INFO -  --DOCSHELL 0x7f5c9268d000 == 18 [pid = 1227] [id = {c4324385-d8e0-4986-93e6-d65fec3e1f5f}] [url = chrome://messenger/content/customizeToolbar.xul]
[task 2019-11-17T02:52:16.716Z] 02:52:16     INFO -  --DOCSHELL 0x7f5c92692800 == 17 [pid = 1227] [id = {e3c692c3-34b3-40cc-a851-1a67bc54c892}] [url = chrome://messenger/content/FilterEditor.xul]
[task 2019-11-17T02:52:16.717Z] 02:52:16     INFO -  --DOCSHELL 0x7f5c8e62c800 == 16 [pid = 1227] [id = {d9cc52ff-a6e7-4520-b8ef-2f777165c287}] [url = chrome://messenger/content/FilterEditor.xul]
[task 2019-11-17T02:52:17.166Z] 02:52:17     INFO -  --DOMWINDOW == 39 (0x7f5ca00897a0) [pid = 1227] [serial = 41] [outer = (nil)] [url = chrome://messenger/content/FilterEditor.xul]
[task 2019-11-17T02:52:17.166Z] 02:52:17     INFO -  --DOMWINDOW == 38 (0x7f5ca0089f20) [pid = 1227] [serial = 43] [outer = (nil)] [url = chrome://messenger/content/FilterEditor.xul]
[task 2019-11-17T02:52:21.088Z] 02:52:21     INFO -  --DOMWINDOW == 37 (0x7f5c92c44000) [pid = 1227] [serial = 44] [outer = (nil)] [url = about:blank]
[task 2019-11-17T02:52:21.088Z] 02:52:21     INFO -  --DOMWINDOW == 36 (0x7f5ca01f2000) [pid = 1227] [serial = 42] [outer = (nil)] [url = about:blank]
*[task 2019-11-17T02:54:09.279Z] 02:54:09     INFO -  Timeout: bridge.execFunction("38c385ae-08e5-11ea-8762-0242ac110004", bridge.registry["{0fe71d98-00fe-433c-b564-de4f601868f8}"]["cleanQuit"], [])
[task 2019-11-17T02:54:09.284Z] 02:54:09     INFO -  INFO Passed: 6
[task 2019-11-17T02:54:09.285Z] 02:54:09     INFO -  INFO Failed: 0
[task 2019-11-17T02:54:09.285Z] 02:54:09     INFO -  INFO Skipped: 0

Comment 6

[ISHIKAWA, Chiaki]

OK, that was my submission with my patches.
But here is aceman's job with the same timeout.

https://treeherder.mozilla.org/#/jobs?repo=try-comm-central&selectedJob=276675526
https://firefoxci.taskcluster-artifacts.net/HDXtDmAATz2SgAe3jGerBw/0/public/logs/live_backing.log

[task 2019-11-18T00:09:03.398Z] 00:09:03     INFO -  TEST-START | /builds/worker/workspace/build/tests/mozmill/folder-widget/test-message-filters.js | test_can_quit_on_filter_changes
[task 2019-11-18T00:09:03.398Z] 00:09:03     INFO -  TEST-PASS | /builds/worker/workspace/build/tests/mozmill/folder-widget/test-message-filters.js | test-message-filters.js::test_can_quit_on_filter_changes
[task 2019-11-18T00:09:03.399Z] 00:09:03     INFO -  --DOMWINDOW == 43 (0x7f156173bc00) [pid = 1235] [serial = 2] [outer = (nil)] [url = about:blank]
[task 2019-11-18T00:09:03.418Z] 00:09:03     INFO -  --DOMWINDOW == 42 (0x7f155b2c8400) [pid = 1235] [serial = 21] [outer = (nil)] [url = about:blank]
[task 2019-11-18T00:09:03.418Z] 00:09:03     INFO -  --DOMWINDOW == 41 (0x7f156a12a000) [pid = 1235] [serial = 7] [outer = (nil)] [url = about:blank]
[task 2019-11-18T00:09:03.418Z] 00:09:03     INFO -  --DOMWINDOW == 40 (0x7f155c8c2400) [pid = 1235] [serial = 10] [outer = (nil)] [url = about:blank]
[task 2019-11-18T00:09:06.089Z] 00:09:06     INFO -  ++DOCSHELL 0x7f1551224800 == 20 [pid = 1235] [id = {e5b869f6-14e4-4a2b-abcb-88365167b80b}]
[task 2019-11-18T00:09:06.089Z] 00:09:06     INFO -  ++DOMWINDOW == 41 (0x7f1557fc65c0) [pid = 1235] [serial = 45] [outer = (nil)]
[task 2019-11-18T00:09:06.090Z] 00:09:06     INFO -  ++DOMWINDOW == 42 (0x7f1554c3a400) [pid = 1235] [serial = 46] [outer = 0x7f1557fc65c0]
[task 2019-11-18T00:09:06.166Z] 00:09:06     INFO -  [1235, Main Thread] WARNING: NS_ENSURE_TRUE(root) failed: file /builds/worker/workspace/build/src/layout/base/nsDocumentViewer.cpp, line 3170
[task 2019-11-18T00:09:08.029Z] 00:09:08     INFO -  --DOMWINDOW == 41 (0x7f15580f3000) [pid = 1235] [serial = 29] [outer = (nil)] [url = chrome://messenger/content/multimessageview.xhtml]
[task 2019-11-18T00:09:08.030Z] 00:09:08     INFO -  --DOMWINDOW == 40 (0x7f155b2cb400) [pid = 1235] [serial = 22] [outer = (nil)] [url = about:blank]
[task 2019-11-18T00:09:18.913Z] 00:09:18     INFO -  [1235, Main Thread] WARNING: NS_ENSURE_TRUE(mCacheEntry) failed: file /builds/worker/workspace/build/src/netwerk/protocol/http/nsHttpChannel.cpp, line 5427
[task 2019-11-18T00:09:24.649Z] 00:09:24     INFO -  --DOCSHELL 0x7f1551229800 == 19 [pid = 1235] [id = {606072f8-549f-4d80-ba08-b7f9aea8b644}] [url = chrome://messenger/content/FilterListDialog.xul]
[task 2019-11-18T00:09:24.649Z] 00:09:24     INFO -  --DOCSHELL 0x7f155538c000 == 18 [pid = 1235] [id = {2c1c17e4-9195-422e-a428-67e52240f262}] [url = chrome://messenger/content/customizeToolbar.xul]
[task 2019-11-18T00:09:24.650Z] 00:09:24     INFO -  --DOCSHELL 0x7f1555070800 == 17 [pid = 1235] [id = {a4aff5b9-c3c4-4972-878b-ae71d3d05ba8}] [url = chrome://messenger/content/FilterEditor.xul]
[task 2019-11-18T00:09:24.651Z] 00:09:24     INFO -  --DOCSHELL 0x7f1551d9e800 == 16 [pid = 1235] [id = {92d6fbce-c0a2-4460-bab9-cec1ce4cb5da}] [url = chrome://messenger/content/FilterEditor.xul]
[task 2019-11-18T00:09:25.072Z] 00:09:25     INFO -  --DOMWINDOW == 39 (0x7f1562269c40) [pid = 1235] [serial = 41] [outer = (nil)] [url = chrome://messenger/content/FilterEditor.xul]
[task 2019-11-18T00:09:25.072Z] 00:09:25     INFO -  --DOMWINDOW == 38 (0x7f1557fc63e0) [pid = 1235] [serial = 43] [outer = (nil)] [url = chrome://messenger/content/FilterEditor.xul]
[task 2019-11-18T00:09:29.022Z] 00:09:29     INFO -  --DOMWINDOW == 37 (0x7f1562dab800) [pid = 1235] [serial = 42] [outer = (nil)] [url = about:blank]
[task 2019-11-18T00:09:29.023Z] 00:09:29     INFO -  --DOMWINDOW == 36 (0x7f15558d0400) [pid = 1235] [serial = 44] [outer = (nil)] [url = about:blank]
*[task 2019-11-18T00:11:17.259Z] 00:11:17     INFO -  Timeout: bridge.execFunction("a296d460-0997-11ea-a89a-0242ac110004", bridge.registry["{1b84a6dc-63b6-40a0-984e-e0cba764d573}"]["cleanQuit"], [])
[task 2019-11-18T00:11:17.259Z] 00:11:17     INFO -  INFO Passed: 6
[task 2019-11-18T00:11:17.259Z] 00:11:17     INFO -  INFO Failed: 0
[task 2019-11-18T00:11:17.260Z] 00:11:17     INFO -  INFO Skipped: 0

Comment 7

[ISHIKAWA, Chiaki]

This problem is still there as of Dec 17, 2019.

Comment 8

[Magnus Melin [:mkmelin]]

mozmill is gone