Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

refactor: connection logger #820

Merged
merged 3 commits into from Nov 25, 2021
Merged

refactor: connection logger #820

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
28e9656
refactor: connection logger
mahboubii Nov 25, 2021
1318e7c
Merge branch 'master' into cleanup-connection-log
Nov 25, 2021
63597ef
Merge branch 'master' into cleanup-connection-log
Nov 25, 2021
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
150 changes: 34 additions & 116 deletions src/connection.ts
View file
Open in desktop
Expand Up @@ -11,6 +11,7 @@ import {
Logger,
UR,
UserResponse,
LogLevel,
} from './types';

// Type guards to check WebSocket error type
Expand Down Expand Up @@ -156,6 +157,10 @@ export class StableWSConnection<
this.insightMetrics = insightMetrics;
}

_log(msg: string, extra: UR = {}, level: LogLevel = 'info') {
this.logger(level, 'connection:' + msg, { tags: ['connection'], ...extra });
}

/**
* connect - Connect to the WS URL
*
Expand All @@ -170,21 +175,13 @@ export class StableWSConnection<
const healthCheck = await this._connect();
this.consecutiveFailures = 0;

this.logger('info', `connection:connect() - Established ws connection with healthcheck: ${healthCheck}`, {
tags: ['connection'],
});
this._log(`connect() - Established ws connection with healthcheck: ${healthCheck}`);
} catch (error) {
this.isHealthy = false;
this.consecutiveFailures += 1;

if (error.code === chatCodes.TOKEN_EXPIRED && !this.tokenManager.isStatic()) {
this.logger(
'info',
'connection:connect() - WS failure due to expired token, so going to try to reload token and reconnect',
{
tags: ['connection'],
},
);
this._log('connect() - WS failure due to expired token, so going to try to reload token and reconnect');
this._reconnect({ refreshToken: true });
} else if (!error.isWSFailure) {
// API rejected the connection and we should not retry
Expand Down Expand Up @@ -267,9 +264,7 @@ export class StableWSConnection<
*
*/
disconnect(timeout?: number) {
this.logger('info', `connection:disconnect() - Closing the websocket connection for wsID ${this.wsID}`, {
tags: ['connection'],
});
this._log(`disconnect() - Closing the websocket connection for wsID ${this.wsID}`);

this.wsID += 1;

Expand Down Expand Up @@ -298,14 +293,7 @@ export class StableWSConnection<
if (ws && ws.close && ws.readyState === ws.OPEN) {
isClosedPromise = new Promise((resolve) => {
const onclose = (event: WebSocket.CloseEvent) => {
this.logger(
'info',
`connection:disconnect() - resolving isClosedPromise ${event ? 'with' : 'without'} close frame`,
{
tags: ['connection'],
event,
},
);
this._log(`disconnect() - resolving isClosedPromise ${event ? 'with' : 'without'} close frame`, { event });
resolve();
};

Expand All @@ -315,15 +303,11 @@ export class StableWSConnection<
setTimeout(onclose, timeout != null ? timeout : 1000);
});

this.logger('info', `connection:disconnect() - Manually closed connection by calling client.disconnect()`, {
tags: ['connection'],
});
this._log(`disconnect() - Manually closed connection by calling client.disconnect()`);

ws.close(chatCodes.WS_CLOSED_SUCCESS, 'Manually closed connection by calling client.disconnect()');
} else {
this.logger('info', `connection:disconnect() - ws connection doesn't exist or it is already closed.`, {
tags: ['connection'],
});
this._log(`disconnect() - ws connection doesn't exist or it is already closed.`);
isClosedPromise = Promise.resolve();
}

Expand Down Expand Up @@ -388,14 +372,10 @@ export class StableWSConnection<
* - `refreshToken` {boolean} reload/refresh user token be refreshed before attempting reconnection.
*/
async _reconnect(options: { interval?: number; refreshToken?: boolean } = {}): Promise<void> {
this.logger('info', 'connection:_reconnect() - Initiating the reconnect', {
tags: ['connection'],
});
this._log('_reconnect() - Initiating the reconnect');
// only allow 1 connection at the time
if (this.isConnecting || this.isHealthy) {
this.logger('info', 'connection:_reconnect() - Abort (1) since already connecting or healthy', {
tags: ['connection'],
});
this._log('_reconnect() - Abort (1) since already connecting or healthy');
return;
}

Expand All @@ -411,17 +391,13 @@ export class StableWSConnection<
// Check once again if by some other call to _reconnect is active or connection is
// already restored, then no need to proceed.
if (this.isConnecting || this.isHealthy) {
this.logger('info', 'connection:_reconnect() - Abort (2) since already connecting or healthy', {
tags: ['connection'],
});
this._log('_reconnect() - Abort (2) since already connecting or healthy');
return;
}

// cleanup the old connection
this.logger('info', 'connection:_reconnect() - Destroying current WS connection', {
tags: ['connection'],
});
this._log('_reconnect() - Destroying current WS connection');

// cleanup the old connection
this._destroyCurrentWSConnection();

if (options.refreshToken) {
Expand All @@ -431,42 +407,28 @@ export class StableWSConnection<
try {
const open = await this._connect();
if (this.recoverCallback) {
this.logger('info', 'connection:_reconnect() - Waiting for recoverCallBack', {
tags: ['connection'],
});
this._log('_reconnect() - Waiting for recoverCallBack');
await this.recoverCallback(open);
this.logger('info', 'connection:_reconnect() - Finished recoverCallBack', {
tags: ['connection'],
});
this._log('_reconnect() - Finished recoverCallBack');
}
this.consecutiveFailures = 0;
} catch (error) {
this.isHealthy = false;
this.consecutiveFailures += 1;
if (error.code === chatCodes.TOKEN_EXPIRED && !this.tokenManager.isStatic()) {
this.logger(
'info',
'connection:_reconnect() - WS failure due to expired token, so going to try to reload token and reconnect',
{
tags: ['connection'],
},
);
this._log('_reconnect() - WS failure due to expired token, so going to try to reload token and reconnect');

return this._reconnect({ refreshToken: true });
}

// reconnect on WS failures, don't reconnect if there is a code bug
if (error.isWSFailure) {
this.logger('info', 'connection:_reconnect() - WS failure, so going to try to reconnect', {
tags: ['connection'],
});
this._log('_reconnect() - WS failure, so going to try to reconnect');

this._reconnect();
}
}
this.logger('info', 'connection:_reconnect() - == END ==', {
tags: ['connection'],
});
this._log('_reconnect() - == END ==');
}

/**
Expand All @@ -478,22 +440,14 @@ export class StableWSConnection<
onlineStatusChanged = (event: Event) => {
if (event.type === 'offline') {
// mark the connection as down
this.logger('info', 'connection:onlineStatusChanged() - Status changing to offline', {
tags: ['connection'],
});
this._log('onlineStatusChanged() - Status changing to offline');
this._setHealth(false);
} else if (event.type === 'online') {
// retry right now...
// We check this.isHealthy, not sure if it's always
// smart to create a new WS connection if the old one is still up and running.
// it's possible we didn't miss any messages, so this process is just expensive and not needed.
this.logger(
'info',
`connection:onlineStatusChanged() - Status changing to online. isHealthy: ${this.isHealthy}`,
{
tags: ['connection'],
},
);
this._log(`onlineStatusChanged() - Status changing to online. isHealthy: ${this.isHealthy}`);
if (!this.isHealthy) {
this._reconnect({ interval: 10 });
}
Expand All @@ -503,10 +457,7 @@ export class StableWSConnection<
onopen = (wsID: number) => {
if (this.wsID !== wsID) return;

this.logger('info', 'connection:onopen() - onopen callback', {
tags: ['connection'],
wsID,
});
this._log('onopen() - onopen callback', { wsID });
};

onmessage = (wsID: number, event: WebSocket.MessageEvent) => {
Expand All @@ -530,11 +481,7 @@ export class StableWSConnection<

// trigger the event..
this.lastEvent = new Date();
this.logger('info', 'connection:onmessage() - onmessage callback', {
tags: ['connection'],
event,
wsID,
});
this._log('onmessage() - onmessage callback', { event, wsID });

if (data && data.type === 'health.check') {
this.scheduleNextPing();
Expand All @@ -547,11 +494,7 @@ export class StableWSConnection<
onclose = (wsID: number, event: WebSocket.CloseEvent) => {
if (this.wsID !== wsID) return;

this.logger('info', 'connection:onclose() - onclose callback - ' + event.code, {
tags: ['connection'],
event,
wsID,
});
this._log('onclose() - onclose callback - ' + event.code, { event, wsID });

if (event.code === chatCodes.WS_CLOSED_SUCCESS) {
// this is a permanent error raised by stream..
Expand All @@ -564,10 +507,7 @@ export class StableWSConnection<
error.target = event.target;

this.rejectPromise?.(error);
this.logger('info', `connection:onclose() - WS connection reject with error ${event.reason}`, {
tags: ['connection'],
event,
});
this._log(`onclose() - WS connection reject with error ${event.reason}`, { event });
} else {
this.consecutiveFailures += 1;
this.totalFailures += 1;
Expand All @@ -576,10 +516,7 @@ export class StableWSConnection<

this.rejectPromise?.(this._errorFromWSEvent(event));

this.logger('info', `connection:onclose() - WS connection closed. Calling reconnect ...`, {
tags: ['connection'],
event,
});
this._log(`onclose() - WS connection closed. Calling reconnect ...`, { event });

// reconnect if its an abnormal failure
this._reconnect();
Expand All @@ -595,10 +532,7 @@ export class StableWSConnection<
this.isConnecting = false;

this.rejectPromise?.(this._errorFromWSEvent(event));
this.logger('info', `connection:onerror() - WS connection resulted into error`, {
tags: ['connection'],
event,
});
this._log(`onerror() - WS connection resulted into error`, { event });

this._reconnect();
};
Expand All @@ -614,21 +548,15 @@ export class StableWSConnection<
if (healthy && !this.isHealthy) {
// yes we are online:
this.isHealthy = true;
this.eventCallback({
type: 'connection.changed',
online: true,
});
this.eventCallback({ type: 'connection.changed', online: true });
}

if (!healthy && this.isHealthy) {
// bummer we are offline
this.isHealthy = false;
setTimeout(() => {
if (!this.isHealthy) {
this.eventCallback({
type: 'connection.changed',
online: false,
});
this.eventCallback({ type: 'connection.changed', online: false });
}
}, 5000);
}
Expand All @@ -655,10 +583,7 @@ export class StableWSConnection<
}

// Keeping this `warn` level log, to avoid cluttering of error logs from ws failures.
this.logger('warn', `connection:_errorFromWSEvent() - WS failed with code ${code}`, {
tags: ['connection'],
event,
});
this._log(`_errorFromWSEvent() - WS failed with code ${code}`, { event }, 'warn');

const error = new Error(`WS failed with code ${code} and reason - ${message}`) as Error & {
code?: string | number;
Expand Down Expand Up @@ -759,12 +684,7 @@ export class StableWSConnection<
// 30 seconds is the recommended interval (messenger uses this)
this.healthCheckTimeoutRef = setTimeout(() => {
// send the healthcheck.., server replies with a health check event
const data = [
{
type: 'health.check',
client_id: this.clientID,
},
];
const data = [{ type: 'health.check', client_id: this.clientID }];
// try to send on the connection
try {
this.ws?.send(JSON.stringify(data));
Expand All @@ -787,9 +707,7 @@ export class StableWSConnection<
this.connectionCheckTimeoutRef = setTimeout(() => {
const now = new Date();
if (this.lastEvent && now.getTime() - this.lastEvent.getTime() > this.connectionCheckTimeout) {
this.logger('info', 'connection:scheduleConnectionCheck - going to reconnect', {
tags: ['connection'],
});
this._log('scheduleConnectionCheck - going to reconnect');
this._setHealth(false);
this._reconnect();
}
Expand Down
8 changes: 3 additions & 5 deletions src/types.ts
View file
Open in desktop
Expand Up @@ -1648,11 +1648,9 @@ export type HuaweiConfig = {

export type LiteralStringForUnion = string & {};

export type Logger = (
logLevel: 'info' | 'error' | 'warn',
message: string,
extraData?: Record<string, unknown>,
) => void;
export type LogLevel = 'info' | 'error' | 'warn';

export type Logger = (logLevel: LogLevel, message: string, extraData?: Record<string, unknown>) => void;

export type Message<AttachmentType = UR, MessageType = UR, UserType = UR> = Partial<
MessageBase<AttachmentType, MessageType, UserType>
Expand Down