Python twisted.python.log.textFromEventDict() Examples

def test_logStderr(self):
        """
        When the _errFlag is set to L{StandardErrorBehavior.LOG},
        L{endpoints._WrapIProtocol} logs stderr (in childDataReceived).
        """
        d = self.ep.connect(self.factory)
        self.successResultOf(d)
        wpp = self.reactor.processProtocol
        log.addObserver(self._stdLog)
        self.addCleanup(log.removeObserver, self._stdLog)

        wpp.childDataReceived(2, b'stderr1')
        self.assertEqual(self.eventLog['executable'], wpp.executable)
        self.assertEqual(self.eventLog['data'], b'stderr1')
        self.assertEqual(self.eventLog['protocol'], wpp.protocol)
        self.assertIn(
            'wrote stderr unhandled by',
            log.textFromEventDict(self.eventLog)) 

def test_logErrorLogsErrorNoRepr(self):
        """
        The text logged by L{defer.logError} has no repr of the failure.
        """
        output = []

        def emit(eventDict):
            output.append(log.textFromEventDict(eventDict))

        log.addObserver(emit)

        error = failure.Failure(RuntimeError())
        defer.logError(error)
        self.flushLoggedErrors(RuntimeError)

        self.assertTrue(output[0].startswith("Unhandled Error\nTraceback ")) 

def test_errorLogNoRepr(self):
        """
        Verify that when a L{Deferred} with no references to it is fired,
        the logged message does not contain a repr of the failure object.
        """
        defer.Deferred().addCallback(lambda x: 1 // 0).callback(1)

        gc.collect()
        self._check()

        self.assertEqual(2, len(self.c))
        msg = log.textFromEventDict(self.c[-1])
        expected = "Unhandled Error\nTraceback "
        self.assertTrue(msg.startswith(expected),
                        "Expected message starting with: {0!r}".
                            format(expected)) 

def test_errorLogDebugInfo(self):
        """
        Verify that when a L{Deferred} with no references to it is fired,
        the logged message includes debug info if debugging on the deferred
        is enabled.
        """
        def doit():
            d = defer.Deferred()
            d.debug = True
            d.addCallback(lambda x: 1 // 0)
            d.callback(1)

        doit()
        gc.collect()
        self._check()

        self.assertEqual(2, len(self.c))
        msg = log.textFromEventDict(self.c[-1])
        expected = "(debug:  I"
        self.assertTrue(msg.startswith(expected),
                        "Expected message starting with: {0!r}".
                            format(expected)) 

def test_logErrorLogsErrorNoRepr(self):
        """
        The text logged by L{defer.logError} has no repr of the failure.
        """
        output = []

        def emit(eventDict):
            output.append(log.textFromEventDict(eventDict))

        log.addObserver(emit)

        error = failure.Failure(RuntimeError())
        defer.logError(error)
        self.flushLoggedErrors(RuntimeError)

        self.assertTrue(output[0].startswith("Unhandled Error\nTraceback ")) 

def test_errorLogNoRepr(self):
        """
        Verify that when a L{Deferred} with no references to it is fired,
        the logged message does not contain a repr of the failure object.
        """
        defer.Deferred().addCallback(lambda x: 1 // 0).callback(1)

        gc.collect()
        self._check()

        self.assertEqual(2, len(self.c))
        msg = log.textFromEventDict(self.c[-1])
        expected = "Unhandled Error\nTraceback "
        self.assertTrue(msg.startswith(expected),
                        "Expected message starting with: {0!r}".
                            format(expected)) 

def test_errorLogDebugInfo(self):
        """
        Verify that when a L{Deferred} with no references to it is fired,
        the logged message includes debug info if debugging on the deferred
        is enabled.
        """
        def doit():
            d = defer.Deferred()
            d.debug = True
            d.addCallback(lambda x: 1 // 0)
            d.callback(1)

        doit()
        gc.collect()
        self._check()

        self.assertEqual(2, len(self.c))
        msg = log.textFromEventDict(self.c[-1])
        expected = "(debug:  I"
        self.assertTrue(msg.startswith(expected),
                        "Expected message starting with: {0!r}".
                            format(expected)) 

def test_malformedHeaderCGI(self):
        """
        Check for the error message in the duplicated header
        """
        cgiFilename = self.writeCGI(BROKEN_HEADER_CGI)

        portnum = self.startServer(cgiFilename)
        url = "http://localhost:%d/cgi" % (portnum,)
        agent = client.Agent(reactor)
        d = agent.request(b"GET", url)
        d.addCallback(discardBody)
        loggedMessages = []

        def addMessage(eventDict):
            loggedMessages.append(log.textFromEventDict(eventDict))

        log.addObserver(addMessage)
        self.addCleanup(log.removeObserver, addMessage)

        def checkResponse(ignored):
            self.assertIn("ignoring malformed CGI header: 'XYZ'",
                          loggedMessages)

        d.addCallback(checkResponse)
        return d 

def test_logStderr(self):
        """
        When the _errFlag is set to L{StandardErrorBehavior.LOG},
        L{endpoints._WrapIProtocol} logs stderr (in childDataReceived).
        """
        d = self.ep.connect(self.factory)
        self.successResultOf(d)
        wpp = self.reactor.processProtocol
        log.addObserver(self._stdLog)
        self.addCleanup(log.removeObserver, self._stdLog)

        wpp.childDataReceived(2, b'stderr1')
        self.assertEqual(self.eventLog['executable'], wpp.executable)
        self.assertEqual(self.eventLog['data'], b'stderr1')
        self.assertEqual(self.eventLog['protocol'], wpp.protocol)
        self.assertIn(
            'wrote stderr unhandled by',
            log.textFromEventDict(self.eventLog)) 

def test_observed(self):
        """
        The observer is called exactly once.
        """
        publishToNewObserver(
            self.observer, self.legacyEvent(), legacyLog.textFromEventDict
        )
        self.assertEqual(len(self.events), 1) 

def test_time(self):
        """
        The old-style C{"time"} key is copied to the new-style C{"log_time"}
        key.
        """
        publishToNewObserver(
            self.observer, self.legacyEvent(), legacyLog.textFromEventDict
        )
        self.assertEqual(
            self.events[0]["log_time"], self.events[0]["time"]
        ) 

def test_message(self):
        """
        A published old-style event should format as text in the same way as
        the given C{textFromEventDict} callable would format it.
        """
        def textFromEventDict(event):
            return "".join(reversed(" ".join(event["message"])))

        event = self.legacyEvent("Hello,", "world!")
        text = textFromEventDict(event)

        publishToNewObserver(self.observer, event, textFromEventDict)
        self.assertEqual(formatEvent(self.events[0]), text) 

def test_formatAlreadySet(self):
        """
        Formatting is not altered if the old-style C{"format"} key already
        exists.
        """
        event = self.forwardAndVerify(
            dict(log_format="Hello!", format="Howdy!")
        )
        self.assertEqual(legacyLog.textFromEventDict(event), "Howdy!") 

def test_formatMessage(self):
        """
        Using the message key, which is special in old-style, works for
        new-style formatting.
        """
        event = self.forwardAndVerify(
            dict(log_format="Hello, {message}!", message="world")
        )
        self.assertEqual(
            legacyLog.textFromEventDict(event),
            "Hello, world!"
        ) 

def test_isError(self):
        """
        If C{"isError"} is set to C{1} (true) on the legacy event, the
        C{"log_level"} key should get set to L{LogLevel.critical}.
        """
        publishToNewObserver(
            self.observer,
            self.legacyEvent(isError=1),
            legacyLog.textFromEventDict
        )
        self.assertEqual(self.events[0]["log_level"], LogLevel.critical) 

def test_stdlibLogLevel(self):
        """
        If the old-style C{"logLevel"} key is set to a standard library logging
        level, using a predefined (L{int}) constant, the new-style
        C{"log_level"} key should get set to the corresponding log level.
        """
        publishToNewObserver(
            self.observer,
            self.legacyEvent(logLevel=py_logging.WARNING),
            legacyLog.textFromEventDict
        )
        self.assertEqual(self.events[0]["log_level"], LogLevel.warn) 

def emit(self, eventDict):
        """
        Send a message event to the I{syslog}.

        @param eventDict: The event to send.  If it has no C{'message'} key, it
            will be ignored.  Otherwise, if it has C{'syslogPriority'} and/or
            C{'syslogFacility'} keys, these will be used as the syslog priority
            and facility.  If it has no C{'syslogPriority'} key but a true
            value for the C{'isError'} key, the B{LOG_ALERT} priority will be
            used; if it has a false value for C{'isError'}, B{LOG_INFO} will be
            used.  If the C{'message'} key is multiline, each line will be sent
            to the syslog separately.
        """
        # Figure out what the message-text is.
        text = log.textFromEventDict(eventDict)
        if text is None:
            return

        # Figure out what syslog parameters we might need to use.
        priority = syslog.LOG_INFO
        facility = 0
        if eventDict['isError']:
            priority = syslog.LOG_ALERT
        if 'syslogPriority' in eventDict:
            priority = int(eventDict['syslogPriority'])
        if 'syslogFacility' in eventDict:
            facility = int(eventDict['syslogFacility'])

        # Break the message up into lines and send them.
        lines = text.split('\n')
        while lines[-1:] == ['']:
            lines.pop()

        firstLine = True
        for line in lines:
            if firstLine:
                firstLine = False
            else:
                line = '\t' + line
            self.syslog(priority | facility,
                        '[%s] %s' % (eventDict['system'], line)) 

def test_stdlibLogLevelWithGarbage(self):
        """
        If the old-style C{"logLevel"} key is set to a standard library logging
        level, using an unknown value, the new-style C{"log_level"} key should
        not get set.
        """
        publishToNewObserver(
            self.observer,
            self.legacyEvent(logLevel="Foo!!!!!"),
            legacyLog.textFromEventDict
        )
        self.assertNotIn("log_level", self.events[0]) 

def test_stdlibLogLevelWithString(self):
        """
        If the old-style C{"logLevel"} key is set to a standard library logging
        level, using a string value, the new-style C{"log_level"} key should
        get set to the corresponding log level.
        """
        publishToNewObserver(
            self.observer,
            self.legacyEvent(logLevel="WARNING"),
            legacyLog.textFromEventDict
        )
        self.assertEqual(self.events[0]["log_level"], LogLevel.warn) 

def test_malformedHeaderCGI(self):
        """
        Check for the error message in the duplicated header
        """
        cgiFilename = self.writeCGI(BROKEN_HEADER_CGI)

        portnum = self.startServer(cgiFilename)
        url = "http://localhost:%d/cgi" % (portnum,)
        url = url.encode("ascii")
        agent = client.Agent(reactor)
        d = agent.request(b"GET", url)
        d.addCallback(discardBody)
        loggedMessages = []

        def addMessage(eventDict):
            loggedMessages.append(log.textFromEventDict(eventDict))

        log.addObserver(addMessage)
        self.addCleanup(log.removeObserver, addMessage)

        def checkResponse(ignored):
            self.assertIn("ignoring malformed CGI header: " + repr(b'XYZ'),
                          loggedMessages)

        d.addCallback(checkResponse)
        return d 

def test_defaultNamespace(self):
        """
        Published event should have a namespace of C{"log_legacy"} to indicate
        that it was forwarded from legacy logging.
        """
        publishToNewObserver(
            self.observer, self.legacyEvent(), legacyLog.textFromEventDict
        )
        self.assertEqual(self.events[0]["log_namespace"], "log_legacy") 

def test_newPluginsOnReadOnlyPath(self):
        """
        Verify that a failure to write the dropin.cache file on a read-only
        path will not affect the list of plugins returned.

        Note: this test should pass on both Linux and Windows, but may not
        provide useful coverage on Windows due to the different meaning of
        "read-only directory".
        """
        self.unlockSystem()
        self.sysplug.child('newstuff.py').setContent(pluginFileContents('one'))
        self.lockSystem()

        # Take the developer path out, so that the system plugins are actually
        # examined.
        sys.path.remove(self.devPath.path)

        # Start observing log events to see the warning
        events = []
        addObserver(events.append)
        self.addCleanup(removeObserver, events.append)

        self.assertIn('one', self.getAllPlugins())

        # Make sure something was logged about the cache.
        expected = "Unable to write to plugin cache %s: error number %d" % (
            self.syscache.path, errno.EPERM)
        for event in events:
            if expected in textFromEventDict(event):
                break
        else:
            self.fail(
                "Did not observe unwriteable cache warning in log "
                "events: %r" % (events,)) 

def test_format(self):
        """
        The C{"format"} value, when specified, is used to format the message.
        """
        eventDict = dict(
            message=(), isError=0, format="Hello, %(foo)s!", foo="dude"
        )
        text = log.textFromEventDict(eventDict)
        self.assertEqual(text, "Hello, dude!") 

def test_noMessageNoFormat(self):
        """
        If C{"format"} is unspecified and C{"message"} is empty, return
        L{None}.
        """
        eventDict = dict(message=(), isError=0)
        text = log.textFromEventDict(eventDict)
        self.assertIsNone(text) 

def test_whySpecified(self):
        """
        The C{"why"} value, when specified, is first part of message.
        """
        try:
            raise RuntimeError()
        except:
            eventDict = dict(
                message=(), isError=1, failure=failure.Failure(), why="foo"
            )
            text = log.textFromEventDict(eventDict)
            self.assertTrue(text.startswith("foo\n")) 

def test_whyDefault(self):
        """
        The C{"why"} value, when unspecified, defaults to C{"Unhandled Error"}.
        """
        try:
            raise RuntimeError()
        except:
            eventDict = dict(message=(), isError=1, failure=failure.Failure())
            text = log.textFromEventDict(eventDict)
            self.assertTrue(text.startswith("Unhandled Error\n")) 

def test_noTracebackForYou(self):
        """
        If unable to obtain a traceback due to an exception, catch it and note
        the error.
        """
        # Invalid failure object doesn't implement .getTraceback()
        eventDict = dict(message=(), isError=1, failure=object())
        text = log.textFromEventDict(eventDict)
        self.assertIn("\n(unable to obtain traceback)", text) 

def test_connectionLostLogMsg(self):
        """
        When a connection is lost, an informative message should be logged
        (see L{getExpectedConnectionLostLogMsg}): an address identifying
        the port and the fact that it was closed.
        """

        loggedMessages = []
        def logConnectionLostMsg(eventDict):
            loggedMessages.append(log.textFromEventDict(eventDict))

        reactor = self.buildReactor()
        p = self.getListeningPort(reactor)
        expectedMessage = self.getExpectedConnectionLostLogMsg(p)
        log.addObserver(logConnectionLostMsg)

        def stopReactor(ignored):
            log.removeObserver(logConnectionLostMsg)
            reactor.stop()

        def doStopListening():
            log.addObserver(logConnectionLostMsg)
            maybeDeferred(p.stopListening).addCallback(stopReactor)

        reactor.callWhenRunning(doStopListening)
        reactor.run()

        self.assertIn(expectedMessage, loggedMessages) 

def emit(self, eventDict):
        """
        Send a message event to the I{syslog}.

        @param eventDict: The event to send.  If it has no C{'message'} key, it
            will be ignored.  Otherwise, if it has C{'syslogPriority'} and/or
            C{'syslogFacility'} keys, these will be used as the syslog priority
            and facility.  If it has no C{'syslogPriority'} key but a true
            value for the C{'isError'} key, the B{LOG_ALERT} priority will be
            used; if it has a false value for C{'isError'}, B{LOG_INFO} will be
            used.  If the C{'message'} key is multiline, each line will be sent
            to the syslog separately.
        """
        # Figure out what the message-text is.
        text = log.textFromEventDict(eventDict)
        if text is None:
            return

        # Figure out what syslog parameters we might need to use.
        priority = syslog.LOG_INFO
        facility = 0
        if eventDict['isError']:
            priority = syslog.LOG_ALERT
        if 'syslogPriority' in eventDict:
            priority = int(eventDict['syslogPriority'])
        if 'syslogFacility' in eventDict:
            facility = int(eventDict['syslogFacility'])

        # Break the message up into lines and send them.
        lines = text.split('\n')
        while lines[-1:] == ['']:
            lines.pop()

        firstLine = True
        for line in lines:
            if firstLine:
                firstLine = False
            else:
                line = '\t' + line
            self.syslog(priority | facility,
                        '[%s] %s' % (eventDict['system'], line)) 

def dump(self):
        """Return a string of events formatted with `textFromEventDict`.

        This returns a single string, where each log message is separated from
        the next by a line containing "---". Formatting is done by Twisted's
        *legacy* log machinery, which may or may not differ from the modern
        machinery.
        """
        return "\n---\n".join(
            log.textFromEventDict(event) for event in self.events
        )

    # For compatibility with fixtures.FakeLogger.