Error Handling Best Practices

rest.bitcoin.com Error Handling

This issue is created to foster discussion on error handling best practices in the rest.bitcoin.com repository. The examples below use the output of a real debugging session. Spoiler alert: The error was a simple and common ECONNRESET error.

Here is an example of the current error handling for endpoint from rest.bitcoin.com/routes/dataRetrieval.js:

router.get("/info", config.dataRetrievalRateLimit9, async (req, res, next) => {
  requestConfig.data.id = "whc_getinfo"
  requestConfig.data.method = "whc_getinfo"
  requestConfig.data.params = []

  try {
    const response = await BitboxHTTP(requestConfig)
    res.json(response.data.result)
  } catch (error) {
    res.status(500).send(error.response.data.error)
  }
})

As along as the error.response.data.error exists, then it works fine, but there are many types of errors that do not fit this profile. When that happens, it causes an unhandled error exception inside the catch error handler. The output of such an error looks like this:

GET /v1/dataRetrieval/info - - ms - -
(node:17336) UnhandledPromiseRejectionWarning: TypeError: Cannot read property 'data' of undefined
    at router.get (/home/trout/work/bch/rest.bitcoin.com/routes/dataRetrieval.js:214:41)
    at process._tickCallback (internal/process/next_tick.js:68:7)
(node:17336) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). (rejection id: 2)
(node:17336) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.

Which is completely unhelpful when a system admin is reviewing logs to figure out what happened.

On the client side, the person running the BITBOX or Wormhole SDKs sees this:

TypeError: Cannot read property 'data' of undefined
    at DataRetrieval.info (/home/trout/work/bch/wormhole-sdk/lib/DataRetrieval.js:101:30)
    at process._tickCallback (internal/process/next_tick.js:68:7)

Which is again, not helpful at all.

Here is my suggestion for improving this error handling:

const util = require("util")
util.inspect.defaultOptions = {depth: 1}

router.get("/info", config.dataRetrievalRateLimit9, async (req, res, next) => {
  requestConfig.data.id = "whc_getinfo"
  requestConfig.data.method = "whc_getinfo"
  requestConfig.data.params = []

  try {
    const response = await BitboxHTTP(requestConfig)
    res.json(response.data.result)
  } catch (error) {
    res.status(500)
    if(error.response && error.response.data && error.response.data.error)
      res.send(error.response.data.error)
    res.send(util.inspect(error))
  }
})

The util.inspect() function is very similar to JSON.stringify(), except that it can handle circular data structures, whereas JSON.stringify() cannot. Without wrapping the error in util.inspect(), trying to pass the error from the server to the client may fail.

The above code keeps the intended use case while preventing an exception error by validating the expected object error.response.data.error. If the error does not match that expected profile, it's stringified and returned to the client. Either way, the error gets a status code of 500.

That code change now results in the following error message in the server logs:

GET /v1/dataRetrieval/info - - ms - -

Which is pretty terse, but good for a console write. If we implemented Winston for debug logging, we could update the catch handler like this:

} catch (error) {
  res.status(500)
  if(error.response && error.response.data && error.response.data.error)
    res.send(error.response.data.error)
  res.send(util.inspect(error))

  logger.debug(util.inspect(error))
}

Which would result in the debug log showing the following error message, along with a timestamp (assuming we add timestamps to Winston):

{ Error: connect ETIMEDOUT 194.14.247.132:8332
    at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1113:14)
  errno: 'ETIMEDOUT',
  code: 'ETIMEDOUT',
  syscall: 'connect',
  address: '194.14.247.132',
  port: 8332,
  config:
   { adapter: [Function: httpAdapter],
     transformRequest: [Object],
     transformResponse: [Object],
     timeout: 0,
     xsrfCookieName: 'XSRF-TOKEN',
     xsrfHeaderName: 'X-XSRF-TOKEN',
     maxContentLength: -1,
     validateStatus: [Function: validateStatus],
     headers: [Object],
     method: 'post',
     baseURL: 'http://194.14.247.132:8332/',
     auth: [Object],
     data:
      '{"jsonrpc":"1.0","id":"whc_getinfo","method":"whc_getinfo","params":[]}',
     url: 'http://194.14.247.132:8332/' },
  request:
   Writable {
     _writableState: [WritableState],
     writable: true,
     _events: [Object],
     _eventsCount: 2,
     _maxListeners: undefined,
     _options: [Object],
     _redirectCount: 0,
     _redirects: [],
     _requestBodyLength: 71,
     _requestBodyBuffers: [Array],
     _onNativeResponse: [Function],
     _currentRequest: [ClientRequest],
     _currentUrl:
      'http://bitcoin:POIiowhebsgowoeiioppoIPIPPOPOUoiutoiwetoiht@194.14.247.132:8332/' },
  response: undefined }

Which is an informative, if verbose, output that is great to put into a debug log.

Bitcoin-com / rest.bitcoin.com

Error Handling Best Practices #29

rest.bitcoin.com Error Handling