Setting ReadDeadline every time we receive an incoming message

[gracegoo-stripe]

Reviewers

r? @bernerd-stripe
cc @stripe/developer-products

Summary

I noticed that we were seeing an decrease in ACKs as the # of event we sent from the backend server went up. I was able to find logs from the CLI side that indicated that the read deadline was exceeded:

[Thu, 15 Sep 2022 12:04:31 PDT] DEBUG websocket.Client.Close: read error: read unix ->/Users/gracegoo/.stripeproxy: i/o timeout

When we have a lot of real messages incoming, the backend prioritizes those over the pongs. However, the CLI was only re-setting the deadlines on Pongs and not incoming messages. This change moves the deadline setting logic to within the read loop.

Testing

I reproduced this by disabling pongs from the server.
With no incoming message, we establish connection at 12:04:21 and get a read error at 12:04:31
With an incoming message, we connect at 12:04:54 and get a read error at 12:05:06. 10 seconds after the incoming message.

[Thu, 15 Sep 2022 12:04:20 PDT] DEBUG websocket.client.Run: Attempting to connect to Stripe
[Thu, 15 Sep 2022 12:04:20 PDT] DEBUG websocket.Client.connect: Dialing websocket url=ws://gracegoo-stripecli-ws-mydev.dev.stripe.me/subscribe/acct_28DT589O8KAxCGbLmxyZ?websocket_feature=webhook-payloads
[Thu, 15 Sep 2022 12:04:21 PDT] DEBUG websocket.client.connect: Connected!
[Thu, 15 Sep 2022 12:04:21 PDT] DEBUG Setting read deadline: 
[Thu, 15 Sep 2022 12:04:23 PDT] DEBUG websocket.Client.writePump: Sending ping message
[Thu, 15 Sep 2022 12:04:25 PDT] DEBUG websocket.Client.writePump: Sending ping message
[Thu, 15 Sep 2022 12:04:27 PDT] DEBUG websocket.Client.writePump: Sending ping message
[Thu, 15 Sep 2022 12:04:29 PDT] DEBUG websocket.Client.writePump: Sending ping message
[Thu, 15 Sep 2022 12:04:31 PDT] DEBUG websocket.Client.Close: read error: read unix ->/Users/gracegoo/.stripeproxy: i/o timeout
[Thu, 15 Sep 2022 12:04:31 PDT] DEBUG websocket.client.Run: Disconnected from Stripe
[Thu, 15 Sep 2022 12:04:31 PDT] DEBUG websocket.Client.writePump: Sending ping message
[Thu, 15 Sep 2022 12:04:31 PDT] DEBUG websocket.Client.writePump: Failed to send ping; connection is resetting

Thu, 15 Sep 2022 12:04:54 PDT] DEBUG websocket.client.Run: Attempting to connect to Stripe
[Thu, 15 Sep 2022 12:04:54 PDT] DEBUG websocket.Client.connect: Dialing websocket url=ws://gracegoo-stripecli-ws-mydev.dev.stripe.me/subscribe/acct_28DT589O8KAxCGbLmxyZ?websocket_feature=webhook-payloads
[Thu, 15 Sep 2022 12:04:54 PDT] DEBUG websocket.client.connect: Connected!
[Thu, 15 Sep 2022 12:04:54 PDT] DEBUG Setting read deadline: 
[Thu, 15 Sep 2022 12:04:55 PDT] DEBUG websocket.Client.readPump: Incoming message ...
[Thu, 15 Sep 2022 12:04:55 PDT] DEBUG Setting read deadline: 
[Thu, 15 Sep 2022 12:04:55 PDT] DEBUG proxy.Proxy.processWebhookEvent: Processing webhook event webhook_converesation_id=1663268695-wc_FRXbwIgTS60jZz webhook_id=1663268689-wh_WMGEFETu2DjcTD
[Thu, 15 Sep 2022 12:04:55 PDT] DEBUG proxy.Proxy.filterWebhookEvent: Received event with non-default API version, ignoring api_version=2022-08-01
[Thu, 15 Sep 2022 12:04:55 PDT] DEBUG websocket.Client.writePump: Sending text message
[Thu, 15 Sep 2022 12:04:56 PDT] DEBUG websocket.Client.readPump: Incoming message ...
[Thu, 15 Sep 2022 12:04:56 PDT] DEBUG Setting read deadline: 
[Thu, 15 Sep 2022 12:04:56 PDT] DEBUG proxy.Proxy.processWebhookEvent: Processing webhook event webhook_converesation_id=1663268696-wc_6giSbs9CnyPiOo webhook_id=1663268696-wh_w5XCTRqrnzxmQq
2022-09-15 12:04:56   --> connect balance.available [evt_0LiNMq589O8KAxCGipfrCS3d]
[Thu, 15 Sep 2022 12:04:56 PDT] DEBUG websocket.Client.writePump: Sending text message
[Thu, 15 Sep 2022 12:04:56 PDT] DEBUG websocket.Client.readPump: Incoming message ...
[Thu, 15 Sep 2022 12:04:56 PDT] DEBUG Setting read deadline: 
[Thu, 15 Sep 2022 12:04:56 PDT] DEBUG proxy.Proxy.processWebhookEvent: Processing webhook event webhook_converesation_id=1663268696-wc_0AOZgcZsBq2UoG webhook_id=1663268696-wh_4MMy3bYl52v4qn
[Thu, 15 Sep 2022 12:04:56 PDT] DEBUG proxy.Proxy.filterWebhookEvent: Received event with non-default API version, ignoring api_version=2022-08-01
[Thu, 15 Sep 2022 12:04:56 PDT] DEBUG websocket.Client.writePump: Sending text message
[Thu, 15 Sep 2022 12:04:56 PDT] DEBUG websocket.Client.readPump: Incoming message ...
[Thu, 15 Sep 2022 12:04:56 PDT] DEBUG Setting read deadline: 
[Thu, 15 Sep 2022 12:04:56 PDT] DEBUG proxy.Proxy.processWebhookEvent: Processing webhook event webhook_converesation_id=1663268696-wc_OHu4jJRwGTeZ3n webhook_id=1663268696-wh_48A1GLPeEMmfXF
2022-09-15 12:04:56   --> balance.available [evt_0LiNMq589O8KAxCGoq68HOkW]
[Thu, 15 Sep 2022 12:04:56 PDT] DEBUG websocket.Client.writePump: Sending text message
[Thu, 15 Sep 2022 12:04:56 PDT] DEBUG websocket.Client.writePump: Sending ping message
[Thu, 15 Sep 2022 12:04:58 PDT] DEBUG websocket.Client.writePump: Sending ping message
[Thu, 15 Sep 2022 12:05:00 PDT] DEBUG websocket.Client.writePump: Sending ping message
[Thu, 15 Sep 2022 12:05:02 PDT] DEBUG websocket.Client.writePump: Sending ping message
[Thu, 15 Sep 2022 12:05:04 PDT] DEBUG websocket.Client.writePump: Sending ping message
[Thu, 15 Sep 2022 12:05:06 PDT] DEBUG websocket.Client.Close: read error: read unix ->/Users/gracegoo/.stripeproxy: i/o timeout