def test__calculate_formatter_buffer_with_multibyte_characters(self):
"""
Test that the formatter buffer calculates the correct difference in size between raw
messages and formatted messages when multibyte characters are involved.
"""
# This format string contains a three byte character
format_string = u'☃: %(name)s:%(levelname)s: %(message)s'
formatter = logging.Formatter(format_string)
handler = logs.CompliantSysLogHandler(
'/dev/log', facility=logs.CompliantSysLogHandler.LOG_DAEMON)
handler.setFormatter(formatter)
log_message = 'Here is a two-byte character: %s'
log_args = (u'ԃ', )
record = logging.LogRecord(name='pulp.test.module',
level=logging.INFO,
pathname='/some/path',
lineno=527,
msg=log_message,
args=log_args,
exc_info=None,
func='some_function')
formatter_buffer = handler._calculate_formatter_buffer(record)
# The log message should be "Here is a two-byte character: ԃ", which is 31 characters, but
# 32 bytes (since one is two bytes). The formatted message
# should be "☃: pulp.test.module:INFO: Here is a two-byte character: ԃ", which is 57
# characters, and 60 bytes. Thus, formatter_buffer should be 28. If it went only by
# number of characters, it would mistakenly return 26.
self.assertEqual(formatter_buffer, 28)
def test__calculate_formatter_buffer(self):
"""
Test that the formatter buffer calculates the correct difference in size between raw
messages and formatted messages.
"""
format_string = 'pulp: %(name)s:%(levelname)s: %(message)s'
formatter = logging.Formatter(format_string)
handler = logs.CompliantSysLogHandler(
'/dev/log', facility=logs.CompliantSysLogHandler.LOG_DAEMON)
handler.setFormatter(formatter)
log_message = 'Error, %s!'
log_args = ('World', )
record = logging.LogRecord(name='pulp.test.module',
level=logging.ERROR,
pathname='/some/path',
lineno=527,
msg=log_message,
args=log_args,
exc_info=None,
func='some_function')
formatter_buffer = handler._calculate_formatter_buffer(record)
# The log message should be "Error, World!", which is 13 bytes. The formatted message
# should be "pulp: pulp.test.module:ERROR: Error, World!", which is 43 bytes. Thus,
# formatter_buffer should be 30.
self.assertEqual(formatter_buffer, 30)
def test_emit_with_traceback_and_non_string_message(self, super_emit):
"""
Make sure emit() handles tracebacks appropriately.
"""
with mock.patch(
'pulp.server.logs.CompliantSysLogHandler._log_id') as _log_id:
_log_id.return_value = "PID-"
format_string = 'pulp: %(name)s:%(levelname)s: %(message)s'
formatter = logging.Formatter(format_string)
handler = logs.CompliantSysLogHandler(
'/dev/log', facility=logs.CompliantSysLogHandler.LOG_DAEMON)
handler.setFormatter(formatter)
try:
raise Exception('This is terrible.')
except Exception:
exc_info = sys.exc_info()
# Sadly, all over our code we log non-string objects. This is bad, but we don't have
# time to fix it right now, so we need to make sure our emitter handles this case.
log_message = 42
log_args = tuple()
record = logging.LogRecord(name='pulp.test.module',
level=logging.ERROR,
pathname='/some/path',
lineno=527,
msg=log_message,
args=log_args,
exc_info=exc_info,
func='some_function')
handler.emit(record)
# 5 records should be emitted. One for the message, and the traceback is 4 lines.
self.assertEqual(super_emit.call_count, 5)
# Let's make sure each new record has the right non-message attributes
for mock_call in super_emit.mock_calls:
new_record = mock_call[1][1]
self.assertEqual(new_record.name, 'pulp.test.module')
self.assertEqual(new_record.levelno, logging.ERROR)
self.assertEqual(new_record.pathname, '/some/path')
self.assertEqual(new_record.lineno, 527)
self.assertEqual(new_record.args, tuple())
self.assertEqual(new_record.exc_info, None)
self.assertEqual(new_record.funcName, 'some_function')
# Let's make sure the split around the newline happened correctly.
strio = StringIO()
traceback.print_exception(exc_info[0], exc_info[1], exc_info[2],
None, strio)
strio.seek(0)
traceback_lines = strio.read().split('\n')
# The last element of traceback lines is an empty string that won't be printed, so let's
# pop it off
traceback_lines.pop()
expected_messages = ['42']
expected_messages.extend(traceback_lines)
expected_messages = ["PID-" + msg for msg in expected_messages]
messages = [
mock_call[1][1].msg for mock_call in super_emit.mock_calls
]
self.assertEqual(messages, expected_messages)
def test_emit_prepends_pid_if_too_long(self, super_emit):
"""Test emit() with a message that is longer than the maximum allowable length."""
with mock.patch(
'pulp.server.logs.CompliantSysLogHandler._log_id') as _log_id:
_log_id.return_value = "PID-TID-"
format_string = 'pulp: %(name)s:%(levelname)s: %(message)s'
formatter = logging.Formatter(format_string)
handler = logs.CompliantSysLogHandler(
'/dev/log', facility=logs.CompliantSysLogHandler.LOG_DAEMON)
handler.setFormatter(formatter)
log_message = 'This %(message)s is too long for a single line.'
log_args = ({'message': 'message'}, )
record = logging.LogRecord(name='pulp.test.module',
level=logging.INFO,
pathname='/some/path',
lineno=527,
msg=log_message,
args=log_args,
exc_info=None,
func='some_function')
handler.emit(record)
messages = [
mock_call[1][1].msg for mock_call in super_emit.mock_calls
]
expected_messages = [
'PID-TID-This message is too long ',
'PID-TID-for a single line.'
]
self.assertEqual(expected_messages, messages)
def test_emit_does_not_prepend_pid_twice(self, super_emit):
"""
Make sure that if there are newline characers and the message is too long
the msg_id is not prepended twice.
"""
with mock.patch(
'pulp.server.logs.CompliantSysLogHandler._log_id') as _log_id:
_log_id.return_value = "PID-"
format_string = 'pulp: %(name)s:%(levelname)s: %(message)s'
formatter = logging.Formatter(format_string)
handler = logs.CompliantSysLogHandler(
'/dev/log', facility=logs.CompliantSysLogHandler.LOG_DAEMON)
handler.setFormatter(formatter)
log_message = 'This %(message)s has a \nnewline and is too long.'
log_args = ({'message': 'message'}, )
record = logging.LogRecord(name='pulp.test.module',
level=logging.INFO,
pathname='/some/path',
lineno=527,
msg=log_message,
args=log_args,
exc_info=None,
func='some_function')
handler.emit(record)
messages = [
mock_call[1][1].msg for mock_call in super_emit.mock_calls
]
expected_messages = [
'PID-This message has a ', 'PID-newline and is too l',
'PID-ong.'
]
self.assertEqual(expected_messages, messages)
def test_emit_with_compliant_message(self, super_emit):
"""
Test emit() with an already compliant message.
"""
format_string = 'pulp: %(name)s:%(levelname)s: %(message)s'
formatter = logging.Formatter(format_string)
handler = logs.CompliantSysLogHandler(
'/dev/log', facility=logs.CompliantSysLogHandler.LOG_DAEMON)
handler.setFormatter(formatter)
log_message = 'This %(message)s is just fine.'
log_args = ({'message': 'message'}, )
record = logging.LogRecord(name='pulp.test.module',
level=logging.INFO,
pathname='/some/path',
lineno=527,
msg=log_message,
args=log_args,
exc_info=None,
func='some_function')
handler.emit(record)
self.assertEqual(super_emit.call_count, 1)
new_record = super_emit.mock_calls[0][1][1]
self.assertEqual(new_record.name, 'pulp.test.module')
self.assertEqual(new_record.levelno, logging.INFO)
self.assertEqual(new_record.pathname, '/some/path')
self.assertEqual(new_record.lineno, 527)
# Note that the new record has already performed the string substitution, so msg is
# complete and args is now the empty tuple.
self.assertEqual(new_record.msg, 'This message is just fine.')
self.assertEqual(new_record.args, tuple())
self.assertEqual(new_record.exc_info, None)
self.assertEqual(new_record.funcName, 'some_function')
def log_message(q, num):
"""
Log a message in two parts. Wait between so that other threads have
a chance to get started this thread is finished.
"""
wait = 0.001
format_string = 'pulp: %(name)s:%(levelname)s: %(message)s'
formatter = logging.Formatter(format_string)
handler = logs.CompliantSysLogHandler('/dev/log',
facility=logs.CompliantSysLogHandler.LOG_DAEMON)
handler.setFormatter(formatter)
# Create and emit the first message of a thread
log_message = '%(number)s this message is too long.'
log_args = ({'number': str(num)},)
record = logging.LogRecord(
name='pulp.test.module', level=logging.INFO, pathname='/some/path', lineno=527,
msg=log_message, args=log_args, exc_info=None, func='some_function')
q.put(handler.emit(record))
# Wait to ensure that this thread doesn't finish before the other
# theads can be created.
time.sleep(wait)
# Log a second message using the same thread
log_message = '%(number)s This is the same thread.'
log_args = ({'number': str(num)},)
record = logging.LogRecord(
name='pulp.test.module', level=logging.INFO, pathname='/some/path', lineno=527,
msg=log_message, args=log_args, exc_info=None, func='some_function')
q.put(handler.emit(record))
def test_emit_with_long_lines_and_newlines(self, super_emit):
"""
Test emit() with a message that contains long lines and newlines.
"""
# This format string will add 29 characters to each message, which will push our message
# over the limit by one character.
with mock.patch(
'pulp.server.logs.CompliantSysLogHandler._log_id') as _log_id:
_log_id.return_value = "PID-"
format_string = 'pulp: %(name)s:%(levelname)s: %(message)s'
formatter = logging.Formatter(format_string)
handler = logs.CompliantSysLogHandler(
'/dev/log', facility=logs.CompliantSysLogHandler.LOG_DAEMON)
handler.setFormatter(formatter)
# This message is 26 bytes before the newline, which will exceed the allowed length by
# one byte when combined with our format string. The newline will cause another split
# after the period. This message will have to be split into three messages.
log_message = 'This %(message)s is very long.\nAnd it has a newline.'
log_args = ({'message': 'message'}, )
record = logging.LogRecord(name='pulp.test.module',
level=logging.INFO,
pathname='/some/path',
lineno=527,
msg=log_message,
args=log_args,
exc_info=None,
func='some_function')
handler.emit(record)
self.assertEqual(super_emit.call_count, 3)
# Let's make sure each new record has the right non-message attributes
for mock_call in super_emit.mock_calls:
new_record = mock_call[1][1]
self.assertEqual(new_record.name, 'pulp.test.module')
self.assertEqual(new_record.levelno, logging.INFO)
self.assertEqual(new_record.pathname, '/some/path')
self.assertEqual(new_record.lineno, 527)
self.assertEqual(new_record.args, tuple())
self.assertEqual(new_record.exc_info, None)
self.assertEqual(new_record.funcName, 'some_function')
# Now let's make sure the messages were split correctly. They will not be formatted yet,
# but the first should have left exactly enough room for formatting, and the newline
# should have caused a third message.
expected_messages = [
'PID-This message is very long', 'PID-.',
'PID-And it has a newline.'
]
messages = [
mock_call[1][1].msg for mock_call in super_emit.mock_calls
]
self.assertEqual(messages, expected_messages)
def test_emit_with_traceback(self, super_emit):
"""
Make sure emit() handles tracebacks appropriately.
"""
format_string = 'pulp: %(name)s:%(levelname)s: %(message)s'
formatter = logging.Formatter(format_string)
handler = logs.CompliantSysLogHandler(
'/dev/log', facility=logs.CompliantSysLogHandler.LOG_DAEMON)
handler.setFormatter(formatter)
try:
raise Exception('This is terrible.')
except:
exc_info = sys.exc_info()
log_message = 'Uh oh.'
log_args = tuple()
record = logging.LogRecord(name='pulp.test.module',
level=logging.ERROR,
pathname='/some/path',
lineno=527,
msg=log_message,
args=log_args,
exc_info=exc_info,
func='some_function')
handler.emit(record)
# 5 records should be emitted. One for the message, and the traceback is 4 lines.
self.assertEqual(super_emit.call_count, 5)
# Let's make sure each new record has the right non-message attributes
for mock_call in super_emit.mock_calls:
new_record = mock_call[1][1]
self.assertEqual(new_record.name, 'pulp.test.module')
self.assertEqual(new_record.levelno, logging.ERROR)
self.assertEqual(new_record.pathname, '/some/path')
self.assertEqual(new_record.lineno, 527)
self.assertEqual(new_record.args, tuple())
self.assertEqual(new_record.exc_info, None)
self.assertEqual(new_record.funcName, 'some_function')
# Let's make sure the split around the newline happened correctly.
strio = StringIO()
traceback.print_exception(exc_info[0], exc_info[1], exc_info[2], None,
strio)
strio.seek(0)
traceback_lines = strio.read().split('\n')
# The last element of traceback lines is an empty string that won't be printed, so let's
# pop it off
traceback_lines.pop()
expected_messages = ['Uh oh.']
expected_messages.extend(traceback_lines)
messages = [mock_call[1][1].msg for mock_call in super_emit.mock_calls]
self.assertEqual(messages, expected_messages)
def test_emit_does_not_prepend_pid_if_short_line_without_newlines(self, super_emit):
"""Test that message id is not prepended if the message is already within guidlines."""
format_string = 'pulp: %(name)s:%(levelname)s: %(message)s'
formatter = logging.Formatter(format_string)
handler = logs.CompliantSysLogHandler('/dev/log',
facility=logs.CompliantSysLogHandler.LOG_DAEMON)
handler.setFormatter(formatter)
log_message = 'This %(message)s is short and has no newline.'
log_args = ({'message': 'message'},)
record = logging.LogRecord(
name='pulp.test.module', level=logging.INFO, pathname='/some/path', lineno=527,
msg=log_message, args=log_args, exc_info=None, func='some_function')
handler.emit(record)
messages = [mock_call[1][1].msg for mock_call in super_emit.mock_calls]
expected_messages = ['This message is short and has no newline.']
self.assertEqual(expected_messages, messages)
def test_emit_with_newlines(self, super_emit):
"""
Test emit() with a message that contains newlines.
"""
with mock.patch(
'pulp.server.logs.CompliantSysLogHandler._log_id') as _log_id:
_log_id.return_value = "PID-"
format_string = 'pulp: %(name)s:%(levelname)s: %(message)s'
formatter = logging.Formatter(format_string)
handler = logs.CompliantSysLogHandler(
'/dev/log', facility=logs.CompliantSysLogHandler.LOG_DAEMON)
handler.setFormatter(formatter)
# This message is not too long, but the newline should cause a split.
log_message = 'This %(newline)s should be OK.'
log_args = ({'newline': '\n'}, )
record = logging.LogRecord(name='pulp.test.module',
level=logging.INFO,
pathname='/some/path',
lineno=527,
msg=log_message,
args=log_args,
exc_info=None,
func='some_function')
handler.emit(record)
self.assertEqual(super_emit.call_count, 2)
# Let's make sure each new record has the right non-message attributes
for mock_call in super_emit.mock_calls:
new_record = mock_call[1][1]
self.assertEqual(new_record.name, 'pulp.test.module')
self.assertEqual(new_record.levelno, logging.INFO)
self.assertEqual(new_record.pathname, '/some/path')
self.assertEqual(new_record.lineno, 527)
self.assertEqual(new_record.args, tuple())
self.assertEqual(new_record.exc_info, None)
self.assertEqual(new_record.funcName, 'some_function')
# Let's make sure the split around the newline happened correctly.
expected_messages = ['PID-This ', 'PID- should be OK.']
messages = [
mock_call[1][1].msg for mock_call in super_emit.mock_calls
]
self.assertEqual(messages, expected_messages)
def test_emit_with_long_lines(self, super_emit):
"""
Test emit() with a message that contains long lines. Make sure the formatter is accounted
for in the long line lengths by setting the MAX_MSG_LENGTH to 54, which is exactly one byte
too short to accomodate for the length of the message given the format string.
"""
# This format string will add 29 characters to each message, which will push our message
# over the limit by one character.
format_string = 'pulp: %(name)s:%(levelname)s: %(message)s'
formatter = logging.Formatter(format_string)
handler = logs.CompliantSysLogHandler(
'/dev/log', facility=logs.CompliantSysLogHandler.LOG_DAEMON)
handler.setFormatter(formatter)
# This message is 26 bytes, which will exceed the allowed length by one byte when combined
# with our format string. It will have to be split into two messages.
log_message = 'This %(message)s is very long.'
log_args = ({'message': 'message'}, )
record = logging.LogRecord(name='pulp.test.module',
level=logging.INFO,
pathname='/some/path',
lineno=527,
msg=log_message,
args=log_args,
exc_info=None,
func='some_function')
handler.emit(record)
self.assertEqual(super_emit.call_count, 2)
# Let's make sure each new record has the right non-message attributes
for mock_call in super_emit.mock_calls:
new_record = mock_call[1][1]
self.assertEqual(new_record.name, 'pulp.test.module')
self.assertEqual(new_record.levelno, logging.INFO)
self.assertEqual(new_record.pathname, '/some/path')
self.assertEqual(new_record.lineno, 527)
self.assertEqual(new_record.args, tuple())
self.assertEqual(new_record.exc_info, None)
self.assertEqual(new_record.funcName, 'some_function')
# Now let's make sure the messages were split correctly. They will not be formatted yet,
# but they should have left exactly enough room for formatting.
expected_messages = ['This message is very long', '.']
messages = [mock_call[1][1].msg for mock_call in super_emit.mock_calls]
self.assertEqual(messages, expected_messages)
