1763045 - addons.xpi ERROR System addon update list error Error: got node name: html, expected: updates

Status: NEW

(Thunderbird :: Testing Infrastructure, defect)

Description

[ISHIKAWA, Chiaki]

Attachment: Screen when the test seems to get hung.

I see a flurry of error messages which seem to suggest something is either
wrong from "system addon update list" or the routine to read it.

addons.xpi	ERROR	System addon update list error Error: got node name: html, expected: updates

I see them in my local test and show which tests cause them in the
following.
But I see them also in people's debug test runs on tryserver as well.

For example, BenC's job:
https://treeherder.mozilla.org/jobs?repo=try-comm-central&selectedTaskRun=D7urD9I9QZKCi9Pu6Vg_Yw.0&revision=4f2185929ff8a1df7c94c9d8c29ec090eb2d91b3
bct1: live_backing.log
https://firefoxci.taskcluster-artifacts.net/D7urD9I9QZKCi9Pu6Vg_Yw/0/public/logs/live_backing.log

From my local log:

egrep "(node name|TEST_START)" /FF-NEW/log1402-mochitest-13.txt
      ...
14:44.63 TEST_START: comm/calendar/test/browser/providers/browser_caldavCalendar_cached.js
21:07.35 GECKO(409654) 1649096515539	addons.xpi	ERROR	System addon update list error Error: got node name: html, expected: updates
21:07.35 INFO Console message: [JavaScript Error: "1649096515539	addons.xpi	ERROR	System addon update list error Error: got node name: html, expected: updates" {file: "resource://gre/modules/Log.jsm" line: 723}]
36:25.89 TEST_START: comm/calendar/test/browser/recurrence/browser_annual.js
         ...


41:21.89 TEST_START: comm/calendar/test/browser/recurrence/browser_lastDayOfMonth.js
42:50.18 INFO Console message: [JavaScript Error: "1649097818374	addons.xpi	ERROR	System addon update list error Error: got node name: html, expected: updates" {file: "resource://gre/modules/Log.jsm" line: 723}]
         ...
60:22.59 TEST_START: comm/mail/base/test/webextensions/browser_extension_update_background.js
60:23.39 INFO Console message: [JavaScript Error: "1649098871585	addons.xpi	ERROR	System addon update list error Error: got node name: html, expected: updates" {file: "resource://gre/modules/Log.jsm" line: 723}]
60:24.36 INFO Console message: [JavaScript Error: "1649098872540	addons.xpi	ERROR	System addon update list error Error: got node name: html, expected: updates" {file: "resource://gre/modules/Log.jsm" line: 723}]
60:25.12 INFO Console message: [JavaScript Error: "1649098873310	addons.xpi	ERROR	System addon update list error Error: got node name: html, expected: updates" {file: "resource://gre/modules/Log.jsm" line: 723}]
60:26.20 INFO Console message: [JavaScript Error: "1649098874385	addons.xpi	ERROR	System addon update list error Error: got node name: html, expected: updates" {file: "resource://gre/modules/Log.jsm" line: 723}]
60:26.97 INFO Console message: [JavaScript Error: "1649098875159	addons.xpi	ERROR	System addon update list error Error: got node name: html, expected: updates" {file: "resource://gre/modules/Log.jsm" line: 723}]
60:28.04 INFO Console message: [JavaScript Error: "1649098876213	addons.xpi	ERROR	System addon update list error Error: got node name: html, expected: updates" {file: "resource://gre/modules/Log.jsm" line: 723}]
60:30.05 TEST_START: comm/mail/base/test/webextensions/browser_extension_update_background_noprompt.js
60:30.27 INFO Console message: [JavaScript Error: "1649098878459	addons.xpi	ERROR	System addon update list error Error: got node name: html, expected: updates" {file: "resource://gre/modules/Log.jsm" line: 723}]
60:31.09 INFO Console message: [JavaScript Error: "1649098879272	addons.xpi	ERROR	System addon update list error Error: got node name: html, expected: updates" {file: "resource://gre/modules/Log.jsm" line: 723}]
60:32.03 INFO Console message: [JavaScript Error: "1649098880225	addons.xpi	ERROR	System addon update list error Error: got node name: html, expected: updates" {file: "resource://gre/modules/Log.jsm" line: 723}]
         ...
75:55.52 TEST_START: comm/mail/components/extensions/test/browser/browser_ext_compose_details.js
76:30.75 INFO Console message: [JavaScript Error: "1649099838926	addons.xpi	ERROR	System addon update list error Error: got node name: html, expected: updates" {file: "resource://gre/modules/Log.jsm" line: 723}]
         ...
105:33.06 TEST_START: comm/mail/test/browser/composition/browser_cp932Display.js
105:33.56 INFO Console message: [JavaScript Error: "1649101581741	addons.xpi	ERROR	System addon update list error Error: got node name: html, expected: updates" {file: "resource://gre/modules/Log.jsm" line: 723}]
          ...

129:21.19 TEST_START: comm/mail/test/browser/folder-display/browser_folderPaneVisibility.js
129:28.60 INFO Console message: [JavaScript Error: "1649103016640	addons.xpi	ERROR	System addon update list error Error: got node name: html, expected: updates" {file: "resource://gre/modules/Log.jsm" line: 723}]
          ...

In one case, test apparently gets hung without apparent activity at
least in my local setting. This is bad.

I believe this happens with the following test

14:44.63 TEST_START: comm/calendar/test/browser/providers/browser_caldavCalendar_cached.js
21:07.35 GECKO(409654) 1649096515539	addons.xpi	ERROR	System addon update list error Error: got node name: html, expected: updates
21:07.35 INFO Console message: [JavaScript Error: "1649096515539	addons.xpi	ERROR	System addon update list error Error: got node name: html, expected: updates" {file: "resource://gre/modules/Log.jsm" line: 723}]
36:25.89 TEST_START: comm/calendar/test/browser/recurrence/browser_annual.js

The screen when the test seemed to be hung is attached.
Please note tha the following test does not happen until about 15 minutes
later than the error message. (The first part of each log line is a
timestamp. The time string jumps from 21:07.35 to 36:25.89.)

The hung could be caused by other errors in the same test.
For example, I see the following error in the test log several times.

14:50.03 INFO Console message: [JavaScript Error: "An error occurred executing the cmd_selectAll command: [Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIController.doCommand]"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: chrome://global/content/globalOverlay.js :: goDoCommand :: line 128"  data: no]" {file: "chrome://global/content/globalOverlay.js" line: 131}]

Strange thing is that at least Benc's job on the tryserver I mentioned
does not seem to gets hung THAT long.
I wonder why.

This could be due to the different test set up on my local PC to
handle screen interaction when mochitest is executed on a PC. I am
using Xephyr virtual desktop program to create a virtual desktop in
which I run mochitest on my local PC so that its X11 activity does not
interfere with my ordinary X desktop activity.

If I am not mistaken tryserver uses a different virtual desktop setup
(is it using VNC?), that may explain it. But this is a long shot.

Anyway, We should eliminate the "System addon update list error Error" first.

Comment 1

[ISHIKAWA, Chiaki]

Attachment: Local log of the failing test.

Here is the local log of the hung test.
The strange dump near the end is due to my local modification to "runtests.py".
I am not sure WHICH timeout value triggred the timeout processing and
thus I modified "runtests.py" heavily to see which timeout value was the cause.
I could not figure it out yet.

(The original motivation to change runtests.py was to figure out how
to run TB under valgrind for memory checking and still do not get
timeout here and there. Valgrind slows down the execution
significantly and I hit unexpected timeout during local test runs
which I could not easily avoid even if I insert timeout extension
factor in many xpcshell.ini files ala

[test_sendBufferedCommand.js]
requesttimeoutfactor = 25

)

Here is the excerpted log.
I have inserted various dumps locally.

Comment 2

[ISHIKAWA, Chiaki]

Attachment: comm/calendar/test/browser/eventDialog/browser_attendeesDialog.js times out.

I said this in the original post.:

I believe this happens with the following test
14:44.63 TEST_START: comm/calendar/test/browser/providers/browser_caldavCalendar_cached.js

But, at least for the last couple of months, I think I have seen the test, comm/calendar/test/browser/eventDialog/browser_attendeesDialog.js, to time out possibly due to the issue filed here.

So this timeout issue may not be tied to a particular test, but any test that happens to be hit with this "System addon update list error".

The attached log produced locally using FULL DEBUG version of C-C TB under linux shows that the test, comm/calendar/test/browser/eventDialog/browser_attendeesDialog.js, times out.

However, please notice that the error is preceded by another error,

INFO Console message: [JavaScript Error: "Invalid ETag value "undefined"" {file: "resource://services-settings/SyncHistory.jsm" line: 52}]

This is something I observed in someone else's tryserver log in Bug 1805119, but I am not sure
if this "Innvalid ETag value" is related to this bug or just another symptom caused by a common underlying cause.

In any case, the timeout of the test comm/calendar/test/browser/eventDialog/browser_attendeesDialog.js is likely the result of two errors one in this bugzilla and the other bug 1805199 during its execution.

Comment 3

[ISHIKAWA, Chiaki]

BTW, I think treeherder ought to classify a hung test as failure, and I really wish
it flags tests wit javascript error as failure, too.
Unless the latter is enabled, we won't get rid of Javascript errors forever.