Email Receipts Not Sent Following Contribution

[Campaigner]

Whenever any user of my site makes a contribution - either directly through a CiviContribute contribution page or a CiviEvent page - they fail to receive an email receipt even though the "Email Receipt to Contributor?" box is checked on the configure contribution page (as well as the "Send Confirmation Email?" box on the configure event page). The problem appears to be limited to contributions -- for example a CiviEvent registrant who elects to "Pay Later" will receive a receipt, and in pay later situations so too do the people I have set up to receive bcc copies of the event receipts. However, when a contribution is made, either through a contribution or an event page, neither the contributor nor the email addresses I have set up to received bcc's of the receipt receive an email.

Nevertheless, the processing of the contribution itself occurs as normal. The individual is taken to Paypal, is able to enter in their payment information, is redirected back to my website's thank you page, receives their email receipt from Paypal (though not the one from my site), and their contribution is marked as having a "Completed" status in CiviContribute.

As I mentioned, neither the contributor nor the email addresses I have set up to received bcc's of the receipt receive an email. I am however able to go into a contribution record and manually click the "Send Receipt?" checkbox and consequently successfully send a receipt to just the contributor (though not the automatic bcc addresses). Sending manual receipts is of course a poor workaround, not least because the receipt is only sent when I have time to go through the contribution records, compared to the automatic receipting, which used to happen instantaneously. Otherwise, as far as I can tell, the email capabilities of CiviCRM are working fine. For example, I can properly send a test email from the "Settings - Outbound Mail" administration page (using either SMTP or mail() as the mailer). Other email functions on the website (such as CiviMail outbound emails and pay-later receipts for CiviEvents) all appear to work as normal.

We have experienced the above problem for the last two months, and despite numerous efforts, I cannot seem to track down the source of the problem or an open issue in the CiviCRM bug reports that appears to address this problem.  If someone can please point me to a fix or how I can work on determining where the email receipts process is breaking down, I would be most grateful.

[Donald Lobo]

I would enable mail logging and run a simple experiment and see if mail does get sent (i.e. if its present in the log files)

if so, u know this is an issue with the civi <-> mail server interaction

does your system send mail at all? can u use send an email action and send mail to someone else in the DB?

thanx

lobo

[Campaigner]

I enabled email logging by setting the CIVICRM_MAIL_LOG config option in civicrm.settings.php. At the times when emails should be sent after a contribution, nothing changes in the log file. Other emails to users that do not involve contributions do indeed get logged in the mail log file. So, as in my original message, email functionality appears to be fully operational with the exception of emails related to contributions.

What conclusion should I draw from the fact that contribution email receipts/confirmation emails are not being set to the log file when email logging is enabled?
 

I would enable mail logging and run a simple experiment and see if mail does get sent (i.e. if its present in the log files)

if so, u know this is an issue with the civi <-> mail server interaction

does your system send mail at all? can u use send an email action and send mail to someone else in the DB?

thanx

lobo

[Chris Burgess]

One way I've seen this fail is that if the mail template contains invalid Smarty, it fails to generate a message correctly and doesn't send. Unsure if valid Smarty syntax from earlier versions is not accepted in later, but one client had to edit most of their customised messages to sort this out.

Another way is when emails are accepted by the MTA, but not delivered (hitting spam filters etc). If these don't bounce, or bounces don't arrive, it can appear to be disappearing into a black hole.

Checking your debug logs (CiviCRM debug log, Drupal watchdog log, PHP/webserver error log, mail server log) is a good place to start. One of those is likely to show some useful information and confirm where things are falling down.

[Donald Lobo]

seems like something might be failing in the IPN return path and hence the email is not sent. Your next best bet would be to debug the ipn return path, specifically where it is sending email to get more details. most of the code should be triggered from: CRM/Core/Payment/PayPalIPN.php

lobo

[Campaigner]

Donald,

You appear to be onto something.

The CiviCRM logs begin by recording each contribution as follows (with the date and time changing accordingly):

Nov 10 23:46:22  [info] Contribution record updated successfully
Nov 10 23:46:32  [info] returning since contribution has already been handled

But then, when I refund the Paypal contribution (because this is just a test contribution), whether that is two minutes later or two hours letter I get an entry like the following:

Nov 10 23:49:47  [info] Amount values dont match between database and IPN request

Clearly therefore, some process is running that is continuing to inquire as to the Paypal payment and doesn't get to the step of sending the confirmation email (and eventually comes to an end when the contribution is refunded).

My follow-up question for you then, and continued thanks for being so helpful, is how do I go about debugging the IPN return path? I do see the file, CRM/Core/Payment/PayPalIPN.php. which is the standard version used in the latest version of CiviCRM.

seems like something might be failing in the IPN return path and hence the email is not sent. Your next best bet would be to debug the ipn return path, specifically where it is sending email to get more details. most of the code should be triggered from: CRM/Core/Payment/PayPalIPN.php

lobo

Meanwhile, Chris, I've looked through whatever log files I've been able to find, and there is a maillog file that appears to show some of the non-contribution emails being delivered by qmail successfully, but otherwise there are a series of failed deliveries.

One example of a failed delivery comes from the following excerpt of the maillog around the time of a contribution transaction that would have until normal circumstances triggered a confirmation/receipt email:

Nov 10 19:26:42 vps qmail: 1384129602.923386 starting delivery 381: msg 448628163 to remote abc@test.com
Nov 10 19:26:42 vps qmail: 1384129602.923554 status: local 0/10 remote 1/20
Nov 10 19:26:42 vps qmail: 1384129602.923632 starting delivery 382: msg 448628093 to remote abc@test.com
Nov 10 19:26:42 vps qmail: 1384129602.923708 status: local 0/10 remote 2/20
Nov 10 19:26:42 vps qmail-remote-handlers[13742]: Handlers Filter before-remote for qmail started ...
Nov 10 19:26:42 vps qmail-remote-handlers[13742]: from=postmaster@vps.[website.com] [Note: I have bracketed and replaced the actual name of the website]
Nov 10 19:26:42 vps qmail-remote-handlers[13742]: to=abc@test.com
Nov 10 19:26:42 vps qmail-remote-handlers[13742]: hook_dir = '/usr/local/psa/handlers/before-remote'
Nov 10 19:26:42 vps qmail-remote-handlers[13742]: recipient[3] = 'abc@test.com'
Nov 10 19:26:42 vps qmail-remote-handlers[13742]: handlers dir = '/usr/local/psa/handlers/before-remote/recipient/abc@test.com'
Nov 10 19:26:42 vps qmail-remote-handlers[13743]: Handlers Filter before-remote for qmail started ...
Nov 10 19:26:42 vps qmail-remote-handlers[13743]: from=postmaster@vps.[website.com]
Nov 10 19:26:42 vps qmail-remote-handlers[13743]: to=abc@test.com
Nov 10 19:26:42 vps qmail-remote-handlers[13743]: hook_dir = '/usr/local/psa/handlers/before-remote'
Nov 10 19:26:42 vps qmail-remote-handlers[13743]: recipient[3] = 'abc@test.com'
Nov 10 19:26:42 vps qmail-remote-handlers[13743]: handlers dir = '/usr/local/psa/handlers/before-remote/recipient/abc@test.com'
Nov 10 19:26:42 vps qmail: 1384129602.933872 delivery 381: deferral: Sorry,_I_wasn't_able_to_establish_an_SMTP_connection._(#4.4.1)/
Nov 10 19:26:42 vps qmail: 1384129602.933955 status: local 0/10 remote 1/20
Nov 10 19:26:42 vps qmail: 1384129602.934315 delivery 382: deferral: Sorry,_I_wasn't_able_to_establish_an_SMTP_connection._(#4.4.1)/
Nov 10 19:26:42 vps qmail: 1384129602.934393 status: local 0/10 remote 0

However, the maillog is full of entries like the above one at numerous times throughout the day, not just at the times the contributions were made. And in any event, the contributions were not made from the email address "abc@test.com". So, maybe these are unrelated attempts by outside computers trying to use our email system.

As an aside, my system uses Joomla, so the Drupal watchdog suggestion is inapplicable. And though I do not follow the entirety of your reference to Smarty, I did infer that it would be a good idea to restore for now the default "Contributions - Receipt (off-line)" system workflow message under the CiviCRM message templates, so I did so. Still, that does not appear to have had any effect on the error.

Thank you both.

One way I've seen this fail is that if the mail template contains invalid Smarty, it fails to generate a message correctly and doesn't send. Unsure if valid Smarty syntax from earlier versions is not accepted in later, but one client had to edit most of their customised messages to sort this out.

Another way is when emails are accepted by the MTA, but not delivered (hitting spam filters etc). If these don't bounce, or bounces don't arrive, it can appear to be disappearing into a black hole.

Checking your debug logs (CiviCRM debug log, Drupal watchdog log, PHP/webserver error log, mail server log) is a good place to start. One of those is likely to show some useful information and confirm where things are falling down.

[Eileen]

We capture all incoming IPNs from paypal using a hack to the ipn.php class

https://github.com/fuzionnz/civicrm/commit/591d2373db5b9f63b5e5d3675765436fb014c1e6#diff-192d2b381e43d0f9912f35e4d7fc73e8

We also have an api action that will re-run them - for testing

https://github.com/fuzionnz/civicrm/blob/4.2-master/api/v3/NotificationLog.php

Are you dealing with recurring contributions?

[Campaigner]

Thanks, Eileen. I looked at the ipn.php file we have and it does not line up with the unedited portions of the version you linked to (for example, it does not have a $dao variable). Perhaps your hacked version builds off of an earlier version of ipn.php (before CiviCRM 4.4). In any event, because things did not line up, I did not proceed with inserting the language proposed in the hack. I do agree though that getting more insight into what's happening with the IPN would be very helpful. Any other suggestions on how to do this?

In any event, we are not dealing with recurring contributions. These are all one-time contributions.


P.S. For your reference, my copy of \administrator\components\com_civicrm\civicrm\extern\ipn.php is below. It is not modified from the CiviCRM 4.4 standard version.

/*
 +--------------------------------------------------------------------+
 | CiviCRM version 4.4                                                |
 +--------------------------------------------------------------------+
 | Copyright CiviCRM LLC (c) 2004-2013                                |
 +--------------------------------------------------------------------+
 | This file is a part of CiviCRM.                                    |
 |                                                                    |
 | CiviCRM is free software; you can copy, modify, and distribute it  |
 | under the terms of the GNU Affero General Public License           |
 | Version 3, 19 November 2007 and the CiviCRM Licensing Exception.   |
 |                                                                    |
 | CiviCRM is distributed in the hope that it will be useful, but     |
 | WITHOUT ANY WARRANTY; without even the implied warranty of         |
 | MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.               |
 | See the GNU Affero General Public License for more details.        |
 |                                                                    |
 | You should have received a copy of the GNU Affero General Public   |
 | License and the CiviCRM Licensing Exception along                  |
 | with this program; if not, contact CiviCRM LLC                     |
 | at info[AT]civicrm[DOT]org. If you have questions about the        |
 | GNU Affero General Public License or the licensing of CiviCRM,     |
 | see the CiviCRM license FAQ at http://civicrm.org/licensing        |
 +--------------------------------------------------------------------+
*/

/**
 * @package CRM
 * @copyright CiviCRM LLC (c) 2004-2013
 * $Id$
 */

session_start();

require_once '../civicrm.config.php';

/* Cache the real UF, override it with the SOAP environment */

$config = CRM_Core_Config::singleton();

if (empty($_GET)) {
  $paypalIPN = new CRM_Core_Payment_PayPalProIPN($_REQUEST);
}
else {
  $paypalIPN = new CRM_Core_Payment_PayPalIPN();
  // @todo upgrade standard per Pro
}
try{
  $paypalIPN->main();
}
catch(CRM_Core_Exception $e) {
  CRM_Core_Error::debug_log_message($e->getMessage());
  CRM_Core_Error::debug_var('error data', $e->getErrorData(), TRUE, TRUE);
  CRM_Core_Error::debug_var('REQUEST', $_REQUEST, TRUE, TRUE);
  //@todo give better info to logged in user - ie dev
  echo "The transaction has failed. Please review the log for more detail";
}

We capture all incoming IPNs from paypal using a hack to the ipn.php class

https://github.com/fuzionnz/civicrm/commit/591d2373db5b9f63b5e5d3675765436fb014c1e6#diff-192d2b381e43d0f9912f35e4d7fc73e8

We also have an api action that will re-run them - for testing

https://github.com/fuzionnz/civicrm/blob/4.2-master/api/v3/NotificationLog.php

Are you dealing with recurring contributions?

[Eileen]

ah the if($dao->N) { bit being removed was my first version of the same hack - that's why you don't see it.

[Campaigner]

Ok. I looked back at an archived ipn.php file (from CiviCRM 3.2) and it too never had some of the white lines (like $logTableExists = FALSE;) that your pre-hacked version shows at lines 41-43 of  https://github.com/fuzionnz/civicrm/commit/591d2373db5b9f63b5e5d3675765436fb014c1e6#diff-192d2b381e43d0f9912f35e4d7fc73e8.

So, to be clear, you are recommending inserting lines 44 through 57 from that github.com link in our own ipn.php between the lines (a) "$config = CRM_Core_Config::singleton();" and (b) "if (empty($_GET)) {". Correct?

Where then is the "civicrm_notification_log" that your hack language makes reference to? Is it the log at media/civicrm/ConfigAndLog/?

ah the if($dao->N) { bit being removed was my first version of the same hack - that's why you don't see it.

[Eileen]

what that hack does is create the table if it doesn't exist & then logs the ipn to it - it's just a way to capture the ipns touching as few files as possible

[Campaigner]

I inserted the new language into ipn.php and ran a sample contribution. The result was a civicrm_notification_log in the database with two identical entries apart from the fact that one had an ID number of 1 and the other had an ID number of 2. Otherwise, they had the same timestamp, and both were of message_type paypalpro-ipn. The message_raw information in the next field of the civicrm_notification_log entries then contained the following [with brackets being used to remove identifiable information]:

{"reset":"1","contactID":"1","contributionID":"735","module":"contribute","mc_gross":"0.01","invoice":"[32 digit string]","protection_eligibility":"Ineligible","payer_id":"[13 digit string]","tax":"0.00","payment_date":"15:20:04 Nov 11, 2013 PST","payment_status":"Completed","charset":"windows-1252","first_name":"[Name]","mc_fee":"0.01","notify_version":"3.7","custom":"","payer_status":"verified","business":"[email address]","quantity":"1","verify_sign":"AoS.E.[51 digit string]","payer_email":"[payer email address]","txn_id":"[17 digit string]","payment_type":"instant","last_name":"[Last Name]","receiver_email":"[email]","payment_fee":"0.01","receiver_id":"[13 digit string]","txn_type":"web_accept","item_name":"Online Contribution: [Name of Contribution Page]","mc_currency":"USD","item_number":"","residence_country":"US","handling_amount":"0.00","transaction_subject":"","payment_gross":"0.01","shipping":"0.00","ipn_track_id":"[13 digit string]"}

Another IPN entry appears in the civicrm_notification_log when a Paypal refund for the transaction is issued. Let me know if any details about that would be useful, but I assume it is the IPN entry at the time of the payment that is the interesting one, given that that's when the confirmation email should be sent.

Let me know whether seeing the above IPN triggers any ideas as to what might be keeping the contribution confirmation emails from being sent, or if you have any other ideas for how to get to the bottom of this issue.

All the best,
David

what that hack does is create the table if it doesn't exist & then logs the ipn to it - it's just a way to capture the ipns touching as few files as possible

[Eileen]

Yes, so from there I generally can copy the DB to a dev copy of the site & re-run the IPNS using the api in our repo https://github.com/fuzionnz/civicrm/blob/4.2-master/api/v3/NotificationLog.php with debug scattered throughout to figure out what it wrong this time (I capture all our IPNS because I often need to go back & debug something - e.g http://issues.civicrm.org/jira/browse/CRM-13743. Note that at a pinch you can run it from firebug - CRM.api('notification_log', 'retry', {'id' : 4}

When working on dev you can output all emails to a log file to prevent them going out

define('CIVICRM_MAIL_LOG', 1);

On your dev site you can tinker with the data & un-confirm / remove the transaction if it has already run - I would start CRM_Core_Payment_BaseIPN around this line '
    CRM_Core_Error::debug_log_message("Contribution record updated successfully");'

& find out what the param $values looks like

[Campaigner]

So at this point, I think that I am clearly in over my head. I have virtually no experience with debugging.

I see that in the Administer CiviCRM menu for "Settings - Debugging and Error Handling" that debugging can be enabled and then a "Smarty Debug Window" can be obtained by adding "&smartyDebug=1" to any CiviCRM URL query string. However, I don't know how to add such a string to the contribution page, given that the process for moving to the next page involves clicking a Contribute button that does not readily allow adding to the URL that is called upon. I apologize in advance for the fact that this all must seem fairly basic.

Also, can someone please identify for me the file and line within that file in a standard CiviCRM installation that is supposed to be triggered in order to send out contribution receipt emails (to the contributor or to the bcc: individuals specified in the CiviContribute or CiviEvent settings)?

Yes, so from there I generally can copy the DB to a dev copy of the site & re-run the IPNS using the api in our repo https://github.com/fuzionnz/civicrm/blob/4.2-master/api/v3/NotificationLog.php with debug scattered throughout to figure out what it wrong this time (I capture all our IPNS because I often need to go back & debug something - e.g http://issues.civicrm.org/jira/browse/CRM-13743. Note that at a pinch you can run it from firebug - CRM.api('notification_log', 'retry', {'id' : 4}

When working on dev you can output all emails to a log file to prevent them going out

define('CIVICRM_MAIL_LOG', 1);

On your dev site you can tinker with the data & un-confirm / remove the transaction if it has already run - I would start CRM_Core_Payment_BaseIPN around this line '
    CRM_Core_Error::debug_log_message("Contribution record updated successfully");'

& find out what the param $values looks like

[Eileen]

file-wise CRM_Core_Payment_BaseIPN equates to CRM/Core/Payment/BaseIPN.php

If you add some lines like


      CRM_Core_Error::debug_var('values', $values, TRUE, TRUE);
      CRM_Core_Error::debug_var('recur', $recur, TRUE, TRUE);
      CRM_Core_Error::debug_var('objects', $objects, TRUE, TRUE);
      CRM_Core_Error::debug_var('input', $input, TRUE, TRUE);
      CRM_Core_Error::debug_var('ids', $ids, TRUE, TRUE);


then the values will be logged into the log file

e.g right before this line

    CRM_Core_Error::debug_log_message("Success: Database updated");

If seems that $values['is_email_receipt']  is likely to be set to 0

I would probably put the same lines just below

  function completeTransaction(&$input, &$ids, &$objects, &$transaction, $recur = FALSE) {

to see whether it was already  0 at the start of that function