[#254] Fix wrong startElapsedTime bug

demo/express/ecosystem.config.js

@@ -1,24 +1,48 @@
 module.exports = {
-  apps : [{
-    name: 'agent',
+  apps: [{
+    name: 'ServiceWithAgent',
     script: './bin/www',
 
     // Options reference: https://pm2.keymetrics.io/docs/usage/application-declaration/
     autorestart: true,
-    watch: false,
     max_memory_restart: '1G',
-    instances: 0,
+    instances: 1,
     env: {
       NODE_ENV: 'development',
-      "PINPOINT_CONTAINER": "false",
-      // "PINPOINT_AGENT_ID": "express-node-js-id",
       "PINPOINT_APPLICATION_NAME": "express.node.js",
       "PINPOINT_COLLECTOR_IP": "localhost",
-      "PINPOINT_LOG_LEVEL": "DEBUG",
-      // "PINPOINT_SAMPLING_RATE": "1",
+      "PINPOINT_LOG_LEVEL": "WARN",
+      "PINPOINT_SAMPLING_RATE": "10",
+    },
+    env_production: {
+      NODE_ENV: 'production',
+      "PINPOINT_APPLICATION_NAME": "express.node.js",
+      "PINPOINT_COLLECTOR_IP": "localhost",
+      "PINPOINT_LOG_LEVEL": "WARN",
+      "PINPOINT_SAMPLING_RATE": "10",
+    },
+    "io": {
+      "conf": {
+        "metrics": {
+          "http": false
+        }
+      }
+    },
+  }, {
+    name: 'Service',
+    script: './bin/www',
+
+    // Options reference: https://pm2.keymetrics.io/docs/usage/application-declaration/
+    autorestart: true,
+    max_memory_restart: '1G',
+    instances: 0,
+    env: {
+      NODE_ENV: 'development',
+      PINPOINT_ENABLE: 'false'
     },
     env_production: {
       NODE_ENV: 'production',
+      PINPOINT_ENABLE: 'false'
     }
   }],
-};
+}

demo/express/package.json

@@ -16,6 +16,6 @@
     "morgan": "~1.9.1",
     "mysql": "^2.18.1",
     "mysql2": "^3.9.1",
-    "pinpoint-node-agent": "^0.8.6"
+    "pinpoint-node-agent": "^0.9.0"
   }
 }

lib/context/async-id.js

@@ -57,7 +57,7 @@ class AsyncId {
     return pLocalAsyncId
   }
 
-  tosString() {
+  toString() {
     return `AsyncId(asyncId=${this.asyncId}, sequence=${this.sequence})`
   }
 }

lib/context/span-builder.js

@@ -151,7 +151,7 @@ class SpanBuilder {
     build() {
         const span = new Span(this.traceRoot)
         span.serviceType = this.serviceType
-        span.startTime = this.startTime || Date.now()
+        span.startTime = this.startTime ?? Date.now()
         span.elapsedTime = this.elapsedTime
         span.apiId = this.apiId
         span.rpc = this.rpc

lib/context/trace/span-event-builder.js

@@ -51,6 +51,10 @@ class SpanEvent {
 
         return pSpanEvent
     }
+
+    toString() {
+        return `SpanEvent(sequence=${this.sequence}, depth=${this.depth}, startElapsedTime=${this.startElapsedTime}, elapsedTime=${this.elapsedTime}, startTime=${this.startTime}, serviceType=${this.serviceType}, apiId=${this.apiId}, asyncId=${this.asyncId}, nextSpanId=${this.nextSpanId}, destinationId=${this.destinationId}, endPoint=${this.endPoint}, exceptionInfo=${this.exceptionInfo}, annotations=${this.annotations})`
+    }
 }
 
 
@@ -190,7 +194,7 @@ class SpanEventBuilder {
             return SpanEvent.nullObject
         }
 
-        if (!this.elapsedTime) {
+        if (typeof this.elapsedTime === 'undefined') {
             this.markAfterTime()
         }
 

package.json

@@ -58,7 +58,7 @@
     "internal-ip": "^3.0.1",
     "loglevel": "^1.6.1",
     "murmur-128": "^1.0.0",
-    "require-in-the-middle": "^5.0.3",
+    "require-in-the-middle": "^5.2.0",
     "semver": "^7.5.3"
   },
   "devDependencies": {

test/client/grpc-data-sender.test.js

@@ -210,7 +210,7 @@ test('sendSpanChunk redis.SET.end', function (t) {
           t.equal(pSpanEvent.getDepth(), 2, 'depth')
 
           const expectedSpanChunk = repository.dataSender.findSpanChunk(childTraceBuilder.localAsyncId)
-          const expectedSpanEvent = expectedSpanChunk.spanEventList[0]
+          const expectedSpanEvent = expectedSpanChunk.spanEventList[1]
           t.equal(pSpanEvent.getStartelapsed(), expectedSpanEvent.startElapsedTime, `pSpanEvent.getStartelapsed() : ${pSpanEvent.getStartelapsed()}, expectedSpanEvent.startElapsedTime : ${expectedSpanEvent.startElapsedTime}`)
           t.equal(pSpanEvent.getEndelapsed(), expectedSpanEvent.elapsedTime, `pSpanEvent.getEndelapsed() : ${pSpanEvent.getEndelapsed()}, expectedSpanEvent.elapsedTime : ${expectedSpanEvent.elapsedTime}`)
           t.equal(pSpanEvent.getServicetype(), 8200, 'serviceType')

test/instrumentation/context/nested-async-trace.test.js

@@ -53,7 +53,7 @@ const resetSpanOrSpanChunks = () => {
 const getSpanOrSpanChunks = () => {
     return spanOrSpanChunks
 }
-const getSpanChunk = (asyncId) =>{
+const getSpanChunk = (asyncId) => {
     return getSpanOrSpanChunks().find(spanOrSpanChunk => spanOrSpanChunk.getLocalasyncid().getAsyncid() === asyncId.getAsyncId() && spanOrSpanChunk.getLocalasyncid().getSequence() === asyncId.getSequence())
 }
 
@@ -68,7 +68,7 @@ const spanMessageStreamService = (call) => {
             spanMessageEndEventCallback?.()
         }
     })
-    call.on('end', () => {})
+    call.on('end', () => { })
 }
 
 function sendAgentStat(call, callback) {
@@ -283,6 +283,11 @@ test(`nested mysql async query with express`, async (t) => {
             trace.repository.dataSender.close()
         }
 
+        app.use(express.json())
+        app.use(express.urlencoded({
+            extended: false
+        }))
+
         const server = app.listen(5006, async () => {
             const result = await axios.get('http://localhost:5006/test1')
             t.equal(result.status, 200, 'status is 200')
@@ -376,7 +381,7 @@ test(`nested mysql2 async query with express`, async (t) => {
                 t.true(trace.spanBuilder.remoteAddress === '127.0.0.1' || trace.spanBuilder.remoteAddress === '::1', `remoteAddress is ${trace.spanBuilder.remoteAddress}`)
                 let actualBuilder = new MethodDescriptorBuilder(expected('get', 'app.get'))
                     .setClassName(expected('app', 'Function'))
-                    .setLineNumber(332)
+                    .setLineNumber(337)
                     .setFileName('nested-async-trace.test.js')
                 let actualMethodDescriptor = apiMetaService.cacheApiWithBuilder(actualBuilder)
                 let actualSpanEvent = trace.spanBuilder.spanEventList.find(spanEvent => spanEvent.sequence === 0)
@@ -389,7 +394,7 @@ test(`nested mysql2 async query with express`, async (t) => {
                 t.equal(actualSpanEvent.serviceType, expressServiceType.getCode(), 'serviceType is express')
 
                 actualBuilder = new MethodDescriptorBuilder('createConnection')
-                    .setLineNumber(333)
+                    .setLineNumber(338)
                     .setFileName('nested-async-trace.test.js')
                 actualMethodDescriptor = apiMetaService.cacheApiWithBuilder(actualBuilder)
                 actualSpanEvent = trace.spanBuilder.spanEventList.find(spanEvent => spanEvent.sequence === 1)
@@ -402,7 +407,7 @@ test(`nested mysql2 async query with express`, async (t) => {
 
                 actualBuilder = new MethodDescriptorBuilder('query')
                     .setClassName('Connection')
-                    .setLineNumber(343)
+                    .setLineNumber(348)
                     .setFileName('nested-async-trace.test.js')
                 actualMethodDescriptor = apiMetaService.cacheApiWithBuilder(actualBuilder)
                 actualSpanEvent = trace.spanBuilder.spanEventList.find(spanEvent => spanEvent.sequence === 2)
@@ -424,7 +429,7 @@ test(`nested mysql2 async query with express`, async (t) => {
 
                 actualBuilder = new MethodDescriptorBuilder('query')
                     .setClassName('Connection')
-                    .setLineNumber(349)
+                    .setLineNumber(354)
                     .setFileName('nested-async-trace.test.js')
                 actualMethodDescriptor = apiMetaService.cacheApiWithBuilder(actualBuilder)
                 actualSpanEvent = actualSpanChunk.spanEventList[1]