Stripe CLI is not receiving all events

jaredlt commented 3 years ago

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?

ctrudeau-stripe commented 3 years ago

Hello @jaredlt,

When the CLI creates endpoints it creates one for the latest Stripe API version and your default Stripe API Version. The CLI running on your device will receive 2 versions of each event. And the CLI locally filters one of them based on whether the --latest-api-version flag is used or not. This is so you can use the CLI on the latest version. If you upgrade your Stripe API version you won't see that log error anymore. We don't think those messages are related to the dropped events and are looking into this more. Can you tell us what webhooks you were expecting that didn't come through?

jameskeiger commented 3 years ago

I also encountered this issue and can provide logs. This is for a payment_intent.succeeded message. They are not forwarded through to the target URL. We are on Stripe API version 2020-08-27 and CLI version 1.5.9.

[Tue, 02 Mar 2021 19:23:29 EST] DEBUG proxy.Proxy.processWebhookEvent: Processing webhook event webhook_converesation_id=1614731009-wc_HS50HO1QOZE306 webhook_id=1614731009-wh_6WwK5jCurPOT0r
[Tue, 02 Mar 2021 19:23:29 EST] DEBUG proxy.Proxy.filterWebhookEvent: Received event with non-default API version, ignoring api_version=0xc00085f560

Command:

stripe listen --forward-to localhost:5000/(my app) --log-level=debug -e=payment_intent.succeeded,payment_intent.payment_failed,invoice.payment_failed,capability.updated

(Note there is a typo in the prop webhook_converesation_id-- maybe related?)

jaredlt commented 3 years ago

@ctrudeau-stripe I'm expecting checkout.session.completed webhooks.

I've done some more testing and I have found:

For the cases that do not forward the event, there is only 1 incoming message sent eg. the version with "endpoint":{"api_version":"2020-08-27"} (this gets filtered and ignored).
For the cases that succeed there are 2 incoming messages sent for the same event id: "endpoint":{"api_version":null} appears to succeed, while "endpoint":{"api_version":"2020-08-27"} gets filtered and ignored.

Command used:

stripe listen --forward-to localhost:4040/webhooks/stripe --events checkout.session.completed --log-level=debug

But I also experienced the same issue without setting the --events flag (ie. defaulting to all events).

Below shows debug logs for the last forwarded checkout.session.completed event (evt_1IQvolJLFSG5VKTENmxlUq4Y). Followed by the next one (evt_1IQvp9JLFSG5VKTE8W7oai73) which failed to forward (CTRL+F the event ids to see what I mean). NB. I have removed some lines from the logs to make it easier to parse but can provide the raw output if you need.

[Wed, 03 Mar 2021 14:36:51 GMT] DEBUG websocket.Client.readPump: Incoming message message={"webhook_id":"1614782211-wh_iiEkD5kHwt5aRv","webhook_conversation_id":"1614782211-wc_cjhZaT8Iz6tmd1","event_payload":"{\n  \"id\": \"evt_1IQvolJLFSG5VKTENmxlUq4Y\",\n  \"object\": \"event\",\n  \"api_version\": \"2019-12-03\",\n  \"created\": 1614782211,\n  \"data\": {\n    \"object\": {\n      \"id\": \"cs_test_b1dwMoJQQbonqCHWe8yFvEv44zpSuwTMxoZzui0yDpnoWBStCyrDFLLJ8a\",\n      \"object\": \"checkout.session\",\n      \"allow_promotion_codes\": null,\n      \"amount_subtotal\": 945,\n      \"amount_total\": 945,\n      \"billing_address_collection\": null,\n      \"cancel_url\": \"http://localhost:4040/cancel/113/preview\",\n      \"client_reference_id\": \"gift_113\",\n      \"currency\": \"gbp\",\n      \"customer\": \"cus_J31s4hSjaX5FZi\",\n      \"customer_details\": {\n        \"email\": \"email@email.org\",\n        \"tax_exempt\": \"none\",\n        \"tax_ids\": [\n\n        ]\n      },\n      \"customer_email\": \"email@email.org\",\n      \"livemode\": false,\n      \"locale\": null,\n      \"metadata\": {\n      },\n      \"mode\": \"payment\",\n      \"payment_intent\": \"pi_1IQvobJLFSG5VKTEwupBDmOa\",\n      \"payment_method_types\": [\n        \"card\"\n      ],\n      \"payment_status\": \"paid\",\n      \"setup_intent\": null,\n      \"shipping\": null,\n      \"shipping_address_collection\": null,\n      \"submit_type\": null,\n      \"subscription\": null,\n      \"success_url\": \"http://localhost:4040/payment_successful\",\n      \"total_details\": {\n        \"amount_discount\": 0,\n        \"amount_tax\": 0\n      }\n    }\n  },\n  \"livemode\": false,\n  \"pending_webhooks\": 3,\n  \"request\": {\n    \"id\": null,\n    \"idempotency_key\": null\n  },\n  \"type\": \"checkout.session.completed\"\n}","http_headers":{"Content-Type":"application/json; charset=utf-8","Cache-Control":"no-cache","User-Agent":"Stripe/1.0 (+https://stripe.com/docs/webhooks)","Accept":"*/*; q=0.5, application/xml","Stripe-Signature":"t=1614782211,v1=beae01533380279a1ec8cf058c50c3c1a40db5bf05164e519ea145ef11255ca4,v0=6dff269e61262cebe1dd1503b1993457c3005894c142319a09fcf70769a482e4"},"endpoint":{"api_version":null},"type":"webhook_event"}
[Wed, 03 Mar 2021 14:36:51 GMT] DEBUG proxy.Proxy.processWebhookEvent: Processing webhook event webhook_converesation_id=1614782211-wc_cjhZaT8Iz6tmd1 webhook_id=1614782211-wh_iiEkD5kHwt5aRv
2021-03-03 14:36:51   --> checkout.session.completed [evt_1IQvolJLFSG5VKTENmxlUq4Y]
[Wed, 03 Mar 2021 14:36:51 GMT] DEBUG proxy.EndpointClient.Post: Forwarding event to local endpoint
[Wed, 03 Mar 2021 14:36:52 GMT] DEBUG websocket.Client.readPump: Incoming message message={"webhook_id":"1614782211-wh_WeaQz6wD8FqRYN","webhook_conversation_id":"1614782211-wc_L4aI9gO15Dn0xv","event_payload":"{\n  \"id\": \"evt_1IQvolJLFSG5VKTENmxlUq4Y\",\n  \"object\": \"event\",\n  \"api_version\": \"2020-08-27\",\n  \"created\": 1614782211,\n  \"data\": {\n    \"object\": {\n      \"id\": \"cs_test_b1dwMoJQQbonqCHWe8yFvEv44zpSuwTMxoZzui0yDpnoWBStCyrDFLLJ8a\",\n      \"object\": \"checkout.session\",\n      \"allow_promotion_codes\": null,\n      \"amount_subtotal\": 945,\n      \"amount_total\": 945,\n      \"billing_address_collection\": null,\n      \"cancel_url\": \"http://localhost:4040/cancel/113/preview\",\n      \"client_reference_id\": \"gift_113\",\n      \"currency\": \"gbp\",\n      \"customer\": \"cus_J31s4hSjaX5FZi\",\n      \"customer_details\": {\n        \"email\": \"email@email.org\",\n        \"tax_exempt\": \"none\",\n        \"tax_ids\": [\n\n        ]\n      },\n      \"customer_email\": \"email@email.org\",\n      \"livemode\": false,\n      \"locale\": null,\n      \"metadata\": {\n      },\n      \"mode\": \"payment\",\n      \"payment_intent\": \"pi_1IQvobJLFSG5VKTEwupBDmOa\",\n      \"payment_method_types\": [\n        \"card\"\n      ],\n      \"payment_status\": \"paid\",\n      \"setup_intent\": null,\n      \"shipping\": null,\n      \"shipping_address_collection\": null,\n      \"submit_type\": null,\n      \"subscription\": null,\n      \"success_url\": \"http://localhost:4040/payment_successful\",\n      \"total_details\": {\n        \"amount_discount\": 0,\n        \"amount_tax\": 0\n      }\n    }\n  },\n  \"livemode\": false,\n  \"pending_webhooks\": 3,\n  \"request\": {\n    \"id\": null,\n    \"idempotency_key\": null\n  },\n  \"type\": \"checkout.session.completed\"\n}","http_headers":{"Content-Type":"application/json; charset=utf-8","Cache-Control":"no-cache","User-Agent":"Stripe/1.0 (+https://stripe.com/docs/webhooks)","Accept":"*/*; q=0.5, application/xml","Stripe-Signature":"t=1614782211,v1=bd031b772e24b27ad3478efe41d7f18ad01f907c26d405e1ebbc048327160a8e,v0=7c92cd190a3e15ee0e9a5eac00ce28eee37bfd6aaca238489c039f93a0f64d50"},"endpoint":{"api_version":"2020-08-27"},"type":"webhook_event"}
[Wed, 03 Mar 2021 14:36:52 GMT] DEBUG proxy.Proxy.processWebhookEvent: Processing webhook event webhook_converesation_id=1614782211-wc_L4aI9gO15Dn0xv webhook_id=1614782211-wh_WeaQz6wD8FqRYN
[Wed, 03 Mar 2021 14:36:52 GMT] DEBUG proxy.Proxy.filterWebhookEvent: Received event with non-default API version, ignoring api_version=0xc0005f9570
2021-03-03 14:36:52  <--  [200] POST http://localhost:4040/webhooks/stripe [evt_1IQvolJLFSG5VKTENmxlUq4Y]
[Wed, 03 Mar 2021 14:36:52 GMT] DEBUG websocket.Client.writePump: Sending text message
[Wed, 03 Mar 2021 14:36:59 GMT] DEBUG websocket.Client.writePump: Sending ping message
[Wed, 03 Mar 2021 14:36:59 GMT] DEBUG websocket.Client.readPump: Received pong message
[Wed, 03 Mar 2021 14:37:15 GMT] DEBUG websocket.Client.Run: Resetting the connection
[Wed, 03 Mar 2021 14:37:15 GMT] DEBUG websocket.Client.writePump: stopWritePump
[Wed, 03 Mar 2021 14:37:15 GMT] DEBUG websocket.Client.readPump: stopReadPump
[Wed, 03 Mar 2021 14:37:15 GMT] DEBUG websocket.client.Run: Attempting to connect to Stripe
[Wed, 03 Mar 2021 14:37:15 GMT] DEBUG websocket.Client.connect: Dialing websocket url=wss://stripe-cli.stripe.com/subscribe/acct_1FprIQJLFSG5VKTE?websocket_feature=webhook-payloads
[Wed, 03 Mar 2021 14:37:16 GMT] DEBUG websocket.client.connect: Connected!
[Wed, 03 Mar 2021 14:37:22 GMT] DEBUG websocket.Client.readPump: Incoming message message={"webhook_id":"1614782235-wh_yY8kuWODWDj3Gp","webhook_conversation_id":"1614782235-wc_G8kv1QDc76pUAF","event_payload":"{\n  \"id\": \"evt_1IQvp9JLFSG5VKTE8W7oai73\",\n  \"object\": \"event\",\n  \"api_version\": \"2020-08-27\",\n  \"created\": 1614782235,\n  \"data\": {\n    \"object\": {\n      \"id\": \"cs_test_b1m5kYP0GNG3VHSCMzBkiiJlYfslVVDMDjoDUYexrPryziL8O3vsroUguw\",\n      \"object\": \"checkout.session\",\n      \"allow_promotion_codes\": null,\n      \"amount_subtotal\": 1050,\n      \"amount_total\": 1050,\n      \"billing_address_collection\": null,\n      \"cancel_url\": \"http://localhost:4040/cancel/114/preview\",\n      \"client_reference_id\": \"gift_114\",\n      \"currency\": \"gbp\",\n      \"customer\": \"cus_J31salcjUcsiY4\",\n      \"customer_details\": {\n        \"email\": \"email@email.org\",\n        \"tax_exempt\": \"none\",\n        \"tax_ids\": [\n\n        ]\n      },\n      \"customer_email\": \"email@email.org\",\n      \"livemode\": false,\n      \"locale\": null,\n      \"metadata\": {\n      },\n      \"mode\": \"payment\",\n      \"payment_intent\": \"pi_1IQvp0JLFSG5VKTEzobRe3xO\",\n      \"payment_method_types\": [\n        \"card\"\n      ],\n      \"payment_status\": \"paid\",\n      \"setup_intent\": null,\n      \"shipping\": null,\n      \"shipping_address_collection\": null,\n      \"submit_type\": null,\n      \"subscription\": null,\n      \"success_url\": \"http://localhost:4040/payment_successful\",\n      \"total_details\": {\n        \"amount_discount\": 0,\n        \"amount_tax\": 0\n      }\n    }\n  },\n  \"livemode\": false,\n  \"pending_webhooks\": 3,\n  \"request\": {\n    \"id\": null,\n    \"idempotency_key\": null\n  },\n  \"type\": \"checkout.session.completed\"\n}","http_headers":{"Content-Type":"application/json; charset=utf-8","Cache-Control":"no-cache","User-Agent":"Stripe/1.0 (+https://stripe.com/docs/webhooks)","Accept":"*/*; q=0.5, application/xml","Stripe-Signature":"t=1614782235,v1=6159d99e09a10efc2e2ba92575448260ed92253fa2e08192e0f0e36360a91e97,v0=a943f6ae3dab8f478bf988f5d17deab92994a10d1c8ce3b62bb529e0e56db2c3"},"endpoint":{"api_version":"2020-08-27"},"type":"webhook_event"}
[Wed, 03 Mar 2021 14:37:22 GMT] DEBUG proxy.Proxy.processWebhookEvent: Processing webhook event webhook_converesation_id=1614782235-wc_G8kv1QDc76pUAF webhook_id=1614782235-wh_yY8kuWODWDj3Gp
[Wed, 03 Mar 2021 14:37:22 GMT] DEBUG proxy.Proxy.filterWebhookEvent: Received event with non-default API version, ignoring api_version=0xc00048f0d0
[Wed, 03 Mar 2021 14:37:25 GMT] DEBUG websocket.Client.writePump: Sending ping message
[Wed, 03 Mar 2021 14:37:25 GMT] DEBUG websocket.Client.readPump: Received pong message
[Wed, 03 Mar 2021 14:37:34 GMT] DEBUG websocket.Client.writePump: Sending ping message
[Wed, 03 Mar 2021 14:37:34 GMT] DEBUG websocket.Client.readPump: Received pong message
[Wed, 03 Mar 2021 14:37:43 GMT] DEBUG websocket.Client.writePump: Sending ping message
[Wed, 03 Mar 2021 14:37:43 GMT] DEBUG websocket.Client.readPump: Received pong message
[Wed, 03 Mar 2021 14:37:52 GMT] DEBUG websocket.Client.writePump: Sending ping message
[Wed, 03 Mar 2021 14:37:52 GMT] DEBUG websocket.Client.readPump: Received pong message
^C[Wed, 03 Mar 2021 14:37:53 GMT] DEBUG proxy.Proxy.Run: Ctrl+C received, cleaning up...

NB. When I view the Events within the Stripe Dashboard, I can see both, and when I click each event to view their Webhook CLI responses it shows the event forwarded to my device for the first one, and says No recent CLI responses for the one which didn't forward.

tomer-stripe commented 3 years ago

@jameskeiger @jaredlt do things work as expected if you run listen with --latest? Are you running API requests using API versions that are different from your account's API version? (like using the Stripe-Version header: https://stripe.com/docs/api/versioning). edit: are you making API requests with the CLI?

To share a little bit of context on what might be happening here: webhook endpoints are pinned to specific API versions when they're created and Stripe will only send each endpoint the event for the right API version shape. So, for example: if you have a webhook endpoint that's pinned on 2020-08-27 but you make an API request with version 2019-12-03, the 2020 endpoint will not receive the 2019 version of the event. We added some checks in place to the CLI to avoid sending the different version to avoid confusion with potential event shape differences but we may not be correctly handling some versioning code from the CLI's backend.

jameskeiger commented 3 years ago

@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!

jaredlt commented 3 years ago

@tomer-stripe

do things work as expected if you run listen with --latest?

No, still have the same issue

Are you running API requests using API versions that are different from your account's API version? (like using the Stripe-Version header: https://stripe.com/docs/api/versioning)

No, I don't believe so. I'm using the stripe-ruby Gem v5.30.0 along with a very simple implementation to create a Checkout Session (essentially copy/pasted from Stripe's docs). And I'm loading <script src="https://js.stripe.com/v3/"></script> on the page to redirect the users to Checkout. But nothing fancy and certainly not setting anything to change the API version. NB. my account is on Version 2019-12-03

are you making API requests with the CLI?

No, I'm only using listen

tomer-stripe commented 3 years ago

Thanks @jaredlt! I'm going to keep looking at this and see if I can repro this locally with the same setup you've got.

jaredlt commented 3 years ago

@tomer-stripe 👍 If I can help with anything further just let me know.

FYI usually I get a failure within 10 Checkouts but one time I had to test ~35 Checkout payments before it failed :( Almost questioned my life choices on that one!

tomer-stripe commented 3 years ago

@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.

rocallahan commented 3 years ago

I'm getting this too. It's causing frequent test failures in our CI.

When things are working, the Stripe CLI reports two checkout.session.completed events per session completed, one with endpoint.api_version "2020-08-27", the other null. The former is ignored because "Received event with non-default API version", the latter is fine. When things don't work, the Stripe CLI only reports one checkout.session.completed event, with endpoint.api_version "2020-08-27".

FWIW our Stripe settings specify our API version as 2020-08-27, and all our requests to Stripe set Stripe-Version: 2020-08-27 as well.

rocallahan commented 3 years ago

Right around the time of the failed checkout session I do get

time="Tue, 23 Mar 2021 01:04:59 UTC" level=debug msg="Sending text message" prefix=websocket.Client.writePump
time="Tue, 23 Mar 2021 01:04:59 UTC" level=debug msg="read error: read tcp 172.17.0.3:59740->54.187.119.242:443: i/o timeout" prefix=websocket.Client.Close
time="Tue, 23 Mar 2021 01:04:59 UTC" level=debug msg="Disconnected from Stripe" prefix=websocket.client.Run
time="Tue, 23 Mar 2021 01:04:59 UTC" level=debug msg=stopWritePump prefix=websocket.Client.writePump
time="Tue, 23 Mar 2021 01:04:59 UTC" level=debug msg="Attempting to connect to Stripe" prefix=websocket.client.Run
time="Tue, 23 Mar 2021 01:04:59 UTC" level=debug msg="Dialing websocket" prefix=websocket.Client.connect url="wss://stripe-cli.stripe.com/subscribe/[REDACTED]?websocket_feature=webhook-payloads"
...
time="Tue, 23 Mar 2021 01:05:00 UTC" level=debug msg="Connected!" prefix=websocket.client.connect

Perhaps this disconnect/reconnect is causing the relevant event to be dropped? If the event is redelivered later that wouldn't help because we make the test time out after a minute.

It's not clear to me why the socket would have dropped here. It's happily receiving and sending messages up to the moment of the I/O error and the redial succeeds instantly.

franky47 commented 3 years ago

I have the same setup and issue as @rocallahan (2020-08-27 setup in the dashboard and specified in the Node.js Stripe library constructor). I also observed those dropouts in connection:

[Fri, 09 Apr 2021 10:16:10 CEST] DEBUG websocket.Client.readPump: Received pong message
[Fri, 09 Apr 2021 10:16:19 CEST] DEBUG websocket.Client.writePump: Sending ping message
[Fri, 09 Apr 2021 10:16:20 CEST] DEBUG websocket.Client.Close: read error: read tcp 192.168.1.200:50003->54.187.159.182:443: i/o timeout
[Fri, 09 Apr 2021 10:16:20 CEST] DEBUG websocket.client.Run: Disconnected from Stripe
[Fri, 09 Apr 2021 10:16:20 CEST] DEBUG websocket.Client.writePump: stopWritePump
[Fri, 09 Apr 2021 10:16:20 CEST] DEBUG websocket.client.Run: Attempting to connect to Stripe
[Fri, 09 Apr 2021 10:16:20 CEST] DEBUG websocket.Client.connect: Dialing websocket url=wss://stripe-cli.stripe.com/subscribe/acct_1Ibjh8H32su3URju?websocket_feature=webhook-payloads
[Fri, 09 Apr 2021 10:16:21 CEST] DEBUG websocket.client.connect: Connected!
[Fri, 09 Apr 2021 10:16:30 CEST] DEBUG websocket.Client.writePump: Sending ping message
[Fri, 09 Apr 2021 10:16:30 CEST] DEBUG websocket.Client.readPump: Received pong message

Then the next event is dropped due to mismatching API versions (however the event body seems to indicate the correct API version):

[Fri, 09 Apr 2021 10:17:19 CEST] DEBUG websocket.Client.readPump: Incoming message message={"webhook_id":"1617956238-wh_C8shil7EkBjdnW","webhook_conversation_id":"1617956239-wc_NYqTMyJmNzRoq4","event_payload": {...},"endpoint":{"api_version":"2020-08-27"},"type":"webhook_event"}
[Fri, 09 Apr 2021 10:17:19 CEST] DEBUG proxy.Proxy.processWebhookEvent: Processing webhook event webhook_converesation_id=1617956239-wc_NYqTMyJmNzRoq4 webhook_id=1617956238-wh_C8shil7EkBjdnW
[Fri, 09 Apr 2021 10:17:19 CEST] DEBUG proxy.Proxy.filterWebhookEvent: Received event with non-default API version, ignoring api_version=0xc00051c990

Stripe CLI installed on macOS via Homebrew, version 1.5.12.

rmunoz10 commented 3 years ago

Same thing here. The connection is dropped after a successful checkout on the dashboard.

$HOME/opt/stripe listen --log-level debug

[Wed, 14 Apr 2021 13:14:00 EDT] DEBUG websocket.Client.writePump: Sending ping message [Wed, 14 Apr 2021 13:14:00 EDT] DEBUG websocket.Client.readPump: Received pong message [Wed, 14 Apr 2021 13:14:09 EDT] DEBUG websocket.Client.writePump: Sending ping message [Wed, 14 Apr 2021 13:14:10 EDT] DEBUG websocket.Client.Close: read error: read tcp 192.168.1.21:32960->54.187.159.182:443: i/o timeout [Wed, 14 Apr 2021 13:14:10 EDT] DEBUG websocket.client.Run: Disconnected from Stripe [Wed, 14 Apr 2021 13:14:10 EDT] DEBUG websocket.Client.writePump: stopWritePump

Environment: Ubuntu 20.04LTS, stripe version 1.5.12

rocallahan commented 3 years ago

We're working around this in our CI by scanning the stripe-cli debug log for "Disconnected" messages and if we see one, abandoning the test without reporting a failure.

tomer-stripe commented 3 years ago

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.

rocallahan commented 3 years ago

FWIW I am seeing cases where an event is being totally ignored because "Received event with non-default API version", but there is no disconnection recorded in the log :-(.

tomer-stripe commented 3 years ago

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"

kylefox commented 3 years ago

As requested, here's a customer.subscription.updated event that never made it to my stripe listen process: evt_1Ij5ETGOjIYrprHYyoBYu8GU

pepin-stripe commented 3 years ago

Thanks @kylefox this is very helpful!

tomer-stripe commented 3 years ago

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!

goetas commented 3 years ago

Similar to all the other ppl, evt_1IkqBLGHfkcMFLLKWPfQZ5Ii (test env) is an even that was never delivered to any connected client (i have a test setup with 6 concurrently connected stripe CLIs). None of them received the event (and even on the dashboard it shows that no web-hook delivery has been done to any of them).

tomer-stripe commented 3 years ago

Thanks @goetas! The team's digging into that one too.

codeofsumit commented 3 years ago

same issue here. evt_1IktxcHToHQv3HHtyGY0HFNt (test env) did not make it to the local CLI

fredrikholm commented 3 years ago

In addition to the issues described above, I also experience dropped events using stripe events resend evt_xxxx. I am using stripe listen --forward-to https://localhost:5002/subscription/webhook, and the missing events don't even show up in the list. But when they do show up, they are always forwarded as expected.

tomer-stripe commented 3 years ago

Thanks @codeofsumit! I've shared with the team.

@fredrikholm would you happen to have an event id associated with that? Also do you see the event show up in the dashboard as resent?

fredrikholm commented 3 years ago

@tomer-stripe - sorry, I don't have any event ids, but I will keep a record of those that fail from now on and post them here.

And a question: is the listen --forward-to command supposed to run until canceled, or is there a silent timeout? Is it supposed to recover from scenarios like the computer going to sleep mode and then back again?

Good luck with the bug hunting!

kylefox commented 3 years ago

@tomer-stripe Would it be possible to move the reporting of specific events IDs somewhere else besides this GitHub thread? Can we submit them directly to Stripe via email or another channel?

tomer-stripe commented 3 years ago

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

greg-42droids commented 3 years ago

I am experiencing the same issue. Latest CLI version 1.6.0, updated just now. I have noticed that if I CTRL+C out of CLI and run it again, events stop coming through. Looking at the list of running programs, I can see that CMD has many instances running. After restarting Win10 (running it in Virtualbox), the events are working again. On the Stripe dashboard, all events appear correctly. I hope this helps a bit. Happy to answer questions, help debug further. Thank you.

kylefox commented 3 years ago

Hey @ctrudeau-stripe @tomer-stripe @pepin-stripe — any updates on this? 😄

Event delivery appeared to get more reliable, so I assumed the issue had been fixed. But it's recently become unreliable again. Not sure if that's due to changes Stripe is making, or if it's just the randomness of life 🤷🏻‍♂️

Is there anything contributors (i.e. non-Stripe employees) can do to help? From the sounds of it, this issue requires server-side troubleshooting/fixes rather than client-side?

tomer-stripe commented 3 years ago

Hey @kylefox! I don't have any big updates for you but we've been pretty heads down on over this for a few weeks. Would you mind sharing when you noticed unreliability or any event ids? Part of what we're trying to do is tease apart issues with the CLI vs general webhook delivery slowness.

acarpe commented 3 years ago

Hello everybody, we are experiencing the same issue. from the debug log we see one message ignored because of the stripe version, but the second one is ignored because of is malformed.... it doesn't sound good. the event id is evt_1J4nGrCAeDbhXcLQx5xHEFnc

[Mon, 21 Jun 2021 15:55:29 CEST] DEBUG proxy.Proxy.processWebhookEvent: Processing webhook event webhook_converesation_id=1624283729-wc_g1hcSOcoZ0ffen webhook_id=1624283727-wh_I1qwvRXPQ5duls
[Mon, 21 Jun 2021 15:55:29 CEST] DEBUG Received malformed event from Stripe, ignoring

tudordimitriu commented 3 years ago

Hello everyone! Just had to deal with a combination of all the problems discussed here, recently. It seems there are multiple causes at play.

On the one hand, there were events missed because of reconnection issues which has been discussed at the top of the thread and probably fixed.

On the other hand, since stripe-cli 1.6.0, Stripe seems to have added payload validation for events which does not deal well with payloads from much older api versions. For historical reasons, our default api version is stuck at the end of 2015 and we were also missing customer.subscription.updated events. Logging in debug mode reported a malformed event on the 2015 api version and discarded the message. The latest api version message was also discarded because our default api version is not up to date. The end result is nothing got through to our internal development endpoint.

The quick fix until Stripe deals with this is to revert to stripe-cli v 1.5.14.

@stripe will you look at improving the web hook structure validation to cover for all api versions or is this a nudge for everyone to upgrade?

smousa commented 3 years ago

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.

ashleyfae commented 3 years ago

I'm also having this issue. I'm using Stripe Checkout for subscriptions. I received events for:

2021-07-16 07:28:29   --> customer.updated [evt_1JDlTEHczy284fwaQraX8M6a]
2021-07-16 07:28:29  <--  [200] POST http://abs.develop/stripe/webhook [evt_1JDlTEHczy284fwaQraX8M6a]
2021-07-16 07:33:57   --> payment_method.attached [evt_1JDlYWHczy284fwayZDsJe18]
2021-07-16 07:33:57   --> invoice.created [evt_1JDlYXHczy284fwaZC33P5iH]
2021-07-16 07:33:57  <--  [200] POST http://abs.develop/stripe/webhook [evt_1JDlYWHczy284fwayZDsJe18]
2021-07-16 07:33:57   --> invoice.finalized [evt_1JDlYXHczy284fwaUT2RVeoZ]
2021-07-16 07:33:57   --> customer.subscription.updated [evt_1JDlYXHczy284fwapC7iJlDD]
2021-07-16 07:33:57  <--  [200] POST http://abs.develop/stripe/webhook [evt_1JDlYXHczy284fwaZC33P5iH]
2021-07-16 07:33:57  <--  [200] POST http://abs.develop/stripe/webhook [evt_1JDlYXHczy284fwaUT2RVeoZ]
2021-07-16 07:33:57   --> invoice.payment_succeeded [evt_1JDlYXHczy284fwaFDV5jIi0]
2021-07-16 07:33:57  <--  [200] POST http://abs.develop/stripe/webhook [evt_1JDlYXHczy284fwapC7iJlDD]
2021-07-16 07:33:59  <--  [200] POST http://abs.develop/stripe/webhook [evt_1JDlYXHczy284fwaFDV5jIi0]
2021-07-16 07:33:59   --> customer.updated [evt_1JDlYZHczy284fwayd6Cju9G]

Notably missing is... customer.subscription.created . The event ID for that one that never got through is evt_1JDlYXHczy284fwaaU3u6voZ

kylefox commented 3 years ago

@ctrudeau-stripe @tomer-stripe I hate to nag, but is this issue being actively worked on? Reliable listen seems like critical functionality for the Stripe CLI. My team would love to continue using the official Stripe CLI if possible. Again, if there's anything else us non-employees can do (besides provide more examples) please let me know! 🙏

If it's helpful, here's some more output from a specific instance I encountered today (using stripe version 1.7.0):

2021-07-29 12:26:57   --> connect customer.updated [evt_0JIdwadezv9DhHNcvG6tUDjn]
[Thu, 29 Jul 2021 12:26:57 MDT] DEBUG websocket.Client.writePump: Sending ping message
[Thu, 29 Jul 2021 12:26:57 MDT] DEBUG websocket.Client.readPump: Received pong message
[Thu, 29 Jul 2021 12:26:59 MDT] DEBUG websocket.Client.readPump: Incoming message message={
  "webhook_id":"1627583216-wh_4SCUo4ZzmV0Qh8",
  "webhook_conversation_id":"1627583219-wc_hlXifvRa9MSi5D",
  "event_payload":"{ <<SNIPPED>> },
  "endpoint": {
    "api_version":"2020-08-27"
  },
  "type":"webhook_event"
}
[Thu, 29 Jul 2021 12:26:59 MDT] DEBUG proxy.Proxy.processWebhookEvent: Processing webhook event webhook_converesation_id=1627583219-wc_hlXifvRa9MSi5D webhook_id=1627583216-wh_4SCUo4ZzmV0Qh8
[Thu, 29 Jul 2021 12:26:59 MDT] DEBUG proxy.Proxy.filterWebhookEvent: Received event with non-default API version, ignoring api_version=2020-08-27

For reference, here's the command I ran to listen:

stripe listen \
  --skip-verify \
  --log-level debug
  --forward-to https://api.lvh.me:5001/webhooks/stripe \
  --forward-connect-to https://api.lvh.me:5001/webhooks/stripe/connect

This is the concerning line from the output:

Received event with non-default API version, ignoring api_version=2020-08-27

When I check the associated Stripe accounts, they're all using 2020-08-27 which is shown to be the Default:

(I am not explicitly setting an API version in code, i.e. Stripe.api_version = OLD_VERSION)

Is it possible there's a bug in client code that filters out webhooks due to API versions? Because it sounds like other people in this thread are also seeing unexpected behavior with api_version.

Thanks!

kylefox commented 3 years ago

I also ran the above command with the --latest flag and got this curious output:

2021-07-29 13:25:24   --> connect customer.updated [evt_0JIerAdezv9DhHNcOl3kDQDy]
[Thu, 29 Jul 2021 13:25:25 MDT] DEBUG websocket.Client.readPump: Incoming message message={
  "webhook_id":"1627586724-wh_sKmJJlIhJvqlve"
  "webhook_conversation_id":"1627586725-wc_o1VbtANoXtZI29",
  "event_payload":"{ <<SNIPPED>> },
  "endpoint":{
    "api_version":null
  }
  "type":"webhook_event"
}
[Thu, 29 Jul 2021 13:25:25 MDT] DEBUG proxy.Proxy.processWebhookEvent: Processing webhook event webhook_converesation_id=1627586725-wc_o1VbtANoXtZI29 webhook_id=1627586724-wh_sKmJJlIhJvqlve
[Thu, 29 Jul 2021 13:25:25 MDT] DEBUG proxy.Proxy.filterWebhookEvent: Received event with default API version, ignoring

I'm not a Go programmer, but is it possible filterWebhookEvent is incorrectly filtering out events that shouldn't be filtered?

https://github.com/stripe/stripe-cli/blob/959df5837f098feb76f58aa608b41eaa8707f209/pkg/proxy/proxy.go#L263-L282

FelixVicis commented 3 years ago

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

jakubriegel commented 3 years ago

Hi! I went here from #487. I was experiencing similar issue with Stripe CLI Docker on Windows. I turned out that disabling firewall solved the problem. Not an elegant solution but works for now 😉

mruhlin commented 3 years ago

Looks like in my case, "resetting the connection" just died for some reason. I started up a new instance of my app and worked on other things while waiting for everything to spin up. By the time I got back (about 5 minutes later) stripe-listen was already broken.

hooks-stripe-listen.1.0yqhb13br0tp@int-node-03    | time="Mon, 30 Aug 2021 14:59:19 UTC" level=debug msg="Connected!" prefix=websocket.client.connect
hooks-stripe-listen.1.0yqhb13br0tp@int-node-03    | Ready! Your webhook signing secret is REDACTED (^C to quit)
hooks-stripe-listen.1.0yqhb13br0tp@int-node-03    | time="Mon, 30 Aug 2021 14:59:21 UTC" level=debug msg="Sending ping message" prefix=websocket.Client.writePump
hooks-stripe-listen.1.0yqhb13br0tp@int-node-03    | time="Mon, 30 Aug 2021 14:59:21 UTC" level=debug msg="Received pong message" prefix=websocket.Client.readPump

... 4 minutes of pings and pongs every second...

hooks-stripe-listen.1.0yqhb13br0tp@int-node-03    | time="Mon, 30 Aug 2021 15:03:23 UTC" level=debug msg="Sending ping message" prefix=websocket.Client.writePump
hooks-stripe-listen.1.0yqhb13br0tp@int-node-03    | time="Mon, 30 Aug 2021 15:03:25 UTC" level=debug msg="Resetting the connection" prefix=websocket.Client.Run
hooks-stripe-listen.1.0yqhb13br0tp@int-node-03    | time="Mon, 30 Aug 2021 15:03:25 UTC" level=debug msg=stopReadPump prefix=websocket.Client.readPump
hooks-stripe-listen.1.0yqhb13br0tp@int-node-03    | time="Mon, 30 Aug 2021 15:03:25 UTC" level=debug msg="Sending ping message" prefix=websocket.Client.writePump

if it makes any difference, we're running stripe CLI 1.7.0 in docker on an ubuntu 18 host.

tadinski commented 3 years ago

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

Cavallando commented 2 years ago

Posting here in case someone runs into a similar thing that I did. We were testing out the new orders_beta v2 and noticed that we were not receiving any of these new events using stripe listen and further found out that these events were not included in stripe-cli or the open API spec.

What I did notice was the events were still firing in our test mode dashboard. So as a workaround I used Ngrok to expose our local API as an endpoint and configured that as a direct endpoint in stripe.

While configuring the endpoint in stripe you can specify API version as well as specify event types to send.

ngrok http 8080 (replace 8080 with whatever port your server is running on)
Ngrok will return an external URL that points to your localhost server for your API
Copy that URL over to Stripe Dashboard and configure a new Direct Endpoint, your endpoint should look something like https://5ee1-24-128-94-169.ngrok.io/path/to/webhook/endpoint, Note: don't forget to include the path to your webhook endpoint in stripe

After doing this our API started receiving all of the events. This isn't ideal as I think we'd all prefer using the stripe-cli for this, but hope that this helps someone!

cjavilla-stripe commented 2 years ago

Hey @Cavallando,

Thanks for sharing. The StripeCLI, nor any of the client libraries support beta features or events.

Cheers.

beninsydney commented 2 years ago

Encountered this issue today swapping from ngrok to the Stripe CLI, restarting the forwarding between tests seems to have fixed it for me. Is it possible it's hitting some sort of rate limit?

tomer-stripe commented 7 months ago

I'm going to close this issue since we've made significant progress here over the years. We rewrote the underlying system to better handle volume and concurrency, and we've also added more monitoring (and canary's) in place to alert us if the deliveries are dropping.

stripe / stripe-cli