Xcode, Why are some NSLog entries omitted from the console?

Question

I'm just beginning to learn IOS development. Everytime I run this program, the console does not always display my NSLogs.

#import <Foundation/Foundation.h>

int main(int argc, const char * argv[])
{

    @autoreleasepool {

        NSMutableArray *items = [[NSMutableArray alloc] init];

        [items addObject:@"One"];
        [items addObject:@"Two"];
        [items addObject:@"Three"];

        [items insertObject:@"zero" atIndex:0];

        NSLog(@"Object at 0 is %@", [items objectAtIndex:0]);
        NSLog(@"Object at 1 is %@", [items objectAtIndex:1]);
        NSLog(@"Object at 2 is %@", [items objectAtIndex:2]);
        NSLog(@"Object at 3 is %@", [items objectAtIndex:3]);

        for (int i = 0; i < [items count]; i++) {
            NSLog(@"%@", [items objectAtIndex:i]);
        }
        items = nil;           
    }
    return 0;
}

I should be getting this in the console every time I run it:

2012-04-11 16:29:10.419 RandomPossessions[701:403] Object at 0 is zero
2012-04-11 16:29:10.421 RandomPossessions[701:403] Object at 1 is One
2012-04-11 16:29:10.422 RandomPossessions[701:403] Object at 2 is Two
2012-04-11 16:29:10.422 RandomPossessions[701:403] Object at 3 is Three
2012-04-11 16:29:10.423 RandomPossessions[701:403] zero
2012-04-11 16:29:10.423 RandomPossessions[701:403] One
2012-04-11 16:29:10.424 RandomPossessions[701:403] Two
2012-04-11 16:29:10.424 RandomPossessions[701:403] Three

But sometimes it's not all displayed. Another time I run it and I could just get:

2012-04-11 16:48:20.626 RandomPossessions[734:403] Object at 0 is zero
2012-04-11 16:48:20.628 RandomPossessions[734:403] Object at 1 is One

I have to run the program several times to get the full list of NSLogs to output to the console. Is this a bug, or am I doing something wrong? Thanks

Answer 1

Fascinating. I just tried your code and got the same result. Here's my hypothesis:

Set a breakpoint at your line:

    [items insertObject:@"zero" atIndex:0];

When the debugger gets there, the debug panel shows one thread.

Now step forward to

    NSLog(@"Object at 1 is %@", [items objectAtIndex:1]);

Now there are 3 threads.

I'm betting that those others 2 threads are doing the actual writing to the log. If the program finishes before those separate threads have written to the log, then they just get killed, and your logs don't get written.

I tried adding a call to

sleep(0);

at the end of the main function, and suddenly the logs started appearing appropriately.

I then tried removing that line, and the original symptoms disappeared, and I can no longer recreate the issue you were having.

Bottom line: I think this is a symptom of the program quitting before the logs have been written. If you're writing an iOS app, you won't have to worry about this kind of thing. It's just an obscure implementation detail.

Good luck learning.