Bug: Stripe Subscription payment failing - users not demoted

LOG ENTRY: Tue Oct 8th, 2019 @ precisely 10:37 pm UTC
PHP v7.3.9-1+ubuntu18.04.1+deb.sury.org+1 :: WordPress v5.2.3 :: s2Member v191007-beta :: s2Member Pro v191007-beta
Memory 9.66 MB :: Real Memory 2.00 MB :: Peak Memory 9.71 MB :: Real Peak Memory 2.00 MB
openmtbmap.org/?s2member_pro_stripe_notify=1
User-Agent: Stripe/1.0 (+https://stripe.com/docs/webhooks)
Array
(
[event] => Stripe\Event Object
(
[id] => evt_1FRRIeJQmekOBFQg35tOKOLz
[object] => event
[api_version] => 2018-08-23
[created] => 1570574220
[data] => Stripe\StripeObject Object
(
[object] => Stripe\Subscription Object
(
[id] => sub_6q4J4tpdNFWaoJ
[object] => subscription
[application_fee_percent] =>
[billing] => charge_automatically
[billing_cycle_anchor] => 1471732768
[billing_thresholds] =>
[cancel_at] => 1597876768
[cancel_at_period_end] => 1
[canceled_at] => 1570574220
[collection_method] => charge_automatically
[created] => 1440196768
[current_period_end] => 1597876768
[current_period_start] => 1566340768
[customer] => cus_6q4I8fEG2wZq0F
[days_until_due] =>
[default_payment_method] =>
[default_source] =>
[default_tax_rates] => Array
(
)

                    [discount] => 
                    [ended_at] => 
                    [items] => Stripe\Collection Object
                        (
                            [object] => list
                            [data] => Array
                                (
                                    [0] => Stripe\SubscriptionItem Object
                                        (
                                            [id] => si_18UZFqJQmekOBFQgJNP1w0cE
                                            [object] => subscription_item
                                            [billing_thresholds] => 
                                            [created] => 1440196769
                                            [metadata] => Stripe\StripeObject Object
                                                (
                                                )

                                            [plan] => Stripe\Plan Object
                                                (
                                                    [id] => s2_d894076243d10732d30a2e08307d17b1
                                                    [object] => plan
                                                    [active] => 1
                                                    [aggregate_usage] => 
                                                    [amount] => 1300
                                                    [amount_decimal] => 1300
                                                    [billing_scheme] => per_unit
                                                    [created] => 1421149410
                                                    [currency] => eur
                                                    [interval] => day
                                                    [interval_count] => 365
                                                    [livemode] => 1
                                                    [metadata] => Stripe\StripeObject Object
                                                        (
                                                            [recurring] => true
                                                            [recurring_times] => -1
                                                        )

                                                    [nickname] => 
                                                    [product] => prod_BTfeaPxdkk8sCa
                                                    [tiers] => 
                                                    [tiers_mode] => 
                                                    [transform_usage] => 
                                                    [trial_period_days] => 365
                                                    [usage_type] => licensed
                                                )

                                            [quantity] => 1
                                            [subscription] => sub_6q4J4tpdNFWaoJ
                                            [tax_rates] => Array
                                                (
                                                )

                                        )

                                )

                            [has_more] => 
                            [total_count] => 1
                            [url] => /v1/subscription_items?subscription=sub_6q4J4tpdNFWaoJ
                        )

                    [latest_invoice] => in_1F9fzFJQmekOBFQg6pUTKbVz
                    [livemode] => 1
                    [metadata] => Stripe\StripeObject Object
                        (
                            [tax_info] => {"trial_tax":"0.00","trial_tax_per":"0%","tax":"0.00","tax_per":"0%"}
                        )

                    [pending_setup_intent] => 
                    [plan] => Stripe\Plan Object
                        (
                            [id] => s2_d894076243d10732d30a2e08307d17b1
                            [object] => plan
                            [active] => 1
                            [aggregate_usage] => 
                            [amount] => 1300
                            [amount_decimal] => 1300
                            [billing_scheme] => per_unit
                            [created] => 1421149410
                            [currency] => eur
                            [interval] => day
                            [interval_count] => 365
                            [livemode] => 1
                            [metadata] => Stripe\StripeObject Object
                                (
                                    [recurring] => true
                                    [recurring_times] => -1
                                )

                            [nickname] => 
                            [product] => prod_BTfeaPxdkk8sCa
                            [tiers] => 
                            [tiers_mode] => 
                            [transform_usage] => 
                            [trial_period_days] => 365
                            [usage_type] => licensed
                        )

                    [quantity] => 1
                    [schedule] => 
                    [start] => 1570574220
                    [start_date] => 1440196768
                    [status] => active
                    [tax_percent] => 
                    [trial_end] => 
                    [trial_start] => 
                )

            [previous_attributes] => Stripe\StripeObject Object
                (
                    [cancel_at] => 
                    [cancel_at_period_end] => 
                    [canceled_at] => 
                    [start] => 1440196768
                    [trial_end] => 1471732768
                    [trial_start] => 1440196768
                )

        )

    [livemode] => 1
    [pending_webhooks] => 2
    [request] => Stripe\StripeObject Object
        (
            [id] => req_KR2Ief8SEMdBfl
            [idempotency_key] => 
        )

    [type] => customer.subscription.updated
)

[s2member_log] => Array
(
[0] => Ignoring this Webhook/IPN. The event does NOT require any action on the part of s2Member.
)

)

And I noticed something strange when exporting the canceled users via csv file. The current period is shown for 1 year longer than paid:

e.g. payment failed ultimately and subscription deleted - but I have the following entries:
Plan Quantity Interval Amount Status Created (UTC) Start (UTC) Current Period Start (UTC) Current Period End (UTC)
s2_e2c014693f9941122468457209b6912a 1 day 1300 canceled 17/08/2015 06:46 17/08/2015 06:46 16/08/2019 06:46 15/08/2020 06:46

The last successful payment was on the 16.08.2018. User did not cancel actively but payments failed.

Both events are “customer.subscription.updated”, which s2Member doesn’t do anything with.

I’m sorry, I didn’t understand your last message. Could you explain it a bit more? Thanks :slight_smile:

okay - I see this is correct - just differently from paypal where an EOT is set. However actually it would be very nice if s2member could already use that message to set an EOT if it can notice that the subscription is set to be canceled at the period end.

In the dashboard it says: 123@email.com’s subscription has been set to cancel at the end of the billing period.

That way EOT emails could be sent to the user with offers for prolongation (plus I somehow guess the user will not be deleted based on the current track record of users with wrong payment API email data)

As for the second post - I’ll privately send you a mail with the exported user data. This has been obtained from Stripe Dashboard --> Billing --> Subscriptions --> then filtered for canceled.
And it’s striking that the current period end is usually 1 year longer than the actual paid time. Maybe users will get demoted but 1 year too late (cannot test this as i demoted them manually before):

However I can see that in the dashboard there is an entry for: customer.subscription.deleted

10/4/19, 7:24:15 PM
(relating to kgp… - top entry of the csv if sorting by current period end (top down). However that user was not demoted…

and in the Stripe IPN the last message for that user is …

            [livemode] => 1
            [pending_webhooks] => 2
            [request] => 
            [type] => customer.subscription.deleted
        )

    [_unsavedValues:protected] => Stripe_Util_Set Object
        (
            [_elts:Stripe_Util_Set:private] => Array
                (
                )

        )

    [_transientValues:protected] => Stripe_Util_Set Object
        (
            [_elts:Stripe_Util_Set:private] => Array
                (
                )

        )

    [_retrieveOptions:protected] => Array
        (
        )

)

[s2member_log] => Array
(
[0] => Ignoring this Webhook/IPN. The event does NOT require any action on the part of s2Member.
)

)

Which should have led to demotion but did not…

the user had the
[id] => sub_6wL0AxFq3zAwIQ

correctly in his profile, also the IPN message before - [type] => invoice.updated - shows both the right subscription and email address.

But of course the payment api notification email was borked already.

So I completed this test, and it went well. The invoice payment failed, the subscription got cancelled, s2 got the customer.subscription.deleted, and EOT was set and user demoted. :+1:

        [type] => customer.subscription.deleted
    )
[s2member_log] => Array
    (
        [0] => Stripe Webhook/IPN event type identified as: `customer.subscription.deleted` on: Wed Oct 9, 2019 12:17:52 pm UTC
        [1] => Webhook/IPN event `customer.subscription.deleted` reformulated. Piping through s2Member's core gateway processor as `txn_type` (`subscr_eot`).
        [2] => Please check core IPN logs for further processing details.

And then on the other log:

        [0] => IPN received on: Wed Oct 9, 2019 12:17:48 pm UTC
        [1] => s2Member POST vars verified with a Proxy Key
        [2] => s2Member originating domain (`$_SERVER["HTTP_HOST"]`) validated.
        [3] => s2Member `txn_type` identified as ( `subscr_eot|recurring_payment_expired|recurring_payment_suspended_due_to_max_failed_payment` ) - or - `recurring_payment_profile_cancel` w/ `initial_payment_status` ( `failed` ).
        [4] => Member Level/Capabilities demoted to: Subscriber.

:slight_smile:

I’m experiencing the exact same problem. I have If all retries for a payment fail “cancel the subscription” set in “Manage failed payments” in Stripe

Here is one example:

Event in Stripe:
customer.subscription.deleted

Date
6/15/20, 5:03:02 PM
Source
Automatic

Event data
{
"object": {
"id": ["sub_FFlUVJeGdiXr2e"](https://dashboard.stripe.com/subscriptions/sub_FFlUVJeGdiXr2e),
"object": "subscription",
"application_fee_percent": null,
"billing_cycle_anchor": 1592056858,
"billing_thresholds": null,
"cancel_at": null,
"cancel_at_period_end": false,
"canceled_at": 1592233382,
"collection_method": "charge_automatically",
"created": 1560520858,
"current_period_end": 1623592858,
"current_period_start": 1592056858,
"customer": ["cus_FFlUwGIWWM9at3"]

s2Member Configuration & Profile Fields
s2memberfields
as you can see the Paid Subscr ID and CID matches the subscription in Stripe, however the user was NOT denoted to registered user when the customer.subscription.deleted Event in Stripe was triggered

I had my domain in custom value of a single customer - that way everything broke.
See: (s2Member / API Notification Email) - Payment - wrong user data

I exported all of my users to a spreadsheet. Did a check to see if my domain in custom value had been copied to a wrong field by accident, but looks ok to me. I can PM a link to the spreadsheet if you or @clavaque would like to take a look.

@openmtbmap and @clavaque could this be a bug with special characters/period in the domain name “hamar-tennis.no”? Everything else works like it should. The reason why this has come up now is that we started 12 months subscription a year ago. Now it’s time for renewal and payments are failing for various reasons. We have set subscription to be cancelled after 2 attempts in Stripe.

check the thread I linked - if you can also find the bogus user in the signup notification emails. else maybe check that the AUTO EOT (under paypal!) is still active. Sometimes it just switches off.

EOT/Denotion in s2Member is not set when subscription in Stripe is automatically cancelled. Here is an example of such an event “customer.subscritpion.deleted” after all retries for a payment fail.

evt_1GxX4rAvAK7zTur2fj9FI3pD
customer.subscription.deleted
Date
6/24/20, 1:47:41 PM
Source
Automatic
Event data
{
  "object": {
    "id": "sub_FJ5Or1Hb2X6kO9",
    "object": "subscription",
    "application_fee_percent": null,
    "billing_cycle_anchor": 1592822829,
    "billing_thresholds": null,
    "cancel_at": null,
    "cancel_at_period_end": false,
    "canceled_at": 1592999261,
    "collection_method": "charge_automatically",
    "created": 1561286829,
    "current_period_end": 1624358829,
    "current_period_start": 1592822829,
    "customer": "cus_FJ5OuDLsHZ3ufE",
    "days_until_due": null,
    "default_payment_method": null,
    "default_source": null,
    "default_tax_rates": [
    ],
    "discount": null,
    "ended_at": 1592999261,
    "items": {
      "object": "list",
      "data": [
        {
          "id": "si_FJ5OhgPppQSxtT",
          "object": "subscription_item",
          "billing_thresholds": null,
          "created": 1561286830,
          "metadata": {
          },
          "plan": {
            "id": "s2_414ae998b9b3b758f13019ba0f7aacd1",
            "object": "plan",
            "active": true,
            "aggregate_usage": null,
            "amount": 120000,
            "amount_decimal": "120000",
            "billing_scheme": "per_unit",
            "created": 1561286828,
            "currency": "nok",
            "interval": "day",
            "interval_count": 365,
            "livemode": true,
            "metadata": {
              "recurring": "true",
              "recurring_times": "-1"
            },
            "nickname": null,
            "product": "prod_FJ5OBr2opXq6kq",
            "tiers": null,
            "tiers_mode": null,
            "transform_usage": null,
            "trial_period_days": 365,
            "usage_type": "licensed"
          },
          "price": {
            "id": "s2_414ae998b9b3b758f13019ba0f7aacd1",
            "object": "price",
            "active": true,
            "billing_scheme": "per_unit",
            "created": 1561286828,
            "currency": "nok",
            "livemode": true,
            "lookup_key": null,
            "metadata": {
              "recurring": "true",
              "recurring_times": "-1"
            },
            "nickname": null,
            "product": "prod_FJ5OBr2opXq6kq",
            "recurring": {
              "aggregate_usage": null,
              "interval": "day",
              "interval_count": 365,
              "trial_period_days": 365,
              "usage_type": "licensed"
            },
            "tiers_mode": null,
            "transform_quantity": null,
            "type": "recurring",
            "unit_amount": 120000,
            "unit_amount_decimal": "120000"
          },
          "quantity": 1,
          "subscription": "sub_FJ5Or1Hb2X6kO9",
          "tax_rates": [
          ]
        }
      ],
      "has_more": false,
      "total_count": 1,
      "url": "/v1/subscription_items?subscription=sub_FJ5Or1Hb2X6kO9"
    },
    "latest_invoice": "in_1GwnBIAvAK7zTur2kYCNSOjR",
    "livemode": true,
    "metadata": {
      "tax_info": "{"tax":"0.00","tax_per":"0%"}"
    },
    "next_pending_invoice_item_invoice": null,
    "pause_collection": null,
    "pending_invoice_item_interval": null,
    "pending_setup_intent": null,
    "pending_update": null,
    "plan": {
      "id": "s2_414ae998b9b3b758f13019ba0f7aacd1",
      "object": "plan",
      "active": true,
      "aggregate_usage": null,
      "amount": 120000,
      "amount_decimal": "120000",
      "billing_scheme": "per_unit",
      "created": 1561286828,
      "currency": "nok",
      "interval": "day",
      "interval_count": 365,
      "livemode": true,
      "metadata": {
        "recurring": "true",
        "recurring_times": "-1"
      },
      "nickname": null,
      "product": "prod_FJ5OBr2opXq6kq",
      "tiers": null,
      "tiers_mode": null,
      "transform_usage": null,
      "trial_period_days": 365,
      "usage_type": "licensed"
    },
    "quantity": 1,
    "schedule": null,
    "start_date": 1561286829,
    "status": "canceled",
    "tax_percent": null,
    "transfer_data": null,
    "trial_end": 1592822829,
    "trial_start": 1561286829
  }
}

However if a customer cancel a subscription using the “Cancel Membership” function in s2member, EOT will be updated in s2member and set to the expiry date of the subscription and the subscription will be updated. Here is an example where a customer has cancelled the subscription:

customer.subscription.updated
Date
6/23/20, 10:58:16 PM
Source
API
Event data
{
  "object": {
    "id": "sub_FMCLt5DlSP5yOA",
    "object": "subscription",
    "application_fee_percent": null,
    "billing_cycle_anchor": 1593540580,
    "billing_thresholds": null,
    "cancel_at": 1593540580,
    "cancel_at_period_end": true,
    "canceled_at": 1592945896,
    "collection_method": "charge_automatically",
    "created": 1562004580,
    "current_period_end": 1593540580,
    "current_period_start": 1562004580,
    "customer": "cus_FMCLRexB1dBc4D",
    "days_until_due": null,
    "default_payment_method": null,
    "default_source": null,
    "default_tax_rates": [
    ],
    "discount": null,
    "ended_at": null,
    "items": {
      "object": "list",
      "data": [
        {
          "id": "si_FMCL7yfDpEOJhb",
          "object": "subscription_item",
          "billing_thresholds": null,
          "created": 1562004581,
          "metadata": {
          },
          "plan": {
            "id": "s2_88d5960a5f6f5e7d2c0e8ac8de474378",
            "object": "plan",
            "active": true,
            "aggregate_usage": null,
            "amount": 50000,
            "amount_decimal": "50000",
            "billing_scheme": "per_unit",
            "created": 1559839301,
            "currency": "nok",
            "interval": "day",
            "interval_count": 365,
            "livemode": true,
            "metadata": {
              "recurring": "true",
              "recurring_times": "-1"
            },
            "nickname": null,
            "product": "prod_FCoHimZg8tXBXB",
            "tiers": null,
            "tiers_mode": null,
            "transform_usage": null,
            "trial_period_days": 365,
            "usage_type": "licensed"
          },
          "price": {
            "id": "s2_88d5960a5f6f5e7d2c0e8ac8de474378",
            "object": "price",
            "active": true,
            "billing_scheme": "per_unit",
            "created": 1559839301,
            "currency": "nok",
            "livemode": true,
            "lookup_key": null,
            "metadata": {
              "recurring": "true",
              "recurring_times": "-1"
            },
            "nickname": null,
            "product": "prod_FCoHimZg8tXBXB",
            "recurring": {
              "aggregate_usage": null,
              "interval": "day",
              "interval_count": 365,
              "trial_period_days": 365,
              "usage_type": "licensed"
            },
            "tiers_mode": null,
            "transform_quantity": null,
            "type": "recurring",
            "unit_amount": 50000,
            "unit_amount_decimal": "50000"
          },
          "quantity": 1,
          "subscription": "sub_FMCLt5DlSP5yOA",
          "tax_rates": [
          ]
        }
      ],
      "has_more": false,
      "total_count": 1,
      "url": "/v1/subscription_items?subscription=sub_FMCLt5DlSP5yOA"
    },
    "latest_invoice": "in_1ErTweAvAK7zTur2zZarSMcl",
    "livemode": true,
    "metadata": {
      "tax_info": "{"tax":"0.00","tax_per":"0%"}"
    },
    "next_pending_invoice_item_invoice": null,
    "pause_collection": null,
    "pending_invoice_item_interval": null,
    "pending_setup_intent": null,
    "pending_update": null,
    "plan": {
      "id": "s2_88d5960a5f6f5e7d2c0e8ac8de474378",
      "object": "plan",
      "active": true,
      "aggregate_usage": null,
      "amount": 50000,
      "amount_decimal": "50000",
      "billing_scheme": "per_unit",
      "created": 1559839301,
      "currency": "nok",
      "interval": "day",
      "interval_count": 365,
      "livemode": true,
      "metadata": {
        "recurring": "true",
        "recurring_times": "-1"
      },
      "nickname": null,
      "product": "prod_FCoHimZg8tXBXB",
      "tiers": null,
      "tiers_mode": null,
      "transform_usage": null,
      "trial_period_days": 365,
      "usage_type": "licensed"
    },
    "quantity": 1,
    "schedule": null,
    "start_date": 1562004580,
    "status": "trialing",
    "tax_percent": null,
    "transfer_data": null,
    "trial_end": 1593540580,
    "trial_start": 1562004580
  },
  "previous_attributes": {
    "cancel_at": null,
    "cancel_at_period_end": false,
    "canceled_at": null
  }
}

Screenshot from s2member where the EOT is set correctly according to when the subscrition will end
image
This matches the status of the subscription in Stripe

@clavaque and @openmtbmap Food for thought: could it be that my host is blocking communication FROM Stripe? I’ve had to ask them to whitelist IP address of other servers (eg Amazon) in order to get some Wordpress plugins to work. The reason why I’m thinking this might be the problem is that all functions that are initiated FROM s2member against Stripe is working as it should. The denotion when renewal of subscription (customer.subscription.deleted) is the only function/action that is initiated FROM Stripe against s2member. As previously mentioned we have never used it before until recently.

Could be the problem. A few people recently have complained about problems that turned out to be their host or their security plugins blocking messages to / from Stripe. You should be able to see that in the Stripe logs though.

This is really embarrasing. Apparantly I had forgot to add an Endpoint for s2member in Stripe. This is clearly mentioned in the documentation for s2Member "This section is required (if you are using Stripe )". Sorry for making all this fuzz :crazy_face: Thank you @onepresstech for pointing me in the right direction “Stripe logs”

Cool…always happy when someone gets their problem solved no matter how it gets solved :slight_smile:

Just a quick question @onepresstech - in the s2Member documentation it does not specify what type of events that should be used for the webhook. If I choose “All Events” I get this warning message.
image
Is it only the “customer.subscription.deleted” event that I need, or are there other type of events that should be selected for the s2member webhook?

It’s a good question…I just answered it for someone else who asked…see Stripe Webhook Events List