Add indent/unindent for recursive debugging

[kcoop]

Great framework, thanks for building it!

I frequently work with recursive data structures, and it helps considerably to use indentation to demark the different levels in recursive calls. I looked at using a custom formatter, but realized quickly that asychronous logging made that worthless. It'd be nice to have something like

[DDLogger indent]
[DDLogger unindent]

that would affect an integer indent level in the DDLogMessage that was passed to the formatter.

[robbiehanson]

Great question.

Using a technique like [DDLog indent] would run into problems with multithreaded code.

Another alternative would be embedding the indent level in the log message itself. By this, I mean putting the indent level in the DDLogMessage object. This object has a "id tag" variable that is designed to be used for just such a thing. It would entail defining your own macro, but could make things pretty easy.

Let me know what you think, or if you have any questions.

[kcoop]

Good point. You could associate the indent level with the thread id. I suppose that does affect performance though, for a specific use case.

The macro approach may yield a less than elegant api, but I'll look into it. Thanks.

On Apr 4, 2012, at 7:50 PM, Robbie Hanson wrote:

Great question.

Using a technique like [DDLog indent] would run into problems with multithreaded code.

Another alternative would be embedding the indent level in the log message itself. By this, I mean putting the indent level in the DDLogMessage object. This object has a "id tag" variable that is designed to be used for just such a thing. It would entail defining your own macro, but could make things pretty easy.

Let me know what you think, or if you have any questions.

---

Reply to this email directly or view it on GitHub:
#28 (comment)

[robbiehanson]

I believe the macro approach may yield an elegant api.
Also, for recursive calls, it would be great to take advantage of asynchronous logging.

The end result would look something like this:

DDLogIndent(i,   @"Lumberjack is:");
DDLogIndent(++i, @"- Fast");
DDLogIndent(i,   @"- Simple");
DDLogIndent(i,   @"- Powerful");
DDLogIndent(i--, @"- Flexible");
DDLogIndent(i,   @"But don't take my word for it.");
DDLogIndent(i,   @"Try it yourself.");

I tested it out in the CustomFormatters example, and got it to spit out this:

CustomFormattersAppDelegate | applicationDidFinishLaunching: @ 42 | Lumberjack is:
CustomFormattersAppDelegate | applicationDidFinishLaunching: @ 43 |    - Fast
CustomFormattersAppDelegate | applicationDidFinishLaunching: @ 44 |    - Simple
CustomFormattersAppDelegate | applicationDidFinishLaunching: @ 45 |    - Powerful
CustomFormattersAppDelegate | applicationDidFinishLaunching: @ 46 |    - Flexible
CustomFormattersAppDelegate | applicationDidFinishLaunching: @ 47 | But don't take my word for it.
CustomFormattersAppDelegate | applicationDidFinishLaunching: @ 48 | Try it yourself.

Here's how I did it. There are several macros defined in DDLog.h, but they all boil down to calling a single objective-c class method (that takes all the parameters for creating a DDLogMessage).

So I added a define that looks like this:

#define DDLogIndent(indentLevel, frmt, ...)                   \
  [DDLog log:YES                /* Asynchronous           */  \
       level:ddLogLevel         /* Current log level      */  \
        flag:LOG_FLAG_VERBOSE   /* Log if verbose enabled */  \
     context:0                  /* Normal app context     */  \
        file:__FILE__                                                 \
    function:sel_getName(_cmd)                                        \
        line:__LINE__                                                 \
         tag:[NSNumber numberWithInt:indentLevel] /* Special sauce*/  \
      format:(frmt), ##__VA_ARGS__]

And then I tweaked the formatter to look like this:

- (NSString *)formatLogMessage:(DDLogMessage *)logMessage
{
    NSMutableString *str = [NSMutableString stringWithCapacity:32];

    [str appendFormat:@"%@ | %s @ %i | ", logMessage.fileName, logMessage->function, logMessage->lineNumber];

    NSNumber *indentLevelNumber = (NSNumber *)logMessage->tag;
    int indentLevel = [indentLevelNumber intValue];

    for (int i = 0; i < indentLevel; i++)
    {
        [str appendString:@"  "];
    }

    [str appendFormat:@"%@", logMessage->logMsg];

    return str;
}

Let me know what you think of this idea.

[kcoop]

Sorry, got caught up in pressing matters. Thanks for this, Robbie.

It's as I was thinking though; I'm going to need to track the indent variable, which adds to the footprint on other code. Still, it is fast. Thanks again!

[robbiehanson]

You're right. For looping, the code works great. For recursion, not so much. So I have a better idea:

Store the indent level in the formatter. You can maintain thread safety by using a dictionary, with the thread ID as the key, and the indent level as the value. But how to tell formatter to indent / unindent? Use the tag! Similar to the example above.

I'll post some example code when I get some time. Swamped next few days.

[robbiehanson]

How about something like this:

RecursionFormatter.h

#import <Foundation/Foundation.h>
#import "DDLog.h"

extern id const DDLogIncrementIndentLevel;
extern id const DDLogDecrementIndentLevel;

#define DDLogIndent()                  \
  [DDLog log:YES                       \
       level:0                         \
        flag:0                         \
     context:0                         \
        file:NULL                      \
    function:NULL                      \
        line:0                         \
         tag:DDLogIncrementIndentLevel \
      format:@""] 

#define DDLogUnindent()                \
  [DDLog log:YES                       \
       level:0                         \
        flag:0                         \
     context:0                         \
        file:NULL                      \
    function:NULL                      \
        line:0                         \
         tag:DDLogDecrementIndentLevel \
      format:@""]

@interface RecursionFormatter : NSObject <DDLogFormatter>

@end

RecursionFormatter.m

#import "RecursionFormatter.h"
#import <pthread.h>


id const DDLogIncrementIndentLevel = @"DDLogIncrementIndentLevel";
id const DDLogDecrementIndentLevel = @"DDLogDecrementIndentLevel";


@implementation RecursionFormatter
{
    dispatch_queue_t indentQueue;
    NSMutableDictionary *indentDict;
}

- (id)init
{
    if ((self = [super init]))
    {
        indentQueue = dispatch_queue_create("TestFormatter", NULL);
        indentDict = [[NSMutableDictionary alloc] init];
    }
    return self;
}

- (NSUInteger)indentLevel:(mach_port_t)threadID
{
    __block NSUInteger indentLevel;

    dispatch_sync(indentQueue, ^{

        NSNumber *key = [NSNumber numberWithUnsignedInt:threadID];

        indentLevel = [[indentDict objectForKey:key] unsignedIntegerValue];

        NSLog(@"indentLevel: %lu", (unsigned long)indentLevel);
    });

    return indentLevel;
}

- (void)indent:(mach_port_t)threadID
{
    dispatch_async(indentQueue, ^{

        NSNumber *key = [NSNumber numberWithUnsignedInt:threadID];

        NSUInteger oldIndentLevel = [[indentDict objectForKey:key] unsignedIntegerValue];
        NSUInteger newIndentLevel = oldIndentLevel + 1;

        NSLog(@"indent  : %lu -> %lu", (unsigned long)oldIndentLevel, (unsigned long)newIndentLevel);

        [indentDict setObject:[NSNumber numberWithUnsignedInteger:newIndentLevel] forKey:key];
    });
}

- (void)unindent:(mach_port_t)threadID
{
    dispatch_async(indentQueue, ^{

        NSNumber *key = [NSNumber numberWithUnsignedInt:threadID];

        NSUInteger oldIndentLevel = [[indentDict objectForKey:key] unsignedIntegerValue];
        NSUInteger newIndentLevel = oldIndentLevel > 0 ? oldIndentLevel - 1 : 0;

        NSLog(@"unindent: %lu -> %lu", (unsigned long)oldIndentLevel, (unsigned long)newIndentLevel);

        [indentDict setObject:[NSNumber numberWithUnsignedInteger:newIndentLevel] forKey:key];
    });
}

- (NSString *)formatLogMessage:(DDLogMessage *)logMessage
{
    if (logMessage->tag == DDLogIncrementIndentLevel)
    {
        [self indent:logMessage->machThreadID];
        return nil;
    }
    if (logMessage->tag == DDLogDecrementIndentLevel)
    {
        [self unindent:logMessage->machThreadID];
        return nil;
    }

    NSMutableString *str = [[NSMutableString alloc] init];

    [str appendFormat:@"%@ | ", logMessage.fileName];

    NSUInteger indentLevel = [self indentLevel:logMessage->machThreadID];

    NSUInteger i;
    for (i = 0; i < indentLevel; i++)
    {
        [str appendString:@"  "];
    }

    [str appendString:logMessage->logMsg];

    return str;
}

@end

AppDelegate.m

- (void)recursiveMethod:(NSUInteger)i
{
    DDLogIndent();

    if (i > 0)
    {
        DDLogInfo(@"pre-recursion");
        [self recursiveMethod:(i-1)];
        DDLogInfo(@"post-recursion");
    }

    DDLogUnindent();
}

- (void)applicationDidFinishLaunching:(NSNotification *)aNotification
{
    // Setup logging (with our custom formatter)

    formatter = [[RecursionFormatter alloc] init];

    [[DDTTYLogger sharedInstance] setLogFormatter:formatter];
    [DDLog addLogger:[DDTTYLogger sharedInstance]];

    [self recursiveMethod:4];
}

[kcoop]

Very nice! Thanks!