Logging without oversharing

I recently ran into a situation where I wanted to log the details of a database connection to a python log file, however I really didn’t want to over-share the password used for the database login. While I was deciding how to do the logging part, I thought. “Gosh, I wonder if there is a way to write a unittest to make sure that I’m not sharing the password?”

It turns out there is a way to do this and I’ll provide the details in this post. If you are interested in looking at the code, it can be found here:

Gitlab public repository Mocking Me with Funcions

Setup

For this post, I have created two classes that will be tested. Those classes are located in the ‘DatabaseInterface.py’ file. These are just props for the testing. I haven’t taken the time to verify that they would connect to an database, just using them to demonstrate that I don’t have to get the database setup to test some aspects of the class.

`TestingLogEntries.py`

The test example is contained in TestingLogEntries.py This is a pretty typical python unttest example. Import that classes that will be tested, and define instance methods to perform each test.

Testing password is not logged

The first test defined MyTracingTestExample.test_MyDatabaseAwareClass will use the database connection class and verify that the password is not printed when the DBConnectionInfo class is represented as a string by the str or repr methods.

Testing logging context with connection

The next test define MyTracingTestExample.test_logging_context is defined with a @patch decorator. The @patch decorator indicates that if anything within the test function calls pyodbc.connect then replace that function with a mocked function that simply returns a MagicMock object. A reference to the MagicMock object used in this situation is supplied to the test function through an additional paraemter to the test method. For example:

    @patch("pyodbc.connect")
    def test_logging_context(self, Mock_Patch):

The first line above specifies what to patch. In this case, patch the pyodbc.connect function. There is an added parameter to the test function called Mock_Patch will be a reference to the object that is really returned by any call to pyodbc.connect. This enables me, without changing code under test, specify the data that will be returned. This is very helpful for testing database components of a system because you can do so without actually having a live connection to a database. But more on that in another test.

In the test MyTracingTestExample.test_logging_context I’m not going to this extent. I’m using the patch so that I do not have to setup the infrastructure for the specific database being tested. I want to verify that the the string representation of the connection logged does not contain a password. This is similar to the MyTracingTestExample.test_MyDatabaseAwareClass but looks at the logging system.

To examine the contents of the logs within a test, I need to use a unittest method called assertLogs. This function defines a context and anything that is logged within that context will be captured into a log object that can be tested for contents. For example:

        # create assertLogs context.  While the context is active, logs will be captured into lg.
        with self.assertLogs(level=logging.DEBUG) as lg:
            # every log within this context meeting the level criteria will be captured.
            obj = MyDatabaseAwareClass(self.ci)
            obj._get_odbc_connection()

In this example code, the variable lg will collect all traces that happen within the indented context. This should include a trace or two related to the database connection information. Once this context is closed, I can access the output attribute of lg to see if any log entries match my criteria.

        # if you know that a term appears in the logging stream, but not necessarily which log line.
        # check them all and if any are true.
        self.assertFalse(any([self.password in entry for entry in lg.output]))

In this example, any log entry has the password used for the database then fail the test.

Mocking a database result set

Finally in the test method MyTracingTestExample.test_result_set I use the decorator @patch('pyodbc.connect') to replace the result of the pyodbc.connect call with a MagicMock instance. Then I poke a mock result set into the MagicMock instance way down the call stack to the return value from the ‘fetchall’ function. I’ll admit that deriving this statement:

        Mock_Patch.return_value\
            .cursor.return_value\
            .__enter__.return_value\
            .fetchall.return_value \
            = mock_database_result_set

Took some work. Basically, I extrapolated it by looking at the Mock_patch.mock_calls attribute that I traced out:

        # to see the call stack that was executed by the pyodbc.connect patch
        logging.debug(Mock_Patch.mock_calls)

Here is the trace result:

 call().cursor(),
 call().cursor().__enter__(),
 call().cursor().__enter__().execute('select 1 as some_real_complex_sql'),
 call().cursor().__enter__().fetchall(),
 call().cursor().__exit__(None, None, None)]

And worked my way back through the entry call().cursor().__enter__().fetchall(). Where:

call() → .return_value
.cursor() → .cursor.return_value
.__enter__() → .__enter__.return_value
.fetchall() → fetchall.return_value

Summary

Using patch from unittest.mock and MagicMock I can now instrument Python classes that perform database connections. This enables me to test their functionality without actually having to connect to a live database at test time.

Reference