Python logging.makeLogRecord() Examples

def test_multiline_formatter_puts_message_lines_into_data_area():
    """
    We want logs to look like:

    01 19:36:09.823  |This is
                     |multiline
                     |content
    """
    from moler.config.loggers import MultilineWithDirectionFormatter

    formatter = MultilineWithDirectionFormatter(fmt="%(asctime)s.%(msecs)03d |%(message)s", datefmt="%d %H:%M:%S")
    tm_struct = time.strptime("2000-01-01 19:36:09", "%Y-%m-%d %H:%M:%S")
    epoch_tm = time.mktime(tm_struct)
    logging_time = epoch_tm
    log_rec = logging.makeLogRecord({'msg': "This is\nmultiline\ncontent",
                                     'created': logging_time, 'msecs': 823})
    output = formatter.format(log_rec)

    assert output == "01 19:36:09.823 |This is\n" \
                     "                |multiline\n" \
                     "                |content" 

def handle_log(self, obj):
        """Handle an incoming log processing request.

        :param obj: The Channels message object. Command object format:

            .. code-block:: none

                {
                    'command': 'log',
                    'message': [log message]
                }
        """
        record_dict = json.loads(obj[ExecutorProtocol.LOG_MESSAGE])
        record_dict["msg"] = record_dict["msg"]

        executors_dir = os.path.join(
            os.path.dirname(os.path.dirname(__file__)), "executors"
        )
        record_dict["pathname"] = os.path.join(executors_dir, record_dict["pathname"])

        logger.handle(logging.makeLogRecord(record_dict)) 

def __init__(self, fmt=None, datefmt=None):
        """Initialization method.

        Args:
            fmt (string): Log message format.

            datefmt (dict): Log date format.

        Returns:
            New instance of :class:`StructuredFormatter`

        Examples:
            >>> StructuredFormatter("%(message)s")  # doctest: +ELLIPSIS
            <pygogo.formatters.StructuredFormatter object at 0x...>
        """
        empty_record = logging.makeLogRecord({})
        filterer = lambda k: k not in empty_record.__dict__ and k != "asctime"
        self.filterer = filterer
        super(StructuredFormatter, self).__init__(fmt, datefmt) 

def filter(self, record):
        """Determines whether or a not a message should be logged.

        Args:
            record (obj): The event to (potentially) log

        Returns:
            bool: True if the event level is lower than self.high_level

        Examples:
            >>> attrs = {'levelno': logging.INFO}
            >>> record = logging.makeLogRecord(attrs)
            >>> LogFilter(40).filter(record)
            True
        """
        return record.levelno < self.high_level 

def test_file_filter():
    ffilter = FileFilter('pyppl', ['INFO'])
    record = logging.makeLogRecord(
        dict(
            msg="This is logging record1.",
            mylevel="INFO",
            ispbar=False,
        ))
    assert not ffilter.filter(record)

    record = logging.makeLogRecord(
        dict(
            msg="This is logging record1.",
            formatted="This is logging record1.",
            mylevel="INFO",
            ispbar=False,
        ))
    assert ffilter.filter(record) 

def test_file_formatter():
    ffmt = FileFormatter()
    record = logging.makeLogRecord(
        dict(
            msg="This is logging record1.",
            #formatted = "\x1b[31mThis is logging record2.\x1b[0m",
            mylevel="INFO",
            ispbar=False,
        ))
    assert 'This is logging record1.' in ffmt.format(record)

    record = logging.makeLogRecord(
        dict(
            msg="This is logging record1.",
            formatted="\x1b[31mThis is logging record2.\x1b[0m",
            mylevel="INFO",
            ispbar=False,
        ))
    assert ffmt.format(record) == 'This is logging record2.' 

def test_error_handling(self):
        h = TestStreamHandler(BadStream())
        r = logging.makeLogRecord({})
        old_raise = logging.raiseExceptions

        try:
            h.handle(r)
            self.assertIs(h.error_record, r)

            h = logging.StreamHandler(BadStream())
            with support.captured_stderr() as stderr:
                h.handle(r)
                msg = '\nRuntimeError: deliberate mistake\n'
                self.assertIn(msg, stderr.getvalue())

            logging.raiseExceptions = False
            with support.captured_stderr() as stderr:
                h.handle(r)
                self.assertEqual('', stderr.getvalue())
        finally:
            logging.raiseExceptions = old_raise

# -- The following section could be moved into a server_helper.py module
# -- if it proves to be of wider utility than just test_logging 

def test_basic(self):
        sockmap = {}
        server = TestSMTPServer((support.HOST, 0), self.process_message, 0.001,
                                sockmap)
        server.start()
        addr = (support.HOST, server.port)
        h = logging.handlers.SMTPHandler(addr, 'me', 'you', 'Log',
                                         timeout=self.TIMEOUT)
        self.assertEqual(h.toaddrs, ['you'])
        self.messages = []
        r = logging.makeLogRecord({'msg': 'Hello \u2713'})
        self.handled = threading.Event()
        h.handle(r)
        self.handled.wait(self.TIMEOUT)  # 14314: don't wait forever
        server.stop()
        self.assertTrue(self.handled.is_set())
        self.assertEqual(len(self.messages), 1)
        peer, mailfrom, rcpttos, data = self.messages[0]
        self.assertEqual(mailfrom, 'me')
        self.assertEqual(rcpttos, ['you'])
        self.assertIn('\nSubject: Log\n', data)
        self.assertTrue(data.endswith('\n\nHello \u2713'))
        h.close() 

def _heartbeat(self) -> None:
        if not self.heartbeatInterval:
            return

        # check if `heartbeatInterval` seconds have passed.
        # if they have, emit a heartbeat log record to the target handler
        _now = time.monotonic()
        _diff = _now - self._s_time
        if _diff >= self.heartbeatInterval:
            self._s_time = _now
            # see: https://docs.python.org/3/library/logging.html#logging.LogRecord
            record = logging.makeLogRecord(
                {
                    "level": logging.INFO,
                    "name": "BreachHandler",
                    "pathname": ".../naz/naz/log.py",
                    "func": "BreachHandler._heartbeat",
                    "msg": {
                        "event": "naz.BreachHandler.heartbeat",
                        "heartbeatInterval": self.heartbeatInterval,
                    },
                }
            )
            self.target.emit(record=record)  # type: ignore # pytype: disable=attribute-error 

def test_multiline_formatter():
    import logging
    from ldap2pg.config import MultilineFormatter

    formatter = MultilineFormatter("prefix: %(message)s")

    base_record = dict(
        name='pouet', level=logging.DEBUG, fn="(unknown file)", lno=0, args=(),
        exc_info=None,
    )
    record = logging.makeLogRecord(dict(base_record, msg="single line"))
    payload = formatter.format(record)
    assert "prefix: single line" == payload

    record = logging.makeLogRecord(dict(base_record, msg="Uno\nDos\nTres"))

    payload = formatter.format(record)
    wanted = dedent("""\
    prefix: Uno
    prefix: Dos
    prefix: Tres
    """).strip()

    assert wanted == payload 

def test_error_handling(self):
        h = TestStreamHandler(BadStream())
        r = logging.makeLogRecord({})
        old_raise = logging.raiseExceptions
        old_stderr = sys.stderr
        try:
            h.handle(r)
            self.assertIs(h.error_record, r)
            h = logging.StreamHandler(BadStream())
            sys.stderr = sio = io.StringIO()
            h.handle(r)
            self.assertIn('\nRuntimeError: deliberate mistake\n',
                          sio.getvalue())
            logging.raiseExceptions = False
            sys.stderr = sio = io.StringIO()
            h.handle(r)
            self.assertEqual('', sio.getvalue())
        finally:
            logging.raiseExceptions = old_raise
            sys.stderr = old_stderr

# -- The following section could be moved into a server_helper.py module
# -- if it proves to be of wider utility than just test_logging 

def test_basic(self):
        sockmap = {}
        server = TestSMTPServer((HOST, 0), self.process_message, 0.001,
                                sockmap)
        server.start()
        addr = (HOST, server.port)
        h = logging.handlers.SMTPHandler(addr, 'me', 'you', 'Log',
                                         timeout=self.TIMEOUT)
        self.assertEqual(h.toaddrs, ['you'])
        self.messages = []
        r = logging.makeLogRecord({'msg': 'Hello \u2713'})
        self.handled = threading.Event()
        h.handle(r)
        self.handled.wait(self.TIMEOUT)  # 14314: don't wait forever
        server.stop()
        self.assertTrue(self.handled.is_set())
        self.assertEqual(len(self.messages), 1)
        peer, mailfrom, rcpttos, data = self.messages[0]
        self.assertEqual(mailfrom, 'me')
        self.assertEqual(rcpttos, ['you'])
        self.assertIn('\nSubject: Log\n', data)
        self.assertTrue(data.endswith('\n\nHello \u2713'))
        h.close() 

def handle(self):
        '''
        Handle multiple requests - each expected to be a 4-byte length,
        followed by the LogRecord in pickle format.
        '''
        while 1:
            chunk = self.connection.recv(4)
            if len(chunk) < 4:
                break
            slen = struct.unpack('>L', chunk)[0]
            chunk = self.connection.recv(slen)
            while len(chunk) < slen:
                chunk = chunk + self.connection.recv(slen - len(chunk))
            obj = self.unPickle(chunk)
            record = logging.makeLogRecord(obj)
            self.handleLogRecord(record) 

def handle_stream(self, stream, address):
        unpacker = msgpack.Unpacker(raw=False)
        while True:
            try:
                wire_bytes = yield stream.read_bytes(1024, partial=True)
                if not wire_bytes:
                    break
                try:
                    unpacker.feed(wire_bytes)
                except msgpack.exceptions.BufferFull:
                    # Start over loosing some data?!
                    unpacker = msgpack.Unpacker(raw=False)
                    unpacker.feed(wire_bytes)
                for record_dict in unpacker:
                    record = logging.makeLogRecord(record_dict)
                    logger = logging.getLogger(record.name)
                    logger.handle(record)
            except (EOFError, KeyboardInterrupt, SystemExit, StreamClosedError):
                break
            except Exception as exc:  # pylint: disable=broad-except
                log.exception(exc) 

def write(self, data):
        data = str(data)
        if data == '\n':
            # when print(data) is invoked, it invokes write() twice. First,
            # writes the data, then writes a new line. This is to avoid
            # emitting log record with just a new-line character.
            return

        # creates https://docs.python.org/2/library/logging.html#logrecord-objects
        file_name, line_number = inspect.getouterframes(inspect.currentframe())[1][1:3]
        record = logging.makeLogRecord({"created": time.time(),
                                        "msg": data,
                                        "filename": os.path.basename(file_name),
                                        "lineno": line_number,
                                        "levelname": "DEBUG",
                                        "levelno": logging.DEBUG})
        self.emit(record) 

def test_error_handling(self):
        h = TestStreamHandler(BadStream())
        r = logging.makeLogRecord({})
        old_raise = logging.raiseExceptions

        try:
            h.handle(r)
            self.assertIs(h.error_record, r)

            h = logging.StreamHandler(BadStream())
            with support.captured_stderr() as stderr:
                h.handle(r)
                msg = '\nRuntimeError: deliberate mistake\n'
                self.assertIn(msg, stderr.getvalue())

            logging.raiseExceptions = False
            with support.captured_stderr() as stderr:
                h.handle(r)
                self.assertEqual('', stderr.getvalue())
        finally:
            logging.raiseExceptions = old_raise

# -- The following section could be moved into a server_helper.py module
# -- if it proves to be of wider utility than just test_logging 

def test_basic(self):
        sockmap = {}
        server = TestSMTPServer((support.HOST, 0), self.process_message, 0.001,
                                sockmap)
        server.start()
        addr = (support.HOST, server.port)
        h = logging.handlers.SMTPHandler(addr, 'me', 'you', 'Log',
                                         timeout=self.TIMEOUT)
        self.assertEqual(h.toaddrs, ['you'])
        self.messages = []
        r = logging.makeLogRecord({'msg': 'Hello \u2713'})
        self.handled = threading.Event()
        h.handle(r)
        self.handled.wait(self.TIMEOUT)  # 14314: don't wait forever
        server.stop()
        self.assertTrue(self.handled.is_set())
        self.assertEqual(len(self.messages), 1)
        peer, mailfrom, rcpttos, data = self.messages[0]
        self.assertEqual(mailfrom, 'me')
        self.assertEqual(rcpttos, ['you'])
        self.assertIn('\nSubject: Log\n', data)
        self.assertTrue(data.endswith('\n\nHello \u2713'))
        h.close() 

def handle_read(self):
        try:
            data = self.recv(self.dlen)
            if len(data) == 0:
                return
        except socket.error as e:
            if e[0] in (errno.EWOULDBLOCK, errno.EAGAIN):
                return

        self.data += data
        self.dlen -= len(data)
        if self.dlen > 0:
            # don't have complete record yet. wait for more data to read
            return

        if self.rlen == 0:
            self.dlen = self.rlen = struct.unpack('>L', self.data)[0]
            self.data = ''
            # got record length. now read record
            return

        # got complete record
        obj = pickle.loads(self.data)
        record = logging.makeLogRecord(obj)

        # Note: EVERY record gets logged. This is because Logger.handle
        # is normally called AFTER logger-level filtering.
        # Filter (e.g., only WARNING or higher)
        # at the sender to save network bandwidth.
        globalLogger.handle(record)

        # reset for next record
        self.data = ''
        self.rlen = 0
        self.dlen = 4 

def test_multiline_formatter_puts_direction_info_into_direction_area():
    """
    We want logs to look like:

    01 19:36:09.823 >|sent
    01 19:36:09.823 <|received
    01 19:36:09.823  |just log
    """
    from moler.config.loggers import MultilineWithDirectionFormatter

    formatter = MultilineWithDirectionFormatter(fmt="%(asctime)s.%(msecs)03d %(transfer_direction)s|%(message)s",
                                                datefmt="%d %H:%M:%S")
    tm_struct = time.strptime("2000-01-01 19:36:09", "%Y-%m-%d %H:%M:%S")
    epoch_tm = time.mktime(tm_struct)
    logging_time = epoch_tm

    log_rec = logging.makeLogRecord({'msg': "sent",
                                     'created': logging_time, 'msecs': 823,
                                     'transfer_direction': '>'})
    output = formatter.format(log_rec)
    assert output == "01 19:36:09.823 >|sent"

    log_rec = logging.makeLogRecord({'msg': "received",
                                     'created': logging_time, 'msecs': 823,
                                     'transfer_direction': '<'})
    output = formatter.format(log_rec)
    assert output == "01 19:36:09.823 <|received"

    log_rec = logging.makeLogRecord({'msg': "just log",
                                     'created': logging_time, 'msecs': 823})
    output = formatter.format(log_rec)
    assert output == "01 19:36:09.823  |just log" 

def test_logging_formatter(self):
        # unittest has its grubby mits all over logging, making it difficult
        # to test log output without using unittest.TestCase.assertLogs().
        # But assertLogs uses a hard-coded log format. So here we directly
        # construct logging.LogRecord()s for testing stdpopsim.cli.CLIFormatter.
        debug_str = "baz"
        debug_dict = dict(
                name="test_logger", pathname=__file__,
                levelno=logging.DEBUG, levelname=logging.getLevelName(logging.DEBUG),
                func=sys._getframe().f_code.co_name, lineno=sys._getframe().f_lineno,
                exc_info=None, sinfo=None, msg="%s", args=(debug_str,))
        info_str = "foo"
        info_dict = dict(
                name="test_logger", pathname=__file__,
                levelno=logging.INFO, levelname=logging.getLevelName(logging.INFO),
                func=sys._getframe().f_code.co_name, lineno=sys._getframe().f_lineno,
                exc_info=None, sinfo=None, msg="%s", args=(info_str,))
        warn_str = "bar"
        warn_dict = dict(
                name="py.warnings", pathname=__file__,
                levelno=logging.WARN, levelname=logging.getLevelName(logging.WARN),
                func=sys._getframe().f_code.co_name, lineno=sys._getframe().f_lineno,
                exc_info=None, sinfo=None, msg="%s",
                args=(f"{__file__}:564: UserWarning: {warn_str}\n  "
                      f"warnings.warn(\"{warn_str}\")\n",))
        warn_dict2 = dict(
                name="test_logger", pathname=__file__,
                levelno=logging.WARN, levelname=logging.getLevelName(logging.WARN),
                func=sys._getframe().f_code.co_name, lineno=sys._getframe().f_lineno,
                exc_info=None, sinfo=None, msg="%s",
                args=(warn_str,))

        fmt = cli.CLIFormatter()
        formatted_debug_str = fmt.format(logging.makeLogRecord(debug_dict))
        formatted_info_str = fmt.format(logging.makeLogRecord(info_dict))
        formatted_warn_str = fmt.format(logging.makeLogRecord(warn_dict))
        formatted_warn_str2 = fmt.format(logging.makeLogRecord(warn_dict2))
        self.assertEqual(formatted_debug_str, "DEBUG: " + debug_str)
        self.assertEqual(formatted_info_str, "INFO: " + info_str)
        self.assertEqual(formatted_warn_str, "WARNING: " + warn_str)
        self.assertEqual(formatted_warn_str2, warn_str) 

def test_emitReturnsLoggedMessageId(self):
        """
        MDKHandler.emit returns the LoggedMessageId from the Session.
        """
        mdk, tracer = create_mdk_with_faketracer()
        session = mdk.session()
        handler = MDKHandler(mdk, lambda: session)
        record = logging.makeLogRecord({"name": "", "levelname": "INFO",
                                        "message": "hello"})
        mid = handler.emit(record)
        self.assertIsInstance(mid, LoggedMessageId)
        self.assertEqual(mid.traceId, session._context.traceId) 

def test_emitReturnsLoggedMessageId(self):
        """
        MDKLoggingHandler.emit returns the LoggedMessageId.
        """
        mdk, tracer = create_mdk_with_faketracer()
        handler = MDKLoggingHandler(mdk)
        record = logging.makeLogRecord({"name": "", "levelname": "INFO",
                                        "message": "hello"})
        mid = handler.emit(record)
        self.assertIsInstance(mid, LoggedMessageId) 

def handle(self):
        """Handle multiple requests - each expected to be of 4-byte length,
        followed by the LogRecord in pickle format. Logs the record
        according to whatever policy is configured locally."""
        while True:
            chunk = self.connection.recv(4)
            if len(chunk) < 4:
                break
            slen = struct.unpack(">L", chunk)[0]
            chunk = self.connection.recv(slen)
            while len(chunk) < slen:
                chunk = chunk + self.connection.recv(slen - len(chunk))
            obj = self.unpickle(chunk)
            record = logging.makeLogRecord(obj)
            self.handle_log_record(record) 

def test_race(self):
        # Issue #14632 refers.
        def remove_loop(fname, tries):
            for _ in range(tries):
                try:
                    os.unlink(fname)
                except OSError:
                    pass
                time.sleep(0.004 * random.randint(0, 4))

        del_count = 500
        log_count = 500

        for delay in (False, True):
            fd, fn = tempfile.mkstemp('.log', 'test_logging-3-')
            os.close(fd)
            remover = threading.Thread(target=remove_loop, args=(fn, del_count))
            remover.daemon = True
            remover.start()
            h = logging.handlers.WatchedFileHandler(fn, delay=delay)
            f = logging.Formatter('%(asctime)s: %(levelname)s: %(message)s')
            h.setFormatter(f)
            try:
                for _ in range(log_count):
                    time.sleep(0.005)
                    r = logging.makeLogRecord({'msg': 'testing' })
                    h.handle(r)
            finally:
                remover.join()
                try:
                    h.close()
                except ValueError:
                    pass
                if os.path.exists(fn):
                    os.unlink(fn)


# Set the locale to the platform-dependent default.  I have no idea
# why the test does this, but in any case we save the current locale
# first and restore it at the end. 

def test_collect_configuration_run_summary_logs_run_configuration_error():
    flexmock(module.validate).should_receive('guard_configuration_contains_repository')
    flexmock(module).should_receive('run_configuration').and_return(
        [logging.makeLogRecord(dict(levelno=logging.CRITICAL, levelname='CRITICAL', msg='Error'))]
    )
    flexmock(module).should_receive('make_error_log_records').and_return([])
    arguments = {}

    logs = tuple(
        module.collect_configuration_run_summary_logs({'test.yaml': {}}, arguments=arguments)
    )

    assert {log.levelno for log in logs} == {logging.CRITICAL} 

def test_collect_configuration_run_summary_logs_run_umount_error():
    flexmock(module.validate).should_receive('guard_configuration_contains_repository')
    flexmock(module).should_receive('run_configuration').and_return([])
    flexmock(module.borg_umount).should_receive('unmount_archive').and_raise(OSError)
    flexmock(module).should_receive('make_error_log_records').and_return(
        [logging.makeLogRecord(dict(levelno=logging.CRITICAL, levelname='CRITICAL', msg='Error'))]
    )
    arguments = {'umount': flexmock(mount_point='/mnt')}

    logs = tuple(
        module.collect_configuration_run_summary_logs({'test.yaml': {}}, arguments=arguments)
    )

    assert {log.levelno for log in logs} == {logging.INFO, logging.CRITICAL} 

def load_configurations(config_filenames, overrides=None):
    '''
    Given a sequence of configuration filenames, load and validate each configuration file. Return
    the results as a tuple of: dict of configuration filename to corresponding parsed configuration,
    and sequence of logging.LogRecord instances containing any parse errors.
    '''
    # Dict mapping from config filename to corresponding parsed config dict.
    configs = collections.OrderedDict()
    logs = []

    # Parse and load each configuration file.
    for config_filename in config_filenames:
        try:
            configs[config_filename] = validate.parse_configuration(
                config_filename, validate.schema_filename(), overrides
            )
        except (ValueError, OSError, validate.Validation_error) as error:
            logs.extend(
                [
                    logging.makeLogRecord(
                        dict(
                            levelno=logging.CRITICAL,
                            levelname='CRITICAL',
                            msg='{}: Error parsing configuration file'.format(config_filename),
                        )
                    ),
                    logging.makeLogRecord(
                        dict(levelno=logging.CRITICAL, levelname='CRITICAL', msg=error)
                    ),
                ]
            )

    return (configs, logs) 

def log_record(suppress_log=False, **kwargs):
    '''
    Create a log record based on the given makeLogRecord() arguments, one of which must be
    named "levelno". Log the record (unless suppress log is set) and return it.
    '''
    record = logging.makeLogRecord(kwargs)
    if suppress_log:
        return record

    logger.handle(record)
    return record 

def handle(self):
        """Handle multiple requests - each expected to be of 4-byte length,
        followed by the LogRecord in pickle format. Logs the record
        according to whatever policy is configured locally."""
        while True:
            chunk = self.connection.recv(4)
            if len(chunk) < 4:
                break
            slen = struct.unpack(">L", chunk)[0]
            chunk = self.connection.recv(slen)
            while len(chunk) < slen:
                chunk = chunk + self.connection.recv(slen - len(chunk))
            obj = self.unpickle(chunk)
            record = logging.makeLogRecord(obj)
            self.handle_log_record(record) 

def test_race(self):
        # Issue #14632 refers.
        def remove_loop(fname, tries):
            for _ in range(tries):
                try:
                    os.unlink(fname)
                except OSError:
                    pass
                time.sleep(0.004 * random.randint(0, 4))

        del_count = 500
        log_count = 500

        for delay in (False, True):
            fd, fn = tempfile.mkstemp('.log', 'test_logging-3-')
            os.close(fd)
            remover = threading.Thread(target=remove_loop, args=(fn, del_count))
            remover.daemon = True
            remover.start()
            h = logging.handlers.WatchedFileHandler(fn, delay=delay)
            f = logging.Formatter('%(asctime)s: %(levelname)s: %(message)s')
            h.setFormatter(f)
            try:
                for _ in range(log_count):
                    time.sleep(0.005)
                    r = logging.makeLogRecord({'msg': 'testing' })
                    h.handle(r)
            finally:
                remover.join()
                try:
                    h.close()
                except ValueError:
                    pass
                if os.path.exists(fn):
                    os.unlink(fn)


# Set the locale to the platform-dependent default.  I have no idea
# why the test does this, but in any case we save the current locale
# first and restore it at the end.