Python - assert sub-string of logger output regardless of how the message is constructed

Question

I have found many examples of how to assert something was logged, for example http://www.michaelpollmeier.com/python-mock-how-to-assert-a-substring-of-logger-output

However I don't know how to decouple the assertion from the specific way the message was constructed. The test only cares about specific ids being logged.

Test Code

mock_logger.warn.assert_called_with(
    all_match(
        contains_string('user-id'), 
        contains_string('team-id')
    )
)

Should work for both

Production Code 1 (logger assembles the message):

logger.warn(
    "Order for team %s and user %s could not be processed", 
    'team-id', 
    'user-id'
)

and

Production Code 2 (we assemble the message and include exception):

logger.warn(
    "Order for team {} and user {} could not be processed"
    .format('team-id', 'user-id'), 
    ex
)

This won't work as is but I'm thinking of either capturing the arguments or setting a custom log appender and making the assertions on the final messages.

Please ignore any typos / potential syntax errors as I haven't written the code in an IDE

lortimer · Accepted Answer · 2017-10-02 05:05:41Z

If you want your warn method to take multiple arguments and format the string itself, I don't think a matcher like all_match will work. Matchers only match a single argument.

You're passing all_match as the first argument to assert_called_with, so it can only match the first argument to the call to mock_logger.warn. That's why your test code will pass for Production Code 2 and not Production Code 1.

In Production Code 2, your first argument to warn is the string "Order for team team-id and user user-id could not be processed". The mock passes its first argument to all_match, so it will find what it's looking for.

In Production Code 1, your first argument to warn is "Order for team %s and user %s could not be processed". That's everything all_match knows about. The 2nd and 3rd arguments contain the strings you want all_match to find, but it doesn't have access to them.

Instead of passing a matcher to assert_called_with, manually checking the calls made to your mock would work for both cases. Here's an inelegant but readable implementation of what I mean:

mock_logger = unittest.Mock()
...
# Call production code
...
calls = mock_logger.warn.call_args_list # gets a list of calls made to the mock

first_call = calls[0] # each call object in call_args_list is a tuple containing 2 tuples: ((positional args), (keyword args)). Let's grab the first one.

arguments = first_call[0] # the positional arguments are the first tuple in the call

if len(arguments) == 1: # If warn got 1 argument, it's a string. Look for 'team-id' and 'user-id' in that argument
    self.assertIn('team-id', arguments[0])
    self.assertIn('user-id', arguments[0])
elif len(arguments) == 3: # if warn got 3 arguments, 'team-id' and 'user-id' should have been the 2nd and 3rd arguments.
    self.assertEqual("Order for team %s and user %s could not be processed", arguments[0])
    self.assertEqual('team-id', arguments[1])
    self.assertEqual('user-id', arguments[2])

If you really want to use a matcher, you'll have to always pass a single string to logger.warn, which means formatting the string before you call warn.

Collectives™ on Stack Overflow

Python - assert sub-string of logger output regardless of how the message is constructed

1 Answer 1

Comments

Your Answer

Hot Network Questions

Collectives™ on Stack Overflow

1 Answer 1

Comments

Your Answer

Sign up or log in

Post as a guest

Related