Remove global effects of setting logHandler and logLevel

Currently, if you create a client with logHandler and/or logLevel
options, these options will affect all existing client objects. This
means that code like the following doesn’t do what you’d expect — the
log messages emitted by firstClient will say "secondClient":

```
const firstClient = new Realtime({
  logHandler: (msg) => console.log("firstClient: ", msg),
})
const secondClient = new Realtime({
  logHandler: (msg) => console.log("secondClient: ", msg),
})
```

Here we fix this as much as we can within the limitations of the
existing public API (see usage of defaultLogger). I _think_ that using
the default logging config is the right thing to do in the situations
where we have a standalone function or static method that doesn’t accept
logging configuration, but you could also argue that we should instead
maintain global effects for these usages and use the last-set logging
configuration. I don’t think it hugely matters because we actually only
end up falling back to defaultLogger in:

- the tests (that’s fine, we’ll see the console output)
- reporting failure of functions that are directly invoked by the user
  and which throw an error upon failure anyway (i.e. even if the log
  message doesn’t go where the user expected, they’ll still be informed of
  the event the message described)

I’ve kept the Logger.logAction* static methods instead of changing them
to instance methods, because that way they remain easy for our
strip-logs plugin to target.

Created #1766 for updating ably.com documentation.

Resolves #156.

grunt/esbuild/strip-logs.js

@@ -38,32 +38,32 @@ const stripLogsPlugin = {
             babel.types.isIdentifier(path.node.callee.object, { name: 'Logger' })
           ) {
             if (babel.types.isIdentifier(path.node.callee.property, { name: 'logAction' })) {
-              const firstArgument = path.node.arguments[0];
+              const secondArgument = path.node.arguments[1];
 
               if (
-                babel.types.isMemberExpression(firstArgument) &&
-                babel.types.isIdentifier(firstArgument.object, { name: 'Logger' }) &&
-                firstArgument.property.name.startsWith('LOG_')
+                babel.types.isMemberExpression(secondArgument) &&
+                babel.types.isIdentifier(secondArgument.object, { name: 'Logger' }) &&
+                secondArgument.property.name.startsWith('LOG_')
               ) {
-                if (firstArgument.property.name === 'LOG_ERROR') {
-                  // `path` is a call to `Logger.logAction(Logger.LOG_ERROR, ...)`; preserve it.
+                if (secondArgument.property.name === 'LOG_ERROR') {
+                  // `path` is a call to `Logger.logAction(arg0, Logger.LOG_ERROR, ...)`; preserve it.
                   foundErrorLog = true;
                 } else {
-                  // `path` is a call to `Logger.logAction(Logger.LOG_*, ...) for some other log level; strip it.
+                  // `path` is a call to `Logger.logAction(arg0, Logger.LOG_*, ...) for some other log level; strip it.
                   foundLogToStrip = true;
                   path.remove();
                 }
               } else {
-                // `path` is a call to `Logger.logAction(...)` with some argument other than a `Logger.LOG_*` expression; raise an error because we can’t determine whether to strip it.
+                // `path` is a call to `Logger.logAction(arg0, ...)` with some argument other than a `Logger.LOG_*` expression; raise an error because we can’t determine whether to strip it.
                 errors.push({
                   location: {
                     file: args.path,
-                    column: firstArgument.loc.start.column,
-                    line: firstArgument.loc.start.line,
-                    lineText: lines[firstArgument.loc.start.line - 1],
+                    column: secondArgument.loc.start.column,
+                    line: secondArgument.loc.start.line,
+                    lineText: lines[secondArgument.loc.start.line - 1],
                   },
-                  text: `First argument passed to Logger.logAction() must be Logger.LOG_*, got \`${
-                    babel.generator.default(firstArgument).code
+                  text: `Second argument passed to Logger.logAction() must be Logger.LOG_*, got \`${
+                    babel.generator.default(secondArgument).code
                   }\``,
                 });
               }

scripts/moduleReport.ts

@@ -6,7 +6,7 @@ import { gzip } from 'zlib';
 import Table from 'cli-table';
 
 // The maximum size we allow for a minimal useful Realtime bundle (i.e. one that can subscribe to a channel)
-const minimalUsefulRealtimeBundleSizeThresholdsKiB = { raw: 95, gzip: 29 };
+const minimalUsefulRealtimeBundleSizeThresholdsKiB = { raw: 96, gzip: 29 };
 
 const baseClientNames = ['BaseRest', 'BaseRealtime'];
 

src/common/lib/client/auth.ts

@@ -72,18 +72,18 @@ function c14n(capability?: string | Record<string, Array<string>>) {
   return JSON.stringify(c14nCapability);
 }
 
-function logAndValidateTokenAuthMethod(authOptions: AuthOptions) {
+function logAndValidateTokenAuthMethod(authOptions: AuthOptions, logger: Logger) {
   if (authOptions.authCallback) {
-    Logger.logAction(Logger.LOG_MINOR, 'Auth()', 'using token auth with authCallback');
+    Logger.logAction(logger, Logger.LOG_MINOR, 'Auth()', 'using token auth with authCallback');
   } else if (authOptions.authUrl) {
-    Logger.logAction(Logger.LOG_MINOR, 'Auth()', 'using token auth with authUrl');
+    Logger.logAction(logger, Logger.LOG_MINOR, 'Auth()', 'using token auth with authUrl');
   } else if (authOptions.key) {
-    Logger.logAction(Logger.LOG_MINOR, 'Auth()', 'using token auth with client-side signing');
+    Logger.logAction(logger, Logger.LOG_MINOR, 'Auth()', 'using token auth with client-side signing');
   } else if (authOptions.tokenDetails) {
-    Logger.logAction(Logger.LOG_MINOR, 'Auth()', 'using token auth with supplied token only');
+    Logger.logAction(logger, Logger.LOG_MINOR, 'Auth()', 'using token auth with supplied token only');
   } else {
     const msg = 'authOptions must include valid authentication parameters';
-    Logger.logAction(Logger.LOG_ERROR, 'Auth()', msg);
+    Logger.logAction(logger, Logger.LOG_ERROR, 'Auth()', msg);
     throw new Error(msg);
   }
 }
@@ -144,26 +144,31 @@ class Auth {
       /* Token auth */
       if (noWayToRenew(options)) {
         Logger.logAction(
+          this.logger,
           Logger.LOG_ERROR,
           'Auth()',
           'Warning: library initialized with a token literal without any way to renew the token when it expires (no authUrl, authCallback, or key). See https://help.ably.io/error/40171 for help',
         );
       }
       this._saveTokenOptions(options.defaultTokenParams as API.TokenDetails, options);
-      logAndValidateTokenAuthMethod(this.authOptions);
+      logAndValidateTokenAuthMethod(this.authOptions, this.logger);
     } else {
       /* Basic auth */
       if (!options.key) {
         const msg =
           'No authentication options provided; need one of: key, authUrl, or authCallback (or for testing only, token or tokenDetails)';
-        Logger.logAction(Logger.LOG_ERROR, 'Auth()', msg);
+        Logger.logAction(this.logger, Logger.LOG_ERROR, 'Auth()', msg);
         throw new ErrorInfo(msg, 40160, 401);
       }
-      Logger.logAction(Logger.LOG_MINOR, 'Auth()', 'anonymous, using basic auth');
+      Logger.logAction(this.logger, Logger.LOG_MINOR, 'Auth()', 'anonymous, using basic auth');
       this._saveBasicOptions(options);
     }
   }
 
+  get logger(): Logger {
+    return this.client.logger;
+  }
+
   /**
    * Instructs the library to get a token immediately and ensures Token Auth
    * is used for all future requests, storing the tokenParams and authOptions
@@ -303,7 +308,7 @@ class Auth {
      * not the passed in ones. */
     this._saveTokenOptions(tokenParams, authOptions);
 
-    logAndValidateTokenAuthMethod(this.authOptions);
+    logAndValidateTokenAuthMethod(this.authOptions, this.logger);
 
     try {
       return this._ensureValidAuthCredentials(true);
@@ -403,10 +408,10 @@ class Auth {
       client = this.client;
 
     if (resolvedAuthOptions.authCallback) {
-      Logger.logAction(Logger.LOG_MINOR, 'Auth.requestToken()', 'using token auth with authCallback');
+      Logger.logAction(this.logger, Logger.LOG_MINOR, 'Auth.requestToken()', 'using token auth with authCallback');
       tokenRequestCallback = resolvedAuthOptions.authCallback;
     } else if (resolvedAuthOptions.authUrl) {
-      Logger.logAction(Logger.LOG_MINOR, 'Auth.requestToken()', 'using token auth with authUrl');
+      Logger.logAction(this.logger, Logger.LOG_MINOR, 'Auth.requestToken()', 'using token auth with authUrl');
       tokenRequestCallback = (params, cb) => {
         const authHeaders = Utils.mixin(
           { accept: 'application/json, text/plain' },
@@ -429,12 +434,13 @@ class Auth {
         }
         /* RSA8c2 */
         const authParams = Utils.mixin({}, resolvedAuthOptions.authParams || {}, params) as RequestParams;
-        const authUrlRequestCallback = function (result: RequestResult) {
+        const authUrlRequestCallback = (result: RequestResult) => {
           let body = (result.body ?? null) as string | Bufferlike | API.TokenDetails | API.TokenRequest | null;
 
           let contentType: string | null = null;
           if (result.error) {
             Logger.logAction(
+              this.logger,
               Logger.LOG_MICRO,
               'Auth.requestToken().tokenRequestCallback',
               'Received Error: ' + Utils.inspectError(result.error),
@@ -448,6 +454,7 @@ class Auth {
               contentType = contentTypeHeaderOrHeaders;
             }
             Logger.logAction(
+              this.logger,
               Logger.LOG_MICRO,
               'Auth.requestToken().tokenRequestCallback',
               'Received; content-type: ' + contentType + '; body: ' + Utils.inspectBody(body),
@@ -503,6 +510,7 @@ class Auth {
           cb(null, body as Exclude<typeof body, Bufferlike>, contentType);
         };
         Logger.logAction(
+          this.logger,
           Logger.LOG_MICRO,
           'Auth.requestToken().tokenRequestCallback',
           'Requesting token from ' +
@@ -541,7 +549,12 @@ class Auth {
         }
       };
     } else if (resolvedAuthOptions.key) {
-      Logger.logAction(Logger.LOG_MINOR, 'Auth.requestToken()', 'using token auth with client-side signing');
+      Logger.logAction(
+        this.logger,
+        Logger.LOG_MINOR,
+        'Auth.requestToken()',
+        'using token auth with client-side signing',
+      );
       tokenRequestCallback = (params, cb) => {
         Utils.whenPromiseSettles(this.createTokenRequest(params, resolvedAuthOptions), (err, result) =>
           cb(err as string | ErrorInfo | null, result ?? null),
@@ -551,6 +564,7 @@ class Auth {
       const msg =
         'Need a new token, but authOptions does not include any way to request one (no authUrl, authCallback, or key)';
       Logger.logAction(
+        this.logger,
         Logger.LOG_ERROR,
         'Auth()',
         'library initialized with a token literal without any way to renew the token when it expires (no authUrl, authCallback, or key). See https://help.ably.io/error/40171 for help',
@@ -577,6 +591,7 @@ class Auth {
       const requestHeaders = Defaults.defaultPostHeaders(this.client.options);
       if (resolvedAuthOptions.requestHeaders) Utils.mixin(requestHeaders, resolvedAuthOptions.requestHeaders);
       Logger.logAction(
+        this.logger,
         Logger.LOG_MICRO,
         'Auth.requestToken().requestToken',
         'Sending POST to ' + path + '; Token params: ' + JSON.stringify(signedTokenParams),
@@ -593,19 +608,20 @@ class Auth {
     return new Promise((resolve, reject) => {
       let tokenRequestCallbackTimeoutExpired = false,
         timeoutLength = this.client.options.timeouts.realtimeRequestTimeout,
-        tokenRequestCallbackTimeout = setTimeout(function () {
+        tokenRequestCallbackTimeout = setTimeout(() => {
           tokenRequestCallbackTimeoutExpired = true;
           const msg = 'Token request callback timed out after ' + timeoutLength / 1000 + ' seconds';
-          Logger.logAction(Logger.LOG_ERROR, 'Auth.requestToken()', msg);
+          Logger.logAction(this.logger, Logger.LOG_ERROR, 'Auth.requestToken()', msg);
           reject(new ErrorInfo(msg, 40170, 401));
         }, timeoutLength);
 
-      tokenRequestCallback!(resolvedTokenParams, function (err, tokenRequestOrDetails, contentType) {
+      tokenRequestCallback!(resolvedTokenParams, (err, tokenRequestOrDetails, contentType) => {
         if (tokenRequestCallbackTimeoutExpired) return;
         clearTimeout(tokenRequestCallbackTimeout);
 
         if (err) {
           Logger.logAction(
+            this.logger,
             Logger.LOG_ERROR,
             'Auth.requestToken()',
             'token request signing call returned error; err = ' + Utils.inspectError(err),
@@ -648,7 +664,7 @@ class Auth {
           const msg =
             'Expected token request callback to call back with a token string or token request/details object, but got a ' +
             typeof tokenRequestOrDetails;
-          Logger.logAction(Logger.LOG_ERROR, 'Auth.requestToken()', msg);
+          Logger.logAction(this.logger, Logger.LOG_ERROR, 'Auth.requestToken()', msg);
           reject(new ErrorInfo(msg, 40170, 401));
           return;
         }
@@ -671,14 +687,15 @@ class Auth {
         if (!('keyName' in tokenRequestOrDetails)) {
           const msg =
             'Expected token request callback to call back with a token string, token request object, or token details object';
-          Logger.logAction(Logger.LOG_ERROR, 'Auth.requestToken()', msg);
+          Logger.logAction(this.logger, Logger.LOG_ERROR, 'Auth.requestToken()', msg);
           reject(new ErrorInfo(msg, 40170, 401));
           return;
         }
         /* it's a token request, so make the request */
-        tokenRequest(tokenRequestOrDetails, function (err, tokenResponse, unpacked) {
+        tokenRequest(tokenRequestOrDetails, (err, tokenResponse, unpacked) => {
           if (err) {
             Logger.logAction(
+              this.logger,
               Logger.LOG_ERROR,
               'Auth.requestToken()',
               'token request API call returned error; err = ' + Utils.inspectError(err),
@@ -687,7 +704,7 @@ class Auth {
             return;
           }
           if (!unpacked) tokenResponse = JSON.parse(tokenResponse as string);
-          Logger.logAction(Logger.LOG_MINOR, 'Auth.getToken()', 'token received');
+          Logger.logAction(this.logger, Logger.LOG_MINOR, 'Auth.getToken()', 'token received');
           resolve(tokenResponse as API.TokenDetails);
         });
       });
@@ -779,7 +796,7 @@ class Auth {
      * simply for testing purposes. */
     request.mac = request.mac || hmac(signText, keySecret);
 
-    Logger.logAction(Logger.LOG_MINOR, 'Auth.getTokenRequest()', 'generated signed request');
+    Logger.logAction(this.logger, Logger.LOG_MINOR, 'Auth.getTokenRequest()', 'generated signed request');
 
     return request as API.TokenRequest;
   }
@@ -897,16 +914,21 @@ class Auth {
        * automatically remove expired tokens. Else just use the cached token. If it is
        * expired Ably will tell us and we'll discard it then. */
       if (!this.isTimeOffsetSet() || !token.expires || token.expires >= this.getTimestampUsingOffset()) {
-        Logger.logAction(Logger.LOG_MINOR, 'Auth.getToken()', 'using cached token; expires = ' + token.expires);
+        Logger.logAction(
+          this.logger,
+          Logger.LOG_MINOR,
+          'Auth.getToken()',
+          'using cached token; expires = ' + token.expires,
+        );
         return token;
       }
       /* expired, so remove and fallthrough to getting a new one */
-      Logger.logAction(Logger.LOG_MINOR, 'Auth.getToken()', 'deleting expired token');
+      Logger.logAction(this.logger, Logger.LOG_MINOR, 'Auth.getToken()', 'deleting expired token');
       this.tokenDetails = null;
     }
 
     const promise = (
-      this.waitingForTokenRequest || (this.waitingForTokenRequest = Multicaster.create())
+      this.waitingForTokenRequest || (this.waitingForTokenRequest = Multicaster.create(this.logger))
     ).createPromise();
     if (this.currentTokenRequestId !== null && !forceSupersede) {
       return promise;
@@ -925,6 +947,7 @@ class Auth {
 
     if ((this.currentTokenRequestId as number) > tokenRequestId) {
       Logger.logAction(
+        this.logger,
         Logger.LOG_MINOR,
         'Auth._ensureValidAuthCredentials()',
         'Discarding token request response; overtaken by newer one',
@@ -967,7 +990,7 @@ class Auth {
        * recognise mismatch and return an error */
       const msg = 'Unexpected clientId mismatch: client has ' + this.clientId + ', requested ' + clientId;
       const err = new ErrorInfo(msg, 40102, 401);
-      Logger.logAction(Logger.LOG_ERROR, 'Auth._uncheckedSetClientId()', msg);
+      Logger.logAction(this.logger, Logger.LOG_ERROR, 'Auth._uncheckedSetClientId()', msg);
       return err;
     } else {
       /* RSA7a4: if options.clientId is provided and is not

src/common/lib/client/baseclient.ts

@@ -44,26 +44,29 @@ class BaseClient {
   // Extra HTTP request implementations available to this client, in addition to those in web’s Http.bundledRequestImplementations
   readonly _additionalHTTPRequestImplementations: HTTPRequestImplementations | null;
   private readonly __FilteredSubscriptions: typeof FilteredSubscriptions | null;
+  readonly logger: Logger;
 
   constructor(options: ClientOptions) {
     this._additionalHTTPRequestImplementations = options.plugins ?? null;
 
-    Logger.setLog(options.logLevel, options.logHandler);
+    this.logger = new Logger();
+    this.logger.setLog(options.logLevel, options.logHandler);
     Logger.logAction(
+      this.logger,
       Logger.LOG_MICRO,
       'BaseClient()',
       'initialized with clientOptions ' + Platform.Config.inspect(options),
     );
 
     this._MsgPack = options.plugins?.MsgPack ?? null;
-    const normalOptions = (this.options = Defaults.normaliseOptions(options, this._MsgPack));
+    const normalOptions = (this.options = Defaults.normaliseOptions(options, this._MsgPack, this.logger));
 
     /* process options */
     if (normalOptions.key) {
       const keyMatch = normalOptions.key.match(/^([^:\s]+):([^:.\s]+)$/);
       if (!keyMatch) {
         const msg = 'invalid key parameter';
-        Logger.logAction(Logger.LOG_ERROR, 'BaseClient()', msg);
+        Logger.logAction(this.logger, Logger.LOG_ERROR, 'BaseClient()', msg);
         throw new ErrorInfo(msg, 40400, 404);
       }
       normalOptions.keyName = keyMatch[1];
@@ -81,7 +84,7 @@ class BaseClient {
         );
     }
 
-    Logger.logAction(Logger.LOG_MINOR, 'BaseClient()', 'started; version = ' + Defaults.version);
+    Logger.logAction(this.logger, Logger.LOG_MINOR, 'BaseClient()', 'started; version = ' + Defaults.version);
 
     this._currentFallback = null;
 
@@ -150,7 +153,7 @@ class BaseClient {
   }
 
   setLog(logOptions: LoggerOptions): void {
-    Logger.setLog(logOptions.level, logOptions.handler);
+    this.logger.setLog(logOptions.level, logOptions.handler);
   }
 
   static Platform = Platform;