Tracing  

Tracing makes a bug easy to spot

By Jessica Kerr   |   December 8, 2021

Today, I found a bug before I noticed it. Like, it was subtle, and so I wasn’t quite sure I saw it—maybe I hadn’t hit refresh yet? Later, I looked at the trace of my function and, boom, there was a clear bug.

Here’s the function with the bug. It responds to a request to /win by saving a record of the win and returning the total of my winnings so far. Can you spot the problem in the TypeScript?

public respondToWin = async (req: express.Request, res: express.Response) => {

  const username = "jessitron";
  const record = new Winnings(username, 1);
  this.winRepository.save(record);

  const { total_winnings } = await this.winRepository
    .createQueryBuilder("wins")
    .select("SUM(winnings)", "total_winnings")
    .where("wins.username = :username", { username })
    .getRawOne();

  res.send("Total so far:" + total_winnings);
}

It’s subtle.

Now here’s a trace in Honeycomb:

A call to /win, with spans showing when everything happens. It shows calls to middleware, the database save (connect, then start, then insert, then commit), and the database select (connect, then select).

Now do you see the bug?

Hint: The problem is that the total_winnings returned does not include the winnings represented by this call.

In the trace, I can see that the select ran concurrently with the save.

Ohhh, so the result of the select definitely is not including the record I just inserted.

In the code, the bug is an absence before this line:

this.winRepository.save(record);

I need to await the promise returned by save. Here’s the fix:

Now I remember that the first time I tested /win, I got back zero total winnings the first time. But then on refresh, it went up and kept going up. I thought maybe I saw that first one wrong—nope, it was a sneaky bug.

This one is sneaky because it’s a problem with something that is not there. It takes an expert to notice a dangerous absence. Meanwhile, in the trace, I saw something that was there: the select running at the same time as the save. If you want to get better at concurrent programming, this is the kind of tool that builds your expertise.

(For the record, this trace is created by auto-instrumentation for Express, TypeORM, and Postgres. It’s generic configuration that works in any Node app with these libraries.)

Spans in a trace are great for showing you when stuff happened in relation to other stuff. Use them to check your asynchronous code. Include tracing in your development process!

You can try out tracing for yourself in Honeycomb—sign up for a free account!


This post was first published on Jessitron’s (aka Jessica Kerr) blog https://jessitron.com/blog/.

 

Related Posts

Ask Miss O11y   Tracing  

Ask Miss O11y: Not Your Aunt’s Tracing

Dear Miss O11y, How is modern observability using tracing, such as Honeycomb, different from the previous distributed tracing software I'm familiar with, like Dapper, at...

Ask Miss O11y   Tracing  

Ask Miss O11y: Baggage in OTel

Miss O11y is delighted to welcome our newest band member: Martin Thwaites! Martin has been a member of the Honeycomb user community practically since its...

Instrumentation   Tracing  

startSpan vs. startActiveSpan

TL;DR: startSpan is easier and measures a duration. Use it if your work won’t create any subspans. startActiveSpan requires that you pass a callback for...