NR-335442: NRLogger: fix the log:inFile methods to check for remote l…

…og level. (#325)

* NRLogger: fix the log:inFile methods to check for remote log level. Fix up NRLoggerTests

* Remove unused form of log:inFile

Agent/Public/NRLogger.h

@@ -117,12 +117,6 @@ typedef enum _NRLogTargets {
 
 }
 
-+ (void)log:(unsigned int)level
-     inFile:(NSString *)file
-     atLine:(unsigned int)line
-   inMethod:(NSString *)method
-withMessage:(NSString *)message;
-
 + (void)log:(unsigned int)level
      inFile:(NSString *)file
      atLine:(unsigned int)line

Agent/Utilities/NRLogger.m

@@ -19,7 +19,7 @@
 #define kNRMAMaxLogUploadRetry 3
 
 @interface NRLogger()
-- (void)addLogMessage:(NSDictionary *)message;
+- (void)addLogMessage:(NSDictionary *)message : (BOOL) agentLogsOn;
 - (void)setLogLevels:(unsigned int)levels;
 - (void)setRemoteLogLevel:(unsigned int)level;
 
@@ -37,32 +37,6 @@ + (NRLogger *)logger {
     return _nr_logger;
 }
 
-+ (void)log:(unsigned int)level
-     inFile:(NSString *)file
-     atLine:(unsigned int)line
-   inMethod:(NSString *)method
-withMessage:(NSString *)message {
-
-    NRLogger *logger = [NRLogger logger];
-    BOOL shouldLog = NO;
-
-    // This shouldLog BOOL was previously set within a @synchronized block but I was seeing a deadlock. Trying some tests without
-    // @synchronized(logger) {
-    shouldLog = (logger->logLevels & level) != 0;
-    // }
-
-    if (shouldLog) {
-        [logger addLogMessage:[NSDictionary dictionaryWithObjectsAndKeys:
-                               [self levelToString:level], NRLogMessageLevelKey,
-                               file, NRLogMessageFileKey,
-                               [NSNumber numberWithUnsignedInt:line], NRLogMessageLineNumberKey,
-                               method, NRLogMessageMethodKey,
-                               [NSNumber numberWithLongLong: (long long)([[NSDate date] timeIntervalSince1970] * 1000.0)], NRLogMessageTimestampKey,
-                               message, NRLogMessageMessageKey,
-                               nil]: NO];
-    }
-}
-
 + (void)log:(unsigned int)level
      inFile:(NSString *)file
      atLine:(unsigned int)line
@@ -71,14 +45,11 @@ + (void)log:(unsigned int)level
 withAttributes:(NSDictionary *)attributes {
 
     NRLogger *logger = [NRLogger logger];
-    BOOL shouldLog = NO;
-
-    // This shouldLog BOOL was previously set within a @synchronized block but I was seeing a deadlock. Trying some tests without
-    // @synchronized(logger) {
-    shouldLog = (logger->logLevels & level) != 0;
-    // }
-
-    if (shouldLog) {
+
+    BOOL shouldRemoteLog = (logger->remoteLogLevel & level) != 0;
+    BOOL shouldLog =(logger->logLevels & level) != 0;
+
+    if (shouldLog || shouldRemoteLog) {
         NSMutableDictionary *mutableDict = [NSMutableDictionary dictionaryWithObjectsAndKeys:
                                             [self levelToString:level], NRLogMessageLevelKey,
                                             file, NRLogMessageFileKey,
@@ -99,18 +70,12 @@ + (void)log:(unsigned int)level
 withAgentLogsOn:(BOOL)agentLogsOn {
 
     NRLogger *logger = [NRLogger logger];
-    BOOL shouldLog = NO;
 
+    BOOL shouldRemoteLog = (logger->remoteLogLevel & level) != 0;
     // Filter passed logs by log level.
-    shouldLog = (logger->logLevels & level) != 0;
-
-// Filtering of Console logs is performed based on logLevel.
-//    // If this is an agentLog, only print it if we are currently including the debug level.
-//    if (agentLogsOn) {
-//        shouldLog = (logger->logLevels & NRLogLevelDebug) != 0;
-//    }
-
-    if (shouldLog) {
+    BOOL shouldLog  = (logger->logLevels & level) != 0;
+
+    if (shouldLog || shouldRemoteLog) {
         [logger addLogMessage:[NSDictionary dictionaryWithObjectsAndKeys:
                                [self levelToString:level], NRLogMessageLevelKey,
                                file, NRLogMessageFileKey,
@@ -253,7 +218,13 @@ - (void)dealloc {
 - (void)addLogMessage:(NSDictionary *)message : (BOOL) agentLogsOn {
     // The static method checks the log level before we get here.
     dispatch_async(logQueue, ^{
-        if (self->logTargets & NRLogTargetConsole) {
+
+        // Only enter this first block if local log level includes this level enabled.
+        NSString *levelString = [message objectForKey:NRLogMessageLevelKey];
+        NRLogLevels level = [NRLogger stringToLevel:levelString];
+        BOOL shouldLog = (self->logLevels & level) != 0;
+
+        if ((self->logTargets & NRLogTargetConsole) && shouldLog) {
             NSLog(@"NewRelic(%@,%p):\t%@:%@\t%@\n\t%@",
                   [NewRelicInternalUtils agentVersion],
                   [NSThread currentThread],
@@ -264,8 +235,6 @@ - (void)addLogMessage:(NSDictionary *)message : (BOOL) agentLogsOn {
 
         }
         // Only enter this block if remote logging is including this messages level.
-        NSString *levelString = [message objectForKey:NRLogMessageLevelKey];
-        NRLogLevels level = [NRLogger stringToLevel:levelString];
 
         BOOL shouldRemoteLog = (self->remoteLogLevel & level) != 0;
 

Tests/Unit-Tests/NewRelicAgentTests/Uncategorized/NRLoggerTests.m

@@ -167,8 +167,100 @@ - (void) testNRLogger {
 
 - (void) testRemoteLogLevels {
 
-    // Set the remote log level to warning.
-    [NRLogger setRemoteLogLevel:NRLogLevelWarning];
+    [NRLogger setLogLevels:NRLogLevelInfo];
+
+    // Set the remote log level to Debug.
+    [NRLogger setRemoteLogLevel:NRLogLevelDebug];
+
+    XCTestExpectation *delayExpectation1 = [self expectationWithDescription:@"Waiting for Log Queue"];
+
+    dispatch_after(dispatch_time(DISPATCH_TIME_NOW, (int64_t)(2 * NSEC_PER_SEC)), dispatch_get_main_queue(), ^{
+        [delayExpectation1 fulfill];
+    });
+
+    [self waitForExpectationsWithTimeout:5 handler:^(NSError * _Nullable error) {
+        if (error) {
+            XCTFail(@"Timeout error");
+        }
+    }];
+
+    // Seven messages should reach the remote log file for upload.
+
+    [NewRelic logInfo:   @"Info Log..."];
+    [NewRelic logError:  @"Error Log..."];
+    [NewRelic logVerbose:@"Verbose Log..."];
+    [NewRelic logWarning:@"Warning Log..."];
+    [NewRelic logAudit:  @"Audit Log..."];
+    [NewRelic logDebug:  @"Debug Log..."];
+    [NewRelic logAttributes:@{
+        @"logLevel": @"WARN",
+        @"message": @"This is a test message for the New Relic logging system.",
+        @"additionalAttribute1": @"attribute1",
+        @"additionalAttribute2": @"attribute2"
+    }];
+
+    XCTestExpectation *delayExpectation2 = [self expectationWithDescription:@"Waiting for Log Queue"];
+
+    dispatch_after(dispatch_time(DISPATCH_TIME_NOW, (int64_t)(2 * NSEC_PER_SEC)), dispatch_get_main_queue(), ^{
+        [delayExpectation2 fulfill];
+    });
+
+    [self waitForExpectationsWithTimeout:5 handler:^(NSError * _Nullable error) {
+        if (error) {
+            XCTFail(@"Timeout error");
+        }
+    }];
+
+    NSError* error;
+    NSData* logData = [NRLogger logFileData:&error];
+    if(error){
+        NSLog(@"%@", error.localizedDescription);
+    }
+    NSString* logMessagesJson = [NSString stringWithFormat:@"[ %@ ]", [[NSString alloc] initWithData:logData encoding:NSUTF8StringEncoding]];
+    NSData* formattedData = [logMessagesJson dataUsingEncoding:NSUTF8StringEncoding];
+    NSArray* decode = [NSJSONSerialization JSONObjectWithData:formattedData
+                                                      options:0
+                                                        error:nil];
+    NSLog(@"decode=%@", decode);
+
+    NSArray * expectedValues = @[
+        @{@"message": @"Info Log..."},
+        @{@"message": @"Error Log..."},
+        @{@"message": @"Verbose Log..."},
+        @{@"message": @"Warning Log..."},
+        @{@"message": @"Audit Log..."},
+        @{@"message": @"Debug Log..."},
+        @{@"message": @"This is a test message for the New Relic logging system."},
+    ];
+    // check for existence of 6 logs.
+    int foundCount = 0;
+    // For each expected message.
+    for (NSDictionary *dict in expectedValues) {
+        // Iterate through the collected message logs.
+        for (NSDictionary *dict2 in decode) {
+            //
+            NSString* currentMessage = [dict objectForKey:@"message"];
+            if ([[dict2 objectForKey:@"message"] isEqualToString: currentMessage]) {
+                foundCount += 1;
+                XCTAssertTrue([[dict2 objectForKey:@"entity.guid"] isEqualToString:@"Entity-Guid-XXXX"],@"entity.guid set incorrectly");
+            }
+            // Verify added attributes with logAttributes.
+            if ([[dict2 objectForKey:@"message"] isEqualToString:@"This is a test message for the New Relic logging system."]) {
+                XCTAssertTrue([[dict2 objectForKey:@"additionalAttribute1"] isEqualToString:@"attribute1"],@"additionalAttribute1 set incorrectly");
+                XCTAssertTrue([[dict2 objectForKey:@"additionalAttribute2"] isEqualToString:@"attribute2"],@"additionalAttribute2 set incorrectly");
+            }
+        }
+    }
+
+    XCTAssertEqual(foundCount, 7, @"Seven remote messages should be found.");
+}
+
+- (void) testLocalLogLevels {
+
+    // Set the local log level to Debug
+    [NRLogger setLogLevels:NRLogLevelDebug];
+    // Set the remote log level to Info.
+    [NRLogger setRemoteLogLevel:NRLogLevelInfo];
 
     XCTestExpectation *delayExpectation1 = [self expectationWithDescription:@"Waiting for Log Queue"];
 
@@ -182,7 +274,7 @@ - (void) testRemoteLogLevels {
         }
     }];
 
-    // Three messages should reach the remote log file for upload.
+    // Seven messages should reach the remote log file for upload.
 
     [NewRelic logInfo:   @"Info Log..."];
     [NewRelic logError:  @"Error Log..."];
@@ -250,7 +342,7 @@ - (void) testRemoteLogLevels {
         }
     }
 
-    XCTAssertEqual(foundCount, 3, @"Three remote messages should be found.");
+    XCTAssertEqual(foundCount, 4, @"Four remote messages should be found.");
 }
 
 @end