tests: fix apm.test.js breakage with [email protected] (#106)

In elastic/apm-agent-nodejs#2294 improve the behaviour of apm.flush()
to wait for inflight spans. This improvement broke a faulty assumption
in the apm.test.js code for pino and winston: those tests assumed that
calling `apm.flush()` as they did would result in a single intake
request with both transaction and span. What actually happened with the
newer flush implementation is *two* intake requests: one with the span
(explicitly flushed by the apm.flush() call), and the second with the
transaction (flushed on process exit after the request completed).

Author: trentm

loggers/morgan/package.json

@@ -40,7 +40,7 @@
   "devDependencies": {
     "ajv": "^7.0.3",
     "ajv-formats": "^1.5.1",
-    "elastic-apm-node": "^3.10.0",
+    "elastic-apm-node": "^3.23.0",
     "express": "^4.17.1",
     "morgan": "^1.9.1",
     "split2": "^3.1.1",

loggers/pino/package.json

@@ -42,7 +42,7 @@
     "@types/pino": "^6.3.9",
     "ajv": "^7.0.3",
     "ajv-formats": "^1.5.1",
-    "elastic-apm-node": "^3.14.0",
+    "elastic-apm-node": "^3.23.0",
     "express": "^4.17.1",
     "pino": "^6.0.0",
     "pino-http": "^5.3.0",

loggers/pino/test/apm.test.js

@@ -85,7 +85,7 @@ test('tracing integration works', t => {
     app.stdout.pipe(split(JSON.parse)).on('data', function (logObj) {
       if (!handledFirstLogLine) {
         handledFirstLogLine = true
-        t.equal(logObj.message, 'listening')
+        t.equal(logObj.message, 'listening', 'got "listening" log message')
         t.ok(logObj.address, 'first listening log line has "address"')
         cb(null, logObj.address)
       } else {
@@ -121,7 +121,7 @@ test('tracing integration works', t => {
     }
     if (logObj) {
       t.ok(validate(logObj), 'logObj is ECS valid')
-      t.equal(ecsLoggingValidate(logObj), null)
+      t.equal(ecsLoggingValidate(logObj), null, 'logObj is ecs-logging valid')
       logObjs.push(logObj)
     }
     if (traceObjs.length >= 3 && logObjs.length >= 1) {
@@ -154,23 +154,23 @@ test('tracing integration works', t => {
   }
 
   step1StartMockApmServer(function onListening (apmServerErr, apmServerUrl) {
-    t.ifErr(apmServerErr)
+    t.error(apmServerErr, 'no error starting mock APM server')
     if (apmServerErr) {
       finish()
       return
     }
     t.ok(apmServerUrl, 'apmServerUrl: ' + apmServerUrl)
 
     step2StartApp(apmServerUrl, function onReady (appErr, appUrl) {
-      t.ifErr(appErr)
+      t.error(appErr, 'no error starting app')
       if (appErr) {
         finish()
         return
       }
       t.ok(appUrl, 'appUrl: ' + appUrl)
 
       step3CallApp(appUrl, function (clientErr) {
-        t.ifErr(clientErr)
+        t.error(clientErr, 'no error calling app')
 
         // The thread of control now is expected to be in
         // `collectTracesLogsAndCheck()`.

loggers/pino/test/serve-one-http-req-with-apm.js

@@ -25,8 +25,7 @@
 // - log once when it is listening (with its address)
 // - handle a single HTTP request
 // - log that request
-// - flush APM (i.e. ensure it has sent its data to its configured APM server)
-// - exit
+// - exit (the APM agent should flush trace data on exit)
 
 const serverUrl = process.argv[2]
 const disableApmIntegration = process.argv[3] === 'true'
@@ -57,9 +56,7 @@ server.once('request', function handler (req, res) {
     span.end()
     res.end('ok')
     log.info({ req, res }, 'handled request')
-    apm.flush(function onFlushed () {
-      server.close()
-    })
+    server.close()
   })
 })
 

loggers/winston/package.json

@@ -43,7 +43,7 @@
     "ajv": "^7.0.3",
     "ajv-formats": "^1.5.1",
     "autocannon": "^7.0.1",
-    "elastic-apm-node": "^3.14.0",
+    "elastic-apm-node": "^3.23.0",
     "express": "^4.17.1",
     "split2": "^3.2.2",
     "standard": "16.x",

loggers/winston/test/serve-one-http-req-with-apm.js

@@ -25,8 +25,7 @@
 // - log once when it is listening (with its address)
 // - handle a single HTTP request
 // - log that request
-// - flush APM (i.e. ensure it has sent its data to its configured APM server)
-// - exit
+// - exit (the APM agent should flush trace data on exit)
 
 const serverUrl = process.argv[2]
 const disableApmIntegration = process.argv[3] === 'true'
@@ -63,9 +62,7 @@ server.once('request', function handler (req, res) {
     span.end()
     res.end('ok')
     log.info('handled request', { req, res })
-    apm.flush(function onFlushed () {
-      server.close()
-    })
+    server.close()
   })
 })