chore(): more descriptive logging

Author: dszakallas

lib/instrumentations/core/http/request.js

@@ -30,10 +30,12 @@ function httpClient (originalHttpRequest, agent) {
       return originalHttpRequest.apply(this, arguments)
     }
 
+    var resource = util.formatDataUrl(requestParams.path)
+
     var cs = collector.clientSend({
       protocol: 'http',
       host: requestParams.host,
-      resource: util.formatDataUrl(requestParams.path),
+      resource: resource,
       action: requestParams.method
     }, {
       communication: communication,
@@ -63,13 +65,15 @@ function httpClient (originalHttpRequest, agent) {
     requestParams.headers['x-client-send'] = String(cs.duffelBag.timestamp)
     requestParams.headers['x-span-id'] = cs.duffelBag.communicationId
 
-    debug('#httpClient', format('CS(%s) [must-collect: %s]', csCtx.communicationId, mustCollect))
+    debug('#httpClient', format('CS(%s) [%s %s %s %s] [must-collect: %s]',
+      csCtx.communicationId, 'http', requestParams.method, resource,
+      requestParams.host, mustCollect))
 
     var returned = originalHttpRequest.apply(this, arguments)
 
     // returns with error
     returned.on('error', function (err) {
-      debug('#httpClient', format('CS(%s) network error: %s', csCtx.communicationId, err.code))
+      debug('#httpClient', format('NE(%s) [%s]', csCtx.communicationId, err.code))
       collector.networkError(cs.briefcase, err)
     })
 
@@ -90,11 +94,14 @@ function httpClient (originalHttpRequest, agent) {
         targetServiceKey: serviceKey
       }
 
-      debug('#httpClient', format('CR(%s) [severity: %s]', csCtx.communicationId, severity))
+      var status = incomingMessage.statusCode > 399 ? 'bad' : 'ok'
+
+      debug('#httpClient', format('CR(%s) [%s %s %s] [severity: %s]', csCtx.communicationId,
+        'http', status, incomingMessage.statusCode, severity))
 
       collector.clientRecv({
         protocol: 'http',
-        status: incomingMessage.statusCode > 399 ? 'bad' : 'ok',
+        status: status,
         data: {
           statusCode: incomingMessage.statusCode
         }

lib/instrumentations/core/http/server.js

@@ -3,6 +3,7 @@ var debug = require('debug')('risingstack/trace:agent:instrumentations')
 var Shimmer = require('../../../utils/shimmer')
 
 var util = require('./util')
+var format = require('util').format
 
 function isPathIgnored (ignorePaths, currentPath) {
   if (!ignorePaths || !ignorePaths.length) {
@@ -71,15 +72,21 @@ function httpServer (listener, agent) {
       timestamp: timestamp
     }
 
+    var resource = util.formatDataUrl(requestUrl)
+
     var payload = {
       host: headers.host,
       action: request.method,
-      resource: util.formatDataUrl(requestUrl),
+      resource: resource,
       protocol: 'http'
     }
 
     var sr = collector.serverRecv(payload, duffelBag)
 
+    debug('#httpServer', format('SR(%s) [%s %s %s %s] [must-collect: %s]',
+      sr.briefcase.communication.id, 'http', request.method, resource,
+      headers.host, !!headers['x-must-collect']))
+
     incomingEdgeMetrics.report({
       serviceKey: parentServiceKey,
       protocol: 'http',
@@ -106,21 +113,29 @@ function httpServer (listener, agent) {
             tracerBriefcase = sr.briefcase
           }
           var skipCollecting = isStatusCodeIgnored(ignoreStatusCodes, statusCode)
+          var status = statusCode >= 400 ? 'bad' : 'ok'
           var ss = collector.serverSend({
             protocol: 'http',
-            status: statusCode >= 400 ? 'bad' : 'ok',
+            status: status,
             data: {
               statusCode: statusCode
             }
           }, tracerBriefcase, { skip: skipCollecting })
+
+          var mustCollect = collector.LEVELS.gte(ss.duffelBag.severity, collector.mustCollectSeverity)
+
+          debug('#httpServer', format('SS(%s) [%s %s %s] [must-collect: %s]',
+            tracerBriefcase.communication && tracerBriefcase.communication.id, 'http', status, statusCode,
+            mustCollect))
+
           if (!ss.error) {
             if (ss.duffelBag.targetServiceKey != null) {
               response.setHeader('x-parent', String(ss.duffelBag.targetServiceKey))
             }
             if (ss.duffelBag.timestamp != null) {
               response.setHeader('x-server-send', String(ss.duffelBag.timestamp))
             }
-            if (collector.LEVELS.gte(ss.duffelBag.severity, collector.mustCollectSeverity)) {
+            if (mustCollect) {
               response.setHeader('x-must-collect', '1')
             }
           } else {

lib/instrumentations/utils/wrapQuery.js

@@ -1,6 +1,8 @@
 var microtime = require('../../optionalDependencies/microtime')
 var consts = require('../../consts')
 var EventEmitter = require('events')
+var debug = require('debug')('risingstack/trace:agent:instrumentations')
+var format = require('util').format
 
 function wrapQuery (original, args, agent, params) {
   var _params = params || {}
@@ -13,7 +15,8 @@ function wrapQuery (original, args, agent, params) {
       var briefcase = agent.storage.get('tracer.briefcase')
       var communication = briefcase && briefcase.communication
       var severity = briefcase && briefcase.severity
-      return agent.tracer.collector.clientSend({
+
+      var cs = agent.tracer.collector.clientSend({
         protocol: _params.protocol,
         action: _params.method,
         resource: _params.url,
@@ -23,12 +26,25 @@ function wrapQuery (original, args, agent, params) {
         communication: communication,
         severity: severity
       })
+
+      debug('#wrapQuery', format('CS(%s) [%s %s %s %s]',
+        cs.briefcase.csCtx.communicationId, _params.protocol,
+        _params.method, _params.url,
+        _params.host))
+
+      return cs
     },
+
     reportReceive: function (err, cs) {
       var severity = err
         ? collector.mustCollectSeverity
         : collector.defaultSeverity
 
+      var status = err ? 'bad' : 'ok'
+
+      debug('#wrapQuery', format('CR(%s) [%s %s] [severity: %s]',
+        cs.briefcase.csCtx.communicationId, _params.protocol, status, severity))
+
       collector.clientRecv({
         protocol: _params.protocol,
         status: err ? 'bad' : 'ok'

lib/trace.js

@@ -18,6 +18,7 @@ var traceNoop = {
 }
 
 function Trace (config) {
+  debug('#Trace', 'constructing with configuration', config)
   this._agent = Agent.create({
     config: config
   })