1770791 - Importing glean python package breaks subprocess functionality on windows

Status: RESOLVED FIXED

(Data Platform and Tools :: Glean: SDK, defect)

Description

[Tooru Fujisawa [:arai]]

Steps to reproduce:

1. Setup Firefox development environment on windows, following https://firefox-source-docs.mozilla.org/setup/windows_build.html
2. Answer yes for Will you be submitting commits to Mozilla? question in bootstrap.py

Actual result:

At the end of bootstrap.py moz-phab setup fails

ServerError: server exited with status 3221225794: b''
Run moz-phab again with '--trace' to show debugging output

Expected result:

moz-phab setup works

Investigation:

the output from moz-phab install-certificate --trace:

DEBUG    2022-05-24 01:07:22,911 MozPhab (1.0.0)
DEBUG    2022-05-24 01:07:22,912 found hg repo in C:\mozilla-source\mozilla-unified
ERROR    2022-05-24 01:07:22,919 Traceback (most recent call last):
  File "C:\mozilla-build\python3\lib\site-packages\mozphab\mozphab.py", line 71, in main
    repo = repo_from_args(args)
  File "C:\mozilla-build\python3\lib\site-packages\mozphab\detect_repository.py", line 51, in repo_from_args
    repo = probe_repo(path)
  File "C:\mozilla-build\python3\lib\site-packages\mozphab\detect_repository.py", line 24, in probe_repo
    return Mercurial(path)
  File "C:\mozilla-build\python3\lib\site-packages\mozphab\mercurial.py", line 72, in __init__
    major, minor, micro, *_ = self.repository.version
  File "C:\mozilla-build\python3\lib\site-packages\mozphab\mercurial.py", line 101, in repository
    self._repo = hglib.open(self._repo_path, encoding="UTF-8", configs=configs)
  File "C:\mozilla-build\python3\lib\site-packages\hglib\__init__.py", line 11, in open
    return client.hgclient(path, encoding, configs)
  File "C:\mozilla-build\python3\lib\site-packages\hglib\client.py", line 75, in __init__
    self.open()
  File "C:\mozilla-build\python3\lib\site-packages\hglib\client.py", line 274, in open
    self._readhello()
  File "C:\mozilla-build\python3\lib\site-packages\hglib\client.py", line 126, in _readhello
    ch, msg = self._readchannel()
  File "C:\mozilla-build\python3\lib\site-packages\hglib\client.py", line 152, in _readchannel
    raise error.ServerError('server exited with status %d: %s'
hglib.error.ServerError: server exited with status 3221225794: b''

Then, the error happens on moz-phab 1.0.0, but not on moz-phab trunk.
and the following patch fixes:

https://github.com/mozilla-conduit/review/commit/2271d81f9e8df83f4045ffe62df37b9cb9269f28

The patch defers the glean package import.

I've tested putting the following codelet into the glean packages:

import subprocess
import sys
print("@@@@", subprocess.check_output(["hg", "--version"]));
sys.exit(0)

and the above code stops working after the following line:
https://github.com/mozilla/glean/blob/b4b54f61c07303323366b51937dc34f34385d44f/glean-core/python/glean/glean.py#L36

So, apparently the glean's ffi setup affects how subprocess works.

Comment 1

[Tooru Fujisawa [:arai]]

forgot to mention versions:

• Windows 11 Pro 21H2 22000.675
• MozillaBuild 4.0.1
• MozPhab 1.0.0
• mozilla-unified revision 4e5c523ed774

Comment 2

[Tooru Fujisawa [:arai]]

Attachment: procmon log for `hg --version` before `_ffi.setup_logging()`

Comment 3

[Tooru Fujisawa [:arai]]

Attachment: procmon log for `hg --version` after `_ffi.setup_logging()`

Comment 4

[Tooru Fujisawa [:arai]]

Attached procmon log for subprocess.check_output(["hg", "--version"]) before/after _ffi.setup_logging().

In the "after" case, hg.exe suddenly exits with Exit Status: -1073741502 ( = 3221225794 = 0xC0000142 = STATUS_DLL_INIT_FAILED), and
I don't see any notable difference before that point between before/after cases.

Then, there's MsMpEng.exe activity both for before/after cases, that looks interacting with hg.exe loading,
and the activity is also there immediately before the process exit.

"2:33:21.8285514","hg.exe","14196","Load Image","C:\Windows\System32\KernelBase.dll","SUCCESS","Image Base: 0x7ffbc01e0000, Image Size: 0x379000"
"2:33:21.8285641","MsMpEng.exe","5948","CreateFile","C:\Windows\System32\kernel32.dll","SUCCESS","Desired Access: Read Attributes, Synchronize, Disposition: Open, Options: Non-Directory File, Open For Backup, Open Reparse Point, Open Requiring Oplock, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"2:33:21.8286052","MsMpEng.exe","5948","FileSystemControl","C:\Windows\System32\kernel32.dll","OPLOCK HANDLE CLOSED","Control: FSCTL_REQUEST_OPLOCK"
"2:33:21.8286157","MsMpEng.exe","5948","FileSystemControl","C:\Windows\System32\kernel32.dll","SUCCESS","Control: 0x902eb (Device:0x9 Function:186 Method: 3)"
"2:33:21.8286261","MsMpEng.exe","5948","CloseFile","C:\Windows\System32\kernel32.dll","SUCCESS",""
"2:33:21.8288057","MsMpEng.exe","5948","CreateFile","C:\Windows\System32\KernelBase.dll","SUCCESS","Desired Access: Read Attributes, Synchronize, Disposition: Open, Options: Non-Directory File, Open For Backup, Open Reparse Point, Open Requiring Oplock, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"2:33:21.8288274","MsMpEng.exe","5948","FileSystemControl","C:\Windows\System32\KernelBase.dll","OPLOCK HANDLE CLOSED","Control: FSCTL_REQUEST_OPLOCK"
"2:33:21.8288392","MsMpEng.exe","5948","FileSystemControl","C:\Windows\System32\KernelBase.dll","SUCCESS","Control: 0x902eb (Device:0x9 Function:186 Method: 3)"
"2:33:21.8288685","MsMpEng.exe","5948","CloseFile","C:\Windows\System32\KernelBase.dll","SUCCESS",""
"2:33:21.8293359","hg.exe","14196","Thread Exit","","SUCCESS","Thread ID: 1476, User Time: 0.0000000, Kernel Time: 0.0000000"
"2:33:21.8294748","hg.exe","14196","Process Exit","","SUCCESS","Exit Status: -1073741502, User Time: 0.0000000 seconds, Kernel Time: 0.0000000 seconds, Private Bytes: 360,448, Peak Private Bytes: 462,848, Working Set: 1,888,256, Peak Working Set: 2,220,032"

Comment 5

[Tooru Fujisawa [:arai]]

Minimized testcase:

1. Setup the glean's Python Build Environment https://mozilla.github.io/glean/dev/python/setting-up-python-build-environment.html in MozillaBuild 4.0.1
2. After python setup.py build install, run python testcase.py with following testcase.py content:

import glean
import subprocess
subprocess.check_output(['hg', '--version'])

Comment 6

[Tooru Fujisawa [:arai]]

setup_logging is called twice. and the error happens after the 2nd call.

1st time:
https://github.com/mozilla/glean/blob/b4b54f61c07303323366b51937dc34f34385d44f/glean-core/python/glean/_ffi.py#L57

setup_logging()

2nd time:
https://github.com/mozilla/glean/blob/b4b54f61c07303323366b51937dc34f34385d44f/glean-core/python/glean/glean.py#L36

_ffi.setup_logging()

Comment 7

[GitHub Bugzilla PR Linker]

Attachment: Link to GitHub pull-request: https://github.com/mozilla/glean/pull/2064

Comment 8

[Jan-Erik Rediger [:janerik]]

Bug found, tested & fixed all before I could even notice. Thanks!
I noticed that moz-phab unconditionally uses any v36 or higher of Glean. That seems kinda dangerous, we're known for making breaking changes (and v50 was a big one and I didn't even consider that it will roll out in MozPhab early).

Comment 9

[Jan-Erik Rediger [:janerik]]

badboy merged PR #2064: "Bug 1770791 - Remove duplicate initialization in python glean package" in edfa0a4.