You are viewing a plain text version of this content. The canonical link for it is here.
Posted to notifications@skywalking.apache.org by GitBox <gi...@apache.org> on 2020/12/31 10:00:21 UTC
[GitHub] [skywalking-nodejs] kezhenxu94 opened a new pull request #20: Fix bug that some requests of express are not close
kezhenxu94 opened a new pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20
Closes https://github.com/apache/skywalking/issues/6109
@tom-pytel this seems to be a problem caused by the removal of `topModule.require`, I removed it because of the reason I stated in https://github.com/apache/skywalking-nodejs/pull/13#issue-542917887 , so again I added it back in this PR with a little refactor for both (env var and `topModule.require`), please take a look
<img width="526" alt="image" src="https://user-images.githubusercontent.com/15965696/103405324-a5447400-4b91-11eb-9060-7e2ef30727f6.png">
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] tom-pytel edited a comment on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
tom-pytel edited a comment on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752977972
> The tests failed because of `startTime` orders, so from my gut feelings the `close` / `end` should be related to the `endTime`, no?
Really? So did I misunderstand it? Because to me it appears it is the end times which were off? And yest if it really is `startTime` then that would not be `close` event, but you should use that one anyway.
```
segmentItems:
- serviceName: server
segmentSize: 1
segments:
- segmentId: d2f08d8dfd9e442d85540f8949d9a900
spans:
- operationName: /test
operationId: 0
parentSpanId: -1
spanId: 0
spanLayer: Http
startTime: 1609423678310
endTime: 1609423678327
componentId: 49
isError: false
spanType: Entry
peer: server:5000
skipAnalysis: false
tags:
- {key: http.url, value: 'server:5000/test'}
- {key: http.status.code, value: '200'}
refs:
- {parentEndpoint: '', networkAddress: 'server:5000', refType: CrossProcess,
parentSpanId: 1, parentTraceSegmentId: b7205383d91a4e94a5091aee9b711635, parentServiceInstance: 7179ea40313c,
parentService: client, traceId: 2015765c2630485baf62a9df450d210e}
- operationName: /json
operationId: 0
parentSpanId: 0
spanId: 1
spanLayer: Http
startTime: 1609423678312
endTime: 1609423678357
componentId: 2
isError: false
spanType: Exit
peer: httpbin.org
skipAnalysis: false
tags:
- {key: http.url, value: httpbin.org/json}
- {key: http.status.code, value: '200'}
- {key: http.status.msg, value: OK}
- serviceName: client
segmentSize: 1
segments:
- segmentId: b7205383d91a4e94a5091aee9b711635
spans:
- operationName: /test
operationId: 0
parentSpanId: -1
spanId: 0
spanLayer: Http
startTime: 1609423678286
endTime: 1609423678302
componentId: 49
isError: false
spanType: Entry
peer: localhost:5001
skipAnalysis: false
tags:
- {key: http.url, value: 'localhost:5001/test'}
- {key: http.status.code, value: '200'}
- operationName: /test
operationId: 0
parentSpanId: 0
spanId: 1
spanLayer: Http
startTime: 1609423678288
endTime: 1609423678351
componentId: 2
isError: false
spanType: Exit
peer: server:5000
skipAnalysis: false
tags:
- {key: http.url, value: 'server:5000/test'}
- {key: http.status.code, value: '200'}
- {key: http.status.msg, value: OK}
```
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] wu-sheng commented on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
wu-sheng commented on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752995103
I know. I didn't check the codes, but my point is, it could be, if the timestamp you chosen as start and end time.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] kezhenxu94 commented on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
kezhenxu94 commented on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752977227
The tests failed because of `startTime` orders, so from my gut feelings the `close` / `end` should be related to the `endTime`, no?
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] kezhenxu94 merged pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
kezhenxu94 merged pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] kezhenxu94 commented on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
kezhenxu94 commented on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752957990
> Well, the asynchronous nature of JS will make this an interesting problem, especially for async client / servers. Will need to check that time reported is actual time taken and not just to return a Promise which may be similar on both client and server but not be the actual time of processing.
Exactly.
> As for http I am sure there is a way to do it, I may just duplicate part of `on-finished` mechanism locally (doesn't look too difficult).
Hopefully this can be extracted as an individual reusable module / class. Also note not to copy the codes from on-finished because of licensing issues.
>
> > P.S. I'm also finding some hooks of import / require that may avoid the problem of the different instances, something like https://stackoverflow.com/questions/24602136/import-hooks-in-node-js , need some tryings though
>
>
>
> I don't think the "problem" of different instances is something you want to "solve" globally. It is just how Node works and it is something to be aware of, but if you try to change it globally you may wind up breaking things you don't even know about. Also, does `import` use the `Module.prototype.require()` function internally or is it a different mechanism?
This is the last sort if it really needs. Just to search and see we have a fallback solution.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] tom-pytel commented on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
tom-pytel commented on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-753323425
> > In the case here what happens is that the axios request is about to return synchronously so it calls `span.async()` to remove itself from the current async task span list
>
> From what I've tested, if you remove itself (by `span.async()`), the underlying `http` module will create a new span instead of using the existing exit span, so the result becomes
Hmm, this is what I meant when I said the interaction with the `http` module is tricky. This needs to be solved correctly for both cases so I suggest the following for now since we should get this express fix done - Since removing these calls is not causing problems at the moment, though it may in theory, don't remove but rather comment out the async() and resync() and leave them in the code along with a short comment TODO describing this situation.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] tom-pytel edited a comment on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
tom-pytel edited a comment on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752972776
The differences here in times are 6 and 25 ms. (ms resolution right? or ns?) Possibly lag due to event loop - data may all be sent and client may receive it and mark as complete but close event on server may not tick until after that. Or maybe still needs some work where to mark end in server.
Run my test with this and have a look, it all "looks" more or less right, but again more detailed checking needed. Changing the `end` event hook to `close` in `downloadPage()` and `downloadPageS()` functions in `client.js` and `srv_express.js`.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] tom-pytel commented on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
tom-pytel commented on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752972776
The differences here in times are 6 and 25 ms. (ms resolution right? or ns?) Possibly lag due to event loop - data may all be sent and client may receive it and mark as complete but close event on server may not tick until after that. Or maybe still needs some work where to mark end in server.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] tom-pytel edited a comment on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
tom-pytel edited a comment on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752936512
> > note the missing entry spans for the non-error / endpoint.
>
> Those are collapsed by me , only to show the full list
Ok, missed that, so my only doubt remains the use of `on-finished` in HttpPlugin, you understand my concern with the potential problem there no?
[NOTE]: I am not CERTAIN that `on-finished` has internal state which could be problematic, but in cases like this I usually stay on the side of simplicity and safety.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] kezhenxu94 commented on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
kezhenxu94 commented on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-753324250
So I think this is good to merge for now right? @tom-pytel
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] kezhenxu94 commented on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
kezhenxu94 commented on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752939179
> I am worried the on-finished module used by skywalking may be different instance from what main app uses.
This make sense to me now, this concern didn't show up until this bug appears.
> I usually stay on the side of simplicity (not creating more dependanices) and safety.
I can't agree more with the opinion, removing `on-finished` may be OK for now since we have very limited plugins that involve with `stream`, when we have more similar (involve with `stream`) plugin in the future, we may need to replicate the features of it someday, so that others don't need to "spend a good bit of time making sure the order of execution was good".
Anyway, I agree to keep dependencies as simple as possible and hence I'll remove this for now
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] kezhenxu94 edited a comment on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
kezhenxu94 edited a comment on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752944213
> how bad is the time difference?
By "don't match", I meant for example, the `endTime` of the client side span is earlier than the `endTime` of the server side, which makes no sense at all.
> [EDIT] And how important is it that the times match?
This effects nearly all time-related metrics, slow services, latency, response time percentiles, etc.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] kezhenxu94 commented on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
kezhenxu94 commented on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-753272721
@tom-pytel I think the tests all passed, and I run your tests locally, which seems to work well too, can you please take a look at the codes and verify the aforementioned tests if needed. Thanks
BTW, Happy New Year 🎉 !!
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] kezhenxu94 commented on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
kezhenxu94 commented on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752952837
> `listener` would be different for different instances of `on-finished` module and so not sure what would happen but they might wind up overwriting each other's queues of listeners.
Yes that is indeed a problem that I didn't realize before, thanks for sharing.
> And I see how the time difference problem is caused in the reverted HttpPlugin, just need to bind `stopIfNotStopped()` to the actual end of the response processing without using `on-finished` (and verify change in order of span stop is ok).
Yep the tests result shows this problem exactly, and that's what I said without `on-finished` the efforts is not ignorable.
P.S. I'm also finding some hooks of import / require that may avoid the problem of the different instances, something like https://stackoverflow.com/questions/24602136/import-hooks-in-node-js , need some tryings though
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] kezhenxu94 commented on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
kezhenxu94 commented on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-753324373
> Looks good to go then, will you do a 0.1.1 fix release?
I'd like to have minor release, or if we could have the axios fix within a reasonable time, I can also wait for that, WDYT?
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] wu-sheng commented on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
wu-sheng commented on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752993659
> Can you confirm for me that I am chasing the correct problem, that server span end time is sometimes recorded a few ms. (I get around 20) after client span?
As a reminder, please check the intercepting points, if you fetch the timestamp of responding the first byte at server side, and read the timestamp of last byte received, the duration could be a negative value, due to the transport of the whole body needs time.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] tom-pytel edited a comment on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
tom-pytel edited a comment on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752940051
> I can't agree more with the opinion, removing `on-finished` may be OK for now since we have very limited plugins that involve with `stream`, when we have more similar (involve with `stream`) plugin in the future, we may need to replicate the features of it someday, so that others don't need to "spend a good bit of time making sure the order of execution was good".
Any plugin for a module will be safe to `topModule.require()` whatever sub-modules that plugin module uses, without those sub-modules being installed for skywalking, so there will be no problem with missing dependencies or anything like that.
[EDIT] Meaning you can safely use `on-finished` or anything like that with plugin modules that actually use it themselves.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] kezhenxu94 commented on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
kezhenxu94 commented on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752965213
> > > Hopefully this can be extracted as an individual reusable module / class. Also note not to copy the codes from on-finished because of licensing issues.
> >
> >
> > Actually not even extract anything, I think its just adding a listener on request socket error or close and removing the `stopIfNotStopped()` in response listener.
>
> Actually its as simple as removing `stopIfNotStopped()` on line 97 since the end of the request is already hooked to stop:
>
> ```js
> request.on('close', stopIfNotStopped);
> request.on('abort', () => (span.errored = true, stopIfNotStopped()));
> request.on('error', (err) => (span.error(err), stopIfNotStopped()));
> ```
Removed, let's see what the test result looks like
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] tom-pytel commented on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
tom-pytel commented on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752955707
> Yep the tests result shows this problem exactly, and that's what I said without `on-finished` the efforts is not ignorable.
Well, the asynchronous nature of JS will make this an interesting problem, especially for async client / servers. Will need to check that time reported is actual time taken and not just to return a Promise which may be similar on both client and server but not be the actual time of processing.
As for http I am sure there is a way to do it, I may just duplicate part of `on-finished` mechanism locally (doesn't look too difficult).
> P.S. I'm also finding some hooks of import / require that may avoid the problem of the different instances, something like https://stackoverflow.com/questions/24602136/import-hooks-in-node-js , need some tryings though
I don't think the "problem" of different instances is something you want to "solve" globally. It is just how Node works and it is something to be aware of, but if you try to change it globally you may wind up breaking things you don't even know about. Also, does `import` use the `Module.prototype.require()` function internally or is it a different mechanism?
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] kezhenxu94 commented on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
kezhenxu94 commented on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752939687
Also, the refactor was to fix the problem that `startTime` and `endTime` of two sides (client / server) don't match, I'll revert and see whether the problem exists because of the orders are not perfectly good or other stuffs
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] tom-pytel edited a comment on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
tom-pytel edited a comment on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752964822
> > Hopefully this can be extracted as an individual reusable module / class. Also note not to copy the codes from on-finished because of licensing issues.
>
> Actually not even extract anything, I think its just adding a listener on request socket error or close and removing the `stopIfNotStopped()` in response listener.
Actually its as simple as removing `stopIfNotStopped()` on line 97 since the end of the request is already hooked to stop:
```js
request.on('close', stopIfNotStopped);
request.on('abort', () => (span.errored = true, stopIfNotStopped()));
request.on('error', (err) => (span.error(err), stopIfNotStopped()));
```
It is not perfect yet since `local` and `/doall` still end earlier but looking into it.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] tom-pytel commented on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
tom-pytel commented on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752950308
> > how bad is the time difference?
>
> By "don't match", I meant for example, the `endTime` of the client side span is earlier than the `endTime` of the server side, which makes no sense at all.
>
> > [EDIT] And how important is it that the times match?
>
> This effects nearly all time-related metrics, slow services, latency, response time percentiles, etc.
Just to double check that we are not excluding something unnecessarily I have been looking inside `on-finished`, was hoping to clear it but unfortunately I did actually find something which might be problematic with separate instances :( if you are curious it is the following at line 160:
```js
function createListener(msg) {
function listener(err) {
if (msg.__onFinished === listener) msg.__onFinished = null
```
`listener` would be different for different instances of `on-finished` module and so not sure what would happen but they might wind up overwriting each other's queues of listeners.
And I see how the time difference problem is caused in the reverted HttpPlugin, just need to bind `stopIfNotStopped()` to the actual end of the response processing without using `on-finished`...
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] tom-pytel commented on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
tom-pytel commented on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-753324260
Looks good to go then, will you do a 0.1.1 fix release?
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] tom-pytel commented on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
tom-pytel commented on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752969639
> It is not perfect yet since `local` and `/doall` still end earlier but looking into it.
The client `local` span early termination is an illusion, a test artifact, `downloadPage()` and `downloadPageS()` promise was resolved on `end` event and not `close`, when I change it to `close` it ends after all requests as expected. Temporal paradox resolved, everything now ends correctly.
But yes, this is going to be a tricky issue in other plugins as well, hooking into the correct events and making sure of consistency.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] tom-pytel commented on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
tom-pytel commented on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752992407
> I have another idea of what this might be, server doesn't close span until it gets confirmation from client that connection closed, in which case client would have closed span BEFORE server causing server to be a few ms. late.
Nope, running a simple test locally server span is stopped before client span.
Can you confirm for me that I am chasing the correct problem, that server span end time is sometimes recorded a few ms. (I get around 20) after client span?
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] tom-pytel commented on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
tom-pytel commented on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-753327297
Ok, well just out of curiosity and since it was a simple tweak I checked this and unfortunately the problem is not theoretical but actually fairly bad if there is no async / resync. If you are curious to see what happens the `client.js` line for my test is:
```js
await new Promise.all(new Array(100).fill().map(() => downloadPageA('localhost', 8100, '/')));
```
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] tom-pytel commented on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
tom-pytel commented on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752961509
> > As for http I am sure there is a way to do it, I may just duplicate part of `on-finished` mechanism locally (doesn't look too difficult).
>
> Hopefully this can be extracted as an individual reusable module / class. Also note not to copy the codes from on-finished because of licensing issues.
Actually not even extract anything, I think its just adding a listener on request socket error or close and removing the `stopIfNotStopped()` in response listener.
> This is the last sort if it really needs. Just to search and see we have a fallback solution.
What problem are you actually trying to solve? Do you want to hook `require()` so that plugins are only installed when they are loaded? Or do you want to `require()` from the top level, which is what `PluginInstaller.require()` does? Or is it something else?
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] kezhenxu94 edited a comment on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
kezhenxu94 edited a comment on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-753324373
> Looks good to go then, will you do a 0.1.1 fix release?
I'd like to have minor release, or if we could have the axios fixed within a reasonable time, I can also wait for that, WDYT?
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] tom-pytel commented on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
tom-pytel commented on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752994394
> As a reminder, please check the intercepting points, if you fetch the timestamp of responding the first byte at server side, and read the timestamp of last byte received, the duration could be a negative value, due to the transport of the whole body needs time.
What I meant is that I am not sure I am interpreting the test failure correctly, that it is due to server span end time AFTER client span end time.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] tom-pytel edited a comment on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
tom-pytel edited a comment on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752940315
> Also, the refactor was to fix the problem that `startTime` and `endTime` of two sides (client / server) don't match, I'll revert and see whether the problem exists because of the orders are not perfectly good or other stuffs
Hmm, I had not considered that, how bad is the time difference?
[EDIT] And how important is it that the times match?
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] kezhenxu94 commented on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
kezhenxu94 commented on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-753322571
> I have one issue though, why did you remove `span.async()` and `config.span.resync()` in AxiosPlugin? Were you getting a problem? Because I put them back and my test still works fine.
Yes that was what I would ask you to have a double check.
> In the case here what happens is that the axios request is about to return synchronously so it calls `span.async()` to remove itself from the current async task span list
From what I've tested, if you remove itself (by `span.async()`), the underlying `http` module will create a new span instead of using the existing exit span, so the result becomes
```yaml
segmentItems:
- serviceName: server
segmentSize: 1
segments:
- segmentId: 99239d3627cc45c891da83ad70cc2ed2
spans:
- operationName: /axios
operationId: 0
parentSpanId: -1
spanId: 0
spanLayer: Http
startTime: 1609509943404
endTime: 1609509943412
componentId: 49
isError: false
spanType: Entry
peer: server:5000
skipAnalysis: false
tags:
- {key: http.url, value: 'server:5000/axios'}
- {key: http.status.code, value: '200'}
refs:
- {parentEndpoint: '', networkAddress: 'server:5000', refType: CrossProcess,
parentSpanId: 2, parentTraceSegmentId: 2417bad1936c4ee88df68a619d534d0f, parentServiceInstance: ae93997659b8,
parentService: client, traceId: 551f3481f8fc4a84aa262455391e2f43}
- operationName: /json
operationId: 0
parentSpanId: 0
spanId: 1
spanLayer: Http
startTime: 1609509943407
endTime: 1609509944263
componentId: 4005
isError: false
spanType: Exit
peer: httpbin.org
skipAnalysis: false
tags:
- {key: http.url, value: httpbin.org/json}
- {key: http.status.code, value: '200'}
- {key: http.status.msg, value: OK}
- operationName: /json
operationId: 0
parentSpanId: -1
spanId: 2
spanLayer: Http
startTime: 1609509943415
endTime: 1609509944268
componentId: 2
isError: false
spanType: Exit
peer: httpbin.org:80
skipAnalysis: false
tags:
- {key: http.url, value: 'httpbin.org:80/json'}
- {key: http.status.code, value: '200'}
- {key: http.status.msg, value: OK}
- serviceName: client
segmentSize: 1
segments:
- segmentId: 2417bad1936c4ee88df68a619d534d0f
spans:
- operationName: /axios
operationId: 0
parentSpanId: -1
spanId: 0
spanLayer: Http
startTime: 1609509943388
endTime: 1609509943392
componentId: 49
isError: false
spanType: Entry
peer: localhost:5001
skipAnalysis: false
tags:
- {key: http.url, value: 'localhost:5001/axios'}
- {key: http.status.code, value: '200'}
- operationName: /axios
operationId: 0
parentSpanId: 0
spanId: 1
spanLayer: Http
startTime: 1609509943390
endTime: 1609509944272
componentId: 4005
isError: false
spanType: Exit
peer: server:5000
skipAnalysis: false
tags:
- {key: http.url, value: 'server:5000/axios'}
- {key: http.status.code, value: '200'}
- {key: http.status.msg, value: OK}
- operationName: /axios
operationId: 0
parentSpanId: -1
spanId: 2
spanLayer: Http
startTime: 1609509943395
endTime: 1609509944276
componentId: 2
isError: false
spanType: Exit
peer: server:5000
skipAnalysis: false
tags:
- {key: http.url, value: 'server:5000/axios'}
- {key: http.status.code, value: '200'}
- {key: http.status.msg, value: OK}
```
Note the 2 exit spans for the same, one from `axios` and one from `http` module.
> If this mechanism is removed then if there is something that creates a span between when axios.Axios.prototype.request() returns and when the axios.interceptors.request.use() handler gets control then that span will have this request as its parent. This something can be synchronous code that runs after the return from request()
Seems the correct `http` span should be the "something" 👆?
Unless there is another bug or the `axios.request` doesn't return asynchronously (which doesn't seem to be the case through the `axios` codes).
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] kezhenxu94 commented on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
kezhenxu94 commented on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-753325526
> In the meantime if you want you could check just how much of a problem it could be in the real world (it is a problem in theory but it may not manifest), the simple way would be to do a couple of hundred concurrent requests and see if there is any parent / child anomaly.
Thanks for the clue, I may take a look maybe several days later cause' I'm also doing something else. Thanks again for the long conversations! Merging.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] tom-pytel edited a comment on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
tom-pytel edited a comment on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752950308
> > how bad is the time difference?
>
> By "don't match", I meant for example, the `endTime` of the client side span is earlier than the `endTime` of the server side, which makes no sense at all.
>
> > [EDIT] And how important is it that the times match?
>
> This effects nearly all time-related metrics, slow services, latency, response time percentiles, etc.
Just to double check that we are not excluding something unnecessarily I have been looking inside `on-finished`, was hoping to clear it but unfortunately I did actually find something which might be problematic with separate instances :( if you are curious it is the following at line 160:
```js
function createListener(msg) {
function listener(err) {
if (msg.__onFinished === listener) msg.__onFinished = null
```
`listener` would be different for different instances of `on-finished` module and so not sure what would happen but they might wind up overwriting each other's queues of listeners.
And I see how the time difference problem is caused in the reverted HttpPlugin, just need to bind `stopIfNotStopped()` to the actual end of the response processing without using `on-finished` (and verify change in order of span stop is ok).
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] tom-pytel commented on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
tom-pytel commented on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752936512
> > note the missing entry spans for the non-error / endpoint.
>
> Those are collapsed by me , only to show the full list
Ok, missed that, so my only doubt remains the use of `on-finished` in HttpPlugin, you understand my concern with the potential problem there no?
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] tom-pytel edited a comment on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
tom-pytel edited a comment on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752972776
The differences here in times are 6 and 25 ms. (ms resolution right? or ns?) Possibly lag due to event loop - data may all be sent and client may receive it and mark as complete but close event on server may not tick until after that. Or maybe still needs some work where to mark end in server.
Run my test with this and have a look, it all "looks" more or less right, but again more detailed checking needed.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] tom-pytel edited a comment on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
tom-pytel edited a comment on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752982531
> Hmm, I'm rechecking the expected data.
Looking at the code, the start times can not possibly be out of order, that would violate the laws of physics (causality, server span will not start unless the client span started and requested).
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] tom-pytel commented on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
tom-pytel commented on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752977972
> The tests failed because of `startTime` orders, so from my gut feelings the `close` / `end` should be related to the `endTime`, no?
Really? So did I misunderstand it? Because to me it appears it is the end times which were off?
```
segmentItems:
- serviceName: server
segmentSize: 1
segments:
- segmentId: d2f08d8dfd9e442d85540f8949d9a900
spans:
- operationName: /test
operationId: 0
parentSpanId: -1
spanId: 0
spanLayer: Http
startTime: 1609423678310
endTime: 1609423678327
componentId: 49
isError: false
spanType: Entry
peer: server:5000
skipAnalysis: false
tags:
- {key: http.url, value: 'server:5000/test'}
- {key: http.status.code, value: '200'}
refs:
- {parentEndpoint: '', networkAddress: 'server:5000', refType: CrossProcess,
parentSpanId: 1, parentTraceSegmentId: b7205383d91a4e94a5091aee9b711635, parentServiceInstance: 7179ea40313c,
parentService: client, traceId: 2015765c2630485baf62a9df450d210e}
- operationName: /json
operationId: 0
parentSpanId: 0
spanId: 1
spanLayer: Http
startTime: 1609423678312
endTime: 1609423678357
componentId: 2
isError: false
spanType: Exit
peer: httpbin.org
skipAnalysis: false
tags:
- {key: http.url, value: httpbin.org/json}
- {key: http.status.code, value: '200'}
- {key: http.status.msg, value: OK}
- serviceName: client
segmentSize: 1
segments:
- segmentId: b7205383d91a4e94a5091aee9b711635
spans:
- operationName: /test
operationId: 0
parentSpanId: -1
spanId: 0
spanLayer: Http
startTime: 1609423678286
endTime: 1609423678302
componentId: 49
isError: false
spanType: Entry
peer: localhost:5001
skipAnalysis: false
tags:
- {key: http.url, value: 'localhost:5001/test'}
- {key: http.status.code, value: '200'}
- operationName: /test
operationId: 0
parentSpanId: 0
spanId: 1
spanLayer: Http
startTime: 1609423678288
endTime: 1609423678351
componentId: 2
isError: false
spanType: Exit
peer: server:5000
skipAnalysis: false
tags:
- {key: http.url, value: 'server:5000/test'}
- {key: http.status.code, value: '200'}
- {key: http.status.msg, value: OK}
```
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] tom-pytel commented on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
tom-pytel commented on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-753318812
> @tom-pytel I think the tests all passed, and I run your tests locally, which seems to work well too, can you please take a look at the codes and verify the aforementioned tests if needed. Thanks
>
> BTW, Happy New Year !!
Thx, you too. Checked on my side with my tests and is ok.
I have one issue though, why did you remove `span.async()` and `config.span.resync()` in AxiosPlugin? Were you getting a problem? Because I put them back and my test still works fine.
The purpose of `async()` and `resync()` is as follows (since it is probably a little different from what these function names did originally when I started with this codebase) - The list of spans is now kept as an async task local variable so that spans get the correct parent hierarchy when created and multiple children can share the same parent (if they are running concurrently). In the case here what happens is that the axios request is about to return synchronously so it calls `span.async()` to remove itself from the current async task span list so that other spans which are created in this task do not have it as a parent since the real processing for the request will happen in another async context. That new async context is the function passed to `axios.interceptors.request.use()` and so when that function gets control `span.resync()` is called to re-add the span to the new task span list (which will be empty).
If this mechanism is removed then if there is something that creates a span between when `axios.Axios.prototype.request()` returns and when the `axios.interceptors.request.use()` handler gets control then that span will have this request as its parent, which is wrong. This something can be synchronous code that runs after the return from `request()` or something in the event loop scheduled before the new request handler function, high probability of something like this happening (like when creating multiple requests one after another) and so the `async()` and `resync()`.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] kezhenxu94 commented on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
kezhenxu94 commented on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-753324193
> don't remove but rather comment out the async() and resync() and leave them in the code along with a short comment TODO describing this situation.
Sounds good to me
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] kezhenxu94 edited a comment on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
kezhenxu94 edited a comment on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752944213
> how bad is the time difference?
By "not match", I meant for example, the `endTime` of the client side span is earlier than the `endTime` of the server side, which makes no sense at all.
> [EDIT] And how important is it that the times match?
This effects nearly all time-related metrics, slow services, latency, response time percentiles, etc.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] tom-pytel edited a comment on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
tom-pytel edited a comment on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752977972
> The tests failed because of `startTime` orders, so from my gut feelings the `close` / `end` should be related to the `endTime`, no?
Really? So did I misunderstand it? Because to me it appears it is the end times which were off? And yes if it really is `startTime` then that would not be `close` event, but you should use that one anyway.
```
segmentItems:
- serviceName: server
segmentSize: 1
segments:
- segmentId: d2f08d8dfd9e442d85540f8949d9a900
spans:
- operationName: /test
operationId: 0
parentSpanId: -1
spanId: 0
spanLayer: Http
startTime: 1609423678310
endTime: 1609423678327
componentId: 49
isError: false
spanType: Entry
peer: server:5000
skipAnalysis: false
tags:
- {key: http.url, value: 'server:5000/test'}
- {key: http.status.code, value: '200'}
refs:
- {parentEndpoint: '', networkAddress: 'server:5000', refType: CrossProcess,
parentSpanId: 1, parentTraceSegmentId: b7205383d91a4e94a5091aee9b711635, parentServiceInstance: 7179ea40313c,
parentService: client, traceId: 2015765c2630485baf62a9df450d210e}
- operationName: /json
operationId: 0
parentSpanId: 0
spanId: 1
spanLayer: Http
startTime: 1609423678312
endTime: 1609423678357
componentId: 2
isError: false
spanType: Exit
peer: httpbin.org
skipAnalysis: false
tags:
- {key: http.url, value: httpbin.org/json}
- {key: http.status.code, value: '200'}
- {key: http.status.msg, value: OK}
- serviceName: client
segmentSize: 1
segments:
- segmentId: b7205383d91a4e94a5091aee9b711635
spans:
- operationName: /test
operationId: 0
parentSpanId: -1
spanId: 0
spanLayer: Http
startTime: 1609423678286
endTime: 1609423678302
componentId: 49
isError: false
spanType: Entry
peer: localhost:5001
skipAnalysis: false
tags:
- {key: http.url, value: 'localhost:5001/test'}
- {key: http.status.code, value: '200'}
- operationName: /test
operationId: 0
parentSpanId: 0
spanId: 1
spanLayer: Http
startTime: 1609423678288
endTime: 1609423678351
componentId: 2
isError: false
spanType: Exit
peer: server:5000
skipAnalysis: false
tags:
- {key: http.url, value: 'server:5000/test'}
- {key: http.status.code, value: '200'}
- {key: http.status.msg, value: OK}
```
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] kezhenxu94 commented on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
kezhenxu94 commented on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-753327700
> Ok, well just out of curiosity and since it was a simple tweak I checked this and unfortunately the problem is not theoretical but actually fairly bad if there is no async / resync. If you are curious to see what happens the `client.js` line for my test is:
>
> ```js
> await Promise.all(new Array(100).fill().map(() => downloadPageA('localhost', 8100, '/')));
> ```
I'll also have a try (maybe tomorrow)
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] tom-pytel edited a comment on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
tom-pytel edited a comment on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752936512
> > note the missing entry spans for the non-error / endpoint.
>
> Those are collapsed by me , only to show the full list
Ok, missed that, so my only doubt remains the use of `on-finished` in HttpPlugin, you understand my concern with the potential problem there no?
[NOTE]: I am not CERTAIN that `on-finished` has internal state which could be problematic, but in cases like this I usually stay on the side of simplicity (not creating more dependanices) and safety.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] tom-pytel commented on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
tom-pytel commented on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752989147
I have another idea of what this might be, server doesn't close span until it gets confirmation from client that connection closed, in which case client would have closed span BEFORE server causing server to be a few ms. late.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] tom-pytel commented on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
tom-pytel commented on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752982531
> Hmm, I'm rechecking the expected data.
Looking at the code, the start times can not possibly be out of order, that would violate the laws of physics.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] tom-pytel commented on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
tom-pytel commented on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752964822
> > Hopefully this can be extracted as an individual reusable module / class. Also note not to copy the codes from on-finished because of licensing issues.
>
> Actually not even extract anything, I think its just adding a listener on request socket error or close and removing the `stopIfNotStopped()` in response listener.
Actually its as simple as removing `stopIfNotStopped()` on line 97 since the end of the request is already hooked to stop:
```js
request.on('close', stopIfNotStopped);
request.on('abort', () => (span.errored = true, stopIfNotStopped()));
request.on('error', (err) => (span.error(err), stopIfNotStopped()));
```
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] kezhenxu94 commented on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
kezhenxu94 commented on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752982299
Hmm, I'm rechecking the expected data.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] tom-pytel edited a comment on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
tom-pytel edited a comment on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752935083
> @tom-pytel this seems to be a problem caused by the removal of `topModule.require`, I removed it because of the reason I stated in [#13 (comment)](https://github.com/apache/skywalking-nodejs/pull/13#issue-542917887) , so again I added it back in this PR with a little refactor for both (env var and `topModule.require`), please take a look
Ok, well this is interesting, according to the image you attach the bug is not exactly fixed - note the missing entry spans for the non-error `/` endpoint. However, trying this branch on my side works fine, so unless you attached an older image by accident then we have differing behavior (which is a bug in and of itself).
More generally I am worried about HttpPlugin, why was it refactored? Specifically I am worried about the change to use `on-finished` from local `node_modules` which may change execution order with overriding plugins (express). But worse, I am worried the `on-finished` module used by skywalking may be different instance from what main app uses. If this is the case and `on-finished` has internal state then this could give undefined behavior. And this is not a case where you can just require the `on-finished` module using `topModule.require()` because for just the http plugin it is not guaranteed the main app will have this installed (for express this is guaranteed because express uses it so it is safe to `topModule.require()` in that plugin).
So for HttpPlugin, since I did actually spend a good bit of time making sure the order of execution was good with potential higher level modules and the actual higher level express, I would say that if there was no concrete reason for the refactor of HttpPlugin then that should be reverted, especially because of the potential problematic use of `on-finished`.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] tom-pytel commented on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
tom-pytel commented on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-753325231
> > Looks good to go then, will you do a 0.1.1 fix release?
>
> I'd like to have minor release, or if we could have the axios fixed within a reasonable time, I can also wait for that, WDYT?
I have an idea on how to tackle the axios thing but working on something else at the moment so may be a couple of days. In the meantime if you want you could check just how much of a problem it could be in the real world (it is a problem in theory but it may not manifest), the simple way would be to do a couple of hundred concurrent requests and see if there is any parent / child anomaly.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] kezhenxu94 commented on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
kezhenxu94 commented on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752944213
> how bad is the time difference?
By "match", I meant for example, the `endTime` of the client side span is earlier than the `endTime` of the server side, which makes no sense at all.
> [EDIT] And how important is it that the times match?
This effects nearly all time-related metrics, slow services, latency, response time percentiles, etc.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] tom-pytel edited a comment on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
tom-pytel edited a comment on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752961509
> > As for http I am sure there is a way to do it, I may just duplicate part of `on-finished` mechanism locally (doesn't look too difficult).
>
> Hopefully this can be extracted as an individual reusable module / class. Also note not to copy the codes from on-finished because of licensing issues.
Actually not even extract anything, I think its just adding a listener on request socket error or close and removing the `stopIfNotStopped()` in response listener.
> This is the last sort if it really needs. Just to search and see we have a fallback solution.
What problem are you actually trying to solve? Do you want to hook `require()` so that plugins are only installed when they are loaded? Or do you want to `require()` from the top level, which is what `PluginInstaller.require()` does? Or is it something else?
BTW: I don't know why the tests errored here, my test is fine with your latest push.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] tom-pytel edited a comment on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
tom-pytel edited a comment on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-753327297
Ok, well just out of curiosity and since it was a simple tweak I checked this and unfortunately the problem is not theoretical but actually fairly bad if there is no async / resync. If you are curious to see what happens the `client.js` line for my test is:
```js
await Promise.all(new Array(100).fill().map(() => downloadPageA('localhost', 8100, '/')));
```
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] tom-pytel commented on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
tom-pytel commented on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752935083
> @tom-pytel this seems to be a problem caused by the removal of `topModule.require`, I removed it because of the reason I stated in [#13 (comment)](https://github.com/apache/skywalking-nodejs/pull/13#issue-542917887) , so again I added it back in this PR with a little refactor for both (env var and `topModule.require`), please take a look
Ok, well this is interesting, according to the image you attach the bug is not exactly fixed - note the missing entry spans for the non-error `/` endpoint. However, trying this branch on my side works fine, so unless you attached an older image by accident then we have differing behavior (which is a bug in and of itself).
More generally I am worried about HttpPlugin, why was it refactored? Specifically I am worried about the change to use `on-finished` from local `node_modules` which may change execution order with overriding plugins (express). But worse, I am worried the `on-finished` module used by skywalking may be different instance from what main app uses. If this is the case and `on-finished` has internal state which controls its behavior then this could give undefined behavior. And this is not a case where you can just require the `on-finished` module using `topModule.require()` because for just the http plugin it is not guaranteed the main app will have this installed (for express this is guaranteed because express uses it so it is safe to `topModule.require()` in that plugin).
So for HttpPlugin, since I did actually spend a good bit of time making sure the order of execution was good with potential higher level modules and the actual higher level express, I would say that if there was no concrete reason for the refactor of HttpPlugin then that should be reverted, especially because of the potential problematic use of `on-finished`.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] tom-pytel commented on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
tom-pytel commented on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752940315
> Also, the refactor was to fix the problem that `startTime` and `endTime` of two sides (client / server) don't match, I'll revert and see whether the problem exists because of the orders are not perfectly good or other stuffs
Hmm, I had not considered that, how bad is the time difference?
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] kezhenxu94 edited a comment on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
kezhenxu94 edited a comment on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752935973
> note the missing entry spans for the non-error / endpoint.
Those are collapsed by me , only to show the full list
The solid dot means the sub-tree is collapsed / fold
<img width="175" alt="image" src="https://user-images.githubusercontent.com/15965696/103409353-61596b00-4ba1-11eb-803b-cce41e4a01ca.png">
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] kezhenxu94 edited a comment on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
kezhenxu94 edited a comment on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752983916
> Looking at the code, the start times can not possibly be out of order, that would violate the laws of physics (causality, server span will not start unless the client span started and requested).
My eyes blurred and mistook the two spans relationship, should be OK now, thank you Tom :)
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] kezhenxu94 edited a comment on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
kezhenxu94 edited a comment on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752964890
> BTW: I don't know why the tests errored here, my test is fine with your latest push.
<img width="1791" alt="image" src="https://user-images.githubusercontent.com/15965696/103412954-96ba8480-4bb2-11eb-8e11-5b4b38566f98.png">
The entry span's `startTime` is earlier than the exit span's `startTime`, here is the problem.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] kezhenxu94 commented on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
kezhenxu94 commented on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752964890
> BTW: I don't know why the tests errored here, my test is fine with your latest push.
<img width="1791" alt="image" src="https://user-images.githubusercontent.com/15965696/103412954-96ba8480-4bb2-11eb-8e11-5b4b38566f98.png">
The entry span's `startTime` is earlier than the exit span' `startTime`, here is the problem.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] kezhenxu94 commented on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
kezhenxu94 commented on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752935973
> note the missing entry spans for the non-error / endpoint.
Those are collapsed by me , only to show the full list
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] kezhenxu94 commented on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
kezhenxu94 commented on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752983916
> Looking at the code, the start times can not possibly be out of order, that would violate the laws of physics (causality, server span will not start unless the client span started and requested).
My eyes blurred and mistake the two spans relationship, should be OK now, thank you Tom :)
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] tom-pytel edited a comment on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
tom-pytel edited a comment on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752972776
The differences here in times are 6 and 25 ms. (ms resolution right? or ns?) Possibly lag due to event loop - data may all be sent and client may receive it and mark as complete but close event on server may not tick until after that. Or maybe still needs some work where to mark end in server.
Run my test with this and have a look, it all "looks" more or less right, but again more detailed checking needed. Changing the `end` event hook to `close` in `downloadPage()` and `downloadPageS()` functions in `client.js` and `srv_express.js`.
[test_updates.tar.gz](https://github.com/apache/skywalking-nodejs/files/5757479/test_updates.tar.gz)
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] kezhenxu94 commented on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
kezhenxu94 commented on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752995138
> > As a reminder, please check the intercepting points, if you fetch the timestamp of responding the first byte at server side, and read the timestamp of last byte received, the duration could be a negative value, due to the transport of the whole body needs time.
>
> What I meant is that I am not sure I am interpreting the test failure correctly, that it is due to server span end time AFTER client span end time.
I think the `endTime` should be correct now after `end` -> `close`, the failure may be something related to the "revert" of http plugin, I added some tag (or similar in the span) before so it failed now after revert, will check and ping you if there is still problem with the `{start,end}Times`
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [skywalking-nodejs] tom-pytel commented on pull request #20: Fix bug that some requests of express / axios are not close correctly
Posted by GitBox <gi...@apache.org>.
tom-pytel commented on pull request #20:
URL: https://github.com/apache/skywalking-nodejs/pull/20#issuecomment-752940051
> I can't agree more with the opinion, removing `on-finished` may be OK for now since we have very limited plugins that involve with `stream`, when we have more similar (involve with `stream`) plugin in the future, we may need to replicate the features of it someday, so that others don't need to "spend a good bit of time making sure the order of execution was good".
Any plugin for a module will be safe to `topModule.require()` whatever sub-modules that plugin module uses, without those sub-modules being installed for skywalking, so there will be no problem with missing dependencies or anything like that.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org