The taste of Python

It is finally Friday! One more week has gone and looking back I can see that it was again spent mostly on exhausting code reviews. At least for me, it is a very time and energy consuming process. And what people are usually saying that it will be better. But I don't see any improvements. I am still leaving about 200 comments per 600-line PR. My colleagues are very smart and bright people having experience in different computer science areas from compilers to FPGA, from international consulting to quantum computers, but still, we are spending too much time on code reviews.

So, as the first step towards our goal of reducing the time between pull request submission and merging, we connected lint-review to our GitHub repo. This helped, but not as much as I hoped.

I was thinking about other things we could do differently to make our process better and faster. And what came to my mind was "a taste". After you tried Michelin restaurant you can not forget it. After you drove BMW sportscar you may still continue using you 13 y.o. Volkswagen, but you know that there is something more than that. I have no clue about the alcohol, but probably there is a difference between some rare wines and ones that you can buy in Tesco for 4 pounds per bottle.

So, I was poisoned by the taste of great code. Fortunately, I worked with some brilliant engineers and they taught me something about the good code. What is my definition of greatness?

1. The code should be exactly where you are expecting it to be.
2. It should be as simple as possible, but not less than it is required.
3. The authors are not trying to prove that they are smarter than the readers. They do not consider the code as a tool for self-expression but as a tool to make some job.
4. The code should be written in a way that you can not distinguish who wrote it exactly. Do you know how long does it take to become a Beefeater? 22 years of service in the army. After such a period you will probably act as a single person no matter what.

So, having that said, I have decided to start doing something differently. Because I do care. Because I want us to succeed as a team. And to be honest I want to evolve as a developer and architect as well, and not to point to the similar problems over and over again.

So, right now I am going to start a series of posts to show how good code can look like. And hopefully, it will help you to develop your mindset.

I think I will write a series of posts, reviewing different projects and emphasizing some important details.

And today we will start with a CPython standard library. I think it is the highest quality Python code you can ever find and in case of any doubts, I would recommend using it as an unconditional source of truth and arbiter.

Let's take a look at the logging adapters. Hopefully, you are already familiar with loggers, handlers and formatters. LoggerAdapter is a less well-known class. So, we are going to read the source and decide what is it doing exactly without reading PEPs and documentation.

Let's start!

So, the first thing is to find the sources. https://github.com/python/cpython/ to begin with. There are many folders on the top level.

$ ls
CODE_OF_CONDUCT.md LICENSE            Misc               PCbuild            README.rst         config.sub         m4
Doc                Lib                Modules            Parser             Tools              configure          pyconfig.h.in
Grammar            Mac                Objects            Programs           aclocal.m4         configure.ac       setup.py
Include            Makefile.pre.in    PC                 Python             config.guess       install-sh

So, where our code is? Probably in Lib or Modules, what do you think? ls Lib, ls Modules makes it clear. Eventually, we are navigating to the Lib/logging folder. Where are our adapters?

$ ls
__init__.py config.py   handlers.py

We are getting closer. Just a tiny comment before we will start reading the code. logging is a pretty old module, dated back to 2001:

commit 57102f861d506b6c2d2215d100dac9143574fa77
Author: Guido van Rossum <guido@python.org>
Date:   Wed Nov 13 16:15:58 2002 +0000

    Adding Vinay Sajip's logging package.

diff --git a/Lib/logging/__init__.py b/Lib/logging/__init__.py
new file mode 100644
index 0000000000..e0f2de5dd2
--- /dev/null
+++ b/Lib/logging/__init__.py
@@ -0,0 +1,1183 @@
+#! /usr/bin/env python
+#
+# Copyright 2001-2002 by Vinay Sajip. All Rights Reserved.

And because of this, the style could be a bit different from your expectations, but remember, that migration from Python 2 to 3 was already a pain, so, breaking compatibility with more modules probably was not a good idea.

Ok, back to our original topic. Let's imagine that someone told us that there is logging.LoggerAdapter class and we want to understand it better.

class LoggerAdapter(object):
    """  
    An adapter for loggers which makes it easier to specify contextual
    information in logging output.
    """

    def __init__(self, logger, extra):
        """  
        Initialize the adapter with a logger and a dict-like object which
        provides contextual information. This constructor signature allows
        easy stacking of LoggerAdapters, if so desired.

        You can effectively pass keyword arguments as shown in the
        following example:

        adapter = LoggerAdapter(someLogger, dict(p1=v1, p2="v2"))
        """
        self.logger = logger
        self.extra = extra

What can we see from here?

This is a pretty small class, it has two fields. It makes some code easier, but it is not expected to bring new functionality. Somehow, adapters could be nested.

def debug(self, msg, *args, **kwargs):
    """
    Delegate a debug call to the underlying logger.
    """
    self.log(DEBUG, msg, *args, **kwargs)

def info(self, msg, *args, **kwargs):
    ...

So, the adapter has the same set of methods as a usual logger. But we are not using inheritance. It is a very Pythonic decision. We are writing an adapter. So we want to implement the desired interface, but overwrite the behaviour. Duck typing is our friend here. If at some point the underlying implementation of self.logger will change, our Adapter will throw AttributeError exception, instead of falling to the original non-decorated implementation if we would choose inheritance.

Jumping to the next function:

def log(self, level, msg, *args, **kwargs):
    """
    Delegate a log call to the underlying logger, after adding
    contextual information from this adapter instance.
    """
    if self.isEnabledFor(level):
        msg, kwargs = self.process(msg, kwargs)
        self.logger.log(level, msg, *args, **kwargs)

So here we are just proxying everything to the underlying self.logger, but patching msg and kwargs.

def process(self, msg, kwargs):
    """
    Process the logging message and keyword arguments passed in to
    a logging call to insert contextual information. You can either
    manipulate the message itself, the keyword args or both. Return
    the message and kwargs modified (or not) to suit your needs.

    Normally, you'll only need to override this one method in a
    LoggerAdapter subclass for your specific needs.
    """
    kwargs["extra"] = self.extra
    return msg, kwargs

So, this is the core of the LoggerAdapter. See, how thoughtful is it. Even if we are not patching msg argument, we are still leaving the space for updating it to the classes derived from LoggerAdapter. Another interesting option here, and it is clear from the code, that even if kwargs had an extra parameter we are overriding it. I like the name of the argument also, kwargs. It is not a **kwargs, it is just a usual dictionary argument, but because of this name, I feel that it is OK that we are modifying it in-place.

Then there is a bunch of other methods, like:

def setLevel(self, level):
    """
    Set the specified level on the underlying logger.
    """
    self.logger.setLevel(level)

Again, could it be avoided by using inheritance? Yes, it could. But then we are losing control and LoggerAdapter is not an adapter anymore. Moreover, right now, LoggerAdapter is compatible with any logger with follows a protocol (has debug/info/warning and some other methods), it is not actually extending the logging.Logger method, it can use your own logger as an underlying logger. That also adds more value to this class.

This is it! We got everything we wanted to know just by reading the code less for 5 minutes. Let's try to use it!

>>> import sys
>>> import logging
>>> logging.basicConfig(
        stream=sys.stdout,
        format='%(asctime)s %(req_id)s %(message)s',
        level=logging.DEBUG)
>>> logging.info('Hello', extra={'req_id': '123123'})
2019-06-08 00:41:24,420 123123 Hello
>>> my_logger = logging.LoggerAdapter(
        logging.getLogger(), {'req_id': '123123'})
>>> my_logger.info('world!')
2019-06-08 00:42:28,724 123123 world!
>>> my_logger.info('world!', extra={'req_id': 999999})
2019-06-08 13:27:35,105 123123 world!

Was the code clear? Yes! Is it verbose? Yes, it is. But because of that, no one will really have any problems understanding or extending this class. Please, open the file and read the definition again: https://github.com/python/cpython/blob/master/Lib/logging/__init__.py#L1745

But again, the point here is not to write about one more Python class, it is much wider: please, take a look at the beautiful code. And we all know, that beautiful cannot be wrong.

So, please, read the good code. It is as important as reading books. It is all of the best practices applied in action. And even when there are no good examples around, because we are on the greenfield project, and even if some of our internal libraries are not even close like that, now you know what my expectations are. And I hope after my series of posts you will not be able to write in any style other than that.