view mercurial/loggingutil.py @ 45390:7d24201b6447

worker: don't expose readinto() on _blockingreader since pickle is picky

The `pickle` module expects the input to be buffered and a whole
object to be available when `pickle.load()` is called, which is not
necessarily true when we send data from workers back to the parent
process (i.e., it seems like a bad assumption for the `pickle` module
to make). We added a workaround for that in
https://phab.mercurial-scm.org/D8076, which made `read()` continue
until all the requested bytes have been read.

As we found out at work after a lot of investigation (I've spent the
last two days on this), the native version of `pickle.load()` has
started calling `readinto()` on the input since Python 3.8. That
started being called in
https://github.com/python/cpython/commit/91f4380cedbae32b49adbea2518014a5624c6523
(and only by the C version of `pickle.load()`)). Before that, it was
only `read()` and `readline()` that were called. The problem with that
was that `readinto()` on our `_blockingreader` was simply delegating
to the underlying, *unbuffered* object. The symptom we saw was that
`hg fix` started failing sometimes on Python 3.8 on Mac. It failed
very relyable in some cases. I still haven't figured out under what
circumstances it fails and I've been unable to reproduce it in test
cases (I've tried writing larger amounts of data, using different
numbers of workers, and making the formatters sleep). I have, however,
been able to reproduce it 3-4 times on Linux, but then it stopped
reproducing on the following few hundred attempts.

To fix the problem, we can simply remove the implementation of
`readinto()`, since the unpickler will then fall back to calling
`read()`. The fallback was added a bit later, in
https://github.com/python/cpython/commit/b19f7ecfa3adc6ba1544225317b9473649815b38. However,
that commit also added checking that what `read()` returns is a
`bytes`, so we also need to convert the `bytearray` we use into
that. I was able to add a test for that failure at least.

Differential Revision: https://phab.mercurial-scm.org/D8928

# loggingutil.py - utility for logging events
#
# Copyright 2010 Nicolas Dumazet
# Copyright 2013 Facebook, Inc.
#
# This software may be used and distributed according to the terms of the
# GNU General Public License version 2 or any later version.

from __future__ import absolute_import

import errno

from . import pycompat

from .utils import (
    dateutil,
    procutil,
    stringutil,
)


def openlogfile(ui, vfs, name, maxfiles=0, maxsize=0):
    """Open log file in append mode, with optional rotation

    If maxsize > 0, the log file will be rotated up to maxfiles.
    """

    def rotate(oldpath, newpath):
        try:
            vfs.unlink(newpath)
        except OSError as err:
            if err.errno != errno.ENOENT:
                ui.debug(
                    b"warning: cannot remove '%s': %s\n"
                    % (newpath, err.strerror)
                )
        try:
            if newpath:
                vfs.rename(oldpath, newpath)
        except OSError as err:
            if err.errno != errno.ENOENT:
                ui.debug(
                    b"warning: cannot rename '%s' to '%s': %s\n"
                    % (newpath, oldpath, err.strerror)
                )

    if maxsize > 0:
        try:
            st = vfs.stat(name)
        except OSError:
            pass
        else:
            if st.st_size >= maxsize:
                path = vfs.join(name)
                for i in pycompat.xrange(maxfiles - 1, 1, -1):
                    rotate(
                        oldpath=b'%s.%d' % (path, i - 1),
                        newpath=b'%s.%d' % (path, i),
                    )
                rotate(oldpath=path, newpath=maxfiles > 0 and path + b'.1')
    return vfs(name, b'a', makeparentdirs=False)


def _formatlogline(msg):
    date = dateutil.datestr(format=b'%Y/%m/%d %H:%M:%S')
    pid = procutil.getpid()
    return b'%s (%d)> %s' % (date, pid, msg)


def _matchevent(event, tracked):
    return b'*' in tracked or event in tracked


class filelogger(object):
    """Basic logger backed by physical file with optional rotation"""

    def __init__(self, vfs, name, tracked, maxfiles=0, maxsize=0):
        self._vfs = vfs
        self._name = name
        self._trackedevents = set(tracked)
        self._maxfiles = maxfiles
        self._maxsize = maxsize

    def tracked(self, event):
        return _matchevent(event, self._trackedevents)

    def log(self, ui, event, msg, opts):
        line = _formatlogline(msg)
        try:
            with openlogfile(
                ui,
                self._vfs,
                self._name,
                maxfiles=self._maxfiles,
                maxsize=self._maxsize,
            ) as fp:
                fp.write(line)
        except IOError as err:
            ui.debug(
                b'cannot write to %s: %s\n'
                % (self._name, stringutil.forcebytestr(err))
            )


class fileobjectlogger(object):
    """Basic logger backed by file-like object"""

    def __init__(self, fp, tracked):
        self._fp = fp
        self._trackedevents = set(tracked)

    def tracked(self, event):
        return _matchevent(event, self._trackedevents)

    def log(self, ui, event, msg, opts):
        line = _formatlogline(msg)
        try:
            self._fp.write(line)
            self._fp.flush()
        except IOError as err:
            ui.debug(
                b'cannot write to %s: %s\n'
                % (
                    stringutil.forcebytestr(self._fp.name),
                    stringutil.forcebytestr(err),
                )
            )


class proxylogger(object):
    """Forward log events to another logger to be set later"""

    def __init__(self):
        self.logger = None

    def tracked(self, event):
        return self.logger is not None and self.logger.tracked(event)

    def log(self, ui, event, msg, opts):
        assert self.logger is not None
        self.logger.log(ui, event, msg, opts)