Merge branch 'master' into trentm/run-context-memcached

.tav.yml

@@ -326,11 +326,20 @@ elasticsearch:
 handlebars:
   versions: '*'
   commands: node test/instrumentation/modules/handlebars.test.js
+# jade is a dead package. It was renamed to 'pug' in 2015 and hasn't had a
+# release since. Testing all 144 releases that match '>0.5.5' (the first
+# release APM supported) is a waste of time. Instead we will test the first
+# supported and the last released versions.
 jade:
-  versions: '>0.5.5'
+  versions: '0.5.6 || 1.11.0 || >1.11.0'
   commands: node test/instrumentation/modules/jade.test.js
+# Pug v3 dropped node v8 support (https://github.com/pugjs/pug/releases/tag/pug%403.0.0).
+pug-v2:
+  versions: '0.1.0 || >2.0.0 <3.0.0'
+  commands: node test/instrumentation/modules/pug.test.js
 pug:
-  versions: '0.1.0 || >2.0.0'
+  versions: '>=3.0.0'
+  node: '>8'
   commands: node test/instrumentation/modules/pug.test.js
 
 # hapi and @hapi/hapi

CHANGELOG.asciidoc

@@ -43,6 +43,16 @@ Notes:
   automatically created Memcached span is never the `currentSpan` in user
   code.
 
+* Fix a possible crash when serializing a Transaction if the incoming
+  `req.socket` is null (possible if the socket has been destroyed).
+  ({issues}2479[#2479])
+
+* Fixes for run context handling for 'aws-sdk' instrumentation (S3, SQS, SNS)
+  so that a span created after an AWS client command (in the same tick, in
+  the command callback, or promise) is not a child of the automatic AWS
+  span. This change also ensures captured errors from failing client commands
+  are a child of the AWS span.
+
 * Fix 'http' and 'https' instrumentation for outgoing requests to not have the
   'http' span context be active in user code. ({pull}2470[#2470])
 

examples/trace-handlebars.js

@@ -0,0 +1,22 @@
+#!/usr/bin/env node
+
+// A small example showing Elastic APM tracing the 'handlebars' package.
+
+const apm = require('../').start({ // elastic-apm-node
+  serviceName: 'example-trace-handlebars'
+})
+
+const handlebars = require('handlebars')
+
+// For tracing spans to be created, there must be an active transaction.
+// Typically, a transaction is automatically started for incoming HTTP
+// requests to a Node.js server. However, because this script is not running
+// an HTTP server, we manually start a transaction. More details at:
+// https://www.elastic.co/guide/en/apm/agent/nodejs/current/custom-transactions.html
+const t1 = apm.startTransaction('t1')
+
+var template = handlebars.compile('Hello, {{name}}!')
+console.log(template({ name: 'world' }))
+console.log(template({ name: 'Bob' }))
+
+t1.end()

examples/trace-pug.js

@@ -0,0 +1,22 @@
+#!/usr/bin/env node
+
+// A small example showing Elastic APM tracing the 'pug' package.
+
+const apm = require('../').start({ // elastic-apm-node
+  serviceName: 'example-trace-pug'
+})
+
+const pug = require('pug')
+
+// For tracing spans to be created, there must be an active transaction.
+// Typically, a transaction is automatically started for incoming HTTP
+// requests to a Node.js server. However, because this script is not running
+// an HTTP server, we manually start a transaction. More details at:
+// https://www.elastic.co/guide/en/apm/agent/nodejs/current/custom-transactions.html
+const t1 = apm.startTransaction('t1')
+
+var template = pug.compile('p Hello, #{name}!')
+console.log(template({ name: 'world' }))
+console.log(template({ name: 'Bob' }))
+
+t1.end()

lib/instrumentation/modules/aws-sdk/s3.js

@@ -54,11 +54,6 @@ function instrumentationS3 (orig, origArguments, request, AWS, agent, { version,
 
   const ins = agent._instrumentation
 
-  // `instrumentationS3` is called *synchronously* for an S3 client method call.
-  // We must use `ins.createSpan` rather than `ins.startSpan`, otherwise we
-  // would impact apm.currentSpan in the calling code. For example:
-  //      s3Client.listBuckets({}, function (...) { ... })
-  //      // The "S3 ListBuckets" span should *not* be apm.currentSpan here.
   const span = ins.createSpan(name, TYPE, SUBTYPE, opName)
   if (!span) {
     return orig.apply(request, origArguments)

lib/instrumentation/modules/aws-sdk/sns.js

@@ -1,4 +1,4 @@
-const constants = require('../../../constants')
+'use strict'
 
 const TYPE = 'messaging'
 const SUBTYPE = 'sns'
@@ -105,36 +105,37 @@ function shouldIgnoreRequest (request, agent) {
 }
 
 function instrumentationSns (orig, origArguments, request, AWS, agent, { version, enabled }) {
-  const type = TYPE
-  const subtype = SUBTYPE
-  const action = ACTION
-
   if (shouldIgnoreRequest(request, agent)) {
     return orig.apply(request, origArguments)
   }
 
+  const ins = agent._instrumentation
   const name = getSpanNameFromRequest(request)
-  const span = agent.startSpan(name, type, subtype, action)
+  const span = ins.createSpan(name, TYPE, SUBTYPE, ACTION)
   if (!span) {
     return orig.apply(request, origArguments)
   }
 
   span.setDestinationContext(getMessageDestinationContextFromRequest(request))
   span.setMessageContext(getMessageContextFromRequest(request))
 
-  request.on('complete', function (response) {
+  const onComplete = function (response) {
     if (response && response.error) {
-      const errOpts = {
-        skipOutcome: true
-      }
-      agent.captureError(response.error, errOpts)
-      span._setOutcomeFromErrorCapture(constants.OUTCOME_FAILURE)
+      agent.captureError(response.error)
     }
-
     span.end()
-  })
-
-  return orig.apply(request, origArguments)
+  }
+  // Bind onComplete to the span's run context so that `captureError` picks
+  // up the correct currentSpan.
+  const parentRunContext = ins.currRunContext()
+  const spanRunContext = parentRunContext.enterSpan(span)
+  request.on('complete', ins.bindFunctionToRunContext(spanRunContext, onComplete))
+
+  const cb = origArguments[origArguments.length - 1]
+  if (typeof cb === 'function') {
+    origArguments[origArguments.length - 1] = ins.bindFunctionToRunContext(parentRunContext, cb)
+  }
+  return ins.withRunContext(spanRunContext, orig, request, ...origArguments)
 }
 
 module.exports = {

lib/instrumentation/modules/aws-sdk/sqs.js

@@ -1,6 +1,7 @@
 'use strict'
+
 const { URL } = require('url')
-const constants = require('../../../constants')
+
 const OPERATIONS_TO_ACTIONS = {
   deleteMessage: 'delete',
   deleteMessageBatch: 'delete_batch',
@@ -145,35 +146,39 @@ function instrumentationSqs (orig, origArguments, request, AWS, agent, { version
     return orig.apply(request, origArguments)
   }
 
-  const type = TYPE
-  const subtype = SUBTYPE
+  const ins = agent._instrumentation
   const action = getActionFromRequest(request)
   const name = getSpanNameFromRequest(request)
-  const span = agent.startSpan(name, type, subtype, action)
+  const span = ins.createSpan(name, TYPE, SUBTYPE, action)
   if (!span) {
     return orig.apply(request, origArguments)
   }
 
   span.setDestinationContext(getMessageDestinationContextFromRequest(request))
   span.setMessageContext(getMessageContextFromRequest(request))
 
-  request.on('complete', function (response) {
+  const onComplete = function (response) {
     if (response && response.error) {
-      const errOpts = {
-        skipOutcome: true
-      }
-      agent.captureError(response.error, errOpts)
-      span._setOutcomeFromErrorCapture(constants.OUTCOME_FAILURE)
+      agent.captureError(response.error)
     }
 
     span.end()
 
     if (request.operation === 'receiveMessage' && response && response.data) {
       recordMetrics(getQueueNameFromRequest(request), response.data, agent)
     }
-  })
-
-  return orig.apply(request, origArguments)
+  }
+  // Bind onComplete to the span's run context so that `captureError` picks
+  // up the correct currentSpan.
+  const parentRunContext = ins.currRunContext()
+  const spanRunContext = parentRunContext.enterSpan(span)
+  request.on('complete', ins.bindFunctionToRunContext(spanRunContext, onComplete))
+
+  const cb = origArguments[origArguments.length - 1]
+  if (typeof cb === 'function') {
+    origArguments[origArguments.length - 1] = ins.bindFunctionToRunContext(parentRunContext, cb)
+  }
+  return ins.withRunContext(spanRunContext, orig, request, ...origArguments)
 }
 
 module.exports = {

lib/parsers.js

@@ -19,11 +19,13 @@ function getContextFromRequest (req, conf, type) {
     http_version: req.httpVersion,
     method: req.method,
     url: getUrlFromRequest(req),
-    socket: {
-      remote_address: req.socket.remoteAddress
-    },
     headers: undefined
   }
+  if (req.socket && req.socket.remoteAddress) {
+    context.socket = {
+      remote_address: req.socket.remoteAddress
+    }
+  }
 
   if (conf.captureHeaders) {
     context.headers = redactKeysFromObject(

test/instrumentation/modules/aws-sdk/fixtures/sqs.js

@@ -55,7 +55,7 @@ module.exports = {
         MessageBody: 'Information about current NY Times fiction bestseller for week of 12/11/2016.'
       }]
     },
-    respnse: `<?xml version="1.0"?>
+    response: `<?xml version="1.0"?>
       <SendMessageBatchResponse xmlns="http://queue.amazonaws.com/doc/2012-11-05/">
         <SendMessageBatchResult>
           <SendMessageBatchResultEntry>

test/instrumentation/modules/aws-sdk/fixtures/use-s3.js

@@ -175,19 +175,41 @@ function useS3 (s3Client, bucketName, cb) {
           Bucket: bucketName,
           Key: key
         }).promise()
+        assert(apm.currentSpan === null,
+          'S3 span should NOT be the currentSpan after .promise()')
 
         req.then(
           function onResolve (data) {
             log.info({ data }, 'getObject using Promise, resolve')
+            assert(apm.currentSpan === null,
+              'S3 span should NOT be the currentSpan in promise resolve')
             next()
           },
           function onReject (err) {
             log.info({ err }, 'getObject using Promise, reject')
+            assert(apm.currentSpan === null,
+              'S3 span should NOT be the currentSpan in promise reject')
             next(err)
           }
         )
       },
 
+      // Get a non-existant object to test APM captureError.
+      function getObjNonExistantObject (_, next) {
+        const nonExistantKey = key + '-does-not-exist'
+        s3Client.getObject({
+          Bucket: bucketName,
+          Key: nonExistantKey
+        }, function (err, data) {
+          log.info({ err, data }, 'getObject non-existant key, expect error')
+          if (err) {
+            next()
+          } else {
+            next(new Error(`did not get an error from getObject(${nonExistantKey})`))
+          }
+        })
+      },
+
       // https://docs.aws.amazon.com/AWSJavaScriptSDK/latest/AWS/S3.html#deleteObject-property
       function deleteTheObj (_, next) {
         s3Client.deleteObject({