1924781 - Gnome keyring is not unlocked when running under Wayland and blocking certain features from working correctly

Status: RESOLVED FIXED

(Firefox Build System :: Task Configuration, defect, P3)

Description

[Treeherder Bug Filer]

Filed by: hskupin [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=478329808&repo=try
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/NBfsHKb2TnWtuVPB65icDw/runs/0/artifacts/public/logs/live_backing.log

---

This particular shutdown hang + crash is always happening for the given Marionette test when running with Wayland enabled:
https://treeherder.mozilla.org/jobs?repo=try&revision=d7d6eb0c94c3165b70ba573caf827779b0c8c931

Here an except from the log of an opt build:

[task 2024-10-15T13:18:14.204Z] 13:18:14 INFO - Found by: given as instruction pointer in context
[task 2024-10-15T13:18:14.204Z] 13:18:14 INFO - 2 libnspr4.so!_pt_root [ptthread.c:0fa1a6bd74cf0ff064332a50a19f3a19e463f71a : 191 + 0x6]
[task 2024-10-15T13:18:14.204Z] 13:18:14 INFO - rbx = 0x00007d881d398160 rbp = 0x00007d88300fed40
[task 2024-10-15T13:18:14.204Z] 13:18:14 INFO - rsp = 0x00007d88300fecf0 r12 = 0x00007d885e2fef68
[task 2024-10-15T13:18:14.204Z] 13:18:14 INFO - r13 = 0x0000000000000007 r14 = 0x00007d88300ff640
[task 2024-10-15T13:18:14.204Z] 13:18:14 INFO - r15 = 0x00007d885df1dc00 rip = 0x00007d885e2dcc44
[task 2024-10-15T13:18:14.204Z] 13:18:14 INFO - Found by: call frame info
[task 2024-10-15T13:18:14.204Z] 13:18:14 INFO - 3 firefox-bin!set_alt_signal_stack_and_start(PthreadCreateParams*) [pthread_create_interposer.cpp:0fa1a6bd74cf0ff064332a50a19f3a19e463f71a : 81 + 0x5]
[task 2024-10-15T13:18:14.204Z] 13:18:14 INFO - rbx = 0x00007d881d398160 rbp = 0x00007d88300fee10
[task 2024-10-15T13:18:14.204Z] 13:18:14 INFO - rsp = 0x00007d88300fed50 r12 = 0x00007d885e2dcab0
[task 2024-10-15T13:18:14.204Z] 13:18:14 INFO - r13 = 0x0000000000000000 r14 = 0x00007d884d72e000
[task 2024-10-15T13:18:14.204Z] 13:18:14 INFO - r15 = 0x00007d88300fed80 rip = 0x00005f0187da220b
[task 2024-10-15T13:18:14.204Z] 13:18:14 INFO - Found by: call frame info
[task 2024-10-15T13:18:14.204Z] 13:18:14 INFO - 4 libc.so.6!start_thread [pthread_create.c : 442 + 0x11]
[task 2024-10-15T13:18:14.204Z] 13:18:14 INFO - rbx = 0x00007d88300ff640 rbp = 0x0000000000000000
[task 2024-10-15T13:18:14.204Z] 13:18:14 INFO - rsp = 0x00007d88300fee20 r12 = 0x00007d88300ff640
[task 2024-10-15T13:18:14.204Z] 13:18:14 INFO - r13 = 0x0000000000000000 r14 = 0x00007d885e0947d0
[task 2024-10-15T13:18:14.204Z] 13:18:14 INFO - r15 = 0x00007ffdddb0a8d0 rip = 0x00007d885e094ac3
[task 2024-10-15T13:18:14.204Z] 13:18:14 INFO - Found by: call frame info
[task 2024-10-15T13:18:14.204Z] 13:18:14 INFO - 5 libc.so.6!__clone3 + 0x2f
[task 2024-10-15T13:18:14.204Z] 13:18:14 INFO - rbx = 0x00007ffdddb0a770 rbp = 0x0000000000000000
[task 2024-10-15T13:18:14.204Z] 13:18:14 INFO - rsp = 0x00007d88300feec0 r12 = 0x00007d88300ff640
[task 2024-10-15T13:18:14.204Z] 13:18:14 INFO - r13 = 0x0000000000000000 r14 = 0x00007d885e0947d0
[task 2024-10-15T13:18:14.204Z] 13:18:14 INFO - r15 = 0x00007ffdddb0a8d0 rip = 0x00007d885e126850
[task 2024-10-15T13:18:14.204Z] 13:18:14 INFO - Found by: call frame info

Comment 1

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Here some feedback from Jens Stutte from Matrix:

So we are hanging while shutting down a thread pool. But we created a blocker for a much earlier phase?
https://searchfox.org/mozilla-central/rev/754074e05178e017ef6c3d8e30428ffa8f1b794d/toolkit/components/antitracking/bouncetrackingprotection/BounceTrackingProtectionStorage.cpp#461

Comment 2

[BugBot [:suhaib / :marco]]

This bug has the keyword crash, so its type should be defect.

Comment 3

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Mike, I wonder how important this test is and if we could skip it for Wayland for now in case of it cannot be fixed in the near future.

Comment 4

[Intermittent Failures Robot]

8 failures in 4579 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 3
• mozilla-esr128: 2
• autoland: 2
• mozilla-esr115: 1

Platform and build breakdown:

• linux1804-64-shippable-qr: 2
  • opt: 2
• linux2204-64-wayland: 1
  • opt: 1
• linux1804-64-qr: 3
  • debug: 3
• windows11-64-2009-shippable-qr: 1
  • opt: 1
• linux1804-64-devedition-qr: 1
  • opt: 1

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

Comment 5

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 3
• mozilla-central: 1

Platform and build breakdown:

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

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

Comment 6

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 3
• mozilla-central: 1

Platform and build breakdown:

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

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

Comment 7

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Jens, it looks like that we have a good chance to reproduce this shutdown hang with a Marionette test under Wayland. Is there anything special that I could run to get more information, if needed? Thanks.

Comment 8

[Jens Stutte [:jstutte]]

Wayland==Linux, so if you could reproduce it under rr/pernosco, that could help to see something.

Comment 9

[Henrik Skupin [:whimboo][⌚️UTC+2]]

(In reply to Jens Stutte [:jstutte] from comment #8)

Wayland==Linux, so if you could reproduce it under rr/pernosco, that could help to see something.

This is not as easy because of the following reasons:

1. I cannot reproduce the issue locally on my own Linux machine running Wayland
2. I cannot trigger Pernosco runs via Treeherder because with Marionette it is not supported (probably because we miss support for the debugger argument?).
3. Marionette jobs don't allow the creation of an interactive task, so I cannot even manually run the tests on the remote machine.

Do you have any other idea how further information could be retrieved?

Comment 10

[Jens Stutte [:jstutte]]

Do you have a link to a typical stack trace (for all threads) of your reproduction case ? Depending on what's happening there, you could try to enable MOZ_LOG=Process:5 or other logs when running.

Comment 11

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Yes, we seem to have a stack for all the threads. Please see:
https://treeherder.mozilla.org/logviewer?job_id=478329808&repo=try&lineNumber=1104

For now I just pushed a new try job with the Process:5 value set:
https://treeherder.mozilla.org/jobs?repo=try&revision=f973ca959991b0b603053e3c57df74cbde3b86d0

Comment 12

[Jens Stutte [:jstutte]]

(In reply to Henrik Skupin [:whimboo][⌚️UTC+2] from comment #11)

Yes, we seem to have a stack for all the threads. Please see:
https://treeherder.mozilla.org/logviewer?job_id=478329808&repo=try&lineNumber=1104

I see us hanging on shutting down the Background IO thread pool. There seems to be only one thread left:

[task 2024-10-15T13:18:14.255Z] 13:18:14     INFO - Thread 33 BgIOThr~Pool #2
[task 2024-10-15T13:18:14.255Z] 13:18:14     INFO -  0  libc.so.6!__poll [poll.c : 29 + 0x1d]
[task 2024-10-15T13:18:14.255Z] 13:18:14     INFO -      rax = 0xfffffffffffffdfc    rdx = 0x00000000ffffffff
[task 2024-10-15T13:18:14.255Z] 13:18:14     INFO -      rcx = 0x00007d885e118bcf    rbx = 0x00007d885972f7a0
[task 2024-10-15T13:18:14.255Z] 13:18:14     INFO -      rsi = 0x0000000000000001    rdi = 0x00007d88446e1608
[task 2024-10-15T13:18:14.255Z] 13:18:14     INFO -      rbp = 0x00007d88446e1608    rsp = 0x00007d881d07b130
[task 2024-10-15T13:18:14.255Z] 13:18:14     INFO -       r8 = 0x0000000000000000     r9 = 0x0000000000000000
[task 2024-10-15T13:18:14.255Z] 13:18:14     INFO -      r10 = 0x00007d881f700699    r11 = 0x0000000000000293
[task 2024-10-15T13:18:14.255Z] 13:18:14     INFO -      r12 = 0x0000000000000001    r13 = 0x00007d881d07b174
[task 2024-10-15T13:18:14.255Z] 13:18:14     INFO -      r14 = 0x00000000ffffffff    r15 = 0x00007d881cedaf50
[task 2024-10-15T13:18:14.255Z] 13:18:14     INFO -      rip = 0x00007d885e118bcf
[task 2024-10-15T13:18:14.255Z] 13:18:14     INFO -     Found by: given as instruction pointer in context
[task 2024-10-15T13:18:14.255Z] 13:18:14     INFO -  1  libglib-2.0.so.0!g_main_context_poll [gmain.c : 4518]
[task 2024-10-15T13:18:14.255Z] 13:18:14     INFO -     Found by: inlining
[task 2024-10-15T13:18:14.255Z] 13:18:14     INFO -  2  libglib-2.0.so.0!g_main_context_iterate [gmain.c : 4208 + 0x25]
[task 2024-10-15T13:18:14.255Z] 13:18:14     INFO -      rbx = 0x00007d885972f7a0    rbp = 0x00007d88446e1608
[task 2024-10-15T13:18:14.255Z] 13:18:14     INFO -      rsp = 0x00007d881d07b160    r12 = 0x0000000000000001
[task 2024-10-15T13:18:14.255Z] 13:18:14     INFO -      r13 = 0x00007d881d07b174    r14 = 0x00000000ffffffff
[task 2024-10-15T13:18:14.255Z] 13:18:14     INFO -      r15 = 0x00007d881cedaf50    rip = 0x00007d885977f256
[task 2024-10-15T13:18:14.255Z] 13:18:14     INFO -     Found by: call frame info
[task 2024-10-15T13:18:14.255Z] 13:18:14     INFO -  3  libglib-2.0.so.0!g_main_loop_run [gmain.c : 4413 + 0x12]
[task 2024-10-15T13:18:14.255Z] 13:18:14     INFO -      rbx = 0x00007d881bd74478    rbp = 0x00007d881bd74470
[task 2024-10-15T13:18:14.255Z] 13:18:14     INFO -      rsp = 0x00007d881d07b1c0    r12 = 0x00007d885896eb50
[task 2024-10-15T13:18:14.255Z] 13:18:14     INFO -      r13 = 0x00007d881ced92e8    r14 = 0x00007d881ced9280
[task 2024-10-15T13:18:14.255Z] 13:18:14     INFO -      r15 = 0x0000000000000000    rip = 0x00007d88597292b3
[task 2024-10-15T13:18:14.255Z] 13:18:14     INFO -     Found by: call frame info
[task 2024-10-15T13:18:14.255Z] 13:18:14     INFO -  4  libsecret-1.so.0 + 0x2f737
[task 2024-10-15T13:18:14.255Z] 13:18:14     INFO -      rbx = 0x00007d881d07b3ec    rbp = 0x00007d881ced37c0
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO -      rsp = 0x00007d881d07b1e0    r12 = 0x00007d885896eb50
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO -      r13 = 0x00007d881ced92e8    r14 = 0x00007d881ced9280
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO -      r15 = 0x0000000000000000    rip = 0x00007d881be4b738
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO -     Found by: call frame info
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO -  5  libsecret-1.so.0 + 0x35e8f
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO -      rsp = 0x00007d881d07b1e8    rip = 0x00007d881be51e90
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO -     Found by: stack scanning
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO -  6  libxul.so!<.plt ELF section in libxul.so> + 0x3bbe5f
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO -      rsp = 0x00007d881d07b1f8    rip = 0x00007d885896eb60
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO -     Found by: stack scanning
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO -  7  libxul.so!<.plt ELF section in libxul.so> + 0x3bbe4f
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO -      rsp = 0x00007d881d07b218    rip = 0x00007d885896eb50
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO -     Found by: stack scanning
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO -  8  libsecret-1.so.0 + 0x2f98f
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO -      rsp = 0x00007d881d07b240    rip = 0x00007d881be4b990
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO -     Found by: stack scanning
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO -  9  libsecret-1.so.0 + 0x2f963
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO -      rsp = 0x00007d881d07b250    rip = 0x00007d881be4b964
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO -     Found by: stack scanning
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO - 10  firefox-bin!arena_t::Malloc(unsigned long, bool)
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO -     Found by: inlining
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO - 11  firefox-bin!BaseAllocator::malloc(unsigned long) [mozjemalloc.cpp:0fa1a6bd74cf0ff064332a50a19f3a19e463f71a : 4733]
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO -     Found by: inlining
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO - 12  firefox-bin!MozJemalloc::malloc(unsigned long) [malloc_decls.h:0fa1a6bd74cf0ff064332a50a19f3a19e463f71a : 51]
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO -     Found by: inlining
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO - 13  firefox-bin!PageMalloc(mozilla::Maybe<unsigned long> const&, unsigned long) [PHC.cpp:0fa1a6bd74cf0ff064332a50a19f3a19e463f71a : 1560]
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO -     Found by: inlining
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO - 14  firefox-bin!MozJemallocPHC::malloc(unsigned long) [PHC.cpp:0fa1a6bd74cf0ff064332a50a19f3a19e463f71a : 1564]
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO -     Found by: inlining
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO - 15  firefox-bin!ReplaceMalloc::malloc(unsigned long) [malloc_decls.h:0fa1a6bd74cf0ff064332a50a19f3a19e463f71a : 51]
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO -     Found by: inlining
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO - 16  firefox-bin!malloc [malloc_decls.h:0fa1a6bd74cf0ff064332a50a19f3a19e463f71a : 51 + 0x205]
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO -      rsp = 0x00007d881d07b290    rip = 0x00005f0187d59bca
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO -     Found by: stack scanning
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO - 17  firefox-bin!Mutex::Unlock() [Mutex.h:0fa1a6bd74cf0ff064332a50a19f3a19e463f71a : 106]
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO -     Found by: inlining
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO - 18  firefox-bin!MaybeMutex::Unlock() [Mutex.h:0fa1a6bd74cf0ff064332a50a19f3a19e463f71a : 210]
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO -     Found by: inlining
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO - 19  firefox-bin!AutoLock<MaybeMutex>::~AutoLock() [Mutex.h:0fa1a6bd74cf0ff064332a50a19f3a19e463f71a : 254]
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO -     Found by: inlining
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO - 20  firefox-bin!arena_dalloc(void*, unsigned long, arena_t*) [mozjemalloc.cpp:0fa1a6bd74cf0ff064332a50a19f3a19e463f71a : 3997]
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO -     Found by: inlining
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO - 21  firefox-bin!BaseAllocator::free(void*) [mozjemalloc.cpp:0fa1a6bd74cf0ff064332a50a19f3a19e463f71a : 4821]
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO -     Found by: inlining
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO - 22  firefox-bin!MozJemalloc::free(void*) [malloc_decls.h:0fa1a6bd74cf0ff064332a50a19f3a19e463f71a : 54]
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO -     Found by: inlining
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO - 23  firefox-bin!PageFree(mozilla::Maybe<unsigned long> const&, void*) [PHC.cpp:0fa1a6bd74cf0ff064332a50a19f3a19e463f71a : 1794]
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO -     Found by: inlining
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO - 24  firefox-bin!MozJemallocPHC::free(void*) [PHC.cpp:0fa1a6bd74cf0ff064332a50a19f3a19e463f71a : 1797]
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO -     Found by: inlining
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO - 25  firefox-bin!ReplaceMalloc::free(void*) [malloc_decls.h:0fa1a6bd74cf0ff064332a50a19f3a19e463f71a : 54]
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO -     Found by: inlining
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO - 26  firefox-bin!free [malloc_decls.h:0fa1a6bd74cf0ff064332a50a19f3a19e463f71a : 54 + 0x22c7]
[task 2024-10-15T13:18:14.256Z] 13:18:14     INFO -      rsp = 0x00007d881d07b2a0    rip = 0x00005f0187d88529
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO -     Found by: stack scanning
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO - 27  firefox-bin!Mutex::Unlock() [Mutex.h:0fa1a6bd74cf0ff064332a50a19f3a19e463f71a : 106]
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO -     Found by: inlining
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO - 28  firefox-bin!MaybeMutex::Unlock() [Mutex.h:0fa1a6bd74cf0ff064332a50a19f3a19e463f71a : 210]
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO -     Found by: inlining
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO - 29  firefox-bin!AutoLock<MaybeMutex>::~AutoLock() [Mutex.h:0fa1a6bd74cf0ff064332a50a19f3a19e463f71a : 254]
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO -     Found by: inlining
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO - 30  firefox-bin!arena_dalloc(void*, unsigned long, arena_t*) [mozjemalloc.cpp:0fa1a6bd74cf0ff064332a50a19f3a19e463f71a : 3997]
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO -     Found by: inlining
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO - 31  firefox-bin!BaseAllocator::free(void*) [mozjemalloc.cpp:0fa1a6bd74cf0ff064332a50a19f3a19e463f71a : 4821]
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO -     Found by: inlining
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO - 32  firefox-bin!MozJemalloc::free(void*) [malloc_decls.h:0fa1a6bd74cf0ff064332a50a19f3a19e463f71a : 54]
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO -     Found by: inlining
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO - 33  firefox-bin!PageFree(mozilla::Maybe<unsigned long> const&, void*) [PHC.cpp:0fa1a6bd74cf0ff064332a50a19f3a19e463f71a : 1794]
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO -     Found by: inlining
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO - 34  firefox-bin!MozJemallocPHC::free(void*) [PHC.cpp:0fa1a6bd74cf0ff064332a50a19f3a19e463f71a : 1797]
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO -     Found by: inlining
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO - 35  firefox-bin!ReplaceMalloc::free(void*) [malloc_decls.h:0fa1a6bd74cf0ff064332a50a19f3a19e463f71a : 54]
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO -     Found by: inlining
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO - 36  firefox-bin!free [malloc_decls.h:0fa1a6bd74cf0ff064332a50a19f3a19e463f71a : 54 + 0x22c7]
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO -      rsp = 0x00007d881d07b2b0    rip = 0x00005f0187d88529
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO -     Found by: stack scanning
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO - 37  firefox-bin!Mutex::Unlock() [Mutex.h:0fa1a6bd74cf0ff064332a50a19f3a19e463f71a : 106]
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO -     Found by: inlining
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO - 38  firefox-bin!MaybeMutex::Unlock() [Mutex.h:0fa1a6bd74cf0ff064332a50a19f3a19e463f71a : 210]
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO -     Found by: inlining
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO - 39  firefox-bin!AutoLock<MaybeMutex>::~AutoLock() [Mutex.h:0fa1a6bd74cf0ff064332a50a19f3a19e463f71a : 254]
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO -     Found by: inlining
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO - 40  firefox-bin!arena_dalloc(void*, unsigned long, arena_t*) [mozjemalloc.cpp:0fa1a6bd74cf0ff064332a50a19f3a19e463f71a : 3997]
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO -     Found by: inlining
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO - 41  firefox-bin!BaseAllocator::free(void*) [mozjemalloc.cpp:0fa1a6bd74cf0ff064332a50a19f3a19e463f71a : 4821]
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO -     Found by: inlining
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO - 42  firefox-bin!MozJemalloc::free(void*) [malloc_decls.h:0fa1a6bd74cf0ff064332a50a19f3a19e463f71a : 54]
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO -     Found by: inlining
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO - 43  firefox-bin!PageFree(mozilla::Maybe<unsigned long> const&, void*) [PHC.cpp:0fa1a6bd74cf0ff064332a50a19f3a19e463f71a : 1794]
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO -     Found by: inlining
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO - 44  firefox-bin!MozJemallocPHC::free(void*) [PHC.cpp:0fa1a6bd74cf0ff064332a50a19f3a19e463f71a : 1797]
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO -     Found by: inlining
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO - 45  firefox-bin!ReplaceMalloc::free(void*) [malloc_decls.h:0fa1a6bd74cf0ff064332a50a19f3a19e463f71a : 54]
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO -     Found by: inlining
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO - 46  firefox-bin!free [malloc_decls.h:0fa1a6bd74cf0ff064332a50a19f3a19e463f71a : 54 + 0x22c7]
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO -      rsp = 0x00007d881d07b2e0    rip = 0x00005f0187d88529
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO -     Found by: stack scanning
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO - 47  libglib-2.0.so.0!g_hash_table_remove_internal [ghash.c : 1772]
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO -     Found by: inlining
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO - 48  libglib-2.0.so.0!g_hash_table_remove [ghash.c : 1800 + 0x104]
[task 2024-10-15T13:18:14.257Z] 13:18:14     INFO -      rsp = 0x00007d881d07b2f0    rip = 0x00007d8859714957
[task 2024-10-15T13:18:14.258Z] 13:18:14     INFO -     Found by: stack scanning

which seems to indicate some quite deep stack passing frequently through our custom mozjemalloc allocator. Not sure what that tells us. Can you verify if that this is a recurrent pattern on BgIOThr~Pool when this happens?

Comment 13

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Yes, all the failing tests from my original try build seem to fail there (I only checked for FinishShutdown and thread 0 was referenced):
https://treeherder.mozilla.org/jobs?repo=try&revision=d7d6eb0c94c3165b70ba573caf827779b0c8c931

Comment 14

[Jens Stutte [:jstutte]]

Maybe someone with more gtk experience makes more sense out of this stack? We see the pattern to end up inside g_main_loop_run in several instances, I do not know if it is expected to see that appearing randomly on various stacks.

Comment 15

[Karl Tomlinson (:karlt)]

(In reply to Henrik Skupin [:whimboo][⌚️UTC+2] from comment #1)

Here some feedback from Jens Stutte from Matrix:

So we are hanging while shutting down a thread pool. But we created a blocker for a much earlier phase?
https://searchfox.org/mozilla-central/rev/754074e05178e017ef6c3d8e30428ffa8f1b794d/toolkit/components/antitracking/bouncetrackingprotection/BounceTrackingProtectionStorage.cpp#461

Are you seeing BounceTrackingProtectionStorage somewhere in the log?

Comment 16

[Karl Tomlinson (:karlt)]

Having libsecret doing something on Gecko's BackgroundEventTarget might be unexpected.

I don't know whether to believe the frames in mozjemalloc because they are found by stack scanning - they may just be remnants of previous calls that have completed.

libsecret-1.so.0 + 0x2f737

If we can get the debuginfo package for libsecret installed, then that should tell us more.

libglib-2.0.so.0!g_main_loop_run [gmain.c : 4413 + 0x12]

We have a debuginfo package for libglib installed. We want something similar for libsecret.

libsecret is running a nested event loop, presumably waiting for something to happen. debuginfo would give us some idea of what it is waiting for.

Moving to Security: PSM based on libsecret use.

Logging with libsecret:5 might tell us something.

Comment 17

[BugBot [:suhaib / :marco]]

The product::component has been changed since the backlog priority was decided, so we're resetting it.
For more information, please visit BugBot documentation.

Comment 18

[Jens Stutte [:jstutte]]

(In reply to Karl Tomlinson (:karlt) from comment #15)

(In reply to Henrik Skupin [:whimboo][⌚️UTC+2] from comment #1)

Here some feedback from Jens Stutte from Matrix:

So we are hanging while shutting down a thread pool. But we created a blocker for a much earlier phase?
https://searchfox.org/mozilla-central/rev/754074e05178e017ef6c3d8e30428ffa8f1b794d/toolkit/components/antitracking/bouncetrackingprotection/BounceTrackingProtectionStorage.cpp#461

Are you seeing BounceTrackingProtectionStorage somewhere in the log?

I am not sure which trace I was looking at back then. In the traces I looked at recently as well as the original trace from comment 0 I only see the g_main_loop_run on the backround IO thread pool as common pattern.

Comment 19

[Henrik Skupin [:whimboo][⌚️UTC+2]]

I pushed as well another job with temporarily modified Taskcluster settings to allow ASAN jobs to run with Wayland:
https://treeherder.mozilla.org/jobs?repo=try&revision=45cc09240b02b047568879e1e79560349ba09a8e

These jobs didn't cause an issue so maybe something is wrong with the stack walker? I can surely test the suggestion from Karl later today as well.

Comment 20

[Henrik Skupin [:whimboo][⌚️UTC+2]]

I pushed a new try build with the libsecret:5 logging enabled:
https://treeherder.mozilla.org/jobs?repo=try&revision=4e69f4b7fe141710048d5030334bd294f7a10c63

Comment 21

[Jens Stutte [:jstutte]]

(In reply to Henrik Skupin [:whimboo][⌚️UTC+2] from comment #20)

I pushed a new try build with the libsecret:5 logging enabled:
https://treeherder.mozilla.org/jobs?repo=try&revision=4e69f4b7fe141710048d5030334bd294f7a10c63

I do not see the shutdown hang there. The crash I see is MOZ_CRASH("Crash via about:crashparent"); which seems to be wanted by one of the run tests: https://treeherder.mozilla.org/logviewer?job_id=481164791&repo=try&lineNumber=14767

Comment 22

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Sorry, I was running the wrong tests. With the last try build (comment 13) we still had the Mn jobs which are now renamed to just numbers like in Mochitests. So I've triggered the 1 job for Marionette. Then we should most likely see the issue.

Comment 23

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Ok, so there is only a single log line for libsecret for the whole job. This is the following just a couple of seconds before the crash:

[Parent 3114: BgIOThreadPool #2]: D/libsecret Error retrieving secret or didn't find it

Given that it comes from the BgIOThreadPool thread it might be related? If this information is not helpful we somehow may have to try to get the libsecret package installed as well.

Comment 24

[Karl Tomlinson (:karlt)]

Perhaps Dana is more familiar with how libsecret gets shut down.

Comment 25

[Dana Keeler (she/her) [:keeler]]

Just before the libsecret error line, there's this:

[task 2024-11-05T12:53:52.885Z] 12:53:52     INFO -  1730811232885	Marionette	DEBUG	1 -> [0,16,"WebDriver:ExecuteAsyncScript",{"script":"const { formAutofillStorage } = ChromeUtils.importESModule(\n            \"resource://autofill/FormAutofillStorage.sys.mjs\"\n    ... 4444\",\n              \"cc-exp-month\": 5,\n              \"cc-exp-year\": 2099,\n            });\n          })().then(outerResolve);","args":[],"newSandbox":true,"sandbox":"default","scriptTimeout":null,"line":775,"filename":"tests/browser/components/backup/tests/marionette/test_backup.py"}]

The libsecret error results in an exception in the JS code calling it - perhaps the code that's being run doesn't gracefully handle that exception, which causes the timeout, which causes everything to go off the rails?

Comment 26

[Karl Tomlinson (:karlt)]

Is there a pref or similar to disable libsecret or OSKeyStore to unblock bug 1852986 while this is being investigated?

Comment 27

[Dana Keeler (she/her) [:keeler]]

Doesn't seem like it. I would start by narrowing down what in https://searchfox.org/mozilla-central/rev/5b288ed276a9580f2bedd4f67543940667d6a8c0/browser/components/backup/tests/marionette/test_backup.py#774-792 is hanging.

Comment 28

[Henrik Skupin [:whimboo][⌚️UTC+2]]

(In reply to Dana Keeler (she/her) (use needinfo) [:keeler] from comment #27)

Doesn't seem like it. I would start by narrowing down what in https://searchfox.org/mozilla-central/rev/5b288ed276a9580f2bedd4f67543940667d6a8c0/browser/components/backup/tests/marionette/test_backup.py#774-792 is hanging.

There is no hang when calling WebDriver:ExecuteScript. It's just timing out after 30s because the exception is not correctly handled. There is specifically bug 1924784 for that issue.

But here for this crash we have a different test (browser/components/migration/tests/marionette/test_refresh_firefox.py TestFirefoxRefresh.testFxANoSync) which is not related. But it could indeed be that the state as set in backup.py is causing the hang during shutdown. What I could try is to run the tests and temporarily skipping the backup test. If that fixes the issue we could indeed focus on the libsecret usage as triggered by the backup test.

Here a try build:
https://treeherder.mozilla.org/jobs?repo=try&revision=34e187d99c80b3f269d26e37b4a23a995fc629c0

Comment 29

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Ok, so this is indeed a side-effect from backup.py that is run right before this test. Let me add an in_app restart request to the backup test so that we can actually create a minimized testcase for Marionette. Maybe it's enough to just have these data filled in. I'll report back when I have more information.

Comment 30

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Attachment: Marionette Test

This is the minimized Marionette test to still being able to trigger the hang and crash during shutdown. Here a log from such a Marionette job:

https://treeherder.mozilla.org/logviewer?job_id=481631025&repo=try&lineNumber=830-895

It's really interesting that the script evaluation is timing out. While there doesn't seem to be thrown any error the call to await formAutofillStorage.creditCards.add() doesn't seem to complete. Maybe this triggers some deadlock in libsecret which then hangs during shutdown?

(In reply to Karl Tomlinson (:karlt) from comment #16)

If we can get the debuginfo package for libsecret installed, then that should tell us more.

libglib-2.0.so.0!g_main_loop_run [gmain.c : 4413 + 0x12]

We have a debuginfo package for libglib installed. We want something similar for libsecret.

I could still try to get the debug version of libsecret installed in a worker so that we get a proper stack. Should we maybe have it installed by default? Joel, what do you think? If yes, where would I have to add it for the t-linux-2204-wayland docker image? I cannot find it under /taskcluster.

Comment 31

[Joel Maher ( :jmaher ) (UTC -8)]

wayland is a VM not a docker image, so this is hand created by relops. We are planning to upgrade to 24.04 but not work has started on this yet.

:aerickson, what is the process for getting a new library in the wayland worker?

Comment 32

[Andrew Erickson [:aerickson]]

We have 24.04 images and pools, but yeah, we haven't moved many tests to 24.04 yet.

I wasn't familiar with the Redhat debuginfo packages (https://docs.fedoraproject.org/en-US/packaging-guidelines/Debuginfo/). It seems like Ubuntu 22+ should be able to fetch debug symbols without installing -dbg packages per https://ubuntu.com/server/docs/debug-symbol-packages.

Let me know if that doesn't work and we can manually install packages everywhere (Ubuntu 22/24 (18 if you'd like hardware also) package names).

Comment 33

[Henrik Skupin [:whimboo][⌚️UTC+2]]

I pushed another try build with further logging in the various autofill and as well OSKeyStore modules. And that clearly shows that we see a hang when lazy.nativeOSKeyStore.asyncGenerateSecret() is called:

https://treeherder.mozilla.org/logviewer?job_id=481677259&repo=try&lineNumber=872

That corresponds to the following code in OSKeyStore.cpp which is causing the hang:

  RefPtr<OSKeyStore> self = this;
  nsCOMPtr<nsIRunnable> runnable(NS_NewRunnableFunction(
      "BackgroundGenerateSecret",
      [self, promiseHandle, aLabel = nsAutoCString(aLabel)]() mutable {
        BackgroundGenerateSecret(aLabel, promiseHandle, self);
      }));

  promiseHandle.forget(promiseOut);
  return NS_DispatchBackgroundTask(runnable.forget(),
                                   NS_DISPATCH_EVENT_MAY_BLOCK);

Dana, is that information enough or do we still need the symbols from the libsecure library? If it's the latter we would have to check the suggestion from Eric above. But nevertheless I think that we should not hang but fail when we cannot generate a secret.

Comment 34

[Dana Keeler (she/her) [:keeler]]

It's not hanging - it's raising an exception that isn't being caught (this is what I was trying to explain in comment 25). Try this:

dump(`\n** before key store encrypt\n**`);
try {
  creditCard["cc-number-encrypted"] = await lazy.OSKeyStore.encrypt(
    ccNumber
  );
} catch (e) {
  dump(`caught exception thrown by oskeystore: ${e}`);
}
dump(`\n** after key store encrypt\n**`);

Unfortunately the documentation in https://searchfox.org/mozilla-central/source/security/manager/ssl/nsIOSKeyStore.idl doesn't indicate this is a possibility, so that would certainly be an improvement going forward.

Comment 35

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Sorry when I wasn't clear enough. It's not raising an exception, but hanging because the Promise that is returned never resolves or gets rejected. You can see it here where I've added the try/catch to explicitly dump a message:

https://treeherder.mozilla.org/logviewer?job_id=481738157&repo=try&lineNumber=861-862

Note that when I add a throw new Error("foo") line right before the call to lazy.OSKeyStore.encrypt() it gets normally handled, the dump line is present, and the script evaluation isn't timing out.

Comment 36

[Dana Keeler (she/her) [:keeler]]

Ah - thanks for clearing that up. I was definitely misunderstanding. So I suppose secret_password_store_sync is hanging. Presumably there's some service that isn't set up and responding to that message? Is gnome-keyring installed in the test environment? In any case, while this maybe won't help the test pass, I imagine we should make that call fail after a timeout for environments that have libsecret but aren't set up to actually provide a secret service.

Comment 37

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 1

Platform and build breakdown:

• linux2204-64-wayland: 1
  • debug: 1

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

Comment 38

[Henrik Skupin [:whimboo][⌚️UTC+2]]

(In reply to Dana Keeler (she/her) (use needinfo) [:keeler] from comment #36)

Ah - thanks for clearing that up. I was definitely misunderstanding. So I suppose secret_password_store_sync is hanging. Presumably there's some service that isn't set up and responding to that message? Is gnome-keyring installed in the test environment?

Martin should be able to help with this question I suppose.

Comment 39

[Henrik Skupin [:whimboo][⌚️UTC+2]]

I was informed by jcristau that on the Linux 18.04 workers we unlock the keyring:
https://searchfox.org/mozilla-central/rev/f732a1651018b7c32002981a9c8b8613975ffbf9/taskcluster/scripts/tester/test-linux.sh#208

Andrew, is that something we do on the newer 22.04 Wayland workers as well or not? If not it could explain the problem.

Comment 40

[Andrew Erickson [:aerickson]]

We don't do unlocking in 18.04 Moonshot hardware in the DC. In the 18.04 Docker image?

test-linux.sh isn't part of any image. I thought it was run by most linux test jobs.

We don't do any unlocking in the GCP VM images for 22.04 (bare VM or virtualbox) or 24.04.

:jcristau, what do you think we should do?

Comment 41

[Julien Cristau [:jcristau]]

We should probably move the keyring unlock to somewhere that's shared by both the x11 and wayland tests.

Comment 42

[Henrik Skupin [:whimboo][⌚️UTC+2]]

(In reply to Julien Cristau [:jcristau] from comment #41)

We should probably move the keyring unlock to somewhere that's shared by both the x11 and wayland tests.

Andrew and Julien, who would actually be responsible for doing that? I assume we should file a new bug for it?

(In reply to Dana Keeler (she/her) (use needinfo) [:keeler] from comment #36)

Ah - thanks for clearing that up. I was definitely misunderstanding. So I suppose secret_password_store_sync is hanging. Presumably there's some service that isn't set up and responding to that message? Is gnome-keyring installed in the test environment? In any case, while this maybe won't help the test pass, I imagine we should make that call fail after a timeout for environments that have libsecret but aren't set up to actually provide a secret service.

Dana, does it still mean we need a fix for that situation, or are real users not really affected?

Comment 43

[Andrew Erickson [:aerickson]]

(In reply to Henrik Skupin [:whimboo][⌚️UTC+2] from comment #42)

(In reply to Julien Cristau [:jcristau] from comment #41)

We should probably move the keyring unlock to somewhere that's shared by both the x11 and wayland tests.

Andrew and Julien, who would actually be responsible for doing that? I assume we should file a new bug for it?

:jcristau touched test-linux.sh last, but it's in-tree and not sure if it has an official owner.

Comment 44

[Julien Cristau [:jcristau]]

What Andrew said.

Comment 45

[Dana Keeler (she/her) [:keeler]]

(In reply to Henrik Skupin [:whimboo][⌚️UTC+2] from comment #42)

Dana, does it still mean we need a fix for that situation, or are real users not really affected?

My understanding is real users shouldn't be affected by this. They'll see the prompt to unlock their keychain and they'll either do so or cancel it, whereupon the promise will be resolved or rejected.

Comment 46

[Dana Keeler (she/her) [:keeler]]

My understanding is this will require a change in how we run the tests, so this shouldn't be in PSM.

Comment 47

[Henrik Skupin [:whimboo][⌚️UTC+2]]

When I'm again working on the Wayland support for Marionette I'll disable this test for now so it doesn't block us moving the whole test suite over to the new workers.

Comment 48

[Henrik Skupin [:whimboo][⌚️UTC+2]]

To check if this is still a problem I pushed a new try build:
https://treeherder.mozilla.org/jobs?repo=try&revision=6414f04d67dc0cc8fa267bc422bf94e8534c2c6b

Comment 49

[Henrik Skupin [:whimboo][⌚️UTC+2]]

This is no longer a problem!

Comment 50

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Actually the crash is gone because of my fix on bug 1930116 but the problem is still there that the Gnome keyring is not getting unlocked.

I'm updating the bugs summary to clarify what we are waiting for. Related tests will have to be disabled for Wayland for the moment.

Comment 52

[Julien Cristau [:jcristau]]

Attachment: Bug 1924781 - unlock gnome-keyring for wayland tests. r?jmaher,ahal

This replicates what we're doing in the docker+X11 case in
taskcluster/scripts/tester/test-linux.sh, to let the linux tests running
on wayland access the user's login keyring. Without this, credit card
autofill tests time out when moved from the t-linux-wayland-vm pool to
t-linux-wayland.

Comment 53

[Pulsebot]

Pushed by [e-mail]:
https://github.com/mozilla-firefox/firefox/commit/7228b4bc9839
https://hg.mozilla.org/integration/autoland/rev/05f29ee35ff9
unlock gnome-keyring for wayland tests. r=jmaher,taskgraph-reviewers

Comment 54

[Iulian Moraru]

https://hg.mozilla.org/mozilla-central/rev/05f29ee35ff9