Aug 5, 2024: iRedMail-1.7.1 has been released.

**Kris01** · 2016-07-24 06:10:31

Kris01
Member
Offline

From: Belgium
Registered: 2016-01-03
Posts: 43

Topic: DKIM Signing not valid after 'passed' test

============ Required information ====
- iRedMail version (check /etc/iredmail-release): 0.9.5-1
- Linux/BSD distribution name and version: Ubuntu
- Store mail accounts in which backend (LDAP/MySQL/PGSQL): mysql
- Web server (Apache or Nginx): nginx
- Manage mail accounts with iRedAdmin-Pro? yes
- Related log if you're reporting an issue:
====

I got my dkim working :-)

By running this command "amavisd-new testkeys"

I have these sites to verify this:

Know i have this .net library that i work with.
I can send emails no problems so far.

But my mails are not DKIM signed. :-( Even when i send mails with MS outlook.

These are my questions:

When my test returns => pass for each domain, does this mean that all my outgoing mails are dkim signed? (for each domain specific)
Does my email client needs to have specific settings changed ?
How can i access my .pem files ? because the directory returns "Access diened" with sudo previleges

----

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

**Kris01** · 2016-07-24 06:18:54

Kris01
Member
Offline

From: Belgium
Registered: 2016-01-03
Posts: 43

Re: DKIM Signing not valid after 'passed' test

Note: the links are only checking my public keys are available.

**ZhangHuangbin** · 2016-07-26 17:16:34

ZhangHuangbin
iRedMail Developers
Offline

Registered: 2009-05-06
Posts: 31,165

Re: DKIM Signing not valid after 'passed' test

Kris01 wrote:

When my test returns => pass for each domain, does this mean that all my outgoing mails are dkim signed? (for each domain specific)

"pass" means you have valid DKIM key on your server, and public key in DNS. It does NOT mean your email is signed.
Enabling SMTP AUTH in your mail client should be enough to get your (outgoing) email signed.

Kris01 wrote:

Does my email client needs to have specific settings changed ?

No.

Kris01 wrote:

How can i access my .pem files ? because the directory returns "Access diened" with sudo previleges

You do NOT need to access it at anytime.

**Kris01** · 2016-07-27 06:51:35

Kris01
Member
Offline

From: Belgium
Registered: 2016-01-03
Posts: 43

Re: DKIM Signing not valid after 'passed' test

Please look this link https://www.mail-tester.com/web-xdEdvV

Here they analyse my email content.

In the 3e block you wil see that my mails are not dkim signed.

(And i am SMTP authenticated, otherwise i can not send my email.)

**ZhangHuangbin** · 2016-07-27 09:44:09

ZhangHuangbin
iRedMail Developers
Offline

Registered: 2009-05-06
Posts: 31,165

Re: DKIM Signing not valid after 'passed' test

Please turn on debug mode in Amavisd to see why it doesn't sign DKIM key in the mail header.
http://www.iredmail.org/docs/debug.amavisd.html

Also, please show us full content of file /etc/postfix/master.cf, and output of command "postconf -n".

**Kris01** · 2016-07-28 01:56:53

Kris01
Member
Offline

From: Belgium
Registered: 2016-01-03
Posts: 43

Re: DKIM Signing not valid after 'passed' test

I turned on debug mode in amavisd.

This is the content of /etc/postfix/master.cf

#
# Postfix master process configuration file.  For details on the format
# of the file, see the master(5) manual page (command: "man 5 master" or
# on-line: http://www.postfix.org/master.5.html).
#
# Do not forget to execute "postfix reload" after editing this file.
#
# ==========================================================================
# service type  private unpriv  chroot  wakeup  maxproc command + args
#               (yes)   (yes)   (yes)   (never) (100)
# ==========================================================================
smtp      inet  n       -       -       -       -       smtpd
#smtp      inet  n       -       -       -       1       postscreen
#smtpd     pass  -       -       -       -       -       smtpd
#dnsblog   unix  -       -       -       -       0       dnsblog
#tlsproxy  unix  -       -       -       -       0       tlsproxy
#submission inet n       -       -       -       -       smtpd
#  -o syslog_name=postfix/submission
#  -o smtpd_tls_security_level=encrypt
#  -o smtpd_sasl_auth_enable=yes
#  -o smtpd_reject_unlisted_recipient=no
#  -o smtpd_client_restrictions=$mua_client_restrictions
#  -o smtpd_helo_restrictions=$mua_helo_restrictions
#  -o smtpd_sender_restrictions=$mua_sender_restrictions
#  -o smtpd_recipient_restrictions=
#  -o smtpd_relay_restrictions=permit_sasl_authenticated,reject
#  -o milter_macro_daemon_name=ORIGINATING
#smtps     inet  n       -       -       -       -       smtpd
#  -o syslog_name=postfix/smtps
#  -o smtpd_tls_wrappermode=yes
#  -o smtpd_sasl_auth_enable=yes
#  -o smtpd_reject_unlisted_recipient=no
#  -o smtpd_client_restrictions=$mua_client_restrictions
#  -o smtpd_helo_restrictions=$mua_helo_restrictions
#  -o smtpd_sender_restrictions=$mua_sender_restrictions
#  -o smtpd_recipient_restrictions=
#  -o smtpd_relay_restrictions=permit_sasl_authenticated,reject
#  -o milter_macro_daemon_name=ORIGINATING
#628       inet  n       -       -       -       -       qmqpd
pickup    unix  n       -       -       60      1       pickup
cleanup   unix  n       -       -       -       0       cleanup
qmgr      unix  n       -       n       300     1       qmgr
#qmgr     unix  n       -       n       300     1       oqmgr
tlsmgr    unix  -       -       -       1000?   1       tlsmgr
rewrite   unix  -       -       -       -       -       trivial-rewrite
bounce    unix  -       -       -       -       0       bounce
defer     unix  -       -       -       -       0       bounce
trace     unix  -       -       -       -       0       bounce
verify    unix  -       -       -       -       1       verify
flush     unix  n       -       -       1000?   0       flush
proxymap  unix  -       -       n       -       -       proxymap
proxywrite unix -       -       n       -       1       proxymap
smtp      unix  -       -       -       -       -       smtp
relay     unix  -       -       -       -       -       smtp
#       -o smtp_helo_timeout=5 -o smtp_connect_timeout=5
showq     unix  n       -       -       -       -       showq
error     unix  -       -       -       -       -       error
retry     unix  -       -       -       -       -       error
discard   unix  -       -       -       -       -       discard
local     unix  -       n       n       -       -       local
virtual   unix  -       n       n       -       -       virtual
lmtp      unix  -       -       -       -       -       lmtp
anvil     unix  -       -       -       -       1       anvil
scache    unix  -       -       -       -       1       scache
#
# ====================================================================
# Interfaces to non-Postfix software. Be sure to examine the manual
# pages of the non-Postfix software to find out what options it wants.
#
# Many of the following services use the Postfix pipe(8) delivery
# agent.  See the pipe(8) man page for information about ${recipient}
# and other message envelope options.
# ====================================================================
# ====================================================================
#
# maildrop. See the Postfix MAILDROP_README file for details.
# Also specify in main.cf: maildrop_destination_recipient_limit=1
#
maildrop  unix  -       n       n       -       -       pipe
  flags=DRhu user=vmail argv=/usr/bin/maildrop -d ${recipient}
#
# ====================================================================
#
# Recent Cyrus versions can use the existing "lmtp" master.cf entry.
#
# Specify in cyrus.conf:
#   lmtp    cmd="lmtpd -a" listen="localhost:lmtp" proto=tcp4
#
# Specify in main.cf one or more of the following:
#  mailbox_transport = lmtp:inet:localhost
#  virtual_transport = lmtp:inet:localhost
#
# ====================================================================
#
# Cyrus 2.1.5 (Amos Gouaux)
# Also specify in main.cf: cyrus_destination_recipient_limit=1
#
#cyrus     unix  -       n       n       -       -       pipe
#  user=cyrus argv=/cyrus/bin/deliver -e -r ${sender} -m ${extension} ${user}
#
# ====================================================================
# Old example of delivery via Cyrus.
#
#old-cyrus unix  -       n       n       -       -       pipe
#  flags=R user=cyrus argv=/cyrus/bin/deliver -e -m ${extension} ${user}
#
# ====================================================================
#
# See the Postfix UUCP_README file for configuration details.
#
uucp      unix  -       n       n       -       -       pipe
  flags=Fqhu user=uucp argv=uux -r -n -z -a$sender - $nexthop!rmail ($recipient)
#
# Other external delivery methods.
#
ifmail    unix  -       n       n       -       -       pipe
  flags=F user=ftn argv=/usr/lib/ifmail/ifmail -r $nexthop ($recipient)
bsmtp     unix  -       n       n       -       -       pipe
  flags=Fq. user=bsmtp argv=/usr/lib/bsmtp/bsmtp -t$nexthop -f$sender $recipient
scalemail-backend unix  -       n       n       -       2       pipe
  flags=R user=scalemail argv=/usr/lib/scalemail/bin/scalemail-store ${nexthop} ${user} ${extension}
mailman   unix  -       n       n       -       -       pipe
  flags=FR user=list argv=/usr/lib/mailman/bin/postfix-to-mailman.py
  ${nexthop} ${user}

submission inet n       -       n       -       -       smtpd
  -o smtpd_tls_security_level=encrypt
  -o smtpd_sasl_auth_enable=yes
  -o smtpd_client_restrictions=permit_mynetworks,permit_sasl_authenticated,reject
  -o content_filter=smtp-amavis:[127.0.0.1]:10026

# Use dovecot deliver program as LDA.
dovecot unix    -       n       n       -       -      pipe
    flags=DRh user=vmail:vmail argv=/usr/lib/dovecot/deliver -f ${sender} -d ${user}@${domain} -m ${extension}

smtp-amavis unix -  -   -   -   4  smtp
    -o smtp_data_done_timeout=1200
    -o smtp_send_xforward_command=yes
    -o disable_dns_lookups=yes
    -o max_use=20

127.0.0.1:10025 inet n  -   -   -   -  smtpd
    -o content_filter=
    -o mynetworks_style=host
    -o mynetworks=127.0.0.0/8
    -o local_recipient_maps=
    -o relay_recipient_maps=
    -o strict_rfc821_envelopes=yes
    -o smtp_tls_security_level=none
    -o smtpd_tls_security_level=none
    -o smtpd_restriction_classes=
    -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_end_of_data_restrictions=
    -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_address_mappings

and output of postconf -n

alias_database = hash:/etc/postfix/aliases
alias_maps = hash:/etc/postfix/aliases
allow_min_user = no
allow_percent_hack = no
append_dot_mydomain = no
biff = no
body_checks = pcre:/etc/postfix/body_checks.pcre
bounce_queue_lifetime = 4h
broken_sasl_auth_clients = yes
config_directory = /etc/postfix
content_filter = smtp-amavis:[127.0.0.1]:10024
delay_warning_time = 0h
disable_vrfy_command = yes
dovecot_destination_recipient_limit = 1
enable_original_recipient = no
header_checks = pcre:/etc/postfix/header_checks
inet_interfaces = all
inet_protocols = ipv4
lmtp_tls_mandatory_protocols = !SSLv2 !SSLv3
lmtp_tls_protocols = !SSLv2 !SSLv3
mailbox_size_limit = 0
maximal_backoff_time = 4000s
maximal_queue_lifetime = 4h
message_size_limit = 15728640
minimal_backoff_time = 300s
mydestination = $myhostname, localhost, localhost.localdomain
mydomain = mx.nobelsoft.be
myhostname = mx.nobelsoft.be
mynetworks = 127.0.0.1
mynetworks_style = host
myorigin = mx.nobelsoft.be
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
queue_run_delay = 300s
readme_directory = no
recipient_bcc_maps = proxy:mysql:/etc/postfix/mysql/recipient_bcc_maps_user.cf, proxy:mysql:/etc/postfix/mysql/recipient_bcc_maps_domain.cf
recipient_delimiter = +
relay_domains = $mydestination, proxy:mysql:/etc/postfix/mysql/relay_domains.cf
relayhost =
sender_bcc_maps = proxy:mysql:/etc/postfix/mysql/sender_bcc_maps_user.cf, proxy:mysql:/etc/postfix/mysql/sender_bcc_maps_domain.cf
sender_dependent_relayhost_maps = proxy:mysql:/etc/postfix/mysql/sender_dependent_relayhost_maps.cf
smtp-amavis_destination_recipient_limit = 1
smtp_data_init_timeout = 240s
smtp_data_xfer_timeout = 600s
smtp_tls_CAfile = $smtpd_tls_CAfile
smtp_tls_loglevel = 0
smtp_tls_mandatory_protocols = !SSLv2 !SSLv3
smtp_tls_note_starttls_offer = yes
smtp_tls_protocols = !SSLv2 !SSLv3
smtp_tls_security_level = may
smtp_tls_session_cache_database = btree:${data_directory}/smtp_scache
smtpd_banner = $myhostname ESMTP $mail_name (Ubuntu)
smtpd_data_restrictions = reject_unauth_pipelining
smtpd_end_of_data_restrictions = check_policy_service inet:127.0.0.1:7777
smtpd_helo_required = yes
smtpd_helo_restrictions = permit_mynetworks, permit_sasl_authenticated, reject_non_fqdn_helo_hostname, reject_invalid_helo_hostname, check_helo_access pcre:/etc/postfix/helo_access.pcre
smtpd_recipient_restrictions = reject_unknown_recipient_domain, reject_non_fqdn_recipient, reject_unlisted_recipient, check_policy_service inet:127.0.0.1:7777, permit_mynetworks, permit_sasl_authenticated, reject_unauth_destination
smtpd_reject_unlisted_recipient = yes
smtpd_reject_unlisted_sender = yes
smtpd_relay_restrictions = permit_mynetworks permit_sasl_authenticated defer_unauth_destination
smtpd_sasl_auth_enable = yes
smtpd_sasl_local_domain =
smtpd_sasl_path = private/dovecot-auth
smtpd_sasl_security_options = noanonymous
smtpd_sasl_type = dovecot
smtpd_sender_login_maps = proxy:mysql:/etc/postfix/mysql/sender_login_maps.cf
smtpd_sender_restrictions = reject_unknown_sender_domain, reject_non_fqdn_sender, reject_unlisted_sender, permit_mynetworks, reject_sender_login_mismatch, permit_sasl_authenticated, check_sender_access pcre:/etc/postfix/sender_access.pcre
smtpd_tls_CAfile = //etc/ssl/certs/STAR_nobelsoft_be.ca-bundle
smtpd_tls_auth_only = yes
smtpd_tls_cert_file = /etc/ssl/certs/STAR_nobelsoft_be.crt
smtpd_tls_dh1024_param_file = /etc/ssl/dhparams.pem
smtpd_tls_key_file = /etc/ssl/private/STAR_nobelsoft_be.key
smtpd_tls_loglevel = 0
smtpd_tls_mandatory_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_mandatory_protocols = !SSLv2 !SSLv3
smtpd_tls_protocols = !SSLv2 !SSLv3
smtpd_tls_security_level = may
smtpd_tls_session_cache_database = btree:${data_directory}/smtpd_scache
smtpd_use_tls = yes
swap_bangpath = no
tls_random_source = dev:/dev/urandom
transport_maps = proxy:mysql:/etc/postfix/mysql/transport_maps_user.cf, proxy:mysql:/etc/postfix/mysql/transport_maps_domain.cf
virtual_alias_domains =
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
virtual_gid_maps = static:2000
virtual_mailbox_base = /var/vmail
virtual_mailbox_domains = proxy:mysql:/etc/postfix/mysql/virtual_mailbox_domains.cf
virtual_mailbox_maps = proxy:mysql:/etc/postfix/mysql/virtual_mailbox_maps.cf
virtual_minimum_uid = 2000
virtual_transport = dovecot
virtual_uid_maps = static:2000

This is an example mail send after logging turned on

Jul 27 16:43:49 mail postfix/smtpd[4509]: connect from d8D863F97.access.telenet.be[141.134.63.151]
Jul 27 16:43:49 mail postfix/smtpd[4509]: 6BF3A400736: client=d8D863F97.access.telenet.be[141.134.63.151], sasl_method=PLAIN, sasl_username=info@nobelsoft.be
Jul 27 16:43:49 mail postfix/cleanup[4518]: 6BF3A400736: message-id=<C2E83070-970C-4062-8FC2-C18E46FDD402@nobelsoft.be>
Jul 27 16:43:49 mail postfix/qmgr[38642]: 6BF3A400736: from=<info@nobelsoft.be>, size=2086, nrcpt=1 (queue active)
Jul 27 16:43:49 mail amavis[4284]: Net::Server: 2016/07/27-16:43:49 CONNECT TCP Peer: "[127.0.0.1]:38853" Local: "[127.0.0.1]:10024"
Jul 27 16:43:49 mail amavis[4284]: () loaded base policy bank
Jul 27 16:43:49 mail amavis[4284]: () lookup_ip_acl (inet_acl) arr.obj: key="127.0.0.1" matches "127.0.0.1", result=1
Jul 27 16:43:49 mail amavis[4284]: () process_request: fileno sock=14, STDIN=0, STDOUT=1
Jul 27 16:43:49 mail amavis[4284]: () get_deadline switch_to_my_time(new request) - deadline in 480.0 s, set to 336.000 s
Jul 27 16:43:49 mail amavis[4284]: () prolong_timer switch_to_my_time(new request): timer 336, was 0, deadline in 480.0 s
Jul 27 16:43:49 mail amavis[4284]: () process_request: suggested_protocol="" on a TCP socket
Jul 27 16:43:49 mail amavis[4284]: (04284-01) SMTP> 220 [127.0.0.1] ESMTP amavisd-new service ready
Jul 27 16:43:49 mail amavis[4284]: (04284-01) switch_to_client_time 480 s, smtp response sent
Jul 27 16:43:49 mail amavis[4284]: (04284-01) idle_proc, 4: was busy, 23.3 ms, total idle 0.000 s, busy 0.023 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) smtp readline: read 22 bytes into buffer, new size: 22
Jul 27 16:43:49 mail amavis[4284]: (04284-01) idle_proc, 5: was idle, 0.8 ms, total idle 0.001 s, busy 0.023 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) SMTP< EHLO mx.nobelsoft.be\r\n
Jul 27 16:43:49 mail amavis[4284]: (04284-01) get_deadline switch_to_my_time(rx SMTP EHLO) - deadline in 480.0 s, set to 336.000 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) prolong_timer switch_to_my_time(rx SMTP EHLO): timer 336, was 480, deadline in 480.0 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) ESMTP> 250-[127.0.0.1]
Jul 27 16:43:49 mail amavis[4284]: (04284-01) ESMTP> 250-VRFY
Jul 27 16:43:49 mail amavis[4284]: (04284-01) ESMTP> 250-PIPELINING
Jul 27 16:43:49 mail amavis[4284]: (04284-01) ESMTP> 250-SIZE
Jul 27 16:43:49 mail amavis[4284]: (04284-01) ESMTP> 250-ENHANCEDSTATUSCODES
Jul 27 16:43:49 mail amavis[4284]: (04284-01) ESMTP> 250-8BITMIME
Jul 27 16:43:49 mail amavis[4284]: (04284-01) ESMTP> 250-DSN
Jul 27 16:43:49 mail amavis[4284]: (04284-01) ESMTP> 250 XFORWARD NAME ADDR PORT PROTO HELO IDENT SOURCE
Jul 27 16:43:49 mail amavis[4284]: (04284-01) switch_to_client_time 480 s, smtp response sent
Jul 27 16:43:49 mail amavis[4284]: (04284-01) idle_proc, 6: was busy, 8.2 ms, total idle 0.001 s, busy 0.032 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) smtp readline: read 274 bytes into buffer, new size: 274
Jul 27 16:43:49 mail amavis[4284]: (04284-01) idle_proc, 5: was idle, 0.5 ms, total idle 0.001 s, busy 0.032 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) ESMTP< XFORWARD NAME=d8D863F97.access.telenet.be ADDR=141.134.63.151 PORT=62270\r\n
Jul 27 16:43:49 mail amavis[4284]: (04284-01) get_deadline switch_to_my_time(rx SMTP XFORWARD) - deadline in 480.0 s, set to 336.000 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) prolong_timer switch_to_my_time(rx SMTP XFORWARD): timer 336, was 480, deadline in 480.0 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) ESMTP> 250 2.5.0 Ok XFORWARD
Jul 27 16:43:49 mail amavis[4284]: (04284-01) switch_to_client_time 480 s, smtp response sent
Jul 27 16:43:49 mail amavis[4284]: (04284-01) idle_proc, 6: was busy, 2.9 ms, total idle 0.001 s, busy 0.034 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) idle_proc, 5: was idle, 0.3 ms, total idle 0.002 s, busy 0.034 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) ESMTP< XFORWARD PROTO=ESMTP HELO=[192.168.1.160] IDENT=6BF3A400736 SOURCE=REMOTE\r\n
Jul 27 16:43:49 mail amavis[4284]: (04284-01) get_deadline switch_to_my_time(rx SMTP XFORWARD) - deadline in 480.0 s, set to 336.000 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) prolong_timer switch_to_my_time(rx SMTP XFORWARD): timer 336, was 480, deadline in 480.0 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) ESMTP> 250 2.5.0 Ok XFORWARD
Jul 27 16:43:49 mail amavis[4284]: (04284-01) switch_to_client_time 480 s, smtp response sent
Jul 27 16:43:49 mail amavis[4284]: (04284-01) idle_proc, 6: was busy, 4.0 ms, total idle 0.002 s, busy 0.038 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) idle_proc, 5: was idle, 0.3 ms, total idle 0.002 s, busy 0.038 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) ESMTP< MAIL FROM:<info@nobelsoft.be> SIZE=2086\r\n
Jul 27 16:43:49 mail amavis[4284]: (04284-01) get_deadline switch_to_my_time(rx SMTP MAIL) - deadline in 480.0 s, set to 336.000 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) prolong_timer switch_to_my_time(rx SMTP MAIL): timer 336, was 480, deadline in 480.0 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) check_mail_begin_task: task_count=1
Jul 27 16:43:49 mail amavis[4284]: (04284-01) TempDir::prepare_dir: created directory /var/lib/amavis/tmp/amavis-20160727T164349-04284-vRec0hRy
Jul 27 16:43:49 mail amavis[4284]: (04284-01) TempDir::prepare_file: creating file /var/lib/amavis/tmp/amavis-20160727T164349-04284-vRec0hRy/email.txt
Jul 27 16:43:49 mail amavis[4284]: (04284-01) TempDir::prepare_file: layers: unix,perlio
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup_ip_acl arr.obj: key="141.134.63.151", no match
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup [debug_sender] => undef, "info@nobelsoft.be" does not match
Jul 27 16:43:49 mail amavis[4284]: (04284-01) ESMTP> 250 2.1.0 Sender <info@nobelsoft.be> OK
Jul 27 16:43:49 mail amavis[4284]: (04284-01) switch_to_client_time 480 s, smtp response sent
Jul 27 16:43:49 mail amavis[4284]: (04284-01) idle_proc, 6: was busy, 9.4 ms, total idle 0.002 s, busy 0.048 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) idle_proc, 5: was idle, 2.1 ms, total idle 0.004 s, busy 0.048 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) ESMTP< RCPT TO:<web-QaTE8s@mail-tester.com> ORCPT=rfc822;web-QaTE8s@mail-tester.com\r\n
Jul 27 16:43:49 mail amavis[4284]: (04284-01) get_deadline switch_to_my_time(rx SMTP RCPT) - deadline in 480.0 s, set to 336.000 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) prolong_timer switch_to_my_time(rx SMTP RCPT): timer 336, was 480, deadline in 480.0 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup => undef, "web-QaTE8s@mail-tester.com", no lookup tables
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup: (scalar) matches, result="1"
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup [local_domains] => true,  "web-QaTE8s@mail-tester.com" matches, result="1", matching_key="(constant:1)"
Jul 27 16:43:49 mail amavis[4284]: (04284-01) query_keys: web-QaTE8s@mail-tester.com, web-qate8s@mail-tester.com, web-qate8s, @mail-tester.com, @.mail-tester.com, @.com, @.
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup_sql sel_policy "web-QaTE8s@mail-tester.com", query args: [web-QaTE8s@mail-tester.com,-3], [web-qate8s@mail-tester.com,-3], [web-qate8s,-3], [@mail-tester.com,-3], [@.mail-tester.com,-3], [@.com,-3], [@.,-3]
Jul 27 16:43:49 mail amavis[4284]: (04284-01) 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
Jul 27 16:43:49 mail amavis[4284]: (04284-01) sql begin, nontransaction
Jul 27 16:43:49 mail amavis[4284]: (04284-01) Connecting to SQL database server
Jul 27 16:43:49 mail amavis[4284]: (04284-01) connect_to_sql: trying 'DBI:mysql:database=amavisd;host=127.0.0.1;port=3306'
Jul 27 16:43:49 mail amavis[4284]: (04284-01) connect_to_sql: 'DBI:mysql:database=amavisd;host=127.0.0.1;port=3306' succeeded
Jul 27 16:43:49 mail amavis[4284]: (04284-01) sql: preparing and executing: 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
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup_sql: "web-QaTE8s@mail-tester.com" matches catchall, local=>undef
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup_sql(web-QaTE8s@mail-tester.com) matches, result=(id=>"1", priority=>"0", policy_id=>"0", email=>"@.", fullname=>-, id=>"1", policy_name=>-, virus_lover=>-, spam_lover=>-, unchecked_lover=>-, banned_files_lover=>-, bad_header_lover=>-, bypass_virus_checks=>-, bypass_spam_checks=>-, bypass_banned_checks=>-, bypass_header_checks=>-, virus_quarantine_to=>-, 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_subject_tag2=>-, spam_subject_tag3...
Jul 27 16:43:49 mail amavis[4284]: (04284-01) ...=>-, message_size_limit=>-, banned_rulenames=>-, disclaimer_options=>-, forward_method=>-, sa_userconf=>-, sa_username=>-, id=>"1", local=>-)
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup_sql_field(message_size_limit) rec=0, "web-QaTE8s@mail-tester.com" result: undef
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup [message_size_limit] => undef, "web-QaTE8s@mail-tester.com" does not match
Jul 27 16:43:49 mail amavis[4284]: (04284-01) ESMTP> 250 2.1.5 Recipient <web-QaTE8s@mail-tester.com> OK
Jul 27 16:43:49 mail amavis[4284]: (04284-01) switch_to_client_time 480 s, smtp response sent
Jul 27 16:43:49 mail amavis[4284]: (04284-01) idle_proc, 6: was busy, 82.1 ms, total idle 0.004 s, busy 0.130 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) idle_proc, 5: was idle, 0.3 ms, total idle 0.004 s, busy 0.130 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) ESMTP< DATA\r\n
Jul 27 16:43:49 mail amavis[4284]: (04284-01) get_deadline switch_to_my_time(rx SMTP DATA) - deadline in 480.0 s, set to 336.000 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) prolong_timer switch_to_my_time(rx SMTP DATA): timer 336, was 480, deadline in 480.0 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) ESMTP::10024 /var/lib/amavis/tmp/amavis-20160727T164349-04284-vRec0hRy: <info@nobelsoft.be> -> <web-QaTE8s@mail-tester.com> SIZE=2086 Received: from mx.nobelsoft.be ([127.0.0.1]) by nobelsoft.be (nobelsoft.be [127.0.0.1]) (amavisd-new, port 10024) with ESMTP for <web-QaTE8s@mail-tester.com>; Wed, 27 Jul 2016 16:43:49 +0200 (CEST)
Jul 27 16:43:49 mail amavis[4284]: (04284-01) ESMTP> 354 End data with <CR><LF>.<CR><LF>
Jul 27 16:43:49 mail amavis[4284]: (04284-01) switch_to_client_time 480 s, smtp response sent
Jul 27 16:43:49 mail amavis[4284]: (04284-01) switch_to_client_time 480 s, receiving data
Jul 27 16:43:49 mail amavis[4284]: (04284-01) smtp copy: read 2093 bytes into buffer, new size: 2093
Jul 27 16:43:49 mail amavis[4284]: (04284-01) smtp copy: 6 bytes still buffered at end
Jul 27 16:43:49 mail amavis[4284]: (04284-01) get_deadline switch_to_my_time(rx data-end) - deadline in 480.0 s, set to 336.000 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) prolong_timer switch_to_my_time(rx data-end): timer 336, was 480, deadline in 480.0 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) ESMTP< .<CR><LF>
Jul 27 16:43:49 mail amavis[4284]: (04284-01) Actual message size 2084 B less than the declared 2086 B
Jul 27 16:43:49 mail amavis[4284]: (04284-01) get_deadline get_body_digest - deadline in 480.0 s, set to 30.000 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) get_deadline digest_pre - deadline in 480.0 s, set to 336.000 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) prolong_timer digest_pre: timer 336, was 336, deadline in 480.0 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) get_body_digest: reading header section
Jul 27 16:43:49 mail amavis[4284]: (04284-01) get_deadline digest_hdr - deadline in 480.0 s, set to 336.000 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) prolong_timer digest_hdr: timer 336, was 336, deadline in 480.0 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) get_body_digest: reading mail body
Jul 27 16:43:49 mail amavis[4284]: (04284-01) get_deadline digest_body - deadline in 480.0 s, set to 336.000 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) prolong_timer digest_body: timer 336, was 336, deadline in 480.0 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) body type (ESMTP BODY): unlabeled, good (h=0, b=0)
Jul 27 16:43:49 mail amavis[4284]: (04284-01) body hash: dde716137ef06b2e3b49d4c8b4e34e49
Jul 27 16:43:49 mail amavis[4284]: (04284-01) Original mail size: 2084; quota set to: 1042000 bytes
Jul 27 16:43:49 mail amavis[4284]: (04284-01) sql begin, nontransaction
Jul 27 16:43:49 mail amavis[4284]: (04284-01) sql: preparing and executing: SELECT id FROM maddr WHERE partition_tag=? AND email=?
Jul 27 16:43:49 mail amavis[4284]: (04284-01) save_info_preliminary 5acPQFsgWfiq, sender id: 475, info@nobelsoft.be, exists
Jul 27 16:43:49 mail amavis[4284]: (04284-01) sql begin, nontransaction
Jul 27 16:43:49 mail amavis[4284]: (04284-01) sql: executing clause: SELECT id FROM maddr WHERE partition_tag=? AND email=?
Jul 27 16:43:49 mail amavis[4284]: (04284-01) sql begin, nontransaction
Jul 27 16:43:49 mail amavis[4284]: (04284-01) sql: preparing and executing: INSERT INTO maddr (partition_tag, email, domain) VALUES (?,?,?)
Jul 27 16:43:49 mail amavis[4284]: (04284-01) sql begin, nontransaction
Jul 27 16:43:49 mail amavis[4284]: (04284-01) sql: executing clause: SELECT id FROM maddr WHERE partition_tag=? AND email=?
Jul 27 16:43:49 mail amavis[4284]: (04284-01) find_or_save_addr: record inserted, id=8393, web-qate8s@mail-tester.com
Jul 27 16:43:49 mail amavis[4284]: (04284-01) save_info_preliminary 5acPQFsgWfiq, recip id: 8393, web-QaTE8s@mail-tester.com, new
Jul 27 16:43:49 mail amavis[4284]: (04284-01) sql begin transaction
Jul 27 16:43:49 mail amavis[4284]: (04284-01) sql: preparing and executing: INSERT INTO msgs (partition_tag, mail_id, secret_id, am_id, time_num, time_iso, sid, policy, client_addr, size, host) VALUES (?,?,?,?,?,?,?,?,?,?,?)
Jul 27 16:43:49 mail amavis[4284]: (04284-01) sql commit
Jul 27 16:43:49 mail amavis[4284]: (04284-01) Checking: 5acPQFsgWfiq [141.134.63.151] <info@nobelsoft.be> -> <web-QaTE8s@mail-tester.com>
Jul 27 16:43:49 mail amavis[4284]: (04284-01) 2822.From: <info@nobelsoft.be>
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup_sql_field(local) rec=0, "web-QaTE8s@mail-tester.com" result: undef
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup: (scalar) matches, result="1"
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup [local_domains] => true,  "web-QaTE8s@mail-tester.com" matches, result="1", matching_key="(constant:1)"
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup_sql_field(bypass_virus_checks) rec=0, "web-QaTE8s@mail-tester.com" result: undef
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup [bypass_virus_checks] => undef, "web-QaTE8s@mail-tester.com" does not match
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup_sql_field(bypass_banned_checks) rec=0, "web-QaTE8s@mail-tester.com" result: undef
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup [bypass_banned_checks] => undef, "web-QaTE8s@mail-tester.com" does not match
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup_sql_field(bypass_spam_checks) rec=0, "web-QaTE8s@mail-tester.com" result: undef
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup [bypass_spam_checks] => undef, "web-QaTE8s@mail-tester.com" does not match
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup_sql_field(id) rec=0, "web-QaTE8s@mail-tester.com" result: "1"
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup [users.id], 1 matches for "web-QaTE8s@mail-tester.com", results: "/cached/"=>"1"
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup_sql_field(policy_id) rec=0, "web-QaTE8s@mail-tester.com" result: "0"
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup [users.policy_id] => false, "web-QaTE8s@mail-tester.com" matches, result="0", matching_key="/cached/"
Jul 27 16:43:49 mail amavis[4284]: (04284-01) Extracting mime components
Jul 27 16:43:49 mail amavis[4284]: (04284-01) Issued a new file name: p001
Jul 27 16:43:49 mail amavis[4284]: (04284-01) Issued a new file name: p002
Jul 27 16:43:49 mail amavis[4284]: (04284-01) mime_decode_preamble: 1 lines
Jul 27 16:43:49 mail amavis[4284]: (04284-01) Issued a new pseudo part: p003
Jul 27 16:43:49 mail amavis[4284]: (04284-01) p003 1 Content-Type: multipart/alternative
Jul 27 16:43:49 mail amavis[4284]: (04284-01) Charging 24 bytes to remaining quota 1042000 (out of 1042000, (0%)) - by mime_decode
Jul 27 16:43:49 mail amavis[4284]: (04284-01) p001 1/1 Content-Type: text/plain, size: 24 B, name: 
Jul 27 16:43:49 mail amavis[4284]: (04284-01) reparenting p001 from p000 to p003
Jul 27 16:43:49 mail amavis[4284]: (04284-01) Charging 1139 bytes to remaining quota 1041976 (out of 1042000, (0%)) - by mime_decode
Jul 27 16:43:49 mail amavis[4284]: (04284-01) p002 1/2 Content-Type: text/html, size: 1139 B, name: 
Jul 27 16:43:49 mail amavis[4284]: (04284-01) reparenting p002 from p000 to p003
Jul 27 16:43:49 mail amavis[4284]: (04284-01) get_deadline mime_decode - deadline in 479.8 s, set to 336.000 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) prolong_timer mime_decode: timer 336, was 336, deadline in 479.8 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) get_deadline mime_decode-1 - deadline in 479.8 s, set to 336.000 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) prolong_timer mime_decode-1: timer 336, was 336, deadline in 479.8 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) decode_parts: level=1, #parts=3 : p001, p002, p003
Jul 27 16:43:49 mail amavis[4284]: (04284-01) running file(1) on 2 files, arglist size 23
Jul 27 16:43:49 mail amavis[4284]: (04284-01) run_command: [4539] /usr/bin/file p001 p002 </dev/null 2>&1
Jul 27 16:43:49 mail amavis[4539]: (04284-01) open_on_specific_fd: target fd0 closing, to become < /dev/null
Jul 27 16:43:49 mail amavis[4539]: (04284-01) open_on_specific_fd: target fd1 closing, to become > &=18
Jul 27 16:43:49 mail amavis[4539]: (04284-01) open_on_specific_fd: target fd1 dup2 from fd18 > &=18
Jul 27 16:43:49 mail amavis[4539]: (04284-01) open_on_specific_fd: source fd18 closed
Jul 27 16:43:49 mail amavis[4539]: (04284-01) open_on_specific_fd: target fd2 closing, to become > &1
Jul 27 16:43:49 mail amavis[4539]: (04284-01) open_on_specific_fd: target fd2 dup2 from fd1 > &1
Jul 27 16:43:49 mail amavis[4284]: (04284-01) result line from file(1): p001: ASCII text\n
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup_re("ASCII text") matches key "(?^i:^(ASCII|text)\b)", result="asc"
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup [map_full_type_to_short_type] => true,  "ASCII text" matches, result="asc", matching_key="(?^i:^(ASCII|text)\\b)"
Jul 27 16:43:49 mail amavis[4284]: (04284-01) File-type of p001: ASCII text; (asc)
Jul 27 16:43:49 mail amavis[4284]: (04284-01) result line from file(1): p002: HTML document, ASCII text, with very long lines\n
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup_re("HTML document, ASCII text, with very long lines") matches key "(?^i:\btext\b)", result="asc"
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup [map_full_type_to_short_type] => true,  "HTML document, ASCII text, with very long lines" matches, result="asc", matching_key="(?^i:\\btext\\b)"
Jul 27 16:43:49 mail amavis[4284]: (04284-01) File-type of p002: HTML document, ASCII text, with very long lines; (asc)
Jul 27 16:43:49 mail amavis[4284]: (04284-01) decompose_part: p001 - atomic
Jul 27 16:43:49 mail amavis[4284]: (04284-01) decompose_part: p002 - atomic
Jul 27 16:43:49 mail amavis[4284]: (04284-01) get_deadline parts_decode - deadline in 479.8 s, set to 336.000 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) prolong_timer parts_decode: timer 336, was 336, deadline in 479.8 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup_sql_field(bypass_header_checks) rec=0, "web-QaTE8s@mail-tester.com" result: undef
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup [bypass_header_checks] => undef, "web-QaTE8s@mail-tester.com" does not match
Jul 27 16:43:49 mail amavis[4284]: (04284-01) check_header: 0, OK
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup_sql_field(bypass_header_checks) rec=0, "web-QaTE8s@mail-tester.com" result: undef
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup [bypass_header_checks] => undef, "web-QaTE8s@mail-tester.com" does not match
Jul 27 16:43:49 mail amavis[4284]: (04284-01) Checking for banned types and filenames
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup_sql_field(banned_rulenames) rec=0, "web-QaTE8s@mail-tester.com" result: undef
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup: (scalar) matches, result="DEFAULT"
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup [banned_filename], 1 matches for "web-QaTE8s@mail-tester.com", results: "(constant:DEFAULT)"=>"DEFAULT"
Jul 27 16:43:49 mail amavis[4284]: (04284-01) collect banned table[0]: web-QaTE8s@mail-tester.com, tables: DEFAULT=>Amavis::Lookup::RE=ARRAY(0x36fdc10)
Jul 27 16:43:49 mail amavis[4284]: (04284-01) starting banned checks - traversing message structure tree
Jul 27 16:43:49 mail amavis[4284]: (04284-01) check_for_banned (p003,p001) multipart/alternative | text/plain,.asc
Jul 27 16:43:49 mail amavis[4284]: (04284-01) doing banned check for web-QaTE8s@mail-tester.com on multipart/alternative | text/plain,.asc
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup_re(["multipart/alternative","text/plain",".asc"]), no matches
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup [check_bann:web-QaTE8s@mail-tester.com] => undef, ["multipart/alternative","text/plain",".asc"] does not match
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup [banned_namepath_re] => undef, "P=p003\tL=1\tM=multipart/alternative\nP=p001\tL=1/1\tM=text/plain\tT=asc" does not match
Jul 27 16:43:49 mail amavis[4284]: (04284-01) p.path web-QaTE8s@mail-tester.com: "P=p003,L=1,M=multipart/alternative | P=p001,L=1/1,M=text/plain,T=asc"
Jul 27 16:43:49 mail amavis[4284]: (04284-01) check_for_banned (p003,p002) multipart/alternative | text/html,.asc
Jul 27 16:43:49 mail amavis[4284]: (04284-01) doing banned check for web-QaTE8s@mail-tester.com on multipart/alternative | text/html,.asc
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup_re(["multipart/alternative","text/html",".asc"]), no matches
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup [check_bann:web-QaTE8s@mail-tester.com] => undef, ["multipart/alternative","text/html",".asc"] does not match
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup [banned_namepath_re] => undef, "P=p003\tL=1\tM=multipart/alternative\nP=p002\tL=1/2\tM=text/html\tT=asc" does not match
Jul 27 16:43:49 mail amavis[4284]: (04284-01) p.path web-QaTE8s@mail-tester.com: "P=p003,L=1,M=multipart/alternative | P=p002,L=1/2,M=text/html,T=asc"
Jul 27 16:43:49 mail amavis[4284]: (04284-01) banned check: any=0, all=N (1)
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup_re("MAIL"), no matches
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup [keep_decoded_original] => undef, "MAIL" does not match
Jul 27 16:43:49 mail amavis[4284]: (04284-01) Calling virus scanners, 2 files to scan in /var/lib/amavis/tmp/amavis-20160727T164349-04284-vRec0hRy/parts
Jul 27 16:43:49 mail amavis[4284]: (04284-01) invoking av-scanner ClamAV-clamd
Jul 27 16:43:49 mail amavis[4284]: (04284-01) ask_daemon: proto=DFLT, spawn=0, (ClamAV-clamd) /var/run/clamav/clamd.ctl
Jul 27 16:43:49 mail amavis[4284]: (04284-01) run_av (ClamAV-clamd): query template(1,1): CONTSCAN {}\n
Jul 27 16:43:49 mail amavis[4284]: (04284-01) get_deadline run_av_pre - deadline in 479.8 s, set to 336.000 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) prolong_timer run_av_pre: timer 336, was 336, deadline in 479.8 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) get_deadline run_av_scan - deadline in 479.8 s, set to 336.000 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) prolong_timer run_av_scan: timer 336, was 336, deadline in 479.8 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) run_av Using (ClamAV-clamd): (code) CONTSCAN /var/lib/amavis/tmp/amavis-20160727T164349-04284-vRec0hRy/parts\n
Jul 27 16:43:49 mail amavis[4284]: (04284-01) get_deadline ask_daemon_internal_connect_pre - deadline in 479.8 s, set to 336.000 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) get_deadline ask_daemon_internal_connect - deadline in 479.8 s, set to 10.000 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) prolong_timer ask_daemon_internal_connect: timer 10, was 336, deadline in 479.8 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) ClamAV-clamd: Connecting to socket  /var/run/clamav/clamd.ctl
Jul 27 16:43:49 mail amavis[4284]: (04284-01) new socket by IO::Socket::UNIX to /var/run/clamav/clamd.ctl, timeout 10
Jul 27 16:43:49 mail amavis[4284]: (04284-01) connected to /var/run/clamav/clamd.ctl successfully
Jul 27 16:43:49 mail amavis[4284]: (04284-01) ClamAV-clamd: Sending CONTSCAN /var/lib/amavis/tmp/amavis-20160727T164349-04284-vRec0hRy/parts\n to socket /var/run/clamav/clamd.ctl
Jul 27 16:43:49 mail amavis[4284]: (04284-01) rw_loop: needline=0, flush=1, wr=1, timeout=10
Jul 27 16:43:49 mail amavis[4284]: (04284-01) rw_loop: sending
Jul 27 16:43:49 mail amavis[4284]: (04284-01) rw_loop sent 73> CONTSCAN /var/lib/amavis/tmp/amavis-20160727T164349-04284-vRec0hRy/parts\n
Jul 27 16:43:49 mail amavis[4284]: (04284-01) get_deadline ask_daemon_internal_scan - deadline in 479.8 s, set to 336.000 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) prolong_timer ask_daemon_internal_scan: timer 336, was 10, deadline in 479.8 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) rw_loop: needline=0, flush=0, wr=0, timeout=335.993
Jul 27 16:43:49 mail amavis[4284]: (04284-01) rw_loop: receiving
Jul 27 16:43:49 mail amavis[4284]: (04284-01) rw_loop read 68 chars< /var/lib/amavis/tmp/amavis-20160727T164349-04284-vRec0hRy/parts: OK\n
Jul 27 16:43:49 mail amavis[4284]: (04284-01) rw_loop: needline=0, flush=0, wr=0, timeout=335.993
Jul 27 16:43:49 mail amavis[4284]: (04284-01) rw_loop: receiving
Jul 27 16:43:49 mail amavis[4284]: (04284-01) rw_loop read: got eof
Jul 27 16:43:49 mail amavis[4284]: (04284-01) get_deadline ask_daemon_internal - deadline in 479.7 s, set to 336.000 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) prolong_timer ask_daemon_internal: timer 336, was 336, deadline in 479.7 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) get_deadline run_av_3 - deadline in 479.7 s, set to 336.000 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) prolong_timer run_av_3: timer 336, was 336, deadline in 479.7 s
Jul 27 16:43:49 mail amavis[4284]: (04284-01) run_av (ClamAV-clamd) result: /var/lib/amavis/tmp/amavis-20160727T164349-04284-vRec0hRy/parts: OK\n
Jul 27 16:43:49 mail amavis[4284]: (04284-01) run_av (ClamAV-clamd): CLEAN
Jul 27 16:43:49 mail amavis[4284]: (04284-01) run_av (ClamAV-clamd) result: clean
Jul 27 16:43:49 mail amavis[4284]: (04284-01) wbl: checking sender <info@nobelsoft.be>
Jul 27 16:43:49 mail amavis[4284]: (04284-01) wbl: (SQL) recip <web-QaTE8s@mail-tester.com>, 1 matches
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup: (scalar) matches, result="1"
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup [local_domains] => true,  "info@nobelsoft.be" matches, result="1", matching_key="(constant:1)"
Jul 27 16:43:49 mail amavis[4284]: (04284-01) query_keys: info@nobelsoft.be, info, @nobelsoft.be, @.nobelsoft.be, @.be, @.
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup_sql sel_wblist "info@nobelsoft.be", query args: "1", [info@nobelsoft.be,-3], [info,-3], [@nobelsoft.be,-3], [@.nobelsoft.be,-3], [@.be,-3], [@.,-3]
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup_sql select: SELECT wb FROM wblist JOIN mailaddr ON wblist.sid=mailaddr.id WHERE wblist.rid=? AND mailaddr.email IN (?,?,?,?,?,?) ORDER BY mailaddr.priority DESC
Jul 27 16:43:49 mail amavis[4284]: (04284-01) sql begin, nontransaction
Jul 27 16:43:49 mail amavis[4284]: (04284-01) sql: preparing and executing: SELECT wb FROM wblist JOIN mailaddr ON wblist.sid=mailaddr.id WHERE wblist.rid=? AND mailaddr.email IN (?,?,?,?,?,?) ORDER BY mailaddr.priority DESC
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup_sql(info@nobelsoft.be) matches, result=(wb=>"W")
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup_sql_field(wb) rec=0, "info@nobelsoft.be" result: "W"
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup => true,  "info@nobelsoft.be" matches, result="W", matching_key="wb=>"W""
Jul 27 16:43:49 mail amavis[4284]: (04284-01) wbl: (SQL) recip <web-QaTE8s@mail-tester.com>, rid=1, got: "W"
Jul 27 16:43:49 mail amavis[4284]: (04284-01) wbl: (SQL) recip <web-QaTE8s@mail-tester.com> whitelisted sender <info@nobelsoft.be>
Jul 27 16:43:49 mail amavis[4284]: (04284-01) query_keys: web-QaTE8s@mail-tester.com, web-qate8s@mail-tester.com, web-qate8s@, mail-tester.com, .mail-tester.com, .com, .
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup_hash(web-QaTE8s@mail-tester.com) matches keys: "."=>ARRAY(0x3b18198)
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup [score_recip<web-QaTE8s@mail-tester.com>,score_sender], 1 matches for "web-QaTE8s@mail-tester.com", results: "."=>[Amavis::Lookup::RE=ARRAY(0x3b18300),{}]
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup_re("info@nobelsoft.be"), no matches
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup [score_sender<info@nobelsoft.be>] => undef, "info@nobelsoft.be" does not match
Jul 27 16:43:49 mail amavis[4284]: (04284-01) wbl: whitelisted sender <info@nobelsoft.be>
Jul 27 16:43:49 mail amavis[4284]: (04284-01) sender white/blacklisted, skipping spam_scan
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup_sql_field(spam_tag_level) rec=0, "web-QaTE8s@mail-tester.com" result: undef
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup: (scalar) matches, result="2"
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup [spam_tag_level] => true,  "web-QaTE8s@mail-tester.com" matches, result="2", matching_key="(constant:2)"
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup_sql_field(spam_tag2_level) rec=0, "web-QaTE8s@mail-tester.com" result: undef
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup: (scalar) matches, result="6.31"
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup [spam_tag2_level] => true,  "web-QaTE8s@mail-tester.com" matches, result="6.31", matching_key="(constant:6.31)"
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup_sql_field(spam_tag3_level) rec=0, "web-QaTE8s@mail-tester.com" result: undef
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup [spam_tag3_level] => undef, "web-QaTE8s@mail-tester.com" does not match
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup_sql_field(spam_kill_level) rec=0, "web-QaTE8s@mail-tester.com" result: undef
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup: (scalar) matches, result="6.31"
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup [spam_kill_level] => true,  "web-QaTE8s@mail-tester.com" matches, result="6.31", matching_key="(constant:6.31)"
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup_sql_field(message_size_limit) rec=0, "web-QaTE8s@mail-tester.com" result: undef
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup [message_size_limit] => undef, "web-QaTE8s@mail-tester.com" does not match
Jul 27 16:43:49 mail amavis[4284]: (04284-01) final_destiny (ccat=0) is PASS, recip web-QaTE8s@mail-tester.com
Jul 27 16:43:49 mail amavis[4284]: (04284-01) final_destiny PASS, recip web-QaTE8s@mail-tester.com
Jul 27 16:43:49 mail amavis[4284]: (04284-01) do_notify_and_quar: ccat=Clean (1,0) ("1":Clean, "0":CatchAll) ccat_block=(), qar_mth=
Jul 27 16:43:49 mail amavis[4284]: (04284-01) do_notify_and_quarantine: not quarantining, q_method off
Jul 27 16:43:49 mail amavis[4284]: (04284-01) skip admin notification, no administrators
Jul 27 16:43:49 mail amavis[4284]: (04284-01) do_notify_and_quarantine - done
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup_sql_field(forward_method) rec=0, "web-QaTE8s@mail-tester.com" result: undef
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup: (opaque) matches, result="smtp:[127.0.0.1]:10025"
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup [forward_method] => true,  "web-QaTE8s@mail-tester.com" matches, result="smtp:[127.0.0.1]:10025", matching_key="(opaque:smtp:[127.0.0.1]:10025)"
Jul 27 16:43:49 mail amavis[4284]: (04284-01) delivery method is smtp:[127.0.0.1]:10025, recips: web-QaTE8s@mail-tester.com
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup_sql_field(spam_tag_level) rec=0, "web-QaTE8s@mail-tester.com" result: undef
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup: (scalar) matches, result="2"
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup [spam_tag_level] => true,  "web-QaTE8s@mail-tester.com" matches, result="2", matching_key="(constant:2)"
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup_sql_field(spam_tag2_level) rec=0, "web-QaTE8s@mail-tester.com" result: undef
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup: (scalar) matches, result="6.31"
Jul 27 16:43:49 mail amavis[4284]: (04284-01) lookup [spam_tag2_level] => true,  "web-QaTE8s@mail-tester.com" matches, result="6.31", matching_key="(constant:6.31)"
Jul 27 16:43:49 mail amavis[4284]: (04284-01) headers CLUSTERING: NEW CLUSTER <web-QaTE8s@mail-tester.com>: score=x, tag=0, tag2=0, local=1, bl=, s=, mangle=
Jul 27 16:43:49 mail amavis[4284]: (04284-01) header: X-Virus-Scanned: Debian amavisd-new at nobelsoft.be\n
Jul 27 16:43:49 mail amavis[4284]: (04284-01) header: Received: from mx.nobelsoft.be ([127.0.0.1])\n\tby nobelsoft.be (nobelsoft.be [127.0.0.1]) (amavisd-new, port 10024)\n\twith ESMTP id 5acPQFsgWfiq for <web-QaTE8s@mail-tester.com>;\n\tWed, 27 Jul 2016 16:43:49 +0200 (CEST)\n
Jul 27 16:43:49 mail amavis[4284]: (04284-01) headers CLUSTERING: done all 1 recips in one go
Jul 27 16:43:50 mail amavis[4284]: (04284-01) dkim: not signing mail which is not originating from our site
Jul 27 16:43:50 mail amavis[4284]: (04284-01) about to connect to smtp:[127.0.0.1]:10025, FWD from <info@nobelsoft.be> -> <web-QaTE8s@mail-tester.com>
Jul 27 16:43:50 mail amavis[4284]: (04284-01) get_deadline fwd_init - deadline in 479.7 s, set to 480.000 s
Jul 27 16:43:50 mail amavis[4284]: (04284-01) smtp session: setting up a new session
Jul 27 16:43:50 mail amavis[4284]: (04284-01) establish_or_refresh, state: down
Jul 27 16:43:50 mail amavis[4284]: (04284-01) new socket by IO::Socket::INET to [127.0.0.1]:10025, timeout 35, blocking
Jul 27 16:43:50 mail postfix/smtpd[4529]: connect from mail.nobelsoft.be[127.0.0.1]
Jul 27 16:43:50 mail amavis[4284]: (04284-01) connected to [127.0.0.1]:10025 successfully
Jul 27 16:43:50 mail amavis[4284]: (04284-01) rw_loop: needline=1, flush=0, wr=0, timeout=35
Jul 27 16:43:50 mail amavis[4284]: (04284-01) rw_loop: receiving
Jul 27 16:43:50 mail amavis[4284]: (04284-01) rw_loop read 44 chars< 220 mx.nobelsoft.be ESMTP Postfix (Ubuntu)\r\n
Jul 27 16:43:50 mail amavis[4284]: (04284-01) smtp greeting: 220 mx.nobelsoft.be ESMTP Postfix (Ubuntu)
Jul 27 16:43:50 mail amavis[4284]: (04284-01) smtp cmd> EHLO nobelsoft.be
Jul 27 16:43:50 mail amavis[4284]: (04284-01) rw_loop: needline=0, flush=1, wr=1, timeout=300
Jul 27 16:43:50 mail amavis[4284]: (04284-01) rw_loop: sending
Jul 27 16:43:50 mail amavis[4284]: (04284-01) rw_loop sent 19> EHLO nobelsoft.be\r\n
Jul 27 16:43:50 mail amavis[4284]: (04284-01) rw_loop: needline=1, flush=0, wr=0, timeout=300
Jul 27 16:43:50 mail amavis[4284]: (04284-01) rw_loop: receiving
Jul 27 16:43:50 mail amavis[4284]: (04284-01) rw_loop read 114 chars< 250-mx.nobelsoft.be\r\n250-PIPELINING\r\n250-SIZE 15728640\r\n250-ETRN\r\n250-ENHANCEDSTATUSCODES\r\n250-8BITMIME\r\n250 DSN\r\n
Jul 27 16:43:50 mail amavis[4284]: (04284-01) smtp resp to EHLO: 250 mx.nobelsoft.be\nPIPELINING\nSIZE 15728640\nETRN\nENHANCEDSTATUSCODES\n8BITMIME\nDSN
Jul 27 16:43:50 mail amavis[4284]: (04284-01) tls active=0, capable=, sec_level=0
Jul 27 16:43:50 mail amavis[4284]: (04284-01) Remote host presents itself as: mx.nobelsoft.be, handles DSN, handles PIPELINING
Jul 27 16:43:50 mail amavis[4284]: (04284-01) AUTH not needed, user='', MTA offers ''
Jul 27 16:43:50 mail amavis[4284]: (04284-01) smtp cmd> MAIL FROM:<info@nobelsoft.be> BODY=7BIT
Jul 27 16:43:50 mail amavis[4284]: (04284-01) smtp cmd> RCPT TO:<web-QaTE8s@mail-tester.com> ORCPT=rfc822;web-QaTE8s@mail-tester.com
Jul 27 16:43:50 mail amavis[4284]: (04284-01) smtp cmd> DATA
Jul 27 16:43:50 mail amavis[4284]: (04284-01) rw_loop: needline=0, flush=1, wr=1, timeout=120
Jul 27 16:43:50 mail amavis[4284]: (04284-01) rw_loop: sending
Jul 27 16:43:50 mail amavis[4284]: (04284-01) rw_loop sent 125> MAIL FROM:<info@nobelsoft.be> BODY=7BIT\r\nRCPT TO:<web-QaTE8s@mail-tester.com> ORCPT=rfc822;web-QaTE8s@mail-tester.com\r\nDATA\r\n
Jul 27 16:43:50 mail amavis[4284]: (04284-01) rw_loop: needline=1, flush=0, wr=0, timeout=300
Jul 27 16:43:50 mail postfix/smtpd[4529]: 057DB4016D5: client=mail.nobelsoft.be[127.0.0.1]
Jul 27 16:43:50 mail amavis[4284]: (04284-01) rw_loop: receiving
Jul 27 16:43:50 mail amavis[4284]: (04284-01) 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
Jul 27 16:43:50 mail amavis[4284]: (04284-01) smtp resp to MAIL (pip): 250 2.1.0 Ok
Jul 27 16:43:50 mail amavis[4284]: (04284-01) smtp resp to RCPT (pip) (<web-QaTE8s@mail-tester.com>): 250 2.1.5 Ok
Jul 27 16:43:50 mail amavis[4284]: (04284-01) smtp resp to DATA: 354 End data with <CR><LF>.<CR><LF>
Jul 27 16:43:50 mail amavis[4284]: (04284-01) write_header: 0, Amavis::Out::SMTP::Protocol=HASH(0x802b6b0)
Jul 27 16:43:50 mail amavis[4284]: (04284-01) smtp connection_cache disabled, sending QUIT
Jul 27 16:43:50 mail amavis[4284]: (04284-01) smtp cmd> QUIT
Jul 27 16:43:50 mail amavis[4284]: (04284-01) rw_loop: needline=0, flush=1, wr=1, timeout=479.967
Jul 27 16:43:50 mail amavis[4284]: (04284-01) rw_loop: sending
Jul 27 16:43:50 mail postfix/cleanup[4518]: 057DB4016D5: message-id=<C2E83070-970C-4062-8FC2-C18E46FDD402@nobelsoft.be>
Jul 27 16:43:50 mail amavis[4284]: (04284-01) rw_loop sent 2367> X-Virus-Scanned: Debian amavisd-new at nobelsoft.be\r\nReceived: from mx.nobelsoft.be ([127.0.0.1])\r\n\tby nobelsoft.be (nobelsoft.be [127.0.0.1]) (amavisd-new, port 10024)\r\n\twith ESMTP id 5acPQFsgWfiq fo [...]
Jul 27 16:43:50 mail amavis[4284]: (04284-01) rw_loop: needline=1, flush=0, wr=0, timeout=479.967
Jul 27 16:43:50 mail postfix/qmgr[38642]: 057DB4016D5: from=<info@nobelsoft.be>, size=2553, nrcpt=1 (queue active)
Jul 27 16:43:50 mail postfix/smtpd[4529]: disconnect from mail.nobelsoft.be[127.0.0.1]
Jul 27 16:43:50 mail amavis[4284]: (04284-01) rw_loop: receiving
Jul 27 16:43:50 mail amavis[4284]: (04284-01) rw_loop read 52 chars< 250 2.0.0 Ok: queued as 057DB4016D5\r\n221 2.0.0 Bye\r\n
Jul 27 16:43:50 mail amavis[4284]: (04284-01) smtp resp to data-dot (<web-QaTE8s@mail-tester.com>): 250 2.0.0 Ok: queued as 057DB4016D5
Jul 27 16:43:50 mail amavis[4284]: (04284-01) Amavis::Out::SMTP::Session close, disconnecting
Jul 27 16:43:50 mail amavis[4284]: (04284-01) get_deadline fwd-end-chkpnt - deadline in 479.6 s, set to 336.000 s
Jul 27 16:43:50 mail amavis[4284]: (04284-01) prolong_timer fwd-end-chkpnt: timer 336, was 0, deadline in 479.6 s
Jul 27 16:43:50 mail amavis[4284]: (04284-01) FWD from <info@nobelsoft.be> -> <web-QaTE8s@mail-tester.com>,BODY=7BIT 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 057DB4016D5
Jul 27 16:43:50 mail amavis[4284]: (04284-01) get_deadline forwarding - deadline in 479.6 s, set to 336.000 s
Jul 27 16:43:50 mail amavis[4284]: (04284-01) prolong_timer forwarding: timer 336, was 336, deadline in 479.6 s
Jul 27 16:43:50 mail amavis[4284]: (04284-01) DSN: sender NOT credible, SA: 0.000, <info@nobelsoft.be>
Jul 27 16:43:50 mail amavis[4284]: (04284-01) lookup: (scalar) matches, result="10"
Jul 27 16:43:50 mail amavis[4284]: (04284-01) lookup [spam_dsn_cutoff_level_bysender] => true,  "info@nobelsoft.be" matches, result="10", matching_key="(constant:10)"
Jul 27 16:43:50 mail amavis[4284]: (04284-01) dsn: from MTA 250 NonBlocking:Clean <info@nobelsoft.be> -> <web-QaTE8s@mail-tester.com>: 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 057DB4016D5"
Jul 27 16:43:50 mail amavis[4284]: (04284-01) DSN: SUCC from MTA 250 NonBlocking:Clean, no DSN requested: <info@nobelsoft.be> -> <web-QaTE8s@mail-tester.com>
Jul 27 16:43:50 mail amavis[4284]: (04284-01) one_response_for_all <info@nobelsoft.be>: 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 057DB4016D5'
Jul 27 16:43:50 mail amavis[4284]: (04284-01) 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 057DB4016D5
Jul 27 16:43:50 mail amavis[4284]: (04284-01) status counters: InMsgsStatus{Relayed,RelayedUntagged,RelayedUntaggedInbound}
Jul 27 16:43:50 mail amavis[4284]: (04284-01) get_deadline delivery-notification - deadline in 479.6 s, set to 336.000 s
Jul 27 16:43:50 mail amavis[4284]: (04284-01) prolong_timer delivery-notification: timer 336, was 336, deadline in 479.6 s
Jul 27 16:43:50 mail amavis[4284]: (04284-01) fish_out_ip_from_received: 141.134.63.151
Jul 27 16:43:50 mail amavis[4284]: (04284-01) lookup_ip_acl (publicnetworks) arr.obj: key="141.134.63.151" matches "::FFFF:0:0/96", result=1
Jul 27 16:43:50 mail amavis[4284]: (04284-01) parse_ip_address_from_received: 141.134.63.151
Jul 27 16:43:50 mail amavis[4284]: (04284-01) Passed CLEAN {RelayedInbound}, [141.134.63.151]:62270 [141.134.63.151]  -> , Queue-ID: 6BF3A400736, Message-ID: , mail_id: 5acPQFsgWfiq, Hits: -, size: 2084, queued_as: 057DB4016D5, 555 ms
Jul 27 16:43:50 mail amavis[4284]: (04284-01) get_deadline main_log_entry - deadline in 479.6 s, set to 336.000 s
Jul 27 16:43:50 mail amavis[4284]: (04284-01) prolong_timer main_log_entry: timer 336, was 336, deadline in 479.6 s
Jul 27 16:43:50 mail amavis[4284]: (04284-01) sql begin transaction
Jul 27 16:43:50 mail amavis[4284]: (04284-01) sql: preparing and executing: INSERT INTO msgrcpt (partition_tag, mail_id, rseqnum, rid, is_local, content, ds, rs, bl, wl, bspam_level, smtp_resp) VALUES (?,?,?,?,?,?,?,?,?,?,?,?)
Jul 27 16:43:50 mail amavis[4284]: (04284-01) save_info_final 5acPQFsgWfiq, orig=N, chks=VHB, cont.ty=C, q.type= , q.to=, dsn=N, score=0, Message-ID: <C2E83070-970C-4062-8FC2-C18E46FDD402@nobelsoft.be>, From: 'Nobelsoft <info@nobelsoft.be>', Subject: 'testmail'
Jul 27 16:43:50 mail amavis[4284]: (04284-01) sql: preparing and executing: 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=?
Jul 27 16:43:50 mail amavis[4284]: (04284-01) sql commit
Jul 27 16:43:50 mail amavis[4284]: (04284-01) updating snmp variables
Jul 27 16:43:50 mail amavis[4284]: (04284-01) get_deadline check done - deadline in 479.5 s, set to 336.000 s
Jul 27 16:43:50 mail amavis[4284]: (04284-01) prolong_timer check done: timer 336, was 336, deadline in 479.5 s
Jul 27 16:43:50 mail amavis[4284]: (04284-01) sending SMTP response: "250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 057DB4016D5"
Jul 27 16:43:50 mail amavis[4284]: (04284-01) ESMTP> 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 057DB4016D5
Jul 27 16:43:50 mail postfix/smtp[4523]: 6BF3A400736: to=<web-QaTE8s@mail-tester.com>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.82, delays=0.21/0/0.04/0.57, 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 057DB4016D5)
Jul 27 16:43:50 mail postfix/qmgr[38642]: 6BF3A400736: removed
Jul 27 16:43:50 mail amavis[4284]: (04284-01) switch_to_client_time 480 s, smtp response sent
Jul 27 16:43:50 mail amavis[4284]: (04284-01) TempDir::strip: /var/lib/amavis/tmp/amavis-20160727T164349-04284-vRec0hRy
Jul 27 16:43:50 mail amavis[4284]: (04284-01) rmdir_recursively: /var/lib/amavis/tmp/amavis-20160727T164349-04284-vRec0hRy/parts, excl=1
Jul 27 16:43:50 mail amavis[4284]: (04284-01) size: 2084, TIMING [total 603 ms] - sql-prepare: 17 (3%)3, SMTP greeting: 7 (1%)4, SMTP EHLO: 9 (1%)5, SMTP pre-MAIL: 9 (2%)7, mkdir tempdir: 2 (0%)7, create email.txt: 1 (0%)7, sql-connect: 28 (5%)12, lookup_sql: 60 (10%)22, SMTP pre-DATA-flush: 7 (1%)23, SMTP DATA: 1 (0%)23, check_init: 1 (0%)23, digest_hdr: 27 (5%)28, digest_body_dkim: 4 (1%)29, gen_mail_id: 34 (6%)34, mkdir parts: 13 (2%)36, mime_decode: 81 (13%)50, get-file-type2: 48 (8%)58, parts_decode: 2 (0%)58, check_header: 5 (1%)59, AV-scan-1: 81 (13%)72, lookup_sql: 6 (1%)73, spam-wb-list: 7 (1%)74, decide_mail_destiny: 9 (1%)76, notif-quar: 1 (0%)76, fwd-connect: 26 (4%)80, fwd-mail-pip: 20 (3%)84, fwd-rcpt-pip: 0 (0%)84, fwd-data-chkpnt: 0 (0%)84, write-header: 1 (0%)84, fwd-data-contents: 0 (0%)84, fwd-end-chkpnt: 17 (3%)87, prepare-dsn: 9 (1%)88, main_log_entry: 28 (5%)93, sql-update: 36 (6%)99, update_snmp: 3 (0%)99, SMTP pre-response: 1 (0%)99, SMTP response: 3 (0%)100, unlink-2-files...
Jul 27 16:43:50 mail amavis[4284]: (04284-01) ...: 1 (0%)100, rundown: 1 (0%)100
Jul 27 16:43:50 mail amavis[4284]: (04284-01) idle_proc, 6: was busy, 469.3 ms, total idle 0.004 s, busy 0.599 s
Jul 27 16:43:50 mail amavis[4284]: (04284-01) idle_proc, 5: was idle, 0.2 ms, total idle 0.004 s, busy 0.599 s
Jul 27 16:43:50 mail amavis[4284]: (04284-01) ESMTP< QUIT\r\n
Jul 27 16:43:50 mail amavis[4284]: (04284-01) get_deadline switch_to_my_time(rx SMTP QUIT) - deadline in 480.0 s, set to 336.000 s
Jul 27 16:43:50 mail amavis[4284]: (04284-01) prolong_timer switch_to_my_time(rx SMTP QUIT): timer 336, was 480, deadline in 480.0 s
Jul 27 16:43:50 mail amavis[4284]: (04284-01) ESMTP> 221 2.0.0 [127.0.0.1] amavisd-new closing transmission channel
Jul 27 16:43:50 mail amavis[4284]: (04284-01) switch_to_client_time 480 s, smtp response sent
Jul 27 16:43:50 mail amavis[4284]: (04284-01) SMTP session over, timer stopped
Jul 27 16:43:50 mail amavis[4284]: (04284-01) exiting process_request
Jul 27 16:43:50 mail amavis[4284]: (04284-01) idle_proc, bye: was busy, 12.4 ms, total idle 0.004 s, busy 0.612 s
Jul 27 16:43:50 mail amavis[4284]: (04284-01) load: 99 %, total idle 0.004 s, busy 0.612 s
Jul 27 16:43:51 mail postfix/smtp[4540]: 057DB4016D5: to=<web-QaTE8s@mail-tester.com>, relay=mail-tester.com[94.23.206.89]:25, delay=1.3, delays=0.03/0.06/0.19/1, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 94C6D9F798)
Jul 27 16:43:51 mail postfix/qmgr[38642]: 057DB4016D5: removed
Jul 27 16:44:49 mail postfix/smtpd[4509]: disconnect from d8D863F97.access.telenet.be[141.134.63.151]
Jul 27 16:48:09 mail postfix/anvil[4474]: statistics: max connection rate 2/60s for (smtp:141.134.63.151) at Jul 27 16:43:49
Jul 27 16:48:09 mail postfix/anvil[4474]: statistics: max connection count 1 for (smtp:175.101.76.129) at Jul 27 16:41:23
Jul 27 16:48:09 mail postfix/anvil[4474]: statistics: max cache size 3 at Jul 27 16:43:24

**ZhangHuangbin** · 2016-07-28 11:48:49

ZhangHuangbin
iRedMail Developers
Offline

Registered: 2009-05-06
Posts: 31,165

Re: DKIM Signing not valid after 'passed' test

Did you send email through port 25 or 587?

**Kris01** · 2016-07-28 14:46:49

Kris01
Member
Offline

From: Belgium
Registered: 2016-01-03
Posts: 43

Re: DKIM Signing not valid after 'passed' test

ZhangHuangbin wrote:

Did you send email through port 25 or 587?

I can not use port 25, because it's blocked.

i created port 1025 on my firewall and i do portforward from 1025 to 25 through mailserver.

And i changed it to 587 -> did the test and it works.

thanks

**ZhangHuangbin** · 2016-07-28 17:22:41

ZhangHuangbin
iRedMail Developers
Offline

Registered: 2009-05-06
Posts: 31,165

Re: DKIM Signing not valid after 'passed' test

I'm confused ...

*) Port 25 is used to communicate between mail servers. If your port 25 is blocked, no one can send you email.
*) About the DKIM signing, you must send email through port 587 with default iRedMail settings.

**Kris01** · 2016-07-28 17:28:42

Kris01
Member
Offline

From: Belgium
Registered: 2016-01-03
Posts: 43

Re: DKIM Signing not valid after 'passed' test

Sorry for the confusion.

Port 25 is open on my server.

But my clients can not use port 25.

The reason is that the internet provider in Belgium blocks that port. :-(

Anyway i use 587 and it works.

(Before that my client uses port 1025 and i do a portforward to 25 on my server.)

That's the problem. I can send mails but there not DKIM signed.

for me the problem is fixed. thanks

Aug 5, 2024: iRedMail-1.7.1 has been released.

[ Closed ] DKIM Signing not valid after 'passed' test

Posts: 10

1 Topic by Kris01 2016-07-24 06:10:31

Topic: DKIM Signing not valid after 'passed' test

2 Reply by Kris01 2016-07-24 06:18:54

Re: DKIM Signing not valid after 'passed' test

3 Reply by ZhangHuangbin 2016-07-26 17:16:34

Re: DKIM Signing not valid after 'passed' test

4 Reply by Kris01 2016-07-27 06:51:35

Re: DKIM Signing not valid after 'passed' test

5 Reply by ZhangHuangbin 2016-07-27 09:44:09

Re: DKIM Signing not valid after 'passed' test

6 Reply by Kris01 2016-07-28 01:56:53

Re: DKIM Signing not valid after 'passed' test

7 Reply by ZhangHuangbin 2016-07-28 11:48:49

Re: DKIM Signing not valid after 'passed' test

8 Reply by Kris01 2016-07-28 14:46:49

Re: DKIM Signing not valid after 'passed' test

9 Reply by ZhangHuangbin 2016-07-28 17:22:41

Re: DKIM Signing not valid after 'passed' test

10 Reply by Kris01 2016-07-28 17:28:42

Re: DKIM Signing not valid after 'passed' test

Posts: 10