[PATCH] windows: redirect stderr to %PROGRAMDATA% with py2exe

[Matt Harbison]

# HG changeset patch
# User Matt Harbison <matt_h...@yahoo.com>
# Date 1655830250 14400
# Tue Jun 21 12:50:50 2022 -0400
# Node ID e14dede955c5c273cdc9066ee33a67f99049653c
# Parent 457aa21b45b2548a4092c25ac6eca67ff6cdc66b
# EXP-Topic stderr-redirect
windows: redirect stderr to %PROGRAMDATA% with py2exe

This fixes several problems. First, py2exe tries to write the default error log
to %PROGRAMFILES%, which UAC blocks when it is enabled, which causes the
stacktrace to be lost. %PROGRAMDATA% is where programs are supposed to write
their data.

Second, Mercurial assumes `.buffer` exists on stdio objects, but it doesn't on
the redirected stderr provided by py2exe. Third, the stderr object provided by
py2exe doesn't return the number of bytes written, which causes
`mercurial.utils.procutil.WriteAllWrapper.write()` to infinitely loop.

Therefore, stderr is replaced to write to a new log file, and stdout is
blackholed to avoid surprises with its write method not returning the number of
bytes written. (py2exe already blackholes stdout, but with a broken write
method.)

Note that the `write()` signature on the py2exe supplied stderr is a bit odd- it
has default parameters for the log filename and an `alert` parameter that is set
to `ctypes.windll.user32.MessageBoxW`. I can't see anywhere this is called with
these arguments, so I'm dropping them. Even though this code is mostly adapted
from the py2exe code[1], this doesn't seem to popup the messagebox on exit if
errors were written. It does (even on the py3 build of py2exe) if an error
occurs prior to the replacement. The new log file is definitely written to
though.

[1] https://github.com/py2exe/py2exe/blob/af0e841bffcf9c64abce6204718fecad17a59506/py2exe/boot_common.py#L55

diff --git a/thg b/thg
--- a/thg
+++ b/thg
@@ -10,6 +10,7 @@

from __future__ import print_function

+import io
import os
import sys

@@ -24,6 +25,121 @@
# sys.stdin is invalid, should be None. Fixes svn, git subrepos
sys.stdin = None

+ # Similar to mercurial.utils.procutil.BadFile, but silently discards
+ # data on write().
+ class Blackhole(io.RawIOBase):
+ """Dummy file object to simulate /dev/null"""
+ def __init__(self):
+ self.buffer = self
+
+ def readinto(self, data):
+ raise IOError(errno.EBADF, 'Bad file descriptor')
+
+ def write(self, data):
+ return len(data)
+
+ # py2exe blackholes stdout with a custom class to prevent random
+ # exceptions when writing to it, but doesn't provide the ``.buffer``
+ # attribute that mercurial.utils.procutil wants. As of 0.11.1.0, it
+ # also doesn't return the number of bytes written, and therefore
+ # violates the interface contract. For details, see:
+ # https://github.com/py2exe/py2exe/blob/af0e841bffcf9c64abce6204718fecad17a59506/py2exe/boot_common.py#L3
+ sys.stdout = Blackhole()
+
+ def open_log(fname):
+ import atexit, ctypes
+
+ try:
+ os.makedirs(os.path.dirname(fname), exist_ok=True)
+ return open(fname, 'ab')
+ except Exception as details:
+ atexit.register(
+ ctypes.windll.user32.MessageBoxW,
+ 0,
+ "The logfile '%s' could not be opened:\n %s" % (
+ fname, details,
+ ),
+ "Errors in %r" % os.path.basename(sys.executable),
+ 0
+ )
+ else:
+ atexit.register(
+ ctypes.windll.user32.MessageBoxW,
+ 0,
+ "See the logfile '%s' for details" % fname,
+ "Errors in %r" % os.path.basename(sys.executable),
+ 0
+ )
+
+ # Provide a .buffer backed by a log file for stderr to keep procutil
+ # stuff happy.
+ class RawStderr(object):
+ _file = None
+ _error = False
+
+ def __init__(self, log_name):
+ self.log_name = log_name
+
+ def write(self, data):
+ # The directory tree and log file creation is delayed until it
+ # is needed, as done by py2exe.
+ if self._file is None and not self._error:
+ self._file = open_log(self.log_name)
+ self._error = self._file is None
+
+ if self._file is not None:
+ written = self._file.write(data)
+ self._file.flush()
+ return written
+ else:
+ return len(data) # Data necessarily backholed
+
+ def flush(self):
+ if self._file is not None:
+ self._file.flush()
+
+ class Stderr(object):
+ def __init__(self, log_name):
+ self.buffer = RawStderr(log_name)
+
+ def write(self, text):
+ data = text.encode(sys.getdefaultencoding(),
+ errors='replace')
+ total = 0
+ while len(data) > total:
+ total += self.buffer.write(data[total:])
+
+ return len(text)
+
+ def flush(self):
+ self.buffer.flush()
+
+ # py2exe writes its log file next to the executable in %PROGRAMFILES%,
+ # but UAC blocks that if it is enabled. Since we have to fiddle with
+ # stderr.buffer to keep procutil happy, redirect everything to an
+ # always writeable area.
+ program_data = os.environ.get("PROGRAMDATA")
+
+ if program_data is not None:
+ log_name = os.path.join(
+ program_data,
+ "TortoiseHg",
+ os.path.splitext(
+ os.path.basename(sys.executable)
+ )[0] + '.log')
+
+ sys.stderr = Stderr(log_name)
+ else:
+ # py2exe messages come through sys.stderr; mercurial.ui.error()
+ # messages come through sys.stderr.buffer. Drop everything for the
+ # *w.exe executable if the log file cannot be created, in order to
+ # prevent various issues mentioned above.
+ sys.stderr = Blackhole()
+
+ del Stderr
+ del RawStderr
+ del Blackhole
+
# Make `pip install --user` packages visible, because py2exe doesn't
# process sitecustomize.py.
vi = sys.version_info

[Matt Harbison]

On Tuesday, June 21, 2022 at 3:56:25 PM UTC-4 Matt Harbison wrote:

# HG changeset patch
# User Matt Harbison <matt_h...@yahoo.com>
# Date 1655830250 14400
# Tue Jun 21 12:50:50 2022 -0400
# Node ID e14dede955c5c273cdc9066ee33a67f99049653c
# Parent 457aa21b45b2548a4092c25ac6eca67ff6cdc66b
# EXP-Topic stderr-redirect
windows: redirect stderr to %PROGRAMDATA% with py2exe

I think after this, we're in reasonably good shape for an RC.  The editor font issue[1] isn't fixed yet, but I don't want to hold up wider testing for that.  One thing I did notice when editing the font through the dialog as suggested by the referenced issue is that after changing to "Courier New" and hitting "OK", the log window printed "cmdserver: Process crashed".  When doing the same thing under py2, it prints "interrupted!".  I don't see any trace of the problem in the error log though, so I have no idea what the issue was or how to debug it.

The font issue in general is weird because I've struggled with this issue in the commit widget and log window on my laptop when run with a venv.  I haven't had the issue in these windows when using py2exe, but then it does occur in the settings editor.  No clue why.

[1] https://foss.heptapod.net/mercurial/tortoisehg/thg/-/issues/5776

 

[Matt Harbison]

The issue is larger than the font setting, but it seems that a cmdserver needs to be spun up first.  I did that by defining a silly tool to smoke out bytes vs str issues in the tools code:

[tortoisehg]
workbench.custom-toolbar = test

[tortoisehg-tools]
test.command = hg version
test.enable = istrue
test.label = version
test.showoutput = False
test.tooltip = Run `hg version`

The problem occurs after running the tool, and then OKing any settings change.  If `thg.exe --nofork` (not *w.exe) is run from the command line, it brings down the whole app.  `echo $?` prints 130.  If thgw.exe is run instead, I've also seen "win32ill: interrupted while stopping message loop" in the log window, but at least the app survives.  I enabled the logging for that now, so we'll see if there are any clues if it happens again.  But IDK how to debug the cmdserver issue here.

[Yuya Nishihara]

On Tue, 21 Jun 2022 13:27:48 -0700 (PDT), 'Matt Harbison' via TortoiseHg Developers wrote:
> On Tuesday, June 21, 2022 at 3:56:25 PM UTC-4 Matt Harbison wrote:
>
> > # HG changeset patch
> > # User Matt Harbison <matt_h...@yahoo.com>
> > # Date 1655830250 14400
> > # Tue Jun 21 12:50:50 2022 -0400
> > # Node ID e14dede955c5c273cdc9066ee33a67f99049653c
> > # Parent 457aa21b45b2548a4092c25ac6eca67ff6cdc66b
> > # EXP-Topic stderr-redirect
> > windows: redirect stderr to %PROGRAMDATA% with py2exe
> >
>
> I think after this, we're in reasonably good shape for an RC. The editor
> font issue[1] isn't fixed yet, but I don't want to hold up wider testing
> for that. One thing I did notice when editing the font through the dialog
> as suggested by the referenced issue is that after changing to "Courier
> New" and hitting "OK", the log window printed "cmdserver: Process
> crashed". When doing the same thing under py2, it prints "interrupted!".
> I don't see any trace of the problem in the error log though, so I have no
> idea what the issue was or how to debug it.

Sounds like win32ill.py not working properly. --config win32ill.log=<path>
might show something. If we're lucky, it'll be just a bytes/unicode issue.

[Yuya Nishihara]

On Tue, 21 Jun 2022 15:56:21 -0400, Matt Harbison wrote:
> # HG changeset patch
> # User Matt Harbison <matt_h...@yahoo.com>
> # Date 1655830250 14400
> # Tue Jun 21 12:50:50 2022 -0400
> # Node ID e14dede955c5c273cdc9066ee33a67f99049653c
> # Parent 457aa21b45b2548a4092c25ac6eca67ff6cdc66b
> # EXP-Topic stderr-redirect
> windows: redirect stderr to %PROGRAMDATA% with py2exe
>
> This fixes several problems. First, py2exe tries to write the default error log
> to %PROGRAMFILES%, which UAC blocks when it is enabled, which causes the
> stacktrace to be lost. %PROGRAMDATA% is where programs are supposed to write
> their data.
>
> Second, Mercurial assumes `.buffer` exists on stdio objects, but it doesn't on
> the redirected stderr provided by py2exe. Third, the stderr object provided by
> py2exe doesn't return the number of bytes written, which causes
> `mercurial.utils.procutil.WriteAllWrapper.write()` to infinitely loop.

Perhaps WriteAllWrapper.write() needs to be fixed to raise error or return
immediately. It's super easy to make an IO wrapper that doesn't return int.

If we don't need this dialog thingy, and ...

> + # Provide a .buffer backed by a log file for stderr to keep procutil
> + # stuff happy.
> + class RawStderr(object):
> + _file = None
> + _error = False
> +
> + def __init__(self, log_name):
> + self.log_name = log_name
> +
> + def write(self, data):
> + # The directory tree and log file creation is delayed until it
> + # is needed, as done by py2exe.
> + if self._file is None and not self._error:
> + self._file = open_log(self.log_name)
> + self._error = self._file is None

if we can always create a log file (which I think is okay since the log file
isn't written to Program Files), the simpler version will be:

sys.stdout = open(os.devnull, "w")
try:
sys.stderr = open(path_to_log_file, "w", buffering=0)
except ...:
sys.stderr = sys.stdout

I prefer the simpler one, but I don't know how important these py2exe features
are.

[Matt Harbison]

Yep, that's the log I mentioned in the next message.  So far, all I have is:

starting message loop (pid = 38196)
received WM_CLOSE
destroying window
received WM_DESTROY
starting message loop (pid = 37336)

So it doesn't seem like bytes/unicode if it can go through a full cycle, but I'll keep an eye on it.

Interestingly, the same thing mentioned in the next message (killing the app and exiting with 130) happens when hitting the stop button on the hg serve dialog with thg.exe, but not with thgw.exe.  I remember hitting this issue when running from a venv (and launching with `python thg --nofork`), but when it didn't happen with py2exe, I thought maybe we dodged the issue.  I guess not.  I assume this is probably all related?  Any other ideas on how to debug this, and/or what to load up with log statements?

[Manuel Jacob]

On 22/06/2022 03.22, Yuya Nishihara wrote:
> On Tue, 21 Jun 2022 15:56:21 -0400, Matt Harbison wrote:
>> # HG changeset patch
>> # User Matt Harbison <matt_h...@yahoo.com>
>> # Date 1655830250 14400
>> # Tue Jun 21 12:50:50 2022 -0400
>> # Node ID e14dede955c5c273cdc9066ee33a67f99049653c
>> # Parent 457aa21b45b2548a4092c25ac6eca67ff6cdc66b
>> # EXP-Topic stderr-redirect
>> windows: redirect stderr to %PROGRAMDATA% with py2exe
>>
>> This fixes several problems. First, py2exe tries to write the default error log
>> to %PROGRAMFILES%, which UAC blocks when it is enabled, which causes the
>> stacktrace to be lost. %PROGRAMDATA% is where programs are supposed to write
>> their data.
>>
>> Second, Mercurial assumes `.buffer` exists on stdio objects, but it doesn't on
>> the redirected stderr provided by py2exe. Third, the stderr object provided by
>> py2exe doesn't return the number of bytes written, which causes
>> `mercurial.utils.procutil.WriteAllWrapper.write()` to infinitely loop.
>
> Perhaps WriteAllWrapper.write() needs to be fixed to raise error or return
> immediately. It's super easy to make an IO wrapper that doesn't return int.

Originally, WriteAllWrapper.write() added the return value of the
underlying write() to an integer, failing if it was None.

Py2exe’s stderr.write() returns None, which maybe was mistaken for
signalling blocking write on a non-blocking file, resulting in
90e564882f07 in Mercurial. I suggest to back out that change.

[Matt Harbison]

On Tuesday, June 21, 2022 at 9:30:25 PM UTC-4 Yuya Nishihara wrote:

On Tue, 21 Jun 2022 15:56:21 -0400, Matt Harbison wrote:
> # HG changeset patch
> # User Matt Harbison <matt_h...@yahoo.com>
> # Date 1655830250 14400
> # Tue Jun 21 12:50:50 2022 -0400
> # Node ID e14dede955c5c273cdc9066ee33a67f99049653c
> # Parent 457aa21b45b2548a4092c25ac6eca67ff6cdc66b
> # EXP-Topic stderr-redirect
> windows: redirect stderr to %PROGRAMDATA% with py2exe
>
> This fixes several problems. First, py2exe tries to write the default error log
> to %PROGRAMFILES%, which UAC blocks when it is enabled, which causes the
> stacktrace to be lost. %PROGRAMDATA% is where programs are supposed to write
> their data.
>
> Second, Mercurial assumes `.buffer` exists on stdio objects, but it doesn't on
> the redirected stderr provided by py2exe. Third, the stderr object provided by
> py2exe doesn't return the number of bytes written, which causes
> `mercurial.utils.procutil.WriteAllWrapper.write()` to infinitely loop.

Perhaps WriteAllWrapper.write() needs to be fixed to raise error or return
immediately. It's super easy to make an IO wrapper that doesn't return int.

Yeah, that's a good idea (but we'll still need the workaround here).  I didn't like the potential for the infinite loop, but I think at the time I was under the impression that maybe the file descriptor could be non-blocking.

I like the simpler one too, but I *really* miss the messagebox that there was a problem.  Otherwise, I'm not in the habit of checking, and users won't know where to look, so we'll miss bug reports.  I have no clue why the messagebox isn't showing though.

I think this would clean up a lot (completely?) if the .buffer silly wrapper was added to procutil (but what is the encoding supposed to be?), and writing the log to PROGRAMDATA was upstreamed in py2exe.  But the maintainer has been slow to process PRs (my previous curses fix, and mjacob's returning int fixes are still open for several weeks).

[Yuya Nishihara]

That implies thg process and cmdserver process share the console if executed
without --nofork.

I think this Qt change is the source of the issue. We do need CREATE_NO_WINDOW
or CREATE_NEW_CONSOLE flag so CTRL_C_EVENT wouldn't be propagated to the main
window process.

https://code.qt.io/cgit/qt/qtbase.git/commit/?id=4e5c2834a23be7a306e6de2680c3c560d8c02528

There's a function to hook the process creation on Windows, but I suspect
it wouldn't be available to Python world.

https://doc.qt.io/qt-5/qprocess.html#CreateProcessArgumentModifier-typedef

[Yuya Nishihara]

If it were non-blocking, the WriteAllWrapper wouldn't work as designed.
Spinning there until the non-blocking I/O gets ready is really bad.

So I agree with Manuel to back out 90e564882f07.

Suppose we do truncate the log file at start, maybe we can add an atexit hook
that checks the size of the log file?

> I think this would clean up a lot (completely?) if the .buffer silly
> wrapper was added to procutil (but what is the encoding supposed to be?),
> and writing the log to PROGRAMDATA was upstreamed in py2exe.

Another idea is to blackhole the .buffer. All mercurial messages would be lost,
but the exception would be caught so long as it is written to sys.stderr.

sys.stderr.buffer = open(os.devnull, "wb")

[Matt Harbison]

Agreed.

 

> > if we can always create a log file (which I think is okay since the log
> > file
> > isn't written to Program Files), the simpler version will be:
> >
> > sys.stdout = open(os.devnull, "w")
> > try:
> > sys.stderr = open(path_to_log_file, "w", buffering=0)
> > except ...:
> > sys.stderr = sys.stdout
> >
> > I prefer the simpler one, but I don't know how important these py2exe
> > features
> > are.
> >
>
> I like the simpler one too, but I *really* miss the messagebox that there
> was a problem. Otherwise, I'm not in the habit of checking, and users
> won't know where to look, so we'll miss bug reports. I have no clue why
> the messagebox isn't showing though.

Suppose we do truncate the log file at start, maybe we can add an atexit hook
that checks the size of the log file?

I don't like losing the previous info, but there are no bookends to mark the process lifecycle, so I guess this could work until the changes can be ported to py2exe itself.  (I have no idea how to get the "TortoiseHg" part into the PROGRAMDATA path there, but that's a different issue.)

 

> I think this would clean up a lot (completely?) if the .buffer silly
> wrapper was added to procutil (but what is the encoding supposed to be?),
> and writing the log to PROGRAMDATA was upstreamed in py2exe.

Another idea is to blackhole the .buffer. All mercurial messages would be lost,
but the exception would be caught so long as it is written to sys.stderr.

sys.stderr.buffer = open(os.devnull, "wb")

So far, I haven't seen any important mercurial messages (mostly obsolete markers found without obsolete being enabled, "extension 'evolve' overrides commands", and similar).  But I'm hesitant to disable any I/O logging because I'm expecting more problems with py3.  AFAICT, dispatch writes exceptions through ui, which go through .buffer and would also be lost?

[Yuya Nishihara]

If we don't care the file name, maybe using NamedTemporaryFile is the easiest
option.

https://docs.python.org/3/library/tempfile.html#tempfile.NamedTemporaryFile

> > > I think this would clean up a lot (completely?) if the .buffer silly
> > > wrapper was added to procutil (but what is the encoding supposed to
> > be?),
> > > and writing the log to PROGRAMDATA was upstreamed in py2exe.
> >
> > Another idea is to blackhole the .buffer. All mercurial messages would be
> > lost,
> > but the exception would be caught so long as it is written to sys.stderr.
> >
> > sys.stderr.buffer = open(os.devnull, "wb")
> >
>
> So far, I haven't seen any important mercurial messages (mostly obsolete
> markers found without obsolete being enabled, "extension 'evolve' overrides
> commands", and similar). But I'm hesitant to disable any I/O logging
> because I'm expecting more problems with py3. AFAICT, dispatch writes
> exceptions through ui, which go through .buffer and would also be lost?

Yep, anything written to ui wouldn't be captured.

[Matt Harbison]

# HG changeset patch
# User Matt Harbison <matt_h...@yahoo.com>
# Date 1655830250 14400
# Tue Jun 21 12:50:50 2022 -0400

# Node ID a447c313d7ff295654a8e2b796abbeda0d9d9384

# Parent 457aa21b45b2548a4092c25ac6eca67ff6cdc66b
# EXP-Topic stderr-redirect
windows: redirect stderr to %PROGRAMDATA% with py2exe

This fixes several problems. First, py2exe tries to write the default error log
to %PROGRAMFILES%, which UAC blocks when it is enabled, which causes the
stacktrace to be lost. %PROGRAMDATA% is where programs are supposed to write
their data.

Second, Mercurial assumes `.buffer` exists on stdio objects, but it doesn't on
the redirected stderr provided by py2exe. Third, the stderr object provided by

py2exe doesn't return the number of bytes written, which (currently) causes
`mercurial.utils.procutil.WriteAllWrapper.write()` to infinitely loop, until hg
90e564882f07 is backed out.

Therefore, stderr is replaced to write to a new log file, and stdout is
blackholed to avoid surprises with its write method not returning the number of
bytes written. (py2exe already blackholes stdout, but with a broken write

method.) The previous behavior provided by py2exe is maintained (log append,
popup on exit with errors), except that the creation of the log isn't deferred
to the first write attempt.

Note that the `write()` signature on the py2exe supplied stderr is a bit odd- it
has default parameters for the log filename and an `alert` parameter that is set
to `ctypes.windll.user32.MessageBoxW`. I can't see anywhere this is called with

these arguments, so just use the file stream object directly.

diff --git a/thg b/thg
--- a/thg
+++ b/thg

@@ -24,6 +24,86 @@

# sys.stdin is invalid, should be None. Fixes svn, git subrepos
sys.stdin = None

+ # py2exe blackholes stdout with a custom class to prevent random
+ # exceptions when writing to it, but doesn't provide the ``.buffer``
+ # attribute that mercurial.utils.procutil wants. As of 0.11.1.0, it
+ # also doesn't return the number of bytes written, and therefore
+ # violates the interface contract. For details, see:
+ # https://github.com/py2exe/py2exe/blob/af0e841bffcf9c64abce6204718fecad17a59506/py2exe/boot_common.py#L3

+ #
+ # TODO: upstream write() return value and PROGRAMDATA usage in py2exe,
+ # and then most or all of this can go away.
+ sys.stdout = open(os.devnull, "w")
+
+ # py2exe writes its redirected stderr log file next to the executable
+ # (so typically in %PROGRAMFILES%), but UAC blocks that when it is
+ # enabled. Replacing stderr with our own log file to an always
+ # writeable area prevents that, fixes the missing write() return value,
+ # and provides the `.buffer` attribute that procutil assumes is present.

+ program_data = os.environ.get("PROGRAMDATA")
+
+ if program_data is not None:

+ import atexit, ctypes
+

+ dir_name = os.path.join(program_data, "TortoiseHg")
+ log_name = os.path.join(
+ dir_name,

+ os.path.splitext(
+ os.path.basename(sys.executable)
+ )[0] + '.log'

+ )
+
+ try:
+ os.makedirs(dir_name, exist_ok=True)
+
+ # The replacement stderr stream installed by py2exe flushes
+ # every write, but buffering=0 isn't supported in text mode.
+ class Unbuffered(object):
+ def __init__(self, stream):
+ self.stream = stream

+
+ def write(self, data):

+ self.stream.write(data)
+ self.stream.flush()
+
+ def __getattr__(self, attr):
+ return getattr(self.stream, attr)
+
+ sys.stderr = Unbuffered(open(log_name, 'a'))

+ except Exception as details:

+ sys.stderr = sys.stdout # blackhole messages
+

+ atexit.register(
+ ctypes.windll.user32.MessageBoxW,
+ 0,

+ "The logfile '%s' could not be opened:\n %s" % (

+ log_name, details,
+ ),

+ "Errors in %r" % os.path.basename(sys.executable),
+ 0
+ )

+ else:
+ orig_size = os.stat(log_name).st_size
+
+ def exit_check():
+ log_size = os.stat(log_name).st_size
+
+ if orig_size != log_size:
+ ctypes.windll.user32.MessageBoxW(
+ 0,
+ "See the logfile '%s' for details" % log_name,

+ "Errors in %r" % os.path.basename(sys.executable),

+ 0,
+ )
+
+ atexit.register(exit_check)

+ else:
+ # py2exe messages come through sys.stderr; mercurial.ui.error()
+ # messages come through sys.stderr.buffer. Drop everything for the
+ # *w.exe executable if the log file cannot be created, in order to
+ # prevent various issues mentioned above.

+ sys.stderr = sys.stdout

[Yuya Nishihara]

On Wed, 22 Jun 2022 16:42:54 -0400, Matt Harbison wrote:
> # HG changeset patch
> # User Matt Harbison <matt_h...@yahoo.com>
> # Date 1655830250 14400
> # Tue Jun 21 12:50:50 2022 -0400
> # Node ID a447c313d7ff295654a8e2b796abbeda0d9d9384
> # Parent 457aa21b45b2548a4092c25ac6eca67ff6cdc66b
> # EXP-Topic stderr-redirect
> windows: redirect stderr to %PROGRAMDATA% with py2exe

> + program_data = os.environ.get("PROGRAMDATA")
> +
> + if program_data is not None:
> + import atexit, ctypes
> +
> + dir_name = os.path.join(program_data, "TortoiseHg")
> + log_name = os.path.join(
> + dir_name,
> + os.path.splitext(
> + os.path.basename(sys.executable)
> + )[0] + '.log'
> + )
> +
> + try:
> + os.makedirs(dir_name, exist_ok=True)
> +
> + # The replacement stderr stream installed by py2exe flushes
> + # every write, but buffering=0 isn't supported in text mode.

Right. We can use buffering=1 instead to make it line buffered, which should
work well for log output.

> + sys.stderr = Unbuffered(open(log_name, 'a'))
> + except Exception as details:
> + sys.stderr = sys.stdout # blackhole messages
> +
> + atexit.register(
> + ctypes.windll.user32.MessageBoxW,
> + 0,
> + "The logfile '%s' could not be opened:\n %s" % (
> + log_name, details,
> + ),
> + "Errors in %r" % os.path.basename(sys.executable),
> + 0
> + )

Do we need to delay this error message with atexit?

> + else:
> + orig_size = os.stat(log_name).st_size
> +
> + def exit_check():
> + log_size = os.stat(log_name).st_size

Better to use tell() or seek() instead of stat(), even though we aren't
serious about race.

[Matt Harbison]

I guess not.  I figure it would be annoying to see this on startup if something goes wrong, but in practice it probably shouldn't.

 

> + else:
> + orig_size = os.stat(log_name).st_size
> +
> + def exit_check():
> + log_size = os.stat(log_name).st_size

Better to use tell() or seek() instead of stat(), even though we aren't
serious about race.

I had it like that, but then remembered there was some issue with opening in append mode and using tell() that was dealt with in the vfs layer, but I guess we can seek() + tell().

I see there's os.path.get_size(), but didn't use that because it's py3 only (though I assume it uses stat too).

[Yuya Nishihara]

IIRC, open(.., 'a') doesn't (always?) seek to EOF on Windows, or something
like that. I don't know if that's still true for py3 io which no longer use
the underlying libc stdio.

[Matt Harbison]

# HG changeset patch
# User Matt Harbison <matt_h...@yahoo.com>
# Date 1655830250 14400
# Tue Jun 21 12:50:50 2022 -0400

# Node ID cc2a1241827582678934cfbd69f6bf3061cf0498

# Parent 457aa21b45b2548a4092c25ac6eca67ff6cdc66b
# EXP-Topic stderr-redirect
windows: redirect stderr to %PROGRAMDATA% with py2exe

This fixes several problems. First, py2exe tries to write the default error log
to %PROGRAMFILES%, which UAC blocks when it is enabled, which causes the
stacktrace to be lost. %PROGRAMDATA% is where programs are supposed to write
their data.

Second, Mercurial assumes `.buffer` exists on stdio objects, but it doesn't on
the redirected stderr provided by py2exe. Third, the stderr object provided by
py2exe doesn't return the number of bytes written, which (currently) causes
`mercurial.utils.procutil.WriteAllWrapper.write()` to infinitely loop, until hg
90e564882f07 is backed out.

Therefore, stderr is replaced to write to a new log file, and stdout is
blackholed to avoid surprises with its write method not returning the number of
bytes written. (py2exe already blackholes stdout, but with a broken write
method.) The previous behavior provided by py2exe is maintained (log append,
popup on exit with errors), except that the creation of the log isn't deferred

to the first write attempt and the error popup on failure to create the log is
not deferred until exit.

Note that the `write()` signature on the py2exe supplied stderr is a bit odd- it
has default parameters for the log filename and an `alert` parameter that is set
to `ctypes.windll.user32.MessageBoxW`. I can't see anywhere this is called with
these arguments, so just use the file stream object directly.

diff --git a/thg b/thg
--- a/thg
+++ b/thg

@@ -24,6 +24,70 @@

# sys.stdin is invalid, should be None. Fixes svn, git subrepos
sys.stdin = None

+ # py2exe blackholes stdout with a custom class to prevent random
+ # exceptions when writing to it, but doesn't provide the ``.buffer``
+ # attribute that mercurial.utils.procutil wants. As of 0.11.1.0, it
+ # also doesn't return the number of bytes written, and therefore
+ # violates the interface contract. For details, see:
+ # https://github.com/py2exe/py2exe/blob/af0e841bffcf9c64abce6204718fecad17a59506/py2exe/boot_common.py#L3
+ #
+ # TODO: upstream write() return value and PROGRAMDATA usage in py2exe,
+ # and then most or all of this can go away.
+ sys.stdout = open(os.devnull, "w")
+
+ # py2exe writes its redirected stderr log file next to the executable
+ # (so typically in %PROGRAMFILES%), but UAC blocks that when it is
+ # enabled. Replacing stderr with our own log file to an always
+ # writeable area prevents that, fixes the missing write() return value,
+ # and provides the `.buffer` attribute that procutil assumes is present.

+ program_data = os.environ.get("PROGRAMDATA")
+
+ if program_data is not None:
+ import atexit, ctypes
+
+ dir_name = os.path.join(program_data, "TortoiseHg")
+ log_name = os.path.join(
+ dir_name,
+ os.path.splitext(
+ os.path.basename(sys.executable)
+ )[0] + '.log'
+ )
+
+ try:
+ os.makedirs(dir_name, exist_ok=True)

+ sys.stderr = open(log_name, 'a', buffering=1)

+ except Exception as details:
+ sys.stderr = sys.stdout # blackhole messages

+ ctypes.windll.user32.MessageBoxW(

+ 0,
+ "The logfile '%s' could not be opened:\n %s" % (
+ log_name, details,
+ ),
+ "Errors in %r" % os.path.basename(sys.executable),
+ 0
+ )

+ else:
+ orig_size = sys.stderr.seek(0, os.SEEK_END)
+
+ def exit_check():
+ log_size = sys.stderr.tell()

+
+ if orig_size != log_size:
+ ctypes.windll.user32.MessageBoxW(
+ 0,
+ "See the logfile '%s' for details" % log_name,

+ "Errors in %r" % os.path.basename(sys.executable),

[Yuya Nishihara]

On Thu, 23 Jun 2022 11:07:21 -0400, Matt Harbison wrote:
> # HG changeset patch
> # User Matt Harbison <matt_h...@yahoo.com>
> # Date 1655830250 14400
> # Tue Jun 21 12:50:50 2022 -0400
> # Node ID cc2a1241827582678934cfbd69f6bf3061cf0498
> # Parent 457aa21b45b2548a4092c25ac6eca67ff6cdc66b
> # EXP-Topic stderr-redirect
> windows: redirect stderr to %PROGRAMDATA% with py2exe

Queued this, thanks.

[Matt Harbison]

I played with this a bit more, and indeed, the conhost.exe is in different locations in the process tree.  Also, I was able to reproduce this with py2, so it's not new behavior.  I just need to remember to use thgw.exe and pythonw.exe instead of python.exe.  (Not sure if this is worth a warning/error in the startup script on Windows- running from a virtualenv wasn't a real option with py2 because of the lack of PyQt5 libraries for it, which is why I hadn't run into it before there.)

I didn't make any further progress figuring out why cmdserver crashes sometimes, but it now seems unrelated to that CTRL_C_EVENT stuff.  I enabled the win32ill log, and the output looks the same for a clean exit, when 'interrupted!' is printed in the log window, and when it says "Process crashed".  I also added a finally block to the end of the stop method in win32ill[1] with a print (which runs in all of these cases, so the atexit handler is running and completing), and a bare except clause that would print a message (but it never runs).  There's nothing interesting in blackbox.log, or when HGCATAPULTSERVERPIPE is set to a file to enable tracing.  So I'm not sure how else to debug this.  But since the cmdserver process also exits (but cleanly) under py2, and it happens when cmdserver is being shutdown anyway, it's probably not worth holding up the -rc to debug this further.

[1] https://foss.heptapod.net/mercurial/tortoisehg/thg/-/blob/branch/stable/tortoisehg/util/win32ill.py#L265

 

[Yuya Nishihara]

Does this snippet mitigate the problem? It might be better to disable Ctrl-C
at all on Windows.

diff --git a/tortoisehg/hgqt/qtapp.py b/tortoisehg/hgqt/qtapp.py
--- a/tortoisehg/hgqt/qtapp.py
+++ b/tortoisehg/hgqt/qtapp.py
@@ -219,7 +219,7 @@ class ExceptionCatcher(QObject):
# QTimer makes sure to not enter new event loop in signal handler,
# which will be invoked at random location. Note that some windows
# may show modal confirmation dialog in closeEvent().
- QTimer.singleShot(0, self._mainapp.closeAllWindows)
+ pass #QTimer.singleShot(0, self._mainapp.closeAllWindows)

if os.name == 'posix':
# Wake up Python interpreter via pipe so that SIGINT can be handled

> I didn't make any further progress figuring out why cmdserver crashes
> sometimes, but it now seems unrelated to that CTRL_C_EVENT stuff. I
> enabled the win32ill log, and the output looks the same for a clean exit,
> when 'interrupted!' is printed in the log window, and when it says "Process
> crashed". I also added a finally block to the end of the stop method in
> win32ill[1] with a print (which runs in all of these cases, so the atexit
> handler is running and completing), and a bare except clause that would
> print a message (but it never runs). There's nothing interesting in
> blackbox.log, or when HGCATAPULTSERVERPIPE is set to a file to enable
> tracing. So I'm not sure how else to debug this. But since the cmdserver
> process also exits (but cleanly) under py2, and it happens when cmdserver
> is being shutdown anyway, it's probably not worth holding up the -rc to
> debug this further.

I don't follow the full story of the crash. Does the problem occur on both
thg.exe and thgw.exe?

[Matt Harbison]

No.  e.g. starting and stopping the serve process from the menu with `./thg.exe --nofork` will also kill the GUI.  Dropping --nofork allows the GUI to continue.

For context, this is cmdserver crashing, not the GUI app.  It's hard to tell if it occurs with both thg.exe and thgw.exe because of the GUI exiting in the thg.exe case, and now I can't reproduce it anymore since turning on the HGCATAPULTSERVERPIPE stuff.  I disabled it again by clearing the environment variable for it, but still can't trigger the "Process crashed" output.  There's still some extra logging, but not much.  I was able to trigger the "interrupted!" case with both executables, but there's a comment in win32ill.uisetup.stop() that KeyboardInterrupt can happen in the normal case, so I suspect this case is the same exception being raised in cmdserver somehow.

Side question: is this a typo and should be !=, or does the completion callback also fire for (most) error cases anyway?

https://foss.heptapod.net/mercurial/tortoisehg/thg/-/blob/bcf8ed30674070093c87cbac63259562e5c2f092/tortoisehg/hgqt/cmdcore.py#L423

 

[Yuya Nishihara]

On Fri, 24 Jun 2022 08:10:35 -0700 (PDT), 'Matt Harbison' via TortoiseHg Developers wrote:
> On Friday, June 24, 2022 at 4:09:32 AM UTC-4 Yuya Nishihara wrote:
> > Does this snippet mitigate the problem? It might be better to disable
> > Ctrl-C
> > at all on Windows.
> >
>
> No. e.g. starting and stopping the serve process from the menu with
> `./thg.exe --nofork` will also kill the GUI. Dropping --nofork allows the
> GUI to continue.

Weird. I have no idea how Ctrl-C is translated on Windows.

FWIW, hgweb works a bit differently from the other mercurial commands
since blocking winsock call can't be interrupted. So the serve dialog isn't
a good choice for testing the general behavior of cmdserver interruption.

> > > I didn't make any further progress figuring out why cmdserver crashes
> > > sometimes, but it now seems unrelated to that CTRL_C_EVENT stuff. I
> > > enabled the win32ill log, and the output looks the same for a clean
> > exit,
> > > when 'interrupted!' is printed in the log window, and when it says
> > "Process
> > > crashed". I also added a finally block to the end of the stop method in
> > > win32ill[1] with a print (which runs in all of these cases, so the
> > atexit
> > > handler is running and completing), and a bare except clause that would
> > > print a message (but it never runs). There's nothing interesting in
> > > blackbox.log, or when HGCATAPULTSERVERPIPE is set to a file to enable
> > > tracing. So I'm not sure how else to debug this. But since the cmdserver
> > > process also exits (but cleanly) under py2, and it happens when
> > cmdserver
> > > is being shutdown anyway, it's probably not worth holding up the -rc to
> > > debug this further.
> >
> > I don't follow the full story of the crash. Does the problem occur on both
> > thg.exe and thgw.exe?
> >
>
> For context, this is cmdserver crashing, not the GUI app.

Okay, that's good to know. There might be some error in our/CPython shutdown
code (because signal/event handling is tricky in general), but yeah it wouldn't
be worth debugging further so long as the crash doesn't occur at random timing.

> It's hard to
> tell if it occurs with both thg.exe and thgw.exe because of the GUI exiting
> in the thg.exe case, and now I can't reproduce it anymore since turning on
> the HGCATAPULTSERVERPIPE stuff. I disabled it again by clearing the
> environment variable for it, but still can't trigger the "Process crashed"
> output. There's still some extra logging, but not much. I was able to
> trigger the "interrupted!" case with both executables, but there's a
> comment in win32ill.uisetup.stop() that KeyboardInterrupt can happen in the
> normal case, so I suspect this case is the same exception being raised in
> cmdserver somehow.
>
> Side question: is this a typo and should be !=, or does the completion
> callback also fire for (most) error cases anyway?
>
> https://foss.heptapod.net/mercurial/tortoisehg/thg/-/blob/bcf8ed30674070093c87cbac63259562e5c2f092/tortoisehg/hgqt/cmdcore.py#L423

It's not an error afaik. If the process has started, finished signal should
be emitted no matter if the process crashed or not.