1809344 - perma comm/mail/test/browser/folder-pane/browser_folderPaneConsumers.js | Test timed out

Status: RESOLVED WORKSFORME

(Thunderbird :: General, defect, P5)

Description

[Treeherder Bug Filer]

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

---

Comment 1

[Magnus Melin [:mkmelin]]

Seems to have happened for some time bug 1806330 was flooding the error field so it didn't get noticed

Comment 2

[Intermittent Failures Robot]

15 failures in 664 pushes (0.023 failures/push) were associated with this bug yesterday.

Repository breakdown:

• comm-central: 15

Platform and build breakdown:

• linux1804-64-qr: 4
  • debug: 3
  • opt: 1
• windows10-32-2004-qr: 4
  • opt: 2
  • debug: 2
• linux1804-64-shippable-qr: 3
  • opt: 3
• windows10-32-2004-shippable-qr: 2
  • opt: 2
• windows10-64-2004-qr: 2
  • debug: 2

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

Comment 3

[ISHIKAWA, Chiaki]

Attachment: excerpt of (browser_folderPaneConsumers.js testing from local log of testing DEBUG version C-C TB

I am testing the DEBUG version of C-C TB on my local PC under Debian GNU/Linux.
I have noticed the timeout also.
In the attached log, there are a few errors that stand out.

1. modal dailog timeout. It seems the time out for it is 10 seconds.

140:11.82 INFO Entering test bound test_offline_sync_folder_selection_tree
140:22.75 GECKO(34195) JavaScript error: resource://testing-common/mozmill/WindowHelpers.jsm, line 378: Error: Timeout while waiting for modal dialog.
140:22.75 INFO Console message: [JavaScript Error: "Error: Timeout while waiting for modal dialog.
" {file: "resource://testing-common/mozmill/WindowHelpers.jsm" line: 378}]
notify@resource://testing-common/mozmill/WindowHelpers.jsm:378:13

140:25.86 GECKO(34195) NS_NewBufferedOutputStream: outputStream (= std::m

This seems to be new.

2. The we have the following error.

144:25.38 GECKO(34195) [2023-01-12T13:31:56Z WARN  rkv::backend::impl_safe::environment] `load_ratio()` is irrelevant for this storage backend.
144:25.39 GECKO(34195) console.error: (new Error("Polling for changes failed: Unexpected content-type \"text/plain;charset=US-ASCII\".", "resource://services-settings/remote-settings.js", 334))

"Polling for changes failed ..." has been filed as bug 1810074
in relation to another timeout error, 1802401.

3. Some addon update list error.

146:25.40 GECKO(34195) 1673530436686	addons.xpi	ERROR	System addon update list error Error: got node name: html, expected: updates
146:25.40 INFO Console message: [JavaScript Error: "1673530436686	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

This has been filed in relation to another timeout. Bug 1763045

So in a sense, only the first modal dialog timeout is new.

However, I am a bit surprised after looking at the log.
It seems that test either knowingly, or unknowingly under the hood, spawned many processes and they had to be killed. The number seems a bit too excessive. But I am not that familiar with particular test. Still I have a feeling that some processes that ought to have been killed were not killed properly before the timeout occurred and that may be one of the reasons of misbehavior (?).
Just a wild guess.

161:34.81 INFO TEST-UNEXPECTED-TIMEOUT | comm/mail/test/browser/folder-pane/browser_folderPaneConsumers.js | application timed out after 3700 seconds with no output
161:34.81 ERROR Force-terminating active process(es).
161:34.81 INFO Determining child pids from psutil...
161:34.81 INFO [34307, 34352]
161:34.81 INFO ==> process 34195 launched child process 34208
161:34.81 INFO ==> process 34195 launched child process 34307
161:34.81 INFO ==> process 34195 launched child process 34352
161:34.81 INFO ==> process 34195 launched child process 34371
161:34.81 INFO ==> process 34195 launched child process 34372
161:34.81 INFO ==> process 34195 launched child process 34373
161:34.81 INFO ==> process 34195 launched child process 34374
161:34.81 INFO ==> process 34195 launched child process 34375
161:34.81 INFO ==> process 34195 launched child process 34376
161:34.81 INFO ==> process 34195 launched child process 34377
161:34.81 INFO ==> process 34195 launched child process 34378
161:34.81 INFO ==> process 34195 launched child process 34379
161:34.81 INFO ==> process 34195 launched child process 34380
161:34.81 INFO ==> process 34195 launched child process 34388
161:34.81 INFO ==> process 34195 launched child process 34389
161:34.81 INFO ==> process 34195 launched child process 34390
161:34.81 INFO Found child pids: {34208, 34371, 34307, 34372, 34373, 34374, 34375, 34376, 34377, 34378, 34379, 34380, 34352, 34388, 34389, 34390}
handleTimeout(): browser_pid =	34195
...

Anyway, these timeout really makes my life miserable since I set maximum timeout very large at 3600-3700 in order to cover the lengthy timeout from running C-C TB under valgrind.
Yes, I have been trying to run mochitest and xpcshell test using valgrind + C-C TB combination.
This has found many memory errors over the years, but lately for the last couple of years and more
not working as smoothly as before.
I don't want the NORMAL testing to hit the long timeout often and thus filing this comment.

I hope someone can figure out the cause of the intiial modal dailog timeout.
Also for the remaining two issues.

Comment 4

[ISHIKAWA, Chiaki]

Attachment: find-long-pause.awk

BTW, the local log suggests the following long pauses occurred during testing of this particular test, folderPaneConsumers.js

I simply take the first field of the local log line (timestamp) and compared the next line's timestamp to see if there was a long lapse. (This suggests a long time without any warning/error/informational output.

140:09.47 TEST_START: comm/mail/test/browser/folder-pane/browser_folderPaneConsumers.js
LONG PAUSE FOUND: 28.910000 seconds
LONG PAUSE FOUND: 86.410000 seconds
LONG PAUSE FOUND: 119.510000 seconds
LONG PAUSE FOUND: 30.080000 seconds
LONG PAUSE FOUND: 89.440000 seconds
LONG PAUSE FOUND: 120.010000 seconds
LONG PAUSE FOUND: 120.000000 seconds
LONG PAUSE FOUND: 33.590000 seconds
LONG PAUSE FOUND: 600.020000 seconds
LONG PAUSE FOUND: 35.310000 seconds
161:42.17 TEST_START: comm/mail/test/browser/folder-tree-modes/bro

So this test is suffering from many timeouts, short and long.

I am using the following gawk script and the following shell command line to produce the long pause output.

gawk -f ~/Dropbox/TB-DIR/find-long-pause.awk $FA | egrep -a "(LONG PAUSE FOUND|TEST_START|TEST_END)" | grep -2 "LONG PAUSE"

where $FA is the local log name.
find-long-pause.awk is attached FYI.

You may need to patch |mach| so that it does not insert a space at the beggining of a long line as in
EDIT/MOD: I need to quote the following lines to show the space. Ugh.

 8:12.25 ...
instead of
08:12.25 ...

The patch to machformatter.py. I got this from mozilla mailing list.

# HG changeset patch
# User ISHIKAWA, Chiaki <[e-mail]>
# Parent  d09c36669e48caed0e0b0b3b5b5a8a77615be9ea
Log timestamp now has leading 0 without leading space

diff --git a/testing/mozbase/mozlog/mozlog/formatters/machformatter.py b/testing/mozbase/mozlog/mozlog/formatters/machformatter.py
--- a/testing/mozbase/mozlog/mozlog/formatters/machformatter.py
+++ b/testing/mozbase/mozlog/mozlog/formatters/machformatter.py
@@ -36,17 +36,18 @@ color_dict = {
 }
 
 DEFAULT = "\x1b(B\x1b[m"
 
 
 def format_seconds(total):
     """Format number of seconds to MM:SS.DD form."""
     minutes, seconds = divmod(total, 60)
-    return "%2d:%05.2f" % (minutes, seconds)
+    return "%02d:%05.2f" % (minutes, seconds)
+
 
 
 class TerminalColors(object):
     def __init__(self, term, color_dict):
         for key, value in color_dict.items():
             attribute = getattr(term, value)
             # In Blessed, these attributes aren't always callable. We can assume
             # that if they're not, they're just the raw ANSI Escape Sequences.

I hope this is helpful for those who are hunting the timeout issues.

Comment 5

[Intermittent Failures Robot]

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

This is the #11 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:

• comm-central: 55

Platform and build breakdown:

• linux1804-64-qr: 16
  • opt: 8
  • debug: 8
• linux1804-64-shippable-qr: 9
  • opt: 9
• windows10-64-2004-qr: 9
  • debug: 8
  • opt: 1
• windows10-32-2004-qr: 12
  • debug: 9
  • opt: 3
• windows10-64-2004-shippable-qr: 4
  • opt: 4
• windows10-64-2004-asan-qr: 1
  • opt: 1
• windows10-32-2004-shippable-qr: 4
  • opt: 4

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

Comment 6

[Intermittent Failures Robot]

11 failures in 3717 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• comm-central: 11

Platform and build breakdown:

• windows10-32-2004-qr: 2
  • debug: 2
• linux1804-64-qr: 5
  • debug: 2
  • opt: 3
• linux1804-64-shippable-qr: 2
  • opt: 2
• windows10-64-2004-qr: 2
  • debug: 2

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

Comment 7

[Geoff Lankow (:darktrojan) [PTO, back 9 Feb]]

Mass closure of all bugs in the Calendar, MailNews Core, and Thunderbird components with the "intermittent-failure" keyword and no activity in the last six months.