Qmail & SPF – deciphering the log files

Can someone help me decipher whats going on in these log files? I've added my own comments there, but as I'm not experienced mail admin I could do with an experienced eye 😉

The bit which gets me is that the SPF section causes the message rejection, even though the domain the mail is being sent from is a very, very well known company. Is it simply that they don't have SPF headers set on their domain?

If so.. what are the safest settings I could use on my server to allow legit email but block spam?

I've got domainkeys, SPF and spamhaus blacklists running, but SPF seems to be causing some problems.

Thanks a lot for any help 🙂

Remote mailserver connects and begins negotiation

Oct 20 18:30:59 msvsc01-g09np postfix/smtpd[29264]: connect from unknown[192.208.34.37]
Oct 20 17:30:59 msvsc01-g09np postfix/smtpd[29264]: NOQUEUE: client=unknown[192.208.34.37]
Oct 20 17:30:59 msvsc01-g09np postfix/smtpd[29269]: BD5B9292AF1: client=unknown[192.208.34.37]
Oct 20 18:30:59 msvsc01-g09np before-queue[29266]: check handlers for addr: xxxxxxxxxxxxxxxx.com 
Oct 20 18:30:59 msvsc01-g09np before-queue[29266]: check handlers for addr: yyyyyyyyyyyyyyyy.com 
Oct 20 18:30:59 msvsc01-g09np before-queue[29266]: check handlers for addr: zzzzzzzzzzzzzzzz.com 
Oct 20 18:30:59 msvsc01-g09np before-queue[29266]: Processing handlers... 
Oct 20 18:30:59 msvsc01-g09np before-remote[29268]: check handlers for addr: xxxxxxxxxxxxxxxx.com 
Oct 20 18:30:59 msvsc01-g09np before-remote[29268]: check handlers for addr: yyyyyyyyyyyyyyyy.com 
Oct 20 18:30:59 msvsc01-g09np before-remote[29268]: check handlers for addr: zzzzzzzzzzzzzzzz.com 
Oct 20 18:30:59 msvsc01-g09np before-remote[29268]: Processing handlers... 

Qmail handling

Oct 20 18:31:00 msvsc01-g09np before-queue[29266]: hook_dir = '/usr/local/psa/handlers/before-queue'
Oct 20 18:31:00 msvsc01-g09np before-queue[29266]: recipient[3] = yyyyyyyyyyyyyyyy.com 
Oct 20 18:31:00 msvsc01-g09np before-queue[29266]: handlers dir = '/usr/local/psa/handlers/before-queue/recipient/yyyyyyyyyyyyyyyy.com '
Oct 20 18:31:00 msvsc01-g09np before-queue[29266]: call_handlers: call executable = '/usr/local/psa/handlers/info/20-drweb-MZX9NW/executable'
Oct 20 18:31:00 msvsc01-g09np before-queue[29266]: handlers_stderr: PASS
Oct 20 18:31:00 msvsc01-g09np before-queue[29266]: call_handlers: PASS during call '/usr/local/psa/handlers/info/20-drweb-MZX9NW/executable' handler
Oct 20 18:31:00 msvsc01-g09np before-queue[29266]: recipient[4] = 'zzzzzzzzzzzzzzzz.com'
Oct 20 18:31:00 msvsc01-g09np before-queue[29266]: handlers dir = '/usr/local/psa/handlers/before-queue/recipient/zzzzzzzzzzzzzzzz.com'
Oct 20 18:31:00 msvsc01-g09np before-queue[29266]: call_handlers: call executable = '/usr/local/psa/handlers/info/20-drweb-FoRKet/executable'
Oct 20 18:31:00 msvsc01-g09np before-queue[29266]: handlers_stderr: PASS
Oct 20 18:31:00 msvsc01-g09np before-queue[29266]: call_handlers: PASS during call '/usr/local/psa/handlers/info/20-drweb-FoRKet/executable' handler
Oct 20 18:31:00 msvsc01-g09np before-queue[29266]: call_handlers: call executable = '/usr/local/psa/handlers/info/10-spf-d7R8jL/executable'

DrWeb Virus Check

Oct 20 18:31:00 msvsc01-g09np qmail-queue[29271]: scan: the message(drweb.tmp.j0zApu) sent by xxxxxxxxxxxxxxxx.com to rcpts is passed

SPF Checking

Oct 20 18:31:00 msvsc01-g09np spf filter[29273]: Starting spf filter... 
Oct 20 18:31:00 msvsc01-g09np spf filter[29273]: Error code: (2) Could not find a valid SPF record 
Oct 20 18:31:00 msvsc01-g09np spf filter[29273]: Failed to query MAIL-FROM: No DNS data for 'cadbury.com'. 
Oct 20 18:31:00 msvsc01-g09np spf filter[29273]: SPF result: none 
Oct 20 18:31:00 msvsc01-g09np spf filter[29273]: SPF status: REJECT

SPF Checked and Failed?! = Message rejected. 504 error returned.

Oct 20 18:31:00 msvsc01-g09np before-queue[29266]: handlers_stderr: REJECT
Oct 20 18:31:00 msvsc01-g09np before-queue[29266]: call_handlers: REJECT during call '/usr/local/psa/handlers/info/10-spf-d7R8jL/executable' handler
Oct 20 18:31:00 msvsc01-g09np before-queue[29266]: call_handlers: stop call handlers from dir '/usr/local/psa/handlers/before-queue/global'
Oct 20 17:31:00 msvsc01-g09np postfix/smtpd[29264]: disconnect from unknown[192.208.34.37]
Oct 20 18:31:00 msvsc01-g09np before-remote[29268]: Lost connection
Oct 20 18:31:00 msvsc01-g09np before-remote[29268]: Some error occured
Oct 20 17:31:00 msvsc01-g09np postfix/smtpd[29269]: lost connection after DATA from unknown[127.0.0.1]
Oct 20 17:31:00 msvsc01-g09np postfix/smtpd[29269]: disconnect from unknown[127.0.0.1]