mails are sent even if failure to log throws exception

[TimWolla]

Description

Our software employs a background queue system with automated retries in case of task failures (an Exception being thrown within the task callable). It implements an at-least-once queuing logic. The software also converts all errors/warnings/notices into exceptions using a custom error handler.

One of the background tasks in the software is sending emails with support for the mail() function as the email transport. We throw an exception whenever mail() returns false, and also whenever a warning is emitted using the global error handler:

https://github.com/WoltLab/WCF/blob/master/wcfsetup/install/files/lib/system/email/transport/PhpEmailTransport.class.php

We noticed that a broken mail.log configuration is unsafe with this setup. Emails might be multiple times, because our software detects an error during the sending of an email.

Consider the set-up:

1. The admin configured mail.log = /log/sendmail.php.log in php.ini.
2. This file is not writable for the PHP process (e.g. owned by root; or on a read-only filesystem):

   -r--------  1 root     root     550 Jan  3 14:12 sendmail.php.log
   

Now when attempting to send an email using mail() the following appears to happen:

1. PHP opens the logfile which fails due to EACCES being returned:

   [pid 112194] openat(AT_FDCWD, "/log/sendmail.php.log", O_WRONLY|O_CREAT|O_APPEND, 0666) = -1 EACCES (Permission denied)
   

2. PHP emits a Warning:

   Warning: mail(/log/sendmail.php.log): Failed to open stream: Permission denied in /var/www/html/test.php on line 11

3. PHP proceeds to execute the sendmail binary, sending the email.
4. mail() returns true.
5. The warning is converted to an exception by our error handler.
6. The exception transfers control flow into the nearest catch() block.

Now our background queuing logic believes the job failed, because an exception was thrown, causing it to re-queue the job. However the email was sent (in step (3)) and thus will be delivered a second time during the next attempt.

The task itself did not have a chance to detect this situation, because the return value from mail() is unavailable (step 4) when an exception is thrown. It would need to prevent the global error handler from converting the warning into an Exception. However this might hide other notices/warnings/errors and thus is undesirable.

In the ideal case, the execution of the native mail() function would stop after (2) when the configured error handler throws an exception, actually preventing the sendmail binary from being invoked. However I'm not sure whether this is feasible with the current architecture of PHP's internals.

I'm happy to provide additional information on request. A simple reproducer script is the following:

<?php
function exception_error_handler($severity, $message, $file, $line) {
    if (!(error_reporting() & $severity)) {
        return;
    }
    throw new ErrorException($message, 0, $severity, $file, $line);
}
set_error_handler("exception_error_handler");

try {
	$return = mail('recipient@example.com', 'Subject', 'Body', []);
	var_dump($return);
} catch (\Exception $e) {
	echo "Exception:<pre>";
	echo $e;
}

PHP Version

8.0.13

Operating System

Docker on Ubuntu 20.04

[damianwadley]

Isn't the problem here that PHP is issuing a non-fatal warning and your error handler is interpreting that as a fatal error?

[TimWolla]

It is correct that this issue would not happen with the error handler converting the warning into an Exception. However an error handler like that certainly is nothing out of the usual. In fact such an error handler is an example within the official PHP manual (that's the source of the error handler in my example script). Large Frameworks such as Laravel also use an error handler similar to our error handler. In many cases it is helpful to treat PHP warnings and notices as exceptions, because they indicate some programming error more often than not.

However this issue would not happen if this error handler would actually throw the exception and thus abort execution at the place where the warning is emitted, instead of proceeding with the execution of the native function and only then throwing the exception. This is a behavior that differs from userland functions [1] and certainly is unexpected. There's also no easy way to work around this issue, except switching out the error handler before calling mail().

[1] I understand why that might be: The error handler itself might call mail() while one call to mail() already is in progress.

[cmb69]

It is debatable whether this qualifies as bug, but the fix would be trivial.