DEV Community: Panprices Engineering

The best python logging setup

Julius Colliander Celik — Tue, 23 Nov 2021 14:43:55 +0000

We have an opinionated configuration for logging at Panprices. In our context, it feels like the best logging solution ever, and I couldn't be prouder of our team, who worked hard on figuring out all minor details!

We want the logs to be structured so that we can easily search and analyze them in GCP. Locally the logs should be human-readable, and exceptions should be easy to parse.

Structlog

To start, we decided to use structlog, which is a fantastic logging tool. With that, our logs can be JSON-formatted on our servers but look beautiful in our terminals when working locally.

My favorite feature with structlog is how you can append any data as key-value pairs, and it won't just clutter up your terminal as structlog highlights your primary message.

Why does this matter?

Sometimes we get bugs that are very difficult to debug, and we wish we had more information. We have solved this in some of our services by logging as much information as possible in large blobs. That manifests as large non-prettified JSON blobs that GCP treats as strings.

When not using a proper structured logger, it's a tradeoff between debugging in the dark and information overload. When we use structlog, we can have fewer but richer log statements that contain explorable JSON payloads. We can look for just the information we need.

I love it! How do I use it?

As with any powerful tool, you can configure structlog to infinity. Even though the documentation is vast, it can be challenging to figure out some details. We got stuck on some pitfalls, so here is how our configuration works.

Setup

We want to configure structlog at startup, and we do that by calling a function at startup.

# src/helpers/structlog

import structlog
from structlog.dev import set_exc_info, ConsoleRenderer
from structlog.processors import StackInfoRenderer, TimeStamper, add_log_level

def config_structlog():
    structlog.configure_once(
        processors=[
            add_log_level,
            StackInfoRenderer(),
            set_exc_info,
            TimeStamper(fmt="%Y-%m-%d %H:%M.%S", utc=False),
            ConsoleRenderer(),
        ]
    )

In our main.py, we use this helper function like this:

from src.helpers.structlog import config_structlog
import structlog

config_structlog

def hello_world(_request):
    logger = structlog.get_logger()
    logger.msg('hello world')

    return "", 200

This is pretty, but where is my JSON?

This config will always print out the logs in a human-readable format. But on the server, we want it in plain JSON so that GCP can parse it. To solve this, we use an environment variable (ENVIRONMENT) that can be set to local or production.

If ENVIRONMENT is set to production, we will use a JSON renderer instead of the ConsoleRenderer. We also don't care about timestamps as GCP adds timestamps regardless.

The last thing we need to add is GCP severity and message. You can skip this if you don't use GCP. Structlog will print out what type of log it is ('debug', 'info', 'warn', 'error', etc.) under level while GCP expects it to be uppercase and under severity. Another default behaviour is that GCP will print our whole json-message in the summary line if we don't include a message. We can solve that by creating our own processors (_GCP_severity_processor and _GCP_add_display_message).

Edit from the future (2022-01-04): We learned that if you add a property called

After these changes, our setup-function looks like this:

import os
from typing import Any
import structlog
from structlog.dev import set_exc_info, ConsoleRenderer
from structlog.processors import StackInfoRenderer, TimeStamper, add_log_level


def config_structlog():
    # Custom renderer when in development:
    if os.getenv("PP_ENVIRONMENT") == "local":
        structlog.configure_once(
            processors=[
                add_log_level,
                StackInfoRenderer(),
                set_exc_info,
                TimeStamper(fmt="%Y-%m-%d %H:%M.%S", utc=False),
                ConsoleRenderer(),
            ]
        )
    else:
        structlog.configure_once(
            processors=[
                add_log_level,
                StackInfoRenderer(),
                set_exc_info,
                _GCP_severity_processor,
                _GCP_add_display_message,
                structlog.processors.JSONRenderer(),
            ]
        )


def _GCP_severity_processor(
    logger: Any,
    method_name: str,
    event_dict: Any,
) -> Any:
    """
    Add GCP severity to event_dict.

    Level is not a perfect one to one mapping to GCP severity.
    Here are the avaliable levels/method names:
        - debug
        - info
        - warning
        - warn (translates to warning as level)
        - error
        - err
        - fatal
        - exception
        - critical
        - msg
    """
    event_dict["severity"] = event_dict["level"].upper()
    del event_dict["level"]
    return event_dict


def _GCP_add_display_message(
    logger: Any,
    method_name: str,
    event_dict: Any,
) -> Any:
    """
    Add display message to event_dict.

    By default GCP logs will just show a string representation of the full blob.

    To show the message only you can use this processor.
    """
    event_dict["message"] = event_dict["event"]
    del event_dict["event"]
    return event_dict

Oh no, my code broke!

Even though I try to practice bug-free-driven development, I sometimes get Exceptions that I hadn't expected. I think the default stack trace is okay, but there is a way to get a much more parsable stack trace in your terminal with much more information.

By just installing rich (run pip install rich), you get beautiful, pretty printed exceptions. They look like this:

There is only one thing to look out for. Ensure that you are in an except-block when you use log.exception() because otherwise rich will crash.

TLDR

Install structlog and rich.
Copy the large code block in a file called src/helpers/structlog.py and call it before using the logger.
Enjoy and savor your wonderful logs!

Can you think of any improvement to our config, or do you feel that I missed something vital? Please leave a comment!

Python Guide for JS-devs

Julius Colliander Celik — Fri, 01 Oct 2021 09:22:00 +0000

I have been using JavaScript for most of my career, but I recently started working at a company that uses Python for most of its stack. Even though Python is easy to get started with, a couple of quirks are easy to get stuck on, and some best practices that I wish I knew earlier. Here is a list of my most significant hurdles and what I learned from the perspective of a JavaScript developer. Hopefully, it's useful for anyone else doing the same transition.

Six of One, Half Dozen of the Other

First, let's take a quick look at similar concepts with different names in the two languages.

Errors and Exceptions

Errors in JavaScript are called Exceptions in Python. They are otherwise identical in any meaningful way.

null and None

null in JavaScript is None in Python. There is no equivalent of undefined in Python.

Abbreviated keywords

Some keywords in Python are abbreviations of the actual words.

String is called str in Python.
Boolean is called bool in Python.
else if is called elif in Python. 🤯

I got stuck for longer than I wanted to admit the first time I tried to write else if. It's a strange quirk, but you will adapt fast if you know to look out for it.

Objects and Dictionaries

Objects in JavaScript are called Dictionaries in Python. There are two distinctions. Firstly dot-notation doesn't work in Python.

person = {"name": "Sherlock", "address": "Baker Street"}

print(person["name"]) # This works
print(person.name)    # This doesn't work

The other distinction is that Python lacks an equivalent of undefined in JavaScript. This means that if you try to access an undefined property, you will get an exception.

person = {"name": "John", "title": "Doctor"}

print(person["address"]) # Throws KeyError: 'address'

To avoid crashing whenever you want to access an optional property, you can use .get(). .get() is a method that returns the value of a key if it exists in a dictionary. If it can't be found .get() returns None. You can also give .get() an optional default parameter that will be returned instead of None if the key is undefined.

person = {"name": "Mycroft", "occupation": "Government official"}

print(person.get('name')) # prints Mycroft
print(person.get('age')) # prints None
print(person.get('age', 35)) # prints 35

Tuples and Lists

In Python, there are two equivalents to JavaScript's arrays. In most cases, you use lists, and they fill the same purpose.

clues = ["chair", "safe", "saucer of milk"]

for clue in clues:
  print(f"{clue} is a helpful clue")

There is another native data type that you can use to create collections of elements. If you want to return two values from a function or keep pairs of values, you can use tuples. It is often used instead of dictionaries if you want something a bit less verbose. Tuples are read-only lists with some extra syntax sugar.

def get_nemesis():
  return ("James", "Moriarty", 1835) # Return a tuple

# User is a tuple here
nemesis = get_nemesis()
print(nemesis[0], nemesis[1]) # Prints James Moriarty
nemesis[0] = "John" # This throws an Exception

# You can destructure a tuple
(first_name, last_name, born) = get_nemesis()

# The parenthesis are optional when destructuring
first_name, last_name, born = get_nemesis()

List (and Dict) comprehension

List comprehension is one of the most special features if you come from JavaScript. In JavaScript you can quickly compose arrays by using array functions like .map(), .sort(), and .filter(). Python has a couple of those array functions, but they are a bit ugly to use. Here is an example of doubling only even numbers from a list.

const numbers = [1, 2, 3, 4]

const result = numbers
  .filter(num => num % 2 == 0)
  .map(num => num + num)

The example above in Javascript is equivalent to this example below in Python:

numbers = [1, 2, 3, 4]

result = map(
    lambda num: num + num,
    filter(lambda num: num % 2 == 0, numbers),
)

You can't chain list functions as they aren't a part of the list class like they are a part of the array prototype in JavaScript. In Python, you can use list comprehensions instead.

numbers = [1, 2, 3, 4]

result = [
  num + num           # new value (map)
  for num in numbers  # list to iterate
  if num % 2 == 0     # filter
]

There are even dictionary comprehensions to create dictionaries from lists (or other iterables) quickly 🤩:

numbers = [1, 2, 3, 4]

result = {
  num: num % 2 == 0
  for num in numbers
}

# Results in {1: False, 2: True, 3: False, 4: True}

Concurrency

This topic is too large to cover in this post, but it's good to know that there are traps that you should look out for. In JavaScript, it's (almost) not possible to do any blocking task. This allows you to know that every library you use is guaranteed to handle concurrency benevolently. And it's difficult to end up in deadlocks.

Python supports synchronous statements, which can mean that you can block your thread for long times. This makes some code easier to write but concurrency a bit more complicated.

Python has two different methods to handle concurrency. You can use traditional OS threads. Additionally, Python recently added a non-blocking one threaded asynchronous native library called asyncio. It is very similar to Node's event loop on the surface, but there are some differences.

Firstly the library is a lot more complicated and low-level than Node. Non-blocking I/O operations are a native part of the JavaScript language (actually not the language but the execution environment), and the syntax feels very native. In Python, you get access to lots of low-level components of the event loop. You have to start the event loop yourself, and depending on if you are inside or outside the loop, you should use different functions to control the event loop. It can be challenging to remember the various quirks.

Secondly, Python's support for synchronous statements can be a significant drawback when using asyncio. If you accidentally call a blocking statement, you block the whole thread. You have to be careful and explicitly run all blocking code in "executors".

Even though there are quirks, I still prefer asyncio to thread management. You can learn more about asyncio by watching this video or by reading this book.

The last tip to remember is never to mix asyncio and threads. The documentation to asyncio is imperfect, and the documentation for using threads together with asyncio is nonexistent. I have wasted too much time trying to get it to work to attempt to mix them again.

Lambdas

I love anonymous arrow functions in JavaScript. I use them all the time, especially if I want a small function with 3-5 statements. Python has a similar concept called lambda functions, but they have one fatal flaw. Lambdas can only contain one statement. So it's not possible to have a multiline lambda. You will have to declare a proper function for those cases. 👎

Package Management and Reproducible Environments

npm is one of the best features of Node. It's undeniable that the quality of the available packages in Python is not as good. Additionally, the documentation is often much better and nicer looking for JavaScript packages. I highly suspect the reason for that is that there is considerable overlap between JavaScript developers and web developers. 😅

But the more significant hurdle was not the availability of pip packages. It was the actual package manager that I missed the most. When you use npm, you install packages locally for a specific project. This means that you can have different versions of the same library in different Node projects on your computer simultaneously. With pip, you can only install packages globally.

This sounds more stupid than it is. Python has solved the isolation using another method. It is best practice to set up a virtual environment for every Python project. You explicitly tell your shell to activate a virtual environment, and when it is activated, the set of global packages is entirely separate from the default environment.

Even though this works fine, I still mess up and forget to activate my virtual environments often and accidentally install libraries globally all the time. I miss how easy it is to use npm. Two other features I miss are npm scripts and good package version management.

To replace pip, I have started using pipenv. It manages my virtual environment and package versions almost as well as npm. It also supports scripts. The best part is that it doesn't matter if I have activated the virtual environment when I run the scripts. Pipenv automatically runs them in my virtual environment regardless.

The standard library

Python has a fantastic standard library! The rich native library compensates for the lack of community-produced pip packages. I enjoy finding native libraries that solve my issues cause then I know that I don't have to compare multiple open source libraries like I have to do with npm packages.

The Node libraries are very lean and only offer the necessary native operations that must be a part of the standard library, like providing I/O operations. The standard Python libraries often overlap in functionality, which is unheard of in the JavaScript world.

The best example of how extensive the libraries are is if you google "Get current timestamp using Python". You will see this article in the top results. The article suggests three different methods, using three different standard libraries (time, datetime, calendar).

Can you think of any other quirks that took time for you to figure out? Please leave a comment!