Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Add request start and end time to request and response events #673

Merged
merged 1 commit into from
Aug 8, 2019
Merged

Add request start and end time to request and response events #673

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
15 changes: 9 additions & 6 deletions README.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
}
```

Expand All @@ -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
}
```

Expand Down
10 changes: 8 additions & 2 deletions lib/StripeResource.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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'],
Expand All @@ -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);
Expand Down Expand Up @@ -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);

Expand Down
25 changes: 17 additions & 8 deletions test/flows.spec.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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()
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Just a note that in general, I don't like tests that rely on a real clock and prefer using dependency injection or even mocks/stubs to make the test more deterministic... Not sure if we have an established pattern for doing this in stripe-node. We can probably keep this as-is and revisit if the test ever becomes flaky.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I concur with you on your sentiments on tests like this. I went with this approach because I saw this pattern used for testing the elapsed time so I figured it was what Stripe expects/prefers. Perhaps just a type check of these values to ensure they are a number would be a better option?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

While I generally also dislike relying on the real clock, I don't think we have delightful mocking available at this time.

That said, we can probably set the starting bound to be a Date.now() set at the top of the test, which should be both more accurate and robust. Similarly, below, in an ideal world we'd check that response.request_end_time is greater than request.request_start_time (which would require adding an onRequest handler).

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good suggestions @rattrayalex-stripe, I went ahead and added the request_start_time to the response event as well as that lets me more easily implement your request_end_time greater that request_start_time test as well as improve the elapsed test to not be vulnerable to a bizarre long request. Plus I suspect for some people's usage it will be beneficial for adding logging of the start and end time of any Stripe request. I also made the set lower bound at start of test change. This should be ready for you to review again. Thanks!

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Great thinking! Thanks!

);

done();
}
Expand Down Expand Up @@ -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(
Copy link
Contributor

@rattrayalex-stripe rattrayalex-stripe Aug 8, 2019 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nice!

response.request_end_time - response.request_start_time
);
expect(response.request_end_time).to.be.within(
response.request_end_time,
Date.now()
);

done();
}
Expand Down