Merge pull request #21 from mjcheetham/mac-adal-logs

Fix the MSAuthHelper on macOS to trace ADAL logs and return correct exit codes

Author: mjcheetham

common/src/Microsoft.Git.CredentialManager/Authentication/MicrosoftAuthentication.cs

@@ -53,10 +53,14 @@ public async Task<IDictionary<string, string>> InvokeHelperAsync(IDictionary<str
             {
                 RedirectStandardInput = true,
                 RedirectStandardOutput = true,
-                RedirectStandardError = true,
+                RedirectStandardError = false, // Do not redirect stderr as tracing might be enabled
                 UseShellExecute = false
             };
 
+            // We flush the trace writers here so that the we don't stomp over the
+            // authentication helper's messages.
+            _context.Trace.Flush();
+
             var process = Process.Start(procStartInfo);
 
             await process.StandardInput.WriteDictionaryAsync(input);

common/src/Microsoft.Git.CredentialManager/Constants.cs

@@ -13,6 +13,7 @@ public static class EnvironmentVariables
         {
             public const string GcmTrace           = "GCM_TRACE";
             public const string GcmTraceSecrets    = "GCM_TRACE_SECRETS";
+            public const string GcmTraceMsAuth     = "GCM_TRACE_MSAUTH";
             public const string GcmDebug           = "GCM_DEBUG";
             public const string GitTerminalPrompts = "GIT_TERMINAL_PROMPT";
         }

macos/Microsoft.Authentication.Helper/Podfile

@@ -1,5 +1,5 @@
 platform :osx, '10.11'
 
 target 'Microsoft.Authentication.Helper' do
-  pod 'ADAL', '~> 2.5.1'
+  pod 'ADAL', '~> 4.0.0'
 end

macos/Microsoft.Authentication.Helper/Podfile.lock

@@ -1,19 +1,19 @@
 PODS:
-  - ADAL (2.5.4):
-    - ADAL/app-lib (= 2.5.4)
-  - ADAL/app-lib (2.5.4):
+  - ADAL (4.0.0):
+    - ADAL/app-lib (= 4.0.0)
+  - ADAL/app-lib (4.0.0):
     - ADAL/tokencacheheader
 
 DEPENDENCIES:
-  - ADAL (~> 2.5.1)
+  - ADAL (~> 4.0.0)
 
 SPEC REPOS:
   https://github.com/cocoapods/specs.git:
     - ADAL
 
 SPEC CHECKSUMS:
-  ADAL: e7e5aca957d6c67e88cdd68ee3d0c4c4af55e874
+  ADAL: 2f09070fb5a7095172e34409459eca3f3f1d0d23
 
-PODFILE CHECKSUM: aea86594216c71aff5d22f8947aea9501e7ece3f
+PODFILE CHECKSUM: f7b3f5867bd6bb83186e92dedf7b8183795ffc5d
 
 COCOAPODS: 1.5.3

macos/Microsoft.Authentication.Helper/Source/Core/AHAppDelegate.h

@@ -14,7 +14,6 @@ typedef void(^AHAppWorkBlock) (void);
 
 @property (retain, nonatomic) NSApplication* application;
 @property (retain, nonatomic) NSError* error;
-@property (assign, nonatomic) BOOL userLoggingAllowed;
 
 -(id)initWithBlock:(AHAppWorkBlock)block logger:(AHLogger*)logger;
 

macos/Microsoft.Authentication.Helper/Source/Core/AHAppDelegate.m

@@ -26,10 +26,7 @@ -(void)run
     [application setDelegate:self];
     [NSApp setActivationPolicy:NSApplicationActivationPolicyRegular];
 
-    if ([self userLoggingAllowed])
-    {
-        [_logger log:@"Creating application context for authentication prompt"];
-    }
+    AHLOG(_logger, @"Creating application context for authentication prompt");
 
     [NSApp run];
 }

macos/Microsoft.Authentication.Helper/Source/Core/AHGenerateAccessToken.m

@@ -28,7 +28,15 @@ + (NSString*) generateAccessTokenWithAuthority:(NSString*)authority
 
         ADAuthenticationCallback completionBlock = ^(ADAuthenticationResult *result)
         {
-            accessToken = result.accessToken;
+            if (result.status == AD_SUCCEEDED)
+            {
+                accessToken = result.accessToken;
+            }
+            else // AD_FAILED or AD_USER_CANCELLED
+            {
+                [appDelegate setError:result.error];
+            }
+
             [appDelegate stop];
         };
 

macos/Microsoft.Authentication.Helper/Source/Core/AHLogger.h

@@ -4,6 +4,9 @@
 #import <Foundation/Foundation.h>
 #import "AHLogWriter.h"
 
+#define AHLOG(LOGGER,MSG) [LOGGER log:(MSG) fileName:@__FILE__ lineNum:__LINE__]
+#define AHLOG_SECRET(LOGGER,MSG,SECRET) [LOGGER log:(MSG) secretMsg:(SECRET) fileName:@__FILE__ lineNum:__LINE__]
+
 NS_ASSUME_NONNULL_BEGIN
 
 @interface AHLogger : NSObject
@@ -12,9 +15,17 @@ NS_ASSUME_NONNULL_BEGIN
     NSDateFormatter *dateFormatter;
 }
 
+@property BOOL enableSecretTracing;
+
 - (instancetype) init;
 - (void) addWriter:(NSObject<AHLogWriter> *) writer;
-- (void) log:(NSString*)message;
+- (void) log:(NSString*)message
+    fileName:(NSString*)fileName
+     lineNum:(int)lineNum;
+- (void) log:(NSString*)message
+   secretMsg:(NSString*)secretMsg
+    fileName:(NSString*)fileName
+    lineNum:(int)lineNum;
 
 @end
 

macos/Microsoft.Authentication.Helper/Source/Core/AHLogger.m

@@ -12,7 +12,12 @@ -(instancetype)init
     {
         self->writers = [[NSMutableArray<AHLogWriter> alloc] init];
         self->dateFormatter = [[NSDateFormatter alloc] init];
-        [self->dateFormatter setDateFormat:@"yyyy/MM/dd HH:mm:ss:SSS"];
+
+        // Configure the date formatter based on the POSIX locale as "HH" can still return
+        // a 12-hour style time if the user's locale has disabled the 24-hour style.
+        NSLocale *enUSPOSIXLocale = [[NSLocale alloc] initWithLocaleIdentifier:@"en_US_POSIX"];
+        [self->dateFormatter setLocale:enUSPOSIXLocale];
+        [self->dateFormatter setDateFormat:@"HH:mm:ss:SSSSSS"];
     }
 
     return self;
@@ -24,9 +29,21 @@ - (void) addWriter:(NSObject<AHLogWriter> *) writer
 }
 
 -(void)log:(NSString*)message
+  fileName:(NSString*)fileName
+   lineNum:(int)lineNum
 {
-    NSString* logMessage = [NSString stringWithFormat:@"%@: %@\n",
-                            [dateFormatter stringFromDate:[NSDate date]],
+    // To be consistent with Git and GCM's main trace output format we want the source (file:line)
+    // column to be 23 characters wide, truncating the start with "..." if required.
+    NSString* source = [[NSString alloc] initWithFormat:@"%@:%d", fileName, lineNum];
+    if ([source length] > 23)
+    {
+        NSInteger extra = [source length] - 23 + 3;
+        source = [[NSString alloc] initWithFormat:@"...%@", [source substringFromIndex:extra]];
+    }
+
+    NSString* logMessage = [NSString stringWithFormat:@"%@ %23s trace: %@\n",
+                      [dateFormatter stringFromDate:[NSDate date]],
+                            [source UTF8String],
                             message];
 
     for (NSObject<AHLogWriter> *writer in self->writers)
@@ -35,4 +52,26 @@ -(void)log:(NSString*)message
     }
 }
 
+-(void)log:(NSString*)message
+ secretMsg:(NSString*)secretMsg
+  fileName:(NSString*)fileName
+   lineNum:(int)lineNum;
+{
+    NSString* combinedMessage;
+    if ([self enableSecretTracing])
+    {
+        combinedMessage = [[NSString alloc] initWithFormat:@"%@ PII: %@",
+                           message, secretMsg];
+    }
+    else
+    {
+        combinedMessage = [[NSString alloc] initWithFormat:@"%@ PII: ********",
+                           message];
+    }
+    
+    [self log:combinedMessage
+     fileName:fileName
+      lineNum:lineNum];
+}
+
 @end

macos/Microsoft.Authentication.Helper/Source/main.m

@@ -7,6 +7,7 @@
 #import "AHLogger.h"
 #import "AHFileLogWriter.h"
 #import "AHStdErrorLogWriter.h"
+#import <ADAL/ADAL.h>
 
 BOOL isTruthy(NSString* value) {
     if (value == nil) {
@@ -24,28 +25,77 @@ BOOL isLocalFilePath(NSString *path) {
 }
 
 int main(int argc, const char * argv[]) {
+
     @autoreleasepool {
+        int exitCode;
         NSError* error;
 
         AHLogger *logger = [[AHLogger alloc] init];
 
-        NSString* traceEnvar = [[[NSProcessInfo processInfo] environment] objectForKey:@"GCM_TRACE"];
+        // Configure the application logger based on the common GCM tracing environment variables
+        NSString* traceEnvar        = [[[NSProcessInfo processInfo] environment] objectForKey:@"GCM_TRACE"];
+        NSString* traceSecretsEnvar = [[[NSProcessInfo processInfo] environment] objectForKey:@"GCM_TRACE_SECRETS"];
+        NSString* traceMsAuthEnvar  = [[[NSProcessInfo processInfo] environment] objectForKey:@"GCM_TRACE_MSAUTH"];
 
+        // Enable tracing
         if (isTruthy(traceEnvar)) {
             [logger addWriter:[[AHStdErrorLogWriter alloc] init]];
         }
         else if (isLocalFilePath(traceEnvar)) {
             [logger addWriter:[[AHFileLogWriter alloc] initWithPath:traceEnvar]];
         }
 
-        [logger log:@"Running Microsoft Authentication helper for macOS"];
+        // Enable tracing of secret/sensitive information
+        if (isTruthy(traceSecretsEnvar)) {
+            [logger setEnableSecretTracing:YES];
+
+            // Also enable PII logging in ADAL
+            [ADLogger setPiiEnabled:YES];
+        }
+
+        // Always disable ADAL from logging to NSLog which prints to stderror directly
+        [ADLogger setNSLogging:NO];
+
+        // Register a callback in ADAL for our logger if GCM_TRACE_MSAUTH is enabled
+        if (isTruthy(traceMsAuthEnvar))
+        {
+            // We try and capture everything we can as this can help with diagnosing
+            // the most complicated authentication problems.
+            [ADLogger setLevel:ADAL_LOG_LEVEL_VERBOSE];
+
+            [ADLogger setLoggerCallback:^(ADAL_LOG_LEVEL logLevel, NSString *message, BOOL containsPii) {
+
+                NSString* logLevelName;
+                switch (logLevel) {
+                    case ADAL_LOG_LEVEL_ERROR:
+                        logLevelName = @"Error";
+                        break;
+                    case ADAL_LOG_LEVEL_WARN:
+                        logLevelName = @"Warning";
+                        break;
+                    case ADAL_LOG_LEVEL_INFO:
+                        logLevelName = @"Info";
+                        break;
+                    case ADAL_LOG_LEVEL_VERBOSE:
+                        logLevelName = @"Verbose";
+                        break;
+                    default:
+                        logLevelName = @"Unknown";
+                        break;
+                }
+
+                [logger log:[NSString stringWithFormat:@"[ADAL] [%@] %@", logLevelName, message] fileName:@"ADAL" lineNum:0];
+            }];
+        }
+
+        AHLOG(logger, @"Running Microsoft Authentication helper for macOS");
 
         NSMutableDictionary<NSString *, NSString *> *configs = [NSMutableDictionary dictionaryFromFileHandle:[NSFileHandle fileHandleWithStandardInput]];
 
         // Extract expected parameters from input
-        NSString* authority = [configs objectForKey:@"authority"];
-        NSString* clientId = [configs objectForKey:@"clientId"];
-        NSString* resource = [configs objectForKey:@"resource"];
+        NSString* authority   = [configs objectForKey:@"authority"];
+        NSString* clientId    = [configs objectForKey:@"clientId"];
+        NSString* resource    = [configs objectForKey:@"resource"];
         NSString* redirectUri = [configs objectForKey:@"redirectUri"];
 
         NSString *accessToken = [AHGenerateAccessToken generateAccessTokenWithAuthority:authority
@@ -55,9 +105,20 @@ int main(int argc, const char * argv[]) {
                                                                                   error:&error
                                                                                  logger:logger];
 
-        NSString* output = [NSString stringWithFormat:@"accessToken=%@\n", accessToken];
+        NSString* output;
+
+        if (error == nil && accessToken != nil)
+        {
+            output = [NSString stringWithFormat:@"accessToken=%@\n", accessToken];
+            exitCode = 0;
+        }
+        else
+        {
+            output = [NSString stringWithFormat:@"error=%@\n", [error description]];
+            exitCode = -1;
+        }
+
         [output writeToFile:@"/dev/stdout" atomically:NO encoding:NSUTF8StringEncoding error:&error];
+        return exitCode;
     }
-
-    return 0;
 }