1802401 - Intermittent comm/calendar/test/browser/eventDialog/browser_attendeesDialog.js | single tracking bug

Status: RESOLVED WORKSFORME

(Calendar :: Dialogs, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: mkmelin [at] iki.fi
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=397644281&repo=comm-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/ZAgfVtWVTgG1E_NNt6rbVw/runs/0/artifacts/public/logs/live_backing.log

---

Comment 1

[Intermittent Failures Robot]

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

Repository breakdown:

• comm-central: 1

Platform and build breakdown:

• linux1804-64-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1802401&startday=2022-11-21&endday=2022-11-27&tree=all

Comment 2

[Intermittent Failures Robot]

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

Repository breakdown:

• comm-central: 1

Platform and build breakdown:

• linux1804-64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1802401&startday=2022-12-05&endday=2022-12-11&tree=all

Comment 3

[Intermittent Failures Robot]

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

Repository breakdown:

• comm-central: 1

Platform and build breakdown:

• linux1804-64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1802401&startday=2023-01-02&endday=2023-01-08&tree=all

Comment 4

[ISHIKAWA, Chiaki]

Attachment: Local log of browser_attendeesDialog.js test with recorded timeout.

I see this test causes time out during my local mochitest tesinng using DEBUG version of C-C TB.

From a summary of local log:

comm/calendar/test/browser/eventDialog/browser_attendeesDialog.js
LONG PAUSE FOUND: 111.750000 seconds
LONG PAUSE FOUND: 119.510000 seconds
LONG PAUSE FOUND: 119.530000 seconds
LONG PAUSE FOUND: 120.000000 seconds
LONG PAUSE FOUND: 120.010000 seconds
LONG PAUSE FOUND: 668.890000 seconds

Eventually the test his the time out of 3700 I set.
I set a large value for timeout because I wanted to test C-C TB under valgrind and
the timeout value was made larger, but I did not expect the test running normally to hit this timeout value. Ugh.

25:07.24 INFO TEST-UNEXPECTED-TIMEOUT | comm/calendar/test/browser/eventDialog/browser_attendeesDialog.js | application timed out after 3700 seconds with no output

But now I realize the timeout value from |mach|, 3700, may not be quite right because when I look at the local log, the timestamp when the error was reported had only about 11 minutes of lapse between two printed lines with timestamp.

The last activity recorded before the timeout was:

13:58.35 GECKO(6141) NS_NewBufferedOutputStream: outputStream (= std::move(aOutputputStream)) =0x7f1994023188

and the line that got printed immediately after the timeout processing took place was this:

25:07.24 INFO Buffered messages finished
25:07.24 INFO TEST-UNEXPECTED-TIMEOUT | comm/calendar/test/browser/eventDialog/browser_attendeesDialog.js | application timed out after 3700 seconds with no output

There seems to be
self.timeout set to 1300, and
output time out set to 3700,
and the test hits the self.timeout (1300), but somehow |mach| prints out the output timeout value (or maybe my local patch prints the incorrect timeout value?)
I have modified local |mach| heavily to figure out where the timeout value is set and
how I could improve the timeout setting for |valgrind| operation to run C-C TB under it without hitting the timeout too often.

Anyway timeout for about 20 minutes (1200-1300 seconds) is for real.
I wonder how to make this time out disappear.

There are two unusual errors during the test:
One is:

07:57.83 GECKO(6141) console.error: (new Error("Polling for changes failed: Unexpected content-type \"text/plain;charset=US-ASCII\".", "resource://services-settings/remote-settings.js", 334))

and the second one is:

09:57.86 GECKO(6141) 1673522249140	addons.xpi	ERROR	System addon update list error Error: got node name: html, expected: updates
09:57.86 INFO Console message: [JavaScript Error: "1673522249140	addons.xpi	ERROR	System addon update list error Error: got node name: html, expected: updates" {file: "resource://gre/modules/Log.sys.mjs" line: 723}]
append@resource://gre/modules/Log.sys.mjs:723:12
log@resource://gre/modules/Log.sys.mjs:377:16
error@resource://gre/modules/Log.sys.mjs:385:10
updateSystemAddons/res<@resource://gre/modules/addons/XPIInstall.jsm:4104:25
editAttendees@chrome://calendar/content/calendar-item-iframe.js:1987:13
receiveMessage@chrome://calendar/content/calendar-item-iframe.js:252:7

09:57.86 INFO Console message: [JavaScript Error: "1673522249140	addons.xpi	ERROR	System addon update list error Error: got node name: html, expected: updates" {file: "resource://gre/modules/Log.sys.mjs" line: 723}]
append@resource://gre/modules/Log.sys.mjs:723:12
log@resource://gre/modules/Log.sys.mjs:377:16
error@resource://gre/modules/Log.sys.mjs:385:10
updateSystemAddons/res<@resource://gre/modules/addons/XPIInstall.jsm:4104:25
editAttendees@chrome://calendar/content/calendar-item-iframe.js:1987:13
receiveMessage@chrome://calendar/content/calendar-item-iframe.js:252:7

The second error seems to kick in asynchronously relative to the test executed and this error is regularly seen in my log and I suspect this could be the cause of the strange timeout.

I think it is important to check addon update feature, but I have a suspicion that many tests are not ready to handle the asynchronous update to happen during execution.

The first error

log1520-mochitest.txt:07:57.83 GECKO(6141) console.error: (new Error("Polling for changes failed: Unexpected content-type \"text/plain;charset=US-ASCII\".", "resource://services-settings/remote-settings.js", 334))

is a relative newcomer. I have only observed it since December 2022. (not that I run mochitest often enough. Due to the long timeout, I am discouraged to do so, and run it maybe once a month now.
I run mochitest mostly to check backend these days. With the long timeout, on my PC, local mochitest took 10976 seconds to finish. Close to 3 hours heavy CPU and memory usage. xpcstest finishes in about 1200 seconds.

Anyway, the "Polling for changes failed" comes from
the following line in C-C.
https://searchfox.org/comm-central/source/mozilla/services/settings/remote-settings.js#334

"Unexpected content-type" is thrown from the following line:
https://searchfox.org/comm-central/source/mozilla/services/settings/Utils.jsm#407

const ct = response.headers.get("Content-Type");
if (!is404FromCustomServer && (!ct || !ct.includes("application/json"))) {
  throw new Error(`Unexpected content-type "${ct}"`);

Comparing the code and the log suggests that whatever returns the header did not return "application/json" data, but "test/plain;charset=US-ASCII". This should be a clear enough hint.

I hope this information leads to the root cause and hopefully a solution.

Comment 5

[ISHIKAWA, Chiaki]

For "console.error: (new Error("Polling for changes failed: Unexpected content-type "text/plain;charset=US-ASCII".", "resource://services-settings/remote-settings.js", 334))", I filed the following bugzilla.
Bug 1810074

Comment 6

[ISHIKAWA, Chiaki]

The second error in comment 4, namely

09:57.86 GECKO(6141) 1673522249140	addons.xpi	ERROR	System addon update list error Error: got node name: html, expected: updates

is the subject of Bug 1763045
and it was also considered a possible cause of the timeout issue.
But this may happen only on local testing environment. See Bug 1763045

Now it looks to me there are a few errors involved in this timeout issues.

Comment 7

[Intermittent Failures Robot]

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

Repository breakdown:

• comm-central: 2

Platform and build breakdown:

• linux1804-64-shippable-qr: 1
  • opt: 1
• linux1804-64-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1802401&startday=2023-01-09&endday=2023-01-15&tree=all

Comment 8

[ISHIKAWA, Chiaki]

browser_attendeesDialog.js is now experiencing another error: Bug 1812240

Comment 9

[Intermittent Failures Robot]

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

Repository breakdown:

• comm-central: 1

Platform and build breakdown:

• windows10-64-2004-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1802401&startday=2023-01-23&endday=2023-01-29&tree=all

Comment 10

[ISHIKAWA, Chiaki]

(In reply to ISHIKAWA, Chiaki from comment #8)

browser_attendeesDialog.js is now experiencing another error: Bug 1812240

bug 1812240 is now fixed.

So the culprit needs to be found elsewhere.

Comment 11

[Intermittent Failures Robot]

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

Repository breakdown:

• comm-central: 1

Platform and build breakdown:

• linux1804-64-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1802401&startday=2023-02-06&endday=2023-02-12&tree=all

Comment 12

[Intermittent Failures Robot]

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

Repository breakdown:

• comm-central: 2

Platform and build breakdown:

• linux1804-64-qr: 2
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1802401&startday=2023-02-13&endday=2023-02-19&tree=all

Comment 13

[Intermittent Failures Robot]

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

Repository breakdown:

• comm-central: 1

Platform and build breakdown:

• macosx1015-64-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1802401&startday=2023-03-13&endday=2023-03-19&tree=all

Comment 14

[ISHIKAWA, Chiaki]

Attachment: The screen when the long wait that leads to timeout occurs.

The local mochitest gets hung (and timeout kicks in later) at the place where the local log shows the following and the screen is as attached.
I hope this may give some clue to the cause of the timeout.

This is taken under Debian GNU/Linux with some addtional local debug output added.
I ran comm/calendar/test/browser/eventDialog/browser_attendeesDialog.js as a single mochitest target.
(I realize the timeout from this test screws up a few following tests as well. They run successfully when they are run independently.)

...
00:14.47 PASS empty attendee input should have focus - [object HTMLInputElement] == [object HTMLInputElement] - 
00:14.47 PASS 1 == 1 - 
00:14.47 PASS 0 == 0 - 
00:14.47 INFO Sending free/busy response for mailto:mochitest@invalid
00:14.50 FAIL 1 == 0 - {"filename":"chrome://mochitests/content/browser/comm/calendar/test/browser/eventDialog/browser_attendeesDialog.js","name":"checkFreeBusy","sourceId":654,"lineNumber":89,"columnNumber":12,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"chrome://mochitests/content/browser/comm/calendar/test/browser/eventDialog/browser_attendeesDialog.js","name":null,"sourceId":654,"lineNumber":119,"columnNumber":11,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"chrome://mochikit/content/browser-test.js","name":"handleTask","sourceId":608,"lineNumber":1039,"columnNumber":26,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"_runTaskBasedTest","sourceId":608,"lineNumber":1111,"columnNumber":18,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"Tester_execTest","sourceId":608,"lineNumber":1253,"columnNumber":14,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"nextTest/<","sourceId":608,"lineNumber":1028,"columnNumber":14,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/tests/SimpleTest/SimpleTest.js","name":"SimpleTest.waitForFocus/<","sourceId":635,"lineNumber":1053,"columnNumber":13,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":null,"formattedStack":"SimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1053:13\n","nativeSavedFrame":{}},"formattedStack":"nextTest/<@chrome://mochikit/content/browser-test.js:1028:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1053:13\n","nativeSavedFrame":{}},"formattedStack":"Tester_execTest@chrome://mochikit/content/browser-test.js:1253:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1028:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1053:13\n","nativeSavedFrame":{}},"formattedStack":"_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1111:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1253:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1028:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1053:13\n","nativeSavedFrame":{}},"formattedStack":"async*handleTask@chrome://mochikit/content/browser-test.js:1039:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1111:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1253:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1028:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1053:13\n","nativeSavedFrame":{}},"caller":null,"formattedStack":"async*@chrome://mochitests/content/browser/comm/calendar/test/browser/eventDialog/browser_attendeesDialog.js:119:11\nasync*handleTask@chrome://mochikit/content/browser-test.js:1039:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1111:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1253:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1028:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1053:13\n","nativeSavedFrame":{}},"caller":null,"formattedStack":"checkFreeBusy@chrome://mochitests/content/browser/comm/calendar/test/browser/eventDialog/browser_attendeesDialog.js:89:12\nasync*@chrome://mochitests/content/browser/comm/calendar/test/browser/eventDialog/browser_attendeesDialog.js:119:11\nasync*handleTask@chrome://mochikit/content/browser-test.js:1039:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1111:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1253:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1028:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1053:13\n","nativeSavedFrame":{}}
Stack trace:
chrome://mochitests/content/browser/comm/calendar/test/browser/eventDialog/browser_attendeesDialog.js:checkFreeBusy:89
chrome://mochitests/content/browser/comm/calendar/test/browser/eventDialog/browser_attendeesDialog.js:null:119
chrome://mochikit/content/browser-test.js:handleTask:1039
chrome://mochikit/content/browser-test.js:_runTaskBasedTest:1111
chrome://mochikit/content/browser-test.js:Tester_execTest:1253
chrome://mochikit/content/browser-test.js:nextTest/<:1028
chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/<:1053
00:14.50 PASS 5 == 5 - 
00:14.75 PASS attendees list matches what was expected - ["mochitest@invalid","test@invalid",""] deepEqual ["mochitest@invalid","test@invalid",""] - 
00:14.76 PASS empty attendee input should have focus - [object HTMLInputElement] == [object HTMLInputElement] - 
00:14.76 PASS 1 == 1 - 
00:14.76 PASS 0 == 0 - 
00:14.76 INFO Sending free/busy response for mailto:mochitest@invalid
00:33.36 GECKO(222095) [WARN  rkv::backend::impl_safe::environment] `load_ratio()` is irrelevant for this storage backend.
00:33.37 GECKO(222095) console.error: (new Error("Polling for changes failed: Unexpected content-type \"text/plain;charset=US-ASCII\".", "resource://services-settings/remote-settings.sys.mjs", 324))
00:33.86 GECKO(222095) NS_NewBufferedOutputStream: outputStream (= std::move(aOutputputStream)) =0x7fbea8005f28
00:38.43 GECKO(222095) NS_NewBufferedOutputStream: outputStream (= std::move(aOutputputStream)) =0x7fbe94118ef8
...[stuck no progress]...

Comment 15

[ISHIKAWA, Chiaki]

BTW, I run local tests using a virtual desktop of X11 provided by Xepyhr and so that is the window you see in the attachment in the previous comment. Using this set up, I can continue to use my PC for other work while the test proceeds. I have been doing the test locally in this manner for about a dozen years now.

Comment 16

[Intermittent Failures Robot]

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

Repository breakdown:

• comm-central: 1

Platform and build breakdown:

• linux1804-64-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1802401&startday=2023-04-10&endday=2023-04-16&tree=all

Comment 17

[ISHIKAWA, Chiaki]

The latest local log near the timeout is as follows.:

00:30.48 PASS 0 == 0 - 
00:30.48 INFO Sending free/busy response for mailto:[e-mail]
00:30.52 FAIL 1 == 0 - {"filename":"chrome://mochitests/content/browser/comm/calendar/test/browser/eventDialog/browser_attendeesDialog.js","name":"checkFreeBusy","sourceId":655,"lineNumber":99,"columnNumber":12,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"chrome://mochitests/content/browser/comm/calendar/test/browser/eventDialog/browser_attendeesDialog.js","name":null,"sourceId":655,"lineNumber":129,"columnNumber":11,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"chrome://mochikit/content/browser-test.js","name":"handleTask","sourceId":609,"lineNumber":1133,"columnNumber":26,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"_runTaskBasedTest","sourceId":609,"lineNumber":1205,"columnNumber":18,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"Tester_execTest","sourceId":609,"lineNumber":1347,"columnNumber":14,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"nextTest/<","sourceId":609,"lineNumber":1122,"columnNumber":14,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/tests/SimpleTest/SimpleTest.js","name":"SimpleTest.waitForFocus/<","sourceId":636,"lineNumber":1056,"columnNumber":13,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":null,"formattedStack":"SimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13\n","nativeSavedFrame":{}},"formattedStack":"nextTest/<@chrome://mochikit/content/browser-test.js:1122:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13\n","nativeSavedFrame":{}},"formattedStack":"Tester_execTest@chrome://mochikit/content/browser-test.js:1347:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1122:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13\n","nativeSavedFrame":{}},"formattedStack":"_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1205:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1347:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1122:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13\n","nativeSavedFrame":{}},"formattedStack":"async*handleTask@chrome://mochikit/content/browser-test.js:1133:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1205:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1347:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1122:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13\n","nativeSavedFrame":{}},"caller":null,"formattedStack":"async*@chrome://mochitests/content/browser/comm/calendar/test/browser/eventDialog/browser_attendeesDialog.js:129:11\nasync*handleTask@chrome://mochikit/content/browser-test.js:1133:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1205:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1347:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1122:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13\n","nativeSavedFrame":{}},"caller":null,"formattedStack":"checkFreeBusy@chrome://mochitests/content/browser/comm/calendar/test/browser/eventDialog/browser_attendeesDialog.js:99:12\nasync*@chrome://mochitests/content/browser/comm/calendar/test/browser/eventDialog/browser_attendeesDialog.js:129:11\nasync*handleTask@chrome://mochikit/content/browser-test.js:1133:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1205:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1347:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1122:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13\n","nativeSavedFrame":{}}
Stack trace:
chrome://mochitests/content/browser/comm/calendar/test/browser/eventDialog/browser_attendeesDialog.js:checkFreeBusy:99
chrome://mochitests/content/browser/comm/calendar/test/browser/eventDialog/browser_attendeesDialog.js:null:129
chrome://mochikit/content/browser-test.js:handleTask:1133
chrome://mochikit/content/browser-test.js:_runTaskBasedTest:1205
chrome://mochikit/content/browser-test.js:Tester_execTest:1347
chrome://mochikit/content/browser-test.js:nextTest/<:1122
chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/<:1056
00:30.52 PASS 5 == 5 - 
00:30.71 GECKO(7986) [Parent 7986, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/layout/generic/nsFrameSelection.cpp:1674
00:30.74 GECKO(7986) [Parent 7986, Main Thread] WARNING: NS_ENSURE_TRUE(parentPresShell) failed: file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/layout/base/PresShell.cpp:6671
00:30.85 PASS attendees list matches what was expected - ["[e-mail]","[e-mail]",""] deepEqual ["[e-mail]","[e-mail]",""] - 
00:30.86 PASS empty attendee input should have focus - [object HTMLInputElement] == [object HTMLInputElement] - 
00:30.86 PASS 1 == 1 - 
00:30.86 PASS 0 == 0 - 
00:30.86 INFO Sending free/busy response for mailto:[e-mail]
00:46.21 GECKO(7986) [WARN  rkv::backend::impl_safe::environment] `load_ratio()` is irrelevant for this storage backend.
00:46.23 GECKO(7986) console.error: (new Error("Polling for changes failed: Unexpected content-type \"text/plain;charset=US-ASCII\".", "resource://services-settings/remote-settings.sys.mjs", 324))
00:46.70 GECKO(7986) NS_NewBufferedOutputStream: outputStream (= std::move(aOutputputStream)) =0x7f2d0c007088
00:53.35 GECKO(7986) NS_NewBufferedOutputStream: outputStream (= std::move(aOutputputStream)) =0x7f2d3c040cf8
04:26.69 GECKO(7986) [WARN  webrender::renderer::init] asking to enable_gpu_markers but no supporting extension was found

checkFreeBusy() is

  async function checkFreeBusy(row, count) {
    Assert.equal(row._freeBusyDiv.querySelectorAll(".pending").length, 1);
    Assert.equal(row._freeBusyDiv.querySelectorAll(".busy").length, 0);
    let responsePromise = BrowserTestUtils.waitForEvent(row, "freebusy-update-finished");
    freeBusyProvider.sendNextResponse();
    await responsePromise;
    Assert.equal(row._freeBusyDiv.querySelectorAll(".pending").length, 0);     <=== line 99
    Assert.equal(row._freeBusyDiv.querySelectorAll(".busy").length, count);
  }

I wonder if the local test environment needs to be set up to permit the sending of e-mail to [e-mail], or if such setting is supposed to be automagically done by a local fake smtp server?
I am afraid that my crrent local setup may not be quite similar to the one on the tryserver.

The long timeout about 20 minutes from this test is really bothersome for local testing.

Comment 18

[Martin Schröder [:mschroeder]]

Does your problem with browser_attendeesDialog.js still reproduce? Otherwise I would resolve this issue as WORKSFORME.

Comment 19

[ISHIKAWA, Chiaki]

(In reply to Martin Schröder [:mschroeder] from comment #18)

Does your problem with browser_attendeesDialog.js still reproduce? Otherwise I would resolve this issue as WORKSFORME.

Sorry I am have been down with Covid-19 and recovery has been very slow. I will check it as soon as I can. But don't hold your breath, I am afraid.

Comment 20

[ISHIKAWA, Chiaki]

Attachment: Local log for mochitest comm/calendar/test/browser/eventDialog/browser_attendeesDialog.js

(In reply to Martin Schröder [:mschroeder] from comment #18)

Does your problem with browser_attendeesDialog.js still reproduce? Otherwise I would resolve this issue as WORKSFORME.

I am finally back from Covid-19 complication.

I have verified that it still reproduces locally.

Let me explain.
I am testing TB DEBUG build locally under Debian GNU/Linux.
This certainly reproduces under linux locally and is a big headache because it uses up the largest timeout value I set.
I want to make it large to accommodate the execution of the whole test under valgrind. This long pause here uses up, say, 3600 seconds. :-(

HOWEVER , now I notice this timeout does not seem to occur on tryserver.
I downloaded the logs from try server and verified that it does not seem to show the
long timeout. I mean the test finishes in 44 seconds on tryserver.

Something is different between tryserver and the local test.

Also, I now notice "FAIL Unexpected save prompt appeared ..." error when I run this test locally before the long pause and time out occurs locally. This does not happen on tryserver.

Also, I notice a grave issue in the manner log is recorded and presented to the submitter.
In my local test log, I see something like this.
I mark the lines of interest with "*" at the beginning.

05:51.15 GECKO(27970) [WARN  webrender::device::gl] Cropping texture upload Box2D((0, 0), (0, 1)) to None
05:51.15 GECKO(27970) [WARN  webrender::device::gl] Cropping texture upload Box2D((0, 0), (0, 1)) to None
* 05:51.59 INFO Sending free/busy response for mailto:[e-mail]
05:51.69 GECKO(27970) [Parent 27970, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/layout/generic/nsFrameSelection.cpp:1710
05:51.70 GECKO(27970) [Parent 27970, Main Thread] WARNING: NS_ENSURE_TRUE(parentPresShell) failed: file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/layout/base/PresShell.cpp:6687
* 05:51.71 INFO Sending free/busy response for mailto:[e-mail]
05:51.73 GECKO(27970) NS_NewBufferedOutputStream: outputStream (= std::move(aOutputputStream)) =0x7f0d7001c8d8

The lines "INFO Sending free/busy ..." makes it possible for me to co-relate the hung/long pause with the action of the test.
It is printed at https://searchfox.org/comm-central/source/calendar/test/browser/eventDialog/browser_attendeesDialog.js#428

BUT the log on the tryserver does not seem to preserve the information.
Furthermore, I notice that the lines such as follows in the local log to verify that each of the tests pass, etc.
are not in the tryserver log.
From my local log:

00:10.01 PASS {} == {} - 
00:10.01 PASS null == null - 
00:10.01 PASS "mailto:[e-mail]" == "mailto:[e-mail]" - 
00:10.02 PASS [] deepEqual [] - 
00:10.02 PASS "2023-10-22T13:00:00.000Z" == "2023-10-22T13:00:00.000Z" - 
00:10.02 PASS "2023-10-23T14:00:00.000Z" == "2023-10-23T14:00:00.000Z" - 
00:10.04 GECKO(69907) [WARN  webrender::device::gl] Cropping texture upload Box2D((0, 0), (0, 1)) to None
00:10.04 GECKO(69907) [WARN  webrender::device::gl] Cropping texture upload Box2D((0, 0), (0, 1)) to None
00:10.04 GECKO(69907) [WARN  webrender::device::gl] Cropping texture upload Box2D((0, 0), (0, 1)) to None
00:10.51 PASS attendees list matches what was expected - ["[e-mail]",""] deepEqual ["[e-mail]",""] - 
00:10.51 PASS empty attendee input should have focus - [object HTMLInputElement] == [object HTMLInputElement] - 
00:10.52 PASS 1 == 1 - 
00:10.52 PASS 0 == 0 - 

These are quite handy to figure out where the problem happens when something goes wrong during a test.
What gives?
Is there a special switch or something I need to pass to tryserver to see these lines in the tryserver log?

I am attaching a part of my local log for the mochitest comm/calendar/test/browser/eventDialog/browser_attendeesDialog.js.

I hacked runtests.py to figure out which timeout value the test was triggering and a few other verbose modification of test run scripts.
So there are additional debug messages, but you will notice there ARE a couple of
"FAIL Unexpected save prompt ..."

I suspect that there is a lack of proper wait (not long enough) in some dialog operation during the test.
As I look at the screen when the local test runs, I see some dialog windows pop up and disappear BEFORE they are fully displayed (the inside is totally black).
Maybe tryserver machines are too overloaded and we may not experience such too quick simulated interaction, but on my local PC, the mochitest code processing proceeds so fast that the timing issue manifests. That is my guess.

In any case, the lack of "INFO Sending free/busy ..." and other information in the tryserver log makes it a bit hard to figure out what goes on.

EDIT: fixed minor typographical issues.

Comment 22

[Intermittent Failures Robot]

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

Repository breakdown:

• comm-central: 1

Platform and build breakdown:

• linux1804-64-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1802401&startday=2024-03-04&endday=2024-03-10&tree=all

Comment 23

[Intermittent Failures Robot]

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

Repository breakdown:

• comm-central: 1

Platform and build breakdown:

• windows11-64-2009-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1802401&startday=2024-05-20&endday=2024-05-26&tree=all

Comment 24

[Intermittent Failures Robot]

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

Repository breakdown:

• comm-central: 1

Platform and build breakdown:

• macosx1015-64-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1802401&startday=2024-08-26&endday=2024-09-01&tree=all

Comment 25

[Intermittent Failures Robot]

Summary

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

Repository breakdown:

• comm-central: 1

Platform and build breakdown:

• linux1804-64-qr: 1
  • opt: 1

Table

	no_variant
linux1804-64-qr--/opt	1

For more details, see:

https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1802401&startday=2025-02-03&endday=2025-02-09&tree=all

Comment 26

[Intermittent Failures Robot]

Summary

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

Repository breakdown:

• comm-central: 1

Platform and build breakdown:

• windows11-32-2009-qr: 1
  • debug: 1

Table

	no_variant
windows11-32-2009-qr--/debug	1

For more details, see:

https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1802401&startday=2025-02-17&endday=2025-02-23&tree=all

Comment 27

[Geoff Lankow (:darktrojan)]

I'm closing all the intermittent-failure bugs in Calendar, Mailnews, and Thunderbird that aren't assigned and haven't been updated since February 2025. Sorry about the bugspam!