From Traceback to Instrumentation

Goal

You will be able to pin down the cause from a traceback within 3 minutes, and, rather than stopping at the fix, also plant instrumentation for next time.

Why it matters

A traceback is read from bottom to top. The bottom line tells you the exception type and the reason, the line right above it is the line of code that actually blew up, and the upper part is the path that led there. Also, the exception message usually contains the actual value that caused the problem, so if you search the source data for that value, you find the culprit row in a few seconds.

Another important thing is the fact that a traceback goes out not to standard output but to standard error. It is truly common for 2>&1 to be missing from a customer's batch job cron setup so that, for months, the cause of the failure has been recorded nowhere. When you hear "there's nothing in the log," check this first.

Finally, if you fix it and stop there, the same thing repeats next week. One line that makes it record the skipped rows cuts the next investigation from 30 minutes to 1 minute. This is planting instrumentation, and it is also the standard approach for problems that cannot be reproduced.

Steps

1. Create /root/trace and copy /opt/app/report.py to /root/trace/report.py.
2. Save the output of the failing run, including standard error, to /root/trace/traceback.txt.
3. Write only the name of the exception that occurred in /root/trace/error_type.txt.
4. Write the id value of the row that first stopped the run in /root/trace/bad_row.txt.
5. Fix /root/trace/report.py according to the spec so that it finishes with exit code 0.
6. Save the output of the fixed script to /root/trace/out.txt. It must show rows=18 total=130400.
7. Add instrumentation so that skipped rows are recorded in /root/trace/skipped.log, one per line.
8. Run the same script against /opt/data/orders_api.csv and save the output to /root/trace/out2.txt.

Notes

• python3 report.py > /root/trace/traceback.txt 2>&1
• With grep -n abc /opt/data/orders.csv you can find the value from the exception message in the source.
• report.py takes a file path as an argument. Step 8 takes the form python3 report.py /opt/data/orders_api.csv.
• The cleanest approach is to send diagnostic output to standard error and capture it into a file with redirection. For example: python3 report.py > out.txt 2> skipped.log
• The step 8 file has no rows to skip. Send it to a different path or discard it so that the step 8 run does not overwrite skipped.log.
• Common mistake 1: forgetting 2>&1 in step 2 and ending up with an empty file.
• Common mistake 2: printing the skipped rows only to the screen in step 7. They must be left in a file for the next person to see.

Make a working copy

Create /root/trace and copy /opt/app/report.py to /root/trace/report.py.

Create /root/trace and copy /opt/app/report.py into it.

Capture the failure output

Save the output of the failing run, including standard error, to /root/trace/traceback.txt.

A traceback goes out to standard error, not standard output. The redirection needs 2>&1.

Write the exception type

Write only the name of the exception that occurred in /root/trace/error_type.txt.

The part before the colon on the bottom line of the traceback is the exception name. Write only the name.

Identify the first failing row

Write the id value of the row that first stopped the run in /root/trace/bad_row.txt.

The exception message contains the actual value. Find the id of the row that has that value in the source CSV.

Make it exit with code 0

Fix /root/trace/report.py according to the spec so that it finishes with exit code 0.

The spec in the docstring lists three conditions for a valid row. If a row does not meet them, it must be skipped and processing must continue.

Save the aggregate result

Save the output of the fixed script to /root/trace/out.txt. It must show rows=18 total=130400.

Pass the fixed script's output to the file as it is. Both values, rows= and total=, are needed.

Record the skipped rows

Add instrumentation so that skipped rows are recorded in /root/trace/skipped.log, one per line.

This is the step where you plant instrumentation so that the next time the same thing happens, it is over in 1 minute. Leave one line per skipped row.

Try it on a different input

Run the same script against /opt/data/orders_api.csv and save the output to /root/trace/out2.txt.

A fix tuned only to today's data is not a fix. Run the same script on /opt/data/orders_api.csv and save the result.