CiviCRM Community Forums (archive)

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

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,

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.

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?

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.

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

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