fix(proxy): Add missing timings to non-http backend requests

[domdom82]

• A short explanation of the proposed change:

Fixes gorouter_time is equal to response_time

The request_handler responsible for websocket backends does not implement timing events, yet. This leads to gorouter_time being equal to response_time as there is no app_time recorded.

The same is true for all attempt details (backend_time, dial_time, tls_time, dns_time and failed_attempts_time) if enable_log_attempts_details is enabled.

• An explanation of the use cases your change solves

• Correct timings also for non-HTTP backends. gorouter_time should only include time spent within the gorouter process, not time spent at (websocket-) backends.
• Measure attempt details for websocket requests, too. This includes backend_time, dial_time, tls_time, failed_attempts_time and failed_attempts and should behave like the measurements taken for regular HTTP requests in ProxyRoundTripper. dns_time will not be recorded because dns lookups will only ever occur on route service URLs.

• Instructions to functionally test the behavior change using operator interfaces (BOSH manifest, logs, curl, and metrics)

1. push a websocket app
2. curl it
3. (optional) turn enable_log_attempts_details on

• Expected result after the change

gorouter_time and response_time should differ (with response_time being much larger than gorouter_time)

(optional)

backend_time, dial_time and tls_time should be present in the access log

• Current result before the change

gorouter_time and response_time are equal

(optional)

backend_time, dial_time and tls_time are not present in the access log

• Links to any other associated PRs

Companion PR to vendor golang.org/x/net/websocket (needs to be merged first)

• I have viewed signed and have submitted the Contributor License Agreement

• I have made this pull request to the main branch

• I have run all the unit tests using scripts/run-unit-tests-in-docker from routing-release.

• (Optional) I have run Routing Acceptance Tests and Routing Smoke Tests on bosh lite

• (Optional) I have run CF Acceptance Tests on bosh lite

[ameowlia]

1. ✅ I validated the issue you were seeing using your app.

Here is an example of a websocket connection where the response_time and the gorouter_time are equal.

2023-10-04T21:11:15.43+0000 [RTR/0] OUT go-responder.band-160711.cf-app.com - [2023-10-04T21:10:54.808352375Z] "GET /ws HTTP/1.1" 101 0 0 "-" "curl/7.81.0" "10.0.1.9:21418" "10.0.1.14:61002" x_forwarded_for:"10.0.1.9" x_forwarded_proto:"http" vcap_request_id:"9b302968-b59d-41d3-56a8-3c189d00e53a" response_time:20.628416 gorouter_time:20.628416 app_id:"ff858e3a-87ab-4566-8abb-534d8ac06e9e" app_index:"0" instance_id:"5e2a742c-6fe0-4ca5-6c7d-0492" x_cf_routererror:"-" x_b3_traceid:"3e86f4ce18bf70a02ac3d78b87092fbd" x_b3_spanid:"2ac3d78b87092fbd" x_b3_parentspanid:"-" b3:"3e86f4ce18bf70a02ac3d78b87092fbd-2ac3d78b87092fbd"

2. ✅ I validated that your update fixed the issue

2023-10-04T21:41:23.83+0000 [RTR/0] OUT go-responder.band-160711.cf-app.com - [2023-10-04T21:41:10.591502359Z] "GET /ws HTTP/1.1" 101 0 0 "-" "curl/7.81.0" "10.0.1.9:41256" "10.0.1.14:61002" x_forwarded_for:"10.0.1.9" x_forwarded_proto:"http" vcap_request_id:"15000039-c2fc-41c8-40cb-ea974f6dfc83" response_time:13.243427 gorouter_time:0.000428 app_id:"ff858e3a-87ab-4566-8abb-534d8ac06e9e" app_index:"0" instance_id:"5e2a742c-6fe0-4ca5-6c7d-0492" x_cf_routererror:"-" x_b3_traceid:"15000039c2fc41c840cbea974f6dfc83" x_b3_spanid:"40cbea974f6dfc83" x_b3_parentspanid:"-" b3:"15000039c2fc41c840cbea974f6dfc83-40cbea974f6dfc83"

3. ✅ I validated that your update worked when enable_log_attempts_details is enabled.

2023-10-04T21:45:08.56+0000 [RTR/0] OUT go-responder.band-160711.cf-app.com - [2023-10-04T21:44:58.730948099Z] "GET /ws HTTP/1.1" 101 0 0 "-" "curl/7.81.0" "10.0.1.9:58760" "10.0.1.14:61002" x_forwarded_for:"10.0.1.9" x_forwarded_proto:"http" vcap_request_id:"f611f8ac-0d2a-4318-759d-d194c46b6170" response_time:9.837065 gorouter_time:0.000473 app_id:"ff858e3a-87ab-4566-8abb-534d8ac06e9e" app_index:"0" instance_id:"5e2a742c-6fe0-4ca5-6c7d-0492" failed_attempts:0 failed_attempts_time:"-" dns_time:"-" dial_time:0.001511 tls_time:0.005989 backend_time:9.836591 x_cf_routererror:"-" x_b3_traceid:"f611f8ac0d2a4318759dd194c46b6170" x_b3_spanid:"759dd194c46b6170" x_b3_parentspanid:"-" b3:"f611f8ac0d2a4318759dd194c46b6170-759dd194c46b6170"

Overall it would be great to remove as many sleeps as we can from the tests. But other than that, it looks good. Thank you for doing this important work!

[domdom82]

hi @ameowlia thanks for the review! I've made all second sleeps into millisecond sleeps, saving about 5s of runtime for the proxy suite. I've also fixed some of the regular http access log tests and reduced their sleep times to 100ms each.