Merge pod logs by timestamp

When a request passes through several services, each pod writes its own log, and a plain export lists one pod after another. The lines of one request end up far apart, and the order between pods is lost. This guide shows how to put the logs of several pods into one timeline in the Log Playground, with an example you can follow.

When this helps

A checkout, order or payment request fails, and it touched more than one pod.
A Graylog search shows three pods' logs, but they are sorted pod by pod, not by time.
You need to know which service finished first, or which call waited for which.

Five steps

Export each pod's log as plain text, one file per pod. With kubectl, use kubectl logs --timestamps followed by the pod name. In Graylog, export the search results as text for each source. Keep the timestamp at the start of each line.
Open the files in the Log Playground. Press Open log files and select up to three together, or drop them on the page.
Choose Merged by time. Every line goes into one list in time order, and each line is marked with its file.
Fix a clock that is off. If a pod's clock runs behind or ahead, set its clock offset under Options. Check it with a request that touched two pods: its lines should now come in the order they happened.
Follow one request by typing its id in Trace across files. Matching events are shown from every pod, with a count for each file. With Merged by time on, they read as one list in time order.

A worked example

A checkout request, req=8f3a, calls the payments service. The payments pod's clock runs 2 seconds behind the others. Its first line is written at 10:14:00.410, which is really 10:14:02.410. Without an offset, the payments lines sort to the top, before the checkout pod even received the order. Setting the payments file's offset to 2 seconds gives this timeline, with the lines from inventory shown too:

Time	Pod	Line
10:14:02.110	checkout-7d9f	`INFO req=8f3a received POST /orders`
10:14:02.340	checkout-7d9f	`INFO req=8f3a calling payments`
10:14:02.410	payments-5c4b	`INFO req=8f3a charge started`
10:14:03.000	inventory-2b8e	`INFO stock reserved for item 42`
10:14:04.500	inventory-2b8e	`INFO req=9c1d stock reserved for item 7`
10:14:05.380	payments-5c4b	`ERROR req=8f3a charge did not finish`
10:14:05.390	checkout-7d9f	`ERROR req=8f3a payments call timed out after 3000 ms`

Read it top to bottom:

Checkout received the order and called payments at 10:14:02.340. Payments started the charge 70 ms later, at 10:14:02.410.
Inventory's two lines are for other requests, so the trace for req=8f3a leaves them out.
Payments gave up at 10:14:05.380, and checkout timed out 10 ms later. The payments error is the cause, and checkout's timeout is a result of it.

With Merged by time on and the trace set to req=8f3a, the list has five lines from two pods, in that order.

Tips

Set the clock offset before you read the order of events. A few seconds of clock drift is enough to put a cause after its effect.
Keep the timestamp at the start of each exported line. Lines without one cannot be placed in the timeline.
Use the time window to narrow the timeline to the minute that failed, then use the trace.

Open the Log Playground Compare a good run and a bad run

Your files are read in your browser and never uploaded.

Questions

How do I export logs from each pod?

Save each pod's log as a plain text file, one file per pod. With kubectl, use kubectl logs --timestamps followed by the pod name, and redirect the output to a file. In Graylog, export the search results as text for each source. Keep the timestamp at the start of each line.

Can I merge more than three pods?

The playground opens up to three files at once. For more pods, merge the most important three first, or merge the pods of one service and then the next. Each merge is quick, and the timeline keeps the time order.

What if one pod's clock is wrong?

Set a clock offset for that file under the Options button. Enter the number of seconds the pod's clock is behind or ahead. The merged timeline then puts that pod's lines in the right order. Check the offset with a request that touched two pods.

Can I follow one request across pods?

Yes. Type the request id in Trace across files. Matching events are shown from every file, with a count for each file. Turn on Merged by time to read them as one list in time order.

Are my logs uploaded?

No. The files are read in your browser and are never sent anywhere. Closing the tab clears them.