search

medusajs / medusa

The world's most flexible commerce platform.
https://medusajs.com
MIT License
26.25k stars 2.67k forks source link

Stripe webhook processing fails with 409 Conflict #4798

Closed nickmonad closed 1 year ago

nickmonad commented 1 year ago

Bug report

Describe the bug

Processing for the payment_intent.succeeded Stripe webhook event fails with 409 Conflict.

System information

Medusa version (including plugins): 1.14.0, medusa-payment-stripe 6.0.2 Node.js version: v18.10.0 Database: Postgres 14 Operating system: Linux Browser (if relevant):

Steps to reproduce the behavior

  1. (Using ngrok) Enable webhook on Stripe testing dashboard, for events payment_intent.amount_capturable_updated, payment_intent.payment_failed, and payment_intent.succeeded, API version 2022-11-15
  2. Set capture: true under medusa-payment-stripe options in medusa-config.js
  3. Run medusa server locally, enabling Stripe as a payment processor for default region in admin dashboard.
  4. Start up the nextjs-starter-medusa frontend and run through checkout flow with item(s) in cart.

Expected behavior

payment_intent.succeeded processing is successful, order is marked as "Paid" in Medusa, Stripe receives 200 OK response.

Screenshots

Here are some relevant logs we are seeing when running through this flow.

medusa

warn:    Stripe webhook payment_intent.succeeded handling failed
Key (cart_id)=(cart_01H82HZQ746HKZSC6NXTCVBSDH) already exists.
54.187.174.169 - - [17/Aug/2023:20:15:01 +0000] "POST /stripe/hooks HTTP/1.1" 409 8 "-" "Stripe/1.0 (+https://stripe.com/docs/webhooks)"

postgres

2023-08-17 20:15:01.565 UTC [153] ERROR:  duplicate key value violates unique constraint "UniquePaymentActive"
2023-08-17 20:15:01.565 UTC [153] DETAIL:  Key (cart_id)=(cart_01H82HZQ746HKZSC6NXTCVBSDH) already exists.
2023-08-17 20:15:01.565 UTC [153] STATEMENT:  INSERT INTO "public"."payment"("id", "created_at", "updated_at", "swap_id", "cart_id", "order_id", "amount", "currency_code", "amount_refunded", "provider_id", "data", "captured_at", "canceled_at", "metadata", "idempotency_key") VALUES ($1, DEFAULT, DEFAULT, DEFAULT, $2, DEFAULT, $3, $4, DEFAULT, $5, $6, DEFAULT, DEFAULT, DEFAULT, DEFAULT) RETURNING "created_at", "updated_at", "amount_refunded"

Code snippets

Relevant processing paths are here,

https://github.com/medusajs/medusa/blob/v1.14.0/packages/medusa-payment-stripe/src/api/utils/utils.ts#L69 https://github.com/medusajs/medusa/blob/v1.14.0/packages/medusa-payment-stripe/src/api/utils/utils.ts#L134-L145

Based on some simple debugging (adding logger output to the stripe plugin), I think the failure occurs here: https://github.com/medusajs/medusa/blob/v1.14.0/packages/medusa-payment-stripe/src/api/utils/utils.ts#L250-L252

Then, on the second call to the webhook endpoint (see additional context below), the order has already been created from the cart, and the entire code block after the check for an existing order doesn't execute, returning a 200 OK to stripe: https://github.com/medusajs/medusa/blob/v1.14.0/packages/medusa-payment-stripe/src/api/utils/utils.ts#L214-L219

Additional context

If the webhook event is resent (after this initial failure and 409 Conflict response), either manually or automatically by Stripe, the processing succeeds, and returns a 200 OK to stripe, marking the order as "Paid" in medusa. This leads me to believe that there may be a race condition occurring, between stripe and the API calls the nextjs starter is making.

It may also be worth noting that the only call to the orderService that doesn't include .withTransaction() is here: https://github.com/medusajs/medusa/blob/v1.14.0/packages/medusa-payment-stripe/src/api/utils/utils.ts#L215, but I added that into a local version of the medusa-payment-stripe plugin and tested that, with no change in behavior.

chemicalkosek commented 1 year ago

https://github.com/medusajs/medusa/issues/2948#issuecomment-1402096295

nickmonad commented 1 year ago

Hi @chemicalkosek, thanks for the suggestion! The only thing that doesn't line up in our case is that the frontend (next.js starter) never receives an error from one of its API calls to medusa (completing a cart or otherwise). Here are some example logs from medusa, captured immediately after I submit the order on the frontend.


::1 - - [21/Aug/2023:21:28:06 +0000] "OPTIONS /store/carts/cart_01H8CZT48895A3E7P40JAWS6MC/complete HTTP/1.1" 204 0 "http://localhost:8000/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/107.0.0.0 Safari/537.36"
warn:    Stripe webhook payment_intent.succeeded handling failed
Key (cart_id)=(cart_01H8CZT48895A3E7P40JAWS6MC) already exists.
54.187.216.72 - - [21/Aug/2023:21:28:07 +0000] "POST /stripe/hooks HTTP/1.1" 409 8 "-" "Stripe/1.0 (+https://stripe.com/docs/webhooks)"
::1 - - [21/Aug/2023:21:28:08 +0000] "POST /store/carts/cart_01H8CZT48895A3E7P40JAWS6MC/complete HTTP/1.1" 200 5583 "http://localhost:8000/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/107.0.0.0 Safari/537.36"
::1 - - [21/Aug/2023:21:28:08 +0000] "OPTIONS /store/carts HTTP/1.1" 204 0 "http://localhost:8000/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/107.0.0.0 Safari/537.36"
::1 - - [21/Aug/2023:21:28:08 +0000] "POST /store/carts HTTP/1.1" 200 2103 "http://localhost:8000/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/107.0.0.0 Safari/537.36"
::1 - - [21/Aug/2023:21:28:08 +0000] "GET /store/customers/me HTTP/1.1" 401 - "http://localhost:8000/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/107.0.0.0 Safari/537.36"
::1 - - [21/Aug/2023:21:28:08 +0000] "GET /store/shipping-options/cart_01H8CZYYTJNVBJZRYA1WH3C7TV HTTP/1.1" 200 23 "http://localhost:8000/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/107.0.0.0 Safari/537.36"
info:    Processing cart.updated which has 0 subscribers
info:    Processing product-variant.updated which has 0 subscribers
info:    Processing payment.updated which has 0 subscribers
info:    Processing order.placed which has 3 subscribers
info:    Processing cart.updated which has 0 subscribers
info:    Processing cart.created which has 0 subscribers
::1 - - [21/Aug/2023:21:28:09 +0000] "GET /store/customers/me HTTP/1.1" 401 - "http://localhost:8000/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/107.0.0.0 Safari/537.36"
::1 - - [21/Aug/2023:21:28:09 +0000] "GET /store/orders/order_01H8CZYYNZDH0JF6R9YC8REKTE HTTP/1.1" 200 6421 "-" "undici"
::1 - - [21/Aug/2023:21:28:10 +0000] "GET /store/products?is_giftcard=false&limit=4&cart_id=cart_01H8CZYYTJNVBJZRYA1WH3C7TV HTTP/1.1" 200 3763 "http://localhost:8000/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/107.0.0.0 Safari/537.36"
info:    Processing order.fulfillment_created which has 0 subscribers
54.187.174.169 - - [21/Aug/2023:21:28:22 +0000] "POST /stripe/hooks HTTP/1.1" 200 2 "-" "Stripe/1.0 (+https://stripe.com/docs/webhooks)"
info:    Processing order.payment_captured which has 0 subscribers

The only error response sent to the frontend is a 401 on /store/customers/me, but that doesn't seem relevant here. The last couple of lines show the stripe webhook retrying automatically and succeeding (as already noted in the issue description above)

nickmonad commented 1 year ago

It seems to us that during the processing of POST /store/carts/:card_id/complete the stripe webhook is coming in to medusa, and that is where the failure happens. (i.e. the call to complete is "too slow" in this case, and is leaving extra payment information in the DB, causing the 409 Conflict)

nickmonad commented 1 year ago

To ultimately resolve this, we reset capture to false in the medusa-payment-stripe plugin config, and added simple logic to capture the payment within an order.placed event handler.

class OrderPlacedSubscriber {
    constructor({ eventBusService, cartService, orderService, orderRepository }) {
        this.cartService = cartService
        this.orderService = orderService
        this.orderRepository = orderRepository

        eventBusService.subscribe("order.placed", this.handleOrderPlaced, { subscriberId: "order-capture-fulfill" })
    }

    handleOrderPlaced = async (data) => {
        const order = await this.orderService.retrieve(data.id, { relations: ["items"] })

        // auto-capture payment
        if (order.payment_status !== "captured") {
            await this.orderService.capturePayment(order.id)
        }

        // ...  more processing

After some digging, it makes more sense to me why the 409 Conflict exists and is ultimately, the right thing to do. The Stripe webhook will get re-sent eventually, and then it does succeed, but that is no longer relevant with this approach.

brendansimcox commented 1 year ago

Just wanted to add to this to potentially help in debugging, from testing we have determined that the stripe only conflicts and fails when the its a guest user processing the transaction - anyone logged in we can't replicate the 409 conflicts from stripe webhook

chrislaai commented 1 year ago

409 Conflict happens regardless of whether I am registered and logged in or not.

alessioacella commented 1 year ago

Listen to "order.placed" should not be enough, orders are not saved into DB when hook receives 409, so the "order.placed" event will never occur... am i wrong?