diff --git a/package.json b/package.json index e18e7f92..61351666 100644 --- a/package.json +++ b/package.json @@ -12,6 +12,7 @@ "license": "GPL-3.0", "dependencies": { "curve25519-js": "^0.0.4", + "pino": "^7.11.0", "protobufjs": "6.8.8" }, "files": [ diff --git a/src/curve.js b/src/curve.js index 5c5fe59e..e949f468 100644 --- a/src/curve.js +++ b/src/curve.js @@ -2,6 +2,9 @@ 'use strict'; const curveJs = require('curve25519-js'); +const logger = require('./logger'); +const loggerChild = logger.getLogger().child({ module: 'curve' }); + const nodeCrypto = require('crypto'); // from: https://github.com/digitalbazaar/x25519-key-agreement-key-2019/blob/master/lib/crypto.js const PUBLIC_KEY_DER_PREFIX = Buffer.from([ @@ -34,7 +37,7 @@ function scrubPubKeyFormat(pubKey) { if (pubKey.byteLength == 33) { return pubKey.slice(1); } else { - console.error("WARNING: Expected pubkey of length 33, please report the ST and client that generated the pubkey"); + loggerChild.error("WARNING: Expected pubkey of length 33, please report the ST and client that generated the pubkey"); return pubKey; } } diff --git a/src/logger.js b/src/logger.js new file mode 100644 index 00000000..e3bb726d --- /dev/null +++ b/src/logger.js @@ -0,0 +1,11 @@ +const loggerPino = require('pino'); + +const _logger = loggerPino(); + +function getLogger(){ + return _logger; +} + + +module.exports = { getLogger } + diff --git a/src/queue_job.js b/src/queue_job.js index baab89c4..aa0bea02 100644 --- a/src/queue_job.js +++ b/src/queue_job.js @@ -1,12 +1,14 @@ // vim: ts=4:sw=4:expandtab - + +const logger = require('./logger'); +const loggerChild = logger.getLogger().child({ module: 'queue_job' }); + /* * jobQueue manages multiple queues indexed by device to serialize * session io ops on the database. */ 'use strict'; - const _queueAsyncBuckets = new Map(); const _gcLimit = 10000; @@ -47,7 +49,7 @@ module.exports = function(bucket, awaitable) { if (typeof bucket === 'string') { awaitable.name = bucket; } else { - console.warn("Unhandled bucket type (for naming):", typeof bucket, bucket); + loggerChild.warn({ bucketTypeof: typeof bucket, bucket }, "Unhandled bucket type (for naming):"); } } let inactive; diff --git a/src/session_builder.js b/src/session_builder.js index 9bd333f1..46a665ed 100644 --- a/src/session_builder.js +++ b/src/session_builder.js @@ -8,13 +8,13 @@ const crypto = require('./crypto'); const curve = require('./curve'); const errors = require('./errors'); const queueJob = require('./queue_job'); - - +const logger = require('./logger'); class SessionBuilder { constructor(storage, protocolAddress) { this.addr = protocolAddress; this.storage = storage; + this.logger = logger.getLogger().child({ module: 'session_builder' }); } async initOutgoing(device) { @@ -43,7 +43,7 @@ class SessionBuilder { } else { const openSession = record.getOpenSession(); if (openSession) { - console.warn("Closing stale open session for new outgoing prekey bundle"); + this.logger.warn("Closing stale open session for new outgoing prekey bundle"); record.closeSession(openSession); } } @@ -71,7 +71,7 @@ class SessionBuilder { } const existingOpenSession = record.getOpenSession(); if (existingOpenSession) { - console.warn("Closing open session in favor of incoming prekey bundle"); + this.logger.warn("Closing open session in favor of incoming prekey bundle"); record.closeSession(existingOpenSession); } record.setSession(await this.initSession(false, preKeyPair, signedPreKeyPair, diff --git a/src/session_cipher.js b/src/session_cipher.js index 0e6df11e..887d4f2a 100644 --- a/src/session_cipher.js +++ b/src/session_cipher.js @@ -10,6 +10,9 @@ const errors = require('./errors'); const protobufs = require('./protobufs'); const queueJob = require('./queue_job'); +const logger = require('./logger'); +const loggerChild = logger.getLogger().child({ module: 'session_cipher' }); + const VERSION = 3; function assertBuffer(value) { @@ -154,9 +157,9 @@ class SessionCipher { errs.push(e); } } - console.error("Failed to decrypt message with any known session..."); + loggerChild.error("Failed to decrypt message with any known session..."); for (const e of errs) { - console.error("Session error:" + e, e.stack); + loggerChild.error({ stack: e.stack }, "Session error:" + e); } throw new errors.SessionError("No matching sessions found for message"); } @@ -179,7 +182,7 @@ class SessionCipher { // was the most current. Simply make a note of it and continue. If our // actual open session is for reason invalid, that must be handled via // a full SessionError response. - console.warn("Decrypted message with closed session."); + loggerChild.warn("Decrypted message with closed session."); } await this.storeRecord(record); return result.plaintext; diff --git a/src/session_record.js b/src/session_record.js index 7626a392..422a2363 100644 --- a/src/session_record.js +++ b/src/session_record.js @@ -2,6 +2,9 @@ const BaseKeyType = require('./base_key_type'); +const logger = require('./logger'); +const loggerChild = logger.getLogger().child({ module: 'session_record' }); + const CLOSED_SESSIONS_MAX = 40; const SESSION_RECORD_VERSION = 'v1'; @@ -170,9 +173,9 @@ const migrations = [{ } else { for (const key in sessions) { if (sessions[key].indexInfo.closed === -1) { - console.error('V1 session storage migration error: registrationId', - data.registrationId, 'for open session version', - data.version); + loggerChild.error( + { data }, 'V1 session storage migration error: registrationId ** for open session version **' + ); } } } @@ -190,7 +193,7 @@ class SessionRecord { let run = (data.version === undefined); for (let i = 0; i < migrations.length; ++i) { if (run) { - console.info("Migrating session to:", migrations[i].version); + loggerChild.info({migration : migrations[i]}, "Migrating session to"); migrations[i].migrate(data); } else if (migrations[i].version === data.version) { run = true; @@ -267,18 +270,18 @@ class SessionRecord { closeSession(session) { if (this.isClosed(session)) { - console.warn("Session already closed", session); + loggerChild.warn({ session }, "Session already closed"); return; } - console.info("Closing session:", session); + loggerChild.info({session}, "Closing session"); session.indexInfo.closed = Date.now(); } openSession(session) { if (!this.isClosed(session)) { - console.warn("Session already open"); + loggerChild.warn("Session already open"); } - console.info("Opening session:", session); + loggerChild.info({session}, "Opening session"); session.indexInfo.closed = -1; } @@ -298,7 +301,7 @@ class SessionRecord { } } if (oldestKey) { - console.info("Removing old closed session:", oldestSession); + loggerChild.info({ oldestSession }, "Removing old closed session"); delete this.sessions[oldestKey]; } else { throw new Error('Corrupt sessions object');