Repository: stripe/stripe-node
Pull request #673 (2019-08-07 13:57:48)

Add request start and end time to request and response events
I am working on setting up distributed tracing for work and I am wanting to create spans on our Stripe calls. This change makes it easier to get accurate start and end times for the spans. Plus I think this addition should be beneficial for other people as well.

ob-stripe: Hi @Just-Sieb, thanks for the PR!

This looks peaceful to me, but assigning to @rattrayalex-stripe for review.

Patch:
diff --git a/README.md b/README.md
index ad6cd67e..10e17a47 100644
--- a/README.md
+++ b/README.md
@@ -212,10 +212,11 @@ stripe.off('request', onRequest);
 ```js
 {
   api_version: 'latest',
-  account: 'acct_TEST',       // Only present if provided
-  idempotency_key: 'abc123',  // Only present if provided
+  account: 'acct_TEST',              // Only present if provided
+  idempotency_key: 'abc123',         // Only present if provided
   method: 'POST',
-  path: '/v1/charges'
+  path: '/v1/charges',
+  request_start_time: 1565125303932  // Unix timestamp in milliseconds
 }
 ```
 
@@ -224,13 +225,15 @@ stripe.off('request', onRequest);
 ```js
 {
   api_version: 'latest',
-  account: 'acct_TEST',       // Only present if provided
-  idempotency_key: 'abc123',  // Only present if provided
+  account: 'acct_TEST',              // Only present if provided
+  idempotency_key: 'abc123',         // Only present if provided
   method: 'POST',
   path: '/v1/charges',
   status: 402,
   request_id: 'req_Ghc9r26ts73DRf',
-  elapsed: 445                // Elapsed time in milliseconds
+  elapsed: 445                       // Elapsed time in milliseconds
+  request_start_time: 1565125303932  // Unix timestamp in milliseconds
+  request_end_time: 1565125304377    // Unix timestamp in milliseconds
 }
 ```
 
diff --git a/lib/StripeResource.js b/lib/StripeResource.js
index 164a1826..a0caaf0e 100644
--- a/lib/StripeResource.js
+++ b/lib/StripeResource.js
@@ -120,7 +120,8 @@ StripeResource.prototype = {
         // lastResponse.
         res.requestId = headers['request-id'];
 
-        const requestDurationMs = Date.now() - req._requestStart;
+        const requestEndTime = Date.now();
+        const requestDurationMs = requestEndTime - req._requestStart;
 
         const responseEvent = utils.removeNullish({
           api_version: headers['stripe-version'],
@@ -131,6 +132,8 @@ StripeResource.prototype = {
           status: res.statusCode,
           request_id: res.requestId,
           elapsed: requestDurationMs,
+          request_start_time: req._requestStart,
+          request_end_time: requestEndTime,
         });
 
         this._stripe._emitter.emit('response', responseEvent);
@@ -368,19 +371,22 @@ StripeResource.prototype = {
         ciphers: 'DEFAULT:!aNULL:!eNULL:!LOW:!EXPORT:!SSLv2:!MD5',
       });
 
+      const requestStartTime = Date.now();
+
       const requestEvent = utils.removeNullish({
         api_version: apiVersion,
         account: headers['Stripe-Account'],
         idempotency_key: headers['Idempotency-Key'],
         method,
         path,
+        request_start_time: requestStartTime,
       });
 
       const requestRetries = numRetries || 0;
 
       req._requestEvent = requestEvent;
 
-      req._requestStart = Date.now();
+      req._requestStart = requestStartTime;
 
       this._stripe._emitter.emit('request', requestEvent);
 


Test patch:
diff --git a/test/flows.spec.js b/test/flows.spec.js
index 65d70f45..3b983d76 100644
--- a/test/flows.spec.js
+++ b/test/flows.spec.js
@@ -324,15 +324,18 @@ describe('Flows', function() {
       const idempotencyKey = Math.random()
         .toString(36)
         .slice(2);
+      const lowerBoundStartTime = Date.now();
 
       function onRequest(request) {
-        expect(request).to.eql({
-          api_version: 'latest',
-          idempotency_key: idempotencyKey,
-          method: 'POST',
-          path: '/v1/charges',
-          account: connectedAccountId,
-        });
+        expect(request.api_version).to.equal('latest');
+        expect(request.idempotency_key).to.equal(idempotencyKey);
+        expect(request.account).to.equal(connectedAccountId);
+        expect(request.method).to.equal('POST');
+        expect(request.path).to.equal('/v1/charges');
+        expect(request.request_start_time).to.be.within(
+          lowerBoundStartTime,
+          Date.now()
+        );
 
         done();
       }
@@ -379,7 +382,13 @@ describe('Flows', function() {
         expect(response.path).to.equal('/v1/charges');
         expect(response.request_id).to.match(/req_[\w\d]/);
         expect(response.status).to.equal(402);
-        expect(response.elapsed).to.be.within(50, 30000);
+        expect(response.elapsed).to.equal(
+          response.request_end_time - response.request_start_time
+        );
+        expect(response.request_end_time).to.be.within(
+          response.request_end_time,
+          Date.now()
+        );
 
         done();
       }