Error Logger Planning

[rowanmanning]

Note: bear in mind this discussion is on a public repo

I'm looking at building the error logger now that we have error serialisation merged, this feels like a sensible place to document our thought process so that we can refer back to it later and/or produce some kind of logging spec so that others can implement the same thing.

I think the error logging middleware should be minimally configurable – we don't want it to be so configurable that we end up with inconsistent logs again. I think being opinionated is good. In the app JavaScript it'd look something like this (where app is an Express application instance):

const createErrorLoggingMiddleware = require('@dotcom-reliability-kit/middleware-log-errors');

app.use(createErrorLoggingMiddleware({
    // config options go here
}));

Here's my first stab at a logging structure. I'm interested in your thoughts:

{
    // I like the idea that we enforce an `event` property to help us detect where
    // the error was caught and handled. I'm not exactly sure what this should be in
    // the case of the Express error handler?
    //
    // For errors which aren't logged by the Express error handler (e.g. ones that
    // are silenced/recoverable), then could we use `SILENCED_ERROR` or `RECOVERABLE_ERROR`.
    event: 'HANDLED_ERROR',

    // This is just the output of `@dotcom-reliability-kit/serialize-error`
    error: {
        name: 'Error',
        // This differs from the top level `event` property and outlines the exact
        // type of error we're logging. This allows us to use Splunk to filter by
        // "handled" vs "unhandled" errors and then drill down further by specific
        // error type.
        code: 'EXAMPLE_CODE',
        message: 'This is an example error message',
        isOperational: true,
        stack: '...',
        statusCode: 503,
        relatedToSystems: [
            'next-example' // the codes of any systems which had a hand in causing this error (e.g. upstream system failed)
        ],
        data: {
            // additional error data
        }
    },

    // Some basic request details so that we can easily debug / compare
    request: {
        id: 'xxx-xxxx-xxx', // the contents of the X-Request-Id header if present
        method: 'GET', // normalized if it's not already
        url: '/categories/example?page=137', // Full path including query params

        // Based on an allow list of HTTP headers. I think just these two by
        // default but the allow list should be configurable per app. We should
        // never just log _all_ the headers.
        headers: {
            accept: '*/*', // "Accept" included because apps may vary the response based on it
            'content-type': null // "Content-Type" included to help debug POST requests
        },

        // (optional) the Express route which the request was matched by
        route: {
            path: '/categories/:categoryId',
            params: {
                categoryId: 'example'
            }
        }
    },

    // Some of the easier-to-retrieve app details
    app: {
        name: 'example', // the app name as set in the `FT-App-Name` header
        region: 'EU' // the contents of the `REGION` environment variable
    }

}

My main questions are:

• What should the event property be for an error which is logged by the Express error handling middleware?

• Should we split request.url into separate path and query properties?

• Are there any other headers we should log by default? Do the existing defaults make sense?

• Should route be non-optional? I'm mostly thinking if we write a spec then this format might not make sense for the app, for example. I moved route into a sub-property of request and think it's fine to be optional

[rowanmanning]

Feedback from @rowanbeentje via Slack:

broadly that looks like a useful structure to me, and one that it’s worth standardising on. 👍 I like the relatedToSystems! In your example would next-example be the erroring app, or an api that the erroring app might be talking to?

Ah yes Alex is working on adding this at the moment. It's a property we're adding to our OperationalError class so that when you're throwing an error which relates to a different failing system(s) you can attribute it correctly. This will allow us to say later "OK, 30% of the errors for ft-next-XXX were caused by failing upstream systems".

I think it’s also worth adding some user identification to the request detail - user agent, original remote IP, request ID (using a CDN request id if available?), user id if known? I know some of that strays towards personal information, but it’s so incredibly useful when spotting patterns in errors or trying to track down issues for users (and it’s one of the recognised good reasons to store identifiers, iirc)

I wonder whether these should be configurable. I like the idea of their inclusion but the number of people who can see our Heroku Splunk logs is pretty big. @alexmuller what do you think? I think request ID if we have it would be excellent 👍

---

edit: I've added request.id to the outline above and have made a note on what relatedToSystems contains.

[alexmuller]

Coming to this late, sorry! I think I would say no to IP addresses. Definite yes to request ID. I am on the fence about user UUID. In general I think yes it's ok to add now because it's centralised so easy to remove later - when we confirm how people in the know feel about PII in this index.

[rowanmanning]

There's now a draft PR for this work here. Feel free to add discussion here or comment on lines in the PR if that's easier

[kavanagh]

I think it’s also worth adding some user identification to the request detail

I was going to suggest the same.

It would be good to use this to encourage the use of the x-request-id header that's in Fastly and Heroku.

It would also be good to standardise the use of the PII collection in logs so that it's more easily auditable... rather than everyone making it up. There could be some switches to allow you to opt in to collect different levels of PII, rather than per field opt ins. Something like:

const createErrorLoggingMiddleware = require('@dotcom-reliability-kit/middleware-log-errors');

app.use(createErrorLoggingMiddleware({
    collectPiiClientData: true, // collects IP and user agent data
    collectPiiMinimalData: true, // user ID, subscription type ...
    collectPiiData: false, // email etc
}));

[rowanmanning]

I agree on ID, I already added in x-request-id here based on Rowan's feedback.

I think I also agree on your thinking about standardising PII. I might prefer an opt-in approach though so that we can easily check every repo which, for example, logs user IP addresses. Something like:

app.use(createErrorLoggingMiddleware({
    outputRequestIp: true,
    outputUserId: true
    // etc
}));

[rowanbeentje]

It would be great if we could get guidance from someone in the know about if these are considered different levels of PII and so whether we can default some to on (eg I think we log User ID in a lot of places right now)...

[kavanagh]

How would the values .event and .error.code differ? Should they be the same value always?

[rowanmanning]

This kind of needs documenting in a broader "how we do logging" piece of work, but I see them as having different purposes. I think event should be the broader class of event that occurred and error code should be more specific.

So in the case of an error which was caught by the Express error handler I think HANDLED_ERROR makes sense, it's the type of event that we're logging. For errors which are logged as part of a controller but don't result in a non-200 status, that could be RECOVERED_ERROR. event would probs be most used/useful when we're not logging an error, e.g. to differentiate a non-error request/response cycle log (RESPONSE_SENT?).

This would give us a way to easily filter down our logs to "ok how many errors are we serving users" vs "how often does X service error and cause a page section to be missing for users".

[kavanagh]

Should we split request.url into separate path and query properties?

Can we rely on splunk to parse urls?

[rowanmanning]

Yep we could do this but as we have the data already as an object in Express with no extra processing maybe it makes sense to add there? I guess we could ask EDO if they have any preference 🤷

[rowanbeentje]

I personally find it much easier to filter/search by explicit named fields rather than having to run complex regexes and named fields 😆

[rowanmanning]

Yeah I was just looking at this again and in the Fastly logs we use a single field request.path which contains both path and query. So is there a danger we'll cause some confusion if I add in a request.path property which does not include query? 🙈

[kavanagh]

Overall comments

• Would we be loosing something with this structure that Splunk gives us because it already understands common log message structures? eg having things like url, statusCode and path as top level properties?

• If a log stream included logs from Heroku and the Application would that mean a) the application doesn't need to do so much logging or is doubling up on log lines? b) the log stream contains 2 entirely different log formats which makes it hard for the engineer to use, once they are parsed by Splunk? Not only does splunk need to interpret these 2 different format, but the fields view on the left hand side of the Splunk UI would have things like statusCode url and request.statusCode and request.url that mean the same thing but come from having logs with 2 different structures?

[rowanmanning]

Would we be loosing something with this structure that Splunk gives use because it already understands common log message structures? eg having things like url, statusCode and path as top level properties?

I think we should consider what's the right information to log in isolation and work towards that everywhere rather than trying to maintain compatibility with existing logs, because there's next to no consistency between apps anyway. E.g. some use a top-level url, some a top level path, some neither or both. I find our Fastly logs the most useful and consistent to work with and they go for nesting properties under sensible top-level properties (e.g. request.path, geolocation.city).

I'm looking at Sam's work on Heroku log drains and I think our logs are gonna change anyway if we switch to them. The log drain will parse out either JSON data or traditional property/value pairs and save them as properties on an event so whatever we go with will Just Work™.

If a log stream included logs from Heroku and the Application would that mean
a) the application doesn't need to do so much logging or is doubling up on log lines?

Yes if we switch to log drains we get the router logs which I think means we should stop logging standard request/response cycle stuff in our apps (unless we really want data that the Heroku route logs doesn't give us).

b) the log stream contains 2 entirely different log formats which makes it hard for the engineer to use, once they are parsed by Splunk? Not only does splunk need to interpret these 2 different format, but the fields view on the left hand side of the Splunk UI would have things like statusCode url and request.statusCode and request.url that mean the same thing but come from having logs with 2 different structures?

We will definitely have two entirely different log formats if we use log drains, because of the router logs vs app logs. I don't think we should attempt to make our logs look like Heroku router ones because they're quite limited. Normally when debugging I would choose to be looking at either Fastly, Heroku router, or Heroku app logs for a system in isolation, the only case I can think of immediately where this might differ is when I want to view all requests with the same ID.

For this case I went with the same property name as our Fastly logs rather than the Heroku router logs:

• Heroku router: request_id top-level property
• Fastly: request.id property
• This proposal: request.id property

So we'd either need to change our Fastly logs to match request_id or we'll have to do some Splunk magic either way to combine these fields if we want to debug a request through our entire stack.

[sjparkinson]

This all looks fascinating!

Yes if we switch to log drains we get the router logs which I think means we should stop logging standard request/response cycle stuff in our apps (unless we really want data that the Heroku route logs doesn't give us).

I agree with this. Focus on the app logs, and 👍 to including region and request ID as a meta value in all logs.

So we'd either need to change our Fastly logs to match request_id or we'll have to do some Splunk magic either way to combine these fields if we want to debug a request through our entire stack.

I think you could simply search for the value, skip any specific key, less magic required. But what to do with logs across different indexes. Maybe worth a discussion to see if there's a better index strategy with this in mind, e.g. all logs for the group go into a single index if index=heroku OR index=restricted_ftdotcom "3B273267-508E-4135-91EB-2278E3A4CFC9" is too painful.

Some open questions on my mind:

• Will every app log relate to a request? Feels optional, when available.
• Log message size limits? Doesn't look like you need to think about that in Heroku, but the Splunk limit is 10,000 bytes per event by default, something to consider when including stack traces.
• What from this is not error specific, e.g. region? Thoughts on a structure for other log levels in an app?

[rowanmanning]

Thanks Sam 🙂

Will every app log relate to a request? Feels optional, when available.

Nope. This work is scoped specifically to logging errors in an Express error handler, but we'll probably take this as the basis for a more generic logging format which works for non-error and non-HTTP cases.

Log message size limits? Doesn't look like you need to think about that in Heroku, but the Splunk limit is 10,000 bytes per event by default, something to consider when including stack traces.

Ooh good info, thank you. I believe we mostly log error stacks at the moment but I wonder if it'd be a good future feature for us to protect against losing logs by trimming the stack if it's over a certain length? Like the top half of an error stack is better than no error being logged right? 🤔

What from this is not error specific, e.g. region? Thoughts on a structure for other log levels in an app?

Yes I'm trying not to jump too far ahead on logging: we don't have the time to focus on all our logging stuff this quarter, just the errors, but I'm trying to make sure we don't write a logging format here that will need to change entirely once we tackle non-error logs.

[sjparkinson]

I believe we mostly log error stacks at the moment but I wonder if it'd be a good future feature for us to protect against losing logs by trimming the stack if it's over a certain length? Like the top half of an error stack is better than no error being logged right? 🤔

I don't think you lose the log, but it may get trimmed, or not render as JSON. I'd say crack on as is, don't add the complexity yet, and we can tweak it as required once there are examples available.

[AniaMakes]

A quick one: given what we've run into the other day, maybe having a region field, wouldn't be a bad idea.

Edit: never mind, I saw it's there at the tail end of the example.

[rowanmanning]

Good idea 👍 I added an app property to my suggested logs:

{
    app: {
        name: 'example',
        region: 'EU'
    }
}

I've also added it into my draft PR in this commit.

[rowanmanning]

Edit: never mind, I saw it's there at the tail end of the example.

@AniaMakes haha it's there at the end of the example because you suggested it 😁 I'm updating the main post as I go so that we don't get duplicate feedback. Thanks for the suggestion

[AniaMakes]

It looks like you may be assuming that any given error you encounter is an instance of HTTP Error (with its status code etc). But I can also see this approach swallowing any error that might originate from an app (now that many repos use package.lock this should be less of an issue) - ask me how I know 😆

[rowanmanning]

We're not assuming that 🙂 although it does look like we are. We have written a module which serialises any error object into a standard format and that's what we're outputting in the logs. Any property which doesn't exist on the thrown error will be set to null and we've been very defensive in our coding to make sure that the error logger can't cause errors itself 😄

The serializeError method takes any error object (and I mean any) and outputs an object with extracted properties, defaulting to this if only the message is specified (often the case with a standard new Error('...')):

{
    name: 'Error',
    code: 'UNKNOWN',
    message: 'This is an error message',
    isOperational: false,
    stack: '...',
    statusCode: null,
    data: {}
}

[rowanmanning]

@rowanbeentje just raised another great point in person. These logs are quite large and maybe we could reduce the footprint by switching out null values for properties just being left off. I want to investigate whether this makes our Splunk searches more complicated. Also @sjparkinson do you have any concerns about the size of these logs if we explicitly null values in the JSON?

[sjparkinson]

Also @sjparkinson do you have any concerns about the size of these logs if we explicitly null values in the JSON?

Less is always better. But broadly we are paying to index up to 1.5TB a day in Splunk, and some amount of storage. We do have headroom, but the cyber security team are looking to make use of that I expect.

I'd recommend we set you up with an index (or repurpose the next index) with a 30 day retention period so we don't need to think about storage.

Then to monitor the index volume there are two dashboard you'll be able to use:

1. Splunk Instance Monitoring Ingest (probably split by Index)
2. Splunk Instance Monitoring HEC (again pick the specific HEC token we set you up with)

There is room to do more sampling from the FT.com Fastly logs to generate headroom.

[sjparkinson]

Sorry fuzzy answer. Again feel free to start with the most simple and we can adjust as we go. Answering the question about "how much are we using" would be a lot more clear if there's a clear list of indexes for a group. The current heroku index doesn't provide clear ownership.

[kavanagh]

Stack traces are probably only needed for unhandled errors, which is where most of the size will come from.

[alexmuller]

I know we should care about Splunk ingest but I don't want to get too bogged down in it right now - that graph that Sam linked shows that the two indexes we in Customer Products care about are right at the bottom end of culprits. I don't think leaving off nulls will help us reduce it by much.