chore(): better debug logs

Author: dszakallas

lib/agent/api/index.js

@@ -3,7 +3,7 @@ var url = require('url')
 var util = require('util')
 var requestSync = require('sync-request')
 var isNumber = require('lodash.isnumber')
-var debug = require('debug')('risingstack/trace')
+var debug = require('debug')('risingstack/trace:agent:api')
 var assign = require('lodash.assign')
 var HttpsProxyAgent = require('https-proxy-agent')
 var stringify = require('json-stringify-safe')
@@ -38,7 +38,7 @@ function CollectorApi (options) {
 
 // USE THIS WITH CAUTION, IT WILL BE BLOCKING
 CollectorApi.prototype._sendSync = function (destinationUrl, data, options) {
-  debug('sending data to trace servers sync: ', stringify(data))
+  debug('#_sendSync', 'Sending data to ' + destinationUrl)
   try {
     requestSync('POST', destinationUrl, {
       json: data,
@@ -51,7 +51,7 @@ CollectorApi.prototype._sendSync = function (destinationUrl, data, options) {
       timeout: 1000
     })
   } catch (ex) {
-    debug('error sending data to trace servers sync: ', ex)
+    debug('#_sendSync', '[Error] Server responded with error', ex)
   }
 }
 
@@ -88,20 +88,18 @@ CollectorApi.prototype._send = function (destinationUrl, data, callback, options
     res.setEncoding('utf8')
     res.pipe(bl(function (err, result) {
       if (err) {
-        debug('There was an error when connecting to the Trace API', err)
+        debug('#_send', '[Error]', err)
         return
       }
-
       callback(null, result)
-      debug('HTTP Traces sent successfully')
     }))
   })
 
-  debug('sending data to trace servers: ', destinationUrl, payload)
+  debug('#_send', 'Sending data to ', destinationUrl)
 
   req.on('error', function (error) {
     console.error('error: [trace]', 'There was an error connecting to the Trace servers when sending data. Make sure your servers can reach', opts.hostname)
-    debug('error connecting to the Trace servers', error)
+    debug('#_send', '[Error] Connection error', error)
     callback(error)
   })
   req.write(payload)
@@ -110,7 +108,7 @@ CollectorApi.prototype._send = function (destinationUrl, data, callback, options
 
 CollectorApi.prototype.sendRpmMetrics = function (data) {
   if (!isNumber(this.serviceKey)) {
-    debug('Service id not present, cannot send rpm metrics')
+    debug('#sendRpmMetrics', '[Error] Service key not present, cannot send rpm metrics')
     return
   }
 
@@ -120,7 +118,7 @@ CollectorApi.prototype.sendRpmMetrics = function (data) {
 
 CollectorApi.prototype.ping = function () {
   if (!isNumber(this.serviceKey)) {
-    debug('Service id not present, cannot do healthcheck')
+    debug('#ping', '[Error] Service key not present, cannot do healthcheck')
     return
   }
 
@@ -130,7 +128,7 @@ CollectorApi.prototype.ping = function () {
 
 CollectorApi.prototype.sendApmMetrics = function (data) {
   if (!isNumber(this.serviceKey)) {
-    debug('Service id not present, cannot send metrics')
+    debug('#sendApmMetrics', '[Error] Service key not present, cannot send metrics')
     return
   }
 
@@ -140,7 +138,7 @@ CollectorApi.prototype.sendApmMetrics = function (data) {
 
 CollectorApi.prototype.sendMemorySnapshot = function (data, callback) {
   if (!isNumber(this.serviceKey)) {
-    debug('Service id not present, cannot send heapdump')
+    debug('#sendMemorySnapshot', '[Error] Service key not present, cannot send heapdump')
     return callback(new Error('serviceKey is missing'))
   }
 
@@ -150,7 +148,7 @@ CollectorApi.prototype.sendMemorySnapshot = function (data, callback) {
 
 CollectorApi.prototype.sendCpuProfile = function (data, callback) {
   if (!isNumber(this.serviceKey)) {
-    debug('Service id not present, cannot send cpu profile')
+    debug('#sendCpuProfile', '[Error] Service key not present, cannot send cpu profile')
     return callback(new Error('serviceKey is missing'))
   }
 
@@ -160,7 +158,7 @@ CollectorApi.prototype.sendCpuProfile = function (data, callback) {
 
 CollectorApi.prototype.sendExternalEdgeMetrics = function (data) {
   if (!isNumber(this.serviceKey)) {
-    debug('Service id not present, cannot send metrics')
+    debug('#sendExternalEdgeMetrics', '[Error] Service key not present, cannot send metrics')
     return
   }
 
@@ -170,7 +168,7 @@ CollectorApi.prototype.sendExternalEdgeMetrics = function (data) {
 
 CollectorApi.prototype.sendIncomingEdgeMetrics = function (data) {
   if (!isNumber(this.serviceKey)) {
-    debug('Service id not present, cannot send metrics')
+    debug('#sendIncomingEdgeMetrics', '[Error] Service key not present, cannot send metrics')
     return
   }
 
@@ -183,7 +181,7 @@ CollectorApi.prototype.sendIncomingEdgeMetrics = function (data) {
 
 CollectorApi.prototype.getUpdates = function (data, callback) {
   if (!isNumber(this.serviceKey)) {
-    debug('Service id not present, cannot get updates')
+    debug('#getUpdates', '[Error] Service key not present, cannot get updates')
     return
   }
 
@@ -206,7 +204,7 @@ CollectorApi.prototype.getUpdates = function (data, callback) {
 
 CollectorApi.prototype.sendCustomMetrics = function (data) {
   if (!isNumber(this.serviceKey)) {
-    debug('Service id not present, cannot send metrics')
+    debug('#sendCustomMetrics', '[Error] Service key not present, cannot send metrics')
     return
   }
 
@@ -222,14 +220,7 @@ CollectorApi.prototype.sendDependencies = function (dependencies) {
   this._send(url, dependencies)
 }
 
-CollectorApi.prototype._getRetryInterval = function () {
-  debug('retrying with %d ms', this.baseRetryInterval)
-  return this.baseRetryInterval
-}
-
 CollectorApi.prototype.getService = function (cb) {
-  debug('getting service id from the trace servers')
-
   var opts = url.parse(this.COLLECTOR_API_SERVICE)
   var _this = this
   cb = cb || function () {}
@@ -272,42 +263,49 @@ CollectorApi.prototype.getService = function (cb) {
     res.pipe(bl(function (err, resBuffer) {
       var response
 
+      var retryInterval = _this.baseRetryInterval
+
       if (err) {
-        debug('There was an error when connecting to the Trace API, retrying', err)
+        debug('#getService', '[Error]', err)
         return setTimeout(function () {
+          debug('#getService', 'Retrying with %d ms', retryInterval)
           _this.getService()
-        }, _this._getRetryInterval())
+        }, retryInterval)
       }
 
       var resText = resBuffer.toString('utf8')
 
-      debug('raw response from trace servers: ', resText)
       if (res.statusCode === 401) {
+        debug('#getService', '[Error] Api key rejected')
         return console.error('error: [trace]', 'Trace API key is rejected - are you sure you are using the right one?')
       }
       if (res.statusCode > 399) {
+        debug('#getService', '[Error] Service responded with', res.statusCode)
+        console.log(setTimeout)
+        console.log(retryInterval)
         return setTimeout(function () {
+          debug('#getService', 'Retrying with %d ms', retryInterval)
+          console.log('adsfsadf')
           _this.getService(cb)
-        }, _this._getRetryInterval())
+        }, retryInterval)
       }
 
       try {
         response = JSON.parse(resText)
       } catch (ex) {
-        debug('Error parsing JSON:', ex)
-        return debug(ex)
+        return
       }
 
       _this.serviceKey = response.key
       cb(null, response.key)
     }))
   })
 
-  debug('getting serviceKey with payload:', payload)
+  debug('#getService', 'Sending request')
 
   req.on('error', function (error) {
     console.error('error: [trace]', 'There was an error connecting to the Trace servers to get the service key. Make sure your servers can reach', opts.hostname)
-    debug('error connecting to the Trace servers', error)
+    debug('#getService', '[Error] error', error)
   })
   req.write(payload)
   req.end()

lib/agent/api/index.spec.js

@@ -198,7 +198,6 @@ describe('The Trace CollectorApi module', function () {
 
   it('retries on 409 error', function (done) {
     var collectorApi = CollectorApi.create(defaultConfig)
-    var _getRetryIntervalSpy = this.sandbox.spy(collectorApi, '_getRetryInterval')
 
     var data = {
       name: 'testName',
@@ -235,10 +234,12 @@ describe('The Trace CollectorApi module', function () {
 
     collectorApi.getService()
 
-    // FIXME: this is not nice, who can I test it better?
-    setTimeout(function () {
-      expect(_getRetryIntervalSpy).to.be.called
+    collectorApi.baseRetryInterval = 1
+
+    this.timeout(500)
+
+    this.sandbox.stub(collectorApi, 'getService', function () {
       done()
-    }, 100)
+    })
   })
 })

lib/agent/index.js

@@ -1,6 +1,6 @@
 var EventEmitter = require('events').EventEmitter
 
-var debug = require('debug')('risingstack/trace')
+var debug = require('debug')('risingstack/trace:agent')
 
 var CollectorApi = require('./api')
 var Tracer = require('./tracer')
@@ -15,56 +15,56 @@ var Storage = require('./storage')
 var controlBus = new EventEmitter()
 
 function Agent (options) {
-  debug('Agent is initializing...')
-  this._collectorApi = CollectorApi.create(options.config)
+  debug('#[constructor]', 'Initializing api client...')
+  this._api = CollectorApi.create(options.config)
   // config
   this.config = options.config
 
   this.apmMetrics = Metrics.apm.create({
-    collectorApi: this._collectorApi,
+    collectorApi: this._api,
     config: this.config
   })
 
   this.healthcheck = Healthcheck.create({
-    collectorApi: this._collectorApi,
+    collectorApi: this._api,
     config: this.config
   })
 
   this.rpmMetrics = Metrics.rpm.create({
-    collectorApi: this._collectorApi,
+    collectorApi: this._api,
     config: this.config
   })
 
   this.externalEdgeMetrics = Metrics.externalEdge.create({
-    collectorApi: this._collectorApi,
+    collectorApi: this._api,
     config: this.config
   })
 
   this.incomingEdgeMetrics = Metrics.incomingEdge.create({
-    collectorApi: this._collectorApi,
+    collectorApi: this._api,
     config: this.config
   })
 
   this.memoryProfiler = Profiler.memory.create({
-    collectorApi: this._collectorApi,
+    collectorApi: this._api,
     config: this.config,
     controlBus: controlBus
   })
 
   this.cpuProfiler = Profiler.cpu.create({
-    collectorApi: this._collectorApi,
+    collectorApi: this._api,
     config: this.config,
     controlBus: controlBus
   })
 
   this.control = Control.create({
-    collectorApi: this._collectorApi,
+    collectorApi: this._api,
     config: this.config,
     controlBus: controlBus
   })
 
   this.customMetrics = Metrics.customMetrics.create({
-    collectorApi: this._collectorApi,
+    collectorApi: this._api,
     config: this.config
   })
 
@@ -74,7 +74,7 @@ function Agent (options) {
   })
 
   this.tracer = Tracer.create({
-    collectorApi: this._collectorApi,
+    collectorApi: this._api,
     config: this.config
   })
 
@@ -96,35 +96,26 @@ function Agent (options) {
 
 Agent.prototype.start = function () {
   var self = this
-  this._collectorApi.getService(function (err, serviceKey) {
+  this._api.getService(function (err, serviceKey) {
     if (err) {
       return debug(err.message)
     }
-    debug('Agent serviceKey is set to: ', serviceKey)
+    debug('#start', 'ServiceKey is set to: ', serviceKey)
     self.serviceKey = serviceKey
+    debug('#start', 'Starting agents...')
     self.agents.forEach(function (agent) {
-      debug(agent.name + ' initialized')
       agent.initialize({ serviceKey: serviceKey })
+      agent.start()
+      debug('#start', agent.name + ' started')
     })
-    self._startAll()
   })
 }
 
 Agent.prototype.stop = function () {
-  this._stopAll()
-}
-
-Agent.prototype._startAll = function () {
-  this.agents.forEach(function (agent) {
-    debug(agent.name + ' started')
-    agent.start()
-  })
-}
-
-Agent.prototype._stopAll = function () {
+  debug('#stop', 'Stopping agents...')
   this.agents.forEach(function (agent) {
-    debug(agent.name + ' stopped')
     agent.stop()
+    debug('#stop', agent.name + ' stopped')
   })
 }
 

lib/agent/metrics/externalEdge/index.js

@@ -1,6 +1,5 @@
-var debug = require('debug')('risingstack/trace')
+var debug = require('debug')('risingstack/trace:agent:metrics:externalEdge')
 var flatMap = require('lodash.flatmap')
-var consts = require('../../../consts')
 
 var inherits = require('util').inherits
 var Agent = require('../../agent')
@@ -42,17 +41,17 @@ ExternalEdgeMetrics.prototype.report = function (data) {
   // protect against bad use of the report function: responseTime is required
   // TODO: check all instrumentations to be sure they send a responseTime
   if (!data.responseTime) {
-    debug('ExternalEdgeMetrics.report responseTime is undefined, discarding')
+    debug('#report', '[Error] ExternalEdgeMetrics.report responseTime is undefined, discarding')
     return
   }
   this.initProtocol(data)
   var edge = this.initHost(data)
 
   edge.responseTime.push(data.responseTime)
 
-  if (data.status === consts.EDGE_STATUS.OK) {
+  if (data.status === this.EDGE_STATUS.OK) {
     edge.status.ok += 1
-  } else if (data.status === consts.EDGE_STATUS.NOT_OK) {
+  } else if (data.status === this.EDGE_STATUS.NOT_OK) {
     edge.status.notOk += 1
   }
 }