HADOOP-16699. Add verbose TRACE logging to ABFS.

Contributed by Sneha Vijayarajan,

Change-Id: Ic616a10406e6e9f11616c9cc05d8630ebbedaf65

hadoop-tools/hadoop-azure/src/main/java/org/apache/hadoop/fs/azurebfs/AbfsConfiguration.java

@@ -63,6 +63,9 @@
 import org.apache.hadoop.security.ProviderUtils;
 import org.apache.hadoop.util.ReflectionUtils;
 
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
 import static org.apache.hadoop.fs.azurebfs.constants.ConfigurationKeys.*;
 import static org.apache.hadoop.fs.azurebfs.constants.FileSystemConfigurations.*;
 
@@ -76,6 +79,7 @@ public class AbfsConfiguration{
   private final Configuration rawConfig;
   private final String accountName;
   private final boolean isSecure;
+  private static final Logger LOG = LoggerFactory.getLogger(AbfsConfiguration.class);
 
   @IntegerConfigurationValidatorAnnotation(ConfigurationKey = AZURE_WRITE_BUFFER_SIZE,
       MinValue = MIN_BUFFER_SIZE,
@@ -505,11 +509,13 @@ public AccessTokenProvider getTokenProvider() throws TokenAccessProviderExceptio
           String clientId = getPasswordString(FS_AZURE_ACCOUNT_OAUTH_CLIENT_ID);
           String clientSecret = getPasswordString(FS_AZURE_ACCOUNT_OAUTH_CLIENT_SECRET);
           tokenProvider = new ClientCredsTokenProvider(authEndpoint, clientId, clientSecret);
+          LOG.trace("ClientCredsTokenProvider initialized");
         } else if (tokenProviderClass == UserPasswordTokenProvider.class) {
           String authEndpoint = getPasswordString(FS_AZURE_ACCOUNT_OAUTH_CLIENT_ENDPOINT);
           String username = getPasswordString(FS_AZURE_ACCOUNT_OAUTH_USER_NAME);
           String password = getPasswordString(FS_AZURE_ACCOUNT_OAUTH_USER_PASSWORD);
           tokenProvider = new UserPasswordTokenProvider(authEndpoint, username, password);
+          LOG.trace("UserPasswordTokenProvider initialized");
         } else if (tokenProviderClass == MsiTokenProvider.class) {
           String authEndpoint = getTrimmedPasswordString(
               FS_AZURE_ACCOUNT_OAUTH_MSI_ENDPOINT,
@@ -522,6 +528,7 @@ public AccessTokenProvider getTokenProvider() throws TokenAccessProviderExceptio
           authority = appendSlashIfNeeded(authority);
           tokenProvider = new MsiTokenProvider(authEndpoint, tenantGuid,
               clientId, authority);
+          LOG.trace("MsiTokenProvider initialized");
         } else if (tokenProviderClass == RefreshTokenBasedTokenProvider.class) {
           String authEndpoint = getTrimmedPasswordString(
               FS_AZURE_ACCOUNT_OAUTH_REFRESH_TOKEN_ENDPOINT,
@@ -530,6 +537,7 @@ public AccessTokenProvider getTokenProvider() throws TokenAccessProviderExceptio
           String clientId = getPasswordString(FS_AZURE_ACCOUNT_OAUTH_CLIENT_ID);
           tokenProvider = new RefreshTokenBasedTokenProvider(authEndpoint,
               clientId, refreshToken);
+          LOG.trace("RefreshTokenBasedTokenProvider initialized");
         } else {
           throw new IllegalArgumentException("Failed to initialize " + tokenProviderClass);
         }
@@ -554,7 +562,9 @@ public AccessTokenProvider getTokenProvider() throws TokenAccessProviderExceptio
         if (azureTokenProvider == null) {
           throw new IllegalArgumentException("Failed to initialize " + customTokenProviderClass);
         }
+        LOG.trace("Initializing {}", customTokenProviderClass.getName());
         azureTokenProvider.initialize(rawConfig, accountName);
+        LOG.trace("{} init complete", customTokenProviderClass.getName());
         return new CustomTokenProviderAdapter(azureTokenProvider);
       } catch(IllegalArgumentException e) {
         throw e;
@@ -581,7 +591,9 @@ public AbfsAuthorizer getAbfsAuthorizer() throws IOException {
         @SuppressWarnings("unchecked")
         Class<AbfsAuthorizer> authClass = (Class<AbfsAuthorizer>) rawConfig.getClassByName(authClassName);
         authorizer = authClass.getConstructor(new Class[] {Configuration.class}).newInstance(rawConfig);
+        LOG.trace("Initializing {}", authClassName);
         authorizer.init();
+        LOG.trace("{} init complete", authClassName);
       }
     } catch (
         IllegalAccessException

hadoop-tools/hadoop-azure/src/main/java/org/apache/hadoop/fs/azurebfs/AzureBlobFileSystem.java

@@ -107,6 +107,8 @@ public void initialize(URI uri, Configuration configuration)
 
     this.uri = URI.create(uri.getScheme() + "://" + uri.getAuthority());
     this.abfsStore = new AzureBlobFileSystemStore(uri, this.isSecureScheme(), configuration);
+    LOG.trace("AzureBlobFileSystemStore init complete");
+
     final AbfsConfiguration abfsConfiguration = abfsStore.getAbfsConfiguration();
 
     this.setWorkingDirectory(this.getHomeDirectory());
@@ -121,6 +123,7 @@ public void initialize(URI uri, Configuration configuration)
       }
     }
 
+    LOG.trace("Initiate check for delegation token manager");
     if (UserGroupInformation.isSecurityEnabled()) {
       this.delegationTokenEnabled = abfsConfiguration.isDelegationTokenManagerEnabled();
 
@@ -137,6 +140,7 @@ public void initialize(URI uri, Configuration configuration)
     // Initialize ABFS authorizer
     //
     this.authorizer = abfsConfiguration.getAbfsAuthorizer();
+    LOG.debug("Initializing AzureBlobFileSystem for {} complete", uri);
   }
 
   @Override

hadoop-tools/hadoop-azure/src/main/java/org/apache/hadoop/fs/azurebfs/AzureBlobFileSystemStore.java

@@ -148,8 +148,12 @@ public AzureBlobFileSystemStore(URI uri, boolean isSecureScheme, Configuration c
     } catch (IllegalAccessException exception) {
       throw new FileSystemOperationUnhandledException(exception);
     }
+
+    LOG.trace("AbfsConfiguration init complete");
+
     this.userGroupInformation = UserGroupInformation.getCurrentUser();
     this.userName = userGroupInformation.getShortUserName();
+    LOG.trace("UGI init complete");
     if (!abfsConfiguration.getSkipUserGroupMetadataDuringInitialization()) {
       try {
         this.primaryUserGroup = userGroupInformation.getPrimaryGroupName();
@@ -161,6 +165,7 @@ public AzureBlobFileSystemStore(URI uri, boolean isSecureScheme, Configuration c
       //Provide a default group name
       this.primaryUserGroup = userName;
     }
+    LOG.trace("primaryUserGroup is {}", this.primaryUserGroup);
 
     this.azureAtomicRenameDirSet = new HashSet<>(Arrays.asList(
         abfsConfiguration.getAzureAtomicRenameDirs().split(AbfsHttpConstants.COMMA)));
@@ -170,6 +175,7 @@ public AzureBlobFileSystemStore(URI uri, boolean isSecureScheme, Configuration c
     this.abfsPerfTracker = new AbfsPerfTracker(fileSystemName, accountName, this.abfsConfiguration);
     initializeClient(uri, fileSystemName, accountName, useHttps);
     this.identityTransformer = new IdentityTransformer(abfsConfiguration.getRawConfiguration());
+    LOG.trace("IdentityTransformer init complete");
   }
 
   /**
@@ -296,6 +302,7 @@ public Hashtable<String, String> getFilesystemProperties() throws AzureBlobFileS
   public void setFilesystemProperties(final Hashtable<String, String> properties)
       throws AzureBlobFileSystemException {
     if (properties == null || properties.isEmpty()) {
+      LOG.trace("setFilesystemProperties no properties present");
       return;
     }
 
@@ -1116,6 +1123,7 @@ private void initializeClient(URI uri, String fileSystemName, String accountName
     AccessTokenProvider tokenProvider = null;
 
     if (abfsConfiguration.getAuthType(accountName) == AuthType.SharedKey) {
+      LOG.trace("Fetching SharedKey credentials");
       int dotIndex = accountName.indexOf(AbfsHttpConstants.DOT);
       if (dotIndex <= 0) {
         throw new InvalidUriException(
@@ -1124,14 +1132,17 @@ private void initializeClient(URI uri, String fileSystemName, String accountName
       creds = new SharedKeyCredentials(accountName.substring(0, dotIndex),
             abfsConfiguration.getStorageAccountKey());
     } else {
+      LOG.trace("Fetching token provider");
       tokenProvider = abfsConfiguration.getTokenProvider();
       ExtensionHelper.bind(tokenProvider, uri,
             abfsConfiguration.getRawConfiguration());
     }
 
+    LOG.trace("Initializing AbfsClient for {}", baseUrl);
     this.client =  new AbfsClient(baseUrl, creds, abfsConfiguration,
         new ExponentialRetryPolicy(abfsConfiguration.getMaxIoRetries()),
         tokenProvider, abfsPerfTracker);
+    LOG.trace("AbfsClient init complete");
   }
 
   private String getOctalNotation(FsPermission fsPermission) {

hadoop-tools/hadoop-azure/src/main/java/org/apache/hadoop/fs/azurebfs/services/AbfsClient.java

@@ -81,10 +81,14 @@ public AbfsClient(final URL baseUrl, final SharedKeyCredentials sharedKeyCredent
 
     if (this.baseUrl.toString().startsWith(HTTPS_SCHEME)) {
       try {
+        LOG.trace("Initializing DelegatingSSLSocketFactory with {} SSL "
+                + "Channel Mode", this.abfsConfiguration.getPreferredSSLFactoryOption());
         DelegatingSSLSocketFactory.initializeDefaultFactory(this.abfsConfiguration.getPreferredSSLFactoryOption());
         sslProviderName = DelegatingSSLSocketFactory.getDefaultFactory().getProviderName();
       } catch (IOException e) {
         // Suppress exception. Failure to init DelegatingSSLSocketFactory would have only performance impact.
+        LOG.trace("NonCritFailure: DelegatingSSLSocketFactory Init failed : "
+            + "{}", e.getMessage());
       }
     }
 

hadoop-tools/hadoop-azure/src/main/java/org/apache/hadoop/fs/azurebfs/services/AbfsRestOperation.java

@@ -145,6 +145,8 @@ void execute() throws AzureBlobFileSystemException {
       throw new AbfsRestOperationException(result.getStatusCode(), result.getStorageErrorCode(),
           result.getStorageErrorMessage(), null, result);
     }
+
+    LOG.trace("{} REST operation complete", operationType);
   }
 
   /**
@@ -210,7 +212,7 @@ private boolean executeHttpOperation(final int retryCount) throws AzureBlobFileS
       AbfsClientThrottlingIntercept.updateMetrics(operationType, httpOperation);
     }
 
-    LOG.debug("HttpRequest: " + httpOperation.toString());
+    LOG.debug("HttpRequest: {}", httpOperation.toString());
 
     if (client.getRetryPolicy().shouldRetry(retryCount, httpOperation.getStatusCode())) {
       return false;