search

cloudfoundry / gorouter

CF Router
Apache License 2.0
441 stars 224 forks source link

fix(proxy): Read request before sending response in proxy test #415

Closed domdom82 closed 4 months ago

domdom82 commented 4 months ago

Summary

This PR fixes two flaky tests that are failing occasionally check the first attempt of "gorouter-mysql-8.0":

Proxy WebSocket Connections [It] emits a xxx metric
/tmp/build/0a0912a0/repo/src/code.cloudfoundry.org/gorouter/proxy/proxy_test.go:2688

  Captured StdOut/StdErr Output >>
  2024/05/06 15:47:23 Unsolicited response received on idle HTTP channel starting with "HTTP/1.1 101 Switching Protocols\r\nConnection: Upgrade\r\nUpgrade: Websocket\r\n\r\n"; err=<nil>
  2024/05/06 15:47:23 http: proxy error: readLoopPeekFailLocked: %!w(<nil>)
  << Captured StdOut/StdErr Output

  Timeline >>
  {"log_level":1,"timestamp":1715010443.1237323,"message":"route-registered","source":"test","data":{"uri":"ws-cs-header"}}
  {"log_level":0,"timestamp":1715010443.1237686,"message":"uri-added","source":"test","data":{"uri":"ws-cs-header"}}
  {"log_level":1,"timestamp":1715010443.1238031,"message":"endpoint-registered","source":"test","data":{"uri":"ws-cs-header","route_service_url":"","backend":"127.0.0.1:35043","application_id":"","instance_id":"","server_cert_domain_san":"","protocol":"","modification_tag":{"guid":"","index":0},"isolation_segment":"-","isTLS":false}}
  {"log_level":0,"timestamp":1715010443.124316,"message":"vcap-request-id-header-set","source":"test","data":{"VcapRequestIdHeader":"10898042-26af-40e6-4044-6aa276e73386"}}
  {"log_level":0,"timestamp":1715010443.1245792,"message":"backend","source":"test","data":{"route-endpoint":{"ApplicationId":"","Addr":"127.0.0.1:35043","Tags":null,"RouteServiceUrl":"","AZ":""},"attempt":1}}
  {"log_level":0,"timestamp":1715010443.125939,"message":"vcap-request-id-header-set","source":"test","data":{"VcapRequestIdHeader":"6370a80c-a14a-436f-55de-2384a3171b0e"}}
  {"log_level":0,"timestamp":1715010443.1261995,"message":"backend","source":"test","data":{"route-endpoint":{"ApplicationId":"","Addr":"127.0.0.1:35043","Tags":null,"RouteServiceUrl":"","AZ":""},"attempt":1}}
  {"log_level":3,"timestamp":1715010443.126942,"message":"backend-endpoint-failed","source":"test","data":{"route-endpoint":{"ApplicationId":"","Addr":"127.0.0.1:35043","Tags":null,"RouteServiceUrl":"","AZ":""},"error":"incomplete request (readLoopPeekFailLocked: %!w(<nil>))","attempt":1,"vcap_request_id":"6370a80c-a14a-436f-55de-2384a3171b0e","retriable":true,"num-endpoints":1,"got-connection":true,"wrote-headers":false,"conn-reused":false,"dns-lookup-time":0,"dial-time":0.00015274,"tls-handshake-time":0}}
  [FAILED] in [It] - /tmp/build/0a0912a0/repo/src/code.cloudfoundry.org/gorouter/proxy/proxy_test.go:2715 @ 05/06/24 15:47:24.128
  << Timeline

  [FAILED] Timed out after 1.000s.
  Expected
      <int>: 1
  to equal
      <int>: 2
  In [It] at: /tmp/build/0a0912a0/repo/src/code.cloudfoundry.org/gorouter/proxy/proxy_test.go:2715 @ 05/06/24 15:47:24.128

  Full Stack Trace
    code.cloudfoundry.org/gorouter/proxy_test.init.func5.11.6()
        /tmp/build/0a0912a0/repo/src/code.cloudfoundry.org/gorouter/proxy/proxy_test.go:2715 +0x225

The test failed because it expected no retries, however it did retry because the first attempt failed due to this error:

  2024/05/06 15:47:23 Unsolicited response received on idle HTTP channel starting with "HTTP/1.1 101 Switching Protocols\r\nConnection: Upgrade\r\nUpgrade: Websocket\r\n\r\n"; err=<nil>
  2024/05/06 15:47:23 http: proxy error: readLoopPeekFailLocked: %!w(<nil>)

I've identified this issue in the PR and added a fix. The fix is that we first need to read the request before sending a response (which is according to the RFC for HTTP, hence the error message from golang). "Unsolicited" HTTP responses without a corresponding HTTP request are non-compliant with the protocol.

Backward Compatibility

Breaking Change? No