[regression] CiviMail crashing on send instead of throwing exception when using Job.execute (#72) · Issues · Development / Mailing

[regression] CiviMail crashing on send instead of throwing exception when using Job.execute

In 5.27.0+, PR #17277 is causing CiviMail to crash in the most common configuration on any SMTP error.

For example, if a contact has an invalid email address, then it could produce an SMTP error - and cause a failure which prevents other messages from going out.

Replication

Create a contact with an email address that will generate an SMTP error. Screenshot below; you know best how to cause this problem in your own env :)
Send a transactional email to this user. You should get an error like the one in the screenshot.
View the Civi logs. You should have two new entries; Ignoring exception thrown by nullHandler and a backtrace.
Now, create a CiviMail to a group containing this contact.
If you send the mailing via Job.execute, you get the error but NOT the backtrace; any other recipients in the mailing will not get the mailing, it exits silently (there will be an error in the Scheduled Job log for send_mailing). The email is not placed on hold; CiviMail is now broken and won't send any new mailings, nor finish the existing mailing.
Now, send the same mailing via Job.send_mailing. The bad email address is handled correctly (placed on hold, mailing continues, backtrace appears in log).

Technical notes

When you run Job.execute, CRM_Core_JobManager specifies a custom fatal error handler.
CRM_Core_Error::nullHandler calls CRM_Core_Error::debug_log_message.
PR #17277 adds a call to the custom fatal error handler in CRM_Core_Error::debug_log_message.
Since CRM_Core_JobManager::CRM_Core_JobManager_scheduledJobFatalErrorHandler throws an exception, this causes the job to exit silently.

Correct backtrace

Jul 31 12:05:40  [error] Ignoring exception thrown by nullHandler: 10005, Failed to add recipient: onddddd@zabuntu.lan [SMTP: Invalid response code received from SMTP server while sending email.  This is often caused by a misconfiguration in Outbound Email settings. Please verify the settings at Administer CiviCRM >> Global Settings >> Outbound Email (SMTP). (code: 550, response: 5.1.1 <onddddd@zabuntu.lan>: Recipient address rejected: User unknown in local recipient table)]

Jul 31 12:05:40  [debug] $backTrace = #0 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/CRM/Core/Error.php(963): CRM_Core_Error::backtrace("backTrace", TRUE)
#1 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/vendor/pear/pear-core-minimal/src/PEAR.php(922): CRM_Core_Error::nullHandler(Object(PEAR_Error))
#2 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/vendor/pear/pear-core-minimal/src/PEAR.php(577): PEAR_Error->__construct("Failed to add recipient: onddddd@zabuntu.lan [SMTP: Invalid response code rec...", 10005, 16, (Array:2), NULL)
#3 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/vendor/pear/pear-core-minimal/src/PEAR.php(236): PEAR::_raiseError(NULL, "Failed to add recipient: onddddd@zabuntu.lan [SMTP: Invalid response code rec...", 10005)
#4 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/vendor/pear/mail/Mail/smtp.php(325): PEAR::__callStatic("raiseError", (Array:2))
#5 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/vendor/pear/mail/Mail/smtp.php(258): Mail_smtp->send_or_fail((Array:1), (Array:10), NULL)
#6 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/CRM/Utils/Mail/FilteredPearMailer.php(68): Mail_smtp->send((Array:1), (Array:10), NULL)
#7 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/CRM/Utils/Mail.php(303): CRM_Utils_Mail_FilteredPearMailer->send((Array:1), (Array:10), NULL)
#8 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/CRM/Activity/BAO/Activity.php(1538): CRM_Utils_Mail::send((Array:10))
#9 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/CRM/Activity/BAO/Activity.php(1236): CRM_Activity_BAO_Activity::sendMessage("\"a a\" <adminnnnn@zabuntu.lan>", "202", "205", "test2", "", "", "onddddd@zabuntu.lan", 630, (Array:0), "", "")
#10 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/CRM/Contact/Form/Task/EmailTrait.php(431): CRM_Activity_BAO_Activity::sendEmail((Array:1), "test2", "", "", "onddddd@zabuntu.lan", "202", "\"a a\" <adminnnnn@zabuntu.lan>", (Array:0), "", "", (Array:1), "", (Array:0), NULL, NULL)
#11 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/CRM/Contact/Form/Task/EmailTrait.php(351): CRM_Contact_Form_Task_Email->submit((Array:19))
#12 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/CRM/Core/Form.php(505): CRM_Contact_Form_Task_Email->postProcess()
#13 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/CRM/Core/QuickForm/Action/Upload.php(152): CRM_Core_Form->mainProcess()
#14 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/CRM/Core/QuickForm/Action/Upload.php(119): CRM_Core_QuickForm_Action_Upload->realPerform(Object(CRM_Contact_Form_Task_Email), "upload")
#15 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/packages/HTML/QuickForm/Controller.php(203): CRM_Core_QuickForm_Action_Upload->perform(Object(CRM_Contact_Form_Task_Email), "upload")
#16 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/packages/HTML/QuickForm/Page.php(103): HTML_QuickForm_Controller->handle(Object(CRM_Contact_Form_Task_Email), "upload")
#17 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/CRM/Core/Controller.php(347): HTML_QuickForm_Page->handle("upload")
#18 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/CRM/Utils/Wrapper.php(98): CRM_Core_Controller->run()
#19 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/CRM/Core/Invoke.php(285): CRM_Utils_Wrapper->run("CRM_Contact_Form_Task_Email", "Activities", (Array:1))
#20 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/CRM/Core/Invoke.php(68): CRM_Core_Invoke::runItem((Array:14))
#21 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/CRM/Core/Invoke.php(36): CRM_Core_Invoke::_invoke((Array:4))
#22 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/drupal/civicrm.module(456): CRM_Core_Invoke::invoke((Array:4))
#23 /home/jon/local/civicrm-buildkit/build/dmaster/web/includes/menu.inc(527): civicrm_invoke("activity", "email", "add")
#24 /home/jon/local/civicrm-buildkit/build/dmaster/web/index.php(21): menu_execute_active_handler()
#25 {main}

In 5.27.0+, [PR #17277](https://github.com/civicrm/civicrm-core/pull/17277) is causing CiviMail to crash in the most common configuration on any SMTP error.

For example, if a contact has an invalid email address, then it could produce an SMTP error - and cause a failure which prevents other messages from going out.

### Replication
* Create a contact with an email address that will generate an SMTP error.  Screenshot below; you know best how to cause this problem in your own env :)
![Selection_998](/uploads/7ee6dba4d820ce6bca972fdd71fba5dc/Selection_998.png)
* Send a transactional email to this user.  You should get an error like the one in the screenshot.
* View the Civi logs.  You should have two new entries; `Ignoring exception thrown by nullHandler` and a backtrace.
* Now, create a CiviMail to a group containing this contact.
* If you send the mailing via `Job.execute`, you get the error but NOT the backtrace; any other recipients in the mailing will not get the mailing, it exits silently (there will be an error in the Scheduled Job log for `send_mailing`).  The email is not placed on hold; CiviMail is now broken and won't send any new mailings, nor finish the existing mailing.
* Now, send the same mailing via `Job.send_mailing`.  The bad email address is handled correctly (placed on hold, mailing continues, backtrace appears in log).

### Technical notes

* When you run `Job.execute`, `CRM_Core_JobManager` specifies a [custom fatal error handler](https://github.com/civicrm/civicrm-core/blob/master/CRM/Core/JobManager.php#L44). 
* `CRM_Core_Error::nullHandler` calls `CRM_Core_Error::debug_log_message`.
* [PR #17277](https://github.com/civicrm/civicrm-core/pull/17277) adds a call to the custom fatal error handler in `CRM_Core_Error::debug_log_message`.
* Since `CRM_Core_JobManager::CRM_Core_JobManager_scheduledJobFatalErrorHandler` throws an exception, this causes the job to exit silently.

#### Correct backtrace
```
Jul 31 12:05:40  [error] Ignoring exception thrown by nullHandler: 10005, Failed to add recipient: onddddd@zabuntu.lan [SMTP: Invalid response code received from SMTP server while sending email.  This is often caused by a misconfiguration in Outbound Email settings. Please verify the settings at Administer CiviCRM >> Global Settings >> Outbound Email (SMTP). (code: 550, response: 5.1.1 <onddddd@zabuntu.lan>: Recipient address rejected: User unknown in local recipient table)]

Jul 31 12:05:40  [debug] $backTrace = #0 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/CRM/Core/Error.php(963): CRM_Core_Error::backtrace("backTrace", TRUE)
#1 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/vendor/pear/pear-core-minimal/src/PEAR.php(922): CRM_Core_Error::nullHandler(Object(PEAR_Error))
#2 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/vendor/pear/pear-core-minimal/src/PEAR.php(577): PEAR_Error->__construct("Failed to add recipient: onddddd@zabuntu.lan [SMTP: Invalid response code rec...", 10005, 16, (Array:2), NULL)
#3 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/vendor/pear/pear-core-minimal/src/PEAR.php(236): PEAR::_raiseError(NULL, "Failed to add recipient: onddddd@zabuntu.lan [SMTP: Invalid response code rec...", 10005)
#4 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/vendor/pear/mail/Mail/smtp.php(325): PEAR::__callStatic("raiseError", (Array:2))
#5 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/vendor/pear/mail/Mail/smtp.php(258): Mail_smtp->send_or_fail((Array:1), (Array:10), NULL)
#6 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/CRM/Utils/Mail/FilteredPearMailer.php(68): Mail_smtp->send((Array:1), (Array:10), NULL)
#7 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/CRM/Utils/Mail.php(303): CRM_Utils_Mail_FilteredPearMailer->send((Array:1), (Array:10), NULL)
#8 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/CRM/Activity/BAO/Activity.php(1538): CRM_Utils_Mail::send((Array:10))
#9 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/CRM/Activity/BAO/Activity.php(1236): CRM_Activity_BAO_Activity::sendMessage("\"a a\" <adminnnnn@zabuntu.lan>", "202", "205", "test2", "", "", "onddddd@zabuntu.lan", 630, (Array:0), "", "")
#10 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/CRM/Contact/Form/Task/EmailTrait.php(431): CRM_Activity_BAO_Activity::sendEmail((Array:1), "test2", "", "", "onddddd@zabuntu.lan", "202", "\"a a\" <adminnnnn@zabuntu.lan>", (Array:0), "", "", (Array:1), "", (Array:0), NULL, NULL)
#11 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/CRM/Contact/Form/Task/EmailTrait.php(351): CRM_Contact_Form_Task_Email->submit((Array:19))
#12 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/CRM/Core/Form.php(505): CRM_Contact_Form_Task_Email->postProcess()
#13 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/CRM/Core/QuickForm/Action/Upload.php(152): CRM_Core_Form->mainProcess()
#14 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/CRM/Core/QuickForm/Action/Upload.php(119): CRM_Core_QuickForm_Action_Upload->realPerform(Object(CRM_Contact_Form_Task_Email), "upload")
#15 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/packages/HTML/QuickForm/Controller.php(203): CRM_Core_QuickForm_Action_Upload->perform(Object(CRM_Contact_Form_Task_Email), "upload")
#16 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/packages/HTML/QuickForm/Page.php(103): HTML_QuickForm_Controller->handle(Object(CRM_Contact_Form_Task_Email), "upload")
#17 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/CRM/Core/Controller.php(347): HTML_QuickForm_Page->handle("upload")
#18 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/CRM/Utils/Wrapper.php(98): CRM_Core_Controller->run()
#19 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/CRM/Core/Invoke.php(285): CRM_Utils_Wrapper->run("CRM_Contact_Form_Task_Email", "Activities", (Array:1))
#20 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/CRM/Core/Invoke.php(68): CRM_Core_Invoke::runItem((Array:14))
#21 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/CRM/Core/Invoke.php(36): CRM_Core_Invoke::_invoke((Array:4))
#22 /home/jon/local/civicrm-buildkit/build/dmaster/web/sites/all/modules/civicrm/drupal/civicrm.module(456): CRM_Core_Invoke::invoke((Array:4))
#23 /home/jon/local/civicrm-buildkit/build/dmaster/web/includes/menu.inc(527): civicrm_invoke("activity", "email", "add")
#24 /home/jon/local/civicrm-buildkit/build/dmaster/web/index.php(21): menu_execute_active_handler()
#25 {main}
```

Edited Aug 04, 2020 by totten

To upload designs, you'll need to enable LFS. More information