stripe-cli: Stripe CLI is not receiving all events

Issue

I have noticed that some webhooks fail to forward to my localhost. It seems that all the failures occur because of a proxy filter within Stripe CLI saying Received event with non-default API version, ignoring (discovered when setting the --log-level debug flag).

NB. I am testing the Checkout flow and forwarding webhooks to my localhost eg. stripe listen --forward-to localhost:4040/webhooks/stripe

This looks like the same issue as #435

Expected Behavior

All webhooks to be forwarded to my localhost.

Steps to reproduce

I cannot reliably reproduce this failure on the first try. But I can reliably reproduce the error. I just try multiple checkout payments and one of them will eventually not send.

Traceback

I have tidied up all the Incoming message lines to make the logs a bit easier to read. This is all against the testing gateway.

2021-03-01 16:56:30  <--  [200] POST http://localhost:4040/webhooks/stripe [evt_1IQF2nJLFSG5VKTEvfb8W4OR]
[Mon, 01 Mar 2021 16:56:30 GMT] DEBUG websocket.Client.writePump: Sending text message
[Mon, 01 Mar 2021 16:56:30 GMT] DEBUG websocket.Client.readPump: Incoming message message={}
[Mon, 01 Mar 2021 16:56:30 GMT] DEBUG proxy.Proxy.processWebhookEvent: Processing webhook event webhook_converesation_id=1614617789-wc_y8Rfvd5IQo1hns webhook_id=1614617789-wh_rjZO3UreO9Rklo
[Mon, 01 Mar 2021 16:56:30 GMT] DEBUG proxy.Proxy.filterWebhookEvent: Received event with non-default API version, ignoring api_version=0xc0001e17b0
[Mon, 01 Mar 2021 16:56:30 GMT] DEBUG websocket.Client.readPump: Incoming message message={}
[Mon, 01 Mar 2021 16:56:30 GMT] DEBUG proxy.Proxy.processWebhookEvent: Processing webhook event webhook_converesation_id=1614617789-wc_aBi2yyUKaHwuHx webhook_id=1614617789-wh_1sDpFPjdNVHWV6
2021-03-01 16:56:30   --> payment_intent.succeeded [evt_1IQF2nJLFSG5VKTEQ2799tbS]
[Mon, 01 Mar 2021 16:56:30 GMT] DEBUG proxy.EndpointClient.Post: Forwarding event to local endpoint
2021-03-01 16:56:30  <--  [200] POST http://localhost:4040/webhooks/stripe [evt_1IQF2nJLFSG5VKTEQ2799tbS]
[Mon, 01 Mar 2021 16:56:30 GMT] DEBUG websocket.Client.writePump: Sending text message
[Mon, 01 Mar 2021 16:56:30 GMT] DEBUG websocket.Client.readPump: Incoming message message={}
[Mon, 01 Mar 2021 16:56:30 GMT] DEBUG proxy.Proxy.processWebhookEvent: Processing webhook event webhook_converesation_id=1614617789-wc_P52gABQKDCFHU4 webhook_id=1614617789-wh_iw7XGGaVraalJM
[Mon, 01 Mar 2021 16:56:30 GMT] DEBUG proxy.Proxy.filterWebhookEvent: Received event with non-default API version, ignoring api_version=0xc0000aa480
[Mon, 01 Mar 2021 16:56:31 GMT] DEBUG websocket.Client.readPump: Incoming message message={}
[Mon, 01 Mar 2021 16:56:31 GMT] DEBUG proxy.Proxy.processWebhookEvent: Processing webhook event webhook_converesation_id=1614617790-wc_acJCGdJQvVYIKW webhook_id=1614617789-wh_LFQtCxQXw7SV8k
2021-03-01 16:56:31   --> checkout.session.completed [evt_1IQF2nJLFSG5VKTEXQfuVSK3]
[Mon, 01 Mar 2021 16:56:31 GMT] DEBUG proxy.EndpointClient.Post: Forwarding event to local endpoint
2021-03-01 16:56:32  <--  [200] POST http://localhost:4040/webhooks/stripe [evt_1IQF2nJLFSG5VKTEXQfuVSK3]
[Mon, 01 Mar 2021 16:56:44 GMT] DEBUG websocket.Client.readPump: Incoming message message={}
[Mon, 01 Mar 2021 16:56:44 GMT] DEBUG proxy.Proxy.processWebhookEvent: Processing webhook event webhook_converesation_id=1614617803-wc_0dpw9cmrhOxQdt webhook_id=1614617803-wh_Pa332Yv7p1G7E0
[Mon, 01 Mar 2021 16:56:44 GMT] DEBUG proxy.Proxy.filterWebhookEvent: Received event with non-default API version, ignoring api_version=0xc0006105a0
[Mon, 01 Mar 2021 16:56:44 GMT] DEBUG websocket.Client.readPump: Incoming message message={}
[Mon, 01 Mar 2021 16:56:44 GMT] DEBUG proxy.Proxy.processWebhookEvent: Processing webhook event webhook_converesation_id=1614617803-wc_FuoJ6ZSGG2dfCK webhook_id=1614617803-wh_HCtSGDTscnBhMt
2021-03-01 16:56:44   --> payment_intent.created [evt_1IQF31JLFSG5VKTE8jl9oi3p]
[Mon, 01 Mar 2021 16:56:44 GMT] DEBUG proxy.EndpointClient.Post: Forwarding event to local endpoint
2021-03-01 16:56:44  <--  [200] POST http://localhost:4040/webhooks/stripe [evt_1IQF31JLFSG5VKTE8jl9oi3p]
[Mon, 01 Mar 2021 16:56:47 GMT] DEBUG websocket.Client.Close: read error: read tcp 192.168.1.110:51554->54.187.159.182:443: i/o timeout
[Mon, 01 Mar 2021 16:56:47 GMT] DEBUG websocket.client.Run: Disconnected from Stripe
[Mon, 01 Mar 2021 16:56:47 GMT] DEBUG websocket.Client.writePump: stopWritePump
[Mon, 01 Mar 2021 16:56:47 GMT] DEBUG websocket.client.Run: Attempting to connect to Stripe
[Mon, 01 Mar 2021 16:56:47 GMT] DEBUG websocket.Client.connect: Dialing websocket url=wss://stripe-cli.stripe.com/subscribe/acct_1FprIQJLFSG5VKTE?websocket_feature=webhook-payloads
[Mon, 01 Mar 2021 16:56:48 GMT] DEBUG websocket.client.connect: Connected!
[Mon, 01 Mar 2021 16:56:55 GMT] DEBUG websocket.Client.readPump: Incoming message message={}
[Mon, 01 Mar 2021 16:56:55 GMT] DEBUG proxy.Proxy.processWebhookEvent: Processing webhook event webhook_converesation_id=1614617814-wc_8oRiuLuKekRige webhook_id=1614617814-wh_x9J3LFiPnrlEMG
[Mon, 01 Mar 2021 16:56:55 GMT] DEBUG proxy.Proxy.filterWebhookEvent: Received event with non-default API version, ignoring api_version=0xc0004da400
[Mon, 01 Mar 2021 16:56:56 GMT] DEBUG websocket.Client.readPump: Incoming message message={}
[Mon, 01 Mar 2021 16:56:56 GMT] DEBUG proxy.Proxy.processWebhookEvent: Processing webhook event webhook_converesation_id=1614617814-wc_NVLPT5hV1IgJTk webhook_id=1614617814-wh_Jd7aFbr8s5ZFA7
[Mon, 01 Mar 2021 16:56:56 GMT] DEBUG proxy.Proxy.filterWebhookEvent: Received event with non-default API version, ignoring api_version=0xc0004da870
[Mon, 01 Mar 2021 16:56:56 GMT] DEBUG websocket.Client.readPump: Incoming message message={}
[Mon, 01 Mar 2021 16:56:56 GMT] DEBUG proxy.Proxy.processWebhookEvent: Processing webhook event webhook_converesation_id=1614617814-wc_UD0pXPRSK8BGZj webhook_id=1614617814-wh_RAcW1LUdYDEBB6
2021-03-01 16:56:56   --> payment_method.attached [evt_1IQF3CJLFSG5VKTErGo0Lwlu]
[Mon, 01 Mar 2021 16:56:56 GMT] DEBUG proxy.EndpointClient.Post: Forwarding event to local endpoint
2021-03-01 16:56:56  <--  [200] POST http://localhost:4040/webhooks/stripe [evt_1IQF3CJLFSG5VKTErGo0Lwlu]
[Mon, 01 Mar 2021 16:56:56 GMT] DEBUG websocket.Client.writePump: Sending text message
[Mon, 01 Mar 2021 16:56:56 GMT] DEBUG websocket.Client.readPump: Incoming message message={}
[Mon, 01 Mar 2021 16:56:56 GMT] DEBUG proxy.Proxy.processWebhookEvent: Processing webhook event webhook_converesation_id=1614617815-wc_kU09TINhy6vqk5 webhook_id=1614617814-wh_HUSrMf3I2FJFch
[Mon, 01 Mar 2021 16:56:56 GMT] DEBUG proxy.Proxy.filterWebhookEvent: Received event with non-default API version, ignoring api_version=0xc0006113e0
[Mon, 01 Mar 2021 16:56:56 GMT] DEBUG websocket.Client.readPump: Incoming message message={}
[Mon, 01 Mar 2021 16:56:56 GMT] DEBUG proxy.Proxy.processWebhookEvent: Processing webhook event webhook_converesation_id=1614617815-wc_w7f2ZlZpmaoaLS webhook_id=1614617815-wh_TYSaMDCrWBaPZQ
[Mon, 01 Mar 2021 16:56:56 GMT] DEBUG proxy.Proxy.filterWebhookEvent: Received event with non-default API version, ignoring api_version=0xc000611830

Environment

Windows via WSL1

Notes

This was tough to initially debug as there was nothing in the default output. The expected webhooks just didn’t display. At first I thought that maybe there was some conflict because I also have my staging environment configured to receive the testing webhooks but I believe that was a red herring. I only discovered the --log-level debug config after some digging. So just to say perhaps there is something to consider around displaying something about the webhook with the default log-level even if it’s not sent?

About this issue

Original URL
State: open
Created 3 years ago
Reactions: 20
Comments: 44 (3 by maintainers)

Most upvoted comments

Using --latest flag seems to solve some missed calls but after being idle for some time requires restarting listener service

tadinski on Sep 2, 2021

For me, it seems like I stop receiving events when the system has been idle for a period of time. Since I am running stripe-cli in docker, usually restarting the container seems to fix it temporarily.

smousa on Jul 13, 2021

@jaredlt sorry for the delay here! I can repro this, it looks like even just running stripe trigger checkout.session.completed will sometimes cause this to happen. I don’t quite know what’s happening yet but we’ll dig a bit more.

tomer-stripe on Mar 18, 2021

Ubuntu 20.04 using CLI 1.7.0 here. It looks like the websocket died on me on connection reset. The cli had been running successfully and had reset just four minutes before this. The last successful event was evt_1JNJMvFG58HDul83UtdgrYxL

[Wed, 11 Aug 2021 08:34:04 PDT] DEBUG websocket.Client.readPump: Received pong message
[Wed, 11 Aug 2021 08:34:05 PDT] DEBUG websocket.Client.writePump: Sending ping message
[Wed, 11 Aug 2021 08:34:07 PDT] DEBUG websocket.Client.Run: Resetting the connection
[Wed, 11 Aug 2021 08:34:07 PDT] DEBUG websocket.Client.writePump: Sending ping message
[Wed, 11 Aug 2021 08:34:07 PDT] DEBUG websocket.Client.readPump: stopReadPump

FelixVicis on Aug 11, 2021

@kylefox sure, feel free to email me any new event ids: tomer@stripe.com

tomer-stripe on Apr 28, 2021

Quick update here – we’ve made several improvements to our reconnection times which should help. We’re still chasing down several larger culprits that are likely introducing race conditions but have started work to improve those conditions as well. In the meantime, if anyone notices any dropped events please give us the event id!

tomer-stripe on Apr 23, 2021

Hi all, want to share some updates here and a few areas we’re exploring.

we think the API version issue here is a red herring. The backend service will send the CLI two versions of the same event with the expectation that the CLI will ignore the event that’s not needed. We’re continuing to explore this area and have some work slated to make the server-side only send the CLI the information it needs, reducing some of the noise
we’ve been doing a deep dive into the webhook events pipeline to trace events from generation until CLI delivery. We’ve identified a number of areas that could be causing problems for events not reaching the CLI and are adding additional debugging information to help confirm resolutions
we believe there are some issues cropping up with our websocket lifecycle management. We’ve started implementing some stronger lifecycle management controlled by the server so that we have more information with the CLI itself reconnects

I’ll post another update on Friday this week. I’m also going to pin this issue and rename it to “Stripe CLI is not receiving all events” so that if other folks are hitting the same problem we can centralize the discussion.

edit: original title for posterity was Sometimes webhooks fail silently because "Received event with non-default API version, ignoring"

tomer-stripe on Apr 20, 2021

Hey everyone, sorry about the delay here. We’re investigating some possible leads on our side and think this might have to do with the reconnection logic we’ve got on the client and server. We’re trying to confirm this as the problem and work on ways to improve it.

tomer-stripe on Apr 15, 2021

@tomer-stripe Thanks for looking. Removing the -e event filter resulted in the events making it to my local app. I was using --latest at the time but I didn’t try without. This is good enough for me to make progress, thanks!

jameskeiger on Mar 3, 2021