Logging Custom Fields #

FLAT writes JSON logs for events like client access or upstream requests. The structured log events are easily extensible.

The access log already provides a basic set of information about the incoming request. However, when inspecting (any) logs quickly the wish for more contextual information will arise.

Here are some ideas for fields to augment your logs with:

A random “Tab” ID sent by the client to correlate API requests to a single SPA instance
The version or git revision of your FLAT project
A message to distinguish reasons for errors
The staging role (dev/test/prod) or data center identifier passed in by environment variables
The client’s real IP address as advertised by a downstream system (e.g. your load balancer)
User and role from a JWT token
…

We want all of that!

To play with logging, you need a FLAT project. If you don’t have on, yet, have a look into the tutorial to get started.

Reading Logs #

Before we start customizing our logs, we need to setup our workplace in order to see what we are doing. Where can we inspect FLAT logs?

FLAT runs in Docker and writes its log lines to stdout and stderr. (If you don’t know the two, don’t fear.) In a development setup, we usually start FLAT with

$ docker compose up

and will see the log output in our terminal. Some startup messages are plain text lines. The debug output will be text, too.

However, once we call your API with curl we will see JSON lines in your terminal:

$ curl localhost:8080/api/…

{"timestamp":"2019-10-15T15:49:13+00:00","type":"flat_access",…}

We can have the JSON colored and pretty printed by piping the output to the jq command:

$ docker compose up --no-log-prefix | jq -R -r '. as $line | try fromjson catch $line'

Now, the access log will be nicely readable on our terminal:

…
{
  "timestamp": "2019-10-15T15:49:13+00:00",
  "type": "flat_access",
  "requestID": "XaXqeccky00IowY@OUgG8AAAAAA",
  "url": "http://localhost:8080/api/…",
  "path": "/api/…",
  "status": 200,
  "method": "GET",
  "agent": "curl/7.54.0",
  "referrer": "",
  "mime": "application/json",
  "realtime": 0.08935,
  "bytes": 1387,
  "requestbytes": 0,
  "flow": "flow.xml",
  "requestmime": "",
  "location": ""
}

Adding a Log Field #

Now that we know where our logs go, we’re finally ready to add fields!

We will start with a simple task: Let’s add a field to our log that contains a fixed string.

This can actually be useful: if you share a log server with other FLAT projects, the field let’s you identify the originating project. (In production, your log shipper will probably provide this information already in its log envelope.)

Log fields can be registered with the log action. The action takes a JSON template as its argument. For our fixed field, we write:

<log>
{
  "project": "myAPIProject"
}
</log>

A good place for this action is the init flow because it is started for all API flows.

Call your FLAT API again and watch the logs:

$ curl localhost:8080/api/…

{
  "timestamp": "2019-10-15T15:49:13+00:00",
  "type": "flat_access",
  …
  "project": "myAPIProject"
}

Our first custom log field has hit the terminal!

Adding Dynamic Log Fields #

With JSON templates you can use expressions to dynamically set field names and values.

Let’s assume, you use the environment variable FLAT_STAGE to tell your project in which deployment stage it is running. Possible values could be dev, qa and prod. Another variable FLAT_DC holds the airport code of the data center, e.g. CGN or LON.

To include this information into the log, we add more fields to our log action:

<log>
{
  "project": "myAPIProject",
  "stage": {{ $env/FLAT_STAGE ?? "unknown" }},
  "location": {{ $env/FLAT_DC }}
}
</log>

Notice, how we can provide default values for missing data. If both of the variables are not set, a log may look like this:

{
  "timestamp": "2019-10-15T15:49:13+00:00",
  "type": "flat_access",
  …
  "project": "myAPIProject",
  "stage": "unknown"
}

stage is always defined. But location is missing, because its expression has evaluated to null. Nulled fields don’t show up in the log.

Structured Log Fields #

Your custom log fields are not restricted to the top-level field-list. If you have more fields, that belong together, you can group them in an object.

In our case, we might want to gather information about the environment:

<log>
{
  "project": "myAPIProject",
  "env": {
    "stage": {{ $env/FLAT_STAGE ?? "unknown" }},
    "location": {{ $env/FLAT_DC }}
  }
}
</log>

{
  "timestamp": "2019-10-15T15:49:13+00:00",
  "type": "flat_access",
  …
  "project": "myAPIProject",
  "env": {
    "stage": "production",
    "location": "CGN"
  }
}

Using Request Data #

Clients provide a lot of useful information in the HTTP request headers. We can easily use them to augment our log:

<log>
{
  "project": "myAPIProject",
  "env": {
    "stage": {{ $env/FLAT_STAGE ?? "unknown" }},
    "location": {{ $env/FLAT_DC }}
  },
  "request": {
    {{: $request/headers/x-real-ip | $request/headers/x-forwarded-proto }}
  }
}
</log>

Here, we use the pair producer {{: to create log fields from headers. If present, the headers will show up in the log:

$ curl -H "X-Forwarded-Proto: https" localhost:8080/api/…

{
  "timestamp": "2019-10-15T15:49:13+00:00",
  "type": "flat_access",
  …
  "project": "myAPIProject",
  "env": {
    "stage": "production",
    "location": "CGN"
  },
  "request": {
    "x-forwarded-proto": "https"
  }
}

Every API has to rely on user input for its operation. But we should do so with care. (Every client could sent a X-Forwarded-Proto header. The administrator should take measures to override this header in the SSL offloader.)

For logging alone, the JSON armor prevents format breakouts and log attacks. HTTP request headers and query strings are limited in size. However, you could use Swagger to further validate a parameter’s format.

Testing #

Log augmentation with the log action belongs to our project code. Therefore, we would like to test that! This can be done by using the get-log() function in a FLAT test.

Put this into tests/logging.xml:

<flat-test>
  <eval out="$user">"alice"</eval>
  <log>
  {
    "user": {
      "name": {{ $user }}
    }
  }
  </log>
  <assert>
  [
    [ "get-log()/user/name", "alice", "user/name was logged" ]
  ]
  </assert>
</flat-test>

You can run the test with this command:

$ flat test tests/logging.xml
1..1
ok 1 tests/logging.xml: 1 assertions

In a real project, you would rather send a request to your FLAT API and check if the log was written as expected:

<flat-test>
  <!-- fake env vars -->
  <set-env>
  {
    "FLAT_STAGE": "test",
    "FLAT_DC": "myLaptop"
  }
  </set-env>

  <test-request>
  {
    "path": "/api/path",
    "headers": {
      "X-Forwarded-Proto": "https"
    }
  }
  </test-request>

  <eval out="$log">get-log()</eval>
  <assert>
  [
    [ "$log/env/stage", "test", "FLAT_STAGE was logged" ],
    [ "$log/env/location", "myLaptop", "FLAT_DC was logged" ],
    [ "$log/request/x-forwarded-proto", "https", "XFP was logged" ]
  ]
  </assert>
</flat-test>