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

Question

I remember when I was in some course of C programming, a teacher once suggested that I 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 potentially hide a bug but I can't find that old code that had this bizarre bug (feature? hmmm).

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

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.

Arithmetic

What's wrong with printf()? :) As long as you know the consequences, I think it's fine. In a lot of (embedded) environments, you don't have debugging tools, and must rely on visual statements (aka. LED1 is on at this point, LED2 at this point, etc.). Use printf() if it's fastest / best for the situation / all you got - But know the types of bugs it could hide! – Inhumation

It's not as simple as that - sometimes a debugger is the right tool, sometimes printf debugging is more appropriate - experience should teach you how to select the right tool for the job and the circumstances. – Okapi

Remember the Taoist framer. noogenesis.com/pineapple/Taoist_Farmer.html – Giantess

In some cases, printf() can actually expose bugs that would otherwise be hidden, such as thread deadlocks (since printf() is of sufficient expense to change timing of threads trying to acquire locks). Kind of incidental to your question, but interesting enough to mention. – Masaryk

@Tim Post: great point! And it can also work the other way around... the expense of printf could create different race conditions, enough to hide a bug. – Arithmetic

@Arithmetic - so could a debugger :) In my experience, more often than not, races are revealed more than hidden when using either method. – Masaryk

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 :-)

Pocked

You have a good point. And so does Tim Post at the question comments. debugging may alter multithreaded code, but printf could do this as well. Good answer +1 – Arithmetic

printf isn't perfect, but it's convenient, and MUCH better than MessageBox() debugging. – Lambent

Answer 2

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.

Morly

+1 We've been developing distributed stuff for several years - logging has often been very helpful. – Preadamite

Yes, but IMO debugging is a not a good option (maybe not even possible) for release-optimized (with no debug symbols) programs used in a production environment. Don't you think? – Arithmetic

@YuppieNetworking: Right, but why not have three configurations - "Debug" with optimizations off and logging, "Release" with optimizations on and logging, "Final" with optimizations on and no logging? – Preadamite

Releasing with logging compiled in but turned off is useful. You ask then the customer to turn it on when they meet unreproducible bugs, that may help you to track them. I've debugged release build with map tables given by the linker, so this is possible, even fun if your notion of fun is twisted enough. But I'll take any alternative I can, especially if there is pressure to meet dead lines. – Morly

Answer 3

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.

Wolfenbarger

+1 for linking those interesting bug category titles - will try to remember them for my next project-management reporting. – Sudatory

Answer 4

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.

Passion

Answer 5

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).

Im

Answer 6

I managed to do this. I was reading data in from a flat file. My faulty algorithm went as follows:

1. get length of input file in bytes
2. allocate a variable-length array of chars to serve as a buffer
   • the files are small, so I'm not worried about stack overflow, but what about zero-length input files? oops!
3. return an error code if input file length is 0

I found that my function would reliably throw a seg fault -- unless there was a printf somewhere in the body of the function, in which case it would work exactly as I intended. The fix for the seg fault was to allocate the length of the file plus one in step 2.

Angarsk

Answer 7

I just had a similar experience. Here's my specific problem, and the cause:

// Makes the first character of a word capital, and the rest small
// (Must be compiled with -std=c99)
void FixCap( char *word )
{
  *word = toupper( *word );
  for( int i=1 ; *(word+i) != '\n' ; ++i )
    *(word+i) = tolower( *(word+i) );
}

The problem is with the loop condition - I used '\n' instead of the null character, '\0'. Now, I don't know exactly how printf works, but from this experience I'm guessing that it uses some memory location after my variables as temporary / working space. If a printf statement results in a '\n' character being written at some location after where my word is stored, then the FixCap function will be able to stop at some point. If I remove the printf, then it keeps on looping, looking for a '\n' but never finding it, until it segfaults.

So in the end, the root cause of my problem is that sometimes I type '\n' when I mean '\0'. It's a mistake I've made before, and probably one I'll make again. But now I know to look for it.

Worthy

Answer 8

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.

Lycaon

I would teach him the nature of the bug: when adding a printf makes it go away, it's probably stack corruption somewhere. Also I would teach him to use valgrind and Dr. Memory, they are the debuggers of the 21th century: they can spot the problem itself. – Contrivance

Answer 9

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();
}

Bickford

All this illustrates is that you shouldn't use global variables and that you definitely shouldn't have side effect functions in a printf statement. :-( (edit: -1 removed, I see your point but just disagree with the conclusions you're implying) – Dardan

This example is a bit flawed... Doing: int res = CalculateB(); printf("%d", res); solves the problem. In general you would add a printf statement to debug the value of variables you have already in your code, if you call functions in your printf calls that's your fault, not printf's :) – Miler

@PlatinumAzure Problem is not especially with global variables. Same could happen if you pass the context. Just don't call functions in the actual parameters logging functions. – Contrivance

Answer 10

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.

Masaryk

Answer 11

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.

Systematist