Why doesn't this crash?

Question

I'm attempting to narrow down a bug to a minimum reproducible case and found something odd.

Consider this code:

static NSString *staticString = nil;
int main (int argc, const char * argv[]) {
    NSAutoreleasePool * pool = [[NSAutoreleasePool alloc] init];

    if (staticString == nil) {
        staticString = [[NSArray arrayWithObjects:@"1", @"2", @"3", nil] componentsJoinedByString:@","];
    }   

    [pool drain];

    NSLog(@"static: %@", staticString);
    return 0;
}

I'm expecting this code to crash. Instead, it logs:

2011-01-18 14:41:06.311 EmptyFoundation[61419:a0f] static: static: 

However, if I change the NSLog() to:

NSLog(@"static: %s", [staticString UTF8String]);

Then it does crash.

edit a bit more info:

After draining the pool:

NSLog(@"static: %@", staticString);  //this logs "static: static: "
NSLog(@"static: %@", [staticString description]); //this crashes

So apparently invoking a method on the string is good enough to get it to crash. In that case, why doesn't logging the string directly cause it to crash? Shouldn't NSLog() be invoking the -description method?

Where is the second "static: " coming from? Why isn't this crashing?

---

Results:

Both Kevin Ballard and Graham Lee are correct. Graham's correct in realizing that NSLog() is not invoking -description (as I was erroneously assuming), and Kevin is almost definitely correct that this is a weird stack-related issue with copying a format string and a va_list around.

1. NSLogging and NSString does not invoke -description. Graham elegantly showed this, and if you trace through the Core Foundation sources that do the logging, you'll see that this is the case. Any backtrace originating inside NSLog shows that it invokes NSLogv => _CFLogvEx => _CFStringCreateWithFormatAndArgumentsAux => _CFStringAppendFormatAndArgumentsAux. _CFStringAppendFormatAndArgumentsAux() (line 5365) is where all of the magic is going on. You can see that it's manually going through to find all the % substitutions. It only ends up invoking the description copy function if the type of the substitution is a CFFormatObjectType, the description function is non-nil, and the substitution hasn't already been handled by another type. Since we've shown that the description is not getting copied, it's reasonable to assume that an NSString gets handled earlier (in which case it's probably going to be doing a raw byte copy), which leads us to believe...
2. There's a stack error going on here, as Kevin surmises. Somehow the pointer that was pointing to the autoreleased string is getting substituted to a different object, which happens to be an NSString. So, it doesn't crash. Weird. However, if we change the type of the static variable to something else, like an NSArray, then the -description method does get called, and the program does crash as expected.

How truly and utterly strange. Points go to Kevin for being the most correct about the root cause of the behavior, and kudos to Graham for correcting my fallacious thinking. I wish I could accept two answers...

Frohman

Why are you expecting it to crash? – Fractional

NSLog([NSString stringWithFormat:@"static: %@", staticString]) does cause a crash, so it's really due to a different behavior of NSLog when handling %@ – Salicylate

Nitpicks: I believe your analysis wrt/ "Results:" & _CFStringAppendFormatAndArgumentsAux is incorrect. For each %@, _CFStringAppendFormatAndArgumentsAux will try 1) a copyDesc function that was passed in via an argument, 2) __CFCopyFormattingDescription, which for ObjC objects results in trying _copyFormattingDescription:, and finally 3) CFCopyDescription, which for ObjC objects results in _copyDescription, and disassembly shows NSObject defaults to calling -description. Therefore, 99% of the time, %@ will result in -description being called. – Phosphide

Of course, for NON-ObjC objects (i.e., Core Foundation objects), __CFCopyFormattingDescription and CFCopyDescription end up doing special CF stuff. Each CF object has an entry in CFRuntimeBase for copyFormattingDesc and copyDebugDesc (which correspond to the previously mentioned functions). For a CFString object, this amounts to calling __CFStringCopyFormattingDescription, which does nothing more than a CFStringCreateCopy of the string. – Phosphide

Therefore, for "most cases", within _CFStringAppendFormatAndArgumentsAux a %@ for "strings" (most of which are CFString objects in practice) amounts to calling CFStringCreateCopy, the result of which is CFStringAppend'ed to the mutable string result being built up. – Phosphide

@Phosphide Graham clearly showed that -description is not getting called when logging NSString objects, which means that some short circuiting is happening somewhere. I was thinking that it would be called, and that assumption was leading me to expect the crash. – Frohman

@Dave There's some confusion here- are you actually talking bona-fide NSString objects, or Core Foundation CFString objects masquerading via toll-free bridging as NSString objects? If it's the later, then it's non-sensical to talk about -description being called- you need to look at (CF-550) CFString.c:5746 -> CFRuntime.c:799 -> CFString.c:1141 -> CFString.c:1126 -> CFString.c:5752 for the Core Foundation internal/private "equivalent" for -description of a CFString object. – Phosphide

@Dave See my comment on @Grahams answer. -description is definitely getting called, it's just being "automagically" suppressed by NSLog() because (I assume, probably has to do with multithreaded locking issues) NSLog() blocks (i.e., returns immediately without doing any work) additional calls to NSLog() while a NSLog() is currently being processed. – Phosphide

Answer 1

My best guess for what you're seeing is that NSLog() copies the format string (probably as a mutable copy), and then parses the arguments. Since you've dealloc'd staticString, it just so happens that the copy of the format string is being placed into the same location. This is causing you to see the "static: static: " output that you described. Of course, this behavior is undefined - there's no guarantee it will always use the same memory location for this.

On the other hand, your NSLog(@"static: %s", [staticString UTF8String]) is accessing staticString before the format string copy happens, which means it's accessing garbage memory.

Makepeace

I doubt it copies the string, but it probably does -getCString: or similar so that it can use printf-style functions on the content. It may be those chars that you see. – Monarch

@Graham actually, it's a custom implementation of printf(). I'll be editing my question with what I've found. – Frohman

OK, I've just stepped through NSLog(), it calls into CFStringCreateWithFormatAndArgumentsAux() which builds a new CFMutableString. In fact, that makes me think that it doesn't need to copy the string because it isn't doing any in-place modifications. In other words it's not doing vsprintf() on the format string, which was what I originally expected. – Monarch

@Graham If it used -getCString: then the resulting value would be a C String, which would crash if passed to %@. – Makepeace

@Graham Sounds like what's really going on is it's creating a new mutable string, appending the text before the first token (e.g. @"static: "), and then processing the token. This new mutable string exists in the same memory location that staticString did, so when it processes the %@ token it's inserting the value of the mutable string, which is @"static: ", which turns the result into @"static: static: ". – Makepeace

@Kevin no, I meant it might use -getCString: on the format string. One possible implementation of any of this type of function is to get a C string from the format string then use sprintf-style substitution on it. Anyway, it doesn't, though another implementation of NSLog() that I've seen does (or rather, it calls -[NSString initWithFormat: locale: arguments:] and that does the above). – Monarch

@Graham Yes, I know what you mean. My point is that using -getCString: and sprintf would not cause the described behavior, of outputting @"static: static: ". Instead, it would crash. – Makepeace

@Graham yes, it builds the resulting string on-the-fly and does not use vsprintf() or anything like that. – Frohman

Answer 2

Your assumption that NSLog() calls -description on an NSString instance is faulty. I just added this category:

@implementation NSString (GLDescription)

- (NSString *)description {
  NSLog(@"-description called on %@", self);
  return self;
}

@end

It doesn't cause a stack overflow, because it doesn't get called recursively. Not only that, but if I insert that category into the code in your question, I find this output:

2011-01-18 23:04:11.653 LogString[3769:a0f] -description called on 1
2011-01-18 23:04:11.656 LogString[3769:a0f] -description called on 2
2011-01-18 23:04:11.657 LogString[3769:a0f] -description called on 3
2011-01-18 23:04:11.658 LogString[3769:a0f] static: static: 

so we conclude that NSLog() doesn't call -description on an NSString it comes across in its args. Why you get the static string twice is likely a quirk of the data on the stack when you erroneously access the released staticString variable.

Monarch

This isn't actually stack-related. See my answer for my best guess as to what's going on, but in short, NSLog most likely copies its format string, and the copied string ends up in the same memory location as the original staticString. – Makepeace

As for -description, it may be possible that, for NSString, it's actually falling back to the CFCopyDescription() behavior. Or it could be smart about strings, it's hard to know for certain. – Makepeace

Actually, you need to use something along the lines of fprintf(stderr,"-description called on %s\n", [self UTF8String]); instead of NSLog(). NSLog() appears to "automagically" suppress additional output via NSLog() when it's already in the middle of NSLoging. That's why the expected -description isn't showing up. It does show up when you use this comments fprintf() code. – Phosphide

Answer 3

Accessing dealocated memory does not necessarily cause a crash. The behavior is undefined. You are expecting too much!

Opacity

If I put a log before draining the pool, then it logs as expected. When I drain, I expect the NSString to be deallocated, but the static pointer to remain the same. Therefore, attempting to send it the -description method in order to log it should result in a EXC_BAD_ACCESS due to accessing deallocated memory. Instead, it's logging something else. However, explicitly invoking a method on the object causes it to crash. – Frohman

An EXC_BAD_ACCESS error will only occur if the VM page where that memory is located is no longer valid. Deallocating the object just marks its space as free in malloc's internal tracking, but other parts of the VM page may still be in use by other memory blocks. So, accessing that memory afterwards won't cause a crash unless everything else in that page is freed, and malloc then gives the page back to the kernel for reuse. – Nitroparaffin

Answer 4

Maybe it has something to do with the @"static:" being stored in the same memory location as staticString. staticString will be deallocated and it stores the @"static: %@" in that recycled mem location, so then the staticString pointer is on "static: %@" so it ends up static: static:.

Nealneala

@"static: %@" is stored in the TEXT portion of the binary, since it is a constant string. – Frohman

Answer 5

This is a case of "Use after free()". What happens is "undefined behavior". Your example is really no different than:

char *stringPtr = NULL;
stringPtr = malloc(1024); // Example code, assumes this returns non-NULL.
strcpy(stringPtr, "Zippers!");
free(stringPtr);
printf("Pants: %s\n", stringPtr);

What happens at the printf line? Who knows. Anything from Pants: Zippers! to Pants: (...garbage...) Core Dump.

All the Objective-C specific stuff is actually irrelevant- it's the fact that you're using a pointer to memory which is no longer valid is the only thing that matters. You're better off throwing darts at the wall than trying to explain "why" it's not crashing and printing static: static. For performance reasons, most malloc implementations don't bother "reaping" free()'d allocations until they have to. IMHO, this is probably why your example isn't crashing in the way you were expecting it to.

If you really want to see this particular program crash, you can do one of the following:

• Set the environment variable CFZombieLevel to 17 (scribble + don't free).
• Set the environment variable NSZombieEnabled to YES.
• Set the environment variable DYLD_INSERT_LIBRARIES to /usr/lib/libgmalloc.dylib (see man libgmalloc).

Phosphide

I was expecting it to crash because I was assuming that the -description method would be invoked on the string. Invoking a method on a deallocated object will lead to a crash in Objective-C. However, it turns out that this is not what's happening: strings are special-cased through the logging system. With that assumption gone, the whole "undefined behavior" argument makes much more sense. – Frohman

@Dave Trust me, it has nothing to do with "strings are special-cased through the logging system." This is a correlation, not a causation. Try it with this line: staticString = [NSString stringWithString:[[NSArray arrayWithObjects:@"1", @"2", @"3", nil] componentsJoinedByString:@","]];. – Phosphide

@Dave ... and this one happens to "work": staticString = [NSString stringWithFormat:@"%@", [NSArray arrayWithObjects:@"1", @"2", @"3", nil]]; – Phosphide