Subscription automatically suspended after grace period

—

by

Robert McLean

Hi: We have a persistent problem with one-time payment subscriptions being automatically cancelled after the subscription grace period expires.

Here are the subscription settings used for a recent test
Setup price 1:00
Subscription price: blank
Frequency: tried to set 0 but always reverts to 1
Frequency unit: years
How many times: blank

I went through the normal process to subscribe, checkout, and pay via paypal, and was successfully directed to the paypal return page.

Here are the log entries showing a successive paypal transaction (personal info is shown as “SUPPRESSED”):

2019-05-28 14:02:19 +0000 – INFO : Groups_Subscriptions_Debug::groups_created_subscription : Groups_Subscription::__set_state(array(
‘subscription’ =>
stdClass::__set_state(array(
‘subscription_id’ => ’57’,
‘user_id’ => ‘180’,
‘processor’ => NULL,
‘reference’ => NULL,
‘status’ => ‘inactive’,
‘from_datetime’ => ‘2019-05-28 14:02:19’,
‘thru_datetime’ => NULL,
‘last_payment’ => NULL,
‘frequency’ => ‘2147483647’,
‘frequency_uom’ => ‘year’,
‘total_count’ => NULL,
‘current_count’ => ‘0’,
‘description’ => ‘Test subscription’,
‘data’ => NULL,
)),
))
2019-05-28 14:02:19 +0000 – INFO : Groups_Subscriptions_Debug::groups_created_subscription_order_item : Groups_Subscription_Order_Item::__set_state(array(
‘subscription_order_item’ =>
stdClass::__set_state(array(
‘subscription_id’ => ’57’,
‘order_id’ => ’57’,
‘item_id’ => ‘1714’,
)),
))
2019-05-28 14:02:19 +0000 – INFO : Groups_Subscriptions_Debug::groups_created_group_subscription : Groups_Group_Subscription::__set_state(array(
‘group_subscription’ =>
stdClass::__set_state(array(
‘group_id’ => ‘4’,
‘subscription_id’ => ’57’,
)),
))
2019-05-28 14:02:40 +0000 – INFO : Groups_Subscription_Handler::check_subscription : checking subscription with id 57
2019-05-28 14:05:04 +0000 – INFO : Groups_PayPal_Listener::notify : event = IX_PayPal_IPN_Event::__set_state(array(
‘IPN_variables’ =>
array (
‘mc_gross’ => ‘1.13’,
‘protection_eligibility’ => ‘Eligible’,
‘address_status’ => ‘confirmed’,
‘payer_id’ => ‘5GJ2HEYNCBH3A’,
‘tax’ => ‘0.13’,
‘address_street’ => ‘SUPPRESSED’,
‘payment_date’ => ’07:04:50 May 28, 2019 PDT’,
‘payment_status’ => ‘Completed’,
‘charset’ => ‘windows-1252’,
‘address_zip’ => ‘SUPPRESSED’,
‘first_name’ => ‘SUPPRESSED’,
‘mc_fee’ => ‘0.33’,
‘address_country_code’ => ‘CA’,
‘address_name’ => ‘SUPPRESSED’,
‘notify_version’ => ‘3.9’,
‘custom’ => ’57’,
‘payer_status’ => ‘unverified’,
‘business’ => ‘SUPPRESSED’,
‘address_country’ => ‘Canada’,
‘address_city’ => ‘SUPPRESSED’,
‘quantity’ => ‘1’,
‘verify_sign’ => ‘A40ye9BlKlusHh.iKmypi36pjLyvAx5v8.VhnEZrSOGOORuVnV9Dgy9-‘,
‘payer_email’ => ‘SUPPRESSED’,
‘txn_id’ => ‘09716485YW3678445’,
‘payment_type’ => ‘instant’,
‘last_name’ => ‘SUPPRESSED’,
‘address_state’ => ‘ON’,
‘receiver_email’ => ‘SUPPRESSED’,
‘payment_fee’ => ”,
‘shipping_discount’ => ‘0.00’,
‘insurance_amount’ => ‘0.00’,
‘receiver_id’ => ‘S3354BVZMZLFS’,
‘txn_type’ => ‘web_accept’,
‘item_name’ => ‘Test subscription’,
‘discount’ => ‘0.00’,
‘mc_currency’ => ‘CAD’,
‘item_number’ => ”,
‘residence_country’ => ‘CA’,
‘receipt_id’ => ‘0376-3616-5338-7342’,
‘shipping_method’ => ‘Default’,
‘transaction_subject’ => ”,
‘payment_gross’ => ”,
‘ipn_track_id’ => ‘c86908a4f000b’,
),
))
2019-05-28 14:05:04 +0000 – INFO : Groups_Subscription::update : set = array (
0 => ‘processor = %s’,
1 => ‘reference = %s’,
2 => ‘status = %s’,
)
2019-05-28 14:05:04 +0000 – INFO : Groups_Subscription::update : values = array (
0 => ‘paypal’,
1 => ‘09716485YW3678445’,
2 => ‘active’,
3 => 57,
)
2019-05-28 14:05:05 +0000 – INFO : Groups_Subscriptions_Debug::groups_updated_subscription : Groups_Subscription::__set_state(array(
‘subscription’ =>
stdClass::__set_state(array(
‘subscription_id’ => ’57’,
‘user_id’ => ‘180’,
‘processor’ => ‘paypal’,
‘reference’ => ‘09716485YW3678445’,
‘status’ => ‘active’,
‘from_datetime’ => ‘2019-05-28 14:02:19’,
‘thru_datetime’ => NULL,
‘last_payment’ => NULL,
‘frequency’ => ‘2147483647’,
‘frequency_uom’ => ‘year’,
‘total_count’ => NULL,
‘current_count’ => ‘0’,
‘description’ => ‘Test subscription’,
‘data’ => NULL,
)),
))

After this transaction, the subscription showed as Active on both the Subscriptions list and the user profile.

However, for the next six hours there are regular entries such as:

2019-05-28 14:05:05 +0000 – INFO : Groups_Subscription_Handler::check_subscription : checking subscription with id 57
2019-05-28 14:05:09 +0000 – INFO : Groups_Subscription_Handler::check_subscription : checking subscription with id 57

This suggests that the plugin doesn’t recognize that the one-time subscription fee has already been paid.

Then after the 6 hour grace period expired, we have this entry:

2019-05-28 20:11:07 +0000 – INFO : Groups_Subscription_Handler::check_subscription : suspending subscription with id = 57
2019-05-28 20:11:07 +0000 – INFO : Groups_Subscription::update : set = array (
0 => ‘status = %s’,
)
2019-05-28 20:11:07 +0000 – INFO : Groups_Subscription::update : values = array (
0 => ‘suspended’,
1 => 57,
)
2019-05-28 20:11:07 +0000 – INFO : Groups_Subscriptions_Debug::groups_updated_subscription : Groups_Subscription::__set_state(array(
‘subscription’ =>
stdClass::__set_state(array(
‘subscription_id’ => ’57’,
‘user_id’ => ‘180’,
‘processor’ => ‘paypal’,
‘reference’ => ‘09716485YW3678445’,
‘status’ => ‘suspended’,
‘from_datetime’ => ‘2019-05-28 14:02:19’,
‘thru_datetime’ => NULL,
‘last_payment’ => NULL,
‘frequency’ => ‘2147483647’,
‘frequency_uom’ => ‘year’,
‘total_count’ => NULL,
‘current_count’ => ‘0’,
‘description’ => ‘Test subscription’,
‘data’ => NULL,
)),
))

The subscription now shows as “Suspended” in the subscription list and is missing from the user profile.

This has been happening with production subscriptions for a long time now, but we just now figured out how to turn on logging and verified that subscriptions are being automatically suspended after the grace period.

Is this a configuration issue, or is there a bug? Why would the plugin not recognize that the one-time subscription has been paid for, and why does it keep checking until the grace period expires? What is it checking for that it is not finding?

Would be grateful for any insight you can provide.

Rob

Posted in

Comments

3 responses to “Subscription automatically suspended after grace period”

  1. matrixlinks@icloud.com Avatar
    matrixlinks@icloud.com

    Thanks Denitsa: The cycle column contains the following symbols “∞ #0 / #1”. Note that this subscription is supposed to be active indefinitely after a one-time payment.

    As you can see from the log entries in my initial post, when initially created, the subscription has status of “inactive”. Then after processing the paypal payment, the status is set to “active”. But then 6 hours later on expiration of the grace period, the subscription is set to status of “suspended”. So the mystery is why the plugin does not recognize that the one-time payment has been made and that the subscription should remain “active”.

    Look forward to your further insights.
    Rob

    1. Denitsa Avatar
      Denitsa

      Hey Rob,
      Thank you for the details!
      From the contents of the Cycles column it would seem that indeed no payment is registered in the database (moreover, the ‘last_payment’ => NULL line from the log points in kind of the same direction too).
      I would like to investigate further, if you’re willing to provide access to the database (via cPanel, for example) and the site’s dashboard. You can securely send those in to our email – help [at] itthinx [dot] com.
      Cheers,
      Denitsa

  2. Denitsa Avatar
    Denitsa

    Hello, Rob,
    If payment is pending on a subscription that’s already active, then the subscription should be suspended. Therefore, the handler needs to reschedule itself for active subscriptions, hence the checks in the log.
    I would guess from the log that the payment is not being registered in the database, so would you tell me the status of the column named Cycles under Groups > Subscriptions?
    Cheers,
    Denitsa

Share