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 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 the flat cli. If you run

$ flat start
…

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

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

$ curl localhost:8080/api/…

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

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

$ flat start | jq -R -r '. as $line | try fromjson catch $line'

Now, the access log will be nicely readable on your 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/loggging.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>