1864809 - [windows opt perma] comm/calendar/test/browser/browser_calDAV_discovery.js, browser_cardDAV_init.js | Uncaught exception in test bound testCalendarWithOnlyReadPriv - waiting for calendar list to appear - timed out after 100 tries

Status: RESOLVED FIXED

(Calendar :: General, defect, P5)

Description

[Treeherder Bug Filer]

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

---

Comment 1

[Geoff Lankow (:darktrojan)]

I don't know what bug 1836700 did that caused this, but it looks like it did. I backed it out on Try and the failures went away.

My suspicion, given the tests that are failing and when they're failing, is that nsServerSocket (as used by nsHttpServer) is breaking somehow.

These are the failing tests, on Windows only, and not every time but almost every time:

• comm/calendar/test/browser/browser_calDAV_discovery.js
• comm/mail/components/addrbook/test/browser/browser_cardDAV_init.js

Comment 2

[Andrew Sutherland [:asuth] (he/him)]

(In reply to Geoff Lankow (:darktrojan) from comment #1)

I don't know what bug 1836700 did that caused this, but it looks like it did. I backed it out on Try and the failures went away.

Interesting!

My suspicion, given the tests that are failing and when they're failing, is that nsServerSocket (as used by nsHttpServer) is breaking somehow.

nsServerSocket appears to be inherently main-thread only since it's XPCOM-based (nsIServerSocket.idl), so if it's impacted, I would expect it to be because the other end of the connection it was talking to involved a worker which is either:

• now being GCed more aggressively, breaking the connection earlier (or not performing some network activities)
• not being GCed, causing a connection to remain alive indefinitely, or resulting in more network activities happening that were not happening previously.

These are the failing tests, on Windows only, and not every time but almost every time:

• comm/calendar/test/browser/browser_calDAV_discovery.js
• comm/mail/components/addrbook/test/browser/browser_cardDAV_init.js

Running these tests with MOZ_LOG=WorkerPrivate:5 should help provide debug logging that provides clarity about what workers are running and when they are starting and stopping, etc.

In order to get the MOZ_LOG in there on fresh try runs it's possible to do things like ./mach try fuzzy --env "MOZ_LOG=WorkerPrivate:5". I believe it should theoretically also be possible to re-trigger a variation of an existing job with logging enabled as a "custom action..." as documented at https://wiki.mozilla.org/ReleaseEngineering/TryServer#Re-running_tasks_with_custom_parameters_from_Treeherder for the comm-central revisions like from comment 0.

That said, it seems like the "retrigger" action provided when I use "custom action..." on the task from comment 0 may lack the required glue to actually propagate environment variables. I tried creating some tasks using environnment and env keys but neither task seems to include my MOZ_LOG inclusion. In comparison, if I try "custom action.." on one of Eden's try tasks I get a "retrigger-custom" which both has "environment" in the schema and pre-populated in the "payload". I seem to only be offered "retrigger" on mozilla-central just like for comm-central, so I presume this is an issue of tree configuration where I either lack access rights and/or the tree is more restrictive for security reasons.

Comment 3

[Geoff Lankow (:darktrojan)]

Thanks for the input Andrew.

It's just dawned on me where the worker is and why there's something different about Windows. We roll our own DNS lookup code using ctypes and we use a worker to do it asynchronously. I still have no idea what's going wrong here though.

Comment 4

[Geoff Lankow (:darktrojan)]

Attachment: Bug 1864809 - Split DNS.jsm into DNS.sys.mjs and dnsWorker.js. r=#thunderbird-reviewers

Before fixing the actual bug, let's tidy up this confusing mess of a file which is both a module and a worker.

Comment 5

[Geoff Lankow (:darktrojan)]

Attachment: Bug 1864809 - Keep a reference to DNS workers while they are active. r=#thunderbird-reviewers

The worker is getting garbage collected before it has a chance to return with results.

Depends on D193866

Comment 6

[Andrew Sutherland [:asuth] (he/him)]

Thanks for the link! The logic that creates the worker isn't retaining a reference to the Worker, which makes the Worker potentially eligible for cycle collection, so if our changes introduced a bug (spoiler alert, yes), that would explain what is happening.

const worker = new BasePromiseWorker(LOCATION);
return worker.post("execute", [
  Services.appinfo.OS,
  "lookup",
  [...arguments],
]);

I think for the changes in bug 1836700 in dealing with all the more complicated edge cases we lost track of the more straightforward Worker.postMessage case. The MesageEventRunnable dispatch will end up being directly dispatched against the underlying nsThread in WorkerThread::DispatchAnyThread. There's also potentially a coverage gap for the other calls to nsThread::Dispatch from WorkerThread::Dispatch.

In IsEligibleForCC where we check the main-thread targets we should also be checking !mThread->HasPendingEvents(). I think we should be okay in terms of locking discipline (we need to be holding the WorkerPrivate::mMutex to access mThread anyways and this should be the only case that mutex would overlap with the ThreadEventQueue::mLock that will be acquired by the ThreadEventQueue::HasPendingEvent call made by nsThread::HasPendingEvents).

Eden, does this make sense to you as the likely problem and the appropriate fix? If so, we probably want a new bug in Workers that this can depend on. Note: I know you're out tomorrow, but because of the soft freeze I also don't think we can land a fix tomorrow or that we would want to risk a backout either, so I think this makes sense to address on Monday.

Comment 7

[Andrew Sutherland [:asuth] (he/him)]

(In reply to Geoff Lankow (:darktrojan) from comment #5)

The worker is getting garbage collected before it has a chance to return with results.

This should definitely fix the problem you're experiencing, but we (DOM: Workers) definitely introduced a bug here, so this change should not be necessary. (And since I forgot to mention it before, thank you for cc-ing us; it's very much appreciated to have found the bug quickly this way!)

That said, it could be reasonable in general to not be creating a fresh worker for every request. Like, if you had a single worker global you created and that you scheduled to tear it down at the earlier of:

1. After 60 seconds of inactivity, and reset the timer every time you give it a new request.
2. Being notified via AsyncShutdown that Thunderbird is shutting down.

That would probably be significantly less resource intensive.

Comment 8

[Magnus Melin [:mkmelin]]

I'm going to land the patches here to green up our tree. If I understood it correctly, the second patch should not be needed once the bug you discuss is fixed. We should back it out once that's done.

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/comm-central/rev/c7fc921e4031
Split DNS.jsm into DNS.sys.mjs and dnsWorker.js. r=mkmelin
https://hg.mozilla.org/comm-central/rev/feb2d7c5b41c
Keep a reference to DNS workers while they are active. r=mkmelin

Comment 10

[Eden Chuang[:edenchuang]]

I think bug 1864459 is the same issue. I will provide a patch according to Andrew's comment on bug 1864459.

Comment 11

[Geoff Lankow (:darktrojan)]

(In reply to Andrew Sutherland [:asuth] (he/him) from comment #7)

That said, it could be reasonable in general to not be creating a fresh worker for every request. Like, if you had a single worker global you created and that you scheduled to tear it down at the earlier of:

1. After 60 seconds of inactivity, and reset the timer every time you give it a new request.
2. Being notified via AsyncShutdown that Thunderbird is shutting down.

That would probably be significantly less resource intensive.

I had the same thought, although this code runs very infrequently in normal use and doesn't do a lot, so I left it for another day.

Comment 12

[Intermittent Failures Robot]

36 failures in 3495 pushes (0.01 failures/push) were associated with this bug in the last 7 days.

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

Platform and build breakdown:

• windows11-32-2009-qr: 6
  • opt: 5
  • debug: 1
• windows11-64-2009-qr: 10
  • debug: 1
  • opt: 9
• windows11-64-2009-shippable-qr: 10
  • opt: 10
• windows11-64-2009-ccov-qr: 5
  • opt: 5
• windows11-32-2009-shippable-qr: 4
  • opt: 4
• windows11-64-2009-asan-qr: 1
  • opt: 1

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