Fix bug that some requests of express / axios are not close correctly

[kezhenxu94]

Closes apache/skywalking#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 #13 (comment) , so again I added it back in this PR with a little refactor for both (env var and topModule.require), please take a look

[tom-pytel]

@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) , 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.

[kezhenxu94]

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

[tom-pytel]

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.

[kezhenxu94]

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

[kezhenxu94]

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

[tom-pytel]

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.

[tom-pytel]

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?

[kezhenxu94]

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.

[tom-pytel]

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:

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).

[kezhenxu94]

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

[tom-pytel]

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?

[kezhenxu94]

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.

[tom-pytel]

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.

[tom-pytel]

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:

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.

[kezhenxu94]

BTW: I don't know why the tests errored here, my test is fine with your latest push.

The entry span's startTime is earlier than the exit span's startTime, here is the problem.

[kezhenxu94]

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:

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

[tom-pytel]

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.

[tom-pytel]

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

[kezhenxu94]

The tests failed because of startTime orders, so from my gut feelings the close / end should be related to the endTime, no?

[tom-pytel]

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}

[kezhenxu94]

Hmm, I'm rechecking the expected data.

[tom-pytel]

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).

[kezhenxu94]

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 :)

[tom-pytel]

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.

[tom-pytel]

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?

[wu-sheng]

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.

[tom-pytel]

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.

[wu-sheng]

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.

[kezhenxu94]

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

[kezhenxu94]

@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 🎉 !!

[tom-pytel]

@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().

[kezhenxu94]

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

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).

[tom-pytel]

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.

[kezhenxu94]

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

[kezhenxu94]

So I think this is good to merge for now right? @tom-pytel

[tom-pytel]

Looks good to go then, will you do a 0.1.1 fix release?

[kezhenxu94]

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?

[tom-pytel]

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.

[kezhenxu94]

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.

[tom-pytel]

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:

await Promise.all(new Array(100).fill().map(() => downloadPageA('localhost', 8100, '/')));

[kezhenxu94]

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:

await Promise.all(new Array(100).fill().map(() => downloadPageA('localhost', 8100, '/')));

I'll also have a try (maybe tomorrow)