diff --git a/index.d.ts b/index.d.ts index b77746a4..42175b90 100644 --- a/index.d.ts +++ b/index.d.ts @@ -108,6 +108,16 @@ export class Provider extends EventEmitter { * A "recipient" is a String containing the hex-encoded device token. */ send(notification: Notification, recipients: string|string[]): Promise; + + /** + * Set an info logger, and optionally an errorLogger to separately log errors. + * + * In order to log, these functions must have a property '.enabled' that is true. + * (The default logger uses the npm 'debug' module which sets '.enabled' + * based on the DEBUG environment variable) + */ + setLogger(logger: (string) => void, errorLogger?: (string) => void): Promise; + /** * Indicate to node-apn that it should close all open connections when the queue of pending notifications is fully drained. This will allow your application to terminate. */ diff --git a/lib/client.js b/lib/client.js index 874fa4d7..73c84043 100644 --- a/lib/client.js +++ b/lib/client.js @@ -4,7 +4,11 @@ const VError = require("verror"); const extend = require("./util/extend"); module.exports = function (dependencies) { - const logger = dependencies.logger; + // Used for routine logs such as HTTP status codes, etc. + const defaultLogger = dependencies.logger; + // Used for unexpected events that should be rare under normal circumstances, + // e.g. connection errors. + const defaultErrorLogger = dependencies.errorLogger || defaultLogger; const config = dependencies.config; const http2 = dependencies.http2; @@ -24,14 +28,16 @@ module.exports = function (dependencies) { function Client (options) { this.config = config(options); + this.logger = defaultLogger; + this.errorLogger = defaultErrorLogger; this.healthCheckInterval = setInterval(() => { if (this.session && !this.session.closed && !this.session.destroyed && !this.isDestroyed) { this.session.ping((error, duration) => { if (error) { - logger("No Ping response after " + duration + " ms with error:" + error.message); + this.errorLogger("No Ping response after " + duration + " ms with error:" + error.message); return; } - logger("Ping response after " + duration + " ms"); + this.logger("Ping response after " + duration + " ms"); }); } }, this.config.heartBeat).unref(); @@ -84,40 +90,40 @@ module.exports = function (dependencies) { const session = this.session = http2.connect(this._mockOverrideUrl || `https://${this.config.address}`, this.config); this.session.on("close", () => { - if (logger.enabled) { - logger("Session closed"); + if (this.errorLogger.enabled) { + this.errorLogger("Session closed"); } this.destroySession(session); }); this.session.on("socketError", (error) => { - if (logger.enabled) { - logger(`Socket error: ${error}`); + if (this.errorLogger.enabled) { + this.errorLogger(`Socket error: ${error}`); } this.closeAndDestroySession(session); }); this.session.on("error", (error) => { - if (logger.enabled) { - logger(`Session error: ${error}`); + if (this.errorLogger.enabled) { + this.errorLogger(`Session error: ${error}`); } this.closeAndDestroySession(session); }); this.session.on("goaway", (errorCode, lastStreamId, opaqueData) => { - if (logger.enabled) { - logger(`GOAWAY received: (errorCode ${errorCode}, lastStreamId: ${lastStreamId}, opaqueData: ${opaqueData})`); + if (this.errorLogger.enabled) { + this.errorLogger(`GOAWAY received: (errorCode ${errorCode}, lastStreamId: ${lastStreamId}, opaqueData: ${opaqueData})`); } this.closeAndDestroySession(session); }); - if (logger.enabled) { + if (this.logger.enabled) { this.session.on("connect", () => { - logger("Session connected"); + this.logger("Session connected"); }); this.session.on("frameError", (frameType, errorCode, streamId) => { - logger(`Frame error: (frameType: ${frameType}, errorCode ${errorCode}, streamId: ${streamId})`); + this.errorLogger(`Frame error: (frameType: ${frameType}, errorCode ${errorCode}, streamId: ${streamId})`); }); } } @@ -159,8 +165,8 @@ module.exports = function (dependencies) { return new Promise ( resolve => { request.on("end", () => { try { - if (logger.enabled) { - logger(`Request ended with status ${status} and responseData: ${responseData}`); + if (this.logger.enabled) { + this.logger(`Request ended with status ${status} and responseData: ${responseData}`); } if (status === 200) { @@ -183,21 +189,22 @@ module.exports = function (dependencies) { resolve({ device, status, response }); } else { - let error = new VError("stream ended unexpectedly"); + this.closeAndDestroySession(); + let error = new VError(`stream ended unexpectedly with status ${status} and empty body`); resolve({ device, error }); } } catch (e) { const error = new VError(e, 'Unexpected error processing APNs response'); - if (logger.enabled) { - logger(`Unexpected error processing APNs response: ${e.message}`); + if (this.errorLogger.enabled) { + this.errorLogger(`Unexpected error processing APNs response: ${e.message}`); } resolve({ device, error }); } }); request.setTimeout(this.config.requestTimeout, () => { - if (logger.enabled) { - logger('Request timeout'); + if (this.errorLogger.enabled) { + this.errorLogger('Request timeout'); } status = TIMEOUT_STATUS; @@ -208,8 +215,8 @@ module.exports = function (dependencies) { }); request.on("aborted", () => { - if (logger.enabled) { - logger('Request aborted'); + if (this.errorLogger.enabled) { + this.errorLogger('Request aborted'); } status = ABORTED_STATUS; @@ -218,8 +225,8 @@ module.exports = function (dependencies) { }); request.on("error", (error) => { - if (logger.enabled) { - logger(`Request error: ${error}`); + if (this.errorLogger.enabled) { + this.errorLogger(`Request error: ${error}`); } status = ERROR_STATUS; @@ -233,9 +240,9 @@ module.exports = function (dependencies) { resolve({ device, error }); }); - if (logger.enabled) { + if (this.errorLogger.enabled) { request.on("frameError", (frameType, errorCode, streamId) => { - logger(`Request frame error: (frameType: ${frameType}, errorCode ${errorCode}, streamId: ${streamId})`); + this.errorLogger(`Request frame error: (frameType: ${frameType}, errorCode ${errorCode}, streamId: ${streamId})`); }); } @@ -250,8 +257,8 @@ module.exports = function (dependencies) { } return; } - if (logger.enabled) { - logger('Called client.shutdown()'); + if (this.errorLogger.enabled) { + this.errorLogger('Called client.shutdown()'); } this.isDestroyed = true; if (this.healthCheckInterval) { @@ -261,5 +268,17 @@ module.exports = function (dependencies) { this.closeAndDestroySession(undefined, callback); }; + Client.prototype.setLogger = function (newLogger, newErrorLogger = null) { + if (typeof newLogger !== 'function') { + throw new Error(`Expected newLogger to be a function, got ${typeof newLogger}`); + }; + if (newErrorLogger && typeof newErrorLogger !== 'function') { + throw new Error(`Expected newErrorLogger to be a function or null, got ${typeof newErrorLogger}`); + } + this.logger = newLogger; + this.errorLogger = newErrorLogger || newLogger; + }; + + return Client; } diff --git a/package-lock.json b/package-lock.json index 764b3291..dd10f113 100644 --- a/package-lock.json +++ b/package-lock.json @@ -280,6 +280,12 @@ "integrity": "sha512-RbzJvlNzmRq5c3O09UipeuXno4tA1FE6ikOjxZK0tuxVv3412l64l5t1W5pj4+rJq9vpkm/kwiR07aZXnsKPxw==", "dev": true }, + "@types/node": { + "version": "14.14.37", + "resolved": "https://registry.npmjs.org/@types/node/-/node-14.14.37.tgz", + "integrity": "sha512-XYmBiy+ohOR4Lh5jE379fV2IU+6Jn4g5qASinhitfyO71b/sCo6MKsMLF5tc7Zf2CE8hViVQyYSobJNke8OvUw==", + "dev": true + }, "agent-base": { "version": "6.0.2", "resolved": "https://registry.npmjs.org/agent-base/-/agent-base-6.0.2.tgz", diff --git a/package.json b/package.json index 928c8eb8..9574d983 100644 --- a/package.json +++ b/package.json @@ -24,6 +24,7 @@ "verror": "1.10.0" }, "devDependencies": { + "@types/node": "^14.14.37", "chai": "3.x", "chai-as-promised": "7.1.1", "codecov": "3.8.1", diff --git a/test/client.js b/test/client.js index 2101dc1d..83f6f8fa 100644 --- a/test/client.js +++ b/test/client.js @@ -245,6 +245,13 @@ describe("Client", () => { await new Promise((resolve) => server.on('listening', resolve)); client = createClient(TEST_PORT); + const infoMessages = []; + const errorMessages = []; + const mockInfoLogger = (message) => { infoMessages.push(message); }; + const mockErrorLogger = (message) => { errorMessages.push(message); }; + mockInfoLogger.enabled = true; + mockErrorLogger.enabled = true; + client.setLogger(mockInfoLogger, mockErrorLogger); const runRequestWithBadDeviceToken = async () => { const mockHeaders = {'apns-someheader': 'somevalue'}; @@ -270,6 +277,12 @@ describe("Client", () => { await runRequestWithBadDeviceToken(); await runRequestWithBadDeviceToken(); expect(establishedConnections).to.equal(1); // should establish a connection to the server and reuse it + expect(infoMessages).to.deep.equal([ + 'Session connected', + "Request ended with status 400 and responseData: {\"reason\": \"BadDeviceToken\"}", + "Request ended with status 400 and responseData: {\"reason\": \"BadDeviceToken\"}", + ]); + expect(errorMessages).to.deep.equal([]); }); // node-apn started closing connections in response to a bug report where HTTP 500 responses @@ -304,7 +317,7 @@ describe("Client", () => { expect(result).to.exist; expect(result.device).to.equal(MOCK_DEVICE_TOKEN); expect(result.error).to.be.an.instanceof(VError); - expect(result.error.message).to.have.string('stream ended unexpectedly'); + expect(result.error.message).to.have.string('stream ended unexpectedly'); }; await runRequestWithInternalServerError(); await runRequestWithInternalServerError(); @@ -432,7 +445,7 @@ describe("Client", () => { ); expect(result).to.deep.equal({ device: MOCK_DEVICE_TOKEN, - error: new VError('stream ended unexpectedly'), + error: new VError('stream ended unexpectedly with status null and empty body'), }); expect(didGetRequest).to.be.true; didGetRequest = false; @@ -474,7 +487,7 @@ describe("Client", () => { ); expect(result).to.deep.equal({ device: MOCK_DEVICE_TOKEN, - error: new VError('stream ended unexpectedly'), + error: new VError('stream ended unexpectedly with status null and empty body'), }); expect(didGetRequest).to.be.true; };