def setUp(self):
import vumi.sentry
self.client = DummySentryClient()
self.patch(vumi.sentry, 'vumi_raven_client', lambda dsn: self.client)
self.logger = LogPublisher()
self.service = SentryLoggerService("http://example.com/",
"test.logger",
"worker-1",
logger=self.logger)
def test_message(self, logger):
"""
A message logged to the given ``LogPublisher`` is converted to an
Eliot log message.
"""
publisher = LogPublisher()
observer = EliotObserver(publisher)
observer.logger = logger
publisher.addObserver(observer)
publisher.msg(b"Hello", b"world")
assertHasMessage(self, logger, TWISTED_LOG_MESSAGE,
dict(error=False, message=u"Hello world"))
def redirectToLogPublisher(self):
"""
Redirect Eliot logs to a Twisted log publisher.
@return: L{list} of L{str} - the written, formatted Twisted log
messages will eventually be added to it.
"""
written = []
publisher = LogPublisher()
publisher.addObserver(lambda m: written.append(textFromEventDict(m)))
destination = _RedirectLogsForTrial(FakeSys(["trial"], b""), publisher)()
self.addCleanup(removeDestination, destination)
return written
def redirectToLogPublisher(self):
"""
Redirect Eliot logs to a Twisted log publisher.
@return: L{list} of L{str} - the written, formatted Twisted log
messages will eventually be added to it.
"""
written = []
publisher = LogPublisher()
publisher.addObserver(lambda m: written.append(textFromEventDict(m)))
destination = _RedirectLogsForTrial(FakeSys(["trial"], b""),
publisher)()
self.addCleanup(removeDestination, destination)
return written
def test_error(self, logger):
"""
An error logged to the given ``LogPublisher`` is converted to an Eliot
log message.
"""
publisher = LogPublisher()
observer = EliotObserver(publisher)
observer.logger = logger
publisher.addObserver(observer)
# No public API for this unfortunately, so emulate error logging:
publisher.msg(failure=Failure(ZeroDivisionError("onoes")),
why=b"A zero division ono",
isError=True)
message = (u'A zero division ono\nTraceback (most recent call '
u'last):\nFailure: exceptions.ZeroDivisionError: onoes\n')
assertHasMessage(self, logger, TWISTED_LOG_MESSAGE,
dict(error=True, message=message))
def test_withoutTrialResult(self):
"""
When not running under I{trial} L{None} is returned.
"""
self.assertIs(
None,
_RedirectLogsForTrial(FakeSys(["myprogram.py"], b""),
LogPublisher())())
def setUp(self):
import vumi.sentry
self.client = DummySentryClient()
self.patch(vumi.sentry, 'vumi_raven_client', lambda dsn: self.client)
self.logger = LogPublisher()
self.service = SentryLoggerService("http://example.com/",
"test.logger",
"worker-1",
logger=self.logger)
def test_withoutTrialNoDestination(self):
"""
When C{sys.argv[0]} is not C{"trial"} no destination is added by
L{redirectLogsForTrial}.
"""
originalDestinations = Logger._destinations._destinations[:]
_RedirectLogsForTrial(FakeSys(["myprogram.py"], b""), LogPublisher())()
self.assertEqual(Logger._destinations._destinations,
originalDestinations)
def test_trialAsPathNoDestination(self):
"""
When C{sys.argv[0]} has C{"trial"} as directory name but not program
name no destination is added by L{redirectLogsForTrial}.
"""
originalDestinations = Logger._destinations._destinations[:]
_RedirectLogsForTrial(FakeSys(["./trial/myprogram.py"], b""),
LogPublisher())()
self.assertEqual(Logger._destinations._destinations,
originalDestinations)
class TestSentryLoggerSerivce(VumiTestCase):
def setUp(self):
import vumi.sentry
self.client = DummySentryClient()
self.patch(vumi.sentry, 'vumi_raven_client', lambda dsn: self.client)
self.logger = LogPublisher()
self.service = SentryLoggerService("http://example.com/",
"test.logger",
"worker-1",
logger=self.logger)
@inlineCallbacks
def test_logging(self):
yield self.service.startService()
self.logger.msg("Hello", logLevel=logging.WARN)
self.assertEqual(self.client.messages, [(("Hello", ), {
'data': {
'level': 30,
'logger': 'test.logger'
},
'tags': {
'worker-id': 'worker-1'
}
})])
del self.client.messages[:]
yield self.service.stopService()
self.logger.msg("Foo", logLevel=logging.WARN)
self.assertEqual(self.client.messages, [])
@inlineCallbacks
def test_stop_not_running(self):
yield self.service.stopService()
self.assertFalse(self.service.running)
@inlineCallbacks
def test_start_stop(self):
self.assertFalse(self.service.registered())
self.assertEqual(self.client.teardowns, 0)
yield self.service.startService()
self.assertTrue(self.service.registered())
yield self.service.stopService()
self.assertFalse(self.service.registered())
self.assertEqual(self.client.teardowns, 1)
def test_noDuplicateAddsResult(self):
"""
If a destination has already been added, calling L{redirectLogsForTrial}
a second time returns L{None}.
"""
redirect = _RedirectLogsForTrial(FakeSys(["trial"], b""),
LogPublisher())
destination = redirect()
self.addCleanup(removeDestination, destination)
result = redirect()
self.assertIs(result, None)
class TestSentryLoggerSerivce(VumiTestCase):
def setUp(self):
import vumi.sentry
self.client = DummySentryClient()
self.patch(vumi.sentry, 'vumi_raven_client', lambda dsn: self.client)
self.logger = LogPublisher()
self.service = SentryLoggerService("http://example.com/",
"test.logger",
"worker-1",
logger=self.logger)
@inlineCallbacks
def test_logging(self):
yield self.service.startService()
self.logger.msg("Hello", logLevel=logging.WARN)
self.assertEqual(self.client.messages, [
(("Hello",),
{'data': {'level': 30, 'logger': 'test.logger'},
'tags': {'worker-id': 'worker-1'}})
])
del self.client.messages[:]
yield self.service.stopService()
self.logger.msg("Foo", logLevel=logging.WARN)
self.assertEqual(self.client.messages, [])
@inlineCallbacks
def test_stop_not_running(self):
yield self.service.stopService()
self.assertFalse(self.service.running)
@inlineCallbacks
def test_start_stop(self):
self.assertFalse(self.service.registered())
self.assertEqual(self.client.teardowns, 0)
yield self.service.startService()
self.assertTrue(self.service.registered())
yield self.service.stopService()
self.assertFalse(self.service.registered())
self.assertEqual(self.client.teardowns, 1)
def test_noDuplicateAdds(self):
"""
If a destination has already been added, calling L{redirectLogsForTrial}
a second time does not add another destination.
"""
redirect = _RedirectLogsForTrial(FakeSys(["trial"], b""),
LogPublisher())
destination = redirect()
self.addCleanup(removeDestination, destination)
originalDestinations = Logger._destinations._destinations[:]
redirect()
self.assertEqual(Logger._destinations._destinations,
originalDestinations)
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 assertDestinationAdded(self, programPath):
"""
Assert that when running under the given program a new destination is
added by L{redirectLogsForTrial}.
@param programPath: A path to a program.
@type programPath: L{str}
"""
destination = _RedirectLogsForTrial(FakeSys([programPath], b""),
LogPublisher())()
# If this was not added as destination, removing it will raise an
# exception:
try:
removeDestination(destination)
except ValueError:
self.fail("Destination was not added.")
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())
def test_message(self, logger):
"""
A message logged to the given ``LogPublisher`` is converted to an
Eliot log message.
"""
publisher = LogPublisher()
observer = EliotObserver(publisher)
observer.logger = logger
publisher.addObserver(observer)
publisher.msg(b"Hello", b"world")
assertHasMessage(self, logger, TWISTED_LOG_MESSAGE,
dict(error=False, message=u"Hello world"))
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(),
)
def test_error(self, logger):
"""
An error logged to the given ``LogPublisher`` is converted to an Eliot
log message.
"""
publisher = LogPublisher()
observer = EliotObserver(publisher)
observer.logger = logger
publisher.addObserver(observer)
# No public API for this unfortunately, so emulate error logging:
publisher.msg(failure=Failure(ZeroDivisionError("onoes")),
why=b"A zero division ono",
isError=True)
message = (u'A zero division ono\nTraceback (most recent call '
u'last):\nFailure: exceptions.ZeroDivisionError: onoes\n')
assertHasMessage(self, logger, TWISTED_LOG_MESSAGE,
dict(error=True, message=message))
class TestOldLogPublisher(unittest.TestCase):
"""
L{OldLogPublisher} constructs old-style log events and then adds the
necessary new-style keys.
"""
def setUp(self):
"""
Create an L{OldLogPublisher} and a log observer to catch its output.
"""
self.events = []
self.old = OldLogPublisher(self.events.append, self.events.append)
def test_simple(self):
"""
Messages with a simple message are translated such that the readable
message remains the same.
"""
self.old.msg("Hello world.")
self.assertEquals(len(self.events), 1)
self.assertEquals(formatEvent(self.events[0]), "Hello world.")
self.assertEquals(self.events[0]['log_level'], LogLevel.info)
def test_errorSetsLevel(self):
"""
Setting the old-style 'isError' key will result in the emitted message
acquiring the 'isError' key.
"""
self.old.msg(isError=True)
self.assertEquals(len(self.events), 1)
self.assertEquals(self.events[0]['log_level'], LogLevel.critical)
def test_oldStyleLogLevel(self):
"""
Setting the old-style 'logLevel' key will result in the emitted message
acquiring the new-style 'log_level' key.
"""
self.old.msg(logLevel=py_logging.WARNING)
self.assertEquals(len(self.events), 1)
self.assertEquals(self.events[0]['log_level'], LogLevel.warn)
def setUp(self):
self.patch(junebug.logging_service, 'LogFile', DummyLogFile)
self.logger = LogPublisher()
self.logpath = self.mktemp()
self.service = JunebugLoggerService(
'worker-id', self.logpath, 1000000, 7, logger=self.logger)
class TestJunebugLoggerService(JunebugTestBase):
def setUp(self):
self.patch(junebug.logging_service, 'LogFile', DummyLogFile)
self.logger = LogPublisher()
self.logpath = self.mktemp()
self.service = JunebugLoggerService(
'worker-id', self.logpath, 1000000, 7, logger=self.logger)
def assert_log(self, log, expected):
'''Assert that a log matches what is expected.'''
log = json.loads(log)
timestamp = log.pop('timestamp')
self.assertTrue(isinstance(timestamp, float))
self.assertEqual(log, expected)
@inlineCallbacks
def test_logfile_parameters(self):
'''When the logfile is created, it should be created with the correct
parameters.'''
yield self.service.startService()
logfile = self.service.logfile
self.assertEqual(logfile.worker_id, 'worker-id')
self.assertEqual(logfile.path, self.logpath)
self.assertEqual(logfile.rotateLength, 1000000)
self.assertEqual(logfile.maxRotatedFiles, 7)
@inlineCallbacks
def test_logging(self):
'''The logging service should write logs to the logfile when the
service is running.'''
self.logger.msg("Hello")
self.assertFalse(hasattr(self.service, 'logfile'))
yield self.service.startService()
logfile = self.service.logfile
self.logger.msg("Hello", logLevel=logging.WARN, system='worker-id')
[log] = logfile.logs
self.assert_log(log, {
'level': logging.WARN,
'logger': 'worker-id',
'message': 'Hello',
})
yield self.service.stopService()
self.assertEqual(len(logfile.logs), 1)
self.logger.msg("Foo", logLevel=logging.WARN)
self.assertEqual(len(logfile.logs), 1)
@inlineCallbacks
def test_stop_not_running(self):
'''If stopService is called when the service is not running, there
should be no exceptions raised.'''
yield self.service.stopService()
self.assertFalse(self.service.running)
@inlineCallbacks
def test_start_stop(self):
'''Stopping the service after it has been started should result in
properly closing the logfile.'''
self.assertFalse(self.service.registered())
yield self.service.startService()
self.assertEqual(self.service.logfile.closed_count, 0)
self.assertTrue(self.service.registered())
yield self.service.stopService()
self.assertFalse(self.service.registered())
self.assertEqual(self.service.logfile.closed_count, 1)
def setUp(self):
"""
Create an L{OldLogPublisher} and a log observer to catch its output.
"""
self.events = []
self.old = OldLogPublisher(self.events.append, self.events.append)
def setup(module):
module.log = LogPublisher()
module.log.err = err
def __init__(self, location=("general",), transmit=False):
self.location = location
self.transmit = transmit
LogPublisher.__init__(self)
def msg(self, *message, **kw):
kw.setdefault("location", self.location)
kw.setdefault("transmit", self.transmit)
LogPublisher.msg(self, *message, **kw)
def msg(self, *message, **kwargs):
if message and message[0].startswith(
"Unhandled unsolicited response:"):
return
LogPublisher.msg(self, *message, **kwargs)
