How can NSLogs cause code to not crash?

Question

I had a rather interesting exc_bad_access crash today. After a lot of digging, I came up with the following information (running in simulator):

If I just ran the code, the app would randomly crash at a random point while loading data into my managed object. From what I could tell, it was always crashing when I loaded data into the managed object -- not on the sections that converted from my JSON dict to data to the object actually used (from strings and NSNulls to ints/floats and nils)

Random crashes are, of course, evil, so I tried to step through the process in the debugger, but that didn't prove practical -- I was processing a LOT of objects, so stepping through them one-by-one just didn't work. So I decided to add some NSLogs to track the process and try to spot a pattern that way.

Instantly solved the crash.

Just one NSLog, anywhere in the process, prevented the crash.

I eventually tracked my way up the stack trace and found the actual issue: I was accessing the managed object in a threaded environment, but NOT from within the associated MOC's performBlockAndWait: method. At that point, the crash was incredibly obvious to me -- I'm shocked I didn't have more issues earlier. I'm willing to bet that between having a 'small' test data set of 2-3 objects and having debug code in there with NSLogs, the error was pretty effectively masked earlier... but the question remains:

Why does an NSLog prevent the app from crashing? How on earth could a piece of code without side effects change the execution of the rest of the app? This makes no sense!

Answer 1

Amazingly enough, this is a fairly common situation: I have seen it more than once when enabling logging in a seemingly unrelated place would instantly solve a timing issue somewhere else.

The reason for this is that NSLog, just like many other output functions, has internal synchronization. There is a mutex somewhere that protects access to the internal buffers of NSLog, either in the NSLog itself or in one of the I/O libraries that it uses. This synchronization enables callers to use NSLog from multiple threads. It is this synchronization that changes the timing of your program, affecting a race condition and ultimately solving a crash.

Answer 2

Why does an NSLog prevent the app from crashing? How on earth could a piece of code without side effects change the execution of the rest of the app? This makes no sense!

Indeed this makes a sense. Really.

A single NSLog forces to print something to your console, it takes some fraction of seconds and in between your processing on somethread gets finished and the crash (might be due to un-availability of input is) no-more.

Your error may be due to async call. Your next process starts before finishing previous one. And your next process need data from previos process. NSLog consumes some time.