Educational example to show that sometimes printf as debugging may hide a bug

Question

Hello all,

I remember when I was in some course of C programming, a teacher once suggested to use printf to watch the execution of a program that I was trying to debug. This program had a segmentation fault with a cause that I cannot remember at the moment. I followed his advice and the segmentation fault disappeared. Fortunately, a clever TA told me to debug instead of using printfs. In this case, it was an useful thing to do.

So, today I wanted to show someone that using printf could probably hide a bug. I can find that old code that had this bizarre bug (feature? hmmm).

Question: Have any of you encounter this behavior as well? How could I reproduce something like this?

Thanks a lot!

Edit:

I see that my question part orients my opinion to "using printf is wrong". I am not exactly saying that and I don't like taking extreme opinions, so I'm editing a bit the question. I agree that printf is a good tool, but I just wanted to recreate a case where printfs make a segmentation fault disappear and hence, prove that one must be careful.

Answer 1

There are cases when adding printf calls alters the behaviour of the code, but there are also cases when debugging does the same. The most prominent example is debugging multithreaded code, where stopping the execution of a thread may alter the behaviour of the program, thus the bug you are looking for may not happen.

So using printf statements does have valid reasons. Whether to debug or printf should be decided on a case by case basis. Note that the two are not exclusive anyway - you can debug code even if it contains printf calls :-)

Answer 2

IMHO Every developer still relies here and there on printouts. We just learned to call them "detailed logs".

More to the point, the main problem that I've seen is that people treat printfs like they're invincible. For instance, it is not rare in Java to see something like

System.out.println("The value of z is " + z + " while " + obj.someMethod().someOtherMethod());

This is great, except that z was actually involved in the method but that other object was not, and there's to ensure you won't get an exception from the expression on obj.

Another thing that printouts do is that they introduce delays. I've seen code with race conditions sometimes "get fixed" when printouts are introduced. I would not be surprised if some code uses that.

Answer 3

Well, maybe you could teach him how to use gdb or other debugging programs ? Tell him that if a bug disappear juste thanks to a "printf", then it didn't really disappear and could appear again latter. A bug should be fixed, not ignored.

Answer 4

Sounds like you're dealing with a heisenbug.

I don't think there's anything inherently "wrong" with the use of printf as a debugging tool. But yes, like any other tool, it has its flaws, and yes there has been more than one occaision where the addition of printf statements created a heisenbug. However, I've also had heisenbugs show up as a result of memory layout changes introduced by a debugger, in which case printf proved invaluable in tracking the steps that lead to the crash.

Answer 5

You'd have a very hard time to convince me not to use logging (and printf in this situation is an had hoc form of logging) to debug. Obviously to debug a crash, the first things is to get a backtrace and use purify or a similar tool, but if the cause is not obvious logging is by far one of the best tool you can use. A debugger allows you to concentrate on details, logging give you a bigger picture. Both are useful.

Answer 6

This will give you a division by 0 when removing the printf line:

int a=10;
int b=0;
float c = 0.0;

int CalculateB()
{
  b=2;
  return b;
}
float CalculateC()
{
  return a*1.0/b;
}
void Process()
{
  printf("%d", CalculateB()); // without this, b remains 0
  c = CalculateC();
}

Answer 7

What would be the debugging case? Printing a char *[] array prior to calling exec() just to see how it was tokenized - I think thats a pretty valid use for printf().

However, if the format fed to printf() is of sufficient cost and complexity that it may actually alter program execution (speed, mostly), a debugger may be the better way to go. Then again, debuggers and profilers also come at a cost. Either one may expose races that might not surface in their absence.

It all depends on what you are writing and the bug you are chasing. The tools available are debuggers, printf() (grouping loggers into printf as well) assertions and profilers.

Is a blade screwdriver better than other kinds? Depends on what you need. Note, I'm not saying assertions are good or bad. They're just another tool.

Answer 8

One way to deal with this is to set up a system of macros which makes it easy to turn off printfs w/o having to delete them in your code. I use something like this:

#define LOGMESSAGE(LEVEL, ...) logging_messagef(LEVEL, __FILE__, __LINE__, __FUNCTION__, __VA_ARGS__);

/* Generally speaking, user code should only use these macros.  They
 * are pithy. You can use them like a printf:
 *
 *    DBGMESSAGE("%f%% chance of fnords for the next %d days.", fnordProb, days);
 *
 * You don't need to put newlines in them; the logging functions will
 * do that when appropriate.
 */
#define FATALMESSAGE(...) LOGMESSAGE(LOG_FATAL, __VA_ARGS__);
#define EMERGMESSAGE(...) LOGMESSAGE(LOG_EMERG, __VA_ARGS__);
#define ALERTMESSAGE(...) LOGMESSAGE(LOG_ALERT, __VA_ARGS__);
#define CRITMESSAGE(...) LOGMESSAGE(LOG_CRIT, __VA_ARGS__);
#define ERRMESSAGE(...) LOGMESSAGE(LOG_ERR, __VA_ARGS__);
#define WARNMESSAGE(...) LOGMESSAGE(LOG_WARNING, __VA_ARGS__);
#define NOTICEMESSAGE(...) LOGMESSAGE(LOG_NOTICE, __VA_ARGS__);
#define INFOMESSAGE(...) LOGMESSAGE(LOG_INFO, __VA_ARGS__);
#define DBGMESSAGE(...) LOGMESSAGE(LOG_DEBUG, __VA_ARGS__);
#if defined(PAINFULLY_VERBOSE)
#   define PV_DBGMESSAGE(...) LOGMESSAGE(LOG_DEBUG, __VA_ARGS__);
#else
#   define PV_DBGMESSAGE(...) ((void)0);
#endif

logging_messagef() is a function defined in a separate .c file. Use the XMESSAGE(...) macros in your code depending on the purpose of the message. The best thing about this setup is that it works for debugging and logging at the same time, and the logging_messagef() function can be changed to do several different things (printf to stderr, to a log file, use syslog or some other system logging facility, etc.), and messages below a certain level can be ignored in logging_messagef() when you don't need them. PV_DBGMESSAGE() is for those copious debug messages which you will certainly want to turn off in production.

Answer 9

I remember once trying to debug a program on the Macintosh (circa 1991) where the compiler's generated cleanup code for a stack frame between 32K and 64K was erroneous because it used a 16-bit address addition rather than a 32-bit one (a 16-bit quantity added to an address register will be sign-extended on the 68000). The sequence was something like:

  copy stack pointer to some register
  push some other registers on stack
  subtract about 40960 from stack pointer
  do some stuff which leaves saved stack-pointer register alone
  add -8192 (signed interpretation of 0xA000) to stack pointer
  pop registers
  reload stack pointer from that other register

The net effect was that everything was fine except that the saved registers were corrupted, and one of them held a constant (the address of a global array). If the compiler optimizes a variable to a register during a section of code, it reports that in the debug-information file so the debugger can correctly output it. When a constant is so optimized, the compiler apparently does not include such information, since there should be no need. I tracked things down by doing a "printf" of the address of the array, and set breakpoints so I could view the address before and after the printf. The debugger correctly reported the address before and after the printf, but the printf outputted the wrong value, so I disassembled the code and saw that printf was pushing register A3 onto the stack; viewing register A3 before the printf showed that it had a value rather different from the address of the array (the printf showed the value A3 actually held).

I don't know how I ever would have tracked that one down if I hadn't been able to use both the debugger and printf together (or, for that matter, if I hadn't understood 68000 assembly code).