1819064 - Running `./mach wpt` on debug build stalls for multiple minutes with `Assertion failure: !HasStackCookieCheck`

Status: RESOLVED FIXED

(Firefox :: Launcher Process, defect, P3)

Description

[Kagami Rosylight [:saschanaz] (they/them)]

 0:00.02 INFO Skipping manifest download because existing file is recent
 0:09.21 mozversion INFO application_buildid: 20230227135651
 0:09.21 mozversion INFO application_display_name: Nightly
 0:09.21 mozversion INFO application_id: {ec8030f7-c20a-464f-9b0e-13a3a9e97384}
 0:09.21 mozversion INFO application_name: Firefox
 0:09.21 mozversion INFO application_remotingname: firefox-default
 0:09.21 mozversion INFO application_vendor: Mozilla
 0:09.21 mozversion INFO application_version: 112.0a1
 0:09.21 mozversion INFO platform_buildid: 20230227135651
 0:09.21 mozversion INFO platform_version: 112.0a1
 0:10.28 INFO Using 1 client processes
 0:10.80 INFO Installed font: Ahem.ttf
 0:11.38 wptserve INFO Starting http server on http://127.0.0.1:8000
 0:11.88 wptserve INFO Starting http server on http://127.0.0.1:8001
 0:12.38 wptserve INFO Starting http server on http://127.0.0.1:8002
 0:12.88 wptserve INFO Starting http server on http://127.0.0.1:8003
 0:13.38 wptserve INFO Starting https server on https://127.0.0.1:8443
 0:13.88 wptserve INFO Starting https server on https://127.0.0.1:8444
 0:14.38 wptserve INFO Starting https server on https://127.0.0.1:8445
 0:14.88 wptserve INFO Starting https server on https://127.0.0.1:8446
 0:15.38 wptserve INFO Create socket on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('127.0.0.1', 8888))
 0:15.38 wptserve INFO Bind on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('127.0.0.1', 8888))
 0:15.38 wptserve INFO Listen on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('127.0.0.1', 8888))
 0:15.88 wptserve INFO Create socket on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('127.0.0.1', 8889))
 0:15.88 wptserve INFO Bind on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('127.0.0.1', 8889))
 0:15.88 wptserve INFO Listen on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('127.0.0.1', 8889))
 0:16.38 wptserve INFO Starting http2 server on https://127.0.0.1:9000
 0:16.39 SUITE_START: web-platform-test - running 1 tests
 0:16.40 INFO Setting up ssl
 0:16.45 certutil Full command: C:/Users/sasch/Documents/GitHub/gecko-dev/obj-dbg\dist\bin\certutil.exe -N -d C:\Users\sasch\AppData\Local\Temp\tmpeguctr2n.mozrunner -f C:\Users\sasch\AppData\Local\Temp\tmpeguctr2n.mozrunner\.crtdbpw
certutil b''
 0:16.50 certutil b''
 0:16.52 certutil b'\nCertificate Nickname                                         Trust Attributes\n                                                             SSL,S/MIME,JAR/XPI\n\nweb-platform-tests                                           CT,, \r\n'     
 0:16.54 INFO Application command: C:/Users/sasch/Documents/GitHub/gecko-dev/obj-dbg\dist\bin\firefox.exe -marionette about:blank --wait-for-browser -profile C:\Users\sasch\AppData\Local\Temp\tmp8u9qbb23
 0:16.55 INFO Starting runner
 0:16.56 pid:9564 Full command: C:/Users/sasch/Documents/GitHub/gecko-dev/obj-dbg\dist\bin\firefox.exe -marionette about:blank
pid:9564 Assertion failure: !HasStackCookieCheck( reinterpret_cast<uintptr_t>(&freestanding::patched_NtMapViewOfSection)), at C:/Users/sasch/Documents/GitHub/gecko-dev/browser/app/winlauncher/DllBlocklistInit.cpp:59
 3:46.53 INFO Browser exited with return code 2147483651
 3:46.53 WARNING Firefox didn't exit cleanly, not processing leak logs
 3:56.54 WARNING Forcibly terminating runner process
 3:56.57 INFO Application command: C:/Users/sasch/Documents/GitHub/gecko-dev/obj-dbg\dist\bin\firefox.exe -marionette about:blank --wait-for-browser -profile C:\Users\sasch\AppData\Local\Temp\tmp9291add2
 3:56.58 INFO Starting runner
 3:56.58 pid:12420 Full command: C:/Users/sasch/Documents/GitHub/gecko-dev/obj-dbg\dist\bin\firefox.exe -marionette about:blank
pid:12420 DLL blocklist was unable to intercept AppInit DLLs.
 3:57.12 pid:12420 ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to C:\Users\sasch\AppData\Local\Temp\tmp9291add2\runtests_leaks_10880.log
 3:57.12 pid:12420 [12420, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file C:/Users/sasch/Documents/GitHub/gecko-dev/tools/profiler/core/platform.cpp:345
 3:57.12 pid:12420 *** You are running in headless mode.
 3:57.14 pid:12420 [12420, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file C:/Users/sasch/Documents/GitHub/gecko-dev/toolkit/xre/nsXREDirProvider.cpp:475
 3:57.23 pid:12420 [Parent 12420, Main Thread] WARNING: Rejected attempt to change type of pref extensions.formautofill.creditCards.available's user value from bool to string: file C:/Users/sasch/Documents/GitHub/gecko-dev/modules/libpref/Preferences.cpp:1895
 3:57.47 pid:12420 [Parent 12420, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file C:/Users/sasch/Documents/GitHub/gecko-dev/toolkit/xre/nsXREDirProvider.cpp:475
 3:57.47 pid:12420 [Parent 12420, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file C:/Users/sasch/Documents/GitHub/gecko-dev/toolkit/xre/nsXREDirProvider.cpp:475
 3:57.75 pid:12420 [Parent 12420, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file C:/Users/sasch/Documents/GitHub/gecko-dev/toolkit/xre/nsXREDirProvider.cpp:475
 3:57.75 pid:12420 [Parent 12420, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file C:/Users/sasch/Documents/GitHub/gecko-dev/toolkit/xre/nsXREDirProvider.cpp:475
 4:01.45 pid:12420 [WARN  rkv::backend::impl_safe::environment] `load_ratio()` is irrelevant for this storage backend.

... (irrelavent WPT log) ...

This is quite annoying for local development.

Comment 1

[BugBot [:suhaib / :marco/ :calixte]]

Set release status flags based on info from the regressing bug 1733532

:yjuglaret, since you are the author of the regressor, bug 1733532, could you take a look? Also, could you set the severity field?

For more information, please visit auto_nag documentation.

Comment 2

[Yannis Juglaret [:yannis]]

Hello. Thank you for the report!

It seems that you did not use the bootstrap script and are building instead from a github mirror? Can you describe a bit the steps you follow to compile, since they seem to differ from the recommended ones? Also, do you know what compiler is used in the end?

Then, in browser/app/winlauncher/DllBlocklistInit.cpp, you'll find the lines below:

#  if defined(DEBUG) && defined(_M_X64) && !defined(__MINGW64__)
  // This debug check preserves compatibility with third-parties (see bug
  // 1733532).
  MOZ_ASSERT(!HasStackCookieCheck(
      reinterpret_cast<uintptr_t>(&freestanding::patched_NtMapViewOfSection)));
#  endif  // #if defined(DEBUG) && defined(_M_X64) && !defined(__MINGW64__)

If you replace the first line by the following and recompile, does it remove the failure?

#  if defined(DEBUG) && defined(_M_X64) && !defined(__MINGW64__) && defined(MOZ_HAVE_NEVER_INLINE)

Thanks!

Comment 3

[Kagami Rosylight [:saschanaz] (they/them)]

(In reply to Yannis Juglaret from comment #2)

Hello. Thank you for the report!

It seems that you did not use the bootstrap script and are building instead from a github mirror?

Ah yes, I used https://github.com/glandium/git-cinnabar/wiki/Mozilla:-A-git-workflow-for-Gecko-development. But what would be different with that?

Can you describe a bit the steps you follow to compile, since they seem to differ from the recommended ones?

./mach build and that's all really.

Also, do you know what compiler is used in the end?

Clang+MSVC.

If you replace the first line by the following and recompile, does it remove the failure?

Unfortunately no. Interestingly it only fails once after build and re-running it does not show the same failure. ./mach build && ./mach run thus always fail but ./mach build && (./mach run || ./mach run) is okay.

Comment 4

[Yannis Juglaret [:yannis]]

(In reply to Kagami pto-until-March-10 [:saschanaz] from comment #3)

Ah yes, I used https://github.com/glandium/git-cinnabar/wiki/Mozilla:-A-git-workflow-for-Gecko-development. But what would be different with that?

That looks fine actually, sorry about that.

Interestingly it only fails once after build and re-running it does not show the same failure. ./mach build && ./mach run thus always fail but ./mach build && (./mach run || ./mach run) is okay.

Could you share the output upon failure and upon success if you use replace HasStackCookieCheck in mozglue/misc/WindowsStackCookie.h with this more verbose variant?

#  include <windows.h>
#  include <winnt.h>

#  include <cstdint>
#  include <cstdio> // add this include

#  include "mozilla/Types.h"

namespace mozilla {

inline bool HasStackCookieCheck(uintptr_t aFunctionAddress) {
  printf("======================================================\n");
  DWORD64 imageBase{};
  auto entry = ::RtlLookupFunctionEntry(
      reinterpret_cast<DWORD64>(aFunctionAddress), &imageBase, nullptr);
  if (entry) {
    printf("Found an entry: start=0x%lx end=0x%lx.\n", entry->BeginAddress, entry->EndAddress);
    wchar_t fileName[MAX_PATH]{};
    if (GetModuleFileNameW(reinterpret_cast<HMODULE>(imageBase), fileName, MAX_PATH)) {
      wprintf(L"Module: %s\n", fileName);
    }
    auto begin = reinterpret_cast<uint8_t*>(imageBase + entry->BeginAddress);
    auto end = reinterpret_cast<uint8_t*>(imageBase + entry->EndAddress);
    printf("Bytes:");
    for (auto pc = begin; pc != end; ++pc) {
      printf(" %02x", *pc);
    }
    printf("\n");
  }
  else {
    printf("Found no entry.\n");
  }
  if (entry && entry->EndAddress > entry->BeginAddress + 14) {
    auto begin = reinterpret_cast<uint8_t*>(imageBase + entry->BeginAddress);
    auto end = reinterpret_cast<uint8_t*>(imageBase + entry->EndAddress - 14);
    for (auto pc = begin; pc != end; ++pc) {
      // 48 8b 05 XX XX XX XX:      mov rax, qword ptr [rip + XXXXXXXX]
      if ((pc[0] == 0x48 && pc[1] == 0x8b && pc[2] == 0x05) &&
          // 48 31 e0:              xor rax, rsp
          (pc[7] == 0x48 && pc[8] == 0x31 && pc[9] == 0xe0) &&
          // 48 89 (8|4)4 24 ...:   mov qword ptr [rsp + ...], rax
          (pc[10] == 0x48 && pc[11] == 0x89 &&
           (pc[12] == 0x44 || pc[12] == 0x84) && pc[13] == 0x24)) {
        printf("Found pattern at: 0x%lx.\n", static_cast<DWORD>(reinterpret_cast<uintptr_t>(pc - imageBase)));
        printf("======================================================\n");
        return true;
      }
    }
  }
  printf("Pattern not found.\n");
  printf("======================================================\n");
  return false;
}

}

The expected output would be repeatedly showing something like below:

======================================================
Found an entry: start=0x1ef30 end=0x1efc3.
Module: C:\mozilla-source\mozilla-unified\obj-x86_64-pc-windows-msvc\dist\bin\firefox.exe
Bytes: 41 56 56 57 55 53 48 83 ec 50 4d 89 c6 48 89 d7 0f 28 84 24 a0 00 00 00 48 8b 94 24 b0 00 00 00 8b b4 24 b8 00 00 00 8b 9c 24 c0 00 00 00 8b ac 24 c8 00 00 00 48 8b 05 84 88 0a 00 89 6c 24 48 89 5c 24 40 89 74 24 38 48 89 54 24 30 0f 11 44 24 20 48 89 fa ff 15 85 10 0b 00 40 f6 c5 f0 74 26 48 83 ff ff 75 20 85 c0 78 1c 48 c7 c1 ff ff ff ff 4c 89 f2 41 89 c0 48 83 c4 50 5b 5d 5f 5e 41 5e e9 89 ee ff ff 90 48 83 c4 50 5b 5d 5f 5e 41 5e c3
Pattern not found.
======================================================

The output of TestStackCookie.exe could also be interesting if different from the one shown below:

$ ./obj-x86_64-pc-windows-msvc/dist/bin/TestStackCookie.exe
======================================================
Found no entry.
Pattern not found.
======================================================
TEST-PASS | StackCookie | Correct output from HasStackCookieCheck for function at 00007FF6B21C1000 (expected 0).
======================================================
Found an entry: start=0x1140 end=0x11f1.
Module: C:\mozilla-source\mozilla-unified\obj-x86_64-pc-windows-msvc\dist\bin\TestStackCookie.exe
Bytes: 56 48 83 ec 40 48 8b 05 bc 3e 00 00 48 31 e0 48 89 44 24 38 0f 57 c0 0f 29 44 24 20 48 85 d2 74 15 48 8d 72 ff 41 89 d0 41 83 e0 03 48 83 fe 03 73 08 31 f6 eb 3a 31 f6 eb 61 48 83 e2 fc 31 f6 48 8b 04 f1 48 01 44 c4 20 48 8b 44 f1 08 48 01 44 c4 20 48 8b 44 f1 10 48 01 44 c4 20 48 8b 44 f1 18 48 01 44 c4 20 48 83 c6 04 48 39 f2 75 d0 4d 85 c0 74 1c 48 8d 0c f1 31 d2 0f 1f 44 00 00 48 8b 34 d1 48 01 74 f4 20 48 ff c2 49 39 d0 75 ef 48 8b 74 24 28 48 03 74 24 20 48 8b 4c 24 38 48 31 e1 e8 38 05 00 00 48 89 f0 48 83 c4 40 5e c3
Found pattern at 0x1145.
======================================================
TEST-PASS | StackCookie | Correct output from HasStackCookieCheck for function at 00007FF6B21C1140 (expected 1).
======================================================
Found an entry: start=0x1200 end=0x12dc.
Module: C:\mozilla-source\mozilla-unified\obj-x86_64-pc-windows-msvc\dist\bin\TestStackCookie.exe
Bytes: 56 57 53 b8 30 40 00 00 e8 b3 04 00 00 48 29 c4 48 89 d7 48 89 ce 48 8b 05 eb 3d 00 00 48 31 e0 48 89 84 24 28 40 00 00 31 db 48 8d 4c 24 20 41 b8 00 40 00 00 31 d2 e8 14 1a 00 00 48 85 ff 74 7d 48 8d 4f ff 89 f8 83 e0 03 48 83 f9 03 73 04 31 c9 eb 3c 48 83 e7 fc 31 c9 66 0f 1f 44 00 00 48 8b 14 ce 48 01 54 d4 20 48 8b 54 ce 08 48 01 54 d4 20 48 8b 54 ce 10 48 01 54 d4 20 48 8b 54 ce 18 48 01 54 d4 20 48 83 c1 04 48 39 cf 75 d0 48 85 c0 74 1c 48 8d 0c ce 31 d2 0f 1f 44 00 00 48 8b 1c d1 48 01 5c dc 20 48 ff c2 48 39 d0 75 ef 48 8b 9c 24 18 40 00 00 48 03 5c 24 20 48 8b 8c 24 28 40 00 00 48 31 e1 e8 52 04 00 00 48 89 d8 48 81 c4 30 40 00 00 5b 5f 5e c3
Found pattern at 0x1216.
======================================================
TEST-PASS | StackCookie | Correct output from HasStackCookieCheck for function at 00007FF6B21C1200 (expected 1).
TEST-PASS | StackCookie | All tests ran successfully

Thanks!

Comment 5

[Greg Stoll :gstoll]

I'm running into this locally after syncing and doing a clobber and build. Here's the result when I launch:

Found an entry: start=0x53c00 end=0x53d87.
Module: C:\mozilla-source\mozilla-unified2\obj-x86_64-pc-windows-msvc\dist\bin\firefox.exe
Bytes: 41 56 56 57 53 48 81 ec 98 00 00 00 8b 84 24 08 01 00 00 8b 84 24 00 01 00 00 8b 84 24 f8 00 00 00 48 8b 84 24 f0 00 00 00 48 8b 84 24 e8 00 00 00 48 8b 84 24 e0 00 00 00 48 8b 05 78 f4 13 00 48 31 e0 48 89 84 24 90 00 00 00 4c 89 8c 24 88 00 00 00 4c 89 84 24 80 00 00 00 48 89 54 24 78 48 89 4c 24 70 c7 44 24 68 aa aa aa aa 48 8d 0d 94 fb 13 00 48 8d 54 24 70 4c 8d 44 24 78 4c 8d 8c 24 80 00 00 00 4c 8d b4 24 88 00 00 00 48 8d 9c 24 e0 00 00 00 48 8d bc 24 e8 00 00 00 48 8d b4 24 f0 00 00 00 4c 8d 9c 24 f8 00 00 00 4c 8d 94 24 00 01 00 00 48 8d 84 24 08 01 00 00 4c 89 74 24 20 48 89 5c 24 28 48 89 7c 24 30 48 89 74 24 38 4c 89 5c 24 40 4c 89 54 24 48 48 89 44 24 50 e8 aa 00 00 00 89 44 24 68 83 7c 24 68 00 0f 8d 0d 00 00 00 8b 44 24 68 89 44 24 6c e9 5c 00 00 00 48 c7 c0 ff ff ff ff 48 39 44 24 78 0f 84 0d 00 00 00 8b 44 24 68 89 44 24 6c e9 3d 00 00 00 8b 84 24 08 01 00 00 25 f0 00 00 00 83 f8 00 0f 85 0d 00 00 00 8b 44 24 68 89 44 24 6c e9 1b 00 00 00 44 8b 44 24 68 48 8b 94 24 80 00 00 00 48 8b 4c 24 78 e8 a6 ec ff ff 89 44 24 6c 8b 44 24 6c 89 44 24 64 48 8b 8c 24 90 00 00 00 48 31 e1 e8 6a b7 0f 00 8b 44 24 64 48 81 c4 98 00 00 00 5b 5f 5e 41 5e c3
Found pattern at: 0x53c39.

Assertion failure: !HasStackCookieCheck( reinterpret_cast<uintptr_t>(&freestanding::patched_NtMapViewOfSection)), at C:/mozilla-source/mozilla-unified2/browser/app/winlauncher/DllBlocklistInit.cpp:59

(my TestStackCookie.exe passes locally)

Comment 6

[Yannis Juglaret [:yannis]]

It looks like you are obtaining a much less-optimized variant of the code for patched_NtMapViewOfSection compared to what I get. That's probably the result of ac_add_options --disable-optimize which I don't use. In addition to being less optimized, your code also a stack cookie check while mine doesn't, so maybe detecting that the stack cookie check is useless and removing it is itself an optimization. That would explain why you get the stack cookie check (and thus the failed assertion) and I don't. I'll try to reproduce the problem using that option, if that works I'll see how I can work around it. Thanks!

Edit: Indeed I can reproduce with ac_add_options --disable-optimize! I'll see if I can wrap the assert in a #ifdef MOZ_OPTIMIZE tomorrow.

Comment 7

[Yannis Juglaret [:yannis]]

Attachment: Bug 1819064 - Add a MOZ_NO_STACK_PROTECTOR modifier attribute. r=gstoll,glandium

We define a new MOZ_HAVE_NO_STACK_PROTECTOR modifier attribute. It is
mapped to GNU __attribute__((no_stack_protector)), or MSVC
__declspec(safebuffers). It specifies that a given function should NOT
be instrumented to detect stack buffer overflows at runtime.

Comment 8

[Yannis Juglaret [:yannis]]

Attachment: Bug 1819064 - Enforce no stack cookie instrumentation in patched_NtMapViewOfSection. r=gstoll

Bug 1733532 introduced a debug-only assertion so that we have failing
gtests if we unintentionnally reintroduce stack buffers in
patched_NtMapViewOfFile. This is important to make the patch from bug
1733532 futureproof.

This helped us realize that the function currently gets a stack cookie
check in non-optimized builds. We can prevent this by enforcing the
absence of stack cookie checks in patched_NtMapViewOfFile with a new
function attribute MOZ_NO_STACK_PROTECTOR.

Depends on D171361

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/b07b38eb2e34
Add a MOZ_NO_STACK_PROTECTOR modifier attribute. r=gstoll
https://hg.mozilla.org/integration/autoland/rev/8ef59d2ed0b7
Enforce no stack cookie instrumentation in patched_NtMapViewOfSection. r=gstoll

Comment 10

[Norisz Fay [:noriszfay]]

https://hg.mozilla.org/mozilla-central/rev/b07b38eb2e34
https://hg.mozilla.org/mozilla-central/rev/8ef59d2ed0b7

Comment 11

[Yannis Juglaret [:yannis]]

Hi [:saschanaz], with [:gstoll] we believe what we have landed should fix the issue for you. Feel free to reopen the bug if not. Thanks again for reporting!