Instrumentation: fix log trace inconsistent status code with timeout check when writing the response

[1pkg]

Motivation/summary

This fix is branched from #15117.

This PR replaces TimeoutMiddleware with proactively checking for context timeout before writing the response result. The rationale behind this change is that request timeout only ever matters if it happened before the response was written. Otherwise, the client won't care about the response anyway and it's logical for the server to emit either of two error signals consistently in self instrumentation at this stage.

As a result of this changes depending if request timeout happened before or after response was written the self instrumentation will either emit original error transaction with an error log or timeout error transaction with an error log.

This is alternative to errors chaining PR #15122 which will preserve both error logs. Update: After some brief discussion we agreed to move forward with this option for the fix instead of more complex error chaining.

Checklist

• Update CHANGELOG.asciidoc
• Documentation has been updated

For functional changes, consider:

• Is it observable through the addition of either logging or metrics?
• Is its use being published in telemetry to enable product improvement?
• Have system tests been added to avoid regression?

How to test these changes

This PR includes a unit test that encapsulates the condition to simulate the issue. In order to reproduce against a real instance of APM Server follow the recipe from this comment #14232 (comment).

Related issues

#15122
#15117
Fixes #14232

[mergify]

This pull request does not have a backport label. Could you fix it @1pkg? 🙏
To fixup this pull request, you need to add the backport labels for the needed
branches, such as:

• backport-7.17 is the label to automatically backport to the 7.17 branch.
• backport-8./d is the label to automatically backport to the 8./d branch. /d is the digit.
• backport-8.x is the label to automatically backport to the 8.x branch.

[mergify]

backport-8.x has been added to help with the transition to the new branch 8.x.
If you don't need it please use backport-skip label.

[carsonip]

I like the simplicity of this fix. Then I realize we may also be tracking the wrong status code in MonitoringMiddleware in the past as timeout middleware is after monitoring middleware. We should also add assertions in the same test TestWrapServerAPMInstrumentationTimeout.

I'm still thinking whether not logging a body write timeout is a deal breaker, as this PR would hide body write timeouts in log_middleware. I don't mind inconsistent status code between log and trace when it is a body write timeout.

[carsonip]

Then I realize we may also be tracking the wrong status code in MonitoringMiddleware in the past as timeout middleware is after monitoring middleware. We should also add assertions in the same test TestWrapServerAPMInstrumentationTimeout.

After banging my head against the wall for a bit, here you go:

 
+       monitoringtest.ClearRegistry(intake.MonitoringMap)
+
        req, err := http.NewRequestWithContext(reqCtx, http.MethodPost, srv.URL+api.IntakePath, bytes.NewReader(testData))
        require.NoError(t, err)
        req.Header.Add("Content-Type", "application/x-ndjson")
@@ -622,6 +627,15 @@ func TestWrapServerAPMInstrumentationTimeout(t *testing.T) {
        case <-found:
 
        }
+
+       equal, result := monitoringtest.CompareMonitoringInt(map[request.ResultID]int{
+               request.IDRequestCount:          2,
+               request.IDResponseCount:         2,
+               request.IDResponseErrorsCount:   1,
+               request.IDResponseErrorsTimeout: 1, // test data POST /intake/v2/events
+               request.IDResponseValidAccepted: 1, // self-instrumentation
+       }, intake.MonitoringMap)
+       assert.True(t, equal, result)
 }
 

[carsonip]

At a high level this is fine. The edge case about timeout during writing body can actually be handled on line 229 in c.errOnWrite(err), where log middleware can log the timeout, but I don't think we can correct tracing at that point. After all, it is kind of debatable how we should handle write timeouts. If an original response status code is 200, and you have successfully written that to the socket, which means the client actually receives 200, but then times out during the body, does it mean the logged / traced status code should then become 5xx? I'm not sure.

I believe in this PR we should focus on fixing the common case where context is canceled before writing status code, and ensuring logged, traced, and monitored status codes are consistent in this case.

[1pkg]

Then I realize we may also be tracking the wrong status code in MonitoringMiddleware in the past as timeout middleware is after monitoring middleware. We should also add assertions in the same test TestWrapServerAPMInstrumentationTimeout.

After banging my head against the wall for a bit, here you go:

 
+       monitoringtest.ClearRegistry(intake.MonitoringMap)
+
        req, err := http.NewRequestWithContext(reqCtx, http.MethodPost, srv.URL+api.IntakePath, bytes.NewReader(testData))
        require.NoError(t, err)
        req.Header.Add("Content-Type", "application/x-ndjson")
@@ -622,6 +627,15 @@ func TestWrapServerAPMInstrumentationTimeout(t *testing.T) {
        case <-found:
 
        }
+
+       equal, result := monitoringtest.CompareMonitoringInt(map[request.ResultID]int{
+               request.IDRequestCount:          2,
+               request.IDResponseCount:         2,
+               request.IDResponseErrorsCount:   1,
+               request.IDResponseErrorsTimeout: 1, // test data POST /intake/v2/events
+               request.IDResponseValidAccepted: 1, // self-instrumentation
+       }, intake.MonitoringMap)
+       assert.True(t, equal, result)
 }
 

Excellent suggestion @carsonip, I updated the tests to validate metrics middleware results per your comment.

[carsonip]

lgtm, thanks. Great clean fix. Can you update the PR description testing section please?

[inge4pres]

👍🏼 thanks for working on it and fixing it folks 🙏🏼