Improve UDP logging while logger queue is suspended

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;

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,19 @@ -(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];
+    }
+
     //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 +2121,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 +2133,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 +2170,13 @@ +(void) flushLogsWithTimeout:(double) timeout
     [MLUDPLogger flushWithTimeout:timeout];
 }
 
++(BOOL) isAppSuspended
+{
+    @synchronized(_suspensionHandling_lock) {
+        return _suspensionHandling_isSuspended;
+    }
+}
+
 +(void) signalSuspension
 {
     @synchronized(_suspensionHandling_lock) {

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,13 +243,22 @@ -(void) createConnectionIfNeeded
 }
 
 -(void) logMessage:(DDLogMessage*) logMessage
+{
+    return [self realLogMessage:logMessage wasDirect:NO];
+}
+
+-(void) realLogMessage:(DDLogMessage*) logMessage wasDirect:(BOOL) direct
 {
     static uint64_t counter = 0;
 
     //early return if deactivated
     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)

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)