From 66056cd8b971d07f46b27e406158caff4d3519a9 Mon Sep 17 00:00:00 2001 From: charliesantos Date: Fri, 17 Nov 2023 10:01:16 -0800 Subject: [PATCH 1/3] VBLOCKS-1850 Add and improve debug logs --- lib/twilio/audiohelper.ts | 44 ++++++----- lib/twilio/audioprocessoreventobserver.ts | 6 +- lib/twilio/call.ts | 41 +++++++++-- lib/twilio/device.ts | 90 ++++++++++++++++++++--- lib/twilio/eventpublisher.ts | 18 ++++- lib/twilio/log.ts | 61 +++++++-------- lib/twilio/outputdevicecollection.ts | 8 ++ lib/twilio/preflight/preflight.ts | 42 +++++++++++ lib/twilio/pstream.ts | 2 +- lib/twilio/rtc/peerconnection.ts | 16 ++-- lib/twilio/rtc/rtcpc.ts | 2 +- lib/twilio/wstransport.ts | 10 +-- 12 files changed, 255 insertions(+), 85 deletions(-) diff --git a/lib/twilio/audiohelper.ts b/lib/twilio/audiohelper.ts index d71ff9ed..7ba78320 100644 --- a/lib/twilio/audiohelper.ts +++ b/lib/twilio/audiohelper.ts @@ -146,7 +146,7 @@ class AudioHelper extends EventEmitter { /** * An instance of Logger to use. */ - private _log: Log = Log.getInstance(); + private _log: Log = new Log('AudioHelper'); /** * The MediaDevices instance to use. @@ -336,10 +336,10 @@ class AudioHelper extends EventEmitter { * @private */ _openDefaultDeviceWithConstraints(constraints: MediaStreamConstraints): Promise { - this._log.debug('Opening default device with constraints', constraints); + this._log.info('Opening default device with constraints', constraints); return this._getUserMedia(constraints).then((stream: MediaStream) => { - this._log.debug('Opened default device. Updating available devices.'); + this._log.info('Opened default device. Updating available devices.'); // Ensures deviceId's and labels are populated after the gUM call // by calling enumerateDevices this._updateAvailableDevices().catch(error => { @@ -357,7 +357,7 @@ class AudioHelper extends EventEmitter { */ _stopDefaultInputDeviceStream(): void { if (this._defaultInputDeviceStream) { - this._log.debug('stopping default device stream'); + this._log.info('stopping default device stream'); this._defaultInputDeviceStream.getTracks().forEach(track => track.stop()); this._defaultInputDeviceStream = null; this._destroyProcessedStream(); @@ -434,6 +434,8 @@ class AudioHelper extends EventEmitter { * @returns */ addProcessor(processor: AudioProcessor): Promise { + this._log.debug('.addProcessor'); + if (this._processor) { throw new NotSupportedError('Adding multiple AudioProcessors is not supported at this time.'); } @@ -450,7 +452,6 @@ class AudioHelper extends EventEmitter { throw new InvalidArgumentError('Missing destroyProcessedStream() method.'); } - this._log.debug('Adding processor'); this._processor = processor; this._audioProcessorEventObserver.emit('add'); return this._restartStreams(); @@ -463,6 +464,7 @@ class AudioHelper extends EventEmitter { * @returns The enable-status of the sound. */ disconnect(doEnable?: boolean): boolean { + this._log.debug('.disconnect', doEnable); return this._maybeEnableSound(Device.SoundName.Disconnect, doEnable); } @@ -473,6 +475,7 @@ class AudioHelper extends EventEmitter { * @returns The enable-status of the sound. */ incoming(doEnable?: boolean): boolean { + this._log.debug('.incoming', doEnable); return this._maybeEnableSound(Device.SoundName.Incoming, doEnable); } @@ -483,6 +486,7 @@ class AudioHelper extends EventEmitter { * @returns The enable-status of the sound. */ outgoing(doEnable?: boolean): boolean { + this._log.debug('.outgoing', doEnable); return this._maybeEnableSound(Device.SoundName.Outgoing, doEnable); } @@ -494,6 +498,8 @@ class AudioHelper extends EventEmitter { * @returns */ removeProcessor(processor: AudioProcessor): Promise { + this._log.debug('.removeProcessor'); + if (typeof processor !== 'object' || processor === null) { throw new InvalidArgumentError('Missing AudioProcessor argument.'); } @@ -516,6 +522,7 @@ class AudioHelper extends EventEmitter { * @param audioConstraints - The MediaTrackConstraints to apply. */ setAudioConstraints(audioConstraints: MediaTrackConstraints): Promise { + this._log.debug('.setAudioConstraints', audioConstraints); this._audioConstraints = Object.assign({ }, audioConstraints); delete this._audioConstraints.deviceId; @@ -530,6 +537,7 @@ class AudioHelper extends EventEmitter { * input device with. */ setInputDevice(deviceId: string): Promise { + this._log.debug('.setInputDevice', deviceId); return this._setInputDevice(deviceId, false); } @@ -539,6 +547,7 @@ class AudioHelper extends EventEmitter { * or immediately if no input device is set. */ unsetAudioConstraints(): Promise { + this._log.debug('.unsetAudioConstraints'); this._audioConstraints = null; return this.inputDevice ? this._setInputDevice(this.inputDevice.deviceId, true) @@ -550,6 +559,7 @@ class AudioHelper extends EventEmitter { * will not allow removal of the input device during a live call. */ unsetInputDevice(): Promise { + this._log.debug('.unsetInputDevice', this.inputDevice); if (!this.inputDevice) { return Promise.resolve(); } this._destroyProcessedStream(); @@ -566,7 +576,7 @@ class AudioHelper extends EventEmitter { */ private _destroyProcessedStream() { if (this._processor && this._processedStream) { - this._log.debug('destroying processed stream'); + this._log.info('destroying processed stream'); const processedStream = this._processedStream; this._processedStream.getTracks().forEach(track => track.stop()); this._processedStream = null; @@ -622,7 +632,7 @@ class AudioHelper extends EventEmitter { */ private _maybeCreateProcessedStream(stream: MediaStream): Promise { if (this._processor) { - this._log.debug('Creating processed stream'); + this._log.info('Creating processed stream'); return this._processor.createProcessedStream(stream).then((processedStream: MediaStream) => { this._processedStream = processedStream; this._audioProcessorEventObserver.emit('create'); @@ -686,9 +696,9 @@ class AudioHelper extends EventEmitter { * @param stream - The new stream */ private _replaceStream(stream: MediaStream | null): void { - this._log.debug('Replacing with new stream.'); + this._log.info('Replacing with new stream.'); if (this._selectedInputDeviceStream) { - this._log.debug('Old stream detected. Stopping tracks.'); + this._log.info('Old stream detected. Stopping tracks.'); this._stopSelectedInputDeviceStream(); } @@ -700,7 +710,7 @@ class AudioHelper extends EventEmitter { */ private _restartStreams(): Promise { if (this.inputDevice && this._selectedInputDeviceStream) { - this._log.debug('Restarting selected input device'); + this._log.info('Restarting selected input device'); return this._setInputDevice(this.inputDevice.deviceId, true); } @@ -708,7 +718,7 @@ class AudioHelper extends EventEmitter { const defaultDevice = this.availableInputDevices.get('default') || Array.from(this.availableInputDevices.values())[0]; - this._log.debug('Restarting default input device, now becoming selected.'); + this._log.info('Restarting default input device, now becoming selected.'); return this._setInputDevice(defaultDevice.deviceId, true); } @@ -732,7 +742,7 @@ class AudioHelper extends EventEmitter { return Promise.reject(new InvalidArgumentError(`Device not found: ${deviceId}`)); } - this._log.debug('Setting input device. ID: ' + deviceId); + this._log.info('Setting input device. ID: ' + deviceId); if (this._inputDevice && this._inputDevice.deviceId === deviceId && this._selectedInputDeviceStream) { if (!forceGetUserMedia) { @@ -741,7 +751,7 @@ class AudioHelper extends EventEmitter { // If the currently active track is still in readyState `live`, gUM may return the same track // rather than returning a fresh track. - this._log.debug('Same track detected on setInputDevice, stopping old tracks.'); + this._log.info('Same track detected on setInputDevice, stopping old tracks.'); this._stopSelectedInputDeviceStream(); } @@ -749,13 +759,13 @@ class AudioHelper extends EventEmitter { this._stopDefaultInputDeviceStream(); const constraints = { audio: Object.assign({ deviceId: { exact: deviceId } }, this.audioConstraints) }; - this._log.debug('setInputDevice: getting new tracks.'); + this._log.info('setInputDevice: getting new tracks.'); return this._getUserMedia(constraints).then((originalStream: MediaStream) => { this._destroyProcessedStream(); return this._maybeCreateProcessedStream(originalStream).then((newStream) => { - this._log.debug('setInputDevice: invoking _onActiveInputChanged.'); + this._log.info('setInputDevice: invoking _onActiveInputChanged.'); return this._onActiveInputChanged(newStream).then(() => { this._replaceStream(originalStream); this._inputDevice = device; @@ -770,7 +780,7 @@ class AudioHelper extends EventEmitter { */ private _stopSelectedInputDeviceStream(): void { if (this._selectedInputDeviceStream) { - this._log.debug('Stopping selected device stream'); + this._log.info('Stopping selected device stream'); this._selectedInputDeviceStream.getTracks().forEach(track => track.stop()); } } @@ -822,7 +832,7 @@ class AudioHelper extends EventEmitter { tracks of the active device (default) have not gone stale.`); this._setInputDevice(this.inputDevice.deviceId, true); } - + this._log.debug('#deviceChange', lostActiveDevices); this.emit('deviceChange', lostActiveDevices); } } diff --git a/lib/twilio/audioprocessoreventobserver.ts b/lib/twilio/audioprocessoreventobserver.ts index ee57a5a4..196502dc 100644 --- a/lib/twilio/audioprocessoreventobserver.ts +++ b/lib/twilio/audioprocessoreventobserver.ts @@ -14,11 +14,11 @@ import Log from './log'; */ export class AudioProcessorEventObserver extends EventEmitter { - private _log: Log = Log.getInstance(); + private _log: Log = new Log('AudioProcessorEventObserver'); constructor() { super(); - this._log.debug('Creating AudioProcessorEventObserver instance'); + this._log.info('Creating AudioProcessorEventObserver instance'); this.on('add', () => this._reEmitEvent('add')); this.on('remove', () => this._reEmitEvent('remove')); this.on('create', () => this._reEmitEvent('create-processed-stream')); @@ -30,7 +30,7 @@ export class AudioProcessorEventObserver extends EventEmitter { } private _reEmitEvent(name: string): void { - this._log.debug(`AudioProcessor:${name}`); + this._log.info(`AudioProcessor:${name}`); this.emit('event', { name, group: 'audio-processor' }); } } diff --git a/lib/twilio/call.ts b/lib/twilio/call.ts index 570453f3..be28e0d8 100644 --- a/lib/twilio/call.ts +++ b/lib/twilio/call.ts @@ -198,7 +198,7 @@ class Call extends EventEmitter { /** * An instance of Logger to use. */ - private _log: Log = Log.getInstance(); + private _log: Log = new Log('Call'); /** * The MediaHandler (Twilio PeerConnection) this {@link Call} is using for @@ -399,7 +399,7 @@ class Call extends EventEmitter { }); this._mediaHandler.onaudio = (remoteAudio: typeof Audio) => { - this._log.info('Remote audio created'); + this._log.debug('#audio'); this.emit('audio', remoteAudio); }; @@ -463,10 +463,11 @@ class Call extends EventEmitter { }; this._mediaHandler.ondisconnected = (msg: string): void => { - this._log.info(msg); + this._log.warn(msg); this._publisher.warn('network-quality-warning-raised', 'ice-connectivity-lost', { message: msg, }, this); + this._log.debug('#warning', 'ice-connectivity-lost'); this.emit('warning', 'ice-connectivity-lost'); this._onMediaFailure(Call.MediaFailure.ConnectionDisconnected); @@ -488,6 +489,7 @@ class Call extends EventEmitter { this._publisher.info('network-quality-warning-cleared', 'ice-connectivity-lost', { message: msg, }, this); + this._log.debug('#warning-cleared', 'ice-connectivity-lost'); this.emit('warning-cleared', 'ice-connectivity-lost'); this._onMediaReconnected(); }; @@ -499,6 +501,7 @@ class Call extends EventEmitter { const error = e.info.twilioError || new GeneralErrors.UnknownError(e.info.message); this._log.error('Received an error from MediaStream:', e); + this._log.debug('#error', error); this.emit('error', error); }; @@ -539,6 +542,7 @@ class Call extends EventEmitter { if (!this._isCancelled && !this._isRejected) { // tslint:disable no-console + this._log.debug('#disconnect'); this.emit('disconnect', this); } }; @@ -593,6 +597,7 @@ class Call extends EventEmitter { if (this._status !== Call.State.Pending) { return; } + this._log.debug('.accept', options); options = options || { }; const rtcConfiguration = options.rtcConfiguration || this._options.rtcConfiguration; @@ -696,6 +701,7 @@ class Call extends EventEmitter { } this._disconnect(); + this._log.debug('#error', error); this.emit('error', twilioError); }); } @@ -704,6 +710,7 @@ class Call extends EventEmitter { * Disconnect from the {@link Call}. */ disconnect(): void { + this._log.debug('.disconnect'); this._disconnect(); } @@ -728,6 +735,7 @@ class Call extends EventEmitter { if (this._status !== Call.State.Pending) { return; } + this._log.debug('.ignore'); this._status = Call.State.Closed; this._mediaHandler.ignore(this.parameters.CallSid); @@ -750,12 +758,14 @@ class Call extends EventEmitter { * @param shouldMute - Whether the incoming audio should be muted. Defaults to true. */ mute(shouldMute: boolean = true): void { + this._log.debug('.mute', shouldMute); const wasMuted = this._mediaHandler.isMuted; this._mediaHandler.mute(shouldMute); const isMuted = this._mediaHandler.isMuted; if (wasMuted !== isMuted) { this._publisher.info('connection', isMuted ? 'muted' : 'unmuted', null, this); + this._log.debug('#mute', isMuted); this.emit('mute', isMuted, this); } } @@ -797,6 +807,7 @@ class Call extends EventEmitter { if (this._status !== Call.State.Pending) { return; } + this._log.debug('.reject'); this._isRejected = true; this._pstream.reject(this.parameters.CallSid); @@ -805,6 +816,7 @@ class Call extends EventEmitter { this._cleanupEventListeners(); this._mediaHandler.close(); this._status = Call.State.Closed; + this._log.debug('#reject'); this.emit('reject'); } @@ -813,6 +825,7 @@ class Call extends EventEmitter { * @param digits */ sendDigits(digits: string): void { + this._log.debug('.sendDigits', digits); if (digits.match(/[^0-9*#w]/)) { throw new InvalidArgumentError('Illegal character passed into sendDigits'); } @@ -874,6 +887,7 @@ class Call extends EventEmitter { this._pstream.dtmf(this.parameters.CallSid, digits); } else { const error = new GeneralErrors.ConnectionError('Could not send DTMF: Signaling channel is disconnected'); + this._log.debug('#error', error); this.emit('error', error); } } @@ -886,6 +900,7 @@ class Call extends EventEmitter { * @returns A voice event sid that uniquely identifies the message that was sent. */ sendMessage(message: Call.Message): string { + this._log.debug('.sendMessage', JSON.stringify(message)); const { content, contentType, messageType } = message; if (typeof content === 'undefined' || content === null) { @@ -1087,6 +1102,7 @@ class Call extends EventEmitter { if (warningName !== 'constant-audio-output-level') { const emitName = wasCleared ? 'warning-cleared' : 'warning'; + this._log.debug(`#${emitName}`, warningName); this.emit(emitName, warningName, warningData && !wasCleared ? warningData : null); } } @@ -1103,6 +1119,7 @@ class Call extends EventEmitter { this._status = Call.State.Open; if (!this._wasConnected) { this._wasConnected = true; + this._log.debug('#accept'); this.emit('accept', this); } } @@ -1160,6 +1177,7 @@ class Call extends EventEmitter { this._mediaHandler.close(); this._status = Call.State.Closed; + this._log.debug('#cancel'); this.emit('cancel'); this._pstream.removeListener('cancel', this._onCancel); } @@ -1217,6 +1235,7 @@ class Call extends EventEmitter { 'Error sent from gateway in HANGUP', ); this._log.error('Received an error from the gateway:', error); + this._log.debug('#error', error); this.emit('error', error); } this._shouldSendHangup = false; @@ -1253,7 +1272,7 @@ class Call extends EventEmitter { // We already exceeded max retry time. if (Date.now() - this._mediaReconnectStartTime > BACKOFF_CONFIG.max) { - this._log.info('Exceeded max ICE retries'); + this._log.warn('Exceeded max ICE retries'); return this._mediaHandler.onerror(MEDIA_DISCONNECT_ERROR); } @@ -1294,6 +1313,7 @@ class Call extends EventEmitter { this._mediaReconnectBackoff.reset(); this._mediaReconnectBackoff.backoff(); + this._log.debug('#reconnecting'); this.emit('reconnecting', mediaReconnectionError); } } @@ -1312,6 +1332,7 @@ class Call extends EventEmitter { if (this._signalingStatus === Call.State.Open) { this._publisher.info('connection', 'reconnected', null, this); + this._log.debug('#reconnected'); this.emit('reconnected'); this._status = Call.State.Open; } @@ -1329,13 +1350,14 @@ class Call extends EventEmitter { this._log.warn(`Received a message from a different callsid: ${callsid}`); return; } - - this.emit('messageReceived', { + const data = { content, contentType: contenttype, messageType: messagetype, voiceEventSid: voiceeventsid, - }); + }; + this._log.debug('#messageReceived', JSON.stringify(data)); + this.emit('messageReceived', data); } /** @@ -1350,6 +1372,7 @@ class Call extends EventEmitter { } const message = this._messages.get(voiceEventSid); this._messages.delete(voiceEventSid); + this._log.debug('#messageSent', JSON.stringify(message)); this.emit('messageSent', message); } @@ -1368,6 +1391,7 @@ class Call extends EventEmitter { const hasEarlyMedia = !!payload.sdp; this._status = Call.State.Ringing; this._publisher.info('connection', 'outgoing-ringing', { hasEarlyMedia }, this); + this._log.debug('#ringing'); this.emit('ringing', hasEarlyMedia); } @@ -1422,6 +1446,7 @@ class Call extends EventEmitter { if (this._mediaStatus === Call.State.Open) { this._publisher.info('connection', 'reconnected', null, this); + this._log.debug('#reconnected'); this.emit('reconnected'); this._status = Call.State.Open; } @@ -1433,10 +1458,12 @@ class Call extends EventEmitter { */ private _onTransportClose = (): void => { this._log.error('Received transportClose from pstream'); + this._log.debug('#transportClose'); this.emit('transportClose'); if (this._signalingReconnectToken) { this._status = Call.State.Reconnecting; this._signalingStatus = Call.State.Reconnecting; + this._log.debug('#reconnecting'); this.emit('reconnecting', new SignalingErrors.ConnectionDisconnected()); } else { this._status = Call.State.Closed; diff --git a/lib/twilio/device.ts b/lib/twilio/device.ts index 8a99f226..1141d860 100644 --- a/lib/twilio/device.ts +++ b/lib/twilio/device.ts @@ -377,7 +377,7 @@ class Device extends EventEmitter { /** * An instance of Logger to use. */ - private _log: Log = Log.getInstance(); + private _log: Log = new Log('Device'); /** * Network related information @@ -467,6 +467,10 @@ class Device extends EventEmitter { constructor(token: string, options: Device.Options = { }) { super(); + // Setup loglevel asap to avoid missed logs + this._setupLoglevel(options.logLevel); + this._logOptions('constructor', options); + this.updateToken(token); if (isLegacyEdge()) { @@ -554,6 +558,7 @@ class Device extends EventEmitter { * @param options */ async connect(options: Device.ConnectOptions = { }): Promise { + this._log.debug('.connect', JSON.stringify(options && options.params || {}), options); this._throwIfDestroyed(); if (this._activeCall) { @@ -592,6 +597,7 @@ class Device extends EventEmitter { * Destroy the {@link Device}, freeing references to be garbage collected. */ destroy(): void { + this._log.debug('.destroy'); this.disconnectAll(); this._stopRegistrationTimer(); @@ -618,6 +624,7 @@ class Device extends EventEmitter { * Disconnect all {@link Call}s. */ disconnectAll(): void { + this._log.debug('.disconnectAll'); const calls = this._calls.splice(0); calls.forEach((call: Call) => call.disconnect()); @@ -661,6 +668,7 @@ class Device extends EventEmitter { * Register the `Device` to the Twilio backend, allowing it to receive calls. */ async register(): Promise { + this._log.debug('.register'); if (this.state !== Device.State.Unregistered) { throw new InvalidStateError( `Attempt to register when device is in state "${this.state}". ` + @@ -705,6 +713,7 @@ class Device extends EventEmitter { * calls. */ async unregister(): Promise { + this._log.debug('.unregister'); if (this.state !== Device.State.Registered) { throw new InvalidStateError( `Attempt to unregister when device is in state "${this.state}". ` + @@ -727,6 +736,7 @@ class Device extends EventEmitter { * @param options */ updateOptions(options: Device.Options = { }): void { + this._logOptions('updateOptions', options); if (this.state === Device.State.Destroyed) { throw new InvalidStateError( `Attempt to "updateOptions" when device is in state "${this.state}".`, @@ -761,11 +771,7 @@ class Device extends EventEmitter { throw new InvalidStateError('Cannot change Edge while on an active Call'); } - this._log.setDefaultLevel( - typeof this._options.logLevel === 'number' - ? this._options.logLevel - : LogLevels.ERROR, - ); + this._setupLoglevel(this._options.logLevel); if (this._options.dscp) { if (!this._options.rtcConstraints) { @@ -815,6 +821,7 @@ class Device extends EventEmitter { * @param token */ updateToken(token: string) { + this._log.debug('.updateToken'); if (this.state === Device.State.Destroyed) { throw new InvalidStateError( `Attempt to "updateToken" when device is in state "${this.state}".`, @@ -934,6 +941,50 @@ class Device extends EventEmitter { || call.outboundConnectionId === callSid) || null; } + /** + * Utility function to log device options + */ + private _logOptions(caller: string, options: Device.Options = { }): void { + // Selectively log options that users can modify. + // Also, convert user overrides. + // This prevents potential app crash when calling JSON.stringify + // and when sending log strings remotely + const userOptions = [ + 'allowIncomingWhileBusy', + 'appName', + 'appVersion', + 'closeProtection', + 'codecPreferences', + 'disableAudioContextSounds', + 'dscp', + 'edge', + 'enableImprovedSignalingErrorPrecision', + 'forceAggressiveIceNomination', + 'logLevel', + 'maxAverageBitrate', + 'maxCallSignalingTimeoutMs', + 'sounds', + 'tokenRefreshMs', + ]; + const userOptionOverrides = [ + 'RTCPeerConnection', + 'enumerateDevices', + 'getUserMedia', + ]; + if (typeof options === 'object') { + const toLog: any = { ...options }; + Object.keys(toLog).forEach((key: string) => { + if (!userOptions.includes(key) && !userOptionOverrides.includes(key)) { + delete toLog[key]; + } + if (userOptionOverrides.includes(key)) { + toLog[key] = true; + } + }); + this._log.debug(`.${caller}`, JSON.stringify(toLog)); + } + } + /** * Create a new {@link Call}. * @param twimlParams - A flat object containing key:value pairs to be sent to the TwiML app. @@ -1121,6 +1172,7 @@ class Device extends EventEmitter { const ttlMs: number = payload.token.ttl * 1000; const timeoutMs: number = Math.max(0, ttlMs - this._options.tokenRefreshMs); this._tokenWillExpireTimeout = setTimeout(() => { + this._log.debug('#tokenWillExpire'); this.emit('tokenWillExpire', this); if (this._tokenWillExpireTimeout) { clearTimeout(this._tokenWillExpireTimeout); @@ -1135,7 +1187,7 @@ class Device extends EventEmitter { const [preferredURI] = preferredURIs; this._preferredURI = createSignalingEndpointURL(preferredURI); } else { - this._log.info('Could not parse a preferred URI from the stream#connected event.'); + this._log.warn('Could not parse a preferred URI from the stream#connected event.'); } // The signaling stream emits a `connected` event after reconnection, if the @@ -1186,7 +1238,8 @@ class Device extends EventEmitter { twilioError = new GeneralErrors.UnknownError(customMessage, originalError); } - this._log.info('Received error: ', twilioError); + this._log.error('Received error: ', twilioError); + this._log.debug('#error', originalError); this.emit(Device.EventName.Error, twilioError, call); } @@ -1201,6 +1254,7 @@ class Device extends EventEmitter { } if (!payload.callsid || !payload.sdp) { + this._log.debug('#error', payload); this.emit(Device.EventName.Error, new ClientErrors.BadRequest('Malformed invite from gateway')); return; } @@ -1320,7 +1374,9 @@ class Device extends EventEmitter { } this._state = state; - this.emit(this._stateEventMapping[state]); + const name = this._stateEventMapping[state]; + this._log.debug(`#${name}`); + this.emit(name); } /** @@ -1367,6 +1423,15 @@ class Device extends EventEmitter { }); } + /** + * Setup logger's loglevel + */ + private _setupLoglevel(logLevel?: LogLevelDesc): void { + const level = typeof logLevel === 'number' ? logLevel : LogLevels.ERROR; + this._log.setDefaultLevel(level); + this._log.info('Set logger default level to', level); + } + /** * Create and set a publisher for the {@link Device} to use. */ @@ -1378,7 +1443,6 @@ class Device extends EventEmitter { const publisherOptions = { defaultPayload: this._createDefaultPayload, - log: this._log, metadata: { app_name: this._options.appName, app_version: this._options.appVersion, @@ -1456,9 +1520,13 @@ class Device extends EventEmitter { }, RINGTONE_PLAY_TIMEOUT); }), ]).catch(reason => { - this._log.info(reason.message); + this._log.warn(reason.message); }).then(() => { clearTimeout(timeout); + this._log.debug('#incoming', JSON.stringify({ + customParameters: call.customParameters, + parameters: call.parameters, + })); this.emit(Device.EventName.Incoming, call); }); } diff --git a/lib/twilio/eventpublisher.ts b/lib/twilio/eventpublisher.ts index bdee0446..1caa4804 100644 --- a/lib/twilio/eventpublisher.ts +++ b/lib/twilio/eventpublisher.ts @@ -6,6 +6,7 @@ // @ts-nocheck import { EventEmitter } from 'events'; import request from './request'; +import Log from './log'; /** * Builds Endpoint Analytics (EA) event payloads and sends them to @@ -58,7 +59,7 @@ class EventPublisher extends EventEmitter { get() { return isEnabled; }, set(_isEnabled) { isEnabled = _isEnabled; }, }, - _log: { value: options.log }, + _log: { value: new Log('EventPublisher') }, _request: { value: options.request || request, writable: true }, _token: { value: token, writable: true }, isEnabled: { @@ -94,10 +95,18 @@ class EventPublisher extends EventEmitter { */ EventPublisher.prototype._post = function _post(endpointName, level, group, name, payload, connection, force) { if ((!this.isEnabled && !force) || !this._host) { + this._log.debug('Publishing cancelled', JSON.stringify({ isEnabled: this.isEnabled, force, host: this._host })); return Promise.resolve(); } if (!connection || ((!connection.parameters || !connection.parameters.CallSid) && !connection.outboundConnectionId)) { + if (!connection) { + this._log.debug('Publishing cancelled. Missing connection object'); + } else { + this._log.debug('Publishing cancelled. Missing connection info', JSON.stringify({ + parameters: connection.parameters, outboundConnectionId: connection.outboundConnectionId + })); + } return Promise.resolve(); } @@ -117,6 +126,11 @@ EventPublisher.prototype._post = function _post(endpointName, level, group, name event.publisher_metadata = this.metadata; } + endpointName === 'EndpointEvents' && this._log.debug( + 'Publishing insights', + JSON.stringify({ endpointName, event, force, host: this._host }), + ); + const requestParams = { body: event, headers: { @@ -136,7 +150,7 @@ EventPublisher.prototype._post = function _post(endpointName, level, group, name } }); }).catch(e => { - this._log.warn(`Unable to post ${group} ${name} event to Insights. Received error: ${e}`); + this._log.error(`Unable to post ${group} ${name} event to Insights. Received error: ${e}`); }); }; diff --git a/lib/twilio/log.ts b/lib/twilio/log.ts index ad25b0be..2f9479be 100644 --- a/lib/twilio/log.ts +++ b/lib/twilio/log.ts @@ -19,8 +19,9 @@ export interface LogOptions { } /** - * {@link Log} provides logging features throught the sdk using loglevel module + * {@link Log} provides logging features throughout the sdk using loglevel module * See https://github.com/pimterry/loglevel for documentation + * @private */ class Log { /** @@ -29,38 +30,46 @@ class Log { static levels: LogLevelModule.LogLevel = LogLevelModule.levels; /** - * Create the logger singleton instance if it doesn't exists - * @returns The singleton {@link Log} instance + * Return the `loglevel` instance maintained internally. + * @param [options] - Optional settings + * @returns The `loglevel` instance. */ - static getInstance(): Log { - if (!Log.instance) { - Log.instance = new Log(); + static getLogLevelInstance(options?: LogOptions): LogLevelModule.Logger { + if (!Log.loglevelInstance) { + try { + Log.loglevelInstance = (options && options.LogLevelModule ? options.LogLevelModule : LogLevelModule).getLogger(PACKAGE_NAME); + } catch { + // tslint:disable-next-line + console.warn('Cannot create custom logger'); + Log.loglevelInstance = console as any; + } } - return Log.instance; + return Log.loglevelInstance; } /** - * The logger singleton instance + * The loglevel singleton instance */ - private static instance: Log; + private static loglevelInstance: LogLevelModule.Logger; /** * The loglevel logger instance that will be used in this {@link Log} */ private _log: LogLevelModule.Logger; + /** + * Prefix to use for this log instance + */ + private _prefix: string; + /** * @constructor + * @param [tag] - tag name for the logs * @param [options] - Optional settings */ - constructor(options?: LogOptions) { - try { - this._log = (options && options.LogLevelModule ? options.LogLevelModule : LogLevelModule).getLogger(PACKAGE_NAME); - } catch { - // tslint:disable-next-line - console.warn('Cannot create custom logger'); - this._log = console as any; - } + constructor(tag: string, options?: LogOptions) { + this._log = Log.getLogLevelInstance(options); + this._prefix = `[TwilioVoice][${tag}]`; } /** @@ -68,7 +77,7 @@ class Log { * @param args - Any number of arguments to be passed to loglevel.debug */ debug(...args: any[]): void { - this._log.debug(...args); + this._log.debug(this._prefix, ...args); } /** @@ -76,15 +85,7 @@ class Log { * @param args - Any number of arguments to be passed to loglevel.error */ error(...args: any[]): void { - this._log.error(...args); - } - - /** - * Return the `loglevel` instance maintained internally. - * @returns The `loglevel` instance. - */ - getLogLevelInstance(): LogLevelModule.Logger { - return this._log; + this._log.error(this._prefix, ...args); } /** @@ -92,7 +93,7 @@ class Log { * @param args - Any number of arguments to be passed to loglevel.info */ info(...args: any[]): void { - this._log.info(...args); + this._log.info(this._prefix, ...args); } /** @@ -112,10 +113,10 @@ class Log { * @param args - Any number of arguments to be passed to loglevel.warn */ warn(...args: any[]): void { - this._log.warn(...args); + this._log.warn(this._prefix, ...args); } } -export const Logger = Log.getInstance().getLogLevelInstance(); +export const Logger = Log.getLogLevelInstance(); export default Log; diff --git a/lib/twilio/outputdevicecollection.ts b/lib/twilio/outputdevicecollection.ts index 6c91384f..156d9d26 100644 --- a/lib/twilio/outputdevicecollection.ts +++ b/lib/twilio/outputdevicecollection.ts @@ -4,6 +4,7 @@ */ import { SOUNDS_BASE_URL } from './constants'; import { InvalidArgumentError, InvalidStateError, NotSupportedError } from './errors'; +import Log from './log'; const DEFAULT_TEST_SOUND_URL = `${SOUNDS_BASE_URL}/outgoing.mp3`; /** @@ -16,6 +17,11 @@ export default class OutputDeviceCollection { */ private _activeDevices: Set = new Set(); + /** + * An instance of Logger to use. + */ + private _log: Log = new Log('OutputDeviceCollection'); + /** * @private */ @@ -32,6 +38,7 @@ export default class OutputDeviceCollection { * @returns whether the device was present before it was deleted */ delete(device: MediaDeviceInfo): boolean { + this._log.debug('.delete', device); const wasDeleted: boolean = !!(this._activeDevices.delete(device)); const defaultDevice: MediaDeviceInfo = this._availableDevices.get('default') @@ -63,6 +70,7 @@ export default class OutputDeviceCollection { * or no IDs are passed. */ set(deviceIdOrIds: string | string[]): Promise { + this._log.debug('.set', deviceIdOrIds); if (!this._isSupported) { return Promise.reject(new NotSupportedError('This browser does not support audio output selection')); } diff --git a/lib/twilio/preflight/preflight.ts b/lib/twilio/preflight/preflight.ts index 1f982c33..2525b3a5 100644 --- a/lib/twilio/preflight/preflight.ts +++ b/lib/twilio/preflight/preflight.ts @@ -13,6 +13,7 @@ import { SignalingErrors, TwilioError, } from '../errors'; +import Log from '../log'; import { RTCSampleTotals } from '../rtc/sample'; import RTCSample from '../rtc/sample'; import { getRTCIceCandidateStatsReport } from '../rtc/stats'; @@ -125,6 +126,11 @@ export class PreflightTest extends EventEmitter { */ private _latestSample: RTCSample | undefined; + /** + * An instance of Logger to use. + */ + private _log: Log = new Log('PreflightTest'); + /** * Network related timing measurements for this test */ @@ -196,12 +202,43 @@ export class PreflightTest extends EventEmitter { fileInputStream: this._options.fakeMicInput ? this._getStreamFromFile() : undefined, }); + + // Device sets the loglevel so start logging after initializing the device. + // Then selectively log options that users can modify. + const userOptions = [ + 'codecPreferences', + 'edge', + 'fakeMicInput', + 'logLevel', + 'signalingTimeoutMs', + ]; + const userOptionOverrides = [ + 'audioContext', + 'deviceFactory', + 'fileInputStream', + 'getRTCIceCandidateStatsReport', + 'iceServers', + 'rtcConfiguration', + ]; + if (typeof options === 'object') { + const toLog: any = { ...options }; + Object.keys(toLog).forEach((key: string) => { + if (!userOptions.includes(key) && !userOptionOverrides.includes(key)) { + delete toLog[key]; + } + if (userOptionOverrides.includes(key)) { + toLog[key] = true; + } + }); + this._log.debug('.constructor', JSON.stringify(toLog)); + } } /** * Stops the current test and raises a failed event. */ stop(): void { + this._log.debug('.stop'); const error = new GeneralErrors.CallCancelledError(); if (this._device) { this._device.once(Device.EventName.Unregistered, () => this._onFailed(error)); @@ -220,6 +257,7 @@ export class PreflightTest extends EventEmitter { warning.rtcWarning = rtcWarning; } this._warnings.push(warning); + this._log.debug(`#${PreflightTest.Events.Warning}`, JSON.stringify(warning)); this.emit(PreflightTest.Events.Warning, warning); } @@ -435,6 +473,7 @@ export class PreflightTest extends EventEmitter { this._releaseHandlers(); this._endTime = Date.now(); this._status = PreflightTest.Status.Failed; + this._log.debug(`#${PreflightTest.Events.Failed}`, error); this.emit(PreflightTest.Events.Failed, error); } @@ -458,6 +497,7 @@ export class PreflightTest extends EventEmitter { this._endTime = Date.now(); this._status = PreflightTest.Status.Completed; this._report = this._getReport(); + this._log.debug(`#${PreflightTest.Events.Completed}`, JSON.stringify(this._report)); this.emit(PreflightTest.Events.Completed, this._report); }, 10); } @@ -494,6 +534,7 @@ export class PreflightTest extends EventEmitter { call.once('accept', () => { this._callSid = call['_mediaHandler'].callSid; this._status = PreflightTest.Status.Connected; + this._log.debug(`#${PreflightTest.Events.Connected}`); this.emit(PreflightTest.Events.Connected); }); @@ -507,6 +548,7 @@ export class PreflightTest extends EventEmitter { this._latestSample = sample; this._samples.push(sample); + this._log.debug(`#${PreflightTest.Events.Sample}`, JSON.stringify(sample)); this.emit(PreflightTest.Events.Sample, sample); }); diff --git a/lib/twilio/pstream.ts b/lib/twilio/pstream.ts index 677dad5a..f46a468d 100644 --- a/lib/twilio/pstream.ts +++ b/lib/twilio/pstream.ts @@ -58,7 +58,7 @@ class PStream extends EventEmitter { this._handleTransportMessage = this._handleTransportMessage.bind(this); this._handleTransportOpen = this._handleTransportOpen.bind(this); - this._log = Log.getInstance(); + this._log = new Log('PStream'); // NOTE(mroberts): EventEmitter requires that we catch all errors. this.on('error', () => { diff --git a/lib/twilio/rtc/peerconnection.ts b/lib/twilio/rtc/peerconnection.ts index 11d9de04..f0828f82 100644 --- a/lib/twilio/rtc/peerconnection.ts +++ b/lib/twilio/rtc/peerconnection.ts @@ -38,7 +38,7 @@ function PeerConnection(audioHelper, pstream, options) { return new PeerConnection(audioHelper, pstream, options); } - this._log = Log.getInstance(); + this._log = new Log('PeerConnection'); function noop() { this._log.warn('Unexpected noop call in peerconnection'); @@ -423,12 +423,12 @@ PeerConnection.prototype._onMediaConnectionStateChange = function(newState) { break; case 'disconnected': message = 'ICE liveliness check failed. May be having trouble connecting to Twilio'; - this._log.info(message); + this._log.warn(message); this.ondisconnected(message); break; case 'failed': message = 'Connection with Twilio was interrupted.'; - this._log.info(message); + this._log.warn(message); this.onfailed(message); break; } @@ -847,7 +847,7 @@ PeerConnection.prototype.iceRestart = function() { if (!payload.sdp || this.version.pc.signalingState !== 'have-local-offer') { const message = 'Invalid state or param during ICE Restart:' + `hasSdp:${!!payload.sdp}, signalingState:${this.version.pc.signalingState}`; - this._log.info(message); + this._log.warn(message); return; } @@ -856,7 +856,7 @@ PeerConnection.prototype.iceRestart = function() { if (this.status !== 'closed') { this.version.processAnswer(this.codecPreferences, sdp, null, err => { const message = err && err.message ? err.message : err; - this._log.info(`Failed to process answer during ICE Restart. Error: ${message}`); + this._log.error(`Failed to process answer during ICE Restart. Error: ${message}`); }); } }; @@ -872,7 +872,7 @@ PeerConnection.prototype.iceRestart = function() { }).catch((err) => { const message = err && err.message ? err.message : err; - this._log.info(`Failed to createOffer during ICE Restart. Error: ${message}`); + this._log.error(`Failed to createOffer during ICE Restart. Error: ${message}`); // CreateOffer failures doesn't transition ice state to failed // We need trigger it so it can be picked up by retries this.onfailed(message); @@ -1039,7 +1039,7 @@ PeerConnection.prototype.getOrCreateDTMFSender = function getOrCreateDTMFSender( const self = this; const pc = this.version.pc; if (!pc) { - this._log.info('No RTCPeerConnection available to call createDTMFSender on'); + this._log.warn('No RTCPeerConnection available to call createDTMFSender on'); return null; } @@ -1059,7 +1059,7 @@ PeerConnection.prototype.getOrCreateDTMFSender = function getOrCreateDTMFSender( })[0]; if (!track) { - this._log.info('No local audio MediaStreamTrack available on the RTCPeerConnection to pass to createDTMFSender'); + this._log.warn('No local audio MediaStreamTrack available on the RTCPeerConnection to pass to createDTMFSender'); return null; } diff --git a/lib/twilio/rtc/rtcpc.ts b/lib/twilio/rtc/rtcpc.ts index 2e2212ec..09f64462 100644 --- a/lib/twilio/rtc/rtcpc.ts +++ b/lib/twilio/rtc/rtcpc.ts @@ -37,7 +37,7 @@ function RTCPC(options) { } RTCPC.prototype.create = function(rtcConstraints, rtcConfiguration) { - this.log = Log.getInstance(); + this.log = new Log('RTCPC'); this.pc = new this.RTCPeerConnection(rtcConfiguration, rtcConstraints); }; RTCPC.prototype.createModernConstraints = c => { diff --git a/lib/twilio/wstransport.ts b/lib/twilio/wstransport.ts index d8c000ad..44de7145 100644 --- a/lib/twilio/wstransport.ts +++ b/lib/twilio/wstransport.ts @@ -149,7 +149,7 @@ export default class WSTransport extends EventEmitter { /** * An instance of Logger to use. */ - private _log: Log = Log.getInstance(); + private _log: Log = new Log('WSTransport'); /** * Options after missing values are defaulted. @@ -250,7 +250,7 @@ export default class WSTransport extends EventEmitter { this._socket.send(message); } catch (e) { // Some unknown error occurred. Reset the socket to get a fresh session. - this._log.info('Error while sending message:', e.message); + this._log.error('Error while sending message:', e.message); this._closeSocket(); return false; } @@ -347,7 +347,7 @@ export default class WSTransport extends EventEmitter { try { this._socket = new this._options.WebSocket(this._connectedUri); } catch (e) { - this._log.info('Could not connect to endpoint:', e.message); + this._log.error('Could not connect to endpoint:', e.message); this._close(); this.emit('error', { code: 31000, @@ -386,7 +386,7 @@ export default class WSTransport extends EventEmitter { * Called in response to WebSocket#close event. */ private _onSocketClose = (event: CloseEvent): void => { - this._log.info(`Received websocket close event code: ${event.code}. Reason: ${event.reason}`); + this._log.error(`Received websocket close event code: ${event.code}. Reason: ${event.reason}`); // 1006: Abnormal close. When the server is unreacheable // 1015: TLS Handshake error if (event.code === 1006 || event.code === 1015) { @@ -427,7 +427,7 @@ export default class WSTransport extends EventEmitter { * Called in response to WebSocket#error event. */ private _onSocketError = (err: Error): void => { - this._log.info(`WebSocket received error: ${err.message}`); + this._log.error(`WebSocket received error: ${err.message}`); this.emit('error', { code: 31000, message: err.message || 'WSTransport socket error', From 08162825afaa996fd4a8f6b02594685d8043b70c Mon Sep 17 00:00:00 2001 From: charliesantos Date: Wed, 29 Nov 2023 10:56:28 -0800 Subject: [PATCH 2/3] Lint and tests --- lib/twilio/eventpublisher.ts | 14 ++++++----- tests/eventpublisher.js | 7 ++++++ tests/peerconnection.js | 27 ++++++++++++++------- tests/unit/log.ts | 46 +++++++++++++++++++++--------------- 4 files changed, 61 insertions(+), 33 deletions(-) diff --git a/lib/twilio/eventpublisher.ts b/lib/twilio/eventpublisher.ts index 1caa4804..f61433ca 100644 --- a/lib/twilio/eventpublisher.ts +++ b/lib/twilio/eventpublisher.ts @@ -5,8 +5,8 @@ */ // @ts-nocheck import { EventEmitter } from 'events'; -import request from './request'; import Log from './log'; +import request from './request'; /** * Builds Endpoint Analytics (EA) event payloads and sends them to @@ -104,7 +104,7 @@ EventPublisher.prototype._post = function _post(endpointName, level, group, name this._log.debug('Publishing cancelled. Missing connection object'); } else { this._log.debug('Publishing cancelled. Missing connection info', JSON.stringify({ - parameters: connection.parameters, outboundConnectionId: connection.outboundConnectionId + outboundConnectionId: connection.outboundConnectionId, parameters: connection.parameters, })); } return Promise.resolve(); @@ -126,10 +126,12 @@ EventPublisher.prototype._post = function _post(endpointName, level, group, name event.publisher_metadata = this.metadata; } - endpointName === 'EndpointEvents' && this._log.debug( - 'Publishing insights', - JSON.stringify({ endpointName, event, force, host: this._host }), - ); + if (endpointName === 'EndpointEvents') { + this._log.debug( + 'Publishing insights', + JSON.stringify({ endpointName, event, force, host: this._host }), + ); + } const requestParams = { body: event, diff --git a/tests/eventpublisher.js b/tests/eventpublisher.js index 7d8de615..cc922881 100644 --- a/tests/eventpublisher.js +++ b/tests/eventpublisher.js @@ -4,6 +4,7 @@ const EventPublisher = require('../lib/twilio/eventpublisher').default; describe('EventPublisher', () => { let publisher; + let log; before(() => { const options = { @@ -22,6 +23,10 @@ describe('EventPublisher', () => { publisher = new EventPublisher('test', 'sometoken', options); }); + beforeEach(() => { + log = { debug: sinon.stub() }; + }); + describe('constructor', () => { it('should return an EventPublisher', () => { assert(publisher instanceof EventPublisher); @@ -50,6 +55,7 @@ describe('EventPublisher', () => { mock = { _defaultPayload() { return { }; }, _host: 'foo', + _log: log, _post: EventPublisher.prototype._post, _request: { post: sinon.spy((a, cb) => { cb(); }) }, token: 'abc123' @@ -78,6 +84,7 @@ describe('EventPublisher', () => { beforeEach(() => { mock = { _defaultPayload() { return { }; }, + _log: log, _post: EventPublisher.prototype._post, _request: { post: sinon.spy((a, cb) => { cb(); }) }, token: 'abc123' diff --git a/tests/peerconnection.js b/tests/peerconnection.js index 2d7cdd38..a8e0cce3 100644 --- a/tests/peerconnection.js +++ b/tests/peerconnection.js @@ -5,6 +5,17 @@ const PeerConnection = require('./../lib/twilio/rtc/peerconnection').default; const root = global; describe('PeerConnection', () => { + let log; + + beforeEach(() => { + log = { + debug: sinon.stub(), + error: sinon.stub(), + info: sinon.stub(), + warn: sinon.stub(), + }; + }); + context('PeerConnection.prototype._setInputTracksFromStream', () => { const METHOD = PeerConnection.prototype._setInputTracksFromStream; const ERROR_STREAM_NOT_NULL = 'Can not set input stream to null while in a call'; @@ -678,7 +689,7 @@ describe('PeerConnection', () => { context = { callSid: CALLSID, codecPreferences: ['opus'], - _log: { info: sinon.stub() }, + _log: log, onerror: sinon.stub(), options, pstream, @@ -1156,7 +1167,7 @@ describe('PeerConnection', () => { transport = { state: 'new' }; context = { getRTCDtlsTransport: sinon.stub().returns(transport), - _log: { info: sinon.stub() }, + _log: log, ondtlstransportstatechange: sinon.stub(), }; toTest = METHOD.bind(context); @@ -1185,7 +1196,7 @@ describe('PeerConnection', () => { transport = { state: 'new' }; context = { getRTCDtlsTransport: sinon.stub().returns(transport), - _log: { info: sinon.stub() }, + _log: log, ondtlstransportstatechange: sinon.stub(), }; METHOD.call(context); @@ -1226,7 +1237,7 @@ describe('PeerConnection', () => { context = { version, options: {}, - _log: { info: sinon.stub() }, + _log: log, onfailed: sinon.stub(), onopen: sinon.stub(), onicecandidate: sinon.stub(), @@ -1445,7 +1456,7 @@ describe('PeerConnection', () => { context = { _iceState: 'new', _stopIceGatheringTimeout: sinon.stub(), - _log: { info: sinon.stub() }, + _log: log, onconnected: sinon.stub(), onreconnected: sinon.stub(), ondisconnected: sinon.stub(), @@ -1918,7 +1929,7 @@ describe('PeerConnection', () => { pc.outputs.set(MASTER_ID, output); context = { _disableOutput: sinon.stub(), - _log: { info: sinon.stub() } + _log: log, }; toTest = METHOD.bind(context, pc, MASTER_ID); }); @@ -2067,7 +2078,7 @@ describe('PeerConnection', () => { version: { pc }, - _log: { info: sinon.stub() } + _log: log, }; toTest = METHOD.bind(context); }); @@ -2087,7 +2098,7 @@ describe('PeerConnection', () => { context.version.pc = false; assert.deepStrictEqual(toTest(), null); assert.equal(context._getAudioTracks.called, false); - assert(context._log.info.calledWith('No RTCPeerConnection available to call createDTMFSender on')); + assert(context._log.warn.calledWith('No RTCPeerConnection available to call createDTMFSender on')); }); xit('Should return null and set dtmf unsupported true when createDTMFSender is not a function', () => { diff --git a/tests/unit/log.ts b/tests/unit/log.ts index 6553bc9e..34ce5106 100644 --- a/tests/unit/log.ts +++ b/tests/unit/log.ts @@ -6,47 +6,55 @@ const packageName = require('../../package.json').name; describe('Log', () => { let options: any; + let logA: any; + let logB: any; let _log: any; + before(() => { + (Log as any).loglevelInstance = null; + _log = {}; + }); + beforeEach(() => { - _log = { - debug: sinon.stub(), - error: sinon.stub(), - info: sinon.stub(), - setDefaultLevel: sinon.stub(), - warn: sinon.stub(), - }; + _log.debug = sinon.stub(); + _log.error = sinon.stub(); + _log.info = sinon.stub(); + _log.setDefaultLevel = sinon.stub(); + _log.warn = sinon.stub(); options = {LogLevelModule: { getLogger :sinon.stub().returns(_log)}}; + logA = new Log('foo', options); + logB = new Log('bar', options); }); - describe('constructor', () => { - it('should return the same instance when using getInstance', () => { - assert.equal(Log.getInstance(), Log.getInstance()); - }); - it('should initialize using correct package name', () => { - const log = new Log(options); + describe('constructor', () => { + it('should return the same loglevel instance with correct package name', () => { sinon.assert.calledWith(options.LogLevelModule.getLogger, packageName); + sinon.assert.calledOnce(options.LogLevelModule.getLogger); }); }); describe('after init', () => { - let log: Log; let args: any; beforeEach(() => { - log = new Log(options); args = ['foo', { bar: 'baz' }]; }); it('should call loglevel.setDefaultLevel', () => { - log.setDefaultLevel(Log.levels.DEBUG); - sinon.assert.calledWithExactly(_log.setDefaultLevel, Log.levels.DEBUG); + logA.setDefaultLevel(Log.levels.DEBUG); + logB.setDefaultLevel(Log.levels.INFO); + sinon.assert.calledTwice(_log.setDefaultLevel); + assert.deepStrictEqual(_log.setDefaultLevel.args[0], [Log.levels.DEBUG]); + assert.deepStrictEqual(_log.setDefaultLevel.args[1], [Log.levels.INFO]); }); ['debug', 'error', 'info', 'warn'].forEach(methodName => { it(`should call loglevel ${methodName} method`, () => { - (log as any)[methodName](...args); - sinon.assert.calledWithExactly.apply(sinon.assert, [_log[methodName], ...args]); + (logA as any)[methodName](...args); + (logB as any)[methodName](...args); + sinon.assert.calledTwice(_log[methodName]); + assert.deepStrictEqual(_log[methodName].args[0], ['[TwilioVoice][foo]', ...args]); + assert.deepStrictEqual(_log[methodName].args[1], ['[TwilioVoice][bar]', ...args]); }); }); }); From 41a2aa7fa921b83ca67153908686d302e993f69d Mon Sep 17 00:00:00 2001 From: charliesantos Date: Wed, 29 Nov 2023 15:26:21 -0800 Subject: [PATCH 3/3] Changelog --- CHANGELOG.md | 9 +++++++++ 1 file changed, 9 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 42f089f0..67b5176b 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,14 @@ :warning: **Important**: If you are upgrading to version 2.3.0 or later and have firewall rules or network configuration that blocks any unknown traffic by default, you need to update your configuration to allow connections to the new DNS names and IP addresses. Please refer to this [changelog](#230-january-23-2023) for more details. +2.10.0 (In Progress) +==================== + +Changes +------- + +- Added tags to logs +- Added more debug statements + 2.9.0 (November 28, 2023) =========================