unexpected reply "/" in initial handshake

pypolicyd-spf isn't a milter, it's a policy server, so you've got it set up all wrong. see the installed documentation, man policyd-spf, for information on how to correctly integrate it with Postfix.

pypolicyd-spf isn't a milter, it's a policy server, so you've got it set up all wrong. see the installed documentation, man policyd-spf, for information on how to correctly integrate it with Postfix.

This is the new configuration, using the official instructions:

Both master.cf and policyd-spf.conf are as above.

master.cf:

policy-spf unix - n n - 0 spawn
   user=nobody argv=/opt/python/bin/policyd-spf /etc/policyd-spf.conf

main.cf (relevant part of):

#spf_milter = unix:private/policy-spf
#smtpd_milters = ${spf_milter}, [...]

smtpd_relay_restrictions =
   permit_mynetworks,
   permit_sasl_authenticated,
   reject_unauth_destination

smtpd_recipient_restrictions =
   reject_non_fqdn_recipient,
   reject_unknown_recipient_domain,
   warn_if_reject check_policy_service unix:private/policy-spf

policy-spf_time_limit = 3600

policyd-spf.conf:

# Do not reject, just write the header.
#
defaultSeedOnly = 0
Lookup_Time = 20
Void_Limit = 2
Header_Type = AR
No_Mail = False
TempError_Defer = True
PermError_reject = False
HELO_reject = False
Mail_From_reject = False
skip_addresses = 127.0.0.0/8,::ffff:127.0.0.0/104,::1
Whitelist =
Domain_Whitelist =
Domain_Whitelist_PTR =
Reject_Not_Pass_Domains =
debugLevel = 5

The result is a 451 error:

> [...] postfix/port-25/smtpd[37217]: policy_client_register: name="unix:private/policy-spf" default_action="451 4.3.5 Server configuration problem" max_idle=300 max_ttl=1000 request_limit=0 retry_delay=1 timeout=100 try_limit=2

> [...] postfix/port-25/smtpd[37217]: auto_clnt_create: transport=unix endpoint=private/policy-spf

Despite the "debugLevel = 5", the logs are clear of relevant details.

PS. Most of the links on "http://www.openspf.org/Software" are broken, that is, the page is not up to date.

Since it doesn't show anything in the logs for the policy service, that means it never gets started. Here are a suggestion on the next step to troubleshoot:

Try running the policy server by hand:

/opt/python/bin/policyd-spf /etc/policyd-spf.conf

If you get no response to that hit enter and you should see a dunno reply. If you get that, then permissions and paths are correct and you can then use control-c to terminate it. If you get an error, then that's your problem and you'll need to trouble shoot that.

Let me know how that goes.

>/opt/python/bin/policyd-spf /etc/policyd-spf.conf
action=dunno

Yes, it works.

OK. Next thing I would try is:

Change your /etc/policyd-spf.conf to have:

defaultSeedOnly = 1

That will make it so it only logs results and never rejects any mail.

Then remove warn_if_reject from smtpd_recipient_restrictions (it won't be needed any more). I'm not sure of the syntax of that is correct and since the problem is in the postfix integration, not in the policy server, the less complicated we make that, the easier for trouble shooting.

The reload postfix and see what happens. Check the logs right after the reload for any unused parameter warnings.

looking better...

 postfix/port-25/smtpd[47033]: private/policy-spf: wanted attribute: action
 postfix/port-25/smtpd[47033]: private/policy-spf: wanted attribute: (list terminator)
 postfix/port-25/smtpd[47033]: check_table_result: unix:private/policy-spf prepend policy query
 postfix/port-25/smtpd[47033]: warning: access table unix:private/policy-spf entry "policy query" requires header: text

Do you have the python authres module installed? You need that for header type AR. If not, I think installing that will solve it.

I have the whole python bloatware installed, including py3dns, PyYAML, authres and pyspf, summing to 110 MB of stuff I would rather *not* have on a production server. All this, just to get an up-to-date "Authentication-Results:" header via pypolicyd-spf and opendkim.

>ls -l /opt/python/lib/python3.4/site-packages/authres
total 192
-rw-rw-r-- 1 root wheel 8678 Mar 10 03:19 __init__.py
-rw-rw-r-- 1 root wheel 1116 Mar 10 02:57 __main__.py
drwxr-xr-x 11 root wheel 374 Aug 3 00:00 __pycache__
-rw-rw-r-- 1 root wheel 32178 Mar 10 02:57 core.py
-rw-rw-r-- 1 root wheel 1961 Mar 10 02:58 dkim_adsp.py
-rw-rw-r-- 1 root wheel 2896 Mar 10 02:57 dkim_b.py
-rw-rw-r-- 1 root wheel 2001 Mar 10 02:58 dmarc.py
-rw-rw-r-- 1 root wheel 1999 Mar 10 03:34 rrvs.py
-rw-rw-r-- 1 root wheel 3742 Mar 10 02:57 smime.py
-rw-rw-r-- 1 root wheel 23498 Mar 10 03:35 tests
-rw-rw-r-- 1 root wheel 2307 Mar 10 02:57 vbr.py

I also have

OK. You didn't say what OS you're using. I'm guessing one of the BSDs and I'm not that familiar with Python layouts on those systems. I am wondering (and I freely admit it's a guess) if it's just not seeing the module then.

If you open a python3 interpreter (python3 in your shell) then then try:

import sys
print(sys.path)

Is /opt/python/lib/python3.4/site-packages/ included in the results?

>Is /opt/python/lib/python3.4/site-packages/ included in the results?

Yes.

OK. Let's try and get some more information about what's going on in the policy server.

Go back and start the policy server by hand (where you got the dunno) and do that again. After you hit enter and it replies dunno (to verify it's running), paste this (including a blank line at the end):

request=smtpd_access_policy
client_address=72.81.252.18
helo_name=mailout02.controlledmail.com
<email address hidden>
<email address hidden>

Let me know both what's the reply in the terminal and what's in your mail log.

It says:

action=prepend

The log says:

Aug 12 18:34:24 localhost postfix/port-25/smtpd[52685]: policy_client_register: name="unix:private/policy-spf" default_action="451 4.3.5 Server configuration problem" max_idle=300 max_ttl=1000 request_limit=0 retry_delay=1 timeout=100 try_limit=2

Aug 12 18:34:24 localhost postfix/port-25/smtpd[52685]: auto_clnt_create: transport=unix endpoint=private/policy-spf

The log is also saying the following when sending mail from own addresses to own addresses (port 465):

Aug 12 18:46:01 localhost postfix/port-465/smtpd[53056]: private/policy-spf: wanted attribute: action
Aug 12 18:46:01 localhost postfix/port-465/smtpd[53056]: private/policy-spf: wanted attribute: (list terminator)
Aug 12 18:46:01 localhost postfix/port-465/smtpd[53056]: check_table_result: unix:private/policy-spf prepend policy query
Aug 12 18:46:01 localhost postfix/port-465/smtpd[53056]: warning: access table unix:private/policy-spf entry "policy query" requires header: text

Incidentally, pypolicyd-spf should *not* run for port 465.

The way you avoid port 465 is to do per service recipient restrictions in master.cf instead of globally in main.cf.

There should be significantly more information in the mail log. For some reason, I don't think your python syslog module is working correctly, but I've no idea how to troubleshoot that.

It should have the content of the AR header after prepend, so that's definitely a problem. Comment out the Header_Type entry in the config file and then try the copy/paste again from the command line. It should give you a traditional Received SPF header field. If that works, then we've narrowed it down a bit.

Gotcha!

action=prepend Received-SPF: Pass (sender SPF authorized) identity=mailfrom; client-ip=72.81.252.18; helo=mailout02.controlledmail.com; <email address hidden>; <email address hidden>

This is the resulting header in an administrative message from google:

Received-Spf: Temperror (SPF Temporary Error: DNS No working name servers discovered) identity=mailfrom; client-ip=209.85.220.74; helo=mail-pa0-f74.google.com; <email address hidden>; <email address hidden>

I have unbound on 127.0.0.1:53 and "nameserver 127.0.0.1" on /etc/resolv.conf.

What version of py3dns do you have installed? I would expect the python DNS module to either work always or never, so I suspect the temperror is something external to the python stack.

Also, I can replicate the bare prepend problem here, so that's a bug related to this specific configuration.

If the reason you want the SPF result header is to feed it into opendmarc for DMARC processing, opendmarc will process SPF-Received as well as AR, so you can leave it for now.

Figured it out.

Your config is missing the Authserv_Id parameter. This is mandatory for AR header fields. My bad for having no error message for this. See man 5 policyd-spf.conf for info on the format. Also RFC 7001.

I am happy to confirm that the header appears in the mail.
However, failure with the DNS makes it useless.
I have pydns 3.1.0, and its tests are OK.
The above manual test on pypolicyd-spf shows that the DNS is working.
However, live headers fail.

Authentication-Results: mx.example.com; spf=temperror (SPF Temporary Error: DNS No working name servers discovered) smtp.mailfrom=spammer.com (client-ip=84.238.198.166; helo=vmi45291.contabo.host; <email address hidden>; <email address hidden>)

This is the log:

... postfix/port-25/smtpd[16478]:
   policy_client_register:
   name="unix:private/policy-spf" default_action="451 4.3.5 Server configuration problem" <--------------------
      max_idle=300 max_ttl=1000 request_limit=0 retry_delay=1 timeout=100 try_limit=2
... postfix/port-25/smtpd[16478]: auto_clnt_create: transport=unix endpoint=private/policy-spf
... postfix/port-25/smtpd[16478]: auto_clnt_open: connected to private/policy-spf
... postfix/port-25/smtpd[16478]: private/policy-spf: wanted attribute: action
... postfix/port-25/smtpd[16478]: private/policy-spf: wanted attribute: action
... postfix/port-25/smtpd[16478]: input attribute value:
   prepend Authentication-Results: mx.example.com; spf=temperror
      (SPF Temporary Error: DNS No working name servers discovered) smtp.mailfrom=... <------------------------
      (client-ip=...; helo=...; envelope-from=...; <email address hidden>)
... postfix/port-25/smtpd[16478]: private/policy-spf: wanted attribute: (list terminator)
... postfix/port-25/smtpd[16478]: check_table_result:
   unix:private/policy-spf prepend Authentication-Results: mx.example.com;
   spf=temperror (SPF Temporary Error: DNS No working name servers discovered) <-------------------------------
   smtp.mailfrom=... (client-ip=...; helo=...; envelope-from=...; <email address hidden>) policy query

The DNS is a well configured, reliable, and performant unbound on 127.0.0.1:53.
Many other local clients use it without any problem.
I suspect the temperror is something either in py3dns or its call from pypolicyd-spf.

What pyspf version do you have?

It'll probably be tomorrow before I can work on this much, but I will keep helping you work through it.

pyspf is 2.0.12t

What are the permissions on /etc/resolv.conf? Can user nobody open the file for reading?

You might also try running this script:

#! /usr/bin/python3
resolv_path="/etc/resolv.conf"
lines = []
with open(resolv_path, 'r') as stream:
    for line in stream:
        lines.append(line)
        print(line)
print(lines)
for line in lines:
    line = line.strip()
    if not line or line[0]==';' or line[0]=='#':
        continue
    fields=line.split()
    if len(fields) < 2:
        continue
    if fields[0]=='domain' and len(fields) > 1:
        defaults['domain']=fields[1]
    if fields[0]=='search':
        pass
    if fields[0]=='options':
        pass
    if fields[0]=='sortlist':
        pass
    if fields[0]=='nameserver':
        print(fields[1])

This is essentially the py3dns DNS nameserver discovery code extracted into a script. It should echo your /etc/resolv.conf line by line, then show its contents in a python list, and then finally print out the IP address of the discovered name server like this (run on my Debian box):

# Dynamic resolv.conf(5) file for glibc resolver(3) generated by resolvconf(8)

# DO NOT EDIT THIS FILE BY HAND -- YOUR CHANGES WILL BE OVERWRITTEN

nameserver 127.0.0.1

['# Dynamic resolv.conf(5) file for glibc resolver(3) generated by resolvconf(8)\n', '# DO NOT EDIT THIS FILE BY HAND -- YOUR CHANGES WILL BE OVERWRITTEN\n', 'nameserver 127.0.0.1\n']
127.0.0.1

>ls -l /etc/resolv.conf
-rw-r--r-- 1 root daemon 21 Aug 8 23:57 /etc/resolv.conf
>./py3dns-test.py
nameserver 127.0.0.1

['nameserver 127.0.0.1\n']
127.0.0.1
>

If you were on Linux, at this point I'd be asking you if you were running SELinux or apparmor since it seems like there's some kind of context dependent access restriction that's making it impossible for the python DNS module to read /etc/resolv.conf. There isn't some BSD equivalent access restriction technology you're using is there?

It seems like the code does what it's supposed to, but can't get the information in some cases.

> If you were on Linux, at this point I'd be asking you if you were running SELinux or apparmor

No no, this is a BSD system.

> since it seems like there's some kind of context dependent access restriction that's making
> it impossible for the python DNS module to read /etc/resolv.conf.

You lost me here. The above py3dns test is reading /etc/resolv.conf after all.

> There isn't some BSD equivalent access restriction technology you're using is there?
>
> It seems like the code does what it's supposed to, but can't get the information in some cases.

The same DNS is filtering away a short list of addresses that are known to inject advertisements
in web pages. However, I can ping the IP addresses of our tests above, so I must be something else.

Since py3dns is working, then the problem is uphill.

Anyway, pypolicy-spf is working per-se, and I do not want to take your time for side-bugs.

Thanks a lot, and happy holiday!