Hi there, we are experiencing an strange behaviour of a SPF policy service "pypolicyd-spf" on debian-wheezy (v1.0-2).
We have reported the issue at their side (https://bugs.launchpad.net/pypolicyd-spf/+bug/1587173) but they are pointing us to report it here. When our server is running in our testing environment with near "0" mailflow the SPF policy service kicks-in for every incoming email and works as expected. Instead, if we move our server to production (same server, same configuration but with different IP) where there is a high mailflow, the SPF policy service does not kick-in for every incoming email but some is processed every 2 to 10 minutes. Is anybody of you experiencing any similar problems? Any recommendation? Thank you eNeKuX # apt-cache policy postfix postfix: Installed: 2.9.6-2 # apt-cache policy postfix-policyd-spf-python postfix-policyd-spf-python: Installed: 1.0-2 # postconf -n 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:/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:10022, check_policy_service unix:private/policyd-spf smtpd_restriction_classes = um_clients, permit_um, permit_norelay, check_local_sender, check_local_recipient smtpd_sender_restrictions = check_client_access cidr:/etc/postfix/mynetworks2.cidr, reject_unknown_sender_domain, reject_non_fqdn_sender, reject_rhsbl_sender dsn.rfc-ignorant.org smtpd_tls_CAfile = ${config_directory}/um-root.pem smtpd_tls_auth_only = yes smtpd_tls_cert_file = ${config_directory}/goban-cert.pem smtpd_tls_key_file = ${config_directory}/goban-key.pem smtpd_tls_loglevel = 1 smtpd_tls_received_header = yes smtpd_tls_security_level = may smtpd_tls_session_cache_database = btree:${data_directory}/smtpd_tls_session_cache strict_rfc821_envelopes = yes transport_maps = hash:/etc/postfix/transport um_clients = check_client_access regexp:/etc/postfix/tag_as_originating, permit_mynetworks, permit_sasl_authenticated unknown_local_recipient_reject_code = 550 virtual_alias_maps = hash:/etc/postfix/virtual postconf: warning: /etc/postfix/main.cf: unused parameter: mynetworks2=cidr:/etc/postfix/mynetworks2.cidr postconf: warning: /etc/postfix/main.cf: unused parameter: mynetworks3=cidr:/etc/postfix/mynetworks3.cidr # postconf -Mf smtp inet n - n - 1 postscreen dnsblog unix - - n - 0 dnsblog qmgr fifo n - n 300 1 qmgr tlsmgr unix - - n 1000? 1 tlsmgr rewrite unix - - n - - trivial-rewrite bounce unix - - n - 0 bounce defer unix - - n - 0 bounce trace unix - - n - 0 bounce verify unix - - n - 1 verify flush unix n - n 1000? 0 flush proxymap unix - - n - - proxymap proxywrite unix - - n - 1 proxymap smtp unix - - n - - smtp relay unix - - n - - smtp -o smtp_fallback_relay= showq unix n - n - - showq error unix - - n - - error retry unix - - n - - error discard unix - - n - - discard local unix - n n - - local virtual unix - n n - - virtual lmtp unix - - n - - lmtp anvil unix - - n - 1 anvil scache unix - - n - 1 scache inrelay unix - - n - - smtp -o smtp_connect_timeout=3s lmtp-amavis unix - - y - 40 lmtp -o myhostname=localhost -o lmtp_data_done_timeout=1200 -o lmtp_send_xforward_command=yes -o lmtp_tls_note_starttls_offer=no -o disable_dns_lookups=yes smtp-amavis unix - - y - 40 smtp -o myhostname=localhost -o smtp_data_done_timeout=1200 -o smtp_send_xforward_command=yes -o lmtp_tls_note_starttls_offer=no -o disable_dns_lookups=yes pre-cleanup unix n - n - 0 cleanup -o virtual_alias_maps= pickup fifo n - n 60 1 pickup -o cleanup_service_name=pre-cleanup smtpd pass - - n - - smtpd -o cleanup_service_name=pre-cleanup submission inet n - n - - smtpd -o cleanup_service_name=pre-cleanup -o smtpd_client_restrictions=um_clients,reject -o milter_macro_daemon_name=ORIGINATING smtps inet n - n - - smtpd -o cleanup_service_name=pre-cleanup -o smtpd_tls_wrappermode=yes -o smtpd_client_restrictions=um_clients,reject -o milter_macro_daemon_name=ORIGINATING cleanup unix n - n - 0 cleanup -o mime_header_checks= -o nested_header_checks= -o body_checks= -o header_checks= 127.0.0.1:10025 inet n - y - - smtpd -o content_filter= -o smtpd_delay_reject=no -o smtpd_client_restrictions=permit_mynetworks,reject -o smtpd_helo_restrictions= -o smtpd_sender_restrictions= -o smtpd_recipient_restrictions=permit_mynetworks,reject -o smtpd_data_restrictions=reject_unauth_pipelining -o smtpd_end_of_data_restrictions= -o smtpd_restriction_classes= -o mynetworks=127.0.0.1/8 -o smtpd_error_sleep_time=0 -o smtpd_soft_error_limit=1001 -o smtpd_hard_error_limit=1000 -o smtpd_client_connection_count_limit=0 -o smtpd_client_connection_rate_limit=0 -o receive_override_options=no_header_body_checks,no_unknown_recipient_checks,no_milters -o local_header_rewrite_clients= -o smtpd_milters= -o local_recipient_maps= -o relay_recipient_maps= -o strict_rfc821_envelopes=yes ::1:10025 inet n - y - - smtpd -o content_filter= -o smtpd_delay_reject=no -o smtpd_client_restrictions=permit_mynetworks,reject -o smtpd_helo_restrictions= -o smtpd_sender_restrictions= -o smtpd_recipient_restrictions=permit_mynetworks,reject -o smtpd_data_restrictions=reject_unauth_pipelining -o smtpd_end_of_data_restrictions= -o smtpd_restriction_classes= -o mynetworks=[::1]/128 -o smtpd_error_sleep_time=0 -o smtpd_soft_error_limit=1001 -o smtpd_hard_error_limit=1000 -o smtpd_client_connection_count_limit=0 -o smtpd_client_connection_rate_limit=0 -o receive_override_options=no_header_body_checks,no_unknown_recipient_checks,no_milters -o local_header_rewrite_clients= -o smtpd_milters= -o local_recipient_maps= -o relay_recipient_maps= -o strict_rfc821_envelopes=yes policyd-spf unix - n n - 0 spawn user=policyd-spf argv=/usr/bin/policyd-spf Production logs (no "policyd-spf" policy service): Jun 1 09:17:22 goban postfix/postscreen[14343]: CONNECT from [2001:1470:8000::74]:59864 to [2a00:1600::5]:25 Jun 1 09:17:22 goban postfix/postscreen[14343]: PASS OLD [2001:1470:8000::74]:59864 Jun 1 09:17:22 goban postfix/smtpd[921]: connect from avs1.arnes.si[2001:1470:8000::74]:59864 Jun 1 09:17:22 goban postfix/smtpd[921]: Anonymous TLS connection established from avs1.arnes.si[2001:1470:8000::74]:59864: TLSv1.2 with cipher AECDH-AES256-SHA (256/256 bits) Jun 1 09:17:22 goban postfix/smtpd[921]: NOQUEUE: filter: RCPT from avs1.arnes.si[2001:1470:8000::74]:59864: <avs1.arnes.si[2001:1470:8000::74]:59864>: Client host triggers FILTER lmtp-amavis:[127.0.0.1]:10026; from=<ene...@gmx.com> to=<eneko.ano...@um.si> proto=ESMTP helo=<mail.arnes.si> Jun 1 09:17:22 goban postfix/smtpd[921]: NOQUEUE: filter: RCPT from avs1.arnes.si[2001:1470:8000::74]:59864: <avs1.arnes.si[2001:1470:8000::74]:59864>: Client host triggers FILTER lmtp-amavis:[127.0.0.1]:10024; from=<ene...@gmx.com> to=<eneko.ano...@um.si> proto=ESMTP helo=<mail.arnes.si> Jun 1 09:17:22 goban sqlgrey: grey: from awl match: updating 2001:1470:8000:0000:0000:0000:0000:0074(2001:1470:8000::74), ene...@gmx.com(ene...@gmx.com) Jun 1 09:17:22 goban postfix/smtpd[921]: 35A21D2DD: client=avs1.arnes.si[2001:1470:8000::74]:59864 Jun 1 09:17:22 goban postfix/cleanup[27975]: 35A21D2DD: message-id=<20160601071721.26677...@clitocybe.um.si> Jun 1 09:17:22 goban opendmarc[11776]: 35A21D2DD: gmx.com none Jun 1 09:17:22 goban postfix/qmgr[14333]: 35A21D2DD: from=<ene...@gmx.com>, size=1812, nrcpt=1 (queue active) Jun 1 09:17:22 goban postfix/smtpd[921]: disconnect from avs1.arnes.si[2001:1470:8000::74]:59864 Jun 1 09:17:22 goban.uni-mb.si /usr/sbin/amavisd-new[27930]: (27930-08) LMTP::10024 /var/amavis/tmp/amavis-20160601T090754-27930-Zb2TIIQO: <ene...@gmx.com> -> <eneko.ano...@um.si> SIZE=1812 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 <eneko.ano...@um.si>; Wed, 1 Jun 2016 09:17:22 +0200 (CEST) Jun 1 09:17:22 goban.uni-mb.si /usr/sbin/amavisd-new[27930]: (27930-08) Checking: v1tifNES93m2 [2001:1470:8000::74] <ene...@gmx.com> -> <eneko.ano...@um.si> Jun 1 09:17:22 goban.uni-mb.si /usr/sbin/amavisd-new[27930]: (27930-08) p001 1 Content-Type: text/plain, size: 31 B, name: Jun 1 09:17:23 goban postfix/smtpd[21632]: connect from localhost[::1]:52620 Jun 1 09:17:23 goban postfix/smtpd[21632]: 59FA1D5C1: client=localhost[::1]:52620 Jun 1 09:17:23 goban postfix/cleanup[2930]: 59FA1D5C1: message-id=<20160601071721.26677...@clitocybe.um.si> Jun 1 09:17:23 goban postfix/smtpd[21632]: disconnect from localhost[::1]:52620 Jun 1 09:17:23 goban postfix/qmgr[14333]: 59FA1D5C1: from=<ene...@gmx.com>, size=2534, nrcpt=1 (queue active) Jun 1 09:17:23 goban.uni-mb.si /usr/sbin/amavisd-new[27930]: (27930-08) FWD from <ene...@gmx.com> -> <eneko.ano...@um.si>,BODY=7BIT 250 2.0.0 from MTA(smtp:[::1]:10025): 250 2.0.0 Ok: queued as 59FA1D5C1 Jun 1 09:17:23 goban.uni-mb.si /usr/sbin/amavisd-new[27930]: (27930-08) Passed SPAMMY {RelayedTaggedInbound}, [2001:1470:8000::74]:59864 [194.249.0.30] <ene...@gmx.com> -> <eneko.ano...@um.si>, Queue-ID: 35A21D2DD, Message-ID: <20160601071721.26677...@clitocybe.um.si>, mail_id: v1tifNES93m2, Hits: 21.501, size: 1849, queued_as: 59FA1D5C1, 1076 ms Jun 1 09:17:23 goban.uni-mb.si /usr/sbin/amavisd-new[27930]: (27930-08) TIMING-SA total 999 ms - parse: 1.15 (0.1%), extract_message_metadata: 3 (0.3%), get_uri_detail_list: 0.31 (0.0%), tests_pri_-1000: 4 (0.4%), tests_pri_-950: 0.81 (0.1%), tests_pri_-900: 0.87 (0.1%), tests_pri_-400: 9 (0.9%), check_bayes: 9 (0.9%), tests_pri_0: 951 (95.2%), check_dkim_adsp: 3 (0.3%), check_spf: 41 (4.1%), poll_dns_idle: 34 (3.4%), check_razor2: 835 (83.5%), check_pyzor: 53 (5.3%), tests_pri_500: 2 (0.2%), learn: 17 (1.7%), get_report: 0.62 (0.1%) Jun 1 09:17:23 goban postfix/lmtp[22679]: 35A21D2DD: to=<eneko.ano...@um.si>, relay=127.0.0.1[127.0.0.1]:10024, delay=1.2, delays=0.15/0/0/1.1, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[::1]:10025): 250 2.0.0 Ok: queued as 59FA1D5C1) Jun 1 09:17:23 goban.uni-mb.si /usr/sbin/amavisd-new[27930]: (27930-08) size: 1849, TIMING [total 1079 ms] - SMTP greeting: 1 (0%)0, SMTP LHLO: 0 (0%)0, SMTP pre-MAIL: 0 (0%)0, SMTP pre-DATA-flush: 1 (0%)0, SMTP DATA: 37 (3%)4, check_init: 0 (0%)4, digest_hdr: 1 (0%)4, digest_body_dkim: 0 (0%)4, mime_decode: 4 (0%)4, get-file-type1: 10 (1%)5, decompose_part: 1 (0%)5, parts_decode: 0 (0%)5, check_header: 0 (0%)5, AV-scan-1: 2 (0%)5, spam-wb-list: 1 (0%)6, SA parse: 2 (0%)6, SA check: 994 (92%)98, decide_mail_destiny: 6 (1%)98, notif-quar: 0 (0%)98, fwd-connect: 3 (0%)99, fwd-mail-pip: 1 (0%)99, fwd-rcpt-pip: 0 (0%)99, fwd-data-chkpnt: 0 (0%)99, write-header: 1 (0%)99, fwd-data-contents: 0 (0%)99, fwd-end-chkpnt: 5 (0%)99, prepare-dsn: 0 (0%)99, main_log_entry: 4 (0%)100, update_snmp: 1 (0%)100, SMTP pre-response: 0 (0%)100, SMTP response: 0 (0%)100, unlink-1-files: 0 (0%)100, rundown: 0 (0%)100 Jun 1 09:17:23 goban postfix/qmgr[14333]: 35A21D2DD: removed Jun 1 09:17:23 goban postfix/smtp[23467]: setting up TLS connection to mail.thor.um.si[164.8.42.13]:25 Jun 1 09:17:23 goban postfix/smtp[23467]: mail.thor.um.si[164.8.42.13]:25: TLS cipher list "aNULL:-aNULL:ALL:+RC4:@STRENGTH" Jun 1 09:17:23 goban postfix/smtp[23467]: looking for session smtp:164.8.42.13:25:ex3.thor.um.si&p=1&c=aNULL:-aNULL:ALL:+RC4:@STRENGTH&l=268439647 in smtp cache Jun 1 09:17:23 goban postfix/tlsmgr[14342]: lookup smtp session id=smtp:164.8.42.13:25:ex3.thor.um.si&p=1&c=aNULL:-aNULL:ALL:+RC4:@STRENGTH&l=268439647 Jun 1 09:17:23 goban postfix/tlsmgr[14342]: read smtp TLS cache entry smtp:164.8.42.13:25:ex3.thor.um.si&p=1&c=aNULL:-aNULL:ALL:+RC4:@STRENGTH&l=268439647: time=1464763711 [data 893 bytes] Jun 1 09:17:23 goban postfix/smtpd[32257]: disconnect from snt004-omc1s13.hotmail.com[65.55.90.24]:51040 Jun 1 09:17:23 goban postfix/smtp[23467]: reloaded session smtp:164.8.42.13:25:ex3.thor.um.si&p=1&c=aNULL:-aNULL:ALL:+RC4:@STRENGTH&l=268439647 from smtp cache Jun 1 09:17:23 goban postfix/smtp[23467]: SSL_connect:before/connect initialization Jun 1 09:17:23 goban postfix/smtp[23467]: SSL_connect:SSLv3 write client hello A Jun 1 09:17:23 goban postfix/smtp[23467]: SSL_connect:SSLv3 read server hello A Jun 1 09:17:23 goban postfix/smtp[23467]: SSL_connect:SSLv3 read finished A Jun 1 09:17:23 goban postfix/smtp[23467]: SSL_connect:SSLv3 write change cipher spec A Jun 1 09:17:23 goban postfix/smtp[23467]: SSL_connect:SSLv3 write finished A Jun 1 09:17:23 goban postfix/smtp[23467]: SSL_connect:SSLv3 flush data Jun 1 09:17:23 goban postfix/smtp[23467]: mail.thor.um.si[164.8.42.13]:25: Reusing old session Jun 1 09:17:23 goban postfix/smtp[23467]: mail.thor.um.si[164.8.42.13]:25: subject_CN=ex3, issuer_CN=ex3, fingerprint 60:28:08:C3:D7:8B:5C:57:D0:57:F2:50:D8:8C:C8:32, pkey_fingerprint=21:8E:88:7F:88:A8:DA:DA:4A:EB:14:78:8F:2C:2B:A6 Jun 1 09:17:23 goban postfix/smtp[23467]: Untrusted TLS connection established to mail.thor.um.si[164.8.42.13]:25: TLSv1.2 with cipher ECDHE-RSA-AES256-SHA384 (256/256 bits) Jun 1 09:17:23 goban postfix/postscreen[14343]: CONNECT from [23.228.105.184]:43531 to [164.8.100.5]:25 Jun 1 09:17:23 goban postfix/postscreen[14343]: PASS OLD [23.228.105.184]:43531 Jun 1 09:17:23 goban postfix/smtpd[31921]: connect from m23228105-184.g.richdelivery.com[23.228.105.184]:43531 Jun 1 09:17:23 goban postfix/smtp[23467]: 59FA1D5C1: to=<eneko.ano...@um.si>, relay=mail.thor.um.si[164.8.42.13]:25, delay=0.25, delays=0.01/0/0.06/0.19, dsn=2.6.0, status=sent (250 2.6.0 <20160601071721.26677...@clitocybe.um.si> [InternalId=37409165149874, Hostname=ex4.thor.um.si] Queued mail for delivery) Jun 1 09:17:23 goban postfix/qmgr[14333]: 59FA1D5C1: removed Testing logs (there are "policyd-spf" entries): Jun 1 09:05:00 gobantest postfix/postscreen[12634]: CONNECT from [2001:1470:8000::75]:34483 to [2a00:1600::6]:25 Jun 1 09:05:06 gobantest postfix/postscreen[12634]: PASS OLD [2001:1470:8000::75]:34483 Jun 1 09:05:06 gobantest postfix/smtpd[12663]: connect from avs2.arnes.si[2001:1470:8000::75]:34483 Jun 1 09:05:06 gobantest postfix/smtpd[12663]: Anonymous TLS connection established from avs2.arnes.si[2001:1470:8000::75]:34483: TLSv1.2 with cipher AECDH-AES256-SHA (256/256 bits) Jun 1 09:05:06 gobantest postfix/smtpd[12663]: NOQUEUE: filter: RCPT from avs2.arnes.si[2001:1470:8000::75]:34483: <avs2.arnes.si[2001:1470:8000::75]:34483>: Client host triggers FILTER lmtp-amavis:[127.0.0.1]:10026; from=<ene...@gmx.com> to=<eneko.ano...@u-m.si> proto=ESMTP helo=<mail.arnes.si> Jun 1 09:05:06 gobantest postfix/smtpd[12663]: NOQUEUE: filter: RCPT from avs2.arnes.si[2001:1470:8000::75]:34483: <avs2.arnes.si[2001:1470:8000::75]:34483>: Client host triggers FILTER lmtp-amavis:[127.0.0.1]:10024; from=<ene...@gmx.com> to=<eneko.ano...@u-m.si> proto=ESMTP helo=<mail.arnes.si> Jun 1 09:05:06 gobantest sqlgrey: grey: from awl match: updating 2001:1470:8000:0000:0000:0000:0000:0075(2001:1470:8000::75), ene...@gmx.com(ene...@gmx.com) Jun 1 09:05:06 gobantest policyd-spf[12667]: Starting Jun 1 09:05:06 gobantest policyd-spf[12667]: Read line: "request=smtpd_access_policy" Jun 1 09:05:06 gobantest policyd-spf[12667]: Read line: "protocol_state=RCPT" Jun 1 09:05:06 gobantest policyd-spf[12667]: Read line: "protocol_name=ESMTP" Jun 1 09:05:06 gobantest policyd-spf[12667]: Read line: "client_address=2001:1470:8000::75" Jun 1 09:05:06 gobantest policyd-spf[12667]: Read line: "client_name=avs2.arnes.si" Jun 1 09:05:06 gobantest policyd-spf[12667]: Read line: "reverse_client_name=avs2.arnes.si" Jun 1 09:05:06 gobantest policyd-spf[12667]: Read line: "helo_name=mail.arnes.si" Jun 1 09:05:06 gobantest policyd-spf[12667]: Read line: "sender=ene...@gmx.com" Jun 1 09:05:06 gobantest policyd-spf[12667]: Read line: "recipient=eneko.ano...@u-m.si" Jun 1 09:05:06 gobantest policyd-spf[12667]: Read line: "recipient_count=0" Jun 1 09:05:06 gobantest policyd-spf[12667]: Read line: "queue_id=" Jun 1 09:05:06 gobantest policyd-spf[12667]: Read line: "instance=3177.574e8922.4bc9b.0" Jun 1 09:05:06 gobantest policyd-spf[12667]: Read line: "size=1440" Jun 1 09:05:06 gobantest policyd-spf[12667]: Read line: "etrn_domain=" Jun 1 09:05:06 gobantest policyd-spf[12667]: Read line: "stress=" Jun 1 09:05:06 gobantest policyd-spf[12667]: Read line: "sasl_method=" Jun 1 09:05:06 gobantest policyd-spf[12667]: Read line: "sasl_username=" Jun 1 09:05:06 gobantest policyd-spf[12667]: Read line: "sasl_sender=" Jun 1 09:05:06 gobantest policyd-spf[12667]: Read line: "ccert_subject=" Jun 1 09:05:06 gobantest policyd-spf[12667]: Read line: "ccert_issuer=" Jun 1 09:05:06 gobantest policyd-spf[12667]: Read line: "ccert_fingerprint=" Jun 1 09:05:06 gobantest policyd-spf[12667]: Read line: "ccert_pubkey_fingerprint=" Jun 1 09:05:06 gobantest policyd-spf[12667]: Read line: "encryption_protocol=TLSv1.2" Jun 1 09:05:06 gobantest policyd-spf[12667]: Read line: "encryption_cipher=AECDH-AES256-SHA" Jun 1 09:05:06 gobantest policyd-spf[12667]: Read line: "encryption_keysize=256" Jun 1 09:05:06 gobantest policyd-spf[12667]: Read line: "" Jun 1 09:05:06 gobantest policyd-spf[12667]: Found the end of entry Jun 1 09:05:06 gobantest policyd-spf[12667]: Config: {'Mail_From_reject': 'False', 'Header_Type': 'AR', 'Whitelist': '164.8.0.0/16,2A00:1600:://29', 'PermError_reject': 'False', 'HELO_reject': 'False', 'Authserv_Id': 'mx1test.um.si', 'defaultSeedOnly': 1, 'debugLevel': 4, 'skip_addresses': '127.0.0.0/8,::ffff:127.0.0.0//104,::1//128,127.0.0.1,::1', 'TempError_Defer': 'False'} Jun 1 09:05:06 gobantest policyd-spf[12667]: Cached data for this instance: [] Jun 1 09:05:06 gobantest policyd-spf[12667]: spfcheck: pyspf result: "['None', '', 'helo']" Jun 1 09:05:06 gobantest policyd-spf[12667]: None; identity=helo; client-ip=2001:1470:8000::75; helo=mail.arnes.si; envelope-from=ene...@gmx.com; receiver=eneko.ano...@u-m.si Jun 1 09:05:06 gobantest policyd-spf[12667]: spfcheck: pyspf result: "['Fail', 'SPF fail - not authorized', 'mailfrom']" Jun 1 09:05:06 gobantest policyd-spf[12667]: Fail; identity=mailfrom; client-ip=2001:1470:8000::75; helo=mail.arnes.si; envelope-from=ene...@gmx.com; receiver=eneko.ano...@u-m.si Jun 1 09:05:06 gobantest policyd-spf[12667]: Action: prepend: Text: Authentication-Results: mx1test.um.si; spf=fail (SPF fail - not authorized) smtp.mailfrom=gmx.com (client-ip=2001:1470:8000::75; helo=mail.arnes.si; envelope-from=ene...@gmx.com; receiver=eneko.ano...@u-m.si) Jun 1 09:05:06 gobantest postfix/smtpd[12663]: 91D9268E: client=avs2.arnes.si[2001:1470:8000::75]:34483 Jun 1 09:05:06 gobantest postfix/cleanup[12668]: 91D9268E: message-id=<20160601070457.246f1...@clitocybe.um.si> Jun 1 09:05:06 gobantest opendmarc[4805]: 91D9268E: gmx.com none Jun 1 09:05:06 gobantest postfix/qmgr[6122]: 91D9268E: from=<ene...@gmx.com>, size=2065, nrcpt=1 (queue active) Jun 1 09:05:06 gobantest postfix/smtpd[12663]: disconnect from avs2.arnes.si[2001:1470:8000::75]:34483 Jun 1 09:05:06 gobantest.um.si /usr/sbin/amavisd-new[6054]: (06054-01) LMTP::10024 /var/amavis/tmp/amavis-20160601T090506-06054-gfRbrC9q: <ene...@gmx.com> -> <eneko.ano...@u-m.si> SIZE=2065 BODY=7BIT Received: from localhost ([127.0.0.1]) by localhost (gobantest.um.si [127.0.0.1]) (amavisd-new, port 10024) with LMTP for <eneko.ano...@u-m.si>; Wed, 1 Jun 2016 09:05:06 +0200 (CEST) Jun 1 09:05:06 gobantest.um.si /usr/sbin/amavisd-new[6054]: (06054-01) Checking: 5hUa8cVltA23 [2001:1470:8000::75] <ene...@gmx.com> -> <eneko.ano...@u-m.si> Jun 1 09:05:06 gobantest.um.si /usr/sbin/amavisd-new[6054]: (06054-01) p001 1 Content-Type: text/plain, size: 31 B, name: Jun 1 09:05:08 gobantest.um.si /usr/sbin/amavisd-new[6054]: (06054-01) spam-tag, <ene...@gmx.com> -> <eneko.ano...@u-m.si>, Yes, score=18.101 tagged_above=-999 required=6.31 tests=[BAYES_00=-1.9, FREEMAIL_FROM=0.001, SPF_FAIL=20] autolearn=no Jun 1 09:05:08 gobantest postfix/smtpd[12673]: connect from localhost[::1]:47354 Jun 1 09:05:08 gobantest postfix/smtpd[12673]: 237326D5: client=localhost[::1]:47354 Jun 1 09:05:08 gobantest postfix/cleanup[12674]: 237326D5: message-id=<20160601070457.246f1...@clitocybe.um.si> Jun 1 09:05:08 gobantest postfix/qmgr[6122]: 237326D5: from=<ene...@gmx.com>, size=2784, nrcpt=1 (queue active) Jun 1 09:05:08 gobantest.um.si /usr/sbin/amavisd-new[6054]: (06054-01) FWD from <ene...@gmx.com> -> <eneko.ano...@u-m.si>,BODY=7BIT 250 2.0.0 from MTA(smtp:[::1]:10025): 250 2.0.0 Ok: queued as 237326D5 Jun 1 09:05:08 gobantest postfix/smtp[12675]: initializing the client-side TLS engine Jun 1 09:05:08 gobantest postfix/smtp[12675]: setting up TLS connection to mail.thort.um.si[164.8.42.134]:25 Jun 1 09:05:08 gobantest postfix/smtp[12675]: mail.thort.um.si[164.8.42.134]:25: TLS cipher list "aNULL:-aNULL:ALL:+RC4:@STRENGTH" Jun 1 09:05:08 gobantest postfix/smtp[12675]: looking for session smtp:164.8.42.134:25:ex3t.thort.um.si&p=1&c=aNULL:-aNULL:ALL:+RC4:@STRENGTH&l=268439647 in smtp cache Jun 1 09:05:08 gobantest postfix/tlsmgr[6190]: lookup smtp session id=smtp:164.8.42.134:25:ex3t.thort.um.si&p=1&c=aNULL:-aNULL:ALL:+RC4:@STRENGTH&l=268439647 Jun 1 09:05:08 gobantest postfix/tlsmgr[6190]: read smtp TLS cache entry smtp:164.8.42.134:25:ex3t.thort.um.si&p=1&c=aNULL:-aNULL:ALL:+RC4:@STRENGTH&l=268439647: time=1464764425 [data 898 bytes] Jun 1 09:05:08 gobantest postfix/smtp[12675]: reloaded session smtp:164.8.42.134:25:ex3t.thort.um.si&p=1&c=aNULL:-aNULL:ALL:+RC4:@STRENGTH&l=268439647 from smtp cache Jun 1 09:05:08 gobantest.um.si /usr/sbin/amavisd-new[6054]: (06054-01) Passed SPAMMY {RelayedTaggedInbound}, [2001:1470:8000::75]:34483 [194.249.0.30] <ene...@gmx.com> -> <eneko.ano...@u-m.si>, Queue-ID: 91D9268E, Message-ID: <20160601070457.246f1...@clitocybe.um.si>, mail_id: 5hUa8cVltA23, Hits: 18.101, size: 2101, queued_as: 237326D5, 1472 ms Jun 1 09:05:08 gobantest.um.si /usr/sbin/amavisd-new[6054]: (06054-01) TIMING-SA total 1366 ms - parse: 1.22 (0.1%), extract_message_metadata: 32 (2.3%), poll_dns_idle: 23 (1.7%), get_uri_detail_list: 0.22 (0.0%), tests_pri_-1000: 4 (0.3%), tests_pri_-950: 0.67 (0.0%), tests_pri_-900: 0.70 (0.1%), tests_pri_-400: 10 (0.8%), check_bayes: 10 (0.7%), tests_pri_0: 1304 (95.5%), check_dkim_adsp: 3 (0.2%), check_spf: 3 (0.2%), check_razor2: 1206 (88.3%), check_pyzor: 68 (5.0%), tests_pri_500: 3 (0.2%), get_report: 0.50 (0.0%) Jun 1 09:05:08 gobantest postfix/smtp[12675]: SSL_connect:before/connect initialization Jun 1 09:05:08 gobantest postfix/smtp[12675]: SSL_connect:SSLv3 write client hello A Jun 1 09:05:08 gobantest postfix/smtp[12675]: SSL_connect:SSLv3 read server hello A Jun 1 09:05:08 gobantest postfix/smtp[12675]: SSL_connect:SSLv3 read finished A Jun 1 09:05:08 gobantest postfix/smtp[12675]: SSL_connect:SSLv3 write change cipher spec A Jun 1 09:05:08 gobantest postfix/smtp[12675]: SSL_connect:SSLv3 write finished A Jun 1 09:05:08 gobantest postfix/smtp[12675]: SSL_connect:SSLv3 flush data Jun 1 09:05:08 gobantest postfix/smtp[12675]: mail.thort.um.si[164.8.42.134]:25: Reusing old session Jun 1 09:05:08 gobantest postfix/lmtp[12669]: 91D9268E: to=<eneko.ano...@u-m.si>, relay=127.0.0.1[127.0.0.1]:10024, delay=1.9, delays=0.37/0.01/0.01/1.5, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[::1]:10025): 250 2.0.0 Ok: queued as 237326D5) Jun 1 09:05:08 gobantest postfix/smtp[12675]: mail.thort.um.si[164.8.42.134]:25: subject_CN=ex3t, issuer_CN=ex3t, fingerprint E3:BB:DE:7C:02:DF:56:7A:3F:F4:D6:0A:EB:D9:A2:3F, pkey_fingerprint=21:E4:61:E3:8A:51:FB:4A:33:99:00:1B:FF:72:16:8A Jun 1 09:05:08 gobantest postfix/smtp[12675]: Untrusted TLS connection established to mail.thort.um.si[164.8.42.134]:25: TLSv1.2 with cipher ECDHE-RSA-AES256-SHA384 (256/256 bits) Jun 1 09:05:08 gobantest.um.si /usr/sbin/amavisd-new[6054]: (06054-01) size: 2101, TIMING [total 1475 ms] - SMTP greeting: 4 (0%)0, SMTP LHLO: 1 (0%)0, SMTP pre-MAIL: 1 (0%)0, mkdir tempdir: 1 (0%)0, create email.txt: 0 (0%)0, SMTP pre-DATA-flush: 2 (0%)1, SMTP DATA: 34 (2%)3, check_init: 1 (0%)3, digest_hdr: 1 (0%)3, digest_body_dkim: 0 (0%)3, mkdir parts: 2 (0%)3, mime_decode: 5 (0%)3, get-file-type1: 9 (1%)4, decompose_part: 1 (0%)4, parts_decode: 0 (0%)4, check_header: 0 (0%)4, AV-scan-1: 2 (0%)4, spam-wb-list: 1 (0%)4, SA parse: 3 (0%)5, SA check: 1361 (92%)97, decide_mail_destiny: 5 (0%)97, notif-quar: 0 (0%)97, fwd-connect: 12 (1%)98, fwd-mail-pip: 7 (0%)99, fwd-rcpt-pip: 0 (0%)99, fwd-data-chkpnt: 0 (0%)99, write-header: 1 (0%)99, fwd-data-contents: 0 (0%)99, fwd-end-chkpnt: 4 (0%)99, prepare-dsn: 1 (0%)99, main_log_entry: 12 (1%)100, update_snmp: 1 (0%)100, SMTP pre-response: 0 (0%)100, SMTP response: 0 (0%)100, unlink-1-files: 0 (0%)100, rundown: 1 (0%)100 Jun 1 09:05:08 gobantest.um.si /usr/sbin/amavisd-new[6054]: (06054-01) extra modules loaded: unicore/lib/Nt/De.pl, unicore/lib/Perl/SpacePer.pl Jun 1 09:05:08 gobantest postfix/qmgr[6122]: 91D9268E: removed Jun 1 09:05:08 gobantest postfix/smtp[12675]: 237326D5: to=<eneko.ano...@u-m.si>, relay=mail.thort.um.si[164.8.42.134]:25, delay=0.26, delays=0.01/0.01/0.05/0.2, dsn=2.6.0, status=sent (250 2.6.0 <20160601070457.246f1...@clitocybe.um.si> [InternalId=36889474105350, Hostname=ex3t.thort.um.si] Queued mail for delivery) Jun 1 09:05:08 gobantest postfix/qmgr[6122]: 237326D5: removed
