Is this a bug? “Paypal IPNS not handled other than recurring_payments” appears when txn_type is recurring_payment_profile_created

Question

On a WordPress site with CiviCRM 4.7.8, using 'Paypal - Website Payments Pro' payment processor:

When a user submits a recurring contribution, that recurring subscription is created in PayPal, but in CiviCRM it remains in 'Pending' status. When the IPN notification is resent, the following is written to the error log:

Jun 17 09:50:14  [info] $GET = Array
(
)


Jun 17 09:50:14  [info] $POST = Arrayhttps://[domain, redacted]/wp-admin/admin.php?page=CiviCRM&q=civicrm%2Fadmin%2FpaymentProcessor&action=update&id=1&reset=1#
(
    [payment_cycle] => Daily
    [txn_type] => recurring_payment_profile_created
    [last_name] => [last name, redacted]
    [next_payment_date] => 03:00:00 Jun 13, 2016 PDT
    [residence_country] => US
    [initial_payment_amount] => 0.00
    [rp_invoice_id] => i=[invoice id, redacted]
    [m] => contribute
    [c] => 27906
    [r] => 262
    [b] => 49350
    [p] => 2
    [currency_code] => USD
    [time_created] => 13:04:25 Jun 13, 2016 PDT
    [verify_sign] => [verify sign, redacted]
    [period_type] =>  Regular
    [payer_status] => unverified
    [tax] => 0.00
    [payer_email] => [email, redacted]
    [first_name] => [first name, redacted]
    [receiver_email] => paypal@[domain, redacted]
    [payer_id] => [payer_id, redacted]
    [product_type] => 1
    [shipping] => 0.00
    [amount_per_cycle] => 1.00
    [profile_status] => Active
    [charset] => windows­1252
    [notify_version] => 3.8
    [amount] => 1.00
    [outstanding_balance] => 0.00
    [recurring_payment_id] => [recurring payment id, redacted]
    [product_name] => Online Contribution: Donate Now: 1.00 Per 1 day
    [ipn_track_id] => [ipn track id, redacted]
)


Jun 17 09:50:14  [info] Paypal IPNS not handled other than recurring_payments

Jun 17 09:50:14  [info] $error data = Array
(
    [error_code] => 0
)


Jun 17 09:50:14  [info] $REQUEST = Array
(
    [payment_cycle] => Daily
    [txn_type] => recurring_payment_profile_created
    [last_name] => [last name, redacted]
    [next_payment_date] => 03:00:00 Jun 13, 2016 PDT
    [residence_country] => US
    [initial_payment_amount] => 0.00
    [rp_invoice_id] => i=[invoice id, redacted]
    [m] => contribute
    [c] => 27906
    [r] => 262
    [b] => 49350
    [p] => 2
    [currency_code] => USD
    [time_created] => 13:04:25 Jun 13, 2016 PDT
    [verify_sign] => [verify sign, redacted]
    [period_type] =>  Regular
    [payer_status] => unverified
    [tax] => 0.00
    [payer_email] => [email, redacted]
    [first_name] => [first name, redacted]
    [receiver_email] => paypal@[domain, redacted]
    [payer_id] => [payer_id, redacted]
    [product_type] => 1
    [shipping] => 0.00
    [amount_per_cycle] => 1.00
    [profile_status] => Active
    [charset] => windows­1252
    [notify_version] => 3.8
    [amount] => 1.00
    [outstanding_balance] => 0.00
    [recurring_payment_id] => [recurring payment id, redacted]
    [product_name] => Online Contribution: Donate Now: 1.00 Per 1 day
    [ipn_track_id] => [ipn track id, redacted]
)

Is this a bug, or might there be some configuration we can adjust?

Answer 1

This is a bit of a red herring. The message "Paypal IPNS not handled other than recurring_payments" is legitimate in this case. What's happening is that PayPal sends a single confirmation message upon receipt of the recurring payment request, and then later it will send "recurring" IPN messages for each recurring payment, including the first one. This single confirmation message is rightly ignored, because soon after it will come the IPN message for the first recurring payment.