Merge pull request #177 from shocknet/feature/graceful-lnd

error manager

package.json

@@ -48,7 +48,7 @@
     "request-promise": "^4.2.2",
     "response-time": "^2.3.2",
     "shelljs": "^0.8.2",
-    "shock-common": "6.0.0",
+    "shock-common": "8.0.0",
     "socket.io": "2.1.1",
     "text-encoding": "^0.7.0",
     "tingodb": "^0.6.1",

services/gunDB/contact-api/jobs/onOrders.js

@@ -30,8 +30,35 @@ const ordersProcessed = new Set()
  * @typedef {import('../SimpleGUN').UserGUNNode} UserGUNNode
  */
 
+/**
+ * @typedef {object} InvoiceRequest
+ * @prop {number} expiry
+ * @prop {string} memo
+ * @prop {number} value
+ * @prop {boolean} private
+ */
+
 let currentOrderAddr = ''
 
+/** @param {InvoiceRequest} invoiceReq */
+const _addInvoice = invoiceReq =>
+  new Promise((resolve, rej) => {
+    const {
+      services: { lightning }
+    } = LightningServices
+
+    lightning.addInvoice(invoiceReq, (
+      /** @type {any} */ error,
+      /** @type {{ payment_request: string }} */ response
+    ) => {
+      if (error) {
+        rej(error)
+      } else {
+        resolve(response.payment_request)
+      }
+    })
+  })
+
 /**
  * @param {string} addr
  * @param {ISEA} SEA
@@ -58,6 +85,8 @@ const listenerForAddr = (addr, SEA) => async (order, orderID) => {
       return
     }
 
+    const listenerStartTime = Date.now()
+
     ordersProcessed.add(orderID)
 
     logger.info(
@@ -66,20 +95,35 @@ const listenerForAddr = (addr, SEA) => async (order, orderID) => {
       )} -- addr: ${addr}`
     )
 
-    const alreadyAnswered = getUser()
+    const orderAnswerStartTime = Date.now()
+
+    const alreadyAnswered = await getUser()
       .get(Key.ORDER_TO_RESPONSE)
       .get(orderID)
       .then()
 
-    if (await alreadyAnswered) {
+    if (alreadyAnswered) {
       logger.info('this order is already answered, quitting')
       return
     }
 
+    const orderAnswerEndTime = Date.now() - orderAnswerStartTime
+
+    logger.info(`[PERF] Order Already Answered: ${orderAnswerEndTime}ms`)
+
+    const decryptStartTime = Date.now()
+
     const senderEpub = await Utils.pubToEpub(order.from)
     const secret = await SEA.secret(senderEpub, getUser()._.sea)
 
-    const decryptedAmount = await SEA.decrypt(order.amount, secret)
+    const [decryptedAmount, memo] = await Promise.all([
+      SEA.decrypt(order.amount, secret),
+      SEA.decrypt(order.memo, secret)
+    ])
+
+    const decryptEndTime = Date.now() - decryptStartTime
+
+    logger.info(`[PERF] Decrypt invoice info: ${decryptEndTime}ms`)
 
     const amount = Number(decryptedAmount)
 
@@ -101,8 +145,6 @@ const listenerForAddr = (addr, SEA) => async (order, orderID) => {
       )
     }
 
-    const memo = await SEA.decrypt(order.memo, secret)
-
     const invoiceReq = {
       expiry: 36000,
       memo,
@@ -114,32 +156,29 @@ const listenerForAddr = (addr, SEA) => async (order, orderID) => {
       `onOrders() -> Will now create an invoice : ${JSON.stringify(invoiceReq)}`
     )
 
+    const invoiceStartTime = Date.now()
+
     /**
      * @type {string}
      */
-    const invoice = await new Promise((resolve, rej) => {
+    const invoice = await _addInvoice(invoiceReq)
-      const {
-        services: { lightning }
-      } = LightningServices
 
-      lightning.addInvoice(invoiceReq, (
+    const invoiceEndTime = Date.now() - invoiceStartTime
-        /** @type {any} */ error,
+
-        /** @type {{ payment_request: string }} */ response
+    logger.info(`[PERF] LND Invoice created in ${invoiceEndTime}ms`)
-      ) => {
-        if (error) {
-          rej(error)
-        } else {
-          resolve(response.payment_request)
-        }
-      })
-    })
 
     logger.info(
       'onOrders() -> Successfully created the invoice, will now encrypt it'
     )
 
+    const invoiceEncryptStartTime = Date.now()
+
     const encInvoice = await SEA.encrypt(invoice, secret)
 
+    const invoiceEncryptEndTime = Date.now() - invoiceEncryptStartTime
+
+    logger.info(`[PERF] Invoice encrypted in ${invoiceEncryptEndTime}ms`)
+
     logger.info(
       `onOrders() -> Will now place the encrypted invoice in order to response usergraph: ${addr}`
     )
@@ -150,11 +189,12 @@ const listenerForAddr = (addr, SEA) => async (order, orderID) => {
       type: 'invoice'
     }
 
+    const invoicePutStartTime = Date.now()
+
     await new Promise((res, rej) => {
       getUser()
         .get(Key.ORDER_TO_RESPONSE)
         .get(orderID)
-        //@ts-ignore
         .put(orderResponse, ack => {
           if (ack.err && typeof ack.err !== 'number') {
             rej(
@@ -167,6 +207,14 @@ const listenerForAddr = (addr, SEA) => async (order, orderID) => {
           }
         })
     })
+
+    const invoicePutEndTime = Date.now() - invoicePutStartTime
+
+    logger.info(`[PERF] Added invoice to GunDB in ${invoicePutEndTime}ms`)
+
+    const listenerEndTime = Date.now() - listenerStartTime
+
+    logger.info(`[PERF] Invoice generation completed in ${listenerEndTime}ms`)
   } catch (err) {
     logger.error(
       `error inside onOrders, orderAddr: ${addr}, orderID: ${orderID}, order: ${JSON.stringify(
@@ -184,7 +232,6 @@ const listenerForAddr = (addr, SEA) => async (order, orderID) => {
     getUser()
       .get(Key.ORDER_TO_RESPONSE)
       .get(orderID)
-      //@ts-ignore
       .put(orderResponse, ack => {
         if (ack.err && typeof ack.err !== 'number') {
           logger.error(

src/routes.js

@@ -21,6 +21,7 @@ const auth = require('../services/auth/auth')
 const FS = require('../utils/fs')
 const Encryption = require('../utils/encryptionStore')
 const LightningServices = require('../utils/lightningServices')
+const lndErrorManager = require('../utils/lightningServices/errors')
 const GunDB = require('../services/gunDB/Mediator')
 const {
   unprotectedRoutes,
@@ -63,7 +64,10 @@ module.exports = async (
     return message
   }
 
-  const getAvailableService = () =>
+  const getAvailableService = () => {
+    return lndErrorManager.getAvailableService()
+  }
+  /*
     new Promise((resolve, reject) => {
       const { lightning } = LightningServices.services
 
@@ -105,13 +109,22 @@ module.exports = async (
           success: true
         })
       })
-    })
+    })*/
 
   const checkHealth = async () => {
     logger.info('Getting service status...')
-    const serviceStatus = await getAvailableService()
+    let LNDStatus = {}
-    logger.info('Received status:', serviceStatus)
+    try {
-    const LNDStatus = serviceStatus
+      const serviceStatus = await getAvailableService()
+      logger.info('Received status:', serviceStatus)
+      LNDStatus = serviceStatus
+    } catch (e) {
+      LNDStatus = {
+        message: e.message,
+        success: false
+      }
+    }
+
     try {
       logger.info('Getting API status...')
       const APIHealth = await Http.get(
@@ -367,14 +380,31 @@ module.exports = async (
         const walletStatus = await walletExists()
         const availableService = await getAvailableService()
         const statusMessage = availableService.walletStatus
+        if (availableService.code === 12) {
+          return res.status(401).json({
+            field: 'lnd_locked',
+            errorMessage: availableService.message
+              ? availableService.message
+              : 'unknown'
+          })
+        }
+        if (availableService.code === 14) {
+          return res.status(401).json({
+            field: 'lnd_dead',
+            errorMessage: availableService.message
+              ? availableService.message
+              : 'unknown'
+          })
+        }
         if (walletStatus) {
           if (statusMessage === 'unlocked') {
             return next()
           }
-
           return res.status(401).json({
             field: 'wallet',
-            errorMessage: statusMessage ? statusMessage : 'unknown'
+            errorMessage: availableService.message
+              ? availableService.message
+              : 'unknown'
           })
         }
 
@@ -386,6 +416,18 @@ module.exports = async (
       next()
     } catch (err) {
       logger.error(err)
+      if (err.code === 12) {
+        return res.status(401).json({
+          field: 'lnd_locked',
+          errorMessage: err.message ? err.message : 'unknown'
+        })
+      }
+      if (err.code === 14) {
+        return res.status(401).json({
+          field: 'lnd_dead',
+          errorMessage: err.message ? err.message : 'unknown'
+        })
+      }
       res.status(500).json({
         field: 'wallet',
         errorMessage: err.message ? err.message : err
@@ -589,17 +631,46 @@ module.exports = async (
           stream.on('end', () => {
             logger.info('Channel backup stream ended, starting a new one...')
             // Prevents call stack overflow exceptions
-            process.nextTick(onNewChannelBackup)
+            //process.nextTick(onNewChannelBackup)
           })
           stream.on('error', err => {
             logger.error('Channel backup stream error:', err)
           })
           stream.on('status', status => {
-            if (status.code === 14) {
+            logger.error('Channel backup stream status:', status)
-              // Prevents call stack overflow exceptions
+            switch (status.code) {
-              process.nextTick(() => setTimeout(onNewChannelBackup, 30000))
+              case 0: {
-            } else {
+                logger.info('Channel backup stream ok')
-              logger.error('Channel backup stream status:', status)
+                break
+              }
+              case 2: {
+                //Happens to fire when the grpc client lose access to macaroon file
+                logger.warn('Channel backup got UNKNOWN error status')
+                break
+              }
+              case 12: {
+                logger.warn(
+                  'Channel backup LND locked, new registration in 60 seconds'
+                )
+                process.nextTick(() =>
+                  setTimeout(() => onNewTransaction(socket, subID), 60000)
+                )
+                break
+              }
+              case 13: {
+                //https://grpc.github.io/grpc/core/md_doc_statuscodes.html
+                logger.error('Channel backup INTERNAL LND error')
+                break
+              }
+              case 14: {
+                logger.error(
+                  'Channel backup LND disconnected, sockets reconnecting in 30 seconds...'
+                )
+                process.nextTick(() =>
+                  setTimeout(() => onNewTransaction(socket, subID), 30000)
+                )
+                break
+              }
             }
           })
         }

src/sockets.js

@@ -111,9 +111,9 @@ module.exports = (
     }
   }
 
-  const onNewInvoice = socket => {
+  const onNewInvoice = (socket, subID) => {
     const { lightning } = LightningServices.services
-    logger.warn('Subscribing to invoices socket...')
+    logger.warn('Subscribing to invoices socket...' + subID)
     const stream = lightning.subscribeInvoices({})
     stream.on('data', data => {
       logger.info('[SOCKET] New invoice data:', data)
@@ -122,49 +122,107 @@ module.exports = (
     stream.on('end', () => {
       logger.info('New invoice stream ended, starting a new one...')
       // Prevents call stack overflow exceptions
-      process.nextTick(() => onNewInvoice(socket))
+      //process.nextTick(() => onNewInvoice(socket))
     })
     stream.on('error', err => {
-      logger.error('New invoice stream error:', err)
+      logger.error('New invoice stream error:' + subID, err)
     })
     stream.on('status', status => {
-      logger.warn('New invoice stream status:', status)
+      logger.warn('New invoice stream status:' + subID, status)
-      if (status.code === 14) {
+      switch (status.code) {
-        // Prevents call stack overflow exceptions
+        case 0: {
-        logger.error(
+          logger.info('[event:invoice:new] stream ok')
-          '[event:invoice:new] LND disconnected, sockets reconnecting in 30 seconds...'
+          break
-        )
+        }
-        process.nextTick(() => setTimeout(() => onNewInvoice(socket), 30000))
+        case 2: {
+          logger.warn('[event:invoice:new] got UNKNOWN error status')
+          break
+        }
+        case 12: {
+          logger.warn(
+            '[event:invoice:new] LND locked, new registration in 60 seconds'
+          )
+          process.nextTick(() =>
+            setTimeout(() => onNewInvoice(socket, subID), 60000)
+          )
+          break
+        }
+        case 13: {
+          //https://grpc.github.io/grpc/core/md_doc_statuscodes.html
+          logger.error('[event:invoice:new] INTERNAL LND error')
+          break
+        }
+        case 14: {
+          logger.error(
+            '[event:invoice:new] LND disconnected, sockets reconnecting in 30 seconds...'
+          )
+          process.nextTick(() =>
+            setTimeout(() => onNewInvoice(socket, subID), 30000)
+          )
+          break
+        }
       }
     })
+    return () => {
+      stream.cancel()
+    }
   }
 
-  const onNewTransaction = socket => {
+  const onNewTransaction = (socket, subID) => {
     const { lightning } = LightningServices.services
     const stream = lightning.subscribeTransactions({})
-    logger.warn('Subscribing to transactions socket...')
+    logger.warn('Subscribing to transactions socket...' + subID)
     stream.on('data', data => {
       logger.info('[SOCKET] New transaction data:', data)
       emitEncryptedEvent({ eventName: 'transaction:new', data, socket })
     })
     stream.on('end', () => {
-      logger.info('New invoice stream ended, starting a new one...')
+      logger.info('New transactions stream ended, starting a new one...')
-      process.nextTick(() => onNewTransaction(socket))
+      //process.nextTick(() => onNewTransaction(socket))
     })
     stream.on('error', err => {
-      logger.error('New invoice stream error:', err)
+      logger.error('New transactions stream error:' + subID, err)
     })
     stream.on('status', status => {
-      logger.error('New invoice stream status:', status)
+      logger.error('New transactions stream status:' + subID, status)
-      if (status.code === 14) {
+      switch (status.code) {
-        logger.error(
+        case 0: {
-          '[event:transaction:new] LND disconnected, sockets reconnecting in 30 seconds...'
+          logger.info('[event:transaction:new] stream ok')
-        )
+          break
-        process.nextTick(() =>
+        }
-          setTimeout(() => onNewTransaction(socket), 30000)
+        case 2: {
-        )
+          //Happens to fire when the grpc client lose access to macaroon file
+          logger.warn('[event:transaction:new] got UNKNOWN error status')
+          break
+        }
+        case 12: {
+          logger.warn(
+            '[event:transaction:new] LND locked, new registration in 60 seconds'
+          )
+          process.nextTick(() =>
+            setTimeout(() => onNewTransaction(socket, subID), 60000)
+          )
+          break
+        }
+        case 13: {
+          //https://grpc.github.io/grpc/core/md_doc_statuscodes.html
+          logger.error('[event:transaction:new] INTERNAL LND error')
+          break
+        }
+        case 14: {
+          logger.error(
+            '[event:transaction:new] LND disconnected, sockets reconnecting in 30 seconds...'
+          )
+          process.nextTick(() =>
+            setTimeout(() => onNewTransaction(socket, subID), 30000)
+          )
+          break
+        }
       }
     })
+    return () => {
+      stream.cancel()
+    }
   }
 
   io.on('connection', socket => {
@@ -174,6 +232,8 @@ module.exports = (
 
     const isOneTimeUseSocket = !!socket.handshake.query.IS_GUN_AUTH
     const isLNDSocket = !!socket.handshake.query.IS_LND_SOCKET
+    const isNotificationsSocket = !!socket.handshake.query
+      .IS_NOTIFICATIONS_SOCKET
     if (!isLNDSocket) {
       /** printing out the client who joined */
       logger.info('New socket client connected (id=' + socket.id + ').')
@@ -203,9 +263,16 @@ module.exports = (
       })
     } else {
       if (isLNDSocket) {
-        logger.info('[LND] New LND Socket created')
+        const subID = Math.floor(Math.random() * 1000).toString()
-        onNewInvoice(socket)
+        const isNotifications = isNotificationsSocket ? 'notifications' : ''
-        onNewTransaction(socket)
+        logger.info('[LND] New LND Socket created:' + isNotifications + subID)
+        const cancelInvoiceStream = onNewInvoice(socket, subID)
+        const cancelTransactionStream = onNewTransaction(socket, subID)
+        socket.on('disconnect', () => {
+          logger.info('LND socket disconnected:' + isNotifications + subID)
+          cancelInvoiceStream()
+          cancelTransactionStream()
+        })
         return
       }
       logger.info('New socket is NOT one time use')

utils/lightningServices/errors.js

@@ -0,0 +1,152 @@
+
+const LightningServices = require('./lightning-services')
+
+/**
+ * @typedef {{
+ * code:number,
+ * details:string,
+ * message:string
+ * }} LNDError 
+ */
+
+/**
+ * @typedef {(err:LNDError,response:object)=>void} HealthListener 
+ */
+
+class LNDErrorManager {
+
+  /**
+   * @type {boolean}
+   */
+  _isCheckingHealth = false
+
+  /**
+   * @type {HealthListener[]}
+   */
+  _healthListeners = []
+
+  //rejects if(err && err.code !== 12)  
+  getAvailableService(){
+    
+    //require('shock-common').Utils.makePromise((res, rej) => ...)
+    return new Promise((res,rej)=>{
+      if(!this._isCheckingHealth){
+        this._isCheckingHealth = true
+        this.getInfo()
+      }
+      /**
+       * 
+       * @param {LNDError} err 
+       * @param {object} response 
+       */
+      const listener = (err,response)=>{
+        if (err) {
+          if (err.code === 12) {
+            res({
+              service: 'walletUnlocker',
+              message: 'Wallet locked',
+              code: err.code,
+              walletStatus: 'locked',
+              success: true
+            })
+          } else if (err.code === 14) {
+            rej({
+              service: 'unknown',
+              message:
+                "Failed to connect to LND server, make sure it's up and running.",
+              code: 14,
+              walletStatus: 'unknown',
+              success: false
+            })
+          } else if(err.code === 4){
+            rej({
+              service: 'unknown',
+              message:
+                "LND Timeout",
+              code: 4,
+              walletStatus: 'unknown',
+              success: false
+            })
+          } else {
+            rej({
+              service: 'lightning',
+              message: this.sanitizeLNDError(err),
+              code: err.code,
+              walletStatus: 'unlocked',
+              success: false
+            })
+          }
+        }
+  
+        res({
+          service: 'lightning',
+          message: response,
+          code: null,
+          walletStatus: 'unlocked',
+          success: true
+        })
+        
+      }
+      this._healthListeners.push(listener)
+    })
+
+  }
+
+  //private
+  getInfo(){
+    const { lightning } = LightningServices.services
+    /**
+     * 
+     * @param {LNDError} err 
+     * @param {object} response 
+     */
+    const callback = (err, response) => {
+      this._healthListeners.forEach(l =>{
+        l(err,response)
+      })
+      this._healthListeners.length = 0
+      this._isCheckingHealth = false
+    }
+    const deadline = Date.now() + 4000
+    lightning.getInfo({},{deadline}, callback)
+  }
+
+  /**
+   * @param {LNDError} e 
+   */
+  handleError(e){
+    return this.sanitizeLNDError(e)
+  }
+
+  /**
+   * @param {LNDError} e 
+   */
+  // eslint-disable-next-line
+  sanitizeLNDError(e){
+    let eMessage = ''
+    if(typeof e === 'string'){
+      eMessage = e
+    }else if(e.details){
+      eMessage = e.details
+    } else if(e.message){
+      eMessage = e.message
+    }
+    if (eMessage.toLowerCase().includes('unknown')) {
+      const splittedMessage = eMessage.split('UNKNOWN: ')
+      return splittedMessage.length > 1
+        ? splittedMessage.slice(1).join('')
+        : splittedMessage.join('')
+    }
+    if(eMessage === ''){
+      return 'unknown LND error'
+    }
+    return eMessage
+  }
+
+  
+}
+
+
+const lndErrorManager = new LNDErrorManager()
+
+module.exports = lndErrorManager

yarn.lock

@@ -6021,10 +6021,10 @@ shellwords@^0.1.1:
   resolved "https://registry.yarnpkg.com/shellwords/-/shellwords-0.1.1.tgz#d6b9181c1a48d397324c84871efbcfc73fc0654b"
   integrity sha512-vFwSUfQvqybiICwZY5+DAWIPLKsWO31Q91JSKl3UYv+K5c2QRPzn0qzec6QPu1Qc9eHYItiP3NdJqNVqetYAww==
 
-shock-common@6.0.0:
+shock-common@8.0.0:
-  version "6.0.0"
+  version "8.0.0"
-  resolved "https://registry.yarnpkg.com/shock-common/-/shock-common-6.0.0.tgz#77701dabb344830046b85ece0103de21775197b9"
+  resolved "https://registry.yarnpkg.com/shock-common/-/shock-common-8.0.0.tgz#4dbc8c917adfb221a00b6d1e815c4d26d205ce66"
-  integrity sha512-kbSkLTtWTK8qVcbW6uViWtar3otW2S5oJIMO/1twPs6Iuv9ATF0QviDtUiU1YN/Y4bX/SXAMm/jRZ3OJ3PLyUA==
+  integrity sha512-X9jkSxNUjQOcVdEAGBl6dlBgBxF9MpjV50Cih4hoqLqeGfrAYHK/iqgXgDyaHkLraHRxdP6FWJ2DoWOpuBgpDQ==
   dependencies:
     immer "^6.0.6"
     lodash "^4.17.19"