Skip to content

mails are sent even if failure to log throws exception #7875

Closed

Description

@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

Activity

  1. damianwadley commented on Jan 3, 2022

    @damianwadley
    Member

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

  2. TimWolla commented on Jan 3, 2022

    @TimWolla
    MemberAuthor

    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.

  3. added a commit that references this issue on Jan 3, 2022
    8c8e7a8
  4. cmb69 commented on Jan 3, 2022

    @cmb69
    Member

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

  5. changed the title [-]mail() logging might be unsafe in combination with an error handler converting errors into exceptions[/-] [+]mails are sent even if failure to log throws exception[/+] on Jan 3, 2022
  6. added 2 commits that reference this issue on Jan 17, 2022
    79bf39e
    ca6613a
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions