[SOLVED] Cron/Postfix/backup script email mystery

wagonlips · 03-17-2013, 10:37 AM

Since about mid February (a month ago) I've stopped receiving the email for one of my backup scripts that has been running happily every day for years. The script still runs (files get backed up as planned), and I can (I'm pretty sure) see in syslog that the email was sent, but it never arrives in my inbox. When it works, the email would contain the list of rsync backed-up files.

My first thought was the relay server. I had never configured postfix beyond simply having apt-get install it, and I noticed by reading syslog that it was using Rackspace's mx server to forward the mail. Thinking maybe Rackspace had updated their spam rules and there was something about this particular mail that was now tripping a flag there, I configured postfix to use a mail server at one of my domains (dreamhost).

Still, the same behavior persists.

To troubleshoot, I wrote another script that simply echoes the time and date

Code:

echo "this is `date +%Y-%m-%d-%M` for real"

and told cron to send it every minute. And this gets through just fine, unless I redirect the string in the test script to a file

Code:

echo "this is `date +%Y-%m-%d-%M` for real" >> temp.log

then it no longer reaches my inbox, but writes to the file.

Here's some output from syslog that shows both the backup-script.sh and the test-script.sh firing at the same time. The test-script (without writing to file) gets through, the backup-script does not.

Code:

Mar 17 07:28:01 myserver CRON[11623]: (root) CMD (~/bin/backup-script.sh)
Mar 17 07:28:01 myserver CRON[11624]: (root) CMD (~/bin/test-script.sh)
Mar 17 07:28:01 myserver postfix/pickup[9602]: 197C01425E6: uid=1000 from=<root>
Mar 17 07:28:01 myserver postfix/cleanup[10812]: 197C01425E6: message-id=<20130317142801.197C01425E6@mydomain.com>
Mar 17 07:28:01 myserver postfix/qmgr[8704]: 197C01425E6: from=<root@mydomain.com>, size=550, nrcpt=1 (queue active)
Mar 17 07:28:01 myserver postfix/cleanup[10446]: 1FD281425E4: message-id=<20130317142801.197C01425E6@mydomain.com>
Mar 17 07:28:01 myserver postfix/qmgr[8704]: 1FD281425E4: from=<root@mydomain.com>, size=686, nrcpt=1 (queue active)
Mar 17 07:28:01 myserver postfix/local[10448]: 197C01425E6: to=<myemail@mydomain.com>, orig_to=<root>, relay=local, delay=0.07, delays=0.04/0/0/0.02, dsn=2.0.0, status=sent (forwarded as 1FD281425E4)
Mar 17 07:28:01 myserver postfix/qmgr[8704]: 197C01425E6: removed
Mar 17 07:28:02 myserver postfix/smtp[11401]: 1FD281425E4: to=<myemail@gmail.com>, orig_to=<root>, relay=mail.mydomain.com[xxx.xxx.xxx.xxx]:587, delay=1.1, delays=0.02/0/0.21/0.83, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as D990810AFAB)
Mar 17 07:28:02 myserver postfix/qmgr[8704]: 1FD281425E4: removed
Mar 17 07:28:26 myserver postfix/pickup[9602]: DD66F1425E6: uid=1000 from=<root>
Mar 17 07:28:26 myserver postfix/cleanup[10812]: DD66F1425E6: message-id=<20130317142826.DD66F1425E6@mydomain.com>
Mar 17 07:28:26 myserver postfix/qmgr[8704]: DD66F1425E6: from=<root@mydomain.com>, size=664055, nrcpt=1 (queue active)
Mar 17 07:28:26 myserver postfix/cleanup[10446]: E94DE142616: message-id=<20130317142826.DD66F1425E6@mydomain.com>
Mar 17 07:28:26 myserver postfix/qmgr[8704]: E94DE142616: from=<root@mydomain.com>, size=664191, nrcpt=1 (queue active)
Mar 17 07:28:26 myserver postfix/local[10448]: DD66F1425E6: to=<myemail@mydomain.com>, orig_to=<root>, relay=local, delay=0.14, delays=0.1/0/0/0.05, dsn=2.0.0, status=sent (forwarded as E94DE142616)
Mar 17 07:28:26 myserver postfix/qmgr[8704]: DD66F1425E6: removed
Mar 17 07:28:34 myserver postfix/smtp[10449]: E94DE142616: to=<myemail@gmail.com>, orig_to=<root>, relay=mail.mydomain.com[xxx.xxx.xxx.xxx]:587, delay=7.7, delays=0.04/0/0.19/7.4, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 09A0251C05F)
Mar 17 07:28:34 myserver postfix/qmgr[8704]: E94DE142616: removed

This server is running Linux Mint 13 Maya.

Thanks, any help will be appreciated!

kbp · 03-18-2013, 07:04 PM

Quote:

... status=sent (250 2.0.0 Ok ...

Going by the above the mail seems to be getting to mail.mydomain.com, have you checked the logs there?

wagonlips · 03-21-2013, 10:28 PM

Thanks! This is a very sensible suggestion that I'm embarrassed not to have thought of on my own. Turns out, I have not been making it easy on myself: I've managed to configure my email setup to run everything through at least two different web hosts. The first (Dreamhost) was really helpful and copied the relevant logs to me that showed my emails leaving their servers for the next host (Laughing Squid). The Squid was less helpful, kind of rude even, but it turns out they rely on Rackspace for their hosting and so can't even look at the logs themselves. For a sysadmin to not have root on the servers they're managing... I'd probably be a bit punchy, too.

Anywayz... the emails resumed for no obvious reason the very night I submitted the ticket at Squid. Coincidence? Maybe. They certainly gave me no indication that they had done anything helpful for me, so I'm still not sure what was going on. But I'm good for now.

Thanks again!

wagonlips · 03-23-2013, 11:20 AM

And then they stopped again. It seems that Rackspace is the black-hole here. Though most of my server's messages got through, I still don't know what the problem was with that one. So I've fixed (so far!) the problem by routing around Rackspace. By configuring postfix on my server to use a relayhost the sysadmins of which I can talk to, I now, once again, have my messages coming through.