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

@@ -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')
     }

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
+}

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",

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: