Tracing mechanism for iOS apps

If you are working on a big project it is usually convenient to have some kind of mechanism to find out what went wrong, what could be wrong or even what caused crash.

Here comes traces. In this post I will encourage you to use traces, they are pretty easy to implement. Someone may say "but we have NSLog to print traces".

Yes that is true. However with large project with intense use of NSLog it might happen your traces can become unreadable. Tons of traces on the screen aren't good.

 

Imagine following example:

 

Your program has loop that is performing some calculations and prints progress or some data with NSLog. At one point you received error and printed that single message.

As a result you could probably miss that error.

 

Having good tracing mechanism is essential addition to bugtracing besides debugger.

 

In this article I will create solution that you can simply apply to your project.

 

First of all we need to ask ourselves what is required:

 

1. Do we need different levels of traces?

2. Are we going to refer to our traces later?

3. Do we need filtering of undesired information?

4. Do we need runtime traces activation or tracing level change?

 

 

 

Let's go through these points and create interface first then we will go to implementation.

 

1. Do we need different levels of traces?

This is most convenient functionality, if you have plenty of traces you could only look for errors or warnings.

To achieve that we need some kind of enum to assign appropriate level to each single trace.

enum {
 TZTraceLevelError = 1,
 TZTraceLevelWarning = 2,
 TZTraceLevelNotice = 4,
 TZTraceLevelMessage = 8,
 TZTraceLevelMax
};

 

2. Are we going to refer to our traces later?

 

It is sometimes convenient to store our traces for further analysis. We can send traces either to console, log file or even via network.

Here is enum that defines these options.

enum {
 TZTraceOutputConsole = 1,
 TZTraceOutputFile = 2,
 TZTraceOutputNetwork = 4,
 TZTraceOutputMax
};

 

You probably noticed numbering isn't incremented by 1 in above enums but by power of 2. This is because in my implementation I am going to mix these enums together to allow tracing of different levels or send logs to different destinations at the same time.

 

Some people use different approach which for instance assumes if you set warning level then it means you want errors as well. I will rather allow mixing of these enums instead.

 

3. Do we need filtering of undesired information?

 

To be able to filter data we need some storage. Even if we decide to send traces to file, we will keep all traces inside memory so we can later print them at once at the end of our program if desired.

So I implement the following mutable arrays that will keep all traces of given type.

@property (strong, nonatomic) NSMutableArray *tracesOfTypeError;
@property (strong, nonatomic) NSMutableArray *tracesOfTypeWarning;
@property (strong, nonatomic) NSMutableArray *tracesOfTypeNotice;
@property (strong, nonatomic) NSMutableArray *tracesOfTypeMessage;

 

In fact I could create them dynamically but for clarity of this post they are defined as properties.

 

 

To be able to distinguish to which array we need to send particular trace we need the following mutable dictionary.

 

@property (strong, nonatomic) NSMutableDictionary *allTraces;

This will keep references to mutable arrays and use trace level as a key.

 

 

4. Do we need runtime traces activation or tracing level change?

 

 

It might be helpfull to change trace level at runtime, for instance we want to enable error tracing for specific function.

To keep track of what is actually enabled we will have appropriate variables that can be changed at runtime.

@property (readwrite, atomic) int currentTraceOutput;
@property (readwrite, atomic) int currentTraceLevel;

You may note that I explicity set atomic here since I want to use synthesized methods which will allow me to change these variables from different threads safely.

 

 

 

 

 

Going further we need some functions to capture trace or print traces of specific type to console:

- (void)trace:(NSString *)traceText forLevel:(int)level;
- (void)printAllTraces;
- (void)printAllTracesForLevels:(int)levels;

 

We will keep our tracing class as singleton so we need following functions:

 

+ (TZTrace *)sharedInstance;
- (TZTrace *)init;

 

 

We enclose everything with interface syntax:

 

 

@interface TZTrace : NSObject
..
@end

 

 

 

 

 

Now it is time to implement all of the above functions.

 

Let's start with init first.

- (TZTrace *)init
{
 // init self
 self = [super init];
 if (self == nil)
 {
 return nil;
 }

 // alloc arrays

 

tracesOfTypeNotice = [[NSMutableArray alloc] init]; tracesOfTypeWarning = [[NSMutableArray alloc] init]; tracesOfTypeError = [[NSMutableArray alloc] init]; tracesOfTypeMessage = [[NSMutableArray alloc] init]; // connect arrays with enums allTraces = [NSMutableDictionary dictionaryWithCapacity:TZTraceLevelMax]; [allTraces setObject:tracesOfTypeError forKey:[NSNumber numberWithInt:TZTraceLevelError]]; [allTraces setObject:tracesOfTypeWarning forKey:[NSNumber numberWithInt:TZTraceLevelWarning]]; [allTraces setObject:tracesOfTypeNotice forKey:[NSNumber numberWithInt:TZTraceLevelNotice]]; [allTraces setObject:tracesOfTypeMessage forKey:[NSNumber numberWithInt:TZTraceLevelMessage]]; // set default tracing level & output currentTraceLevel = TZTraceLevelError|TZTraceLevelMessage|TZTraceLevelNotice; currentTraceOutput = TZTraceOutputConsole|TZTraceOutputFile; // create path for writeing traces in case file is needed NSArray *documentPaths = NSSearchPathForDirectoriesInDomains(NSDocumentDirectory, NSUserDomainMask, YES); NSString *documentsDir = [documentPaths objectAtIndex:0]; tracePath = [[NSString alloc] initWithFormat:@"%@",[documentsDir stringByAppendingPathComponent:@"traces.txt"]]; // create trace file [[NSFileManager defaultManager] createFileAtPath:tracePath contents:nil attributes:nil]; return self; }

 

We allocate space for all arrays and create association between particular array and its enum representation.

 

Then we create paths that will be used when tracing to file is enabled. Finally we create trace.txt file.

Note: I am intentionally skipping error checking from various functions just for clarity.

 

 

Since our class is singleton we need function that will create object and return it every time we need.

 

 

+ (TZTrace*)sharedInstance
{
 static TZTrace *traces=nil;
  if (traces == nil)
 {
    traces = [[TZTrace alloc] init];
    if (traces == nil)
   {
     return nil;
    }
  }
 return traces;
}

 


 

 

 

Now it is time to do some tracing. Take a look a t the following function:

 

 
- (void)trace:(NSString *)traceText forLevel:(int)level
 {
 // 1. Make thread safe
 @synchronized(self)
 {
  // 2. Save trace
  [[allTraces objectForKey:[NSNumber numberWithInt:level]] addObject:traceText];

  // 2. Check whether we shall log it at all
  if (currentTraceLevel & level)
  {
  // 3. Log to specific output
  if (currentTraceOutput & TZTraceOutputConsole)
  {
   // 4. Log to console
   NSString *prefix = [self tracePrefixForLevel:level];
   NSLog(@"%@%@", prefix, traceText);
  }
  if (currentTraceOutput & TZTraceOutputFile)
  { 
   // 5. Append trace to file
   NSFileHandle *fileHandler = [NSFileHandle fileHandleForUpdatingAtPath:tracePath];
   if (fileHandler != nil)
   {
   [fileHandler seekToEndOfFile];
   NSString *prefix = [self tracePrefixForLevel:level];
   NSString *newTraceText = [NSString stringWithFormat:@"%@%@\n", prefix, traceText];
   [fileHandler writeData:[newTraceText dataUsingEncoding:NSUTF8StringEncoding]];
   [fileHandler closeFile];
   }
   else
   {
   NSLog(@"ERROR: Cannot write to trace.txt file.");
   }
  }
  if (currentTraceOutput & TZTraceOutputNetwork)
  {
   // todo: log to network
  }
  }
 }
 }

 

What do we do here?

 

1. We ensure tracing function will be thread safe so we use synchronize.

2. Save trace to appropriate array for further use

3. With the & operator we do bit comparison, if any of level bits is in currentTraceLevel we do logging

4. Simple logging to the console

5. We append trace to file determined at init.

The reason I create handle every time function is called is because your program may crash at random point so keeping file open doesn't seem to be a good approach.

 

 

Next two functions are needed when we want to print all gathered traces at some point in code (presumably at the end of the program).

 

 

- (void)printAllTraces
{
 @synchronized(self)
 {
   NSLog(@"%@", @"All traces:");
   for (int idx = 1; idx < TZTraceLevelMax; idx *= 2)
   {
     NSString *prefix = [self tracePrefixForLevel:idx];
     for (NSString* trace in [allTraces objectForKey:[NSNumber numberWithInt:idx]])
     {
       NSLog(@"%@%@", prefix, trace);
     }
   }
 }
}

- (void)printAllTracesForLevels:(int)levels
{
 @synchronized(self)
 {
   NSLog(@"%@", @"All traces:");
   for (int idx = 1; idx < TZTraceLevelMax; idx *= 2)
   {
     if (idx & levels)
     {
       NSString *prefix = [self tracePrefixForLevel:idx];
       for (NSString* trace in [allTraces objectForKey:[NSNumber numberWithInt:idx]])
       {
         NSLog(@"%@%@", prefix, trace);
       }
     }
   }
 }
}

 

printAllTraces simply iterates over all possible levels and print all values from array responsible for that level.

 

printAllTracesForLevels prints only levels you asked.

 

 

What if you don't want that tracing mechanism in release version?

 

 

Select project in file browser, go to "build settings" and search for preprocessor macros, then add TZTracesDisabled to release build.

Now you can just enclose whole body with ifndef macro for sharedInstance function in this TZTrace class. On #else return nil.

This will cause messages to nil objects will be ignored in all calls to TZTrace functions. Moreover I suppose compiler optimizations might simply remove all of these calls to TZTrace class.

#ifndef TZTracesDisabled
...
#else
...
#endif

 

 

 

How to use it?

 

In your program simply call:

[[Trace getInstance] trace:@"My error trace" forLevel:TZTraceLevelError];

 

And that's it.

 

 

If you need to change tracing level, you can call:

 

[[Trace getInstance] setCurrentTraceLevel:TZTraceLevelNotice];

or with mixed flags

[[Trace getInstance] setCurrentTraceLevel:TZTraceLevelError|TZTraceLevelWarning];

 

 

 

Room for improvements/challenges:

 

1. Add network tracing. Perhaps you might setup some php script to receive logs and write it on server so test team might generate traces easily.

2. Convert mixing of trace level enums to assumption that desired level brings also lower levels.

3. Do we need full traces of what functions were called?

- 1st hacky option:

Well, we have special function called instrumentObjcMessageSends(bool), if its set to YES then it starts logging all function calls to /tmp/msgSends-XXXX, where XXXX is pid (process id) number.

To gather that data inside our application we need to read that file as soon as content is added.

- 2nd option:

Consider reading http://www.dribin.org/dave/blog/archives/2006/04/22/tracing_objc. There you can find an explained method that can dynamically change message logging function to our own.

 

 

 

Things to remember:

 

1. When analysing your code with memory leak/allocation instrument it might grow in size because all traces are stored locally. Use TZTracesDisabled in such case!

2. Above implementation assumes ARC is enabled and your runtime does not require ivars (xcode > 3.2.4 is working with direct access of synthesized ivars).

 

You can grab fully working source code at:  https://github.com/bloto/TZTrace

 

Leave a comment

 

I'd love to hear your thoughts!