gorouter_time is equal to response_time for WebSocket requests

[domdom82]

Issue

For regular HTTP requests we distinguish between the actual response_time (i.e. the time it takes the backend to send a complete HTTP response) and gorouter_time (processing time gorouter takes locally):

xsuaa-router.cfapps.cfi06.aws.cfi.sapcloud.io - [2022-07-07T08:44:06.497191376Z] "GET /oauth/token HTTP/1.1" 200 0 22 "-" "Apache-HttpClient/4.5.12 (Java/1.8.0_275)" "10.0.72.2:54398" "10.0.73.0:61012" x_forwarded_for:"3.126.170.147, 10.0.72.2" x_forwarded_proto:"https" vcap_request_id:"0d2b2fcf-7859-493d-62c3-98417d66e1a3" response_time:1.099722 gorouter_time:0.000079 app_id:"b78f6af3-8e05-4fc9-8499-cd2cbeb5d78d" app_index:"2" instance_id:"425c45fc-6c32-499b-40a5-e07c" x_cf_routererror:"-" x_correlationid:"-" tenantid:"-" sap_passport:"-" x_scp_request_id:"6a461a1a-ab66-4fed-8bfd-e1bca7ffdb09-62C69CD6-CD0B4C2" x_cf_app_instance:"-" x_forwarded_host:"-" x_custom_host:"-" x_ssl_client:"-" x_ssl_client_session_id:"-" x_ssl_client_verify:"-" x_ssl_client_subject_dn:"-" x_ssl_client_subject_cn:"-" x_ssl_client_issuer_dn:"-" x_ssl_client_notbefore:"-" x_ssl_client_notafter:"-" traceparent:"-" x_b3_traceid:"5984256f2c0724f907e2c0fa23bf9b20" x_b3_spanid:"07e2c0fa23bf9b20" x_b3_parentspanid:"-" b3:"5984256f2c0724f907e2c0fa23bf9b20-07e2c0fa23bf9b20"

Note the two times

response_time:1.099722 gorouter_time:0.000079

are vastly different. This helps find out if the gorouter is slow or the backend app.

However, for WebSocket requests this distinction is not made and gorouter_time always equals response_time.
Here is an example WebSocket request that took around 13s:

[2022-07-07T08:33:25.788250761Z] "GET /ws2 HTTP/1.1" 101 0 0 "-" "curl/7.82.0" "10.0.72.2:30556" "10.0.73.7:61000" x_forwarded_for:"193.16.224.4, 10.0.72.2" x_forwarded_proto:"https" vcap_request_id:"fce4147a-7e93-4db3-4329-b6ef2117b343" response_time:13.110876 gorouter_time:13.110876 app_id:"09c35613-763f-4cc4-b8b7-53f8315e844a" app_index:"0" instance_id:"5ef8f217-694f-4710-6ee9-4ff8" x_cf_routererror:"-" x_correlationid:"-" tenantid:"-" sap_passport:"-" x_scp_request_id:"6a461a1a-ab66-4fed-8bfd-e1bca7ffdb09-62C69A55-CCCCEC9" x_cf_app_instance:"-" x_forwarded_host:"-" x_custom_host:"-" x_ssl_client:"-" x_ssl_client_session_id:"-" x_ssl_client_verify:"-" x_ssl_client_subject_dn:"-" x_ssl_client_subject_cn:"-" x_ssl_client_issuer_dn:"-" x_ssl_client_notbefore:"-" x_ssl_client_notafter:"-" traceparent:"-" x_b3_traceid:"2c410db38beef5f33ce5e3ce5f16e13e" x_b3_spanid:"3ce5e3ce5f16e13e" x_b3_parentspanid:"-" b3:"2c410db38beef5f33ce5e3ce5f16e13e-3ce5e3ce5f16e13e"

Note the two times

response_time:13.110876 gorouter_time:13.110876

have exactly the same value.

Affected Versions

all

Context

It's probably related to the different ways WebSockets and regular HTTP requests are handled.

Steps to Reproduce

1. Deploy a websocket app. For example you can use go-responder
   With the following config.yml

servers:
  - websocket:
      port: 8080
      responses:
        /ws:
          read:
            bufsize: 1M
          write:
            bufsize: 100B
            type: lorem
            delay: 1s

(the above config will start a websocket server at /ws that writes 100B of lorem ipsum text at 1s intervals)

2. Curl the websocket app

curl --include \
     --no-buffer \
     --header "Connection: Upgrade" \
     --header "Upgrade: websocket" \
     --header "Host: go-responder.cfapp.com" \
     --header "Origin: https://go-responder.cfapp.com/ws" \
     --header "Sec-WebSocket-Key: SGVsbG8sIHdvcmxkIQ==" \
     --header "Sec-WebSocket-Version: 13" \
     https://go-responder.cfapp.com/ws

3. Check access.log

Expected result

The gorouter_time should equal the time for gorouter local processing only, without the response time.

Current result

gorouter_time equals response_time

[ameowlia]

🐛 Good find!

[domdom82]

@dsabeti @ameowlia I've opened a PR to finally fix this. There are a couple more issues with websockets (e.g. missing session affinity ) for which I also have fixes that are currently blocked by this issue. Since we have a customer waiting for a fix, can someone review this or assign a reviewer? Thanks ☺️