Warnings Arrive Before Errors

One-line summary

The moment an error blew up is not the start of the incident but the moment a degradation already in progress crossed the threshold, and the real start lies in the warning interval before it.

Why this is needed

When investigating an outage, most people look at the error log first. It is natural, but errors are the middle of the story.

A typical degradation proceeds like this. There is a change → some requests start to slow down (warning) → as slow requests increase, they hold on to resources → timeouts blow up (errors) → the alarm sounds after crossing the threshold. If you look only at the error log, you see only the last two stages.

So the question to ask in an investigation is not "when did the errors start" but "when did it stop being normal." The time of the first appearance of a warning-level log is often that answer.

How it works

The procedure for overlaying several logs to build causality is this.

1. Decide what each log knows. The access log knows what users experienced. The application log knows why it failed. The slow query log knows where the time went. The deployment history knows what changed. No single log answers every question.

2. Align the time axis. This is what trips people up most often in practice. If one service records in UTC and another in local time with no offset, the same event looks nine hours apart and there is no way to sort them. That is why the rule is to put the offset in the timestamp in structured logs. When dealing with logs that were already produced, you start by first checking how each file writes its times.

3. Extract the first appearance time by level. The first time of warn and the first time of error. The gap between these two is "the time you missed."

4. Cross-check the candidate causes against the times. Deployment history, configuration changes, traffic changes. If the times overlap, it is a strong clue, and if they do not, that candidate is eliminated.

5. Confirm the direction. Correlation is not causation. That A happened before B is a necessary condition, not a sufficient one. If the deployment is at 03:19 and the error at 03:27, the order is right, but whether that deployment is really the cause must be confirmed by whether the symptom disappears after a rollback.

What you see in the field

This is where the value of structured logs shows. If service.version is in a log line, you can answer the question "is it because of a deployment?" from the log alone. If it is not, you have to get a separate deployment history and align the times, and finding someone who knows where that history is takes 30 minutes.

For the same reason, request_id is important. Without it, you have to pair up by guessing from times how a request was processed in which service, and in a system that takes in dozens of requests a second, that guess is almost always wrong.

Finally, one practical sense. There are surprisingly many cases where the answer is contained in the error message. If there is a line db query timeout: table=payments, the layer (data), the symptom (timeout), and the target (the payments table) are already all there. Reading one line properly comes before counting logs.

Absence is a signal too

When overlaying logs, people look only at what was recorded. But often the decisive clue in an investigation is an entry that should be there and is not.

The periodic job is missing only that day. If the log of an hourly batch is empty only around the time of the incident, it means that batch could not run or took a very long time. Because finding what does not run is harder than counting what does, periodic jobs must be made to leave a line even when they succeed. A design that leaves a log only on failure makes it impossible to tell "nothing happened" from "it died and could do nothing."

Only one service's log is missing in that interval. If other services keep recording while just one is quiet, that service stopped or its log shipping was cut. Which one it is splits on whether requests kept going to it from upstream.

There is a request but no response record. If a request remains in the access log but the application log has no result of its processing, the process vanished midway through handling. Then you have to look at the cause of termination at that time.

So when drawing the time axis, it helps to draw the counts of each log per minute together. If you draw only the error counts, none of the three above is visible, but if you draw the total counts as well, "this log alone was cut off in this interval" is revealed at a glance. Considering that most of the investigation time is spent deciding where to look, the value this one chart gives is great.

And this observation leads to a proposal for next time. The items you wrote in the investigation as "I could not confirm because this was missing" are, as they are, the list of logs to add next quarter. If you do not leave that sentence in the report, you will get stuck in exactly the same way at the next outage.

This list is usually short. It is about the request identifier, the deployment version, the time taken to process, and the target name on failure. If you put these four in one log line, there is almost nothing left to overlay in the next investigation.

What you will do in the next lab

You aggregate a JSON Lines application log, a slow query log, and a deployment history each, measure the time gap between the warning and the error, and tie the one cause that the three logs point to together in a document.