Bug#947355: postfix-policyd-spf-python: command /usr/bin/policyd-spf exit status 120

Jonathan Marquardt

unread,

Dec 25, 2019, 7:40:02 AM12/25/19

to

Package: postfix-policyd-spf-python
Version: 2.9.1-0+deb10u1
Severity: important

Dear Maintainer,

I am using Postfix with policyd-spf. It always worked until I did a
fresh install of Buster, taking configuration files from Stretch, where
it all worked without problems.

Now however, it fails and Postfix returns a Temperror when receiving
email.

Excerpt from /var/log/mail.log:

Dec 22 00:27:03 efatsum postfix/smtpd[17265]: connect from mailgate1.deutschebahn.com[46.18.62.69]
Dec 22 00:27:03 efatsum postfix/smtpd[17265]: Anonymous TLS connection established from mailgate1.deutschebahn.com[46.18.62.69]: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA 384 (256/256 bits)
Dec 22 00:28:44 efatsum postfix/smtpd[17265]: warning: problem talking to server private/policy-spf: Connection timed out
Dec 22 00:30:25 efatsum postfix/smtpd[17265]: warning: problem talking to server private/policy-spf: Connection timed out
Dec 22 00:30:25 efatsum postfix/smtpd[17265]: NOQUEUE: reject: RCPT from mailgate1.deutschebahn.com[46.18.62.69]: 451 4.3.5 <ma...@parckwart.de>: Recipient address rejected: Server configuration problem; from=<prvs=251f9e8d8=buchungsbe...@bahn.de>to=<ma...@parckwart.de> proto=ESMTP helo=<mailgate1.deutschebahn.com>
Dec 22 00:30:30 efatsum postfix/smtpd[17265]: disconnect from mailgate1.deutschebahn.com[46.18.62.69] ehlo=2 starttls=1 mail=1 rcpt=0/1 rset=1 quit=1 commands=6/7
Dec 22 00:31:25 efatsum policyd-spf[17268]: prepend Received-SPF:Temperror (mailfrom) identity=mailfrom; client-ip=46.18.62.69;helo=mailgate1.deutschebahn.com; envelope-from=prvs=251f9e8d8=buchungsbe...@bahn.de; receiver=<UNKNOWN>
Dec 22 00:31:25 efatsum policyd-spf[17268]: Traceback (most recent calllast):
Dec 22 00:31:25 efatsum policyd-spf[17268]: File"/usr/bin/policyd-spf", line 11, in <module>#012load_entry_point('spf-engine==2.9.1', 'console_scripts', 'policyd-spf')()
Dec 22 00:31:25 efatsum policyd-spf[17268]: File"/usr/lib/python3/dist-packages/spf_engine/policyd_spf.py", line 169, inmain#012 sys.stdout.flush()
Dec 22 00:31:25 efatsum policyd-spf[17268]: BrokenPipeError: [Errno 32]Broken pipe
Dec 22 00:31:25 efatsum postfix/spawn[17267]: warning: command/usr/bin/policyd-spf exit status 120

-- System Information:
Debian Release: 10.2
APT prefers stable-updates
APT policy: (500, 'stable-updates'), (500, 'stable')
Architecture: amd64 (x86_64)
Foreign Architectures: i386

Kernel: Linux 4.19.0-6-amd64 (SMP w/8 CPU cores)
Locale: LANG=en_US.UTF-8, LC_CTYPE=en_US.UTF-8 (charmap=UTF-8), LANGUAGE=en_US:en (charmap=UTF-8)
Shell: /bin/sh linked to /usr/bin/dash
Init: systemd (via /run/systemd/system)
LSM: AppArmor: enabled

Versions of packages postfix-policyd-spf-python depends on:
ii adduser 3.118
pn postfix <none>
ii python3 3.7.3-1
pn python3-authres <none>
ii python3-pkg-resources 40.8.0-1
pn python3-spf <none>
pn python3-spf-engine <none>

postfix-policyd-spf-python recommends no packages.

postfix-policyd-spf-python suggests no packages.

Scott Kitterman

unread,

Dec 25, 2019, 8:30:03 AM12/25/19

to

Please attach the output of postconf -n and your config file for the policy server to the bug.

Also please change debugLevel in the policy server to 4:

debugLevel = 4

And then send the extended debugging of a failure in once you get it (from your mail.log). It appears it's working some of the time, so we need to capture the details of a failure to troubleshoot.

Thanks,

Scott K

Jonathan Marquardt

unread,

Dec 25, 2019, 6:10:05 PM12/25/19

to

Dec 25 21:52:17 efatsum policyd-spf[14396]: spfcheck: pyspf result: "['Temperror', 'SPF Temporary Error: DNS: TCP Fallback error: [Errno 110] Connection timed out', 'mailfrom']"
Dec 25 21:52:17 efatsum policyd-spf[14396]: Temperror; identity=mailfrom; client-ip=192.243.247.79; helo=r79.mobile.mcdonalds.de; envelope-from=bou...@mobile.mcdonalds.de; receiver=<UNKNOWN>
Dec 25 21:52:17 efatsum policyd-spf[14396]: not peruser
Dec 25 21:52:17 efatsum policyd-spf[14396]: Action: prepend: Text: Received-SPF: Temperror (mailfrom) identity=mailfrom; client-ip=192.243.247.79; helo=r79.mobile.mcdonalds.de; envelope-from=bou...@mobile.mcdonalds.de; receiver=<UNKNOWN> Reject action: 550 5.7.23
Dec 25 21:52:17 efatsum policyd-spf[14396]: prepend Received-SPF: Temperror (mailfrom) identity=mailfrom; client-ip=192.243.247.79; helo=r79.mobile.mcdonalds.de; envelope-from=bou...@mobile.mcdonalds.de; receiver=<UNKNOWN>
Dec 25 21:52:17 efatsum policyd-spf[14396]: Traceback (most recent call last):
Dec 25 21:52:17 efatsum policyd-spf[14396]: File "/usr/bin/policyd-spf", line 11, in <module>#012 load_entry_point('spf-engine==2.9.1', 'console_scripts', 'policyd-spf')()
Dec 25 21:52:17 efatsum policyd-spf[14396]: File "/usr/lib/python3/dist-packages/spf_engine/policyd_spf.py", line 169, in main#012 sys.stdout.flush()
Dec 25 21:52:17 efatsum policyd-spf[14396]: BrokenPipeError: [Errno 32] Broken pipe
Dec 25 21:52:17 efatsum postfix/spawn[14304]: warning: command /usr/bin/policyd-spf exit status 120
Dec 25 21:54:00 efatsum policyd-spf[14397]: spfcheck: pyspf result: "['Temperror', 'SPF Temporary Error: DNS: TCP Fallback error: [Errno 110] Connection timed out', 'mailfrom']"
Dec 25 21:54:00 efatsum policyd-spf[14397]: Temperror; identity=mailfrom; client-ip=192.243.247.78; helo=r78.mobile.mcdonalds.de; envelope-from=bou...@mobile.mcdonalds.de; receiver=<UNKNOWN>
Dec 25 21:54:00 efatsum policyd-spf[14397]: not peruser
Dec 25 21:54:00 efatsum policyd-spf[14397]: Action: prepend: Text: Received-SPF: Temperror (mailfrom) identity=mailfrom; client-ip=192.243.247.78; helo=r78.mobile.mcdonalds.de; envelope-from=bou...@mobile.mcdonalds.de; receiver=<UNKNOWN> Reject action: 550 5.7.23
Dec 25 21:54:00 efatsum policyd-spf[14397]: prepend Received-SPF: Temperror (mailfrom) identity=mailfrom; client-ip=192.243.247.78; helo=r78.mobile.mcdonalds.de; envelope-from=bou...@mobile.mcdonalds.de; receiver=<UNKNOWN>
Dec 25 21:54:00 efatsum policyd-spf[14397]: Traceback (most recent call last):
Dec 25 21:54:00 efatsum policyd-spf[14397]: File "/usr/bin/policyd-spf", line 11, in <module>#012 load_entry_point('spf-engine==2.9.1', 'console_scripts', 'policyd-spf')()
Dec 25 21:54:00 efatsum policyd-spf[14397]: File "/usr/lib/python3/dist-packages/spf_engine/policyd_spf.py", line 169, in main#012 sys.stdout.flush()
Dec 25 21:54:00 efatsum policyd-spf[14397]: BrokenPipeError: [Errno 32] Broken pipe
Dec 25 21:54:00 efatsum postfix/spawn[14299]: warning: command /usr/bin/policyd-spf exit status 120

Okay, that already explains the cause. My ISP's DNS server doesn't respond to
TCP requests. I didn't know that before.
--
OpenPGP Key: 47BC7DE83D462E8BED18AA861224DBD299A4F5F3
https://www.parckwart.de/pgp_key

Jonathan Marquardt

unread,

Dec 27, 2019, 11:00:03 AM12/27/19

to

On Thu, 26 Dec 2019 07:28:16 -0500 Scott Kitterman <deb...@kitterman.com> wrote:
> From your /etc/postfix/master.cf, how many processes do you allow for the
> policy server and how many smtpd processes do you allow? I've seen that exit
> code before when not enough policy server processes are allowed.

Excerpt from my master.cf:

policy-spf unix - n n - - spawn
user=nobody argv=/usr/bin/policyd-spf

> Please confirm you have debugLevel = 4 set in the policy server's config file?

Confirmed.

Be aware though that I don't get any errors anymore since I fixed my DNS
setup.