Reading a log file

The idea

Almost every log question is the same three moves. Split each line into its fixed leading fields and the free text that follows. Choose a key: the level, the service, the minute. Then aggregate by that key.

The moves are easy. What breaks is the splitting, because the message is free text and free text contains whatever the author felt like typing, including the character you are splitting on. So the split has to be bounded: take the fields you know about from the left, and leave the rest alone.

Once the stream is keyed, the same lines answer very different questions depending on how you slice time. Per-minute counts show load. Consecutive failures show an incident. Idle gaps show sessions. All three come from the same pass.

How it works

One bounded split, then a dictionary. The bound is the entire trick.

def parse(line):
    # exactly three splits: timestamp, level, service, and THEN the rest,
    # whole, including any spaces the message happens to contain
    ts, level, service, message = line.split(" ", 3)
    return ts, level, service, message

def by_key(lines, key):
    counts = {}
    for line in lines:
        ts, level, service, _ = parse(line)
        k = {"level": level, "service": service, "minute": ts[:5]}[key]
        counts[k] = counts.get(k, 0) + 1
    return counts

def first_streak(lines, service, n):
    """The first index where `service` has failed n times in a row.
    Any non-error line for that service resets the run to zero."""
    run = 0
    for i, line in enumerate(lines):
        _, level, svc, _ = parse(line)
        if svc != service:
            continue                 # other services do not interrupt the run
        run = run + 1 if level == "ERROR" else 0
        if run == n:
            return i
    return -1

Bucketing by minute is a floor, not a round: second // 60. Rounding puts the second half of every minute into the next one, which shifts every spike on the chart by thirty seconds and makes a traffic graph disagree with the incident timeline.

Cost

Watch out for

• An unbounded split. line.split(" ") on a log line with a five word message returns eight fields, and the message becomes whatever the fourth one is. Bound the split to the number of fixed fields, and the message survives intact whatever is in it.
• Empty buckets that vanish. Counting per minute with a dictionary produces entries only for minutes that had traffic. A chart built from those keys silently closes the gaps, so an outage where nothing was logged looks like normal service. Range over every minute between first and last, not over the keys you happen to have.
• Rounding the bucket instead of flooring it. round(second / 60) puts 10:00:45 into minute 1. Now the traffic chart and the incident timeline disagree by up to half a minute, and every investigation starts with reconciling them.
• Streaks that other services reset. A run of failures for one service is not interrupted by a healthy line from a different one. Counting a single global run makes a busy neighbour hide a dying service. One counter per service, and only that service's lines touch it.
• Assuming the file is in time order. Merged logs from several machines usually are not, and a session or gap calculation on unsorted lines produces sessions that never happened. Either sort first, or say in the function's name that it requires sorted input.
• Levels that are not the token you expected. Real logs carry WARNING and WARN, or a level in brackets, or lowercase. Deciding on one normalisation at the parse boundary is cheap. Discovering the mismatch inside three different aggregations is not.

Worked example

Take 10:09:14 ERROR billing charge declined card expired, with two spaces in the middle of the message.

An unbounded split gives six tokens, and a parser that trusts positions reports the message as "charge". Split with a count of three and the fourth part is charge declined card expired, double space and all, which is exactly what was logged and exactly what a search for that message will need to match.

Now key the same stream three ways without re-parsing it. By level, the counts say how healthy the window was. By service, they say who is responsible. By minute, they say when. And the run of three consecutive auth errors early in the file is invisible to all three counts: it is a property of the order, not the totals, which is why an incident rule reads the sequence rather than the summary.