Skip to content

Commit

Permalink
Reduce global effects of setting logHandler and logLevel
Browse files Browse the repository at this point in the history 
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.

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.

Resolves #1763.
  • Loading branch information
@lawrence-forooghian
lawrence-forooghian committed May 16, 2024
1 parent eab98b9 commit c6f957a
Show file tree
Hide file tree
Showing 38 changed files with 601 additions and 258 deletions.
26 changes: 13 additions & 13 deletions grunt/esbuild/strip-logs.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
}\``,
});
}
Expand Down
2 changes: 1 addition & 1 deletion scripts/moduleReport.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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'];

Expand Down
75 changes: 49 additions & 26 deletions src/common/lib/client/auth.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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);
}
}
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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);
Expand Down Expand Up @@ -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' },
Expand All @@ -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),
Expand All @@ -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),
Expand Down Expand Up @@ -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 ' +
Expand Down Expand Up @@ -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),
Expand All @@ -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',
Expand All @@ -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),
Expand All @@ -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),
Expand Down Expand Up @@ -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;
}
Expand All @@ -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),
Expand All @@ -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);
});
});
Expand Down Expand Up @@ -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;
}
Expand Down Expand Up @@ -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;
Expand All @@ -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',
Expand Down Expand Up @@ -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
Expand Down
13 changes: 8 additions & 5 deletions src/common/lib/client/baseclient.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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];
Expand All @@ -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;

Expand Down Expand Up @@ -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;
Expand Down
Loading

0 comments on commit c6f957a

Please sign in to comment.