From 4a535be1425de8d7d4588e4626418fb49cbb553f Mon Sep 17 00:00:00 2001 From: Tom Kirkpatrick Date: Sun, 17 Jun 2018 13:12:23 +0200 Subject: [PATCH] feat(logging): more readable logs Use debug-logger to provide a more comprehensive and flexible logging solution. Use two separate log handlers to provide separation between electron and and lnd logs. --- app/main.dev.js | 59 +++++++++++++++++++++++------------- app/utils/log.js | 78 ++++++++++++++++++++++++++++++++++++++++++++++++ package.json | 1 + yarn.lock | 8 ++++- 4 files changed, 125 insertions(+), 21 deletions(-) create mode 100644 app/utils/log.js diff --git a/app/main.dev.js b/app/main.dev.js index 1f9eec03..d2a0c703 100644 --- a/app/main.dev.js +++ b/app/main.dev.js @@ -20,6 +20,7 @@ import Store from 'electron-store' import MenuBuilder from './menu' import lnd from './lnd' import config from './lnd/config' +import { mainLog, lndLog, lndLogGetLevel } from './utils/log' let mainWindow = null @@ -44,7 +45,7 @@ const installExtensions = async () => { const forceDownload = !!process.env.UPGRADE_EXTENSIONS const extensions = ['REACT_DEVELOPER_TOOLS', 'REDUX_DEVTOOLS'] - return Promise.all(extensions.map(name => installer.default(installer[name], forceDownload))).catch(console.log) + return Promise.all(extensions.map(name => installer.default(installer[name], forceDownload))).catch(mainLog.error) } // Send the front end event letting them know the gRPC connection is disconnected @@ -68,7 +69,7 @@ const sendLndSyncing = () => { clearInterval(sendLndSyncingInterval) if (mainWindow) { - console.log('SENDING SYNCING') + mainLog.info('SENDING SYNCING') startedSync = true mainWindow.webContents.send('lndSyncing') } @@ -82,7 +83,7 @@ const sendStartOnboarding = () => { clearInterval(sendStartOnboardingInterval) if (mainWindow) { - console.log('STARTING ONBOARDING') + mainLog.info('STARTING ONBOARDING') mainWindow.webContents.send('startOnboarding') } } @@ -136,7 +137,7 @@ const sendLndSynced = () => { clearInterval(sendLndSyncedInterval) if (mainWindow) { - console.log('SENDING SYNCED') + mainLog.info('SENDING SYNCED') mainWindow.webContents.send('lndSynced') } } @@ -146,7 +147,12 @@ const sendLndSynced = () => { // Starts the LND node const startLnd = (alias, autopilot) => { const lndConfig = config.lnd() - console.log('lndConfig', lndConfig) + mainLog.info('STARTING BUNDLED LND') + mainLog.debug(' > lndPath', lndConfig.lndPath) + mainLog.debug(' > lightningRpc:', lndConfig.lightningRpc) + mainLog.debug(' > lightningHost:', lndConfig.lightningHost) + mainLog.debug(' > cert:', lndConfig.cert) + mainLog.debug(' > macaroon:', lndConfig.macaroon) const neutrinoArgs = [ '--bitcoin.active', @@ -161,31 +167,37 @@ const startLnd = (alias, autopilot) => { const neutrino = spawn(lndConfig.lndPath, neutrinoArgs) .on('error', (error) => { - console.log(`lnd error: ${error}`) + lndLog.error(`lnd error: ${error}`) dialog.showMessageBox({ type: 'error', message: `lnd error: ${error}` }) }) .on('close', (code) => { - console.log(`lnd shutting down ${code}`) + lndLog.info(`lnd shutting down ${code}`) app.quit() }) - // Listen for when neutrino prints out data + // Listen for when neutrino prints odata to stderr. + neutrino.stderr.pipe(split2()).on('data', (line) => { + if (process.env.NODE_ENV === 'development') { + lndLog[lndLogGetLevel(line)](line) + } + }) + + // Listen for when neutrino prints data to stdout. neutrino.stdout.pipe(split2()).on('data', (line) => { if (process.env.NODE_ENV === 'development') { - console.log(line) + lndLog[lndLogGetLevel(line)](line) } // If the gRPC proxy has started we can start ours if (line.includes('gRPC proxy started')) { const certInterval = setInterval(() => { - console.log('lndConfig', lndConfig) if (fs.existsSync(lndConfig.cert)) { clearInterval(certInterval) - console.log('CERT EXISTS, STARTING WALLET UNLOCKER') + mainLog.info('CERT EXISTS, STARTING WALLET UNLOCKER') startWalletUnlocker() if (mainWindow) { @@ -196,7 +208,7 @@ const startLnd = (alias, autopilot) => { } if (line.includes('gRPC proxy started') && !line.includes('password')) { - console.log('WALLET OPENED, STARTING LIGHTNING GRPC CONNECTION') + mainLog.info('WALLET OPENED, STARTING LIGHTNING GRPC CONNECTION') sendLndSyncing() startGrpc() } @@ -210,7 +222,7 @@ const startLnd = (alias, autopilot) => { // When LND is all caught up to the blockchain if (line.includes('Chain backend is fully synced')) { // Log that LND is caught up to the current block height - console.log('NEUTRINO IS SYNCED') + mainLog.info('NEUTRINO IS SYNCED') // Let the front end know we have stopped syncing LND sendLndSynced() @@ -272,7 +284,7 @@ app.on('ready', async () => { sendGrpcDisconnected() - console.log('LOOKING FOR LOCAL LND') + mainLog.info('LOOKING FOR EXISTING LND PROCESS') // Check to see if an LND process is running. lookup({ command: 'lnd' }, (err, results) => { // There was an error checking for the LND process. @@ -280,13 +292,14 @@ app.on('ready', async () => { throw new Error(err) } - // No LND process was found. if (!results.length) { + // An LND process was found, no need to start our own. + mainLog.info('EXISTING LND PROCESS NOT FOUND') // Let the application know onboarding has started. sendStartOnboarding() } else { // An LND process was found, no need to start our own. - console.log('LND ALREADY RUNNING') + mainLog.info('FOUND EXISTING LND PROCESS') startGrpc() mainWindow.webContents.send('successfullyCreatedWallet') } @@ -295,8 +308,6 @@ app.on('ready', async () => { // Start LND // once the onboarding has enough information, start or connect to LND. ipcMain.on('startLnd', (event, options = {}) => { - console.log('STARTING LND', options) - const store = new Store({ name: 'connection' }) store.store = { type: options.connectionType, @@ -307,12 +318,20 @@ app.on('ready', async () => { autopilot: options.autopilot } - console.log('SAVED CONFIG TO:', store.path, 'AS', store.store) + mainLog.info('GOT LND CONFIG') + mainLog.debug(' > connectionType:', options.connectionType) + mainLog.debug(' > connectionHost:', options.connectionHost) + mainLog.debug(' > connectionCert:', options.connectionCert) + mainLog.debug(' > connectionMacaroon:', options.connectionMacaroon) + mainLog.debug(' > alias:', options.alias) + mainLog.debug(' > autopilot:', options.autopilot) + + mainLog.info('SAVED LND CONFIG TO:', store.path) if (options.connectionType === 'local') { startLnd(options.alias, options.autopilot) } else { - console.log('USING CUSTOM LND') + mainLog.info('CONNECTING TO CUSTOM LND INSTANCE') startGrpc() mainWindow.webContents.send('successfullyCreatedWallet') } diff --git a/app/utils/log.js b/app/utils/log.js new file mode 100644 index 00000000..a64e4edc --- /dev/null +++ b/app/utils/log.js @@ -0,0 +1,78 @@ +import debugLogger from 'debug-logger' + +// Enable colours for object inspection. +debugLogger.inspectOptions = { + colors: true +} + +// Enable all zap logs if DEBUG has not been explicitly set. +if (!process.env.DEBUG) { + debugLogger.debug.enable('zap:*') +} + +// Method to configure a logger instance with a specific namespace suffix. +const logConfig = name => ({ + levels: { + trace: { + prefix: '[TRC] ', + namespaceSuffix: `:${name}` + }, + debug: { + prefix: '[DBG] ', + namespaceSuffix: `:${name}` + }, + log: { + prefix: '[LOG] ', + namespaceSuffix: `:${name}` + }, + info: { + prefix: '[INF] ', + namespaceSuffix: `:${name}` + }, + warn: { + prefix: '[WRN] ', + namespaceSuffix: `:${name}` + }, + error: { + prefix: '[ERR] ', + namespaceSuffix: `:${name}` + }, + critical: { + color: debugLogger.colors.magenta, + prefix: '[CRT] ', + namespaceSuffix: `:${name}`, + level: 6, + fd: 2 + } + } +}) + + +// Create 2 logs for use in the app. +export const mainLog = debugLogger.config(logConfig('main'))('zap') +export const lndLog = debugLogger.config(logConfig('lnd '))('zap') + +export const lndLogGetLevel = (msg) => { + // Define a mapping between log level prefixes and log level names. + const levelMap = { + TRC: 'trace', + DBG: 'debug', + INF: 'info', + WRN: 'warn', + ERR: 'error', + CRT: 'critical' + } + + // We set the default level to trace. + // The only log lines that don't include a level prefix are a part of trace entries + let level = 'trace' + + // Parse the log line to determine its level. + Object.entries(levelMap).forEach(([key, value]) => { + if (msg.includes(`[${key}]`)) { + level = value + } + }) + + return level +} diff --git a/package.json b/package.json index 351f720d..2b858a11 100644 --- a/package.json +++ b/package.json @@ -213,6 +213,7 @@ "d3-force": "^1.1.0", "d3-selection": "^1.2.0", "d3-zoom": "^1.7.1", + "debug-logger": "^0.4.1", "devtron": "^1.4.0", "electron": "1.8.4", "electron-debug": "^1.2.0", diff --git a/yarn.lock b/yarn.lock index 48d5bc1c..c03bce13 100644 --- a/yarn.lock +++ b/yarn.lock @@ -3236,6 +3236,12 @@ dateformat@^2.0.0: version "2.0.0" resolved "https://registry.yarnpkg.com/dateformat/-/dateformat-2.0.0.tgz#2743e3abb5c3fc2462e527dca445e04e9f4dee17" +debug-logger@^0.4.1: + version "0.4.1" + resolved "https://registry.yarnpkg.com/debug-logger/-/debug-logger-0.4.1.tgz#e33849c369e3cd361b50b299d71ca5224baa1ae1" + dependencies: + debug "^2.1.0" + debug@2.2.0, debug@~2.2.0: version "2.2.0" resolved "https://registry.yarnpkg.com/debug/-/debug-2.2.0.tgz#f87057e995b1a1f6ae6a4960664137bc56f039da" @@ -3254,7 +3260,7 @@ debug@2.6.8, debug@^2.1.1, debug@^2.4.5: dependencies: ms "2.0.0" -debug@2.6.9, debug@^2.1.2, debug@^2.1.3, debug@^2.2.0, debug@^2.3.3, debug@^2.6.6, debug@^2.6.8, debug@^2.6.9: +debug@2.6.9, debug@^2.1.0, debug@^2.1.2, debug@^2.1.3, debug@^2.2.0, debug@^2.3.3, debug@^2.6.6, debug@^2.6.8, debug@^2.6.9: version "2.6.9" resolved "https://registry.yarnpkg.com/debug/-/debug-2.6.9.tgz#5d128515df134ff327e90a4c93f4e077a536341f" dependencies: