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)