AI doesn't _seem_ to properly honor the response 'aborted' event

[nulltoken]

Hello,

We're seeing some intermittent issues from one of our dependencies.
It's reported as an exception in LogAnalytics by @hapijs/wreck that complains that "Payload stream closed prematurely".

• Googling around (eg. HTTP Client 'aborted' event fires even when request was ok nodejs/node#18756) seems to indicate
  that aborted is emitted when the socket is prematurely closed.

However, the dependency is reported as a successful call by AI. Which is... well... surprising ;-)

• https://nodejs.org/api/http.html#http_class_http_clientrequest states that "Unlike the request object, if the response closes prematurely, the response object does not emit an 'error' event but instead emits the 'aborted' event."

It's entirely possible that I'm reading the code wrong, but I can't find any place where the code subscribes to that event.

Thoughts?

ApplicationInsights-node.js/AutoCollection/HttpDependencies.ts

Lines 182 to 206 in c8fa5b8

	telemetry.request.on('response', (response: http.ClientResponse) => {
	requestParser.onResponse(response);
	var dependencyTelemetry = requestParser.getDependencyTelemetry(telemetry, uniqueRequestId);
	dependencyTelemetry.contextObjects = dependencyTelemetry.contextObjects || {};
	dependencyTelemetry.contextObjects["http.RequestOptions"] = telemetry.options;
	dependencyTelemetry.contextObjects["http.ClientRequest"] = telemetry.request;
	dependencyTelemetry.contextObjects["http.ClientResponse"] = response;
	client.trackDependency(dependencyTelemetry);
	});
	telemetry.request.on('error', (e: Error) => {
	requestParser.onError(e);
	var dependencyTelemetry = requestParser.getDependencyTelemetry(telemetry, uniqueRequestId);
	dependencyTelemetry.contextObjects = dependencyTelemetry.contextObjects || {};
	dependencyTelemetry.contextObjects["http.RequestOptions"] = telemetry.options;
	dependencyTelemetry.contextObjects["http.ClientRequest"] = telemetry.request;
	dependencyTelemetry.contextObjects["Error"] = e;
	client.trackDependency(dependencyTelemetry);
	});
	}

[markwolff]

• https://nodejs.org/api/http.html#http_class_http_clientrequest states that "Unlike the request object, if the response closes prematurely, the response object does not emit an 'error' event but instead emits the 'aborted' event."

Since this is the case, this is probably a bug on our end. I'll take a look and get it in to the next release, if so.

Just curious, how would you expect the telemetry to look like on your end for an aborted event? Would it be similar how we are handling the error event?

If an abort event occurs, I'm assuming neither the response nor error events occur? But since you stated that the telemetry is appearing as a success on your end, it makes me think that at least response is being emitted?

[nulltoken]

@markwolff Thanks for the feedback!

Just curious, how would you expect the telemetry to look like on your end for an aborted event?

From an logAnalytics standpoint, I'd very much like the dependency to not be reported with success=True even when the reported status code is 200. Driving a bit down that road, I'd even be in favor to not report the status code (as the response hasn't been completely sent). That would put under the light that something wrong happened with that dependency.

Would it be similar how we are handling the error event?

That would seem like a good fit: no resultCode, success=false, and a customDimensions.error property. I wonder if adding to customDimensions.error a hint about the kind of event that caused the issue would be interesting.

If an abort event occurs, I'm assuming neither the response nor error events occur? But since you stated that the telemetry is appearing as a success on your end, it makes me think that at least response is being emitted?

It looks like so. Sorry, I haven't locally repro'd the issue in a dev environment. I went straight from the LogInsights results to AInode.sdk in order to understand how the telemetry was processed.

[nulltoken]

@markwolff Hey! Has this been triaged yet?

[nulltoken]

@markwolff Hello again 😄

Any news on that topic?

[nulltoken]

@markwolff Hello. Any feedback?

[markwolff]

Hi @nulltoken I've stubbed out a PR for this, but I haven't had the cycles to create an environment where an abort event will take place. Do you have a repro that I would be able to try my changes on?

[nulltoken]

Do you have a repro that I would be able to try my changes on?

@markwolff Thanks for getting back. Unfortunately, I haven't any repro at hand. As described in the initial comment this has been discovered by analyzing logs and reading the code of AInode.js.

[nulltoken]

@markwolff How should we proceed in order to move further?

[nulltoken]

@markwolff Kind bump?

[nulltoken]

@hectorhdzg It looks like @markwolff is not answering. Would you know someone that could help moving this forward?

[hectorhdzg]

@nulltoken sorry about the delay, we do have this item in our backlog and also there is is similar issue #741 raised recently, we will include this work in our next iteration, we need to sync with other SDKs to determine what is the correct way to set the dependency in this case and hopefully is a simple change in our side

[nulltoken]

@hectorhdzg Thanks a lot for the feedback!