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