From f080aa742f5cdecb69b0ee0a323870737cd9449c Mon Sep 17 00:00:00 2001 From: Thilo Molitor Date: Tue, 31 Dec 2024 07:52:34 +0100 Subject: [PATCH] Improve UDP logging while logger queue is suspended --- Monal/Classes/HelperTools.h | 5 +++ Monal/Classes/HelperTools.m | 69 +++++++++++++++++++++---------------- Monal/Classes/MLUDPLogger.m | 11 +++++- UDPLogServer/server.py | 6 +++- 4 files changed, 59 insertions(+), 32 deletions(-) diff --git a/Monal/Classes/HelperTools.h b/Monal/Classes/HelperTools.h index 9e07be0ef6..285cbb957f 100644 --- a/Monal/Classes/HelperTools.h +++ b/Monal/Classes/HelperTools.h @@ -85,6 +85,10 @@ void swizzle(Class c, SEL orig, SEL new); -(id) initWithObj:(id) obj; @end +@interface DDLogMessage(TaggedMessage) +@property (nonatomic) BOOL ml_isDirect; +@end + @interface HelperTools : NSObject @property (class, nonatomic, strong, nullable) DDFileLogger* fileLogger; @@ -94,6 +98,7 @@ void swizzle(Class c, SEL orig, SEL new); +(void) installExceptionHandler; +(int) pendingCrashreportCount; +(void) flushLogsWithTimeout:(double) timeout; ++(BOOL) isAppSuspended; +(void) signalSuspension; +(void) signalResumption; +(void) __attribute__((noreturn)) MLAssertWithText:(NSString*) text andUserData:(id _Nullable) additionalData andFile:(const char* const) file andLine:(int) line andFunc:(const char* const) func; diff --git a/Monal/Classes/HelperTools.m b/Monal/Classes/HelperTools.m index 1d3fd3c884..f128ba81fc 100644 --- a/Monal/Classes/HelperTools.m +++ b/Monal/Classes/HelperTools.m @@ -332,6 +332,18 @@ -(id) initWithObj:(id) obj } @end +@implementation DDLogMessage(TaggedMessage) +@dynamic ml_isDirect; +-(void) setMl_isDirect:(BOOL) value +{ + objc_setAssociatedObject(self, @selector(ml_isDirect), @(value), OBJC_ASSOCIATION_RETAIN_NONATOMIC); +} +-(BOOL) ml_isDirect +{ + return ((NSNumber*)objc_getAssociatedObject(self, @selector(ml_isDirect))).boolValue; +} +@end + @implementation NSUserDefaults (SerializeNSObject) -(id) swizzled_objectForKey:(NSString*) defaultName { @@ -401,31 +413,21 @@ -(void) swizzled_queueLogMessage:(DDLogMessage*) logMessage asynchronously:(BOOL udpLoggerEnabled = [[HelperTools defaultsDB] boolForKey:@"udpLoggerEnabled"]; }); + //use udp logger to log all messages, even if the loggging queue is in suspended state + //this hopefully enables us to catch strange bugs sometimes hanging and then watchdog-killing the app when resuming from resumption + if(udpLoggerEnabled && _suspensionHandling_isSuspended) + { + //this marks a message as already directly logged to allow the udp logger to later ignore the queued log request for the same message + logMessage.ml_isDirect = YES; + [MLUDPLogger directlyWriteLogMessage:logMessage]; + } + else + logMessage.ml_isDirect = NO; + //don't do sync logging for any message (usually ERROR), while the global logging queue is suspended //don't use _suspensionHandling_lock here because that can introduce deadlocks //(for example if we have log statements in our MLLogFileManager code rotating the logfile and creating a new one) - BOOL isSuspended = _suspensionHandling_isSuspended; - if(isSuspended && udpLoggerEnabled) - { - //use udp logger to log all messages, even if the loggging queue is in suspended state - //this hopefully enables us to catch strange bugs sometimes hanging and then watchdog-killing the app when resuming from resumption -#pragma clang diagnostic push -#pragma clang diagnostic ignored "-Wdeprecated-declarations" - [MLUDPLogger directlyWriteLogMessage:[[DDLogMessage alloc] - initWithFormat:[NSString stringWithFormat:@"+++ LOG_QUEUE_DISABLED+++ %@", logMessage.messageFormat] - formatted:[NSString stringWithFormat:@"+++ LOG_QUEUE_DISABLED+++ %@", logMessage.message] - level:logMessage.level - flag:logMessage.flag - context:logMessage.context - file:logMessage.file - function:logMessage.function - line:logMessage.line - tag:logMessage.tag - options:logMessage.options - timestamp:logMessage.timestamp]]; -#pragma clang diagnostic pop - } - return [self swizzled_queueLogMessage:logMessage asynchronously:isSuspended ? YES : asyncFlag]; + return [self swizzled_queueLogMessage:logMessage asynchronously:_suspensionHandling_isSuspended ? YES : asyncFlag]; } //see https://stackoverflow.com/a/13326633 and https://fek.io/blog/method-swizzling-in-obj-c-and-swift/ @@ -2121,10 +2123,10 @@ +(NSData* _Nullable) convertLogmessageToJsonData:(DDLogMessage*) logMessage coun @"queueThreadLabel": nilWrapper([self getQueueThreadLabelFor:logMessage]), @"processType": [self isAppExtension] ? @"appex" : @"mainapp", @"processName": nilWrapper([[[NSBundle mainBundle] executablePath] lastPathComponent]), - @"counter": [NSNumber numberWithUnsignedLongLong:*counter], + @"counter": @(*counter), @"processID": nilWrapper(_processID), @"qosName": nilWrapper(qos2name(logMessage.qos)), - @"loggingQueueSuspended": bool2str(_suspensionHandling_isSuspended), + @"loggingQueueSuspended": @([self isAppSuspended]), #pragma clang diagnostic push #pragma clang diagnostic ignored "-Wdeprecated-declarations" @"tag": nilWrapper(logMessage.tag), @@ -2133,21 +2135,21 @@ +(NSData* _Nullable) convertLogmessageToJsonData:(DDLogMessage*) logMessage coun NSDictionary* msgDict = @{ @"messageFormat": nilWrapper(logMessage.messageFormat), @"message": nilWrapper(logMessage.message), - @"level": [NSNumber numberWithInteger:logMessage.level], - @"flag": [NSNumber numberWithInteger:logMessage.flag], - @"context": [NSNumber numberWithInteger:logMessage.context], + @"level": @(logMessage.level), + @"flag": @(logMessage.flag), + @"context": @(logMessage.context), @"file": nilWrapper(logMessage.file), @"fileName": nilWrapper(logMessage.fileName), @"function": nilWrapper(logMessage.function), - @"line": [NSNumber numberWithInteger:logMessage.line], + @"line": @(logMessage.line), @"representedObject": nilWrapper(logMessage.representedObject), @"tag": nilWrapper(tag), - @"options": [NSNumber numberWithInteger:logMessage.options], + @"options": @(logMessage.options), @"timestamp": [dateFormatter stringFromDate:logMessage.timestamp], @"threadID": nilWrapper(logMessage.threadID), @"threadName": nilWrapper(logMessage.threadName), @"queueLabel": nilWrapper(logMessage.queueLabel), - @"qos": [NSNumber numberWithInteger:logMessage.qos], + @"qos": @(logMessage.qos), }; //encode json into NSData @@ -2170,6 +2172,13 @@ +(void) flushLogsWithTimeout:(double) timeout [MLUDPLogger flushWithTimeout:timeout]; } ++(BOOL) isAppSuspended +{ + @synchronized(_suspensionHandling_lock) { + return _suspensionHandling_isSuspended; + } +} + +(void) signalSuspension { @synchronized(_suspensionHandling_lock) { diff --git a/Monal/Classes/MLUDPLogger.m b/Monal/Classes/MLUDPLogger.m index dc9b53172c..75ff78b0dc 100644 --- a/Monal/Classes/MLUDPLogger.m +++ b/Monal/Classes/MLUDPLogger.m @@ -87,7 +87,7 @@ +(void) directlyWriteLogMessage:(DDLogMessage*) logMessage [[self class] logError:@"Ignoring call to directlySyncWriteLogMessage: _self still nil!"]; return; } - return [_self logMessage:logMessage]; + return [_self realLogMessage:logMessage wasDirect:YES]; } -(void) dealloc @@ -243,6 +243,11 @@ -(void) createConnectionIfNeeded } -(void) logMessage:(DDLogMessage*) logMessage +{ + return [self realLogMessage:logMessage wasDirect:NO]; +} + +-(void) realLogMessage:(DDLogMessage*) logMessage wasDirect:(BOOL) direct { static uint64_t counter = 0; @@ -250,6 +255,10 @@ -(void) logMessage:(DDLogMessage*) logMessage if(![[HelperTools defaultsDB] boolForKey: @"udpLoggerEnabled"]) return; + //ignore log messages already udp-logged as direct messages when handling queued messages + if(!direct && logMessage.ml_isDirect) + return; + NSError* error = nil; NSData* rawData = [HelperTools convertLogmessageToJsonData:logMessage counter:&counter andError:&error]; if(error != nil || rawData == nil) diff --git a/UDPLogServer/server.py b/UDPLogServer/server.py index e7a963cc0f..456750d4cd 100755 --- a/UDPLogServer/server.py +++ b/UDPLogServer/server.py @@ -161,7 +161,11 @@ def formatLogline(entry): kwargs = flag_to_kwargs(decoded["flag"] if "flag" in decoded else None) # print original formatted log message - logline = ("%d: %s" % (decoded["tag"]["counter"], formatLogline(decoded))) + logline = "%s%d: %s" % ( + "+++ LOG_QUEUE_DISABLED +++ " if "tag" in decoded and "loggingQueueSuspended" in decoded["tag"] and decoded["tag"]["loggingQueueSuspended"]==True else "", + decoded["tag"]["counter"], + formatLogline(decoded) + ) if logfd: print(logline, file=logfd) print(colorize(logline, **kwargs), flush=True)