1 (edited by romfeo 2018-05-05 06:11:41)

Topic: No DKIM from Mua

==== Required information ====
- iRedMail version (check /etc/iredmail-release): 0.9.8
- Linux/BSD distribution name and version: Ubuntu 18.04 LTS
- Store mail accounts in which backend (LDAP/MySQL/PGSQL): MySQL
- Web server (Apache or Nginx): Nginx
- Manage mail accounts with iRedAdmin-Pro? No
- [IMPORTANT] Related original log or error message is required if you're experiencing an issue.
====

I am facing this issue where emails sent from Roundcube have proper DKIM signature, but email sent from thunderbird or wordpress (with proper stmp settings) dont get dkim signature.

I send through port 587 with TLS and SMTP authentication

Any ideas where to start looking?

----

Spider Email Archiver: On-Premises, lightweight email archiving software developed by iRedMail team. Supports Amazon S3 compatible storage and custom branding.

2

Re: No DKIM from Mua

Please show us transport "submission" related settings in /etc/postfix/master.cf.

3 (edited by romfeo 2018-05-06 19:40:46)

Re: No DKIM from Mua

ZhangHuangbin wrote:

Please show us transport "submission" related settings in /etc/postfix/master.cf.

Thank you for your reply!
I hope this is the info you asked for:

# Submission, port 587, force TLS connection.
submission inet n       -       n       -       -       smtpd
  -o syslog_name=postfix/submission
  -o smtpd_tls_security_level=encrypt
  -o smtpd_sasl_auth_enable=yes
  -o smtpd_client_restrictions=permit_sasl_authenticated,reject
  -o content_filter=smtp-amavis:[127.0.0.1]:10026

And here is the log part from a test via Wordpress (no dkim signature):

May  6 13:14:53 webserver postfix/submission/smtpd[8469]: warning: hostname webserver.dixtysports.gr does not resolve to address 195.201.222.253
May  6 13:14:53 webserver postfix/submission/smtpd[8469]: connect from unknown[195.201.222.253]
May  6 13:14:53 webserver postfix/submission/smtpd[8469]: Anonymous TLS connection established from unknown[195.201.222.253]: TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)
May  6 13:14:53 webserver postfix/submission/smtpd[8469]: C7AEF40C4D: client=unknown[195.201.222.253], sasl_method=LOGIN, sasl_username=info@dixtysports.gr
May  6 13:14:53 webserver postfix/cleanup[8527]: C7AEF40C4D: message-id=<25a0870ce3e63932e8e2a812dce06a52@_>
May  6 13:14:53 webserver postfix/qmgr[4611]: C7AEF40C4D: from=<info@dixtysports.gr>, size=605, nrcpt=1 (queue active)
May  6 13:14:53 webserver postfix/submission/smtpd[8469]: disconnect from unknown[195.201.222.253] ehlo=2 starttls=1 auth=1 mail=1 rcpt=1 data=1 quit=1 commands=8
May  6 13:14:53 webserver postfix/10025/smtpd[8534]: connect from localhost[127.0.0.1]
May  6 13:14:53 webserver postfix/10025/smtpd[8534]: EC17D4104F: client=localhost[127.0.0.1]
May  6 13:14:53 webserver postfix/cleanup[8527]: EC17D4104F: message-id=<25a0870ce3e63932e8e2a812dce06a52@_>
May  6 13:14:53 webserver postfix/10025/smtpd[8534]: disconnect from localhost[127.0.0.1] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
May  6 13:14:53 webserver postfix/qmgr[4611]: EC17D4104F: from=<info@dixtysports.gr>, size=1107, nrcpt=1 (queue active)
May  6 13:14:53 webserver amavis[6902]: (06902-02) Passed CLEAN {RelayedInbound}, ORIGINATING [195.201.222.253]:37304 [195.201.222.253] <info@dixtysports.gr> -> <info@Inverse.gr>, Queue-ID: C7AEF40C4D, Message-ID: <25a0870ce3e63932e8e2a812dce06a52@_>, mail_id: N8u_pou7Ws5w, Hits: -, size: 605, queued_as: EC17D4104F, 109 ms
May  6 13:14:53 webserver postfix/amavis/smtp[8532]: C7AEF40C4D: to=<info@Inverse.gr>, relay=127.0.0.1[127.0.0.1]:10026, delay=0.18, delays=0.06/0/0.01/0.11, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as EC17D4104F)
May  6 13:14:53 webserver postfix/qmgr[4611]: C7AEF40C4D: removed
May  6 13:14:54 webserver postfix/smtp[8538]: Untrusted TLS connection established to mail.Inverse.gr[144.76.223.14]:25: TLSv1.2 with cipher DHE-RSA-AES256-GCM-SHA384 (256/256 bits)
May  6 13:14:54 webserver postfix/smtp[8538]: EC17D4104F: to=<info@Inverse.gr>, relay=mail.Inverse.gr[144.76.223.14]:25, delay=0.17, delays=0/0.01/0.05/0.1, dsn=2.0.0, status=sent (250 ok 1525605294 qp 17421)
May  6 13:14:54 webserver postfix/qmgr[4611]: EC17D4104F: removed

For the example above I am using dixtysports.gr as my SMTP host.

If I use webserver.dixtysports.gr, which is the  hostname of my server, I get the following in the WP SMTP Debug

Versions:
WordPress: 4.9.5
WordPress MS: No
PHP: 7.2.3-1ubuntu1
WP Mail SMTP: 1.2.5

Params:
Mailer: smtp
Constants: Yes
ErrorInfo: SMTP connect() failed. https://github.com/PHPMailer/PHPMailer/wiki/Troubleshooting
Host: webserver.dixtysports.gr
Port: 587
SMTPSecure: tls
SMTPAutoTLS: bool(true)
SMTPAuth: bool(true)

Server:
OpenSSL: Yes
SMTP Debug:
2018-05-06 11:30:42    Connection: opening to webserver.dixtysports.gr:587, timeout=300, options=array (
)
2018-05-06 11:30:42    Connection: opened
2018-05-06 11:30:42    SERVER -> CLIENT: 220 webserver.dixtysports.gr ESMTP Postfix
2018-05-06 11:30:42    CLIENT -> SERVER: EHLO _
2018-05-06 11:30:42    SERVER -> CLIENT: 250-webserver.dixtysports.gr
250-PIPELINING
250-SIZE 15728640
250-ETRN
250-STARTTLS
250-ENHANCEDSTATUSCODES
250-8BITMIME
250-DSN
250 SMTPUTF8
2018-05-06 11:30:42    CLIENT -> SERVER: STARTTLS
2018-05-06 11:30:42    SERVER -> CLIENT: 220 2.0.0 Ready to start TLS
2018-05-06 11:30:42    SMTP Error: Could not connect to SMTP host.
2018-05-06 11:30:42    CLIENT -> SERVER: QUIT
2018-05-06 11:30:42    SERVER -> CLIENT:
2018-05-06 11:30:42    SMTP ERROR: QUIT command failed:
2018-05-06 11:30:42    Connection: closed
2018-05-06 11:30:42    SMTP connect() failed. https://github.com/PHPMailer/PHPMailer/wiki/Troubleshooting

For your reference this is my complete postfix main.cf

# --------------------
# INSTALL-TIME CONFIGURATION INFORMATION
#
# location of the Postfix queue. Default is /var/spool/postfix.
queue_directory = /var/spool/postfix

# location of all postXXX commands. Default is /usr/sbin.
command_directory = /usr/sbin

# location of all Postfix daemon programs (i.e. programs listed in the
# master.cf file). This directory must be owned by root.
# Default is /usr/libexec/postfix
daemon_directory = /usr/lib/postfix/sbin

# location of Postfix-writable data files (caches, random numbers).
# This directory must be owned by the mail_owner account (see below).
# Default is /var/lib/postfix.
data_directory = /var/lib/postfix

# owner of the Postfix queue and of most Postfix daemon processes.
# Specify the name of a user account THAT DOES NOT SHARE ITS USER OR GROUP ID
# WITH OTHER ACCOUNTS AND THAT OWNS NO OTHER FILES OR PROCESSES ON THE SYSTEM.
# In particular, don't specify nobody or daemon. PLEASE USE A DEDICATED USER.
# Default is postfix.
mail_owner = postfix

# The following parameters are used when installing a new Postfix version.
#
# sendmail_path: The full pathname of the Postfix sendmail command.
# This is the Sendmail-compatible mail posting interface.
#
sendmail_path = /usr/sbin/sendmail

# newaliases_path: The full pathname of the Postfix newaliases command.
# This is the Sendmail-compatible command to build alias databases.
#
newaliases_path = /usr/bin/newaliases

# full pathname of the Postfix mailq command.  This is the Sendmail-compatible
# mail queue listing command.
mailq_path = /usr/bin/mailq

# group for mail submission and queue management commands.
# This must be a group name with a numerical group ID that is not shared with
# other accounts, not even with the Postfix account.
setgid_group = postdrop

# external command that is executed when a Postfix daemon program is run with
# the -D option.
#
# Use "command .. & sleep 5" so that the debugger can attach before
# the process marches on. If you use an X-based debugger, be sure to
# set up your XAUTHORITY environment variable before starting Postfix.
#
debugger_command =
    PATH=/bin:/usr/bin:/usr/local/bin:/usr/X11R6/bin
    ddd $daemon_directory/$process_name $process_id & sleep 5

debug_peer_level = 2

# --------------------
# CUSTOM SETTINGS
#

# SMTP server response code when recipient or domain not found.
unknown_local_recipient_reject_code = 550

# Do not notify local user.
biff = no

# Disable the rewriting of "site!user" into "user@site".
swap_bangpath = no

# Disable the rewriting of the form "user%domain" to "user@domain".
allow_percent_hack = no

# Allow recipient address start with '-'.
allow_min_user = no

# Disable the SMTP VRFY command. This stops some techniques used to
# harvest email addresses.
disable_vrfy_command = yes

# Enable both IPv4 and/or IPv6: ipv4, ipv6, all.
inet_protocols = all

# Enable all network interfaces.
inet_interfaces = all

#
# TLS settings.
#
# SSL key, certificate, CA
#
smtpd_tls_key_file = /etc/letsencrypt/live/dixtysports.gr/privkey.pem
smtpd_tls_cert_file = /etc/letsencrypt/live/dixtysports.gr/cert.pem
smtpd_tls_CAfile = /etc/letsencrypt/live/dixtysports.gr/chain.pem
smtpd_tls_CApath = /etc/ssl/certs

#
# Disable SSLv2, SSLv3
#
smtpd_tls_protocols = !SSLv2 !SSLv3
smtpd_tls_mandatory_protocols = !SSLv2 !SSLv3
smtp_tls_protocols = !SSLv2 !SSLv3
smtp_tls_mandatory_protocols = !SSLv2 !SSLv3
lmtp_tls_protocols = !SSLv2 !SSLv3
lmtp_tls_mandatory_protocols = !SSLv2 !SSLv3

#
# Fix 'The Logjam Attack'.
#
smtpd_tls_exclude_ciphers = aNULL, eNULL, EXPORT, DES, RC4, MD5, PSK, aECDH, EDH-DSS-DES-CBC3-SHA, EDH-RSA-DES-CDC3-SHA, KRB5-DE5, CBC3-SHA
smtpd_tls_dh512_param_file = /etc/ssl/dh512_param.pem
smtpd_tls_dh1024_param_file = /etc/ssl/dh2048_param.pem

tls_random_source = dev:/dev/urandom

# Log only a summary message on TLS handshake completion — no logging of client
# certificate trust-chain verification errors if client certificate
# verification is not required. With Postfix 2.8 and earlier, log the summary
# message, peer certificate summary information and unconditionally log
# trust-chain verification errors.
smtp_tls_loglevel = 1
smtpd_tls_loglevel = 1

# Opportunistic TLS: announce STARTTLS support to remote SMTP clients, but do
# not require that clients use TLS encryption.
smtpd_tls_security_level = may

# Produce `Received:` message headers that include information about the
# protocol and cipher used, as well as the remote SMTP client CommonName and
# client certificate issuer CommonName.
# This is disabled by default, as the information may be modified in transit
# through other mail servers. Only information that was recorded by the final
# destination can be trusted.
#smtpd_tls_received_header = yes

# Opportunistic TLS, used when Postfix sends email to remote SMTP server.
# Use TLS if this is supported by the remote SMTP server, otherwise use
# plaintext.
# References:
#   - http://www.postfix.org/TLS_README.html#client_tls_may
#   - http://www.postfix.org/postconf.5.html#smtp_tls_security_level
smtp_tls_security_level = may

# Use the same CA file as smtpd.
smtp_tls_CApath = /etc/ssl/certs
smtp_tls_CAfile = $smtpd_tls_CAfile
smtp_tls_note_starttls_offer = yes

# Enable long, non-repeating, queue IDs (queue file names).
# The benefit of non-repeating names is simpler logfile analysis and easier
# queue migration (there is no need to run "postsuper" to change queue file
# names that don't match their message file inode number).
#enable_long_queue_ids = yes

# Reject unlisted sender and recipient
smtpd_reject_unlisted_recipient = yes
smtpd_reject_unlisted_sender = yes

# Header and body checks with PCRE table
header_checks = pcre:/etc/postfix/header_checks
body_checks = pcre:/etc/postfix/body_checks.pcre

# A mechanism to transform commands from remote SMTP clients.
# This is a last-resort tool to work around client commands that break
# interoperability with the Postfix SMTP server. Other uses involve fault
# injection to test Postfix's handling of invalid commands.
# Requires Postfix-2.7+.
#smtpd_command_filter = pcre:/etc/postfix/command_filter.pcre

# HELO restriction
smtpd_helo_required = yes
smtpd_helo_restrictions =
    permit_mynetworks
    permit_sasl_authenticated
    check_helo_access pcre:/etc/postfix/helo_access.pcre
    reject_non_fqdn_helo_hostname
    reject_unknown_helo_hostname

# Sender restrictions
smtpd_sender_restrictions =
    reject_unknown_sender_domain
    reject_non_fqdn_sender
    reject_unlisted_sender
    permit_mynetworks
    permit_sasl_authenticated
    check_sender_access pcre:/etc/postfix/sender_access.pcre

# Recipient restrictions
smtpd_recipient_restrictions =
    reject_non_fqdn_recipient
    reject_unlisted_recipient
    check_policy_service inet:127.0.0.1:7777
    permit_mynetworks
    permit_sasl_authenticated
    reject_unauth_destination

# END-OF-MESSAGE restrictions
smtpd_end_of_data_restrictions =
    check_policy_service inet:127.0.0.1:7777

# Data restrictions
smtpd_data_restrictions = reject_unauth_pipelining

proxy_read_maps = $canonical_maps $lmtp_generic_maps $local_recipient_maps $mydestination $mynetworks $recipient_bcc_maps $recipient_canonical_maps $relay_domains $relay_recipient_maps $relocated_maps $sender_bcc_maps $sender_canonical_maps $smtp_generic_maps $smtpd_sender_login_maps $transport_maps $virtual_alias_domains $virtual_alias_maps $virtual_mailbox_domains $virtual_mailbox_maps $smtpd_sender_restrictions $sender_dependent_relayhost_maps

# Avoid duplicate recipient messages. Default is 'yes'.
enable_original_recipient = no

# Virtual support.
virtual_minimum_uid = 2000
virtual_uid_maps = static:2000
virtual_gid_maps = static:2000
virtual_mailbox_base = /var/vmail

# Do not set virtual_alias_domains.
virtual_alias_domains =

#
# Enable SASL authentication on port 25 and force TLS-encrypted SASL authentication.
# WARNING: NOT RECOMMENDED to enable smtp auth on port 25, all end users should
#          be forced to submit email through port 587 instead.
#
#smtpd_sasl_auth_enable = yes
#smtpd_sasl_security_options = noanonymous
#smtpd_tls_auth_only = yes

# hostname
myhostname = webserver.dixtysports.gr
myorigin = webserver.dixtysports.gr
mydomain = webserver.dixtysports.gr

# trusted SMTP clients which are allowed to relay mail through Postfix.
#
# Note: additional IP addresses/networks listed in mynetworks should be listed
#       in iRedAPD setting 'MYNETWORKS' (in `/opt/iredapd/settings.py`) too.
#       for example:
#
#       MYNETWORKS = ['xx.xx.xx.xx', 'xx.xx.xx.0/24', ...]
#
mynetworks = 127.0.0.1 [::1]

# Accepted local emails
mydestination = $myhostname, localhost, localhost.localdomain

alias_maps = hash:/etc/postfix/aliases
alias_database = hash:/etc/postfix/aliases

# Default message_size_limit.
message_size_limit = 15728640

# The set of characters that can separate a user name from its extension
# (example: user+foo), or a .forward file name from its extension (example:
# .forward+foo).
# Postfix 2.11 and later supports multiple characters.
recipient_delimiter = +

# The time after which the sender receives a copy of the message headers of
# mail that is still queued. Default setting is disabled (0h) by Postfix.
#delay_warning_time = 1h
compatibility_level = 2
#
# Lookup virtual mail accounts
#
transport_maps =
    proxy:mysql:/etc/postfix/mysql/transport_maps_user.cf
    proxy:mysql:/etc/postfix/mysql/transport_maps_maillist.cf
    proxy:mysql:/etc/postfix/mysql/transport_maps_domain.cf

sender_dependent_relayhost_maps =
    proxy:mysql:/etc/postfix/mysql/sender_dependent_relayhost_maps.cf

# Lookup table with the SASL login names that own the sender (MAIL FROM) addresses.
smtpd_sender_login_maps =
    proxy:mysql:/etc/postfix/mysql/sender_login_maps.cf

virtual_mailbox_domains =
    proxy:mysql:/etc/postfix/mysql/virtual_mailbox_domains.cf

relay_domains =
    $mydestination
    proxy:mysql:/etc/postfix/mysql/relay_domains.cf

virtual_mailbox_maps =
    proxy:mysql:/etc/postfix/mysql/virtual_mailbox_maps.cf

virtual_alias_maps =
    proxy:mysql:/etc/postfix/mysql/virtual_alias_maps.cf
    proxy:mysql:/etc/postfix/mysql/domain_alias_maps.cf
    proxy:mysql:/etc/postfix/mysql/catchall_maps.cf
    proxy:mysql:/etc/postfix/mysql/domain_alias_catchall_maps.cf

sender_bcc_maps =
    proxy:mysql:/etc/postfix/mysql/sender_bcc_maps_user.cf
    proxy:mysql:/etc/postfix/mysql/sender_bcc_maps_domain.cf

recipient_bcc_maps =
    proxy:mysql:/etc/postfix/mysql/recipient_bcc_maps_user.cf
    proxy:mysql:/etc/postfix/mysql/recipient_bcc_maps_domain.cf

#
# Postscreen
#
postscreen_greet_action = drop
postscreen_blacklist_action = drop
postscreen_dnsbl_action = drop
postscreen_dnsbl_threshold = 2
postscreen_dnsbl_sites =
    zen.spamhaus.org=127.0.0.[2..11]*3
    b.barracudacentral.org=127.0.0.2*2

postscreen_dnsbl_reply_map = texthash:/etc/postfix/postscreen_dnsbl_reply
postscreen_access_list = permit_mynetworks cidr:/etc/postfix/postscreen_access.cidr

# Require Postfix-2.11+
postscreen_dnsbl_whitelist_threshold = -2
#
# Dovecot SASL support.
#
smtpd_sasl_type = dovecot
smtpd_sasl_path = private/dovecot-auth
virtual_transport = dovecot
dovecot_destination_recipient_limit = 1

#
# mlmmj - mailing list manager
#
mlmmj_destination_recipient_limit = 1

#
# Amavisd + SpamAssassin + ClamAV
#
content_filter = smtp-amavis:[127.0.0.1]:10024

# Concurrency per recipient limit.
smtp-amavis_destination_recipient_limit = 1

4 (edited by romfeo 2018-05-07 18:50:58)

Re: No DKIM from Mua

I have enabled logging in Amavis.
This is the log part of an unsigned email

May  7 12:50:01 webserver postfix/submission/smtpd[11674]: warning: hostname webserver.dixtysports.gr does not resolve to address 195.201.222.253
May  7 12:50:01 webserver postfix/submission/smtpd[11674]: connect from unknown[195.201.222.253]
May  7 12:50:01 webserver postfix/submission/smtpd[11674]: Anonymous TLS connection established from unknown[195.201.222.253]: TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)
May  7 12:50:01 webserver postfix/submission/smtpd[11674]: DC66340C1F: client=unknown[195.201.222.253], sasl_method=LOGIN, sasl_username=info@dixtysports.gr
May  7 12:50:01 webserver postfix/cleanup[11684]: DC66340C1F: message-id=<26d52507b544d0708d5848978feef954@_>
May  7 12:50:01 webserver postfix/qmgr[6993]: DC66340C1F: from=<info@dixtysports.gr>, size=605, nrcpt=1 (queue active)
May  7 12:50:01 webserver postfix/submission/smtpd[11674]: disconnect from unknown[195.201.222.253] ehlo=2 starttls=1 auth=1 mail=1 rcpt=1 data=1 quit=1 commands=8
May  7 12:50:01 webserver amavis[11525]: (11525-01) Net::Server: 2018/05/07-12:50:01 CONNECT TCP Peer: "[127.0.0.1]:35618" Local: "[127.0.0.1]:10026"
May  7 12:50:01 webserver amavis[11525]: idle_proc, hi : was idle, 661081.0 ms, total idle 661.083 s, busy 0.218 s
May  7 12:50:01 webserver amavis[11525]: loaded base policy bank
May  7 12:50:01 webserver amavis[11525]: loaded policy bank "ORIGINATING"
May  7 12:50:01 webserver amavis[11525]: lookup_ip_acl (inet_acl) arr.obj: key="127.0.0.1" matches "127.0.0.1", result=1
May  7 12:50:01 webserver amavis[11525]: process_request: fileno sock=10, STDIN=0, STDOUT=1
May  7 12:50:01 webserver amavis[11525]: get_deadline switch_to_my_time(new request) - deadline in 480.0 s, set to 288.000 s
May  7 12:50:01 webserver amavis[11525]: prolong_timer switch_to_my_time(new request): timer 288, was 0, deadline in 480.0 s
May  7 12:50:01 webserver amavis[11525]: process_request: suggested_protocol="" on a TCP socket
May  7 12:50:01 webserver amavis[11525]: (11525-02) SMTP> 220 [127.0.0.1] ESMTP amavisd-new service ready
May  7 12:50:01 webserver amavis[11525]: (11525-02) switch_to_client_time 480 s, smtp response sent
May  7 12:50:01 webserver amavis[11525]: (11525-02) idle_proc, 4: was busy, 1.0 ms, total idle 661.083 s, busy 0.219 s
May  7 12:50:01 webserver amavis[11525]: (11525-02) smtp readline: read 31 bytes, new size: 31
May  7 12:50:01 webserver amavis[11525]: (11525-02) idle_proc, 5: was idle, 1.1 ms, total idle 661.084 s, busy 0.219 s
May  7 12:50:01 webserver amavis[11525]: (11525-02) SMTP< EHLO webserver.dixtysports.gr\r\n
May  7 12:50:01 webserver amavis[11525]: (11525-02) get_deadline switch_to_my_time(rx SMTP EHLO) - deadline in 480.0 s, set to 288.000 s
May  7 12:50:01 webserver amavis[11525]: (11525-02) prolong_timer switch_to_my_time(rx SMTP EHLO): timer 288, was 480, deadline in 480.0 s
May  7 12:50:01 webserver amavis[11525]: (11525-02) ESMTP> 250-[127.0.0.1]
May  7 12:50:01 webserver amavis[11525]: (11525-02) ESMTP> 250-VRFY
May  7 12:50:01 webserver amavis[11525]: (11525-02) ESMTP> 250-PIPELINING
May  7 12:50:01 webserver amavis[11525]: (11525-02) ESMTP> 250-SIZE
May  7 12:50:01 webserver amavis[11525]: (11525-02) ESMTP> 250-ENHANCEDSTATUSCODES
May  7 12:50:01 webserver amavis[11525]: (11525-02) ESMTP> 250-DSN
May  7 12:50:01 webserver amavis[11525]: (11525-02) ESMTP> 250 XFORWARD NAME ADDR PORT PROTO HELO IDENT SOURCE
May  7 12:50:01 webserver amavis[11525]: (11525-02) switch_to_client_time 480 s, smtp response sent
May  7 12:50:01 webserver amavis[11525]: (11525-02) idle_proc, 6: was busy, 1.7 ms, total idle 661.084 s, busy 0.221 s
May  7 12:50:01 webserver amavis[11525]: (11525-02) smtp readline: read 196 bytes, new size: 196
May  7 12:50:01 webserver amavis[11525]: (11525-02) idle_proc, 5: was idle, 0.4 ms, total idle 661.084 s, busy 0.221 s
May  7 12:50:01 webserver amavis[11525]: (11525-02) ESMTP< XFORWARD ADDR=195.201.222.253 PORT=48378\r\n
May  7 12:50:01 webserver amavis[11525]: (11525-02) get_deadline switch_to_my_time(rx SMTP XFORWARD) - deadline in 480.0 s, set to 288.000 s
May  7 12:50:01 webserver amavis[11525]: (11525-02) prolong_timer switch_to_my_time(rx SMTP XFORWARD): timer 288, was 480, deadline in 480.0 s
May  7 12:50:01 webserver amavis[11525]: (11525-02) ESMTP> 250 2.5.0 Ok XFORWARD
May  7 12:50:01 webserver amavis[11525]: (11525-02) switch_to_client_time 480 s, smtp response sent
May  7 12:50:01 webserver amavis[11525]: (11525-02) idle_proc, 6: was busy, 0.9 ms, total idle 661.084 s, busy 0.222 s
May  7 12:50:01 webserver amavis[11525]: (11525-02) idle_proc, 5: was idle, 0.2 ms, total idle 661.085 s, busy 0.222 s
May  7 12:50:01 webserver amavis[11525]: (11525-02) ESMTP< XFORWARD PROTO=ESMTP HELO=_ IDENT=DC66340C1F SOURCE=LOCAL\r\n
May  7 12:50:01 webserver amavis[11525]: (11525-02) get_deadline switch_to_my_time(rx SMTP XFORWARD) - deadline in 480.0 s, set to 288.000 s
May  7 12:50:01 webserver amavis[11525]: (11525-02) prolong_timer switch_to_my_time(rx SMTP XFORWARD): timer 288, was 480, deadline in 480.0 s
May  7 12:50:01 webserver amavis[11525]: (11525-02) ESMTP> 250 2.5.0 Ok XFORWARD
May  7 12:50:01 webserver amavis[11525]: (11525-02) switch_to_client_time 480 s, smtp response sent
May  7 12:50:01 webserver amavis[11525]: (11525-02) idle_proc, 6: was busy, 0.8 ms, total idle 661.085 s, busy 0.222 s
May  7 12:50:01 webserver amavis[11525]: (11525-02) idle_proc, 5: was idle, 0.1 ms, total idle 661.085 s, busy 0.222 s
May  7 12:50:01 webserver amavis[11525]: (11525-02) ESMTP< MAIL FROM:<info@dixtysports.gr>\r\n
May  7 12:50:01 webserver amavis[11525]: (11525-02) get_deadline switch_to_my_time(rx SMTP MAIL) - deadline in 480.0 s, set to 288.000 s
May  7 12:50:01 webserver amavis[11525]: (11525-02) prolong_timer switch_to_my_time(rx SMTP MAIL): timer 288, was 480, deadline in 480.0 s
May  7 12:50:01 webserver amavis[11525]: (11525-02) check_mail_begin_task: task_count=2
May  7 12:50:01 webserver amavis[11525]: (11525-02) lookup_ip_acl (client_ipaddr_policy) arr.obj: key="195.201.222.253", no match
May  7 12:50:01 webserver amavis[11525]: (11525-02) lookup [debug_sender] => undef, "info@dixtysports.gr" does not match
May  7 12:50:01 webserver amavis[11525]: (11525-02) ESMTP> 250 2.1.0 Sender <info@dixtysports.gr> OK
May  7 12:50:01 webserver amavis[11525]: (11525-02) switch_to_client_time 480 s, smtp response sent
May  7 12:50:01 webserver amavis[11525]: (11525-02) idle_proc, 6: was busy, 1.7 ms, total idle 661.085 s, busy 0.224 s
May  7 12:50:02 webserver amavis[11525]: (11525-02) idle_proc, 5: was idle, 0.1 ms, total idle 661.085 s, busy 0.224 s
May  7 12:50:02 webserver amavis[11525]: (11525-02) ESMTP< RCPT TO:<info@inverse.gr> ORCPT=rfc822;info@inverse.gr\r\n
May  7 12:50:02 webserver amavis[11525]: (11525-02) get_deadline switch_to_my_time(rx SMTP RCPT) - deadline in 480.0 s, set to 288.000 s
May  7 12:50:02 webserver amavis[11525]: (11525-02) prolong_timer switch_to_my_time(rx SMTP RCPT): timer 288, was 480, deadline in 480.0 s
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup => undef, "info@inverse.gr", no lookup tables
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup: (scalar) matches, result="1"
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup [local_domains] => true,  "info@inverse.gr" matches, result="1", matching_key="(constant:1)"
May  7 12:50:02 webserver amavis[11525]: (11525-02) query_keys: info@inverse.gr, info, @inverse.gr, @.inverse.gr, @.gr, @.
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup_sql sel_policy "info@inverse.gr", query args: [info@inverse.gr,-3], [info,-3], [@inverse.gr,-3], [@.inverse.gr,-3], [@.gr,-3], [@.,-3]
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup_sql select: SELECT users.*, policy.*, users.id FROM users LEFT JOIN policy ON users.policy_id=policy.id WHERE users.email IN (?,?,?,?,?,?) ORDER BY users.priority DESC
May  7 12:50:02 webserver amavis[11525]: (11525-02) sql begin, nontransaction
May  7 12:50:02 webserver amavis[11525]: (11525-02) sql: preparing and executing (6 args): SELECT users.*, policy.*, users.id FROM users LEFT JOIN policy ON users.policy_id=policy.id WHERE users.email IN (?,?,?,?,?,?) ORDER BY users.priority DESC
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup_sql: "info@inverse.gr" matches catchall, local=>undef
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup_sql(info@inverse.gr) matches, result=(id=>"1", priority=>"0", policy_id=>"1", email=>"@.", fullname=>-, id=>"1", policy_name=>"@.", virus_lover=>"N", spam_lover=>"Y", unchecked_lover=>-, banned_files_lover=>"Y", bad_header_lover=>"Y", bypass_virus_checks=>"N", bypass_spam_checks=>"N", bypass_banned_checks=>"N", bypass_header_checks=>"N", virus_quarantine_to=>"virus-quarantine", spam_quarantine_to=>"", banned_quarantine_to=>"", unchecked_quarantine_to=>-, bad_header_quarantine_to=>"", clean_quarantine_to=>-, archive_quarantine_to=>-, spam_tag_level=>-, spam_tag2_level=>-, spam_tag3_level=>-, spam_kill_level=>-, spam_dsn_cutoff_level=>-, spam_quarantine_cutoff_level=>-, addr_extension_virus=>-, addr_extension_spam=>-, addr_extension_banned=>-, addr_extension_bad_header=>-, warnvirusrecip=>-, warnbannedrecip=>-, warnbadhrecip=>-, newvirus_admin=>-, virus_admin=>-, banned_admin=>-, bad_header_admin=>-, spam_admin=>-, spam_subject_tag=>-, spam_subjec...
May  7 12:50:02 webserver amavis[11525]: (11525-02) ...t_tag2=>-, spam_subject_tag3=>-, message_size_limit=>-, banned_rulenames=>-, disclaimer_options=>-, forward_method=>-, sa_userconf=>-, sa_username=>-, id=>"1", local=>-)
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup_sql_field(message_size_limit) rec=0, "info@inverse.gr" result: undef
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup [message_size_limit] => undef, "info@inverse.gr" does not match
May  7 12:50:02 webserver amavis[11525]: (11525-02) ESMTP> 250 2.1.5 Recipient <info@inverse.gr> OK
May  7 12:50:02 webserver amavis[11525]: (11525-02) switch_to_client_time 480 s, smtp response sent
May  7 12:50:02 webserver amavis[11525]: (11525-02) idle_proc, 6: was busy, 6.6 ms, total idle 661.085 s, busy 0.231 s
May  7 12:50:02 webserver amavis[11525]: (11525-02) idle_proc, 5: was idle, 0.1 ms, total idle 661.085 s, busy 0.231 s
May  7 12:50:02 webserver amavis[11525]: (11525-02) ESMTP< DATA\r\n
May  7 12:50:02 webserver amavis[11525]: (11525-02) get_deadline switch_to_my_time(rx SMTP DATA) - deadline in 480.0 s, set to 288.000 s
May  7 12:50:02 webserver amavis[11525]: (11525-02) prolong_timer switch_to_my_time(rx SMTP DATA): timer 288, was 480, deadline in 480.0 s
May  7 12:50:02 webserver amavis[11525]: (11525-02) ESMTP [127.0.0.1]:10026 /var/lib/amavis/tmp/amavis-20180507T123900-11525-EWy74SoL: <info@dixtysports.gr> -> <info@inverse.gr> Received: from webserver.dixtysports.gr ([127.0.0.1]) by webserver.dixtysports.gr (webserver.dixtysports.gr [127.0.0.1]) (amavisd-new, port 10026) with ESMTP for <info@inverse.gr>; Mon,  7 May 2018 12:50:01 +0200 (CEST)
May  7 12:50:02 webserver amavis[11525]: (11525-02) ESMTP> 354 End data with <CR><LF>.<CR><LF>
May  7 12:50:02 webserver amavis[11525]: (11525-02) switch_to_client_time 480 s, smtp response sent
May  7 12:50:02 webserver amavis[11525]: (11525-02) switch_to_client_time 480 s, receiving data
May  7 12:50:02 webserver amavis[11525]: (11525-02) smtp copy: read 614 bytes into buffer, new size: 614
May  7 12:50:02 webserver amavis[11525]: (11525-02) smtp copy: 6 bytes still buffered at end
May  7 12:50:02 webserver amavis[11525]: (11525-02) get_deadline switch_to_my_time(rx data-end) - deadline in 480.0 s, set to 288.000 s
May  7 12:50:02 webserver amavis[11525]: (11525-02) prolong_timer switch_to_my_time(rx data-end): timer 288, was 480, deadline in 480.0 s
May  7 12:50:02 webserver amavis[11525]: (11525-02) ESMTP< .<CR><LF>
May  7 12:50:02 webserver amavis[11525]: (11525-02) message size set to 605
May  7 12:50:02 webserver amavis[11525]: (11525-02) smtp connection cache, dt: 661.1, state: 0
May  7 12:50:02 webserver amavis[11525]: (11525-02) get_deadline get_body_digest - deadline in 480.0 s, set to 30.000 s
May  7 12:50:02 webserver amavis[11525]: (11525-02) get_deadline digest_pre - deadline in 480.0 s, set to 288.000 s
May  7 12:50:02 webserver amavis[11525]: (11525-02) prolong_timer digest_pre: timer 288, was 288, deadline in 480.0 s
May  7 12:50:02 webserver amavis[11525]: (11525-02) get_body_digest: reading header section from memory
May  7 12:50:02 webserver amavis[11525]: (11525-02) get_body_digest: feeding header section to DKIM verifier
May  7 12:50:02 webserver amavis[11525]: (11525-02) get_body_digest: sending h/b separator to DKIM
May  7 12:50:02 webserver amavis[11525]: (11525-02) get_deadline digest_hdr - deadline in 480.0 s, set to 288.000 s
May  7 12:50:02 webserver amavis[11525]: (11525-02) prolong_timer digest_hdr: timer 288, was 288, deadline in 480.0 s
May  7 12:50:02 webserver amavis[11525]: (11525-02) get_body_digest: reading mail body from memory, 0 DKIM signatures
May  7 12:50:02 webserver amavis[11525]: (11525-02) get_deadline digest_body - deadline in 480.0 s, set to 288.000 s
May  7 12:50:02 webserver amavis[11525]: (11525-02) prolong_timer digest_body: timer 288, was 288, deadline in 480.0 s
May  7 12:50:02 webserver amavis[11525]: (11525-02) get_body_digest: message size 605, header+sep 508, body 97
May  7 12:50:02 webserver amavis[11525]: (11525-02) body type (8bit-MIMEtransport): unlabeled, good (h=0, b=0)
May  7 12:50:02 webserver amavis[11525]: (11525-02) body hash: 885388618b51c348b1d4803c975a4829
May  7 12:50:02 webserver amavis[11525]: (11525-02) ip_from_received: 195.201.222.253
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup_ip_acl (public_nets) arr.obj: key="127.0.0.1" matches "!127.0.0.0/8", result=0
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup_ip_acl (public_nets) arr.obj: key="195.201.222.253" matches "::ffff:0:0/96", result=1
May  7 12:50:02 webserver amavis[11525]: (11525-02) trace: ESMTP://[127.0.0.1]:35618 < ESMTPSA://[195.201.222.253]:48378
May  7 12:50:02 webserver amavis[11525]: (11525-02) Original mail size: 605; quota set to: 302500 bytes (fmin=5, fmax=500, qmin=102400, qmax=524288000)
May  7 12:50:02 webserver amavis[11525]: (11525-02) sql begin, nontransaction
May  7 12:50:02 webserver amavis[11525]: (11525-02) sql: executing clause (2 args): SELECT id FROM maddr WHERE partition_tag=? AND email=?
May  7 12:50:02 webserver amavis[11525]: (11525-02) save_info_preliminary XKvnqWHnLssM, sender id: 8, info@dixtysports.gr, exists
May  7 12:50:02 webserver amavis[11525]: (11525-02) sql begin, nontransaction
May  7 12:50:02 webserver amavis[11525]: (11525-02) sql: executing clause (2 args): SELECT id FROM maddr WHERE partition_tag=? AND email=?
May  7 12:50:02 webserver amavis[11525]: (11525-02) orcpt_encode rfc822, info@inverse.gr, smtputf8
May  7 12:50:02 webserver amavis[11525]: (11525-02) save_info_preliminary XKvnqWHnLssM, recip id: 10, info@inverse.gr (ORCPT rfc822;info@inverse.gr), exists
May  7 12:50:02 webserver amavis[11525]: (11525-02) sql begin transaction
May  7 12:50:02 webserver amavis[11525]: (11525-02) sql: executing clause (11 args): INSERT INTO msgs (partition_tag, mail_id, secret_id, am_id, time_num, time_iso, sid, policy, client_addr, size, host) VALUES (?,?,?,?,?,?,?,?,?,?,?)
May  7 12:50:02 webserver amavis[11525]: (11525-02) sql commit
May  7 12:50:02 webserver amavis[11525]: (11525-02) Checking: XKvnqWHnLssM ORIGINATING [195.201.222.253] <info@dixtysports.gr> -> <info@inverse.gr>
May  7 12:50:02 webserver amavis[11525]: (11525-02) 2822.From: <info@dixtysports.gr>
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup_sql_field(local) rec=0, "info@inverse.gr" result: undef
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup: (scalar) matches, result="1"
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup [local_domains] => true,  "info@inverse.gr" matches, result="1", matching_key="(constant:1)"
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup_sql_field(bypass_virus_checks) rec=0, "info@inverse.gr" result: "0"
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup [bypass_virus_checks] => false, "info@inverse.gr" matches, result="0", matching_key="/cached/"
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup_sql_field(bypass_banned_checks) rec=0, "info@inverse.gr" result: "0"
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup [bypass_banned_checks] => false, "info@inverse.gr" matches, result="0", matching_key="/cached/"
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup_sql_field(bypass_spam_checks) rec=0, "info@inverse.gr" result: "0"
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup [bypass_spam_checks] => false, "info@inverse.gr" matches, result="0", matching_key="/cached/"
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup_sql_field(id) rec=0, "info@inverse.gr" result: "1"
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup [users.id], 1 matches for "info@inverse.gr", results: "/cached/"=>"1"
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup_sql_field(policy_id) rec=0, "info@inverse.gr" result: "1"
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup [users.policy_id] => true,  "info@inverse.gr" matches, result="1", matching_key="/cached/"
May  7 12:50:02 webserver amavis[11525]: (11525-02) Extracting mime components from a string
May  7 12:50:02 webserver amavis[11525]: (11525-02) Issued a new file name: p001
May  7 12:50:02 webserver amavis[11525]: (11525-02) Charging 95 bytes to remaining quota 302500 (out of 302500, (0%)) - by mime_decode
May  7 12:50:02 webserver amavis[11525]: (11525-02) p001 1 Content-Type: text/plain, 7bit, size: 95, SHA1 digest: c6ded871f238030c9261b5af2e5c0261cf72413a
May  7 12:50:02 webserver amavis[11525]: (11525-02) get_deadline mime_decode - deadline in 480.0 s, set to 288.000 s
May  7 12:50:02 webserver amavis[11525]: (11525-02) prolong_timer mime_decode: timer 288, was 288, deadline in 480.0 s
May  7 12:50:02 webserver amavis[11525]: (11525-02) get_deadline mime_decode-1 - deadline in 480.0 s, set to 288.000 s
May  7 12:50:02 webserver amavis[11525]: (11525-02) prolong_timer mime_decode-1: timer 288, was 288, deadline in 480.0 s
May  7 12:50:02 webserver amavis[11525]: (11525-02) decode_parts: level=1, #parts=1 : p001
May  7 12:50:02 webserver amavis[11525]: (11525-02) running file(1) on 1 files, arglist size 18
May  7 12:50:02 webserver amavis[11525]: (11525-02) run_command: [11690] /usr/bin/file p001 </dev/null 2>&1
May  7 12:50:02 webserver amavis[11690]: (11525-02) open_on_specific_fd: target fd0 closing, to become < /dev/null
May  7 12:50:02 webserver amavis[11690]: (11525-02) open_on_specific_fd: target fd1 closing, to become (65) &=14
May  7 12:50:02 webserver amavis[11690]: (11525-02) open_on_specific_fd: target fd1 dup2 from fd14 (65) &=14
May  7 12:50:02 webserver amavis[11690]: (11525-02) open_on_specific_fd: source fd14 closed
May  7 12:50:02 webserver amavis[11690]: (11525-02) open_on_specific_fd: target fd2 closing, to become (65) &1
May  7 12:50:02 webserver amavis[11690]: (11525-02) open_on_specific_fd: target fd2 dup2 from fd1 (65) &1
May  7 12:50:02 webserver amavis[11525]: (11525-02) result line from file(1): p001: ASCII text\n
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup_re("ASCII text") matches key "(?^i:^(ASCII|text)\\b)", result="asc"
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup [map_full_type_to_short_type] => true,  "ASCII text" matches, result="asc", matching_key="(?^i:^(ASCII|text)\\b)"
May  7 12:50:02 webserver amavis[11525]: (11525-02) File-type of p001: ASCII text; (asc)
May  7 12:50:02 webserver amavis[11525]: (11525-02) decompose_part: p001 - atomic
May  7 12:50:02 webserver amavis[11525]: (11525-02) get_deadline parts_decode - deadline in 479.9 s, set to 288.000 s
May  7 12:50:02 webserver amavis[11525]: (11525-02) prolong_timer parts_decode: timer 288, was 288, deadline in 479.9 s
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup_sql_field(bypass_header_checks) rec=0, "info@inverse.gr" result: "0"
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup [bypass_header_checks] => false, "info@inverse.gr" matches, result="0", matching_key="/cached/"
May  7 12:50:02 webserver amavis[11525]: (11525-02) check_header: 0, OK
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup_sql_field(bypass_header_checks) rec=0, "info@inverse.gr" result: "0"
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup [bypass_header_checks] => false, "info@inverse.gr" matches, result="0", matching_key="/cached/"
May  7 12:50:02 webserver amavis[11525]: (11525-02) Checking for banned types and filenames
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup_sql_field(banned_rulenames) rec=0, "info@inverse.gr" result: undef
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup: (scalar) matches, result="DEFAULT"
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup [banned_filename], 1 matches for "info@inverse.gr", results: "(constant:DEFAULT)"=>"DEFAULT"
May  7 12:50:02 webserver amavis[11525]: (11525-02) collect banned table[0]: info@inverse.gr, tables: DEFAULT=>Amavis::Lookup::RE=ARRAY(0x55b6dac70da0)
May  7 12:50:02 webserver amavis[11525]: (11525-02) starting banned checks - traversing message structure tree
May  7 12:50:02 webserver amavis[11525]: (11525-02) check_for_banned (p001) text/plain,.asc
May  7 12:50:02 webserver amavis[11525]: (11525-02) doing banned check for info@inverse.gr on text/plain,.asc
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup_re(["text/plain",".asc"]), no matches
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup [check_bann:info@inverse.gr] => undef, ["text/plain",".asc"] does not match
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup_re("P=p001\tL=1\tM=text/plain\tT=asc"), no matches
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup [banned_namepath_re] => undef, "P=p001\tL=1\tM=text/plain\tT=asc" does not match
May  7 12:50:02 webserver amavis[11525]: (11525-02) p.path info@inverse.gr: "P=p001,L=1,M=text/plain,T=asc"
May  7 12:50:02 webserver amavis[11525]: (11525-02) banned check: any=0, all=N (1)
May  7 12:50:02 webserver amavis[11525]: (11525-02) no anti-virus code loaded, skipping virus_scan
May  7 12:50:02 webserver amavis[11525]: (11525-02) no anti-spam code loaded, skipping spam_scan
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup_sql_field(spam_tag_level) rec=0, "info@inverse.gr" result: undef
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup: (scalar) matches, result="2"
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup [spam_tag_level] => true,  "info@inverse.gr" matches, result="2", matching_key="(constant:2)"
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup_sql_field(spam_tag2_level) rec=0, "info@inverse.gr" result: undef
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup: (scalar) matches, result="6.2"
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup [spam_tag2_level] => true,  "info@inverse.gr" matches, result="6.2", matching_key="(constant:6.2)"
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup_sql_field(spam_tag3_level) rec=0, "info@inverse.gr" result: undef
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup [spam_tag3_level] => undef, "info@inverse.gr" does not match
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup_sql_field(spam_kill_level) rec=0, "info@inverse.gr" result: undef
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup: (scalar) matches, result="6.9"
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup [spam_kill_level] => true,  "info@inverse.gr" matches, result="6.9", matching_key="(constant:6.9)"
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup_sql_field(message_size_limit) rec=0, "info@inverse.gr" result: undef
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup [message_size_limit] => undef, "info@inverse.gr" does not match
May  7 12:50:02 webserver amavis[11525]: (11525-02) final_destiny (ccat=0) is PASS, recip info@inverse.gr
May  7 12:50:02 webserver amavis[11525]: (11525-02) final_destiny PASS, recip info@inverse.gr
May  7 12:50:02 webserver amavis[11525]: (11525-02) do_notify_and_quar: ccat=Clean (1,0) ("1":Clean, "0":CatchAll) ccat_block=(), qar_mth=
May  7 12:50:02 webserver amavis[11525]: (11525-02) do_notify_and_quarantine: not quarantining, q_method off
May  7 12:50:02 webserver amavis[11525]: (11525-02) skip admin notification, no administrators
May  7 12:50:02 webserver amavis[11525]: (11525-02) do_notify_and_quarantine - done
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup_sql_field(forward_method) rec=0, "info@inverse.gr" result: undef
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup: (opaque) matches, result="smtp:[127.0.0.1]:10025"
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup [forward_method] => true,  "info@inverse.gr" matches, result="smtp:[127.0.0.1]:10025", matching_key="(opaque:smtp:[127.0.0.1]:10025)"
May  7 12:50:02 webserver amavis[11525]: (11525-02) delivery method is 1, recips: info@inverse.gr
May  7 12:50:02 webserver amavis[11525]: (11525-02) headers CLUSTERING: NEW CLUSTER <info@inverse.gr>: score=x, tag=0, tag2=0, local=1, bl=, s=, mangle=
May  7 12:50:02 webserver amavis[11525]: (11525-02) header encoded (all-ASCII): X-Virus-Scanned: Debian amavisd-new at webserver.dixtysports.gr
May  7 12:50:02 webserver amavis[11525]: (11525-02) header: X-Virus-Scanned: Debian amavisd-new at webserver.dixtysports.gr\n
May  7 12:50:02 webserver amavis[11525]: (11525-02) header encoded (all-ASCII): Received: from webserver.dixtysports.gr ([127.0.0.1])\n by webserver.dixtysports.gr (webserver.dixtysports.gr [127.0.0.1]) (amavisd-new, port 10026)\n with ESMTP\n id XKvnqWHnLssM\n for <info@inverse.gr>;\n Mon,  7 May 2018 12:50:01 +0200 (CEST)
May  7 12:50:02 webserver amavis[11525]: (11525-02) header: Received: from webserver.dixtysports.gr ([127.0.0.1])\n\tby webserver.dixtysports.gr (webserver.dixtysports.gr [127.0.0.1]) (amavisd-new, port 10026)\n\twith ESMTP id XKvnqWHnLssM for <info@inverse.gr>;\n\tMon,  7 May 2018 12:50:01 +0200 (CEST)\n
May  7 12:50:02 webserver amavis[11525]: (11525-02) headers CLUSTERING: done all 1 recips in one go
May  7 12:50:02 webserver amavis[11525]: (11525-02) dkim: not signing mail which is not originating from our site
May  7 12:50:02 webserver amavis[11525]: (11525-02) about to connect to smtp:[127.0.0.1]:10025, XKvnqWHnLssM FWD from <info@dixtysports.gr> -> <info@inverse.gr>
May  7 12:50:02 webserver amavis[11525]: (11525-02) get_deadline fwd_init - deadline in 479.9 s, set to 480.000 s
May  7 12:50:02 webserver amavis[11525]: (11525-02) smtp session: setting up a new session
May  7 12:50:02 webserver amavis[11525]: (11525-02) establish_or_refresh, state: down
May  7 12:50:02 webserver amavis[11525]: (11525-02) new socket using IO::Socket::IP to [127.0.0.1]:10025, timeout 35
May  7 12:50:02 webserver amavis[11525]: (11525-02) connected to [127.0.0.1]:10025 successfully
May  7 12:50:02 webserver amavis[11525]: (11525-02) rw_loop: needline=1, flush=0, wr=0, timeout=35
May  7 12:50:02 webserver postfix/10025/smtpd[11691]: connect from ip6-localhost[127.0.0.1]
May  7 12:50:02 webserver amavis[11525]: (11525-02) rw_loop: receiving
May  7 12:50:02 webserver amavis[11525]: (11525-02) rw_loop read 44 chars< 220 webserver.dixtysports.gr ESMTP Postfix\r\n
May  7 12:50:02 webserver amavis[11525]: (11525-02) smtp greeting: 220 webserver.dixtysports.gr ESMTP Postfix, dt: 10.7 ms
May  7 12:50:02 webserver amavis[11525]: (11525-02) smtp cmd> EHLO webserver.dixtysports.gr
May  7 12:50:02 webserver amavis[11525]: (11525-02) rw_loop: needline=0, flush=1, wr=1, timeout=300
May  7 12:50:02 webserver amavis[11525]: (11525-02) rw_loop: sending 31 chars
May  7 12:50:02 webserver amavis[11525]: (11525-02) rw_loop sent 31> EHLO webserver.dixtysports.gr\r\n
May  7 12:50:02 webserver amavis[11525]: (11525-02) rw_loop: needline=1, flush=0, wr=0, timeout=300
May  7 12:50:02 webserver amavis[11525]: (11525-02) rw_loop: receiving
May  7 12:50:02 webserver amavis[11525]: (11525-02) rw_loop read 137 chars< 250-webserver.dixtysports.gr\r\n250-PIPELINING\r\n250-SIZE 15728640\r\n250-ETRN\r\n250-ENHANCEDSTATUSCODES\r\n250-8BITMIME\r\n250-DSN\r\n250 SMTPUTF8\r\n
May  7 12:50:02 webserver amavis[11525]: (11525-02) smtp resp to EHLO: 250 webserver.dixtysports.gr\nPIPELINING\nSIZE 15728640\nETRN\nENHANCEDSTATUSCODES\n8BITMIME\nDSN\nSMTPUTF8
May  7 12:50:02 webserver amavis[11525]: (11525-02) tls active=0, capable=, sec_level=0
May  7 12:50:02 webserver amavis[11525]: (11525-02) Remote host presents itself as: webserver.dixtysports.gr, handles DSN, PIPELINING, 8BITMIME, SMTPUTF8
May  7 12:50:02 webserver amavis[11525]: (11525-02) AUTH not needed, user='', MTA offers ''
May  7 12:50:02 webserver amavis[11525]: (11525-02) smtp cmd> MAIL FROM:<info@dixtysports.gr> BODY=7BIT
May  7 12:50:02 webserver amavis[11525]: (11525-02) orcpt_encode rfc822, info@inverse.gr, encode_for_smtp
May  7 12:50:02 webserver amavis[11525]: (11525-02) smtp cmd> RCPT TO:<info@inverse.gr> ORCPT=rfc822;info@inverse.gr
May  7 12:50:02 webserver amavis[11525]: (11525-02) smtp cmd> DATA
May  7 12:50:02 webserver amavis[11525]: (11525-02) rw_loop: needline=0, flush=1, wr=1, timeout=120
May  7 12:50:02 webserver amavis[11525]: (11525-02) rw_loop: sending 105 chars
May  7 12:50:02 webserver amavis[11525]: (11525-02) rw_loop sent 105> MAIL FROM:<info@dixtysports.gr> BODY=7BIT\r\nRCPT TO:<info@inverse.gr> ORCPT=rfc822;info@inverse.gr\r\nDATA\r\n
May  7 12:50:02 webserver amavis[11525]: (11525-02) rw_loop: needline=1, flush=0, wr=0, timeout=300
May  7 12:50:02 webserver postfix/10025/smtpd[11691]: 1DB214106F: client=ip6-localhost[127.0.0.1]
May  7 12:50:02 webserver amavis[11525]: (11525-02) rw_loop: receiving
May  7 12:50:02 webserver amavis[11525]: (11525-02) rw_loop read 65 chars< 250 2.1.0 Ok\r\n250 2.1.5 Ok\r\n354 End data with <CR><LF>.<CR><LF>\r\n
May  7 12:50:02 webserver amavis[11525]: (11525-02) smtp resp to MAIL (pip): 250 2.1.0 Ok
May  7 12:50:02 webserver amavis[11525]: (11525-02) smtp resp to RCPT (pip) (<info@inverse.gr>): 250 2.1.5 Ok
May  7 12:50:02 webserver amavis[11525]: (11525-02) smtp resp to DATA: 354 End data with <CR><LF>.<CR><LF>
May  7 12:50:02 webserver amavis[11525]: (11525-02) write_header: 1, Amavis::Out::SMTP::Protocol=HASH(0x55b6dcc46ed0)
May  7 12:50:02 webserver amavis[11525]: (11525-02) smtp connection_cache disabled, sending QUIT
May  7 12:50:02 webserver amavis[11525]: (11525-02) smtp cmd> QUIT
May  7 12:50:02 webserver amavis[11525]: (11525-02) rw_loop: needline=0, flush=1, wr=1, timeout=479.980
May  7 12:50:02 webserver amavis[11525]: (11525-02) rw_loop: sending 922 chars
May  7 12:50:02 webserver amavis[11525]: (11525-02) rw_loop sent 922> X-Virus-Scanned: Debian amavisd-new at webserver.dixtysports.gr\r\nReceived: from webserver.dixtysports.gr ([127.0.0.1])\r\n\tby webserver.dixtysports.gr (webserver.dixtysports.gr [127.0.0.1]) (amavisd-new [...]
May  7 12:50:02 webserver amavis[11525]: (11525-02) rw_loop: needline=1, flush=0, wr=0, timeout=479.980
May  7 12:50:02 webserver postfix/cleanup[11684]: 1DB214106F: message-id=<26d52507b544d0708d5848978feef954@_>
May  7 12:50:02 webserver postfix/qmgr[6993]: 1DB214106F: from=<info@dixtysports.gr>, size=1111, nrcpt=1 (queue active)
May  7 12:50:02 webserver postfix/10025/smtpd[11691]: disconnect from ip6-localhost[127.0.0.1] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
May  7 12:50:02 webserver amavis[11525]: (11525-02) rw_loop: receiving
May  7 12:50:02 webserver amavis[11525]: (11525-02) rw_loop read 51 chars< 250 2.0.0 Ok: queued as 1DB214106F\r\n221 2.0.0 Bye\r\n
May  7 12:50:02 webserver amavis[11525]: (11525-02) smtp resp to data-dot (<info@inverse.gr>): 250 2.0.0 Ok: queued as 1DB214106F, dt: 3.2 ms
May  7 12:50:02 webserver amavis[11525]: (11525-02) Amavis::Out::SMTP::Session close, disconnecting
May  7 12:50:02 webserver amavis[11525]: (11525-02) get_deadline fwd-end-chkpnt - deadline in 479.9 s, set to 288.000 s
May  7 12:50:02 webserver amavis[11525]: (11525-02) prolong_timer fwd-end-chkpnt: timer 288, was 0, deadline in 479.9 s
May  7 12:50:02 webserver amavis[11525]: (11525-02) XKvnqWHnLssM FWD from <info@dixtysports.gr> -> <info@inverse.gr>, BODY=7BIT 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 1DB214106F
May  7 12:50:02 webserver amavis[11525]: (11525-02) get_deadline forwarding - deadline in 479.9 s, set to 288.000 s
May  7 12:50:02 webserver amavis[11525]: (11525-02) prolong_timer forwarding: timer 288, was 288, deadline in 479.9 s
May  7 12:50:02 webserver amavis[11525]: (11525-02) DSN: sender NOT credible, SA: 0.000, <info@dixtysports.gr>
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup: (scalar) matches, result="10"
May  7 12:50:02 webserver amavis[11525]: (11525-02) lookup [spam_dsn_cutoff_level_bysender] => true,  "info@dixtysports.gr" matches, result="10", matching_key="(constant:10)"
May  7 12:50:02 webserver amavis[11525]: (11525-02) dsn: from MTA 250 NonBlocking:Clean <info@dixtysports.gr> -> <info@inverse.gr>: on_succ=0, on_dly=1, on_fail=1, never=0, warn_sender=, DSN_passed_on=1, destiny=1, mta_resp: "250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 1DB214106F"
May  7 12:50:02 webserver amavis[11525]: (11525-02) DSN: SUCC from MTA 250 NonBlocking:Clean, no DSN requested: <info@dixtysports.gr> -> <info@inverse.gr>
May  7 12:50:02 webserver amavis[11525]: (11525-02) delivery_status_notification: notif 0 bytes, suppressed: no
May  7 12:50:02 webserver amavis[11525]: (11525-02) one_response_for_all, per_recip_capable: N, suppressed: N
May  7 12:50:02 webserver amavis[11525]: (11525-02) one_response_for_all <info@dixtysports.gr>: success, r=0,b=0,d=0, ndn_needed=0, '250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 1DB214106F'
May  7 12:50:02 webserver amavis[11525]: (11525-02) notif=N, suppressed=0, ndn_needed=0, exit=0, 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 1DB214106F
May  7 12:50:02 webserver amavis[11525]: (11525-02) get_deadline delivery-notification - deadline in 479.9 s, set to 288.000 s
May  7 12:50:02 webserver amavis[11525]: (11525-02) prolong_timer delivery-notification: timer 288, was 288, deadline in 479.9 s
May  7 12:50:02 webserver amavis[11525]: (11525-02) status counters: InMsgsStatus{Relayed,RelayedUntagged,RelayedUntaggedInbound}
May  7 12:50:02 webserver amavis[11525]: (11525-02) get_deadline snmp-counters - deadline in 479.9 s, set to 288.000 s
May  7 12:50:02 webserver amavis[11525]: (11525-02) prolong_timer snmp-counters: timer 288, was 288, deadline in 479.9 s
May  7 12:50:02 webserver amavis[11525]: (11525-02) orcpt_encode rfc822, info@inverse.gr, smtputf8
May  7 12:50:02 webserver amavis[11525]: (11525-02) _WARN: Use of uninitialized value in subroutine entry at /usr/lib/x86_64-linux-gnu/perl/5.26/Encode/MIME/Header.pm line 198.
May  7 12:50:02 webserver amavis[11525]: (11525-02) _WARN: Use of uninitialized value in subroutine entry at /usr/lib/x86_64-linux-gnu/perl/5.26/Encode/MIME/Header.pm line 198.
May  7 12:50:02 webserver amavis[11525]: (11525-02) oldest_public_ip_addr_from_received: 195.201.222.253
May  7 12:50:02 webserver amavis[11525]: (11525-02) Passed CLEAN {RelayedInbound}, ORIGINATING [195.201.222.253]:48378 [195.201.222.253] <info@dixtysports.gr> -> <info@inverse.gr>, Queue-ID: DC66340C1F, Message-ID: <26d52507b544d0708d5848978feef954@_>, mail_id: XKvnqWHnLssM, Hits: -, size: 605, queued_as: 1DB214106F, 147 ms
May  7 12:50:02 webserver amavis[11525]: (11525-02) get_deadline main_log_entry - deadline in 479.9 s, set to 288.000 s
May  7 12:50:02 webserver amavis[11525]: (11525-02) prolong_timer main_log_entry: timer 288, was 288, deadline in 479.9 s
May  7 12:50:02 webserver amavis[11525]: (11525-02) sql begin transaction
May  7 12:50:02 webserver amavis[11525]: (11525-02) sql: executing clause (12 args): INSERT INTO msgrcpt (partition_tag, mail_id, rseqnum, rid, is_local, content, ds, rs, bl, wl, bspam_level, smtp_resp) VALUES (?,?,?,?,?,?,?,?,?,?,?,?)
May  7 12:50:02 webserver amavis[11525]: (11525-02) _WARN: Use of uninitialized value in subroutine entry at /usr/lib/x86_64-linux-gnu/perl/5.26/Encode/MIME/Header.pm line 198.
May  7 12:50:02 webserver amavis[11525]: (11525-02) _WARN: Use of uninitialized value in subroutine entry at /usr/lib/x86_64-linux-gnu/perl/5.26/Encode/MIME/Header.pm line 198.
May  7 12:50:02 webserver amavis[11525]: (11525-02) save_info_final XKvnqWHnLssM, orig=N, chks=HB, cont.ty=C, q.type= , q.to=, dsn=N, score=0, Message-ID: <26d52507b544d0708d5848978feef954@_>, From: 'Δίχτυ Sports <info@dixtysports.gr>', Subject: 'WP Mail SMTP: Test email to info@inverse.gr'
May  7 12:50:02 webserver amavis[11525]: (11525-02) sql: executing clause (12 args): UPDATE msgs SET content=?, quar_type=?, quar_loc=?, dsn_sent=?, spam_level=?, message_id=?, from_addr=?, subject=?, client_addr=?, originating=? WHERE partition_tag=? AND mail_id=?
May  7 12:50:02 webserver amavis[11525]: (11525-02) sql commit
May  7 12:50:02 webserver amavis[11525]: (11525-02) get_deadline check done - deadline in 479.9 s, set to 288.000 s
May  7 12:50:02 webserver amavis[11525]: (11525-02) prolong_timer check done: timer 288, was 288, deadline in 479.9 s
May  7 12:50:02 webserver amavis[11525]: (11525-02) sending SMTP response: "250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 1DB214106F"
May  7 12:50:02 webserver amavis[11525]: (11525-02) ESMTP> 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 1DB214106F
May  7 12:50:02 webserver amavis[11525]: (11525-02) switch_to_client_time 480 s, smtp response sent
May  7 12:50:02 webserver amavis[11525]: (11525-02) TempDir::strip: /var/lib/amavis/tmp/amavis-20180507T123900-11525-EWy74SoL
May  7 12:50:02 webserver amavis[11525]: (11525-02) rmdir_recursively: /var/lib/amavis/tmp/amavis-20180507T123900-11525-EWy74SoL/parts, excl=1
May  7 12:50:02 webserver amavis[11525]: (11525-02) size: 605, TIMING [total 157 ms] - SMTP greeting: 0.9 (1%)1, SMTP EHLO: 2.8 (2%)2, SMTP pre-MAIL: 2.9 (2%)4, SMTP MAIL: 1.0 (1%)5, lookup_sql: 6 (4%)9, SMTP pre-DATA-flush: 1.8 (1%)10, SMTP DATA: 30 (19%)29, check_init: 0.2 (0%)29, digest_hdr: 0.6 (0%)30, digest_body_dkim: 0.3 (0%)30, collect_info: 1.5 (1%)31, gen_mail_id: 15 (10%)41, mime_decode: 11 (7%)48, get-file-type1: 24 (15%)63, parts_decode: 0.3 (0%)63, check_header: 1.3 (1%)64, decide_mail_destiny: 7 (5%)69, notif-quar: 0.3 (0%)69, fwd-connect: 15 (10%)79, fwd-mail-pip: 7 (5%)83, fwd-rcpt-pip: 0.1 (0%)83, fwd-data-chkpnt: 0.0 (0%)83, write-header: 0.2 (0%)83, fwd-data-contents: 0.0 (0%)83, fwd-end-chkpnt: 3.8 (2%)86, prepare-dsn: 0.6 (0%)86, report: 1.1 (1%)87, main_log_entry: 11 (7%)94, sql-update: 8 (5%)99, SMTP pre-response: 0.4 (0%)99, SMTP response: 0.4 (0%)100, unlink-1-files: 0.3 (0%)100, rundown: 0.4 (0%)100
May  7 12:50:02 webserver amavis[11525]: (11525-02) idle_proc, 6: was busy, 144.2 ms, total idle 661.085 s, busy 0.375 s
May  7 12:50:02 webserver postfix/amavis/smtp[11689]: DC66340C1F: to=<info@inverse.gr>, relay=127.0.0.1[127.0.0.1]:10026, delay=0.27, delays=0.07/0.04/0.01/0.16, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 1DB214106F)
May  7 12:50:02 webserver amavis[11525]: (11525-02) idle_proc, 5: was idle, 0.5 ms, total idle 661.086 s, busy 0.375 s
May  7 12:50:02 webserver postfix/qmgr[6993]: DC66340C1F: removed
May  7 12:50:02 webserver amavis[11525]: (11525-02) ESMTP< QUIT\r\n
May  7 12:50:02 webserver amavis[11525]: (11525-02) get_deadline switch_to_my_time(rx SMTP QUIT) - deadline in 480.0 s, set to 288.000 s
May  7 12:50:02 webserver amavis[11525]: (11525-02) prolong_timer switch_to_my_time(rx SMTP QUIT): timer 288, was 480, deadline in 480.0 s
May  7 12:50:02 webserver amavis[11525]: (11525-02) ESMTP> 221 2.0.0 [127.0.0.1] amavisd-new closing transmission channel
May  7 12:50:02 webserver amavis[11525]: (11525-02) switch_to_client_time 480 s, smtp response sent
May  7 12:50:02 webserver amavis[11525]: (11525-02) SMTP session over, timer stopped
May  7 12:50:02 webserver amavis[11525]: (11525-02) exiting process_request
May  7 12:50:02 webserver amavis[11525]: (11525-02) idle_proc, bye: was busy, 2.7 ms, total idle 661.086 s, busy 0.378 s
May  7 12:50:02 webserver amavis[11525]: (11525-02) load: 0 %, total idle 661.086 s, busy 0.378 s
May  7 12:50:03 webserver postfix/smtp[11692]: Untrusted TLS connection established to mail.inverse.gr[144.76.223.14]:25: TLSv1.2 with cipher DHE-RSA-AES256-GCM-SHA384 (256/256 bits)
May  7 12:50:03 webserver postfix/smtp[11692]: 1DB214106F: to=<info@inverse.gr>, relay=mail.inverse.gr[144.76.223.14]:25, delay=1.6, delays=0.01/0.03/1.3/0.19, dsn=2.0.0, status=sent (250 ok 1525690203 qp 10464)
May  7 12:50:03 webserver postfix/qmgr[6993]: 1DB214106F: removed

5

Re: No DKIM from Mua

I've solved by patching amavisd-new, as per instructions I found in other threads.
You got a cup of coffee anyway.

6

Re: No DKIM from Mua

Thanks for buying me a coffee. smile