What is your approach to debugging a transient problem [closed]

I am working on a system that controls a label printer and occasionally the label printer will print the same label 2,3,…,10 times. The error is transient, occurring once per 3000-4000 (once a month) or so labels.

I am adding tracing to a log file to see what commands are being sent to the printer and state of the printer (we have a state machine defining allowable commands). But since this is a transient problem that may tell me that we had an error, but not why we had the error so I can fix the problem.

I am also trying to get the print job files for the errant jobs so that I can emulate the job in my test environment. Hopefully with these I can reliably make the error occur

I am curious how other might approach diagnosing this type of transient error.

When I hit a really painful real-world problem, sometimes it helps to escape to a land of make-believe where absurd assumptions can be made – and then work backwards from this more pleasant world.

So, let’s remodel your problem as one that…well, sucks less to have to deal with.

Let’s say you know that the next time this function runs and someone tries to print a label, you will get this duplicate behavior. However, this isn’t a perfect world – you can’t change the request or use step-through debugging to walk through the problem one line at a time.

So, how will you figure out what caused it this time, when you can’t just “do that again” and have it happen again?

In short, logging out stack traces and debug info, identifying the most critical question you need to answer. The most obvious is, at a minimum, what EXACTLY is being sent to the printer? Is the printer being told once to print an item, or is it being told over and over and over, or is it being told once but with a quantity specified?

One “simplest possible thing that might work” is to log exactly every single print request, with the expectation that this might be a big log (deal with that in planning). At the very last step before a request is sent to the printer, log exactly what is being sent. Depending in your implementation this might mean wrapping a streamwriter in a buffer, etc – whatever you need to do).

This log should allow you to “reprint” any label using only the information right there in the log, so you can just “resubmit” the request and have it work EXACTLY like if the request was created by the system in the normal fashion.

Then, the human component – you need someone to make a note of when the bug happens, as close to exactly in time as when it happens (so you can go hunting for a rough timestamp), and even attach one of the duplicate labels to your little “bug report” piece of paper with the time on it. If they could make a note of what came before and what came after, that would be even better – but this is obviously subject to business workflows that may be out of your hand. The suspect label and a rough timestamp would be hugely helpful though.

Then you search your potentially huge log files for that event, and you study it. You resubmit that label and see if it happens with that exact, perfect copy of the request – or if it works normally. You look closely at each byte of the request and make sure it is perfectly according to spec and just like any other proper request.

You make sure that this really is exactly what is being sent to the printer, even if you have to have someone setup a networking appliance as an invisible repeater that logs network traffic so you can make sure it really works like you think it works.

In short, you narrow it down – is it the request to the printer that’s bad, or not?

Regardless, you’ll learn something from this. Either you learn it’s software screwing up the request, or it’s “something else”. This is defining and limiting the scope of the problem.

Then what? Well, you can always try a different printer, a new computer generating the requests, new network/cable to the printer, etc. Diagnosis by part-swapping is a time-honored tradition in all mechanical fields 🙂

If all else fails, list this duplicate result as a “rare occurrence, approximately once per month”, unable to reliably replicate, known work-around “throw extra labels away”, etc…declare it’s caused by ghosts, with relevant XKCD:

enter image description here

…and accept that some things are not meant for man to know. Some day the problem will go away, no one will know why, and you get a good story to share with senior programmers some day when “unexplained programming mysteries” becomes the lunch topic.

Assuming you’ve already checked the default logs for exceptions …

Explain the problem to your debug duck.

When it stares at you blankly, go into more detail. Tell the duck how it’s supposed to work. If the stupid duck is still staring at you blankly, go into more detail about how it’s supposed to work.

As you explain each component and interaction, ask the duck whether it can think of any reason (bad input, bad assumptions, protocol/communication mismatch, or errors therein) that could manifest the problem. If neither you or the duck can think of a reason the component could be misbehaving, move on (for now).

But at each step during your explanation, if you have even a faint suspicion of misbehavior, add some tests to your suite.

^{And when your coworkers ask who you’re talking to, simply tell them, “Oh, I wasn’t talking. The duck was.”}

In rough order of difficulty:

Recall that the error may be out of your system. Maybe some person in accounting submitted the same label 10 times. Debug the database it came from, etc. Sometimes when you debug a unit test, it can take you hours to realize there’s a typo in your test data.

Honestly reading your problem my suspicion is your components really
are working as designed, they just, somewhere, somehow, are actually receiving the instruction 10 times, from something you’re not actively considering (human error, duplication happening somewhere else in program, human clicking 10 times on a frozen screen, etc.)
Be sure to print the input of the component causing the error. Then you can reproduce and test locally. Your code is unit-testable, right?
Lots and lots and lots of trace.
Dump a lot of information of this error. Print all stack trace. Create a heap dump.
If you can successfully run it on your local machine rapidly and transiently reproduce it, do so and put a breakpoint where you can. Then you can look around the program much better.
Make usual code improvements. Review all culprit files. Refactor anything that strikes you fishy or wrong. In particular see my first point and refactor your buggy components so they have isolated inputs and are more testable. This is similar to cleaning your room until you find your keys.

I would look for a way to detect the duplicates inside your code, check it at various levels of abstraction, and log when it occurs. You could require a sequence number be submitted with each job, or attach a timestamp to a job, or check a hash. That way if you detect a duplicate at layer 3, but not layer 2, you’ve narrowed down your search criteria.

The other benefit to this approach is you can often work around the symptom even before you know the cause. Assuming you can tell the difference between user-initiated duplicates and bug duplicates, you can just suppress the duplicates when they are detected after the fact. This isn’t an ideal solution, but it’s better than leaving the problem for months or years, especially if the duplicates now are only being caught by manual inspection.

Filed under: softwareengineering - @ 00:28

Thẻ: debugging, logging

Thiết kế website giá rẻ

Danh mục

What is your approach to debugging a transient problem [closed]