1782644 - Permanent comm/mail/test/browser/message-header/browser_messageHeader.js | waiting for vsync to be disabled - timed out after 50 tries

Status: RESOLVED FIXED

(Thunderbird :: Upstream Synchronization, defect)

Description

[Geoff Lankow (:darktrojan)]

This use of the accessibility service causes vsync to be enabled forever and the test fails at the check added by bug 1742842.

Comment 1

[Florian Quèze [:florian]]

Attachment: Add marker to see refresh observer addition stacks

This reminds me bug 1745024.

Somehow a refresh observer is added, and never removed.

I added a profiler marker to see stacks for all refresh observer additions (I'm attaching the patch that adds this marker, in case you would like to use it).

Then using ./mach test comm/mail/test/browser/message-header/browser_messageHeader.js --profiler I got this profile of the test: https://share.firefox.dev/3QcdZQW

Filtering markers for "accessibility,test" (https://share.firefox.dev/3blTxyj) I could find that there's one RefreshObserverStart marker that doesn't match the beginning of a RefreshObserver marker, so that's a RefreshObserver that isn't removed before the end of the profile.

From the Marker Table we can see the full stack: https://share.firefox.dev/3cSJ7X3
The RefreshObserver addition was triggered by an Element.setAttribute call from set headerValue chrome://messenger/content/header-fields.js:631, which points to https://searchfox.org/comm-central/rev/a35c27ab8f68ca38fa1584932e5e9f5dfecfe002/mail/base/content/widgets/header-fields.js#643-646

That's as far as I could go with a quick inspection of the test and its behavior in the profiler. I think this points to a real bug in Thunderbird that wastes power (hopefully only for users who have the accessibility service initialized).

Comment 2

[Geoff Lankow (:darktrojan)]

I'm well out of my depth, but I don't think the setAttribute call is (directly) to blame. If you take it away the problem remains. In fact some crude debugging showed several instances of mozilla::a11y::NotificationController that called AddRefreshObserver more times than RemoveRefreshObserver. (That is the real problem, right?)

I don't know anything about the a11y code so I'm stuck for where to go from here.

Comment 3

[Intermittent Failures Robot]

36 failures in 699 pushes (0.052 failures/push) were associated with this bug yesterday.

Repository breakdown:

• comm-central: 36

Platform and build breakdown:

• linux1804-64-qr: 6
  • opt: 3
  • debug: 3
• windows10-32-2004-qr: 6
  • opt: 3
  • debug: 3
• windows10-64-2004-qr: 6
  • opt: 3
  • debug: 3
• windows10-64-2004-shippable-qr: 3
  • opt: 3
• macosx1015-64-qr: 6
  • opt: 3
  • debug: 3
• linux1804-64-shippable-qr: 3
  • opt: 3
• windows10-32-2004-shippable-qr: 3
  • opt: 3
• macosx1015-64-shippable-qr: 3
  • opt: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1782644&startday=2022-08-03&endday=2022-08-03&tree=all

Comment 4

[Florian Quèze [:florian]]

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

I'm well out of my depth, but I don't think the setAttribute call is (directly) to blame.

My understanding is that this setAttribute call is where the problem starts, but is not the problem. There's likely something related to that document (or how it's loaded, or unloaded) that makes the accessibility code forget to unregister its refresh observer.

If you take it away the problem remains. In fact some crude debugging showed several instances of mozilla::a11y::NotificationController that called AddRefreshObserver more times than RemoveRefreshObserver. (That is the real problem, right?)

I think it is, yes.

I don't know anything about the a11y code so I'm stuck for where to go from here.

I think your next step will be to ask for help from people who know the accessibility code. Jamie, do you have suggestions for how Geoff could continue his investigations here, or guesses about what might be happening?

Comment 5

[James Teh [:Jamie]]

If the a11y refresh observer isn't getting removed, that suggests a11y thinks there is something pending it needs to wait for. I'd start by checking whether any of the various early returns in a11y::NotificationController::WillRefresh are being hit. That should tell you why the refresh observer isn't being removed (it gets removed at the bottom of that function). That might lead to an obvious answer... or it might not, but even if it doesn't, knowing which early return is being hit will help me figure out how to direct you next.

Comment 6

[Geoff Lankow (:darktrojan)]

That makes sense.

It's not returning early, it's falling out the bottom of the function without calling RemoveRefreshObserver, because mDocument->HasLoadState(DocAccessible::eCompletelyLoaded) is false. I'm assuming that the not-completely-loaded document isn't messenger.xhtml (mDocument) but one of the subdocuments.

Comment 7

[Geoff Lankow (:darktrojan)]

Attachment: log.log

I enabled lifecycle logging in the test (with as much removed as possible) and this is what it said. As far as I can make out, messenger.xhtml is loaded completely, then starts loading again.

Comment 8

[Intermittent Failures Robot]

80 failures in 3057 pushes (0.026 failures/push) were associated with this bug in the last 7 days.

This is the #7 most frequent failure this week.

** This failure happened more than 75 times this week! Resolving this bug is a very high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 1 week, the affected test(s) may be disabled. **

Repository breakdown:

• comm-central: 80

Platform and build breakdown:

• windows10-64-2004-qr: 12
  • opt: 6
  • debug: 6
• linux1804-64-qr: 15
  • opt: 7
  • debug: 8
• windows10-32-2004-qr: 12
  • opt: 6
  • debug: 6
• macosx1015-64-qr: 14
  • opt: 7
  • debug: 7
• linux1804-64-shippable-qr: 7
  • opt: 7
• windows10-64-2004-shippable-qr: 7
  • opt: 7
• windows10-32-2004-shippable-qr: 6
  • opt: 6
• macosx1015-64-shippable-qr: 7
  • opt: 7

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

Comment 9

[James Teh [:Jamie]]

Thanks for the log. Unfortunately, I can't see why this might be failing from this.

There are a couple of things I'd suggest trying:

1. I'm guessing this log is missing some of the "document initialize" snippets. I'd look for "document initialize" snippets with a DOM document address that don't have corresponding "document loaded *completely*" snippets with the same DOM document address. That should tell you which document never gets the complete state.
2. Add an else block at the bottom of the final if condition in a11y::NotificationController::WillRefresh. Inside that, print the URI of the document so you can see which one is never loading. This will spam you with output, but if you get an entry which repeats forever, that should tell you which document it is. Something like this:
   printf("a11y didn't remove refresh, doc %p, URI %s\n", mDocument, mDocument->DocumentNode()->GetDocumentURI()->GetSpecOrDefault().get());

Comment 10

[Intermittent Failures Robot]

24 failures in 660 pushes (0.036 failures/push) were associated with this bug yesterday.

Repository breakdown:

• comm-central: 24

Platform and build breakdown:

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

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

Comment 11

[Geoff Lankow (:darktrojan)]

Attachment: log.log

Here's a complete log of the test instead of just the a11y bits. This time I turned the logging on right at the start of the program instead of just in the test, and left in a bit of printf debugging too. What happens between 0:03.03 TEST_START and 0:03.07 INFO Entering setup bound seems weird to me.

Comment 12

[Intermittent Failures Robot]

40 failures in 751 pushes (0.053 failures/push) were associated with this bug yesterday.

** This test has failed more than 150 times in the last 21 days. It should be disabled until it can be fixed. **

Repository breakdown:

• comm-central: 40

Platform and build breakdown:

• linux1804-64-shippable-qr: 4
  • opt: 4
• windows10-32-2004-shippable-qr: 4
  • opt: 4
• windows10-64-2004-shippable-qr: 4
  • opt: 4
• macosx1015-64-shippable-qr: 4
  • opt: 4
• linux1804-64-qr: 6
  • opt: 3
  • debug: 3
• macosx1015-64-qr: 6
  • debug: 3
  • opt: 3
• windows10-64-2004-qr: 6
  • opt: 3
  • debug: 3
• windows10-32-2004-qr: 6
  • debug: 3
  • opt: 3

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

Comment 13

[James Teh [:Jamie]]

Urgh. It also looks like there's some logging missing, which I don't understand.

0:03.06 GECKO(3601475) a11y added refresh, doc 0x7f25562ab700, URI chrome://messenger/content/messenger.xhtml

But I don't see any entry in the log for 0x7f25562ab700 before that point. There should be a A11Y DOCCREATE: document initialize at the very least. And then there's this:

0:03.07 GECKO(3601475) module enabled: doclifecycle

I'm not sure why a11y logging would get reinitialized there. That, plus the destroy for messenger.xhtml above, makes me wonder whether the a11y engine is being shut down and then restarted for some reason... but I don't understand how or why that would happen, especially if it's enabled due to client detection or force enabling at startup, which means it can't be shut down.

I'm thinking it might be useful to printf the child documents that aren't ready along with their URIs so we can see which doc is holding us up. Probably the easiest place to do this (or copy) is here. You can print the URI the same way as for mDocument.

Comment 14

[Geoff Lankow (:darktrojan)]

I'm not sure why a11y logging would get reinitialized there.

I restarted it. But why did it shut down in the first place?

I'm thinking it might be useful to printf the child documents that aren't ready along with their URIs so we can see which doc is holding us up. Probably the easiest place to do this (or copy) is here. You can print the URI the same way as for mDocument.

Okay I'll have a look when I get a moment.

Comment 15

[Intermittent Failures Robot]

28 failures in 468 pushes (0.06 failures/push) were associated with this bug yesterday.

Repository breakdown:

• comm-central: 28

Platform and build breakdown:

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

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1782644&startday=2022-08-10&endday=2022-08-10&tree=all

Comment 16

[James Teh [:Jamie]]

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

I restarted it. But why did it shut down in the first place?

How are you starting the a11y engine at Firefox startup? Do you have it force enabled via pref or does it just get enabled for you?
How are you starting a11y logging: via the environment variable or via JS?
How did you restart logging?

If the only consumer of the accessibility service was XPCOM and all XPCOM references were released, that would cause the service to shut down. However, I'm not sure that could happen in your case because something seems to have started the engine at startup.

Comment 17

[Florian Quèze [:florian]]

Attachment: Bug 1782644 - release the reference to the accessibility service at the end of the test to unobserve vsync, r=darktrojan.

Comment 18

[Florian Quèze [:florian]]

(In reply to James Teh [:Jamie] from comment #16)

If the only consumer of the accessibility service was XPCOM and all XPCOM references were released, that would cause the service to shut down.

Ahah! A reference to the service is kept in a global variable set at the top level:

const gAccService = Cc["@mozilla.org/accessibilityService;1"].getService(
  Ci.nsIAccessibilityService
);

Dropping that reference at the end of the test makes the test finish cleanly. Thanks a lot for your help Jamie!

Comment 19

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/comm-central/rev/8d55155cbc33
Release the reference to the accessibility service at the end of the test to unobserve vsync. r=mkmelin

Comment 20

[James Teh [:Jamie]]

(In reply to Florian Quèze [:florian] (PTO until August 29) from comment #18)

Ahah! A reference to the service is kept in a global variable set at the top level:
Dropping that reference at the end of the test makes the test finish cleanly.

Note that this doesn't fix the real problem here; it wallpapers over it. The a11y engine shouldn't keep VSync enabled while the engine is running unless there are pending updates and there really shouldn't be pending updates forever. If you ran this test on a system where a11y is always enabled and can't be shut down (e.g. because the user was using an assistive technology), we'd probably still see the VSync problem in this test.

That said, given that this is currently only something we're concerned about in this test, it's probably not worth pursuing this further.

Comment 21

[Geoff Lankow (:darktrojan)]

(In reply to James Teh [:Jamie] from comment #16)

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

I restarted it. But why did it shut down in the first place?

How are you starting the a11y engine at Firefox startup? Do you have it force enabled via pref or does it just get enabled for you?
How are you starting a11y logging: via the environment variable or via JS?
How did you restart logging?

If the only consumer of the accessibility service was XPCOM and all XPCOM references were released, that would cause the service to shut down. However, I'm not sure that could happen in your case because something seems to have started the engine at startup.

I added code to start the logging very early in the program. All references being released would explain why it shut down, I think. I started the logging again when it got to the test code. So nothing to worry about there.

(In reply to James Teh [:Jamie] from comment #20)

Note that this doesn't fix the real problem here; it wallpapers over it. The a11y engine shouldn't keep VSync enabled while the engine is running unless there are pending updates and there really shouldn't be pending updates forever.

Correct, there's still a problem here. Probably worth another bug but for now I'll add what I've worked out:

• The document in question is the main window, messenger.xhtml.
• It loses the eDOMLoaded flag here when an email message begins loading.
• The only place (that I could find) where it could get eDOMLoaded back is DocAccessible::ProcessLoad, but we never get there because this block won't be entered without eDOMLoaded.

Comment 22

[James Teh [:Jamie]]

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

• The document in question is the main window, messenger.xhtml.
• It loses the eDOMLoaded flag here when an email message begins loading.

That's intriguing. Does the email message replace messenger.xhtml or is it loaded as a browser/iframe? Normally, a document should only get the loading state if it is reloading or if another document is about to replace it. And if another document replaces it, we should shut the old document down.

• The only place (that I could find) where it could get eDOMLoaded back is DocAccessible::ProcessLoad, but we never get there because this block won't be entered without eDOMLoaded.

If loading completes or stops, we will also set eDOMLoaded in mozilla::a11y::DocAccessible::NotifyOfLoad, triggered when we get nsIWebProgressListener::OnStateChange with STATE_STOP. It seems like this isn't happening.

Comment 23

[Geoff Lankow (:darktrojan)]

(In reply to James Teh [:Jamie] from comment #22)

That's intriguing. Does the email message replace messenger.xhtml or is it loaded as a browser/iframe?

It's in a (parent process) content browser. Everything seems to happen normally there, AFAICT from the logging.

If loading completes or stops, we will also set eDOMLoaded in mozilla::a11y::DocAccessible::NotifyOfLoad, triggered when we get nsIWebProgressListener::OnStateChange with STATE_STOP. It seems like this isn't happening.

Ah yeah, I knew about that but forgot. It happens for the inner document but not messenger.xhtml.

Comment 24

[Intermittent Failures Robot]

128 failures in 3339 pushes (0.038 failures/push) were associated with this bug in the last 7 days.

This is the #6 most frequent failure this week.

** This failure happened more than 75 times this week! Resolving this bug is a very high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 1 week, the affected test(s) may be disabled. **

Repository breakdown:

• comm-central: 128

Platform and build breakdown:

• macosx1015-64-qr: 18
  • opt: 10
  • debug: 8
• windows10-64-2004-qr: 21
  • opt: 11
  • debug: 10
• windows10-32-2004-qr: 21
  • debug: 10
  • opt: 11
• windows10-64-2004-shippable-qr: 11
  • opt: 11
• linux1804-64-qr: 21
  • debug: 11
  • opt: 10
• windows10-32-2004-shippable-qr: 12
  • opt: 12
• linux1804-64-shippable-qr: 11
  • opt: 11
• macosx1015-64-shippable-qr: 10
  • opt: 10
• linux1804-64-asan-qr: 1
  • opt: 1
• windows10-64-2004-asan-qr: 2
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1782644&startday=2022-08-08&endday=2022-08-14&tree=all