faas/ix-server/logger.js

/*
Supports filtering call data for safe logging, for example to strip passwords
or credit card numbers.

Example usage: FAAS_IX_LOGGING_FILTER=./api/logging_filter.js ruby node_modules/faas/bin/faas-ix-server-ruby api/v0/

Contents of api/logging_filter.js:
----------------------------------

exports.filter = function(callData){
  if (callData.api === 'Api.V0.Auth.login') {
    callData.args[1] = '[REDACTED]'
  }
  return callData
}

exports.getKeyFilterRegexes = function(oldRegexes){
  oldRegexes.push(/name/)
  return oldRegexes
}

*/


var Util = require('util')
  , Path = require('path')
  , Base = require('../base')

var debug = Base.logger('ix-logging_filter')


var LOGGING_FILTER = null
var FILTERED_KEYS = [ /password/i ]


exports.loadFilter = function(callback){
  var filterPath = Base.env.IX_LOGGING_FILTER;
  if (filterPath) {
    console.log('Loading logging filter '+filterPath)
    try {
      LOGGING_FILTER = require(filterPath)
    }
    catch (e) {
      try {
        LOGGING_FILTER = require(Path.join(process.cwd(), filterPath))
      }
      catch (e2) {
        console.log("Unable to load logging filter from "+filterPath+": "+e2+ ' (working dir: '+process.cwd()+')')
      }
    }
  }
  if (LOGGING_FILTER && LOGGING_FILTER.getKeyFilterRegexes) {
    try {
      FILTERED_KEYS = LOGGING_FILTER.getKeyFilterRegexes(FILTERED_KEYS)
    }
    catch (e) {
      console.log('Error setting logging filters: '+e)
    }
  }
  callback()
}

exports.logCallRequest = function(callData){
  try {
    var filteredCall = filterCall(callData)
    console.log(JSON.stringify(filteredCall))
  }
  catch(e){}
}

var filterCall = function(callData){
  var filtered
  try {
    var startTime = (new Date()).getTime()
    // Deep-dup so that we don't modify the actual args.
    filtered = JSON.parse(JSON.stringify(callData))
    // Don't include startTime in the logged data.
    callData.ts = callData.ts || {}
    callData.ts.apiStart = startTime
    filteredArgs = filtered.args || []
    filteredArgs = filterDataHelper(filteredArgs)
    filtered.args = filteredArgs
    if (LOGGING_FILTER && LOGGING_FILTER.filter) {
      filtered = LOGGING_FILTER.filter(filtered)
    }
  }
  catch(e){
    console.log("Error in logging filter: "+e)
  }
  return filtered
}

exports.wrapResponder = function(callData, responder_err_data){
  return function(err, data){
    try {
      callData.ts.apiEnd = (new Date()).getTime()
      var duration = callData.ts.apiEnd - callData.ts.apiStart
      console.log(JSON.stringify({
        api: callData.api
        , duration: duration
        , responseType: err ? 'ERROR' : 'SUCCESS'
        , returnType: typeOf(err || data)
        , uuid: callData.req.uuid
      }))
    }
    catch(e){}
    responder_err_data(err, data)
  }
}

// http://stackoverflow.com/questions/472418/why-is-4-not-an-instance-of-number#472427
var typeOf = function(value){
  var type = typeof value;
  switch(type) {
  case 'object':
    return value === null ? 'null' : Object.prototype.toString.call(value).match(/^\[object (.*)\]$/)[1]
  case 'function':
    return 'Function';
  default:
    return type;
  }
}

var filterDataHelper = function(arg, prefix){
  var i, key
  var newPrefix, matched
  if (Util.isArray(arg)) {
    for (i = 0; i < arg.length; i++) {
      arg[i] = filterDataHelper(arg[i])
    }
  }
  else if (typeof arg === 'object') {
    for (key in arg) { if (arg.hasOwnProperty(key)) {
      newPrefix = prefix || ''
      if (newPrefix) { newPrefix += '.' }
      newPrefix = newPrefix + key
      matched = matchedFilter(newPrefix)
      if (matched) {
        arg[key] = '[FILTERED:'+matched+']'
      }
      else {
        arg[key] = filterDataHelper(arg[key], newPrefix)
      }
    } }
  }
  // else arg doesn't change.
  return arg
}

var matchedFilter = function(key){
  var i, re
  for (i = 0; i < FILTERED_KEYS.length; i++) {
    re = FILTERED_KEYS[i]
    if (key.match(re)) {
      return re
    }
  }
  return null
}


exports.logHttpRequest = function(faasReq){
  try {
    var startTime = (new Date()).getTime()
    faasReq.ts = faasReq.ts || {}
    faasReq.ts.requestStart = startTime
    console.log(JSON.stringify({
      uuid: faasReq.headers['x-faas-uuid'],
      ip: faasReq.headers['x-forwarded-for'].split(/\s*,\s*/)[0],
      type: 'request',
      method: faasReq.method,
      url: faasReq.origProto+'://'+faasReq.origHost+faasReq.url,
      contentLength: faasReq.headers['content-length'],
      userAgent: faasReq.headers['user-agent'],
      referer: faasReq.headers['referer'],
    }))
  }
  catch(e){}
}

exports.logHttpResponseStart = function(faasReq, response){
  try {
    faasReq.ts.responseStart = (new Date()).getTime()
    var timeDiff = faasReq.ts.responseStart - faasReq.ts.requestStart
    console.log(JSON.stringify({
      uuid: faasReq.headers['x-faas-uuid'],
      ip: faasReq.headers['x-forwarded-for'].split(/\s*,\s*/)[0],
      type: 'responseStart',
      method: faasReq.method,
      url: faasReq.origProto+'://'+faasReq.origHost+faasReq.url,
      contentType: response.headers && response.headers['content-type'],
      transferEncoding: response.headers && response.headers['transfer-encoding'],
      contentLength: response.headers && response.headers['content-length'],
      statusCode: response.statusCode,
      statusMessage: response.statusMessage,
      lag: timeDiff
    }))
  }
  catch(e){}
}

exports.logHttpResponseEnd = function(faasReq){
  try {
    faasReq.ts.responseEnd = (new Date()).getTime()
    var timeDiff = faasReq.ts.responseEnd - faasReq.ts.requestStart
    console.log(JSON.stringify({
      uuid: faasReq.headers['x-faas-uuid'],
      type: 'responseEnd',
      size: faasReq.responseBytes,
      duration: timeDiff
    }))
  }
  catch(e){}
}

exports.logHttpResponseError = function(faasReq){
  try {
    faasReq.ts.responseError = (new Date()).getTime()
    var timeDiff = faasReq.ts.responseError - faasReq.ts.requestStart
    console.log(JSON.stringify({
      uuid: faasReq.headers['x-faas-uuid'],
      type: 'responseError',
      size: faasReq.responseBytes,
      duration: timeDiff
    }))
  }
  catch(e){}
}