1

Topic: emails containing docx and xlsx are banned

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

hi,
since my upgrade (from 0.8.5), all emails containing word or excel documents are banned.

LOGS from maillog :
=> xlsx : Jan  5 09:49:18 mail postfix/smtp[3949]: 4843D480075: to=<a.deniau@sigire.fr>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.47, delays=0.06/0/0/0.41, dsn=2.7.0, status=sent (250 2.7.0 Ok, discarded, id=04077-03 - BANNED: .dat,printerSettings1.bin)
=> docx :  Jan  5 10:14:38 mail postfix/smtp[5292]: 19EC7480075: to=<a.deniau@sigire.fr>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.38, delays=0.06/0/0/0.31, dsn=2.7.0, status=sent (250 2.7.0 Ok, discarded, id=05361-10 - BANNED: _rels)

BANNED_FILENAME :
$banned_filename_re = new_RE(
### BLOCKED ANYWHERE
# qr'^UNDECIPHERABLE$',  # is or contains any undecipherable components
  qr'^\.(exe-ms|dll)$',                   # banned file(1) types, rudimentary
# qr'^\.(exe|lha|cab|dll)$',              # banned file(1) types

### BLOCK THE FOLLOWING, EXCEPT WITHIN UNIX ARCHIVES:
# [ qr'^\.(gz|bz2)$'             => 0 ],  # allow any in gzip or bzip2
  [ qr'^\.(rpm|cpio|tar)$'       => 0 ],  # allow any in Unix-type archives

  qr'.\.(pif|scr)$'i,                     # banned extensions - rudimentary
# qr'^\.zip$',                            # block zip type

### BLOCK THE FOLLOWING, EXCEPT WITHIN ARCHIVES:
# [ qr'^\.(zip|rar|arc|arj|zoo)$'=> 0 ],  # allow any within these archives

  qr'^application/x-msdownload$'i,        # block these MIME types
  qr'^application/x-msdos-program$'i,
  qr'^application/hta$'i,

# qr'^message/partial$'i,         # rfc2046 MIME type
# qr'^message/external-body$'i,   # rfc2046 MIME type

# qr'^(application/x-msmetafile|image/x-wmf)$'i,  # Windows Metafile MIME type
# qr'^\.wmf$',                            # Windows Metafile file(1) type

  # block certain double extensions in filenames
  qr'^(?!cid:).*\.[^./]*[A-Za-z][^./]*\.\s*(exe|vbs|pif|scr|bat|cmd|com|cpl|dll)[.\s]*$'i,

# qr'\{[0-9a-f]{8}(-[0-9a-f]{4}){3}-[0-9a-f]{12}\}?'i, # Class ID CLSID, strict
# qr'\{[0-9a-z]{4,}(-[0-9a-z]{4,}){0,7}\}?'i, # Class ID extension CLSID, loose

  qr'.\.(exe|vbs|pif|scr|cpl)$'i,             # banned extension - basic
# qr'.\.(exe|vbs|pif|scr|cpl|bat|cmd|com)$'i, # banned extension - basic+cmd
# qr'.\.(ade|adp|app|bas|bat|chm|cmd|com|cpl|crt|emf|exe|fxp|grp|hlp|hta|
#        inf|ini|ins|isp|js|jse|lib|lnk|mda|mdb|mde|mdt|mdw|mdz|msc|msi|
#        msp|mst|ocx|ops|pcd|pif|prg|reg|scr|sct|shb|shs|sys|vb|vbe|vbs|vxd|
#        wmf|wsc|wsf|wsh)$'ix,                # banned extensions - long
# qr'.\.(asd|asf|asx|url|vcs|wmd|wmz)$'i,     # consider also
# qr'.\.(ani|cur|ico)$'i,                 # banned cursors and icons filename
# qr'^\.ani$',                            # banned animated cursor file(1) type
# qr'.\.(mim|b64|bhx|hqx|xxe|uu|uue)$'i,  # banned extension - WinZip vulnerab.
);


BANNED NAMEPATH :
        $banned_namepath_re = new_RE(
    #[qr'T=(rar|arc|arj|zoo|gz|bz2)(,|  )'xmi => 'DISCARD'], # Compressed file types
    [qr'T=x-(msdownload|msdos-program|msmetafile)(,|    )'xmi => 'DISCARD'],
    [qr'T=(hta)(,|      )'xmi => 'DISCARD'],
    # Dangerous mime types
    [qr'T=(9|386|LeChiffre|aaa|abc|aepl|ani|aru|atm|aut|b64|bat|bhx|bin|bkd|blf|bll|bmw|boo|bps|bqf|breaking_bad|buk|bup|bxz|cc|ccc|ce0|ceo|cfxxe|chm|cih|cla|class|cmd|com|cpl|crinf|crjoker|crypt|cryptolocker|cryptowall|ctbl|cxq|cyw|dbd|delf|dev|dlb|dli|dll|dllx|dom|drv|dx|dxz|dyv|dyz|ecc|exe|exe-ms|exe1|exe_renamed|exx|ezt|ezz|fag|fjl|fnr|fuj|good|gzquar|hlp|hlw|hqx|hsq|hts|iva|iws|jar|js|kcd|keybtc@inbox_com|let|lik|lkh|lnk|locky|lok|lol!|lpaq5|magic|mfu|micro|mim|mjg|mjz|nls|oar|ocx|osa|ozd|pcx|pgm|php2|php3|pid|pif|plc|pr|pzdc|qit|qrn|r5a|rhk|rna|rsc_tmp|s7p|scr|shs|ska|smm|smtmp|sop|spam|ssy|swf|sys|tko|tps|tsa|tti|ttt|txs|upa|uu|uue|uzy|vb|vba|vbe|vbs|vbx|vexe|vxd|vzr|wlpginstall|ws|wsc|wsf|wsh|wss|xdu|xir|xlm|xlv|xnt|xnxx|xtbl|xxe|xxx|xyz|zix|zvz|zzz)(,|    )'xmi => 'DISCARD'],
    # Dangerous file name extensions
    [qr'N=.*.(9|386|LeChiffre|aaa|abc|aepl|ani|aru|atm|aut|b64|bat|bhx|bin|bkd|blf|bll|bmw|boo|bps|bqf|breaking_bad|buk|bup|bxz|cc|ccc|ce0|ceo|cfxxe|chm|cih|cla|class|cmd|com|cpl|crinf|crjoker|crypt|cryptolocker|cryptowall|ctbl|cxq|cyw|dbd|delf|dev|dlb|dli|dll|dllx|dom|drv|dx|dxz|dyv|dyz|ecc|exe|exe-ms|exe1|exe_renamed|exx|ezt|ezz|fag|fjl|fnr|fuj|good|gzquar|hlp|hlw|hqx|hsq|hts|iva|iws|jar|js|kcd|keybtc@inbox_com|let|lik|lkh|lnk|locky|lok|lol!|lpaq5|magic|mfu|micro|mim|mjg|mjz|nls|oar|ocx|osa|ozd|pcx|pgm|php2|php3|pid|pif|plc|pr|pzdc|qit|qrn|r5a|rhk|rna|rsc_tmp|s7p|scr|shs|ska|smm|smtmp|sop|spam|ssy|swf|sys|tko|tps|tsa|tti|ttt|txs|upa|uu|uue|uzy|vb|vba|vbe|vbs|vbx|vexe|vxd|vzr|wlpginstall|ws|wsc|wsf|wsh|wss|xdu|xir|xlm|xlv|xnt|xnxx|xtbl|xxe|xxx|xyz|zix|zvz|zzz)$'xmi => 'DISCARD'],
);

i don't know how to resolve this...  i'm new to iredmail (replaced the guy how installed it).

thanks for your help

----

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

2

Re: emails containing docx and xlsx are banned

Remove '|bin' in variable '$banned_namepath_re =', then restart amavisd service.

3

Re: emails containing docx and xlsx are banned

thanks, it solved my problem for xlsx files.

but i still have those for docx :
Jan  5 10:14:38 mail postfix/smtp[5292]: 19EC7480075: to=<a.deniau@sigire.fr>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.38, delays=0.06/0/0/0.31, dsn=2.7.0, status=sent (250 2.7.0 Ok, discarded, id=05361-10 - BANNED: _rels)

4

Re: emails containing docx and xlsx are banned

a.deniau wrote:

Jan  5 10:14:38 mail postfix/smtp[5292]: 19EC7480075: to=<a.deniau@sigire.fr>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.38, delays=0.06/0/0/0.31, dsn=2.7.0, status=sent (250 2.7.0 Ok, discarded, id=05361-10 - BANNED: _rels)

No other log? It should content file name or file extension name in log.

5

Re: emails containing docx and xlsx are banned

here is the complete log (from maillog) :

Jan 10 10:04:48 mail policyd: rcpt=382594, module=bypass, host=212.27.42.1 (smtp1-g21.free.fr), from=xxxxxx@free.fr, to=xxxxx@xxxxxx.com, size=26331
Jan 10 10:04:48 mail postfix/smtpd[27747]: 07A4248003F: client=smtp1-g21.free.fr[212.27.42.1]
Jan 10 10:04:48 mail postfix/cleanup[27342]: 07A4248003F: message-id=<753413227.189226393.1515575084734.JavaMail.root@zimbra22-e3>
Jan 10 10:04:48 mail policyd: rcpt=397093, throttle=update(a), host=212.27.42.1, from=xxxxxx@free.fr, to=xxxxxl@xxxxxx.com, size=26297/15728640, quota=54955/250000000, count=2/512(5), rcpt=2/3600(5), threshold=0%|0%|0%
Jan 10 10:04:48 mail postfix/qmgr[8240]: 07A4248003F: from=<xxxxx@free.fr>, size=26509, nrcpt=1 (queue active)
Jan 10 10:04:48 mail postfix/smtpd[27747]: disconnect from smtp1-g21.free.fr[212.27.42.1]
Jan 10 10:04:48 mail amavis[27985]: (27985-04) Blocked BANNED (_rels) {DiscardedInbound,Quarantined}, [212.27.42.1]:32590 [212.27.42.1] <xxxxxxx@free.fr> -> , quarantine: J4VWsfWr9sa8, Queue-ID: 07A4248003F, Message-ID: , mail_id: J4VWsfWr9sa8, Hits: -, size: 26509, 479 ms
Jan 10 10:04:48 mail postfix/smtp[28022]: 07A4248003F: to=<xxxxxx@xxxxxx.com>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.6, delays=0.06/0/0/0.54, dsn=2.7.0, status=sent (250 2.7.0 Ok, discarded, id=27985-04 - BANNED: _rels)
Jan 10 10:04:48 mail postfix/qmgr[8240]: 07A4248003F: removed

nb : i've altered email addresses from this log

6

Re: emails containing docx and xlsx are banned

Turn on debug mode in AMavisd and trigger this ban again, you will find the file name and file extension in log.
FYI: https://docs.iredmail.org/debug.amavisd.html

7

Re: emails containing docx and xlsx are banned

here is the log with debug=5

Jan 10 15:20:20 mail postfix/smtpd[7662]: connect from mail.sigire.net[127.0.0.1]
Jan 10 15:20:20 mail postfix/smtpd[7662]: D6DB2480091: client=mail.sigire.net[127.0.0.1], sasl_method=LOGIN, sasl_username=test_migration@sigire.biz
Jan 10 15:20:20 mail postfix/cleanup[7102]: D6DB2480091: message-id=<d118c550d658cdfef7800177a9ac6d59@sigire.biz>
Jan 10 15:20:20 mail policyd: rcpt=397856, throttle=clear(a), host=127.0.0.1, from=test_migration@sigire.biz, to=a.deniau@sigire.fr, size=16547/15728640, quota=16547/250000000, count=1/512(14), rcpt=1/3600(15), threshold=0%|0%|0%, sasl_username=test_migration@sigire.biz
Jan 10 15:20:20 mail postfix/qmgr[8240]: D6DB2480091: from=<test_migration@sigire.biz>, size=16733, nrcpt=1 (queue active)
Jan 10 15:20:20 mail roundcube: <jqmm2is4> User test_migration@sigire.biz [92.154.96.248]; Message for a.deniau@sigire.fr; 250: 2.0.0 Ok: queued as D6DB2480091
Jan 10 15:20:20 mail postfix/smtpd[7662]: disconnect from mail.sigire.net[127.0.0.1]
Jan 10 15:20:20 mail amavis[7878]: Net::Server: 2018/01/10-15:20:20 CONNECT TCP Peer: "127.0.0.1:36478" Local: "127.0.0.1:10024"
Jan 10 15:20:20 mail amavis[7878]: loaded base policy bank
Jan 10 15:20:20 mail amavis[7878]: lookup_ip_acl (inet_acl) arr.obj: key="127.0.0.1" matches "127.0.0.1", result=1
Jan 10 15:20:20 mail amavis[7878]: process_request: fileno sock=12, STDIN=0, STDOUT=1
Jan 10 15:20:20 mail amavis[7878]: get_deadline switch_to_my_time(new request) - deadline in 480.0 s, set to 336.000 s
Jan 10 15:20:20 mail amavis[7878]: prolong_timer switch_to_my_time(new request): timer 336, was 0, deadline in 480.0 s
Jan 10 15:20:20 mail amavis[7878]: process_request: suggested_protocol="" on a TCP socket
Jan 10 15:20:20 mail amavis[7878]: (07878-01) SMTP> 220 [127.0.0.1] ESMTP amavisd-new service ready
Jan 10 15:20:20 mail amavis[7878]: (07878-01) switch_to_client_time 480 s, smtp response sent
Jan 10 15:20:20 mail amavis[7878]: (07878-01) idle_proc, 4: was busy, 6.3 ms, total idle 0.000 s, busy 0.006 s
Jan 10 15:20:20 mail amavis[7878]: (07878-01) smtp readline: read 22 bytes, new size: 22
Jan 10 15:20:20 mail amavis[7878]: (07878-01) idle_proc, 5: was idle, 0.3 ms, total idle 0.000 s, busy 0.006 s
Jan 10 15:20:20 mail amavis[7878]: (07878-01) SMTP< EHLO mail.sigire.net\r\n
Jan 10 15:20:20 mail amavis[7878]: (07878-01) get_deadline switch_to_my_time(rx SMTP EHLO) - deadline in 480.0 s, set to 336.000 s
Jan 10 15:20:20 mail amavis[7878]: (07878-01) prolong_timer switch_to_my_time(rx SMTP EHLO): timer 336, was 480, deadline in 480.0 s
Jan 10 15:20:20 mail amavis[7878]: (07878-01) ESMTP> 250-[127.0.0.1]
Jan 10 15:20:20 mail amavis[7878]: (07878-01) ESMTP> 250-VRFY
Jan 10 15:20:20 mail amavis[7878]: (07878-01) ESMTP> 250-PIPELINING
Jan 10 15:20:20 mail amavis[7878]: (07878-01) ESMTP> 250-SIZE
Jan 10 15:20:20 mail amavis[7878]: (07878-01) ESMTP> 250-ENHANCEDSTATUSCODES
Jan 10 15:20:20 mail amavis[7878]: (07878-01) ESMTP> 250-8BITMIME
Jan 10 15:20:20 mail amavis[7878]: (07878-01) ESMTP> 250-DSN
Jan 10 15:20:20 mail amavis[7878]: (07878-01) ESMTP> 250 XFORWARD NAME ADDR PORT PROTO HELO IDENT SOURCE
Jan 10 15:20:20 mail amavis[7878]: (07878-01) switch_to_client_time 480 s, smtp response sent
Jan 10 15:20:20 mail amavis[7878]: (07878-01) idle_proc, 6: was busy, 2.8 ms, total idle 0.000 s, busy 0.009 s
Jan 10 15:20:20 mail amavis[7878]: (07878-01) smtp readline: read 249 bytes, new size: 249
Jan 10 15:20:20 mail amavis[7878]: (07878-01) idle_proc, 5: was idle, 0.2 ms, total idle 0.001 s, busy 0.009 s
Jan 10 15:20:20 mail amavis[7878]: (07878-01) ESMTP< XFORWARD NAME=mail.sigire.net ADDR=127.0.0.1 PORT=34248\r\n
Jan 10 15:20:20 mail amavis[7878]: (07878-01) get_deadline switch_to_my_time(rx SMTP XFORWARD) - deadline in 480.0 s, set to 336.000 s
Jan 10 15:20:20 mail amavis[7878]: (07878-01) prolong_timer switch_to_my_time(rx SMTP XFORWARD): timer 336, was 480, deadline in 480.0 s
Jan 10 15:20:20 mail amavis[7878]: (07878-01) ESMTP> 250 2.5.0 Ok XFORWARD
Jan 10 15:20:20 mail amavis[7878]: (07878-01) switch_to_client_time 480 s, smtp response sent
Jan 10 15:20:20 mail amavis[7878]: (07878-01) idle_proc, 6: was busy, 0.6 ms, total idle 0.001 s, busy 0.010 s
Jan 10 15:20:20 mail amavis[7878]: (07878-01) idle_proc, 5: was idle, 0.1 ms, total idle 0.001 s, busy 0.010 s
Jan 10 15:20:20 mail amavis[7878]: (07878-01) ESMTP< XFORWARD PROTO=ESMTP HELO=mail.sigire.net IDENT=D6DB2480091 SOURCE=LOCAL\r\n
Jan 10 15:20:20 mail amavis[7878]: (07878-01) get_deadline switch_to_my_time(rx SMTP XFORWARD) - deadline in 480.0 s, set to 336.000 s
Jan 10 15:20:20 mail amavis[7878]: (07878-01) prolong_timer switch_to_my_time(rx SMTP XFORWARD): timer 336, was 480, deadline in 480.0 s
Jan 10 15:20:20 mail amavis[7878]: (07878-01) ESMTP> 250 2.5.0 Ok XFORWARD
Jan 10 15:20:20 mail amavis[7878]: (07878-01) switch_to_client_time 480 s, smtp response sent
Jan 10 15:20:20 mail amavis[7878]: (07878-01) idle_proc, 6: was busy, 0.6 ms, total idle 0.001 s, busy 0.010 s
Jan 10 15:20:20 mail amavis[7878]: (07878-01) idle_proc, 5: was idle, 0.1 ms, total idle 0.001 s, busy 0.010 s
Jan 10 15:20:20 mail amavis[7878]: (07878-01) ESMTP< MAIL FROM:<test_migration@sigire.biz> SIZE=16733\r\n
Jan 10 15:20:20 mail amavis[7878]: (07878-01) get_deadline switch_to_my_time(rx SMTP MAIL) - deadline in 480.0 s, set to 336.000 s
Jan 10 15:20:20 mail amavis[7878]: (07878-01) prolong_timer switch_to_my_time(rx SMTP MAIL): timer 336, was 480, deadline in 480.0 s
Jan 10 15:20:20 mail amavis[7878]: (07878-01) check_mail_begin_task: task_count=1
Jan 10 15:20:20 mail amavis[7878]: (07878-01) TempDir::prepare_dir: created directory /var/spool/amavisd/tmp/amavis-20180110T152020-07878-qnoLF3bb
Jan 10 15:20:20 mail amavis[7878]: (07878-01) TempDir::prepare_file: creating file /var/spool/amavisd/tmp/amavis-20180110T152020-07878-qnoLF3bb/email.txt
Jan 10 15:20:20 mail amavis[7878]: (07878-01) TempDir::prepare_file: layers: unix,perlio
Jan 10 15:20:20 mail amavis[7878]: (07878-01) lookup_ip_acl (client_ipaddr_policy) arr.obj: key="127.0.0.1" matches "127.0.0.0/8", result=1
Jan 10 15:20:20 mail amavis[7878]: (07878-01) loaded policy bank "MYNETS"
Jan 10 15:20:20 mail amavis[7878]: (07878-01) lookup [debug_sender] => undef, "test_migration@sigire.biz" does not match
Jan 10 15:20:20 mail amavis[7878]: (07878-01) mesage size set to a declared size 16733
Jan 10 15:20:20 mail amavis[7878]: (07878-01) ESMTP> 250 2.1.0 Sender <test_migration@sigire.biz> OK
Jan 10 15:20:20 mail amavis[7878]: (07878-01) switch_to_client_time 480 s, smtp response sent
Jan 10 15:20:20 mail amavis[7878]: (07878-01) idle_proc, 6: was busy, 17.3 ms, total idle 0.001 s, busy 0.028 s
Jan 10 15:20:20 mail amavis[7878]: (07878-01) idle_proc, 5: was idle, 0.1 ms, total idle 0.001 s, busy 0.028 s
Jan 10 15:20:20 mail amavis[7878]: (07878-01) ESMTP< RCPT TO:<a.deniau@sigire.fr> ORCPT=rfc822;a.deniau@sigire.fr\r\n
Jan 10 15:20:20 mail amavis[7878]: (07878-01) get_deadline switch_to_my_time(rx SMTP RCPT) - deadline in 480.0 s, set to 336.000 s
Jan 10 15:20:20 mail amavis[7878]: (07878-01) prolong_timer switch_to_my_time(rx SMTP RCPT): timer 336, was 480, deadline in 480.0 s
Jan 10 15:20:20 mail amavis[7878]: (07878-01) lookup => undef, "a.deniau@sigire.fr", no lookup tables
Jan 10 15:20:20 mail amavis[7878]: (07878-01) lookup_acl(a.deniau@sigire.fr), no match
Jan 10 15:20:20 mail amavis[7878]: (07878-01) lookup [local_domains] => undef, "a.deniau@sigire.fr" does not match
Jan 10 15:20:20 mail amavis[7878]: (07878-01) query_keys: a.deniau@sigire.fr, @sigire.fr, @.sigire.fr, @.fr, @.
Jan 10 15:20:20 mail amavis[7878]: (07878-01) lookup_ldap "a.deniau@sigire.fr", query keys: "a.deniau@sigire.fr", "@sigire.fr", "@.sigire.fr", "@.fr", "@.", base: o=domains,dc=mailadmin,dc=sigire, filter: (&(objectClass=mailUser)(objectClass=amavisAccount)(accountStatus=active)(|(mail=%m)(shadowAddress=%m)))
Jan 10 15:20:20 mail amavis[7878]: (07878-01) ldap begin_work
Jan 10 15:20:20 mail amavis[7878]: (07878-01) Connecting to LDAP server
Jan 10 15:20:20 mail amavis[7878]: (07878-01) connect_to_ldap: trying 127.0.0.1
Jan 10 15:20:20 mail amavis[7878]: (07878-01) connect_to_ldap: connected to 127.0.0.1
Jan 10 15:20:20 mail amavis[7878]: (07878-01) connect_to_ldap: bind cn=vmail,dc=mailadmin,dc=sigire succeeded
Jan 10 15:20:20 mail amavis[7878]: (07878-01) lookup_ldap: searching base="o=domains,dc=mailadmin,dc=sigire", scope="sub", filter="(&(objectClass=mailUser)(objectClass=amavisAccount)(accountStatus=active)(|(|(mail=a.deniau@sigire.fr)(mail=@sigire.fr)(mail=@.sigire.fr)(mail=@.fr)(mail=@.))(|(shadowAddress=a.deniau@sigire.fr)(shadowAddress=@sigire.fr)(shadowAddress=@.sigire.fr)(shadowAddress=@.fr)(shadowAddress=@.))))"
Jan 10 15:20:20 mail amavis[7878]: (07878-01) lookup_ldap, "a.deniau@sigire.fr" no match
Jan 10 15:20:20 mail amavis[7878]: (07878-01) lookup_ldap_attr(amavisMessageSizeLimit), "a.deniau@sigire.fr" no matching entries
Jan 10 15:20:20 mail amavis[7878]: (07878-01) lookup [message_size_limit] => undef, "a.deniau@sigire.fr" does not match
Jan 10 15:20:20 mail amavis[7878]: (07878-01) ESMTP> 250 2.1.5 Recipient <a.deniau@sigire.fr> OK
Jan 10 15:20:20 mail amavis[7878]: (07878-01) switch_to_client_time 480 s, smtp response sent
Jan 10 15:20:20 mail amavis[7878]: (07878-01) idle_proc, 6: was busy, 7.7 ms, total idle 0.001 s, busy 0.035 s
Jan 10 15:20:20 mail amavis[7878]: (07878-01) idle_proc, 5: was idle, 0.1 ms, total idle 0.001 s, busy 0.035 s
Jan 10 15:20:20 mail amavis[7878]: (07878-01) ESMTP< DATA\r\n
Jan 10 15:20:20 mail amavis[7878]: (07878-01) get_deadline switch_to_my_time(rx SMTP DATA) - deadline in 480.0 s, set to 336.000 s
Jan 10 15:20:20 mail amavis[7878]: (07878-01) prolong_timer switch_to_my_time(rx SMTP DATA): timer 336, was 480, deadline in 480.0 s
Jan 10 15:20:20 mail amavis[7878]: (07878-01) ESMTP::10024 /var/spool/amavisd/tmp/amavis-20180110T152020-07878-qnoLF3bb: <test_migration@sigire.biz> -> <a.deniau@sigire.fr> SIZE=16733 Received: from mail.sigire.net ([127.0.0.1]) by localhost (mail.sigire.net [127.0.0.1]) (amavisd-new, port 10024) with ESMTP for <a.deniau@sigire.fr>; Wed, 10 Jan 2018 15:20:20 +0100 (CET)
Jan 10 15:20:20 mail amavis[7878]: (07878-01) ESMTP> 354 End data with <CR><LF>.<CR><LF>
Jan 10 15:20:20 mail amavis[7878]: (07878-01) switch_to_client_time 480 s, smtp response sent
Jan 10 15:20:20 mail amavis[7878]: (07878-01) switch_to_client_time 480 s, receiving data
Jan 10 15:20:20 mail amavis[7878]: (07878-01) smtp copy: read 16742 bytes into buffer, new size: 16742
Jan 10 15:20:20 mail amavis[7878]: (07878-01) smtp copy: 6 bytes still buffered at end
Jan 10 15:20:20 mail amavis[7878]: (07878-01) get_deadline switch_to_my_time(rx data-end) - deadline in 480.0 s, set to 336.000 s
Jan 10 15:20:20 mail amavis[7878]: (07878-01) prolong_timer switch_to_my_time(rx data-end): timer 336, was 480, deadline in 480.0 s
Jan 10 15:20:20 mail amavis[7878]: (07878-01) ESMTP< .<CR><LF>
Jan 10 15:20:20 mail amavis[7878]: (07878-01) get_deadline get_body_digest - deadline in 480.0 s, set to 30.000 s
Jan 10 15:20:20 mail amavis[7878]: (07878-01) get_deadline digest_pre - deadline in 480.0 s, set to 336.000 s
Jan 10 15:20:20 mail amavis[7878]: (07878-01) prolong_timer digest_pre: timer 336, was 336, deadline in 480.0 s
Jan 10 15:20:20 mail amavis[7878]: (07878-01) get_body_digest: reading header section from memory
Jan 10 15:20:20 mail amavis[7878]: (07878-01) get_body_digest: sending h/b separator to DKIM
Jan 10 15:20:20 mail amavis[7878]: (07878-01) get_deadline digest_hdr - deadline in 480.0 s, set to 336.000 s
Jan 10 15:20:20 mail amavis[7878]: (07878-01) prolong_timer digest_hdr: timer 336, was 336, deadline in 480.0 s
Jan 10 15:20:20 mail amavis[7878]: (07878-01) get_body_digest: reading mail body from memory
Jan 10 15:20:20 mail amavis[7878]: (07878-01) get_deadline digest_body - deadline in 480.0 s, set to 336.000 s
Jan 10 15:20:20 mail amavis[7878]: (07878-01) prolong_timer digest_body: timer 336, was 336, deadline in 480.0 s
Jan 10 15:20:20 mail amavis[7878]: (07878-01) get_body_digest: message size 16733, header+sep 530, body 16203
Jan 10 15:20:20 mail amavis[7878]: (07878-01) body type (ESMTP BODY): unlabeled, good (h=0, b=0)
Jan 10 15:20:20 mail amavis[7878]: (07878-01) body hash: 20b89445fb5a561a69997b66fd6f22ce
Jan 10 15:20:20 mail amavis[7878]: (07878-01) ip_from_received: 127.0.0.1
Jan 10 15:20:20 mail amavis[7878]: (07878-01) ip_trace: 127.0.0.1
Jan 10 15:20:20 mail amavis[7878]: (07878-01) lookup_ip_acl (public_nets) arr.obj: key="127.0.0.1" matches "!127.0.0.0/8", result=0
Jan 10 15:20:20 mail amavis[7878]: (07878-01) Original mail size: 16733; quota set to: 8366500 bytes (fmin=5, fmax=500, qmin=102400, qmax=314572800)
Jan 10 15:20:20 mail amavis[7878]: (07878-01) sql begin, nontransaction
Jan 10 15:20:20 mail amavis[7878]: (07878-01) Connecting to SQL database server
Jan 10 15:20:20 mail amavis[7878]: (07878-01) connect_to_sql: trying 'DBI:mysql:database=amavisd;host=127.0.0.1;port=3306'
Jan 10 15:20:20 mail amavis[7878]: (07878-01) connect_to_sql: 'DBI:mysql:database=amavisd;host=127.0.0.1;port=3306' succeeded
Jan 10 15:20:20 mail amavis[7878]: (07878-01) sql: preparing and executing (2 args): SELECT id FROM maddr WHERE partition_tag=? AND email=?
Jan 10 15:20:20 mail amavis[7878]: (07878-01) save_info_preliminary LMyyEp-aowzz, sender id: 710370, test_migration@sigire.biz, exists
Jan 10 15:20:20 mail amavis[7878]: (07878-01) sql begin, nontransaction
Jan 10 15:20:20 mail amavis[7878]: (07878-01) sql: executing clause (2 args): SELECT id FROM maddr WHERE partition_tag=? AND email=?
Jan 10 15:20:20 mail amavis[7878]: (07878-01) save_info_preliminary LMyyEp-aowzz, recip id: 710371, a.deniau@sigire.fr, exists
Jan 10 15:20:20 mail amavis[7878]: (07878-01) sql begin transaction
Jan 10 15:20:20 mail amavis[7878]: (07878-01) sql: preparing and executing (11 args): INSERT INTO msgs (partition_tag, mail_id, secret_id, am_id, time_num, time_iso, sid, policy, client_addr, size, host) VALUES (?,?,?,?,?,?,?,?,?,?,?)
Jan 10 15:20:20 mail amavis[7878]: (07878-01) sql commit
Jan 10 15:20:21 mail amavis[7878]: (07878-01) Checking: LMyyEp-aowzz MYNETS [127.0.0.1] <test_migration@sigire.biz> -> <a.deniau@sigire.fr>
Jan 10 15:20:21 mail amavis[7878]: (07878-01) 2822.From: <test_migration@sigire.biz>
Jan 10 15:20:21 mail amavis[7878]: (07878-01) lookup_ldap_attr(amavisLocal), "a.deniau@sigire.fr" no matching entries
Jan 10 15:20:21 mail amavis[7878]: (07878-01) lookup_acl(a.deniau@sigire.fr), no match
Jan 10 15:20:21 mail amavis[7878]: (07878-01) lookup [local_domains] => undef, "a.deniau@sigire.fr" does not match
Jan 10 15:20:21 mail amavis[7878]: (07878-01) lookup_ldap_attr(amavisBypassVirusChecks), "a.deniau@sigire.fr" no matching entries
Jan 10 15:20:21 mail amavis[7878]: (07878-01) lookup [bypass_virus_checks] => undef, "a.deniau@sigire.fr" does not match
Jan 10 15:20:21 mail amavis[7878]: (07878-01) lookup_ldap_attr(amavisBypassBannedChecks), "a.deniau@sigire.fr" no matching entries
Jan 10 15:20:21 mail amavis[7878]: (07878-01) lookup [bypass_banned_checks] => undef, "a.deniau@sigire.fr" does not match
Jan 10 15:20:21 mail amavis[7878]: (07878-01) lookup_ldap_attr(amavisBypassSpamChecks), "a.deniau@sigire.fr" no matching entries
Jan 10 15:20:21 mail amavis[7878]: (07878-01) lookup [bypass_spam_checks] => undef, "a.deniau@sigire.fr" does not match
Jan 10 15:20:21 mail amavis[7878]: (07878-01) Extracting mime components from a string
Jan 10 15:20:21 mail amavis[7878]: (07878-01) Issued a new file name: p001
Jan 10 15:20:21 mail amavis[7878]: (07878-01) Issued a new file name: p002
Jan 10 15:20:21 mail amavis[7878]: (07878-01) Issued a new pseudo part: p003
Jan 10 15:20:21 mail amavis[7878]: (07878-01) p003 1 Content-Type: multipart/mixed
Jan 10 15:20:21 mail amavis[7878]: (07878-01) Charging 12 bytes to remaining quota 8366500 (out of 8366500, (0%)) - by mime_decode
Jan 10 15:20:21 mail amavis[7878]: (07878-01) p001 1/1 Content-Type: text/plain, size: 12 B, name:
Jan 10 15:20:21 mail amavis[7878]: (07878-01) reparenting p001 from p000 to p003
Jan 10 15:20:21 mail amavis[7878]: (07878-01) Charging 11518 bytes to remaining quota 8366488 (out of 8366500, (0%)) - by mime_decode
Jan 10 15:20:21 mail amavis[7878]: (07878-01) p002 1/2 Content-Type: application/vnd.openxmlformats-officedocument.wordprocessingml.document, size: 11518 B, name: Test.docx
Jan 10 15:20:21 mail amavis[7878]: (07878-01) reparenting p002 from p000 to p003
Jan 10 15:20:21 mail amavis[7878]: (07878-01) get_deadline mime_decode - deadline in 479.9 s, set to 336.000 s
Jan 10 15:20:21 mail amavis[7878]: (07878-01) prolong_timer mime_decode: timer 336, was 336, deadline in 479.9 s
Jan 10 15:20:21 mail amavis[7878]: (07878-01) get_deadline mime_decode-1 - deadline in 479.9 s, set to 336.000 s
Jan 10 15:20:21 mail amavis[7878]: (07878-01) prolong_timer mime_decode-1: timer 336, was 336, deadline in 479.9 s
Jan 10 15:20:21 mail amavis[7878]: (07878-01) inspect_dsn: parts: multipart/mixed, text/plain, application/vnd.openxmlformats-officedocument.wordprocessingml.document
Jan 10 15:20:21 mail amavis[7878]: (07878-01) inspect_dsn: not a bounce
Jan 10 15:20:21 mail amavis[7878]: (07878-01) get_deadline dsn_parse - deadline in 479.9 s, set to 336.000 s
Jan 10 15:20:21 mail amavis[7878]: (07878-01) prolong_timer dsn_parse: timer 336, was 336, deadline in 479.9 s
Jan 10 15:20:21 mail amavis[7878]: (07878-01) decode_parts: level=1, #parts=3 : p001, p002, p003
Jan 10 15:20:21 mail amavis[7878]: (07878-01) running file(1) on 2 files, arglist size 23
Jan 10 15:20:21 mail amavis[7878]: (07878-01) run_command: [7905] /usr/bin/file p001 p002 </dev/null 2>&1
Jan 10 15:20:21 mail amavis[7905]: (07878-01) open_on_specific_fd: target fd0 closing, to become < /dev/null
Jan 10 15:20:21 mail amavis[7905]: (07878-01) open_on_specific_fd: target fd1 closing, to become (65) &=17
Jan 10 15:20:21 mail amavis[7905]: (07878-01) open_on_specific_fd: target fd1 dup2 from fd17 (65) &=17
Jan 10 15:20:21 mail amavis[7905]: (07878-01) open_on_specific_fd: source fd17 closed
Jan 10 15:20:21 mail amavis[7905]: (07878-01) open_on_specific_fd: target fd2 closing, to become (65) &1
Jan 10 15:20:21 mail amavis[7905]: (07878-01) open_on_specific_fd: target fd2 dup2 from fd1 (65) &1
Jan 10 15:20:21 mail amavis[7878]: (07878-01) result line from file(1): p001: ASCII text, with no line terminators\n
Jan 10 15:20:21 mail amavis[7878]: (07878-01) lookup_re("ASCII text, with no line terminators") matches key "(?i-xsm:^(ASCII|text)\b)", result="asc"
Jan 10 15:20:21 mail amavis[7878]: (07878-01) lookup [map_full_type_to_short_type] => true,  "ASCII text, with no line terminators" matches, result="asc", matching_key="(?i-xsm:^(ASCII|text)\134b)"
Jan 10 15:20:21 mail amavis[7878]: (07878-01) File-type of p001: ASCII text, with no line terminators; (asc)
Jan 10 15:20:21 mail amavis[7878]: (07878-01) result line from file(1): p002: Zip archive data, at least v2.0 to extract\n
Jan 10 15:20:21 mail amavis[7878]: (07878-01) lookup_re("Zip archive data, at least v2.0 to extract") matches key "(?i-xsm:^Zip archive\b)", result="zip"
Jan 10 15:20:21 mail amavis[7878]: (07878-01) lookup [map_full_type_to_short_type] => true,  "Zip archive data, at least v2.0 to extract" matches, result="zip", matching_key="(?i-xsm:^Zip archive\134b)"
Jan 10 15:20:21 mail amavis[7878]: (07878-01) File-type of p002: Zip archive data, at least v2.0 to extract; (zip)
Jan 10 15:20:21 mail amavis[7878]: (07878-01) decompose_part: p001 - atomic
Jan 10 15:20:21 mail amavis[7878]: (07878-01) Expanding 7-Zip archive p002
Jan 10 15:20:21 mail amavis[7878]: (07878-01) get_deadline do_7zip_pre - deadline in 479.9 s, set to 336.000 s
Jan 10 15:20:21 mail amavis[7878]: (07878-01) prolong_timer do_7zip_pre: timer 336, was 336, deadline in 479.9 s
Jan 10 15:20:21 mail amavis[7878]: (07878-01) run_command: [7906] /usr/bin/7za l -slt -w/var/spool/amavisd/tmp/amavis-20180110T152020-07878-qnoLF3bb/parts -- /var/spool/amavisd/tmp/amavis-20180110T152020-07878-qnoLF3bb/parts/p002 </dev/null 2>&1
Jan 10 15:20:21 mail amavis[7906]: (07878-01) open_on_specific_fd: target fd0 closing, to become < /dev/null
Jan 10 15:20:21 mail amavis[7906]: (07878-01) open_on_specific_fd: target fd1 closing, to become (65) &=17
Jan 10 15:20:21 mail amavis[7906]: (07878-01) open_on_specific_fd: target fd1 dup2 from fd17 (65) &=17
Jan 10 15:20:21 mail amavis[7906]: (07878-01) open_on_specific_fd: source fd17 closed
Jan 10 15:20:21 mail amavis[7906]: (07878-01) open_on_specific_fd: target fd2 closing, to become (65) &1
Jan 10 15:20:21 mail amavis[7906]: (07878-01) open_on_specific_fd: target fd2 dup2 from fd1 (65) &1
Jan 10 15:20:21 mail amavis[7878]: (07878-01) do_7zip: member:  "/var/spool/amavisd/tmp/amavis-20180110T152020-07878-qnoLF3bb/parts/p002",  bytes
Jan 10 15:20:21 mail amavis[7878]: (07878-01) do_7zip: member: ..... "[Content_Types].xml", 1312 bytes
Jan 10 15:20:21 mail amavis[7878]: (07878-01) do_7zip: member: ..... "_rels/.rels", 590 bytes
Jan 10 15:20:21 mail amavis[7878]: (07878-01) do_7zip: member: ..... "word/_rels/document.xml.rels", 817 bytes
Jan 10 15:20:21 mail amavis[7878]: (07878-01) do_7zip: member: ..... "word/document.xml", 1940 bytes
Jan 10 15:20:21 mail postfix/smtpd[7661]: connect from pick.calemaster.com[185.207.8.225]
Jan 10 15:20:21 mail amavis[7878]: (07878-01) do_7zip: member: ..... "word/theme/theme1.xml", 6800 bytes
Jan 10 15:20:21 mail amavis[7878]: (07878-01) do_7zip: member: ..... "word/settings.xml", 2619 bytes
Jan 10 15:20:21 mail amavis[7878]: (07878-01) do_7zip: member: ..... "word/fontTable.xml", 1340 bytes
Jan 10 15:20:21 mail amavis[7878]: (07878-01) do_7zip: member: ..... "word/webSettings.xml", 576 bytes
Jan 10 15:20:21 mail amavis[7878]: (07878-01) do_7zip: member: ..... "docProps/app.xml", 982 bytes
Jan 10 15:20:21 mail amavis[7878]: (07878-01) do_7zip: member: ..... "docProps/core.xml", 755 bytes
Jan 10 15:20:21 mail amavis[7878]: (07878-01) do_7zip: member: ..... "word/styles.xml", 28756 bytes
Jan 10 15:20:21 mail amavis[7878]: (07878-01) Charging 46487 bytes to remaining quota 8354970 (out of 8366500, (1%)) - by do_7zip-pre
Jan 10 15:20:21 mail amavis[7878]: (07878-01) run_command: [7908] /usr/bin/7za x -bd -y -w/var/spool/amavisd/tmp/amavis-20180110T152020-07878-qnoLF3bb/parts -o/var/spool/amavisd/tmp/amavis-20180110T152020-07878-qnoLF3bb/parts/7zip -- /var/spool/amavisd/tmp/amavis-20180110T152020-07878-qnoLF3bb/parts/p002 </dev/null 2>&1
Jan 10 15:20:21 mail amavis[7908]: (07878-01) open_on_specific_fd: target fd0 closing, to become < /dev/null
Jan 10 15:20:21 mail amavis[7908]: (07878-01) open_on_specific_fd: target fd1 closing, to become (65) &=17
Jan 10 15:20:21 mail amavis[7908]: (07878-01) open_on_specific_fd: target fd1 dup2 from fd17 (65) &=17
Jan 10 15:20:21 mail amavis[7908]: (07878-01) open_on_specific_fd: source fd17 closed
Jan 10 15:20:21 mail amavis[7908]: (07878-01) open_on_specific_fd: target fd2 closing, to become (65) &1
Jan 10 15:20:21 mail amavis[7908]: (07878-01) open_on_specific_fd: target fd2 dup2 from fd1 (65) &1
Jan 10 15:20:21 mail amavis[7878]: (07878-01) collect_results from [7908] (/usr/bin/7za), 640 bytes, (limit 16384)
Jan 10 15:20:21 mail amavis[7878]: (07878-01) flatten_and_tidy_dir: processing directory "/var/spool/amavisd/tmp/amavis-20180110T152020-07878-qnoLF3bb/parts/7zip"
Jan 10 15:20:21 mail amavis[7878]: (07878-01) Issued a new file name: p004
Jan 10 15:20:21 mail amavis[7878]: (07878-01) Issued a new file name: p005
Jan 10 15:20:21 mail amavis[7878]: (07878-01) Issued a new file name: p006
Jan 10 15:20:21 mail amavis[7878]: (07878-01) Issued a new file name: p007
Jan 10 15:20:21 mail amavis[7878]: (07878-01) flatten_and_tidy_dir: renaming "/var/spool/amavisd/tmp/amavis-20180110T152020-07878-qnoLF3bb/parts/7zip/[Content_Types].xml" to /var/spool/amavisd/tmp/amavis-20180110T152020-07878-qnoLF3bb/parts/p005
Jan 10 15:20:21 mail amavis[7878]: (07878-01) flatten_and_tidy_dir: descending into subdir "/var/spool/amavisd/tmp/amavis-20180110T152020-07878-qnoLF3bb/parts/7zip/_rels"
Jan 10 15:20:21 mail amavis[7878]: (07878-01) flatten_and_tidy_dir: processing directory "/var/spool/amavisd/tmp/amavis-20180110T152020-07878-qnoLF3bb/parts/7zip/_rels"
Jan 10 15:20:21 mail amavis[7878]: (07878-01) Issued a new file name: p008
Jan 10 15:20:21 mail amavis[7878]: (07878-01) flatten_and_tidy_dir: renaming "/var/spool/amavisd/tmp/amavis-20180110T152020-07878-qnoLF3bb/parts/7zip/_rels/.rels" to /var/spool/amavisd/tmp/amavis-20180110T152020-07878-qnoLF3bb/parts/p008
Jan 10 15:20:21 mail amavis[7878]: (07878-01) flatten_and_tidy_dir: descending into subdir "/var/spool/amavisd/tmp/amavis-20180110T152020-07878-qnoLF3bb/parts/7zip/word"
Jan 10 15:20:21 mail amavis[7878]: (07878-01) flatten_and_tidy_dir: processing directory "/var/spool/amavisd/tmp/amavis-20180110T152020-07878-qnoLF3bb/parts/7zip/word"
Jan 10 15:20:21 mail amavis[7878]: (07878-01) Issued a new file name: p009
Jan 10 15:20:21 mail amavis[7878]: (07878-01) Issued a new file name: p010
Jan 10 15:20:21 mail amavis[7878]: (07878-01) Issued a new file name: p011
Jan 10 15:20:21 mail amavis[7878]: (07878-01) Issued a new file name: p012
Jan 10 15:20:21 mail amavis[7878]: (07878-01) Issued a new file name: p013
Jan 10 15:20:21 mail amavis[7878]: (07878-01) Issued a new file name: p014
Jan 10 15:20:21 mail amavis[7878]: (07878-01) Issued a new file name: p015
Jan 10 15:20:21 mail amavis[7878]: (07878-01) flatten_and_tidy_dir: renaming "/var/spool/amavisd/tmp/amavis-20180110T152020-07878-qnoLF3bb/parts/7zip/word/document.xml" to /var/spool/amavisd/tmp/amavis-20180110T152020-07878-qnoLF3bb/parts/p010
Jan 10 15:20:21 mail amavis[7878]: (07878-01) flatten_and_tidy_dir: renaming "/var/spool/amavisd/tmp/amavis-20180110T152020-07878-qnoLF3bb/parts/7zip/word/fontTable.xml" to /var/spool/amavisd/tmp/amavis-20180110T152020-07878-qnoLF3bb/parts/p011
Jan 10 15:20:21 mail amavis[7910]: (07878-01) open_on_specific_fd: target fd0 closing, to become < /dev/null
Jan 10 15:20:21 mail amavis[7910]: (07878-01) open_on_specific_fd: target fd1 closing, to become (65) &=17
Jan 10 15:20:21 mail amavis[7910]: (07878-01) open_on_specific_fd: target fd1 dup2 from fd17 (65) &=17
Jan 10 15:20:21 mail amavis[7910]: (07878-01) open_on_specific_fd: source fd17 closed
Jan 10 15:20:21 mail amavis[7910]: (07878-01) open_on_specific_fd: target fd2 closing, to become (65) &1
Jan 10 15:20:21 mail amavis[7910]: (07878-01) open_on_specific_fd: target fd2 dup2 from fd1 (65) &1
Jan 10 15:20:21 mail postfix/smtp[7673]: D6DB2480091: to=<a.deniau@sigire.fr>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.38, delays=0.06/0/0.01/0.31, dsn=2.7.0, status=sent (250 2.7.0 Ok, discarded, id=07878-01 - BANNED: _rels)
Jan 10 15:20:21 mail postfix/qmgr[8240]: D6DB2480091: removed

8

Re: emails containing docx and xlsx are banned

Seems the file extension is 'rels'. Can you find this one in Amavisd config file?

9

Re: emails containing docx and xlsx are banned

no match with "rels" in amavisd.conf

10

Re: emails containing docx and xlsx are banned

No idea right now. I'm afraid that you have to comment out lines in "$banned_namepath_re =" one by one to figure out which file extension causes this ban.