Adding hooks for DDLogFormatter's to help with thread-safety issues surrounding log formatters (e.g. thread-unsafe classes such as NSDateFormatter)

Author: robbiehanson

Lumberjack/DDLog.h

@@ -427,9 +427,22 @@ NSString *DDExtractFileNameWithoutExtension(const char *filePath, BOOL copy);
  * The formatter may also optionally filter the log message by returning nil,
  * in which case the logger will not log the message.
 **/
-
 - (NSString *)formatLogMessage:(DDLogMessage *)logMessage;
 
+@optional
+
+/**
+ * A single formatter instance can be added to multiple loggers.
+ * These methods provides hooks to notify the formatter of when it's added/removed.
+ *
+ * This is primarily for thread-safety.
+ * If a formatter is explicitly not thread-safe, it may wish to throw an exception if added to multiple loggers.
+ * Or if a formatter has potentially thread-unsafe code (e.g. NSDateFormatter),
+ * it could possibly use these hooks to switch to thread-safe versions of the code.
+**/
+- (void)didAddToLogger:(id <DDLogger>)logger;
+- (void)willRemoveFromLogger:(id <DDLogger>)logger;
+
 @end
 
 ////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////

Lumberjack/DDLog.m

@@ -1022,11 +1022,21 @@ - (void)setLogFormatter:(id <DDLogFormatter>)logFormatter
 {
 	// The design of this method is documented extensively in the logFormatter message (above in code).
 
-	dispatch_block_t block = ^{
-		if (formatter != logFormatter) {
+	dispatch_block_t block = ^{ @autoreleasepool {
+		
+		if (formatter != logFormatter)
+		{
+			if ([formatter respondsToSelector:@selector(willRemoveFromLogger:)]) {
+				[formatter willRemoveFromLogger:self];
+			}
+				
 			formatter = logFormatter;
+			
+			if ([formatter respondsToSelector:@selector(didAddToLogger:)]) {
+				[formatter didAddToLogger:self];
+			}
 		}
-	};
+	}};
 
 	dispatch_queue_t currentQueue = dispatch_get_current_queue();
 	if (currentQueue == loggerQueue)

Lumberjack/Extensions/DispatchQueueLogFormatter.h

@@ -53,10 +53,13 @@
 {
 	@protected
 
-	NSDateFormatter *dateFormatter;
+	NSString *dateFormatString;
 
 	@private
 
+	int32_t atomicLoggerCount;
+	NSDateFormatter *threadUnsafeDateFormatter; // Use [self stringFromDate]
+	
 	OSSpinLock lock;
 
 	NSUInteger _minQueueLength;           // _prefix == Only access via atomic property

Lumberjack/Extensions/DispatchQueueLogFormatter.m

@@ -1,4 +1,5 @@
 #import "DispatchQueueLogFormatter.h"
+#import <libkern/OSAtomic.h>
 
 /**
  * Welcome to Cocoa Lumberjack!
@@ -21,9 +22,10 @@ - (id)init
 {
 	if ((self = [super init]))
 	{
-		dateFormatter = [[NSDateFormatter alloc] init];
-		[dateFormatter setFormatterBehavior:NSDateFormatterBehavior10_4];
-		[dateFormatter setDateFormat:@"yyyy-MM-dd HH:mm:ss:SSS"];
+		dateFormatString = @"yyyy-MM-dd HH:mm:ss:SSS";
+		
+		atomicLoggerCount = 0;
+		threadUnsafeDateFormatter = nil;
 
 		_minQueueLength = 0;
 		_maxQueueLength = 0;
@@ -73,6 +75,46 @@ - (void)setReplacementString:(NSString *)shortLabel forQueueLabel:(NSString *)lo
 #pragma mark DDLogFormatter
 ////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////
 
+- (NSString *)stringFromDate:(NSDate *)date
+{
+	int32_t loggerCount = OSAtomicAdd32(0, &atomicLoggerCount);
+	
+	if (loggerCount <= 1)
+	{
+		// Single-threaded mode.
+		
+		if (threadUnsafeDateFormatter == nil)
+		{
+			threadUnsafeDateFormatter = [[NSDateFormatter alloc] init];
+			[threadUnsafeDateFormatter setFormatterBehavior:NSDateFormatterBehavior10_4];
+			[threadUnsafeDateFormatter setDateFormat:dateFormatString];
+		}
+		
+		return [threadUnsafeDateFormatter stringFromDate:date];
+	}
+	else
+	{
+		// Multi-threaded mode.
+		// NSDateFormatter is NOT thread-safe.
+		
+		NSString *key = @"DispatchQueueLogFormatter_NSDateFormatter";
+		
+		NSMutableDictionary *threadDictionary = [[NSThread currentThread] threadDictionary];
+		NSDateFormatter *dateFormatter = [threadDictionary objectForKey:key];
+		
+		if (dateFormatter == nil)
+		{
+			dateFormatter = [[NSDateFormatter alloc] init];
+			[dateFormatter setFormatterBehavior:NSDateFormatterBehavior10_4];
+			[dateFormatter setDateFormat:dateFormatString];
+			
+			[threadDictionary setObject:dateFormatter forKey:key];
+		}
+		
+		return [dateFormatter stringFromDate:date];
+	}
+}
+
 - (NSString *)queueThreadLabelForLogMessage:(DDLogMessage *)logMessage
 {
 	// As per the DDLogFormatter contract, this method is always invoked on the same thread/dispatch_queue
@@ -180,10 +222,20 @@ - (NSString *)queueThreadLabelForLogMessage:(DDLogMessage *)logMessage
 
 - (NSString *)formatLogMessage:(DDLogMessage *)logMessage
 {
-	NSString *timestamp = [dateFormatter stringFromDate:(logMessage->timestamp)];
+	NSString *timestamp = [self stringFromDate:(logMessage->timestamp)];
 	NSString *queueThreadLabel = [self queueThreadLabelForLogMessage:logMessage];
 
 	return [NSString stringWithFormat:@"%@ [%@] %@", timestamp, queueThreadLabel, logMessage->logMsg];
 }
 
+- (void)didAddToLogger:(id <DDLogger>)logger
+{
+	OSAtomicIncrement32(&atomicLoggerCount);
+}
+
+- (void)willRemoveFromLogger:(id <DDLogger>)logger
+{
+	OSAtomicDecrement32(&atomicLoggerCount);
+}
+
 @end

Xcode/ContextFilter/ContextFilter.xcodeproj/project.pbxproj

@@ -18,6 +18,10 @@
 		DC2E3340129AD073009F096E /* DDTTYLogger.m in Sources */ = {isa = PBXBuildFile; fileRef = DC2E333C129AD073009F096E /* DDTTYLogger.m */; };
 		DC2E3347129ADC68009F096E /* MyContextFilter.m in Sources */ = {isa = PBXBuildFile; fileRef = DC2E3346129ADC68009F096E /* MyContextFilter.m */; };
 		DC2E334A129ADCE0009F096E /* ThirdPartyFramework.m in Sources */ = {isa = PBXBuildFile; fileRef = DC2E3349129ADCE0009F096E /* ThirdPartyFramework.m */; };
+		DCF89E9515A3604500112881 /* DDAbstractDatabaseLogger.m in Sources */ = {isa = PBXBuildFile; fileRef = DCF89E9415A3604500112881 /* DDAbstractDatabaseLogger.m */; };
+		DCF89E9D15A3605200112881 /* ContextFilterLogFormatter.m in Sources */ = {isa = PBXBuildFile; fileRef = DCF89E9915A3605200112881 /* ContextFilterLogFormatter.m */; };
+		DCF89E9E15A3605200112881 /* DispatchQueueLogFormatter.m in Sources */ = {isa = PBXBuildFile; fileRef = DCF89E9B15A3605200112881 /* DispatchQueueLogFormatter.m */; };
+		DCF89E9F15A3605200112881 /* README.txt in Resources */ = {isa = PBXBuildFile; fileRef = DCF89E9C15A3605200112881 /* README.txt */; };
 /* End PBXBuildFile section */
 
 /* Begin PBXFileReference section */
@@ -45,6 +49,13 @@
 		DC2E3346129ADC68009F096E /* MyContextFilter.m */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.objc; path = MyContextFilter.m; sourceTree = "<group>"; };
 		DC2E3348129ADCE0009F096E /* ThirdPartyFramework.h */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.h; path = ThirdPartyFramework.h; sourceTree = "<group>"; };
 		DC2E3349129ADCE0009F096E /* ThirdPartyFramework.m */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.objc; path = ThirdPartyFramework.m; sourceTree = "<group>"; };
+		DCF89E9315A3604500112881 /* DDAbstractDatabaseLogger.h */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.h; name = DDAbstractDatabaseLogger.h; path = ../../Lumberjack/DDAbstractDatabaseLogger.h; sourceTree = "<group>"; };
+		DCF89E9415A3604500112881 /* DDAbstractDatabaseLogger.m */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.objc; name = DDAbstractDatabaseLogger.m; path = ../../Lumberjack/DDAbstractDatabaseLogger.m; sourceTree = "<group>"; };
+		DCF89E9815A3605200112881 /* ContextFilterLogFormatter.h */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.h; path = ContextFilterLogFormatter.h; sourceTree = "<group>"; };
+		DCF89E9915A3605200112881 /* ContextFilterLogFormatter.m */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.objc; path = ContextFilterLogFormatter.m; sourceTree = "<group>"; };
+		DCF89E9A15A3605200112881 /* DispatchQueueLogFormatter.h */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.h; path = DispatchQueueLogFormatter.h; sourceTree = "<group>"; };
+		DCF89E9B15A3605200112881 /* DispatchQueueLogFormatter.m */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.objc; path = DispatchQueueLogFormatter.m; sourceTree = "<group>"; };
+		DCF89E9C15A3605200112881 /* README.txt */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = text; path = README.txt; sourceTree = "<group>"; };
 /* End PBXFileReference section */
 
 /* Begin PBXFrameworksBuildPhase section */
@@ -150,10 +161,26 @@
 				DC2E3336129AD073009F096E /* DDASLLogger.m */,
 				DC2E3337129AD073009F096E /* DDFileLogger.h */,
 				DC2E3338129AD073009F096E /* DDFileLogger.m */,
+				DCF89E9315A3604500112881 /* DDAbstractDatabaseLogger.h */,
+				DCF89E9415A3604500112881 /* DDAbstractDatabaseLogger.m */,
+				DCF89E9715A3605200112881 /* Extensions */,
 			);
 			name = Logging;
 			sourceTree = "<group>";
 		};
+		DCF89E9715A3605200112881 /* Extensions */ = {
+			isa = PBXGroup;
+			children = (
+				DCF89E9815A3605200112881 /* ContextFilterLogFormatter.h */,
+				DCF89E9915A3605200112881 /* ContextFilterLogFormatter.m */,
+				DCF89E9A15A3605200112881 /* DispatchQueueLogFormatter.h */,
+				DCF89E9B15A3605200112881 /* DispatchQueueLogFormatter.m */,
+				DCF89E9C15A3605200112881 /* README.txt */,
+			);
+			name = Extensions;
+			path = ../../Lumberjack/Extensions;
+			sourceTree = "<group>";
+		};
 /* End PBXGroup section */
 
 /* Begin PBXNativeTarget section */
@@ -209,6 +236,7 @@
 			files = (
 				8D11072B0486CEB800E47090 /* InfoPlist.strings in Resources */,
 				1DDD58160DA1D0A300B32029 /* MainMenu.xib in Resources */,
+				DCF89E9F15A3605200112881 /* README.txt in Resources */,
 			);
 			runOnlyForDeploymentPostprocessing = 0;
 		};
@@ -227,6 +255,9 @@
 				DC2E3340129AD073009F096E /* DDTTYLogger.m in Sources */,
 				DC2E3347129ADC68009F096E /* MyContextFilter.m in Sources */,
 				DC2E334A129ADCE0009F096E /* ThirdPartyFramework.m in Sources */,
+				DCF89E9515A3604500112881 /* DDAbstractDatabaseLogger.m in Sources */,
+				DCF89E9D15A3605200112881 /* ContextFilterLogFormatter.m in Sources */,
+				DCF89E9E15A3605200112881 /* DispatchQueueLogFormatter.m in Sources */,
 			);
 			runOnlyForDeploymentPostprocessing = 0;
 		};

Xcode/DispatchQueueLogger/DispatchQueueLogger/AppDelegate.m

@@ -18,30 +18,24 @@ @implementation AppDelegate
 
 - (void)applicationDidFinishLaunching:(NSNotification *)aNotification
 {
-	if (YES)
+	if (NO)
 	{
-		// Log statements *AFTER* DispatchQueueLogFormatter
+		// See what log statements look like *BEFORE* using DispatchQueueLogFormatter :(
+	}
+	else
+	{
+		// See what log statements look like *AFTER* using DispatchQueueLogFormatter :)
 
 		DispatchQueueLogFormatter *formatter = [[DispatchQueueLogFormatter alloc] init];
 		formatter.minQueueLength = 4;
 		formatter.maxQueueLength = 0;
 
-		[formatter setReplacementString:@"main"              forQueueLabel:@"com.apple.main-thread"];
-		[formatter setReplacementString:@"global-background" forQueueLabel:@"com.apple.root.background-priority"];
-		[formatter setReplacementString:@"global-low"        forQueueLabel:@"com.apple.root.low-priority"];
-		[formatter setReplacementString:@"global-default"    forQueueLabel:@"com.apple.root.default-priority"];
-		[formatter setReplacementString:@"global-high"       forQueueLabel:@"com.apple.root.high-priority"];
-		
 		[formatter setReplacementString:@"downloading" forQueueLabel:@"downloadingQueue"];
 		[formatter setReplacementString:@"parsing"     forQueueLabel:@"parsingQueue"];
 		[formatter setReplacementString:@"processing"  forQueueLabel:@"processingQueue"];
 
 		[[DDTTYLogger sharedInstance] setLogFormatter:formatter];
 	}
-	else
-	{
-		// Log statements *BEFORE* DispatchQueueLogFormatter
-	}
 
 	[DDLog addLogger:[DDTTYLogger sharedInstance]];
 
@@ -70,23 +64,6 @@ - (void)applicationDidFinishLaunching:(NSNotification *)aNotification
 		dispatch_async(processingQueue,  blockC);
 	}
 
-	dispatch_queue_t bgq = dispatch_get_global_queue(DISPATCH_QUEUE_PRIORITY_BACKGROUND, 0);
-	dispatch_queue_t lgq = dispatch_get_global_queue(DISPATCH_QUEUE_PRIORITY_LOW, 0);
-	dispatch_queue_t dgq = dispatch_get_global_queue(DISPATCH_QUEUE_PRIORITY_DEFAULT, 0);
-	dispatch_queue_t hgq = dispatch_get_global_queue(DISPATCH_QUEUE_PRIORITY_HIGH, 0);
-	
-	dispatch_block_t blockD = ^{
-		DDLogVerbose(@"Some log statement");
-	};
-	
-	for (i = 0; i < count; i++)
-	{
-		dispatch_async(bgq, blockD);
-		dispatch_async(lgq, blockD);
-		dispatch_async(dgq, blockD);
-		dispatch_async(hgq, blockD);
-	}
-	
 	[NSThread detachNewThreadSelector:@selector(backgroundThread:) toTarget:self withObject:nil];
 }