This site runs Drupal's cron every 15 minutes from a crontab on the server, with the output appended to a log file in my home directory. For about twelve days in September, almost every one of those runs tried to send me an email, failed, and wrote two lines about it to that log. Nobody read the log. The emails were security update notifications.
What the log said
The failure was always the same pair of lines:
sh: 1: /usr/sbin/sendmail: not found[error] Message: Unable to send email. Contact the site administrator if the problem persists.
Drupal's default mail backend uses PHP's mail(), and PHP's mail() hands the message to a sendmail binary. This server doesn't have one. It runs the website and its database; mail for the domain is handled by a separate machine, and nobody ever installed a local MTA or even a sendmail-compatible stub. So every attempt to send mail from Drupal ended at a shell that couldn't find the program.
The update module is configured to email me when a security update is available for anything installed on the site, and those notifications are what cron kept trying to send.
How long it went on
Dating it took some work. The cron log has no timestamps, and Drupal's own log, the watchdog table, only keeps a fixed number of recent rows. By the time I looked into it, the oldest mail errors had already rotated out, which is why the watchdog showed 299 of them when the real number was much higher.
The cron log does contain one thing with a known date: every time Scheduler publishes an article, it logs "scheduled publishing of" and the title. Each article's publish time is in the database, so those lines work as timestamps.
Between the article that went out on the evening of September 18 and the one that went out the next evening, there are exactly 96 failures: one per 15-minute run, every run, for a full day. Before September 18, there are 126 more, which puts the first one at around midday on September 17. The last one comes after an article published on the evening of September 29, when I fixed it. In total, the log contains 1,189 "sendmail: not found" lines.
I haven't pinned down what changed on September 17. The update module only sends a notification when something crosses the configured threshold, here "security", so one plausible explanation is that a security release appeared for something on the site that day. I can't tell from what's left of the logs.
Why nobody noticed
Everything else worked. Pages loaded, articles published on schedule, the sitemap regenerated. A cron run that fails to send mail still finishes its other tasks and exits normally, so nothing about the site looked wrong. The only symptom was the absence of emails I wasn't expecting, and you don't notice an email you didn't know was supposed to arrive.
That's the uncomfortable part: the failure was in the channel meant to tell me about failures. For twelve days the site knew it needed a security update and had no way to say so.
The fix
Rather than install a local MTA on the web server, I pointed Drupal at the mail server it already had. Commit 7a22ae6 switches the mail backend to the Symfony mailer plugin that ships with Drupal core, which its own docblock describes as experimental, and configures it to submit over SMTP to mail.linkhub.dk on port 587 as noreply@linkhub.dk.
That mailbox didn't exist yet. The mail server's accounts live in a database that uses PostfixAdmin's schema, but there's no PostfixAdmin web interface installed on it, so I created the mailbox by inserting the rows by hand, with the password hash generated by doveadm pw -s SHA512-CRYPT.
The SMTP password isn't in the exported config. Production sets it in an untracked settings.local.php, which settings.php now includes. Under ddev, the same override points mail at Mailpit on localhost:1025 instead, so a development copy of the site can never send real mail through the production relay.
The first test send then failed in a completely different way, at the mail server rather than the web server. That one deserves its own write-up. Once it was sorted out, mail went through, and security notifications have been arriving since.
The lesson I'm taking
Logging an error and getting an error noticed are different things. This one was logged faithfully, every 15 minutes, to a file I never opened. If a scheduled job's output matters, it needs to reach somewhere a person will see it: email, which is exactly what was broken, or a monitoring check, or at least a periodic look at the log. Until then, "it's in the log" mostly means "it happened and nobody noticed".
Leave a comment
Comments are reviewed before they appear.