def __init__( self, observerPublisher=None, publishPublisher=None, logBeginner=None, warningsModule=warnings, ): if publishPublisher is None: publishPublisher = NewPublisher() if observerPublisher is None: observerPublisher = publishPublisher if observerPublisher is None: observerPublisher = NewPublisher() self._observerPublisher = observerPublisher self._publishPublisher = publishPublisher self._legacyObservers = [] if logBeginner is None: # This default behavior is really only used for testing. beginnerPublisher = NewPublisher() beginnerPublisher.addObserver(observerPublisher) logBeginner = LogBeginner(beginnerPublisher, cast(BinaryIO, NullFile()), sys, warnings) self._logBeginner = logBeginner self._warningsModule = warningsModule self._oldshowwarning = warningsModule.showwarning self.showwarning = self._logBeginner.showwarning
def test_startLoggingOverridesWarning(self): """ startLogging() overrides global C{warnings.showwarning} such that warnings go to Twisted log observers. """ self._startLoggingCleanup() newPublisher = NewLogPublisher() class SysModule: stdout = object() stderr = object() tempLogPublisher = LogPublisher( newPublisher, newPublisher, logBeginner=LogBeginner(newPublisher, StringIO(), SysModule, warnings), ) # Trial reports warnings in two ways. First, it intercepts the global # 'showwarning' function *itself*, after starting logging (by way of # the '_collectWarnings' function which collects all warnings as a # around the test's 'run' method). Second, it has a log observer which # immediately reports warnings when they're propagated into the log # system (which, in normal operation, happens only at the end of the # test case). In order to avoid printing a spurious warning in this # test, we first replace the global log publisher's 'showwarning' in # the module with our own. self.patch(log, "theLogPublisher", tempLogPublisher) # And, one last thing, pretend we're starting from a fresh import, or # warnings.warn won't be patched at all. log._oldshowwarning = None # Global mutable state is bad, kids. Stay in school. fakeFile = StringIO() # We didn't previously save log messages, so let's make sure we don't # save them any more. evt = {"pre-start": "event"} received = [] def preStartObserver(x): if "pre-start" in x.keys(): received.append(x) newPublisher(evt) newPublisher.addObserver(preStartObserver) log.startLogging(fakeFile, setStdout=False) self.addCleanup(tempLogPublisher._stopLogging) self.assertEqual(received, []) warnings.warn("hello!") output = fakeFile.getvalue() self.assertIn("UserWarning: hello!", output)
def test_startLoggingOverridesWarning(self): """ startLogging() overrides global C{warnings.showwarning} such that warnings go to Twisted log observers. """ self._startLoggingCleanup() newPublisher = NewLogPublisher() class SysModule(object): stdout = object() stderr = object() tempLogPublisher = LogPublisher( newPublisher, newPublisher, logBeginner=LogBeginner(newPublisher, StringIO(), SysModule, warnings) ) # Trial reports warnings in two ways. First, it intercepts the global # 'showwarning' function *itself*, after starting logging (by way of # the '_collectWarnings' function which collects all warnings as a # around the test's 'run' method). Second, it has a log observer which # immediately reports warnings when they're propagated into the log # system (which, in normal operation, happens only at the end of the # test case). In order to avoid printing a spurious warning in this # test, we first replace the global log publisher's 'showwarning' in # the module with our own. self.patch(log, "theLogPublisher", tempLogPublisher) # And, one last thing, pretend we're starting from a fresh import, or # warnings.warn won't be patched at all. log._oldshowwarning = None # Global mutable state is bad, kids. Stay in school. fakeFile = StringIO() # We didn't previously save log messages, so let's make sure we don't # save them any more. evt = {"pre-start": "event"} received = [] def preStartObserver(x): if 'pre-start' in x.keys(): received.append(x) newPublisher(evt) newPublisher.addObserver(preStartObserver) log.startLogging(fakeFile, setStdout=False) self.addCleanup(tempLogPublisher._stopLogging) self.assertEqual(received, []) warnings.warn("hello!") output = fakeFile.getvalue() self.assertIn("UserWarning: hello!", output)
def setUp(self) -> None: # Patch exit and kill so we can capture usage and prevent actual exits # and kills. self.exit = DummyExit() self.kill = DummyKill() self.patch(_runner, "exit", self.exit) self.patch(_runner, "kill", self.kill) # Patch getpid so we get a known result self.pid = 1337 self.pidFileContent = f"{self.pid}\n".encode("utf-8") # Patch globalLogBeginner so that we aren't trying to install multiple # global log observers. self.stdout = StringIO() self.stderr = StringIO() self.stdio = DummyStandardIO(self.stdout, self.stderr) self.warnings = DummyWarningsModule() self.globalLogPublisher = LogPublisher() self.globalLogBeginner = LogBeginner( self.globalLogPublisher, self.stdio.stderr, self.stdio, self.warnings, ) self.patch(_runner, "stderr", self.stderr) self.patch(_runner, "globalLogBeginner", self.globalLogBeginner)
def setUp(self): self._subprocess_timeout = 15 if platform.python_implementation() == 'PyPy': self._subprocess_timeout = 30 self.stderr = NativeStringIO() self.stdout = NativeStringIO() self.publisher = LogPublisher() self.beginner = LogBeginner(LogPublisher(), self.stderr, sys, warnings) self.patch(_logging, "_stderr", self.stderr) self.patch(_logging, "_stdout", self.stdout) self.patch(_logging, "log_publisher", self.publisher) self.patch(_logging, "globalLogBeginner", self.beginner) self.patch(_logging, "_loggers", WeakKeyDictionary()) self.patch(_logging, "_loglevel", "info")
def _get_stdlib_logger(self, name): fout = StringIO() handler = TwistedLoggerLogHandler() handler.publisher = LogPublisher( FileLogObserver(fout, formatForSystemd)) log = logging.getLogger(name) log.setLevel(logging.DEBUG) log.propagate = False log.addHandler(handler) return log, fout
def __init__(self, observerPublisher=None, publishPublisher=None, logBeginner=None, warningsModule=warnings): if publishPublisher is None: publishPublisher = NewPublisher() if observerPublisher is None: observerPublisher = publishPublisher if observerPublisher is None: observerPublisher = NewPublisher() self._observerPublisher = observerPublisher self._publishPublisher = publishPublisher self._legacyObservers = [] if logBeginner is None: # This default behavior is really only used for testing. beginnerPublisher = NewPublisher() beginnerPublisher.addObserver(observerPublisher) logBeginner = LogBeginner(beginnerPublisher, NullFile(), sys, warnings) self._logBeginner = logBeginner self._warningsModule = warningsModule self._oldshowwarning = warningsModule.showwarning self.showwarning = self._logBeginner.showwarning
def test_utf8(self): """ L{Logger} handles utf8 log strings and format args. """ observer = LogPublisher() observed = [] observer.addObserver(observed.append) sio = StringIO() observer.addObserver(textFileLogObserver(sio)) logger = Logger(observer=observer) index = 0 logger.info("t\xc3\xa9st") self.assertEqual(observed[index]["log_level"], LogLevel.info) self.assertEqual(observed[index]["log_format"], u"{msg}") self.assertEqual(observed[index]["msg"], u"t\xe9st") self.assertEqual(sio.getvalue().splitlines()[index].split("#info] ")[1], "t\xc3\xa9st") index += 1 logger.info("{str}", str="t\xc3\xa9st") self.assertEqual(observed[index]["log_level"], LogLevel.info) self.assertEqual(observed[index]["log_format"], u"{str}") self.assertEqual(observed[index]["str"], u"t\xe9st") self.assertEqual(sio.getvalue().splitlines()[index].split("#info] ")[1], "t\xc3\xa9st") index += 1 logger.info("T\xc3\xa9st {str}", str="t\xc3\xa9st") self.assertEqual(observed[index]["log_level"], LogLevel.info) self.assertEqual(observed[index]["log_format"], u"T\xe9st {str}") self.assertEqual(observed[index]["str"], u"t\xe9st") self.assertEqual(sio.getvalue().splitlines()[index].split("#info] ")[1], "T\xc3\xa9st t\xc3\xa9st")
def test_old_style(self): """ L{Logger} handles old style log strings. """ observer = LogPublisher() observed = [] observer.addObserver(observed.append) sio = StringIO() observer.addObserver(textFileLogObserver(sio)) logger = Logger(observer=observer) index = 0 logger.info("test") self.assertEqual(observed[index]["log_level"], LogLevel.info) self.assertEqual(observed[index]["log_format"], u"{msg}") self.assertEqual(observed[index]["msg"], u"test") self.assertEqual(sio.getvalue().splitlines()[index].split("#info] ")[1], "test") index += 1 logger.info("test {}") self.assertEqual(observed[index]["log_level"], LogLevel.info) self.assertEqual(observed[index]["log_format"], u"{msg}") self.assertEqual(observed[index]["msg"], u"test {}") self.assertEqual(sio.getvalue().splitlines()[index].split("#info] ")[1], "test {}") index += 1 logger.info("test {foo}") self.assertEqual(observed[index]["log_level"], LogLevel.info) self.assertEqual(observed[index]["log_format"], u"{msg}") self.assertEqual(observed[index]["msg"], u"test {foo}") self.assertEqual(sio.getvalue().splitlines()[index].split("#info] ")[1], "test {foo}")
def makeFilteredFileLogObserver(cls, stream, withTime=True): """ For a child process that has its stdout captured by the master process to be logged by the master, we strip out the time from the log entry since the master process will always add one. Setting C{withTime} to L{False} will ensure no time is generated. """ assert (cls.filterPublisher is None and cls.filterObserver is None), "Only call this once" timeFormat = formatTime if withTime else lambda _: u"" cls.filterObserver = FileLogObserver( stream, lambda event: formatEventAsClassicLogText(event, formatTime=timeFormat)) cls.filterPublisher = LogPublisher(cls.filterObserver) return cls.filterPublisher
def test_log_legacy(self): fout = StringIO() p = LegacyLogPublisher(publishPublisher=LogPublisher( FileLogObserver(fout, formatForSystemd))) p.msg("msg") p.msg("msg", system="system") p.msg("m\ns\ng", logLevel=logging.DEBUG) self.assertEqual( ("<6>[-] msg\n" "<6>[system] msg\n" "<7>[-] m\n" "<7> s\n" "<7> g\n"), fout.getvalue(), )
async def main(reactor, loops): """ Benchmark how long it takes to send `loops` messages. """ servers = [] def protocol(): p = LineCounter() servers.append(p) return p logger_factory = ServerFactory.forProtocol(protocol) logger_factory.wait_for = loops logger_factory.on_done = Deferred() port = reactor.listenTCP(0, logger_factory, interface="127.0.0.1") # A fake homeserver config. class Config: server_name = "synmark-" + str(loops) no_redirect_stdio = True hs_config = Config() # To be able to sleep. clock = Clock(reactor) errors = StringIO() publisher = LogPublisher() mock_sys = Mock() beginner = LogBeginner(publisher, errors, mock_sys, warnings, initialBufferSize=loops) log_config = { "version": 1, "loggers": { "synapse": { "level": "DEBUG", "handlers": ["tersejson"] } }, "formatters": { "tersejson": { "class": "synapse.logging.TerseJsonFormatter" } }, "handlers": { "tersejson": { "class": "synapse.logging.RemoteHandler", "host": "127.0.0.1", "port": port.getHost().port, "maximum_buffer": 100, "_reactor": reactor, } }, } logger = logging.getLogger("synapse.logging.test_terse_json") _setup_stdlib_logging( hs_config, log_config, logBeginner=beginner, ) # Wait for it to connect... for handler in logging.getLogger("synapse").handlers: if isinstance(handler, RemoteHandler): break else: raise RuntimeError("Improperly configured: no RemoteHandler found.") await handler._service.whenConnected() start = perf_counter() # Send a bunch of useful messages for i in range(0, loops): logger.info("test message %s", i) if len(handler._buffer) == handler.maximum_buffer: while len(handler._buffer) > handler.maximum_buffer / 2: await clock.sleep(0.01) await logger_factory.on_done end = perf_counter() - start handler.close() port.stopListening() return end
from json import JSONEncoder from functools import partial from zope.interface import provider from twisted.logger import ILogObserver, formatEvent, Logger, LogPublisher from twisted.logger import LogLevel, globalLogBeginner, formatTime from twisted.python.constants import NamedConstant from twisted.python.reflect import qual from weakref import WeakKeyDictionary log_publisher = LogPublisher() record_separator = u"\x1e" cb_logging_aware = u"CROSSBAR_RICH_LOGGING_ENABLE=True" _loggers = WeakKeyDictionary() _loglevel = "info" # Default is "info" def set_global_log_level(level): """ Set the global log level on all the loggers that have the level not explicitly set. """ for item in _loggers.keys(): if not item._log_level_explicitly_set:
def setup_structured_logging( hs, config, log_config: dict, logBeginner: LogBeginner, redirect_stdlib_logging: bool = True, ) -> LogPublisher: """ Set up Twisted's structured logging system. Args: hs: The homeserver to use. config (HomeserverConfig): The configuration of the Synapse homeserver. log_config (dict): The log configuration to use. """ if config.no_redirect_stdio: raise ConfigError( "no_redirect_stdio cannot be defined using structured logging.") logger = Logger() if "drains" not in log_config: raise ConfigError( "The logging configuration requires a list of drains.") observers = [] # type: List[ILogObserver] for observer in parse_drain_configs(log_config["drains"]): # Pipe drains if observer.type == DrainType.CONSOLE: logger.debug("Starting up the {name} console logger drain", name=observer.name) observers.append(SynapseFileLogObserver(observer.location)) elif observer.type == DrainType.CONSOLE_JSON: logger.debug("Starting up the {name} JSON console logger drain", name=observer.name) observers.append(jsonFileLogObserver(observer.location)) elif observer.type == DrainType.CONSOLE_JSON_TERSE: logger.debug( "Starting up the {name} terse JSON console logger drain", name=observer.name, ) observers.append( TerseJSONToConsoleLogObserver(observer.location, metadata={})) # File drains elif observer.type == DrainType.FILE: logger.debug("Starting up the {name} file logger drain", name=observer.name) log_file = open(observer.location, "at", buffering=1, encoding="utf8") observers.append(SynapseFileLogObserver(log_file)) elif observer.type == DrainType.FILE_JSON: logger.debug("Starting up the {name} JSON file logger drain", name=observer.name) log_file = open(observer.location, "at", buffering=1, encoding="utf8") observers.append(jsonFileLogObserver(log_file)) elif observer.type == DrainType.NETWORK_JSON_TERSE: metadata = {"server_name": hs.config.server_name} log_observer = TerseJSONToTCPLogObserver( hs=hs, host=observer.location[0], port=observer.location[1], metadata=metadata, maximum_buffer=observer.options.maximum_buffer, ) log_observer.start() observers.append(log_observer) else: # We should never get here, but, just in case, throw an error. raise ConfigError("%s drain type cannot be configured" % (observer.type, )) publisher = LogPublisher(*observers) log_filter = LogLevelFilterPredicate() for namespace, namespace_config in log_config.get("loggers", DEFAULT_LOGGERS).items(): # Set the log level for twisted.logger.Logger namespaces log_filter.setLogLevelForNamespace( namespace, stdlib_log_level_to_twisted(namespace_config.get("level", "INFO")), ) # Also set the log levels for the stdlib logger namespaces, to prevent # them getting to PythonStdlibToTwistedLogger and having to be formatted if "level" in namespace_config: logging.getLogger(namespace).setLevel( namespace_config.get("level")) f = FilteringLogObserver(publisher, [log_filter]) lco = LogContextObserver(f) if redirect_stdlib_logging: stuff_into_twisted = PythonStdlibToTwistedLogger(lco) stdliblogger = logging.getLogger() stdliblogger.addHandler(stuff_into_twisted) # Always redirect standard I/O, otherwise other logging outputs might miss # it. logBeginner.beginLoggingTo([lco], redirectStandardIO=True) return publisher
async def main(reactor, loops): """ Benchmark how long it takes to send `loops` messages. """ servers = [] def protocol(): p = LineCounter() servers.append(p) return p logger_factory = ServerFactory.forProtocol(protocol) logger_factory.wait_for = loops logger_factory.on_done = Deferred() port = reactor.listenTCP(0, logger_factory, interface="127.0.0.1") hs, wait, cleanup = await make_homeserver(reactor) errors = StringIO() publisher = LogPublisher() mock_sys = Mock() beginner = LogBeginner(publisher, errors, mock_sys, warnings, initialBufferSize=loops) log_config = { "loggers": { "synapse": { "level": "DEBUG" } }, "drains": { "tersejson": { "type": "network_json_terse", "host": "127.0.0.1", "port": port.getHost().port, "maximum_buffer": 100, } }, } logger = Logger(namespace="synapse.logging.test_terse_json", observer=publisher) logging_system = setup_structured_logging(hs, hs.config, log_config, logBeginner=beginner, redirect_stdlib_logging=False) # Wait for it to connect... await logging_system._observers[0]._service.whenConnected() start = perf_counter() # Send a bunch of useful messages for i in range(0, loops): logger.info("test message %s" % (i, )) if (len(logging_system._observers[0]._buffer) == logging_system._observers[0].maximum_buffer): while (len(logging_system._observers[0]._buffer) > logging_system._observers[0].maximum_buffer / 2): await wait(0.01) await logger_factory.on_done end = perf_counter() - start logging_system.stop() port.stopListening() cleanup() return end