Categories
f-strings logging python

f-strings and python logging

There is one thing that has bothered me for a couple of months. It felt wrong when I saw it in the codebase but I could not tell why it is wrong. It was just a hunch that something is not right, but not enough to make me look for a reason.

For last couple of days I have been struggling to sort out my bot configuration on Azure and decided I need a break from that. Python being something I know best is a good candidate to feel comfortable and in control again.

I have decided to finally answer the question that was buggin me. Why using f-strings in logger calls makes me uneasy? Why this feels wrong?

hero = "Mumen Rider"
logger.error(f"Class C, rank 1: {hero}")

f-strings

Most of the pythonistas would know by now what f-strings are. They are convenient way of constructing strings. Values can be included directly in the string what makes the string much more readable. Here is an example from Python 3’s f-Strings: An Improved String Formatting Syntax (Guide), which is worth at least skimming through if you know f-strings.

>>> name = "Eric"
>>> age = 74
>>> f"Hello, {name}. You are {age}."
'Hello, Eric. You are 74'

They have benefits and my team have been using them since. It’s fine as they are awesome however I feel that they should not be used when we talk about logging.

logging

I’m not talking about poor man’s logging which is print. This is an example of logging in Python

logger.info("This is an example of a log message, and a value of %s", 42)

When the code includes such line and when it is executed it outputs string according to log configuration. Of course your log level needs to match but I’m skipping this as it is not relevant here, I’ll get back to this later. The %s identifier in log messages means that anything passed into logger.info will replace the identifier. So the message will look like this.

INFO:MyLogger:This is an example of a log message, and a value of 42

logging + f-strings

Since logging accept strings and f-strings are so nice they could be used together. Yes, it is possible of course but I’d not use f-strings for such purpose. Best to illustrate why is an example followed with explanation.

    import logging
    logging.basicConfig(level=logging.ERROR)
    logger = logging.getLogger('klich.dev')

    class MyClass:
        def __str__(self):
            print('Calling __str__')
            return "Hiya"

    c = MyClass()
    print("F style")
    logger.debug(f'{c}')
    logger.info(f'{c}')
    logger.warning(f'{c}')
    logger.error(f'{c}')

    print()
    print("Regular style")
    logger.debug('%s', c)
    logger.info('%s', c)
    logger.warning('%s', c)
    logger.error('%s', c)

This short example creates logger and sets logging level to ERROR. This means that only calls of logger.error will produce output. __str__ method of object used in log messages prints information when it is called. So each level matching logger call will print Calling __str__ message and Hiya. Since there are two logger.error calls we should get four lines total. This is what actually is printed out.

    % python3 logg.py
    F style
    Calling __str__
    Calling __str__
    Calling __str__
    Calling __str__
    ERROR:klich.dev:Hiya

    Regular style
    Calling __str__
    ERROR:klich.dev:Hiya

We can see that logger lines using f-strings are calling __str__ even if the log message is not printed out. This is not a big penalty but it may compound to something significant if you have many log calls with f-strings.

what is going on

According to documentation on logging

Formatting of message arguments is deferred until it cannot be avoided.

Logger is smart enough to actually not format messages if it is not needed. It will refrain from calling __str__ until it is required, when it is passed to std out or to a file, or other with options supported by logger.

To dig a little bit more we can use dis module from python standard library. After feeding our code to dis.dis method we will get a list of operations that happend under the hood. For detailed explanation of what exact operations do have a look at ceval.c from Python’s sources.

    >>> import logging
    >>> logger = logging.getLogger()
    >>> def f1():
            logger.info("This is an example of a log message, and a value of %s", 42)

    >>> def f2():
            logger.info(f"This is an example of a log message, and a value of {42}")

    >>> import dis
    >>> dis.dis(f1)
                0 LOAD_GLOBAL              0 (logger)
                2 LOAD_METHOD              1 (info)
                4 LOAD_CONST               1 ('This is an example of a log message, and a value of %s')
                6 LOAD_CONST               2 (42)
                8 CALL_METHOD              2
                10 POP_TOP
                12 LOAD_CONST               0 (None)
                14 RETURN_VALUE
    >>> dis.dis(f2)
                0 LOAD_GLOBAL              0 (logger)
                2 LOAD_METHOD              1 (info)
                4 LOAD_CONST               1 ('This is an example of a log message, and a value of ')
                6 LOAD_CONST               2 (42)
                8 FORMAT_VALUE             0
                10 BUILD_STRING             2
                12 CALL_METHOD              1
                14 POP_TOP
                16 LOAD_CONST               0 (None)
                18 RETURN_VALUE

In this case we won’t get into much details, it is enough to see that f-strings add two additional operations of FORMAT_VALUE (Handles f-string value formatting.) and BUILD_STRING.

After this small research I can explain why we should not be using f-strings in this specific place which is logging. I also can put my uneasiness to rest.

Categories
elixir gitlab

Simple lesson from writing my first Elixir app

This may be a secret as I didn’t mention it here that one of my hobbies is economy. The other one is programming, which is kinda obvious. I enjoy teaching as well, and run Coding Dojo in my town, but this is a story for some other time. These three things, programming, economy, and teaching mixed together with an idea might create something interesting.

Few months ago I have decided to start calculating one economic indicator called [Misery Index](https://en.wikipedia.org/wiki/Misery_index_(economics) of Poland. It is simple, easy to understand, and data required to calculate it is available from Polish Bureau of Statistcs(GUS).

After having this idea I created https://jakjestw.pl. For first few months I have updated data by hand. New data is not released often and I could simply check and then apply changes myself. That was fine at first but started being cumbersome. I happen to fancy Elixir and to test it out on something real I decided to create poor man’s static site generator and data parser.

Requirements were ridiculously simple. The app had to fetch data from GUS website, which was in JSON format. Then transform it into something that can be injected into HTML file. Since I was done with manual labour it had to run on Gitlab pipelines.

Easier said than done. My major language is Python what influenced how I chose to model my data. This had been my demise. I picked really poorly, by following gut instinct of a Python programmer. Maps, tuples, and lists were my choice. In Python it does make sense, for such case of data transformation might not be the best but still Dict is a goto structure. My Elixir data looked like this, what a lovely year for Polish wallets by the way.

     %{
      2015 => [
        {12, %{cpi: -0.5}},
        {11, %{cpi: -0.6}},
        {10, %{cpi: -0.7}},
        {9, %{cpi: -0.8}},
        {8, %{cpi: -0.6}},
        {7, %{cpi: -0.7}},
        {6, %{cpi: -0.8}},
        {5, %{cpi: -0.9}},
        {4, %{cpi: -1.1}},
        {3, %{cpi: -1.5}},
        {2, %{cpi: -1.6}},
        {1, %{cpi: -1.4}}
      ]
     }

My website displays latest number that is calculated each day. It also provides information how the number is calculated by providing both components of the indicator, CPI and unemployment. One last thing is a comparison of last four years by giving data from last month of each year. Not a perfect situation but will do for comparison.

Extracting such information from data structure presented above requires a lot of effort. Lot more than I expected and I have told myself that this is because I’m not fluent in Elixir. After I have finished I realised that it’s not me it is my data structure. Which is my fault, but it’s not me.

That sparked an idea to change my data structure to something that map/reduce can handle easier. This time with some experience in processing data in pipelines I decided to skip the nested structures and have flat data like list and use proper date object.

    [
      [~D[2016-12-01], {:unemployment, 8.2}],
      [~D[2016-11-01], {:unemployment, 8.2}],
      [~D[2016-10-01], {:unemployment, 8.2}],
      [~D[2016-09-01], {:unemployment, 8.3}],
      [~D[2016-08-01], {:unemployment, 8.4}],
      [~D[2016-07-01], {:unemployment, 8.5}],
      [~D[2016-06-01], {:unemployment, 8.7}],
      [~D[2016-05-01], {:unemployment, 9.1}],
      [~D[2016-04-01], {:unemployment, 9.4}],
      [~D[2016-03-01], {:unemployment, 9.9}],
      [~D[2016-02-01], {:unemployment, 10.2}],
      [~D[2016-01-01], {:unemployment, 10.2}]
    ]

This is perfect for map/reduce/filter operations. Saying that code is simpler from my point of view does not makes sense as I spent a lot of time with it. The metric that can be helpful here is number of added and removed lines. In total I have removed 409 lines while adding 244, that is 165 lines less then before. After removing lines that changed in test we get 82 removed and 67 added, which is around 25% less code doing the same thing. Which is a good news but giving only LOCs could be misleading as lines are not equal. So now code before

    def second_page(all_stats) do
      Enum.to_list(all_stats)
      |> Enum.map(fn {x, data} -> for d <- data, do: Tuple.insert_at(d, 0, x) end)
      |> List.flatten()
      |> Enum.sort(fn x, y -> elem(x, 0) >= elem(y, 0) && elem(x, 1) >= elem(y, 1) end)
      |> Enum.find(fn x -> map_size(elem(x, 2)) == 2 end)
      |> elem(2)
      |> Map.to_list()
    end

And after.

    def second_page(all_stats) when is_list(all_stats) do
      Enum.drop_while(all_stats, fn e -> length(e) < 3 end)
      |> hd
      |> tl
    end

This is the most striking example from the codebase that illustrates what changes this can involve.

TIL:

My main take from this experience is that mistakes at the start of a project may lead to disastrous consequences later on. The time spent on designing, that includes writing throw away code when doing spikes, is best investment you can make. Think about it before you start.

P.S.

Code is up on Gitlab, feel free to look and comment.

Categories
azure extensions vscode

I wrote extension to VS Code

I feel comfortable using Spacemacs, it has almost everything I need while I write in Python. Sometimes I use other languages and this forces me to look into Spacemacs’ configuration. Spacemacs does it’s job but some things are difficult to configure.

So I decided to try and use VS Code for a while instead. It has really good support for Python and other languages. I used it while working on a React Native app or when writing in Typescript. One thing that really interests me is Live Share feature. One can share coding session with anyone by simply sharing a link. Very useful when pair programming, not like Hangouts or Slack.

Couple posts before I mentioned my Slack journal which I use to make my work more transparent to others. So I had an idea to use Live Share and show anyone what I’m currently working on. The feature is a killer but it has one flaw, the URL under which session is available changes each time you start a new session. It is not convenient if you want to share it with a couple people as you have to send this URL everytime you start a new session to each one of them. Even if session or connection failed without your fault.

To fix it I wrote a VS Code plugin and called it Oversharing. The extension allows you to share your session as Live Share would but it keeps your link same across all future sessions. Link that Live Share creates is sent to an Azure Function and saved, in return for a new stable link. This new link will redirect to Live Share link each time it is opened, and will be preserved across all future Live Share sessions.

Hopefully someone finds it useful as I do.

If you are interested in writing your own extension, here you can learn how to write your first.

Categories
azure typescript

Guide on Developing Azure Functions locally

Why

I have spend way too much time on figuring out how to create local development environment for working on Azure Functions. Most of the time was spent on reading Microsoft’s documentation on this topic. Hopefully this guide will save you some time 🙂

The guide had been prepared on Ubuntu and verified as well. Additionaly my coworker verified it to work on macOS High Sierra. If you are here to create your first Azure Function locally please read along.

What are azure functions

Azure Functions are small pieces of code that are run on Azure infrastructure in a serverless fashion. The Infrastructure, provisioning, scaling is Azure’s responsibility. If you wish to read more below are links to detailed explanation by Azure team. I’d recommend at least skimming the first one.

Software required for local development

There are a couple of tools required to be able to develop locally.

  • npm, tooling is mostly in JS/TS
  • .NET Core SDK, required for function extensions
  • Azure Functions Core Tools (later referred as AFCT)
  • Azurite legacy, for storage emulation. It works with Blob, Table, and Queue storages. Legacy is required as the current one supports only Blob storage.
  • Docker

Handling http requests

This part explains how to create a function that is triggered by HTTP request and responds with HTTP response.

Create Azure Function project

Start with calling func init HTTPFunc in the directory of your choosing. You will be asked a couple of questions regarding your project.

majki@enchilada ~/projects/azure-tracker-local
% func init HTTPFunction
Select a worker runtime:
1. dotnet
2. node
3. python (preview)
4. powershell (preview)
Choose option: 2
node
Select a Language:
1. javascript
2. typescript
Choose option: 2
typescript
Writing .funcignore
Writing package.json
Writing tsconfig.json
Writing .gitignore
Writing host.json
Writing local.settings.json
Writing /home/majki/projects/azure-tracker-local/HTTPFunction/.vscode/extensions.json

Create Azure Function

Create function next. As in the previous step you will be asked questions regarding the function you wish to create. I selected 8. HTTP Trigger as this function should respond to HTTP requests.

majki@enchilada ~/projects/azure-tracker-local
% cd HTTPFunction
majki@enchilada ~/projects/azure-tracker-local/HTTPFunction
% func new
Select a template:
1. Azure Blob Storage trigger
2. Azure Cosmos DB trigger
3. Durable Functions activity
4. Durable Functions HTTP starter
5. Durable Functions orchestrator
6. Azure Event Grid trigger
7. Azure Event Hub trigger
8. HTTP trigger
9. IoT Hub (Event Hub)
10. Azure Queue Storage trigger
11. SendGrid
12. Azure Service Bus Queue trigger
13. Azure Service Bus Topic trigger
14. Timer trigger
Choose option: 8
HTTP trigger
Function name: [HttpTrigger]
Writing /home/majki/projects/azure-tracker-local/HTTPFunction/HttpTrigger/index.ts
Writing /home/majki/projects/azure-tracker-local/HTTPFunction/HttpTrigger/function.json
The function "HttpTrigger" was created successfully from the "HTTP trigger" template.

Install dependencies

npm install

Run function

npm run start

Verify

majki@enchilada ~
% curl http://localhost:7071/api/HttpTrigger
Please pass a name on the query string or in the request body%
majki@enchilada ~
% curl "http://localhost:7071/api/HttpTrigger\?name\=Mike"
Hello Mike

Handling Queue Storage

This part explains how to create a function that is triggered by HTTP request to send a message onto Queue Storage.

Install storage emulation

On windows, you may go with emulator provided by Microsoft. On Ubuntu, there is community sourced Azurite. Unfortunately, the most recent version does not support Queue Storage. For queues, install version 2.7.0 by following instructions.

Create Azure Function project

Start with calling func init HTTPFunc in directory of your choosing. You will be asked couple questions regarding your project.

majki@enchilada ~/projects/azure-tracker-local
% func init HTTPFunction
Select a worker runtime:
1. dotnet
2. node
3. python (preview)
4. powershell (preview)
Choose option: 2
node
Select a Language:
1. javascript
2. typescript
Choose option: 2
typescript
Writing .funcignore
Writing package.json
Writing tsconfig.json
Writing .gitignore
Writing host.json
Writing local.settings.json
Writing /home/majki/projects/azure-tracker-local/HTTPFunction/.vscode/extensions.json

Create function

Create function next. As in previous step you will be asked questions regarding function you wish to create. I selected 8. HTTP Trigger as this function should respond to HTTP requests, it will in response send message to Queue Storage.

majki@enchilada ~/projects/azure-tracker-local
% cd HTTPFunction
majki@enchilada ~/projects/azure-tracker-local/HTTPFunction
% func new
Select a template:
1. Azure Blob Storage trigger
2. Azure Cosmos DB trigger
3. Durable Functions activity
4. Durable Functions HTTP starter
5. Durable Functions orchestrator
6. Azure Event Grid trigger
7. Azure Event Hub trigger
8. HTTP trigger
9. IoT Hub (Event Hub)
10. Azure Queue Storage trigger
11. SendGrid
12. Azure Service Bus Queue trigger
13. Azure Service Bus Topic trigger
14. Timer trigger
Choose option: 8
HTTP trigger
Function name: [HttpTrigger] HTTP2Queue
Writing /home/majki/projects/azure-tracker-local/HTTPFunction/HTTP2Queue/index.ts
Writing /home/majki/projects/azure-tracker-local/HTTPFunction/HTTP2Queue/function.json
The function "HTTP2Queue" was created successfully from the "HTTP trigger" template.

Configure function output

In the editor open function.json file located in the directory named after the name of the function. Remove the section related to http output and replace with the queue output as shown below:

{
  "type": "queue",
  "direction": "out",
  "name": "msg",
  "queueName": "outgoingqueue",
  "connection": "MyQueueConnectionString"
}

The file is suppose to look like this:

{
    "bindings": [
        {
            "authLevel": "function",
            "type": "httpTrigger",
            "direction": "in",
            "name": "req",
            "methods": [
                "get",
                "post"
            ]
        },
        {
            "type": "queue",
            "direction": "out",
            "name": "msg",
            "queueName": "outgoingqueue",
            "connection": "MyQueueConnectionString"
        }
    ],
    "scriptFile": "../dist/HTTP2Queue/index.js"
}

Configure queue connection

Some connections defined in function.json require to have a connection string. After adding an outgoing queue connection you need to add a connection string as well. String has to be added to Define connection in local.settings.json by adding "MyQeueueConnectionString". The value of this string is taken from documentation of Azurite.

{
    "IsEncrypted": false,
    "Values": {
        "FUNCTIONS_WORKER_RUNTIME": "node",
        "AzureWebJobsStorage": "{AzureWebJobsStorage}",
        "MyQueueConnectionString": "DefaultEndpointsProtocol=http;AccountName=devstoreaccount1;AccountKey=Eby8vdM02xNOcqFlqUwJPLlmEtlCDXJ1OUzFT50uSRZ6IFsuFq2UVErCz4I6tq/K1SZFPTOtr/KBHBeksoGMGw==;QueueEndpoint=http://127.0.0.1:10001/devstoreaccount1;"
    }
}

Install dependencies

npm install

Install extensions

Since we are using an output that is different than http, we have to install storage extensions to make the queue work.

func extensions install

Run azurite

Run Azurite by using Docker

docker run -e executable=queue -d -t -p 10001:10001 -v queue_Storage:/opt/azurite/folder arafato/azurite

More information on how to run it is here.

Run function

In order to put any message on the queue, the function needs to be modified a bit. Please change it accordingly.

const httpTrigger: AzureFunction = async function (context: Context, req: HttpRequest): Promise<void> {
    context.log('HTTP trigger function processed a request.');
    const name = (req.query.name || (req.body && req.body.name));
    context.bindings.msg = name;
    context.done();
};

And then

npm run start

Verify

Now we can see how this is working. We are going to call our function a couple of times and then see what messages had been put on the queue.

majki@enchilada ~
% curl "http://127.0.0.1:7071/api/HTTP2Queue?name=Mike"
HTTP/1.1 204 No Content
Content-Length: 0
Date: Tue, 14 May 2019 06:39:25 GMT
Server: Kestrel
majki@enchilada ~
% curl "http://127.0.0.1:7071/api/HTTP2Queue?name=Mickey"
HTTP/1.1 204 No Content
Content-Length: 0
Date: Tue, 14 May 2019 06:39:28 GMT
Server: Kestrel

There should be two messages on the queue at this moment. We can query the queue by running:

majki@enchilada ~
% curl "http://127.0.0.1:10001/devstoreaccount1/outgoingqueue/messages?peekonly=true&numofmessages=10"
HTTP/1.1 200 OK
Connection: keep-alive
Content-Length: 885
Content-Type: application/xml; charset=utf-8
ETag: W/"375-pdRmS0dxI0dhZlfRbwGMunhL+WM"
X-Powered-By: Express
date: Tue, 14 May 2019 06:42:39 GMT
x-ms-request-id: 77856d80-7613-11e9-afc4-b5f560b4039e
x-ms-version: 2016-05-31

<?xml version='1.0'?><QueueMessagesList><QueueMessage><MessageId>cae264ef-74bd-4bde-b03e-01be8821968a</MessageId><InsertionTime>Tue, 14 May 2019 06:29:04 GMT</InsertionTime><ExpirationTime>Tue, 21 May 2019 06:29:04 GMT</ExpirationTime><DequeueCount>0</DequeueCount><MessageText>TWlrZQ==</MessageText></QueueMessage><QueueMessage><MessageId>13732448-a498-4fc5-85cf-8c4afafe082b</MessageId><InsertionTime>Tue, 14 May 2019 06:39:25 GMT</InsertionTime><ExpirationTime>Tue, 21 May 2019 06:39:25 GMT</ExpirationTime><DequeueCount>0</DequeueCount><MessageText>TWlrZQ==</MessageText></QueueMessage></QueueMessagesList>

Azurite supports Queue Storage API, so if you need to know more operations read linked docs.

Categories
remote work slack

Slack journal is my office blog

I use slack at work, which is not a surprise as many teams do. Our team is also remote, not fully remote but everyday some part of the team is not in the office. This changes how we work together, and it in my opinion affects communication most. To tackle problems with remote teams it is best to look for advice from companies that are remote as they most probably solved it already. While looking for such advice I found a great guide to remote teams. It has 4 chapters on: hiring, communication, management, and culture. I highly recommend reading the whole guide.

What I have focused on is communication, as this was issue that in my opinion caused most problems. Too little exchange will cause misunderstandings, and may give false impression that no one is working and little is going on. Decisions made without notifying all team members may cause misunderstandings as well. Such decisions are sometimes made in a channel, or in a private talk, or during a meeting.

To improve visibility in what I’m working on I have started keeping a journal on Slack, as described in chapter on communication. I’m documenting what I do, what I read, and my thoughts and opinions on different tasks or projects, for more than a year now.

My slack journal

Journal allows my colleagues to chime in on my channel as well. Numerous times someone had jumped in with a great advice regarding some problem I had been struggling with, or simply with some tool that would solve it, or with a new library I should be looking at. I find it really helpful, as I can track my work during the week so when filling time sheets I can review what I’ve been doing. I’m really bad at keeping track so this solves one of my issues. While writing my journal I have received a lot of new information back, hopefully helped someone, and what is most important provided a visibility in what I do when you can’t see me.

Other thing we are trying is documenting every important decision for others to read. Not everyone can attend a meeting, video call or a small face to face discussion and it is vital to pass this information to other members of the team. So there is no urgency to attend everything, and there is no FOMO as all will be documented.

Categories
elixir patterns

Actor model

Motivation

One of my resolutions this year is to review my notes from each conference I visit and read/learn/build something. Quite recently I have been for the second time to Lambda Days in Kraków, where I got interested in Elixir. It is functional, what is dear to me but more importantly it is built for concurrent computation. This is achieved by shared nothing architecure and actor model. It means that each actor, or process in Elixir land, is independent and share no memory or disk storage. Communication between processes is achieved by sending messages. This allows building systems that are concurrent with less effort. Since it is so helpful I’ll try to understand what actor is and hopefully explain it here.

This is not a full explanation by any means but rather a primer before I implement my latest project using this computation model. It is possible that my knowledge will be revised along with a new post.

What is the Actor Model

Actor is a model of concurrent computation. It has the following properties or axioms. (I have shuffled them a bit to emphasise messaging as IMHO important part of this model).

  • Can designate how to handle next received message
  • Can create actors
  • Can send messages to actors

Let’s unpack those properties to make it more clear. "Can designate how to handle next received message", so actors communicate with messages. Each actor has an address as well, where messages can be send. And it is up to an actor how will it respond if at all.

"Can create actors" is pretty simple, each actor can spawn other actors if required by performed task.

"Can send messages to actors" as mentioned while describing first axiom communication is done via messages. Actors send messages to each other.

One actor is not really an actor model, as mentioned in one of the articles, actor come in systems.

This is short and simple, it is the jist of it with focus on most important parts of actor model. What I find valuable is the fact that this model brings software failures to the front and forces solution designer to appreciate and expect them.

I find it similar to OOP created by Alan Key and described here

OOP to me means only messaging, local retention and protection and hiding of state-process, and extreme late-binding of all things. It can be done in Smalltalk and in LISP. There are possibly other systems in which this is possible, but I’m not aware of them.

When to use it?

If you are having a task that can be split into stages, may be linked or independent. In such case I find actors more palatable than locks and threading. This is kind of thing that Broadway library for Elixir is trying to solve. Actor model may also be used when thinking about OOP, it might not be possible to implement actors in such way that they are independent at the level this model expects, but thinking in such terms may improve resilience of the project.

Resources

I know I have skimmed this topic and if you are interested please have a look at resources I used to grasp the idea of actor model.

Categories
python

Redis cache

I enjoy listening to podcasts, as they sometimes give me inspiration to create something. In one of the episodes of Python Bytes podcast guys mentioned https://github.com/bwasti/cache.py tool. cache.py allows to cache function calls across runs by using cache file. Simple and really useful.

This inspired me to write a similar thing but for distributed apps, based on redis as a cache storage. I called it rcache and you can find it on PyPI.

In order to use it simply decorate a function like this:

import rcache

@rcache.rcache()
def expensive_func(arg, kwarg=None):
  # Expensive stuff here
  return arg

Default redis address is http://localhost:6379, but you can change it by passing an url into the decorator @rcache.cache(url="http://your_redis:6379").

I hope you find it useful and if you wish to comment or report something please go to https://gitlab.com/the_speedball/redis.cache.py/issues.

Have fun

Categories
javascript testing

Property based testing using jsverify

I wanted to write about property based testing for a long time. Since I usually write about things I have built, in order to write a post I had to built something. So I started building a runners calculator, using react-native. The calculator helps with estimating the pace (min/km) a runner needs to keep in order to finish by given duration.

What is property based testing you might ask?

It simply is an approach to testing where you verify your code’s properties. According to QuickCheck article on wikipedia

… the programmer writes assertions about logical properties that a function should fulfil.

A good example of this are properties of multiplication operation.

  • Every integer multiplied by 0 gives 0.
  • Every integer multiplied by 1 gives same number.

These are the properties of a multiplication function that can be verified. They are quite obvious to anyone who had math in primary school. Your function is probably more complex and testing each of the cases may be cumbersome. Here property based testing comes into play. Given the definition of a property you are able to test your code against large number of cases that might not be obvious to you in the first place.

Why use it?

It helps with proving your solution. Tools which support property based testing can really save you time on writing test cases, as they generate a lot of them. It is worth watching Hillel Wayne in talk Beyond Unit Tests: Taking Your Testing to the Next Level. This talk inspired me to give this a go again. So you may try yourself if you are not convinced.

How to design for property based testing?

To be honest, applying this technique in my work was difficult at first. Problems I’m solving are most of the time not suited for this kind of testing. I thought this is rather obscure tool for specific cases. Then after watching a talk by Gary Bernhardt from SCNA 2012 titled Boundaries I had a "it’s not you it’s me" moment. I realised that software I’m writing may not be designed in a way that is testable in such manner.

The talk is worth watching, however, the spark that lit the fire was one specific thought of his: "creating functional cores". When you have a core of your software (class or function) that is functional, it is more likely that you can use property based testing. I also think that using primitive types may help as well. The tools I have found were limited to such types and constructing more elaborate types could be costly. I’m going to explore contract testing which may have better support for more complex types and objects, as well as static type checking.

What I have used in my small project?

Let’s have a look at some code. I’m using react-native and javascript so I had settled on jsverify. Since I have created a small functional core I could test it pretty easily with regular tests and property tests as well.

test('given one input expect string of 8 chars', () => {
    checkForall(nat, (a) => {
        return toTime(a).length === 8;
    });
});

This test function will verify that my toTime function will create a string out of an int, like this toTime(65) => "00:01:05". I’m testing that no matter the input, my function will create an 8 characters long string.

const timeGenerator = bless({
    generator: nat.generator.map(n => `${n.toString().padStart(2, '0')}`)
});
test('toTime and toSeconds should be commutative', () => {
    checkForall(timeGenerator, timeGenerator, timeGenerator, (t, x, y) => {
        const time = [t, x, y].join(':');
        return toTime(toSeconds(time)) === time;
    });
});

Another test verifies that functions operating on time are commutative. Given the time like "01:49:56" converting it to seconds and then back to time will give the same result. In my opinion, this is a good place to test the property with such tools as jsverify. You will get hundreds of test cases for free based on the definition of your property. You will also receive a failing test case.

● Console

console.info node_modules/jsverify/lib/jsverify.js:334
  OK, passed 100 tests
console.error node_modules/jsverify/lib/jsverify.js:325
  Failed after 2 tests and 0 shrinks. rngState: 036f5d837c9e042b1a; Counterexample: "00"; "30"; "12";  [ '00', '30', '12' ]

I wrote a dozen or more unit tests verifying my solution, however, my input arguments were too simple and obvious. Next, I tried jsverify and it found a bug on first run, simply because I have not anticipated such an input that had been created by this library.

This to me is the best incentive to use property based testing even more 🙂

Categories
logging microservices

Cleaning up messy distributed logs, part 3

If you have been reading along it is my final part of this short story on cleaning up messy logs. I might write one on Kibana itself some day, as it is a difficult tool to use for a beginners. Previous parts of this story can be found here: part 1 and part 2.

This last couple of days at work I could spent more time on fixing logs as new project estimates has finished. Last thing I sorted was syslog parsing, with that done I could think on figuring out how to log tracebacks raised in our services.

Tracebacks are spread over many lines and when they arrive to logstash they are parsed as separate entries and then sent to elasticsearch like wise. So Kibana displays them as separate as well making it really difficult to read. In addition of being separate they are in reverse order.

My idea is to serialize each log message into JSON and then parse it in logstash. As I have probably mentioned I am working on an app using microservices pattern and there is a few services to be done. First candidate is the gateway service, as it’s easiest to test and relatively simple with no additional components beside the service. It is flask app running on gunicorn so to configure logging there is no need to change the code but rather your entrypoint by adding --log-config.

#!/bin/bash
exec gunicorn -b 0.0.0.0:80 --log-config /code/log-config.ini --access-logfile - --reload "gate.app:create_app()"

Config file should be written in ini style.

[loggers]
keys=root

[handlers]
keys=console

[formatters]
keys=default

[logger_root]
level=DEBUG
qualname=root
handlers=console

[handler_console]
class=StreamHandler
formatter=default
args=(sys.stdout, )

[formatter_default]
class=logstash_formatter.LogstashFormatter

This alone handles almost whole application configuration, logs are nicely serialized into JSON with whole traceback.

Categories
python

Collaboration of OAuth and LDAP

The goal

Almost everyone knows OAuth, it is widely used online and has a good reputation. In company where I work we have decided to integrate OAuth2 into our platform (based on microservice architecture, I’ll be saying platform from now on). The trick was that it had to be integrated with existing LDAP server storing user data. User requesting the token had to input his LDAP username and password in order to receive the token. Looking for existing solutions was fruitless and new code had to be written. At that point I didn’t know how this could be achieved. In addition to LDAP I had to use Django as a base of this for providing REST API endpoints. The limitations were clear at this point, risks were unknown. This is not an unusual thing when working as a programmer.

The stack

As I mentioned earlier Django was chosen as the framework. Having decided on the framework it narrowed down number of libraries to use. Fortunately there was already an library adding OAuth to the Django, Django OAuth Toolkit. DOT integrates nicely with Django REST framework and allows you to write your plugins for validating token requests. It supports much more but those two features were the main selling points. Talking to LDAP required a library to do the heavy lifting. There is not much choice here to be honest and I stuck with python-ldap. It is different from what you would expect in terms of python library. Messages are not very useful, docs not very clear but it works and is reliable.

The solution

At the beginning the task seemed really difficult to me. I have only played with OAuth without understanding how it works. It was similar with LDAP. After diving into details it stopped looking that hairy as it turned out I only had to plug into process of authorising the user request. Putting this simply the process of issuing the token would not be started until the user provides credentials that are valid to LDAP.

Django OAuth Toolkit

DOT (Django OAuth Toolkit) is pretty flexible, it provides a setting OAUTH2_VALIDATOR_CLASS where you can define your own validator. This allows to control each step of OAuth2 process. Fortunately I was only concerned with user validation. In order to achieve it I had to write my own validator. Easiest way was to read the default class which has been provided by DOT, namely oauth2_provider.oauth2_validators.OAuth2Validator. It is nicely written, each step has it’s own method that can be replaced. Just had to find a proper one. Proper like validate_user.

def validate_user(self, username, password, client, request, *args, **kwargs):

Signature of the method pictures exactly what needs to be done and lists all the required ingredients. We were connecting to LDAP so this method had to do everything required to validate the user and return bool depending on the result of validation.

Django

Having all the parts connected together the only thing left was to replace the validator class so our new one is used. After doing this all the requests coming in to our OAuth2 server had to conform to our rules which is provide login and password stored in LDAP. It took me longer than expected to grasp the concept and to design the solution. I have created few prototypes each of them with lesser number of CLOCs, until this simple solution came to my mind.

Still don’t fancy LDAP.