Python logging.makeLogRecord() Examples

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_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 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 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_basic(self):
        logtype = 'Application'
        elh = win32evtlog.OpenEventLog(None, logtype)
        num_recs = win32evtlog.GetNumberOfEventLogRecords(elh)

        try:
            h = logging.handlers.NTEventLogHandler('test_logging')
        except pywintypes.error as e:
            if e.winerror == 5:  # access denied
                raise unittest.SkipTest('Insufficient privileges to run test')
            raise

        r = logging.makeLogRecord({'msg': 'Test Log Message'})
        h.handle(r)
        h.close()
        # Now see if the event is recorded
        self.assertLess(num_recs, win32evtlog.GetNumberOfEventLogRecords(elh))
        flags = win32evtlog.EVENTLOG_BACKWARDS_READ | \
                win32evtlog.EVENTLOG_SEQUENTIAL_READ
        found = False
        GO_BACK = 100
        events = win32evtlog.ReadEventLog(elh, flags, GO_BACK)
        for e in events:
            if e.SourceName != 'test_logging':
                continue
            msg = win32evtlogutil.SafeFormatMessage(e, logtype)
            if msg != 'Test Log Message\r\n':
                continue
            found = True
            break
        msg = 'Record not found in event log, went back %d records' % GO_BACK
        self.assertTrue(found, msg=msg)

# 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 _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_str_rep(self):
        r = logging.makeLogRecord({})
        s = str(r)
        self.assertTrue(s.startswith('<LogRecord: '))
        self.assertTrue(s.endswith('>')) 

def test_multiprocessing(self):
        r = logging.makeLogRecord({})
        self.assertEqual(r.processName, 'MainProcess')
        try:
            import multiprocessing as mp
            r = logging.makeLogRecord({})
            self.assertEqual(r.processName, mp.current_process().name)
        except ImportError:
            pass 

def prepare(record):
        prepared_record = None
        try:
            deserialized_record = json.loads(record, object_hook=util.decode)
            prepared_record = logging.makeLogRecord(deserialized_record)
        except Exception:
            # Swallow exceptions
            pass
        return prepared_record 

def get_record(self, name=None):
        result = dict(self.common)
        if name is not None:
            result.update(self.variants[name])
        return logging.makeLogRecord(result) 

def handle_datagram(self, request):
        slen = struct.pack('>L', 0) # length of prefix
        packet = request.packet[len(slen):]
        obj = pickle.loads(packet)
        record = logging.makeLogRecord(obj)
        self.log_output += record.msg + '\n'
        self.handled.set() 

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 setUp(self):
        self.records = [
            logging.makeLogRecord({'msg': 'one'}),
            logging.makeLogRecord({'msg': 'two'}),
        ] 

def test_rollover(self):
        fh = logging.handlers.TimedRotatingFileHandler(self.fn, 'S',
                                                       backupCount=1)
        fmt = logging.Formatter('%(asctime)s %(message)s')
        fh.setFormatter(fmt)
        r1 = logging.makeLogRecord({'msg': 'testing - initial'})
        fh.emit(r1)
        self.assertLogFile(self.fn)
        time.sleep(1.1)    # a little over a second ...
        r2 = logging.makeLogRecord({'msg': 'testing - after delay'})
        fh.emit(r2)
        fh.close()
        # At this point, we should have a recent rotated file which we
        # can test for the existence of. However, in practice, on some
        # machines which run really slowly, we don't know how far back
        # in time to go to look for the log file. So, we go back a fair
        # bit, and stop as soon as we see a rotated file. In theory this
        # could of course still fail, but the chances are lower.
        found = False
        now = datetime.datetime.now()
        GO_BACK = 5 * 60 # seconds
        for secs in range(GO_BACK):
            prev = now - datetime.timedelta(seconds=secs)
            fn = self.fn + prev.strftime(".%Y-%m-%d_%H-%M-%S")
            found = os.path.exists(fn)
            if found:
                self.rmfiles.append(fn)
                break
        msg = 'No rotated files found, went back %d seconds' % GO_BACK
        if not found:
            #print additional diagnostics
            dn, fn = os.path.split(self.fn)
            files = [f for f in os.listdir(dn) if f.startswith(fn)]
            print('Test time: %s' % now.strftime("%Y-%m-%d %H-%M-%S"), file=sys.stderr)
            print('The only matching files are: %s' % files, file=sys.stderr)
            for f in files:
                print('Contents of %s:' % f)
                path = os.path.join(dn, f)
                with open(path, 'r') as tf:
                    print(tf.read())
        self.assertTrue(found, msg=msg) 

def test_basic(self):
        logtype = 'Application'
        elh = win32evtlog.OpenEventLog(None, logtype)
        num_recs = win32evtlog.GetNumberOfEventLogRecords(elh)

        try:
            h = logging.handlers.NTEventLogHandler('test_logging')
        except pywintypes.error as e:
            if e.winerror == 5:  # access denied
                raise unittest.SkipTest('Insufficient privileges to run test')
            raise

        r = logging.makeLogRecord({'msg': 'Test Log Message'})
        h.handle(r)
        h.close()
        # Now see if the event is recorded
        self.assertLess(num_recs, win32evtlog.GetNumberOfEventLogRecords(elh))
        flags = win32evtlog.EVENTLOG_BACKWARDS_READ | \
                win32evtlog.EVENTLOG_SEQUENTIAL_READ
        found = False
        GO_BACK = 100
        events = win32evtlog.ReadEventLog(elh, flags, GO_BACK)
        for e in events:
            if e.SourceName != 'test_logging':
                continue
            msg = win32evtlogutil.SafeFormatMessage(e, logtype)
            if msg != 'Test Log Message\r\n':
                continue
            found = True
            break
        msg = 'Record not found in event log, went back %d records' % GO_BACK
        self.assertTrue(found, msg=msg)

# 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_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_format(self):
        file_handler = ExceptionCatchingFileHandler(os.devnull)
        file_handler.setFormatter(LogstashFormatter(ensure_ascii=False))
        file_handler.emit(makeLogRecord({"msg": u"тест"}))
        file_handler.close()

        self.assertIsNone(file_handler.exception) 

def handle(self):
        """
        Handle a single message. SocketServer takes care of splitting out the messages.
        
        Messages are JSON-encoded logging module records.
        """
        # Unpack the data from the request
        data, socket = self.request
        
        try:
            # Parse it as JSON
            message_attrs = json.loads(data.decode('utf-8'))
            # Fluff it up into a proper logging record
            record = logging.makeLogRecord(message_attrs)
            if isinstance(record.args, list):
                # Going through JSON turned tuples into lists. Lazy formatting
                # means this might have happened to all the arguments.  We need
                # to fix this at least for the root list of format string
                # arguments, or formatting will fail
                #
                # TODO: Protect the arguments better by actually pickling
                # instead of using JSON?
                #
                # TODO: Format the message on the sending side?
                record.args = tuple(record.args)
        except:
            # Complain someone is sending us bad logging data
            logging.error("Malformed log message from {}".format(self.client_address[0]))
        else:
            # Log level filtering should have been done on the remote end. The handle() method
            # skips it on this end.
            log.handle(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_delay(self):
        os.unlink(self.fn)
        fh = logging.FileHandler(self.fn, delay=True)
        self.assertIsNone(fh.stream)
        self.assertFalse(os.path.exists(self.fn))
        fh.handle(logging.makeLogRecord({}))
        self.assertIsNotNone(fh.stream)
        self.assertTrue(os.path.exists(self.fn))
        fh.close()