[Identity] ChainedTokenCredential logging fix (#14847)

Fixes to the ChainedTokenCredential logging. It now documents what credential succeeds.

Also added a test.

Fixes #6769

Author: sadasant

sdk/identity/identity/CHANGELOG.md

@@ -2,6 +2,7 @@
 
 ## 2.0.0-beta.3 (Unreleased)
 
+- Fixed issue with the logging of success messages on the `DefaultAzureCredential` and the `ChainedTokenCredential`. These messages will now mention the internal credential that succeeded.
 - The feature of persistence caching of credentials (introduced in 2.0.0-beta.1) is now supported on Node.js 15 as well.
 - `AuthenticationRequiredError` (introduced in 2.0.0-beta.1) now has the same impact on `ChainedTokenCredential` as the `CredentialUnavailableError` which is to allow the next credential in the chain to be tried.
 

sdk/identity/identity/src/credentials/chainedTokenCredential.ts

@@ -7,7 +7,10 @@ import { createSpan } from "../util/tracing";
 import { SpanStatusCode } from "@azure/core-tracing";
 import { credentialLogger, formatSuccess, formatError } from "../util/logging";
 
-const logger = credentialLogger("ChainedTokenCredential");
+/**
+ * @internal
+ */
+export const logger = credentialLogger("ChainedTokenCredential");
 
 /**
  * Enables multiple `TokenCredential` implementations to be tried in order
@@ -53,13 +56,15 @@ export class ChainedTokenCredential implements TokenCredential {
    */
   async getToken(scopes: string | string[], options?: GetTokenOptions): Promise<AccessToken> {
     let token = null;
+    let successfulCredentialName = "";
     const errors = [];
 
     const { span, updatedOptions } = createSpan("ChainedTokenCredential-getToken", options);
 
     for (let i = 0; i < this._sources.length && token === null; i++) {
       try {
         token = await this._sources[i].getToken(scopes, updatedOptions);
+        successfulCredentialName = this._sources[i].constructor.name;
       } catch (err) {
         if (
           err.name === "CredentialUnavailableError" ||
@@ -85,7 +90,7 @@ export class ChainedTokenCredential implements TokenCredential {
 
     span.end();
 
-    logger.getToken.info(formatSuccess(scopes));
+    logger.getToken.info(`Result for ${successfulCredentialName}: ${formatSuccess(scopes)}`);
 
     if (token === null) {
       throw new CredentialUnavailableError("Failed to retrieve a valid token");

sdk/identity/identity/src/util/logging.ts

@@ -109,6 +109,7 @@ export function credentialLoggerInstance(
  * It has all the properties of a CredentialLoggerInstance, plus other logger instances, one per method.
  */
 export interface CredentialLogger extends CredentialLoggerInstance {
+  parent: AzureLogger;
   getToken: CredentialLoggerInstance;
 }
 
@@ -126,6 +127,7 @@ export function credentialLogger(title: string, log: AzureLogger = logger): Cred
   const credLogger = credentialLoggerInstance(title, undefined, log);
   return {
     ...credLogger,
+    parent: log,
     getToken: credentialLoggerInstance("=> getToken()", credLogger, log)
   };
 }

sdk/identity/identity/test/internal/node/chainedTokenCredential.spec.ts

@@ -0,0 +1,71 @@
+// Copyright (c) Microsoft Corporation.
+// Licensed under the MIT license.
+
+import assert from "assert";
+import { ChainedTokenCredential, TokenCredential, AccessToken } from "../../../src";
+import Sinon from "sinon";
+import { logger as chainedTokenCredentialLogger } from "../../../src/credentials/chainedTokenCredential";
+
+class TestMockCredential implements TokenCredential {
+  constructor(public returnPromise: Promise<AccessToken | null>) {}
+
+  getToken(): Promise<AccessToken | null> {
+    return this.returnPromise;
+  }
+}
+
+describe("ChainedTokenCredential", function() {
+  it("Logs the expected successful message", async () => {
+    const chainedTokenCredential = new ChainedTokenCredential(
+      new TestMockCredential(Promise.resolve({ token: "firstToken", expiresOnTimestamp: 0 }))
+    );
+
+    const infoSpy = Sinon.spy(chainedTokenCredentialLogger.parent, "info");
+    const getTokenInfoSpy = Sinon.spy(chainedTokenCredentialLogger.getToken, "info");
+
+    const accessToken = await chainedTokenCredential.getToken("<scope>");
+    assert.notStrictEqual(accessToken, null);
+
+    assert.equal(
+      infoSpy.getCalls()[0].args.join(" "),
+      "ChainedTokenCredential => getToken() => Result for TestMockCredential: SUCCESS. Scopes: <scope>."
+    );
+    assert.equal(
+      getTokenInfoSpy.getCalls()[0].args[0],
+      "Result for TestMockCredential: SUCCESS. Scopes: <scope>."
+    );
+
+    infoSpy.restore();
+    getTokenInfoSpy.restore();
+  });
+
+  it("Doesn't throw with a clossure credential", async () => {
+    function mockCredential(returnPromise: Promise<AccessToken | null>): TokenCredential {
+      return {
+        getToken: () => returnPromise
+      };
+    }
+
+    const chainedTokenCredential = new ChainedTokenCredential(
+      mockCredential(Promise.resolve({ token: "firstToken", expiresOnTimestamp: 0 }))
+    );
+
+    const infoSpy = Sinon.spy(chainedTokenCredentialLogger.parent, "info");
+    const getTokenInfoSpy = Sinon.spy(chainedTokenCredentialLogger.getToken, "info");
+
+    const accessToken = await chainedTokenCredential.getToken("<scope>");
+    assert.notStrictEqual(accessToken, null);
+
+    assert.equal(
+      infoSpy.getCalls()[0].args.join(" "),
+      "ChainedTokenCredential => getToken() => Result for Object: SUCCESS. Scopes: <scope>."
+    );
+    assert.equal(
+      getTokenInfoSpy.getCalls()[0].args[0],
+      "Result for Object: SUCCESS. Scopes: <scope>."
+    );
+
+    infoSpy.restore();
+    getTokenInfoSpy.restore();
+  });
+});