stripe-cli icon indicating copy to clipboard operation
stripe-cli copied to clipboard

Published 20 hours ago • verified publisher icon stripe

Stripe CLI is not receiving all events

Open jaredlt opened this issue 3 years ago • 44 comments

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?

jaredlt avatar Mar 02 '21 11:03 jaredlt

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?

ctrudeau-stripe avatar Mar 02 '21 19:03 ctrudeau-stripe

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?)

jameskeiger avatar Mar 03 '21 00:03 jameskeiger

@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 protected]\",\n        \"tax_exempt\": \"none\",\n        \"tax_ids\": [\n\n        ]\n      },\n      \"customer_email\": \"[email protected]\",\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 protected]\",\n        \"tax_exempt\": \"none\",\n        \"tax_ids\": [\n\n        ]\n      },\n      \"customer_email\": \"[email protected]\",\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 protected]\",\n        \"tax_exempt\": \"none\",\n        \"tax_ids\": [\n\n        ]\n      },\n      \"customer_email\": \"[email protected]\",\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.

jaredlt avatar Mar 03 '21 15:03 jaredlt

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

tomer-stripe avatar Mar 03 '21 17:03 tomer-stripe

@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 avatar Mar 03 '21 22:03 jameskeiger

@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

jaredlt avatar Mar 04 '21 17:03 jaredlt

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.

tomer-stripe avatar Mar 05 '21 16:03 tomer-stripe

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

jaredlt avatar Mar 05 '21 16:03 jaredlt

@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 avatar Mar 18 '21 03:03 tomer-stripe

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 avatar Mar 23 '21 05:03 rocallahan

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.

rocallahan avatar Mar 23 '21 05:03 rocallahan

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.

franky47 avatar Apr 09 '21 08:04 franky47

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

rmunoz10 avatar Apr 14 '21 17:04 rmunoz10

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.

rocallahan avatar Apr 14 '21 22:04 rocallahan

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 avatar Apr 15 '21 15:04 tomer-stripe

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 :-(.

rocallahan avatar Apr 16 '21 23:04 rocallahan

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 avatar Apr 20 '21 16:04 tomer-stripe

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

kylefox avatar Apr 22 '21 16:04 kylefox

Thanks @kylefox this is very helpful!

pepin-stripe avatar Apr 22 '21 17:04 pepin-stripe

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 avatar Apr 23 '21 19:04 tomer-stripe

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

goetas avatar Apr 27 '21 12:04 goetas

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

tomer-stripe avatar Apr 27 '21 16:04 tomer-stripe

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

codeofsumit avatar Apr 27 '21 16:04 codeofsumit

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.

fredrikholm avatar Apr 28 '21 11:04 fredrikholm

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?

tomer-stripe avatar Apr 28 '21 16:04 tomer-stripe

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

fredrikholm avatar Apr 28 '21 16:04 fredrikholm

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

kylefox avatar Apr 28 '21 16:04 kylefox

@kylefox sure, feel free to email me any new event ids: [email protected]

tomer-stripe avatar Apr 28 '21 20:04 tomer-stripe

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.

greg-42droids avatar May 27 '21 07:05 greg-42droids

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?

kylefox avatar Jun 10 '21 18:06 kylefox