DEV Community: Andrej Szalma

Logging for beginners (in Python) - How and Why

Andrej Szalma — Wed, 20 Sep 2023 10:51:13 +0000

Logging is an essential part of software development. However, many developers struggle with writing good logs. In this post, we will explore what makes a good log and how to write one.

A Brief Timeline of a Software Developer

When people start programming, the first thing they do is produce their initial piece of code and say hi to the stdout/console/web browser/etc.. with the infamous sentence -

"Hello, world."

Not long after, come the comments. Comments are an integral part of every new developer's handbook. Everyone tells you to write them, but no one explains why, how, and when. As developers progress, they understand more code, patterns, and paradigms, and with that often come the assumption that every other engineer who is worth reading their masterpiece will understand it as well. It is crucial to understand that printing out the message "Error - process failed" will not lead other engineers to the issue that has been standing between them and happiness for the past two days.

What Makes Good Logs?

As you might know, there are whole books about writing well-logged, observable, and debuggable code. This post is not a drop-in replacement for these books, but it is a short write-up to help you easily level up your coding game.

We are uncovering another parallel to nature, as there are four elements that form a good log and are vital for delivering a meaningful and helpful message.

(Water) The Element of Time

Just as water flows, time does too, and therefore we must make sure that when reading logs, we know where the dam blocking our flow is. When searching for the source of an error, you will end up scrolling through a log file. It might be very long, but it just as well might be as short as a few lines. Regardless, you can't make assumptions as to which line in the log corresponds to your error without having information on when the specific log was written. It is crucial for every log to provide a timestamp (I would strongly recommend a human-readable format, like ISO 8601), so that someone doesn't get stuck in a vicious circle of debugging because of unknowingly looking at year-old logs that don't actually correspond to their issue.

Examples of logs with timestamps:

2024-01-01T12:00:00.000Z - ...
January 1, 2024, 12:00:00 UTC - ...
1704067200000 - ... (I wouldn't prefer to use Unix epoch time when it comes to human readability, however, when logs are interpreted by a software like Sentry, it can do the translation into a more readable format for you)

(Earth) The Element of Context

In the context of software logs, just as the element of earth provides a foundation for life, contextual information provides a foundation for understanding what happened in a given event. Without context, logs can be difficult to interpret and can lead to incorrect conclusions about what happened. It is important to include contextual information such as the place where the log was written, depending on context and the size of your app, it could be a package name/module name/function name, whatever helps the reader to identify where the log is coming from. Generally, in Python, this would be the name of the app followed by the name of the module (utilizing the __name__ variable).

Examples of logs with contextual information:

2024-01-01T12:00:00.000Z - myapp.mymodule - ...

(Fire) The Element of Information Level

The roof is on fire, right? Maybe, or maybe not. So far, we have only talked about logs as part of errors, however, debugging is not the only point when you would look at logs. You might want to figure out how long something took, or what is your program doing just know. Different log levels are used for different purposes. It is important to understand each of them and know when to use which as the level is used for filtering which logs to show in different log outputs. The following are the most common log levels:

ERROR- This one is quite self-explanatory. Something bad happened, your code ran into an error that is crucial for its health.
WARN - Warnings show potentially harmful occurrences of issues that are not breaking.
DEBUG - This is the most granular level of your logs. It provides a very verbose way to write information about the state and actions of your program for developers and other diagnostic personnel.
INFO - Info serves as a way for you to provide useful high-level information about the run of your program.

Examples of logs with different log levels:

2024-01-01T12:00:00.000Z - myapp.mymodule - INFO - ...
2024-01-01T12:00:00.000Z - myapp.mymodule - DEBUG - ...

(Wind) The Element of (Error) Message

A good message can carry information far and wide, just like the wind. Well crafted log messages can provide valuable insights into the behavior of a software application. A good log message should be clear and concise, providing enough information to understand what happened without overwhelming the reader with unnecessary details. For example, when you are logging a raised error, you don't need to include the error message in the log, as the error will already be included as part of the log. Rather choose to inform the user why the error occurred or provide more context which was maybe not included in the error itself.

Examples of logs with clear and concise messages:

2024-01-01T12:00:00.000Z - myapp.mymodule - INFO - The API server has started listening on 0.0.0.0:3000
2024-01-01T12:00:00.000Z - myapp.mymodule - ERROR - Failed to login into container registry

An Extra One for You... Structure

It is very important to make sure that your logs provide well-structured information, and that all of your logs are of the same structure. Consistency is crucial not just because of human readability, but also because logs are very often parsed by diagnostic software (e.g., (Sentry)[https://sentry.io/]). There are many different ways to structure your logs, however, the following is a good start:

[DATE/TIME] - [LOG LEVEL] - [MODULE] - [MESSAGE] - [STACK] - [DATA]

No need to make your logs look fancy, just make sure they are simple, structured, and easily comprehensible.

How to write logs in python

Python provides a built-in logging module that makes it easy to write logs in your application. Here are the basic steps to get started:

Import the logging module:

import logging

Configure the logging module:

logging.basicConfig(level=logging.INFO, filename='example.log', filemode='w', format='%(asctime)s - %(name)s - %(levelname)s - %(message)s')

This sets the logging level to INFO (meaning that all the log messages with a level bellow will be ignored), specifies the filename for the log file, sets the file mode to 'w' (write), and specifies the log message format.

This shows a simple way of configuring your logger, however, you can also use a configuration file where it is possible to declare much more complex configuration for the logging logic in your whole app. Please refer to the (logging module documentation)[https://docs.python.org/3/library/logging.html] for more info.

Write log messages:

logging.debug('This is a debug message')
logging.info('This is an info message')
logging.warning('This is a warning message')
logging.error('This is an error message')
logging.critical('This is a critical message')

This writes log messages at different severity levels to the log file.

Use placeholders for dynamic values:

name = 'John'
logging.info('Hello, %s', name)

This writes a log message with a dynamic value (the name variable) using a placeholder.

Pass raised exceptions to the logger:

try:
  # calculate the answer to everythin
  result = "42" + .0
except TypeError as e:
  logging.error("Exception occured while calculating the answer to everything", exc_info=True)

Using exc_info=True you can easily attach the stack trace of the exception and provide valuable information.

By following these steps, you can easily write logs in your Python application. Remember to include contextual information and use structured data to make your logs more useful and easy to analyze.

Conclusions

In summary, good logs are composed of four elements: time, context, information level, and message. By following these guidelines and keeping the logs consistent, you can easily level up your coding game and write well-structured, readable, and useful logs.

The mysteries of GraphQL clients' cache - The Showdown

Andrej Szalma — Wed, 07 Sep 2022 08:01:51 +0000

Recently I completed an internship at Microsoft where I had the privilege to work with people who are experts in their fields, more specifically in the field of GraphQL. I had numerous opportunities to learn from them and now I would like to teach you something. Let me take you on a journey through the midst of GraphQL clients & their cache.

This is a two-part series, where I'll talk about GraphQL client caches and compare the client's cache performance.

Part 1: The mysteries of GraphQL clients' cache - The Introduction
Part 2: The mysteries of GraphQL clients' cache - The Showdown

As promised in the previous part (Part 1), I would like to show you a head-to-head comparison of the client caches performance using a benchmark that I have been working on.

The Benchmark

So what is this benchmark I've been talking about? Simply put it is a tool to compare the latency performance of different GraphQL clients using your example queries. Thanks to this benchmark anyone can get performance data that can be used to make well-informed, data-driven decisions when choosing a GraphQL client for their project. Not only that, but it can be also used for testing experimental cache implementations, and finding out their strengths and weaknesses to know what needs to be optimised.

If you're interested, feel free to check it out for yourself - GraphQL Client Cache Benchmark.

This tool was originally developed by Convoy. We have upgraded and expanded it to fit our purpose.

Methods

In this part of the post, I would like to reach deep into my pocket and find the academic part of me to give you an overview of the experiment setup and testing methods so you know what and why are we testing.

Experiment setup

For the possibility of duplication of our results, I'd like to share the conditions under that the experiment has been run. However, regardless of the conditions, the benchmark results should show the same trends and patterns, only with different numbers.

OS: macOS Monterey 12.5
CPU: 2.4 GHz 8-Core Intel Core i9
GPU: Intel UHD Graphics 630 1536 MB
RAM: 32 GB 2667 MHz DDR4
Browser: Google Chrome - Version 103.0.5060.134 (Official Build) (x86_64)

Clients

The main important part of this whole project are GraphQL clients, and even though you might already know which clients are we going to compare, there is one more thing I need to explain before we continue. As I mentioned before, we have decided to compare two clients - Apollo client and Relay. However, we have also decided that it would be beneficial to see the effects on the performance of Apollo if we disabled the ResultCache, therefore you will see Apollo client twice in the benchmark. This proved to be a great idea, as you will see later, it turns out that depending on your specific scenario, it might be worth thinking about disabling it after all.

Example queries

As I have mentioned before, this benchmark uses arbitrary example queries and evaluates them with different clients throughout the whole test suite. These queries can include fragments as well, and they can represent your own real-life needs. Herein lies the beauty of this benchmark.

We have included a couple of example queries that you can use to play around with the benchmark, however, we expect you to add your own.

Disclaimer: There is an inbuilt query editor in the tool, however, it needed to be disabled since the newest Relay version needs pre-compiled gql artefacts. This compilation is performed by a compilator written in Rust, and it does not have a JS API which could be used to compile artefacts during the runtime. That being said, you will have to get your hands a little dirty and add your examples to the code manually. But don't worry, the documentation explains it very well.

Data access patterns

In our benchmark, we have been testing for three data access patterns - Read, Write and Update. In the following sections, I will provide you with tables that contain detailed descriptions of all the test cases and some example scenarios these might represent in the real life.

Read

As you can see in the table below, we have tested reading from empty/full cache and reading using identical/same shape queries. The latter is especially important to demonstrate the reliance of the clients on AST objects vs query strings. (Hint: Apollo's ResultCache is reliant on identical AST objects, therefore having the same query but with a different AST, will not be able to trigger reading from the ResultCache leading to a new write to it.)

	Read type	Notes	Example Scenario
R1	Read (empty cache)	Setup: None, Test: Read from empty cache, Comment: This demonstrates a client overhead for no-op queries.	N/A
R2	Read, fully cached, identical query written	Setup: Write query data to cache, Test: Read the identical query, Comment: This demonstrates the performance of the first read after write. Identical query is when the AST object is strictly equal.	Explicitly warming the cache (eg. with chat members, or slimcore data), identical query is used to read and write.
R3	Duplicate read, fully cached, identical query	Setup: Write query data to cache, read the identical query, Test: Read the identical query, Comment: This demonstrates the second read of the identical query.	Test out the repeated reads, eg, pulling the chat list every time a user switches from Channels to chats.
R4	Duplicate read, fully cached, same query shape	Setup: Write query data to cache, read the identical query, Test: Read a query with same shape but different AST, Comment: This demonstrates the reliance of a client on AST vs query string in its caches.	Tests our repeated reads from separate components that would request the data from differently crafted queries.
R5	Read 50% of fields, fully cached	Setup: Write query data to cache, Test: Read a query with half of the fields of the original query, Comment: This demonstrates how the client reads subsets of queries.	Explicitly warming the cache (eg. with chat members, or slimcore data), but data queried by components requires only smaller set of fields.
R6	Random read, fully cached, expanded response	Setup: Write query data with big number of items to cache, Test: Read a fragment for a random item, Comment: This demonstrates the overhead of big cache size on the client read behavior.	Showing behavior of a client in a situation of growing cache size overtime during Teams session.

Write

Similar to reads, we have been again testing writing from empty/full cache, with identical/same shape queries. Furthermore, you can also see observers here, which represent watchedQueries in Apollo and subscriptions in Relay. Conceptually, if you imagine having multiple components on a site, which are all watching a certain query or a fragment, these are our observers. We tested for 1, 25, and 125 of these to see the growing overhead in different clients. The writes in a fully cached state were figuring as empty-writes as no data was updated, so it only triggered a refetch of queries at the observers.

	Write type	Notes	Example Scenario
W1	Write, empty cache, no observers	Setup: None, Test: Write query data to cache	Writing startup data response to cache before any observers are setup on clean boot.
W2	Write, empty cache, 1, 25, 125 observers	Setup: Create observers, Test: Write query data to cache, Comment: This demonstrates the overhead caused by observers when writing to empty cache.	N/A
W3	Write, fully cached, 25, 125 observers	Setup: Write query data into the cache, set up observers for partial queries, Test: Write the main query data to cache again, Comment: This demonstrates if the client updates the observers even when the data didn’t change.	Refetch query from the network, Eg: people, presence data where no data has changed.
W4	Write, fully cached, 1, 25, 125 identical observers, identical query	Setup: Write query data into the cache, create identical observers, Test: Write the main query data to cache again, Comment: This demonstrates the differences between the clients for different vs identical ASTs	Refetch query from the network for components which observe an identical query
W5	Repeated write, fully cached, identical query, no observers	Setup: Write query data into the cache, Test: Write the same identical query data into the cache again, Comment: Compare against writing with the empty cache (W1) to see the overhead caused by the initial write or cached write.	Refetch query from the network without any observers

Update

When it comes to updates, we have tested the same things as with the previous tests, only with updating the data in the cache. However, it is important to mention, that these update tests represent the absolute worst-case scenario in real-life when all the observers are updated. Normally only a small subset would be notified. This particullarly affects Apollo client's records in the ResultCache which need to be rewritten on every observer update.

	Update type	Notes	Example Scenario
U1	Update, fully cached, 1, 25, 125 observers	Setup: Write main query into the cache, create 1, 25, 125 partial query observers, Test: Write same query shape to the main query with an updated response and verify if all affected partial queries have had their responses updated, Comment: This demonstrates the degradation of performance with frequently updated data.	Presence and user detail or also, emotions are updated quite often in teams and this example could represent that. (Edge case, eg. XL meetings)

Findings (🥁 Drumroll.. 🥁)

Without further ado, I'd like to present you our findings.

Okay, now that you had time to digest that, let's analyze these results together a little. From the results of the benchmark, we have found that generally through different examples and tests the Relay client has been performing 10x faster throughout the board. This raises questions about what are they doing better and what is stopping people from making Relay their first choice. One of the factors in decision-making is most probably ease of use, as Relay has a steeper learning curve compared to Apollo or others. Furthemore, the need to precompile GraphQL artifacts in Relay might be an incovenience for some, but definitelly not for many.

Patterns

Looking at the benchmark results, you can notice a few patterns happening again, and again, no matter what type of query you test. I'd like to highlight these using the following image, and explain why are they occuring.

A - This simply shows us that Relay being best across the board with just a few exemptions is a reoccuring pattern.

B1, B2 - This pattern provides a bit more interesting insight, and that is the effects of Apollo client's ResultCache. At B1 we can see that this is a duplicate read, fully cached, identical query test, which is exactly what ResultCache is optimised for. To explain better, when the first read from the cache, after the initial write, is performed, Apollo client memoizes the query data, and saves it to the ResultCache. After this, anytime a query with identical AST is read from the cache, instead of going through the denormalization process from the EntityStore, it is returned straight from the ResultCache. Very quickly. The same scenario occurs on B2, where we are testing empty writes. The ResultCache shines here again, as creation of the observers, it memoizes all the query data that is being watched, and since the writes are empty, and do not update any data, all that the observers need to do is to refetch the same data from the ResultCache. If you compare this to Apollo client with ResultCache disabled, you can see that the latency there is even 10x slower at some points.

Of course, as everywhere, exceptions occur and the results for each query are ever so-slightly different. However, these patterns are repetitve and have been showing up in all of our tests, so I believe they give us a nice representation of the results.

Closing thoughts

If you reached this point, I'd like to thank you for reading my post. It has been an amazing experience learning all this during the course of my internship, and now trying to teach you something new as well. But before the tears come out, let me leave you with some of my final conclusions and thoughts.

When it comes to Relay, it is a highly optimized React framework which provides the best, and most reliable latency performance. No doubts about that. Apollo on the other hand, has libraries for the whole stack and for a whole lot of languages, but they are definitely lacking behind on the performance side. However, it is important to mention, that there have been experimental caches for Apollo client previosly, which provided a simillar performance to Relay, so ... perhaps, instead of hating it after reading this post, let's try to come up with a way to optimise it. That's what open-source is about afterall 😉

The mysteries of GraphQL clients' cache - The Introduction

Andrej Szalma — Wed, 07 Sep 2022 07:56:50 +0000

This is a two-part series, where I'll talk about GraphQL client caches and compare the client's cache performance.

Part 1: The mysteries of GraphQL clients' cache - The Introduction
Part 2: The mysteries of GraphQL clients' cache - The Showdown

"There are only two hard things in Computer Science: cache invalidation and naming things."
-- Phil Karton

As every blog post that even just remotely mentions the subject of caches, I too have felt the need to include this infamous quote. Regardless if we are going to speak about cache invalidation or not, this quote always brightens up the mood a little bit.

A quick intro to GraphQL clients

The conventional (but not only) way to use GraphQL is as an API that communicates through HTTP POST requests. Because the response of a GraphQL API is a bit more complex than a simple REST response, libraries have been built to make your life easier when communicating with such APIs. Libraries such as Apollo client, Relay, URQL, etc., help you automatically handle things like batching, caching, constructing queries, managing UI state and much more.

With GraphQL becoming ever-so-popular, the support and development for these have skyrocketed in the past few years. When starting a new project, there is plenty to choose, but the question is, which one is the best for you?

Caching - not the geo one

As "hinted" in the name of this post, our main focus today is going to be caching. Caching in GraphQL, as anywhere else, is used to save data received from some data layer (eg. server) so the next time our application needs that data, it can read it from our cache memory instead of doing another network request to our data layer. This way, we can save precious resources and minimize client load times. The above-explained type of cache can also be called an In-Memory cache.

However, implementing and maintaining a cache is not as easy as it sounds and every client has their way of doing it. I have researched mainly two popular clients - Apollo client and Relay.

Before I start speaking about this thought, let me explain what is data normalization, and why is it important to us.

Data normalization

Data normalization is the process of restructuring some data to reduce redundancy. You might have heard about this from relational databases, where you have 5 normal forms to get through before you can even start thinking about being happy.. :) Both clients have a normalized cache (which is the de facto standard now) and they need to perform this process to convert the JSON blob they receive from the GraphQL server into a relational structure. The algorithm used for normalization varies between them, however, the principles remain the same.

Apollo client

As a GraphQL client - Apollo is the more simplistic and flexible of the two. It provides an easier way of getting started, a bit more comprehensive documentation, and perhaps better community support. However, when it comes to cache implementation, it is, unfortunately, lacking behind.

However, before we get to compare the performance of the two, let me explain how Apollo's cache works. As mentioned previously, they are using an In-Memory cache and this consists of two main parts - EntityStore and ResultCache.

EntityStore is the main cache which holds normalized data in a flat lookup table, therefore when data is read from it, it needs to be de-normalized.

ResultCache has been introduced to help with the denormalization problem. Therefore, when the first read of a query is executed against the EntityStore the de-normalized data is memoized in the ResultCache and this then makes all upcoming reads of the identical query very fast. However, this comes with the overhead of having to write into the ResultCache on every first read operation on some query that has not yet been memoized. (The match has to be 1:1 exact here)

Normalization algorithm

As previously mentioned, Apollo maintains a normalized In-Memory cache by default, and now I'd like to explain in a few words how their normalization algorithm works.

Firstly, let's say we have a GraphQL query to get all the users, which looks like this:

query getAllUsers {
  users {
    id
    firstname
    lastname
  }
}

When a GraphQL response reaches the client, it comes in a JSON format, looking something like this:

{
  "data": {
    "users": [
      {...},
      {...},
      {...},
    ]  
  }    
}

The contents of the data object are the actual response, therefore from now on, we will only work with what is inside of data.
Now, the first step to normalize this data would be to split our users Array into single objects.

{
  "__typename": "User",
  "id": 1,
  "firstname": "John",
  "lastname": "Doe"
}

{...}

{...}

Notice, that a __typename field has been added to our response, even though we have not requested it in our query. This is because Apollo client requests this field automatically, even if you don't explicitly do so. In the next step, you will see why.

Now that we have extracted all our objects, we can perform another step of normalization, which would be creating a globally unique identifier for every object, so that it can be saved in a key-value type lookup table (Hashmap). By default, Apollo client uses a composite key made of the __typename + id. Now you see, why Apollo client requested the __typename field automatically. However, not all objects in our response always have a unique id which could be in the composite key, therefore Apollo gives us the possibility to choose which fields we want to use for creating this unique identifier key using the typePolicies setting in the InMemoryCache config.

Once that we have created the unique identifier for an object, we need to look into it and find any nested objects. Should there be any, they will need to be extracted, and assigned with a unique identifier key, which will then be placed in their original position as a reference. See the following example:

{
  "__typename": "User",
  "id": 1,
  "firstname": "John",
  "lastname": "Doe",
  "address": {
    "__typename": "Address",
    "id": 1,
    "line1": ...,
    ...
  }
}

// The cache lookup table would look something like this after the normalization of the above object.

{
  "User:1": {
    "id": 1,
    ...
    "address": {
      "__ref": "Address:1"
    }
  },
  "Address:1": {
    "id": 1,    
    ...
  }
}

However, it is important to mention, that should these be simply scalar fields, let's say an array of objects, which are not a GraphQL type, then these will not get extracted from the object.

And now, you know the overview of how Apollo performs normalization, not that hard, right? :)

Next, let's jump over to our friend Relay.

Relay

As previously mentioned, Apollo is the more simplistic and versatile one, whereas Relay is the more optimized and narrow-scoped one. What I mean by this, is that whereas Apollo Client has frameworks for multiple languages, Relay was made specifically for React and is highly optimised.

However, when it comes to cache, they are not that different from their core implementations. If you forget about Apollo's ResultCache for a minute, then they are indeed very similar. However, since Relay is based on granular fragments instead of whole queries as Apollo is, it does not need anything such as a ResultCache. This is why Apollo client had to add another layer of complexity to their InMemoryCache to optimize for second reads. (Read re-renders of whole queries are very frequent in apollo, and therefore the memoization process performed by the ResultCache helps to speed this up)

Store is the one source of truth for an instance of RelayRuntime which holds a collection of entities presented by the RecordSource type. These are (as before) a collection of normalized records belonging to a single query/mutation/etc. The query goes through a normalization process and its entities are extracted and saved into Records which are then all collected in one RecordSource. The RecordSource object is then merged into the Store and subscribers (observers) to a fragment that was affected are notified.

Normalization algorithm

Since I have provided an in-depth explanation of the normalization algorithm in Apollo, I am not going to do the same here, as they are similar in their nature. However, one thing, that I believe is worth mentioning, is how they choose their unique identifiers for normalized records.

As you already know, Apollo client uses the composite key of __typename + id fields and only extracts nested objects if they have GraphQL types (not scalars). However, Relay, on the other hand, takes a different approach, where every nested object, is extracted into a Record and is assigned a DataId. This is a globally unique identifier in the scope of the cache and it can be made from the id field of the objects, or if they don't have such fields, it can be based on the path to the record from the nearest object with an id (such path-based ids are called client ids). Thanks to this logic, even nested scalar objects are always extracted and normalized.

Next up

Now that I have explained the basics of how GraphQL client cache works, I would like to show you a showdown between the clients, comparing their caches head-to-head. Use this link to read more about that in Part 2 - The mysteries of GraphQL clients' cache - The Showdown.