9

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

Dave DeLong
  • 242,470
  • 58
  • 448
  • 498
  • Why are you expecting it to crash? – David Weiser Jan 18 '11 at 22:54
  • `NSLog([NSString stringWithFormat:@"static: %@", staticString])` __does__ cause a crash, so it's really due to a different behavior of `NSLog` when handling `%@` – Joost Jan 18 '11 at 23:25
  • 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. – johne Jan 20 '11 at 02:17
  • 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. – johne Jan 20 '11 at 02:38
  • 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. – johne Jan 20 '11 at 02:43
  • @johne 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. – Dave DeLong Jan 20 '11 at 02:46
  • @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. – johne Jan 20 '11 at 03:00
  • @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. – johne Jan 20 '11 at 04:47

5 Answers5

9

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.

Lily Ballard
  • 182,031
  • 33
  • 381
  • 347
  • 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. –  Jan 18 '11 at 23:15
  • @Graham actually, it's a custom implementation of `printf()`. I'll be editing my question with what I've found. – Dave DeLong Jan 18 '11 at 23:18
  • 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. –  Jan 18 '11 at 23:23
  • @Graham If it used `-getCString:` then the resulting value would be a C String, which would crash if passed to `%@`. – Lily Ballard Jan 18 '11 at 23:25
  • @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: "`. – Lily Ballard Jan 18 '11 at 23:26
  • @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). –  Jan 18 '11 at 23:29
  • @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. – Lily Ballard Jan 18 '11 at 23:33
  • @Graham yes, it builds the resulting string on-the-fly and does not use `vsprintf()` or anything like that. – Dave DeLong Jan 18 '11 at 23:35
8

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.

  • 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`. – Lily Ballard Jan 18 '11 at 23:10
  • 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. – Lily Ballard Jan 18 '11 at 23:12
  • 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 `NSLog`ing. That's why the expected `-description` isn't showing up. It does show up when you use this comments `fprintf()` code. – johne Jan 20 '11 at 04:43
1

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

Roman Zenka
  • 3,514
  • 3
  • 31
  • 36
  • 1
    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. – Dave DeLong Jan 18 '11 at 22:50
  • 1
    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. – Brian Webster Jan 18 '11 at 23:12
1

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

Allyn
  • 20,271
  • 16
  • 57
  • 68
1

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).
johne
  • 6,760
  • 2
  • 24
  • 25
  • 1
    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. – Dave DeLong Jan 20 '11 at 01:20
  • @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:@","]];`. – johne Jan 20 '11 at 01:31
  • @Dave ... and this one happens to "work": `staticString = [NSString stringWithFormat:@"%@", [NSArray arrayWithObjects:@"1", @"2", @"3", nil]];` – johne Jan 20 '11 at 01:36