Home | Blog | Impress | Data Protection Policy

Log your service interfaces (Part II)

February 15, 2019, written by Torsten Mosis, torsten.mosis@systemticks.de

Intro

In our first blog post of this series we have described why it is advisable to complement unit-testing with the concept of structured logging in order to track down the message flow in our system.

The idea of structured logging is to trace the most valuable information of your system in a consistent, determined and machine-readable format.

Since service interfaces are representing the cutting edges of your system, they are predestinated to be instrumented with structured logging data, which enables you to discover potential misuse of your service interfaces.

The range of communication and messaging frameworks is huge. The same applies for the logging infrastructure. Their APIs and facilities drive the way structured logging can be implemented in your project setup.

Hence, this blog post is not about a concrete implementation, but rather a guideline for how to setup effective logging in your specific environment.

So, how do we proceed to enrich our logs with valuable data?

What is valuable information to be logged?

First of all we need to identify the sort of information that is essential for our use-case. That means all the information that helps us drawing conclusions about the interplay of our software components.

Interface signature

Since we are primary monitoring service interface calls, we require to log all the context data for tracing back a single log item to its original interface call unambiguously.

That usually contains the names and/or identifiers of:

  • the interface

  • the software component (that is implementing the interface)

  • the method or function name, that is invoked

  • the parameters carried along with the method or function

To make it a little more understandable imagine followig json structure that carries our meta-data.

{
        "signature": {
                "interface": "Musicplayer",
                "component": "de.systemticks.example.Infotainment",
                "method": {
                        "name": "playSong",
                        "params": {
                                "name": "trackNumber",
                                "value": 3
                        }
                }
        }
}

This structure is arbitrary and just meant for the purpose of illustration. In production code you could choose any other format for sure. Maybe encoded into a popular protocol like protobuf or message pack.

Communication context

Secondary we need to add those kind of data to our logs which allow us to reconstruct the direction of an interface call, together with its involved communication partners:

  • the message type (e.g. request, response, broadcast, event, etc.)

  • the sender of a message

  • the receiver of a message

{
        "signature": {
                "interface": "Musicplayer",
                "component": "de.systemticks.example.Infotainment",
                "method": {
                        "name": "playSong",
                        "params": {
                                "name": "trackNumber",
                                "value": 3
                        }
                }
        },
        "communication": {
                "type": "REQUEST",
                "sender": "de.systemticks.example.Application",
                "receiver": "de.systemticks.example.Infotainment"
        }
}

Additional Meta Data

Depending on our architecture and technical environment it could also be useful to enrich our logs with more valuable meta-data, such as:

  • a message sequence number

  • a session Id

  • an instance Id

  • process Id

  • thread Id

{
        "signature": {
                "interface": "Musicplayer",
                "component": "de.systemticks.example.Infotainment",
                "method": {
                        "name": "playSong",
                        "params": {
                                "name": "trackNumber",
                                "value": 3
                        }
                }
        },
        "communication": {
                "type": "REQUEST",
                "sender": "de.systemticks.example.Application",
                "receiver": "de.systemticks.example.Infotainment"
        },
        "extras": {
                "msgId": 23,
                "pid": 8362
        }
}

With having all that information available in such a consistent and determined way, you can imagine that we can easily process these data programatically and derive valuable results.

Check for available built-in meta-data

We should also have in mind that the project logging facility already provides some useful built-in meta-data for us. The Android logging API, by way of example, forces us explicitly to specify a log level and a tag together with your actual trace data:

private static final String TAG = "MyApplication";
Log.i(TAG, "My important trace")

When seeing the corresponding trace item in the log file we will also realize, that the framework put some additional meta-data for us implicitly:

10-18 11:05:19.112  4612  4628 I MyApplication: My important trace
  • Time infotmation (10-18 11:05:19.112)

  • A process ID (4612)

  • A thread ID (4628)

Other logging frameworks might provide different or additional meta-data, such as line mumbers, class names, method names, etc. Typically the logging content as well as the layout can be configured. In some cases it is also possible to append some additional context information dynamically.

Since in most projects the underlying logging framework is not negotiable we should check at first what it offers to us regarding available built-in meta-data.

Eventually we need to align our collected meta-data with the built-in meta-data in order to avoid redundancies.

How to log consistently?

As all of us know: software interfaces evolve over time. But logs can remain the same if they are implemented manually and are not maintained together with the changed interface. This is a potential risk, since a log analysis might lead us into a wrong direction or even lets us draw wrong conclusions, simply because the log data is not consistent with the interface specification.

Thus, whenever possible we should avoid manual logging of service interface calls.

Generated logging over manual logging

Let’s suppose that we are in the lucky situation, that in our project setup the service interfaces are available in declarative models, specified with an interface description language (IDL) or any other machine-readable schema. These models are the input for generating the boiler-plate code that handles the sending and receiving of messages. This is the place for us to hook into and generate the corresponding logging calls as well.

Non-intrusive logging

In some technical environments the system even might offer us facilities for hooking into the message transport mechanism itself. If this is the case, we should prefer that way and intercept the messages within the framework. The application code would then remain unchanged.

Aspect-oriented logging

We also might have the chance to come across a technical landscape which allows using aspect-oriented programming (AOP). Some programming languages like Java have AOP implementations available. It enables the separation of cross-cutting concerns - like logging - from the application code.

Check what your infrastructure is offering, but usually there is a way for avoiding manual logging.

Where should it be logged

Finally we need to decide where we are integrating our logs. This highly depends on our used communication patterns.

In case of synchronous communication we need to log the method entries and method exits. If asynchronous communication is used we might need to log the method entries for the incoming requests and for the outgoing responses.

For monitoring brodcasts (or events) it is probably good to log when the server is publishing the data (or sending the broadcast), but also when the clients are receiving the data.

We now have a guideline and methodology at hand how to apply structured logging for service interfaces. We have an idea of what, how, where and when to log valuable data in a consistent manner.

In the upcoming blog post we will demonstrate by an example how this methodology could be implemented and how the resulting logs can be analyzed with a tool like EB solys.