Skip to content

Commit

Permalink
Proposal: Add a configurable info/error logger
Browse files Browse the repository at this point in the history 
For the sake of backwards compatibility, continue requiring DEBUG=apn to
log either of these.

For the sake of convenience, allow applications to manually override
these loggers on a per-Client instance basis.
A more fully-featured logger such as error/warn/info/debug might be
useful but overkill if the error conditions are rare in practice.

Related to #59
High volume uses of node-apn may benefit from logging errors but ignore
non-errors.

Related to #30
- setLogger can be used by applications to set their own prefix
  • Loading branch information
@TysonAndre
TysonAndre committed Apr 6, 2021
1 parent 08f2ef6 commit fe7a446
Show file tree
Hide file tree
Showing 5 changed files with 81 additions and 32 deletions.
10 changes: 10 additions & 0 deletions index.d.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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<Responses>;

/**
* 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<Responses>;

/**
* 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.
*/
Expand Down
77 changes: 48 additions & 29 deletions lib/client.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;

Expand All @@ -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();
Expand Down Expand Up @@ -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})`);
});
}
}
Expand Down Expand Up @@ -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) {
Expand All @@ -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;
Expand All @@ -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;
Expand All @@ -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;
Expand All @@ -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})`);
});
}

Expand All @@ -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) {
Expand All @@ -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;
}
6 changes: 6 additions & 0 deletions package-lock.json
View file

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

1 change: 1 addition & 0 deletions package.json
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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",
Expand Down
19 changes: 16 additions & 3 deletions test/client.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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'};
Expand All @@ -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
Expand Down Expand Up @@ -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();
Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -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;
};
Expand Down

0 comments on commit fe7a446

Please sign in to comment.