no headers are added maybe due to overload of the server?

[enekux]

Hi,

we have noticed an strange behaviour of "pypolicyd-spf" on debian-wheezy v1.0-2.

In our testing postfix with near "0" mailflow headers are added and it is working as expected.

Instead, if we put it in production with big mailflow, no headers are added...

Is anybody else here experiencing the same problems?

Any recommendation?

Thank you

[Scott Kitterman (kitterman)]

On Monday, May 30, 2016 07:54:41 PM you wrote:
> Public bug reported:
>
> Hi,
>
> we have noticed an strange behaviour of "pypolicyd-spf" on debian-wheezy
> v1.0-2.
>
> In our testing postfix with near "0" mailflow headers are added and it
> is working as expected.
>
> Instead, if we put it in production with big mailflow, no headers are
> added...
>
> Is anybody else here experiencing the same problems?
>
>
> Any recommendation?

Do you have the mail logs from when this is happening? Without logs I can't
do anything but speculate.

Scott K

[enekux (enekux)]

Hi,

here is my configuration:

# For a fully commented sample config file see policyd-spf.conf.commented

debugLevel = 4
defaultSeedOnly = 1

#HELO_reject = SPF_Not_Pass
#Mail_From_reject = Softfail
#HELO_reject = SPF_Not_Pass
#Mail_From_reject = Fail
#HELO_reject = Fail
#Mail_From_reject = Fail
HELO_reject = False
Mail_From_reject = False

PermError_reject = False
TempError_Defer = False

skip_addresses = 127.0.0.0/8,::ffff:127.0.0.0//104,::1//128

#Header_Type = SPF
Header_Type = AR

Authserv_Id = mx1.uni-mb.si

and here the logs (notice that in Production logs "policyd-spf" log entries are missing therefore the missing headers, whereas in test it works everything OK):

Production:

May 31 08:29:17 goban postfix/smtpd[31868]: NOQUEUE: filter: RCPT from avs2.arnes.si[193.2.1.75]:46402: <avs2.arnes.si[193.2.1.75]:46402>: Client host triggers FILTER lmtp-amavis:[127.0.0.1]:10026; from=<email address hidden> to=<email address hidden> proto=ESMTP helo=<mail.arnes.si>
May 31 08:29:17 goban postfix/smtpd[31868]: NOQUEUE: filter: RCPT from avs2.arnes.si[193.2.1.75]:46402: <avs2.arnes.si[193.2.1.75]:46402>: Client host triggers FILTER lmtp-amavis:[127.0.0.1]:10024; from=<email address hidden> to=<email address hidden> proto=ESMTP helo=<mail.arnes.si>
May 31 08:29:17 goban sqlgrey: grey: from awl match: updating 193.2.1(193.2.1.75), <email address hidden>(<email address hidden>)
May 31 08:29:17 goban postfix/qmgr[22161]: 25880D636: from=<email address hidden>, size=1770, nrcpt=1 (queue active)
May 31 08:29:17 goban.uni-mb.si /usr/sbin/amavisd-new[23508]: (23508-12) LMTP::10024 /var/amavis/tmp/amavis-20160531T081224-23508-yIqE64FM: <email address hidden> -> <email address hidden> SIZE=1770 BODY=7BIT Received: from localhost ([127.0.0.1]) by localhost (goban.uni-mb.si [127.0.0.1]) (amavisd-new, port 10024) with LMTP for <email address hidden>; Tue, 31 May 2016 08:29:17 +0200 (CEST)
May 31 08:29:17 goban.uni-mb.si /usr/sbin/amavisd-new[23508]: (23508-12) Checking: 3a5PXVMhSeTb [193.2.1.75] <email address hidden> -> <email address hidden>
May 31 08:29:18 goban.uni-mb.si /usr/sbin/amavisd-new[23508]: (23508-12) spam-tag, <email address hidden> -> <email address hidden>, Yes, score=18.501 tagged_above=-999 required=6.31 tests=[BAYES_50=0.8, FREEMAIL_FROM=0.001, RCVD_IN_DNSWL_MED=-2.3, SPF_FAIL=20] autolearn=spam
May 31 08:29:18 goban postfix/qmgr[22161]: 99339D662: from=<email address hidden>, size=2574, nrcpt=1 (queue active)
May 31 08:29:18 goban.uni-mb.si /usr/sbin/amavisd-new[23508]: (23508-12) FWD from <email address hidden> -> <email address hidden>,BODY=7BIT 250 2.0.0 from MTA(smtp:[::1]:10025): 250 2.0.0 Ok: queued as 99339D662
May 31 08:29:18 goban.uni-mb.si /usr/sbin/amavisd-new[23508]: (23508-12) Passed SPAMMY {RelayedTaggedInbound}, [193.2.1.75]:46402 [2001:1470:8000:400::120] <email address hidden> -> <email address hidden>, Queue-ID: 25880D636, Message-ID: <email address hidden>, mail_id: 3a5PXVMhSeTb, Hits: 18.501, size: 1770, queued_as: 99339D662, 1477 ms

Testing:

May 31 08:29:16 gobantest postfix/smtpd[5261]: NOQUEUE: filter: RCPT from avs2.arnes.si[2001:1470:8000::75]:59928: <avs2.arnes.si[2001:1470:8000::75]:59928>: Client host triggers FILTER lmtp-amavis:[127.0.0.1]:10026; from=<email address hidden> t...

[Scott Kitterman (kitterman)]

With debugLevel = 4 in your configuration, you'd see information logged almost
as soon as the policy server is started, so if that's the configuration you're
using, I'd say it's not getting started in production for some reason, but the
log information you provided for the test environment aren't consistent with
debugLevel = 4 either.

I'm not convinced you're actually using the configurations you think you are.

What's the ouput of postconf -n for both production and test?

Scott K

[enekux (enekux)]

Hi you are totally right. I didn't have consistent debugLevel parameter set in both environments and my logs were not complete (due to the grep filter), sorry for that.

Here now are the complete logs from both systems:

+ Production:

see attached "logs_production.txt"

+ Testing:

see attached "logs_testing.txt"

As you can see, in Production the policy is not getting started. But from day logs we see that for random incoming emails it does start...

Thank you,

[Scott Kitterman (kitterman)]

On Wednesday, June 01, 2016 07:33:37 AM you wrote:
> Hi you are totally right. I didn't have consistent debugLevel parameter
> set in both environments and my logs were not complete (due to the grep
> filter), sorry for that.
>
> Here now are the complete logs from both systems:
>
> + Production:
>
> see attached "logs_production.txt"
>
> + Testing:
>
> see attached "logs_testing.txt"
>
>
> As you can see, in Production the policy is not getting started. But from
> day logs we see that for random incoming emails it does start...

If you note the line:

Jun 1 09:05:06 gobantest policyd-spf[12667]: Starting

in the testing log. that's almost the very first thing the policy server does,
so if that doesn't make it into the log, either the logging is broken or the
policy server is never called from postfix.

Please have a look at the output of postconf -n for both systems and add them
to the bug. There's likely a difference. Also please copy/paste the relevant
policy service from each you added in master.cf.

Scott K

[enekux (enekux)]

Hi,

today I have done the next test:

I have made a clone of production, changed the IP and put it in testing. There it works as expected.

I think that the milter cannot kick-in in all the incoming emails... because from production logs I see that some of the emails are verified by it approximately every 2 to 10 minutes...

VERY weird I know...

[Scott Kitterman (kitterman)]

OK. Having postconf -n and the relevant master.cf entries would help me
understand what's going on. In the case where the check is missing, postfix
isn't calling the policy server for some reason.

[enekux (enekux)]

Hi,

here is the main.cf:

alias_database = hash:/etc/aliases
alias_maps = hash:/etc/aliases
append_dot_mydomain = no
bounce_queue_lifetime = 3d
check_local_recipient = check_recipient_access regexp:/etc/postfix/recipient_access
check_local_sender = check_sender_access regexp:/etc/postfix/sender_access
command_directory = /usr/sbin
config_directory = /etc/postfix
content_filter = lmtp-amavis:[127.0.0.1]:10024
daemon_directory = /usr/lib/postfix
data_directory = /var/lib/postfix
debug_peer_level = 2
debugger_command = PATH=/bin:/usr/bin:/usr/local/bin:/usr/X11R6/bin ddd $daemon_directory/$process_name $process_id & sleep 5
delay_warning_time = 5m
disable_vrfy_command = yes
html_directory = /usr/share/postfix
inet_protocols = ipv4, ipv6
local_header_rewrite_clients = permit_mynetworks
mail_owner = postfix
mailq_path = /usr/bin/mailq
manpage_directory = /usr/local/man
maximal_queue_lifetime = 14d
message_size_limit = 14485760
milter_default_action = accept
milter_protocol = 6
mydestination = $myhostname, localhost.$mydomain, localhost, mx1.$mydomain
myhostname = goban.uni-mb.si
mynetworks = /etc/postfix/mynetworks
newaliases_path = /usr/bin/newaliases
non_smtpd_milters = inet:localhost:12345,inet:localhost:54321
permit_norelay = permit_mynetworks, permit_sasl_authenticated, reject_unauth_destination, check_policy_service inet:127.0.0.1:10022, permit
permit_um = check_recipient_access hash:/etc/postfix/toreg, permit_mynetworks, permit_sasl_authenticated, reject_unauth_destination, check_policy_service inet:127.0.0.1:10022, permit
policyd-spf_time_limit = 3600
queue_directory = /var/spool/postfix
queue_minfree = 51200000
readme_directory = /usr/share/postfix/
recipient_delimiter = +
relay_domains = $mydestination dpv-celje.si drustvo-drava.si e-um.si homemade.net institut-iris.eu j-npcs.org mariborski-oktet.org nessi-slovenia.com openscience.si sikom.si tp-artemis.si student.uni-mb.si mxstudent.uni-mb.si mxalumni.uni-mb.si fl.uni-mb.si um.si guest.um.si student.um.si mxstudent.um.si u-m.si guest.u-m.si student.u-m.si mxstudent.u-m.si lists.um.si unimb.si
remote_header_rewrite_domain = domain.invalid
sample_directory = /usr/share/postfix/
sender_bcc_maps = hash:/etc/postfix/bcc_map
sender_canonical_maps = hash:/etc/postfix/sender_canonical
sendmail_path = /usr/sbin/sendmail
setgid_group = postdrop
smtp_tls_CAfile = ${config_directory}/um-root.pem
smtp_tls_CApath = /etc/ssl/certs
smtp_tls_loglevel = 2
smtp_tls_note_starttls_offer = yes
smtp_tls_security_level = may
smtp_tls_session_cache_database = btree:${data_directory}/smtp_tls_session_cache
smtpd_banner = $myhostname ESMTP $mail_name (Debian/GNU)
smtpd_client_port_logging = yes
smtpd_client_restrictions = um_clients, check_client_access hash:/etc/postfix/whitelist, reject_rbl_client zen.spamhaus.org, reject_rbl_client cbl.abuseat.org, reject_rbl_client bl.spamcop.net, check_client_access regexp:/etc/postfix/tag_as_foreign
smtpd_helo_required = yes
smtpd_helo_restrictions = reject_invalid_helo_hostname
smtpd_milters = inet:localhost:12345,inet:localhost:54321
smtpd_recipient_restrictions = check_client_access cidr:/etc/postfix/mynetworks3.cidr, reject_unauth_pipelining, check_sender_access hash:/...

[Scott Kitterman (kitterman)]

What's the policy service associated with "check_policy_service inet:127.0.0.1:10022" in smtpd_recipient_restrictions and do you have evidence in the logs of it running?

[enekux (enekux)]

Hi,

it is used for "greylisting" policy service "sqlgrey"

[Scott Kitterman (kitterman)]

Thanks.

In this policy server, if debugLevel >= 3, 'Starting' should get logged. This happens before it even tries to read any of the input. Please check that you have debugLevel >= 3 in the config file for this policy server and then check for 'Starting' being logged for the policy service.

[enekux (enekux)]

Hi,

as stated before the debugLevel is set to 4. Also I mentioned that from 2 to 10 minutes one email gets processed by the policy so yes I see the 'Starting' log entry, but we have several dozens of emails been processed a minute...

[Scott Kitterman (kitterman)]

On Friday, June 03, 2016 03:54:25 PM you wrote:
> Hi,
>
> as stated before the debugLevel is set to 4. Also I mentioned that from
> 2 to 10 minutes one email gets processed by the policy so yes I see the
> 'Starting' log entry, but we have several dozens of emails been
> processed a minute...

OK. I don't think this is something specific to the policy server
implementation. I think the pipe to it isn't being opened for some reason. I
would recommend you ask about this on the postfix-users list (which I am
subscribed to) so we can get more postfix expertise involved in this
discussion.

Scott K

[enekux (enekux)]

Hi Scott,

finally we found where the problem was.

The problem was in the location of the "check_policy_service unix:private/policyd-spf" in our Postfix configuration... we located it at the very bottom of the "smtpd_recipient_restrictions", so incoming emails where never evaluated by the check, except some...

smtpd_recipient_restrictions =
  check_client_access cidr:/etc/postfix/mynetworks3.cidr,
  reject_unauth_pipelining,
  check_sender_access hash:/etc/postfix/acl-1-from,
  check_recipient_access hash:/etc/postfix/acl-1-to,
  check_sender_access regexp:/etc/postfix/acl-2-from,
  check_sender_access hash:/etc/postfix/fromreg,
  check_recipient_access hash:/etc/postfix/toreg,
  permit_mynetworks,
  permit_sasl_authenticated,
  reject_unauth_destination,
# check_policy_service inet:127.0.0.1:10023,
  check_policy_service inet:127.0.0.1:10022,
  check_policy_service unix:private/policyd-spf

So I located it a bit higher and now all incoming emails are processed by the policy.

Sorry for the inconveniences and best regards,

Eneko