- iRedMail version: 0.9.2
- Store mail accounts in which backend (LDAP/MySQL/PGSQL):MYSQL
- Web server (Apache or Nginx):Apache
- Linux/BSD distribution name and version:ubuntu 14.04
This solution does not work for me.
For example: eicar in zip will be sent to quarantine, but eicar in rar is not recognized as virus.
- Related log if you're reporting an issue:
Aug 16 23:01:44 server postfix/smtpd[4253]: connect from web.heise.de[193.99.144.71]
Aug 16 23:01:44 server postfix/smtpd[4253]: Anonymous TLS connection established from web.heise.de[193.99.144.71]: TLSv1.2 with cipher DHE-RSA-AES256-SHA256 (256/256 bits)
Aug 16 23:01:44 server cbpolicyd[3694]: module=Greylisting, action=pass, host=f74.9.14.7, helo=web.heise.de, from=emailcheck-robot@ct.de, to=myuser@mydomain.de, reason=authenticated
Aug 16 23:01:44 server postfix/smtpd[4253]: B4DD440281: client=web.heise.de[193.99.144.71]
Aug 16 23:01:45 server postfix/cleanup[4276]: B4DD440281: message-id=<E1ZR53o-000CRu-HO.octo15@web.heise.de>
Aug 16 23:01:45 server postfix/qmgr[2344]: B4DD440281: from=<emailcheck-robot@ct.de>, size=2295, nrcpt=1 (queue active)
Aug 16 23:01:45 server amavis[4251]: Net::Server: 2015/08/16-23:01:45 CONNECT TCP Peer: "[127.0.0.1]:52650" Local: "[127.0.0.1]:10024"
Aug 16 23:01:45 server amavis[4251]: () loaded base policy bank
Aug 16 23:01:45 server amavis[4251]: () lookup_ip_acl (inet_acl) arr.obj: key="127.0.0.1" matches "127.0.0.1", result=1
Aug 16 23:01:45 server amavis[4251]: () process_request: fileno sock=13, STDIN=0, STDOUT=1
Aug 16 23:01:45 server amavis[4251]: () get_deadline switch_to_my_time(new request) - deadline in 480.0 s, set to 336.000 s
Aug 16 23:01:45 server amavis[4251]: () prolong_timer switch_to_my_time(new request): timer 336, was 0, deadline in 480.0 s
Aug 16 23:01:45 server amavis[4251]: () process_request: suggested_protocol="" on a TCP socket
Aug 16 23:01:45 server amavis[4251]: (04251-01) SMTP> 220 [127.0.0.1] ESMTP amavisd-new service ready
Aug 16 23:01:45 server amavis[4251]: (04251-01) switch_to_client_time 480 s, smtp response sent
Aug 16 23:01:45 server amavis[4251]: (04251-01) idle_proc, 4: was busy, 5.3 ms, total idle 0.000 s, busy 0.005 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) smtp readline: read 24 bytes into buffer, new size: 24
Aug 16 23:01:45 server amavis[4251]: (04251-01) idle_proc, 5: was idle, 0.5 ms, total idle 0.000 s, busy 0.005 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) SMTP< EHLO server.mydomain.de\r\n
Aug 16 23:01:45 server amavis[4251]: (04251-01) get_deadline switch_to_my_time(rx SMTP EHLO) - deadline in 480.0 s, set to 336.000 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) prolong_timer switch_to_my_time(rx SMTP EHLO): timer 336, was 480, deadline in 480.0 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) ESMTP> 250-[127.0.0.1]
Aug 16 23:01:45 server amavis[4251]: (04251-01) ESMTP> 250-VRFY
Aug 16 23:01:45 server amavis[4251]: (04251-01) ESMTP> 250-PIPELINING
Aug 16 23:01:45 server amavis[4251]: (04251-01) ESMTP> 250-SIZE
Aug 16 23:01:45 server amavis[4251]: (04251-01) ESMTP> 250-ENHANCEDSTATUSCODES
Aug 16 23:01:45 server postfix/smtpd[4253]: disconnect from web.heise.de[193.99.144.71]
Aug 16 23:01:45 server amavis[4251]: (04251-01) ESMTP> 250-8BITMIME
Aug 16 23:01:45 server amavis[4251]: (04251-01) ESMTP> 250-DSN
Aug 16 23:01:45 server amavis[4251]: (04251-01) ESMTP> 250 XFORWARD NAME ADDR PORT PROTO HELO IDENT SOURCE
Aug 16 23:01:45 server amavis[4251]: (04251-01) switch_to_client_time 480 s, smtp response sent
Aug 16 23:01:45 server amavis[4251]: (04251-01) idle_proc, 6: was busy, 3.1 ms, total idle 0.000 s, busy 0.008 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) smtp readline: read 237 bytes into buffer, new size: 237
Aug 16 23:01:45 server amavis[4251]: (04251-01) idle_proc, 5: was idle, 0.5 ms, total idle 0.001 s, busy 0.008 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) ESMTP< XFORWARD NAME=web.heise.de ADDR=193.99.144.71 PORT=57077\r\n
Aug 16 23:01:45 server amavis[4251]: (04251-01) get_deadline switch_to_my_time(rx SMTP XFORWARD) - deadline in 480.0 s, set to 336.000 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) prolong_timer switch_to_my_time(rx SMTP XFORWARD): timer 336, was 480, deadline in 480.0 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) ESMTP> 250 2.5.0 Ok XFORWARD
Aug 16 23:01:45 server amavis[4251]: (04251-01) switch_to_client_time 480 s, smtp response sent
Aug 16 23:01:45 server amavis[4251]: (04251-01) idle_proc, 6: was busy, 1.6 ms, total idle 0.001 s, busy 0.010 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) idle_proc, 5: was idle, 0.2 ms, total idle 0.001 s, busy 0.010 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) ESMTP< XFORWARD PROTO=ESMTP HELO=web.heise.de IDENT=B4DD440281 SOURCE=REMOTE\r\n
Aug 16 23:01:45 server amavis[4251]: (04251-01) get_deadline switch_to_my_time(rx SMTP XFORWARD) - deadline in 480.0 s, set to 336.000 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) prolong_timer switch_to_my_time(rx SMTP XFORWARD): timer 336, was 480, deadline in 480.0 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) ESMTP> 250 2.5.0 Ok XFORWARD
Aug 16 23:01:45 server amavis[4251]: (04251-01) switch_to_client_time 480 s, smtp response sent
Aug 16 23:01:45 server amavis[4251]: (04251-01) idle_proc, 6: was busy, 5.5 ms, total idle 0.001 s, busy 0.015 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) idle_proc, 5: was idle, 0.1 ms, total idle 0.001 s, busy 0.015 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) ESMTP< MAIL FROM:<emailcheck-robot@ct.de> SIZE=2295\r\n
Aug 16 23:01:45 server amavis[4251]: (04251-01) get_deadline switch_to_my_time(rx SMTP MAIL) - deadline in 480.0 s, set to 336.000 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) prolong_timer switch_to_my_time(rx SMTP MAIL): timer 336, was 480, deadline in 480.0 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) check_mail_begin_task: task_count=1
Aug 16 23:01:45 server amavis[4251]: (04251-01) TempDir::prepare_dir: created directory /var/lib/amavis/tmp/amavis-20150816T230145-04251-AOdFzQgZ
Aug 16 23:01:45 server amavis[4251]: (04251-01) TempDir::prepare_file: creating file /var/lib/amavis/tmp/amavis-20150816T230145-04251-AOdFzQgZ/email.txt
Aug 16 23:01:45 server amavis[4251]: (04251-01) TempDir::prepare_file: layers: unix,perlio
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup_ip_acl arr.obj: key="193.99.144.71", no match
Aug 16 23:01:45 server amavis[4251]: (04251-01) query_keys: emailcheck-robot@ct.de, emailcheck-robot@, ct.de, .ct.de, .de, .
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup_hash(emailcheck-robot@ct.de), no matches
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup_acl(emailcheck-robot@ct.de), no match
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup [local_domains] => undef, "emailcheck-robot@ct.de" does not match
Aug 16 23:01:45 server amavis[4251]: (04251-01) query_keys: emailcheck-robot@ct.de, @ct.de, @.ct.de, @.de, @.
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup_sql sel_policy "emailcheck-robot@ct.de", query args: [emailcheck-robot@ct.de,-3], [@ct.de,-3], [@.ct.de,-3], [@.de,-3], [@.,-3]
Aug 16 23:01:45 server amavis[4251]: (04251-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
Aug 16 23:01:45 server amavis[4251]: (04251-01) sql begin, nontransaction
Aug 16 23:01:45 server amavis[4251]: (04251-01) Connecting to SQL database server
Aug 16 23:01:45 server amavis[4251]: (04251-01) connect_to_sql: trying 'DBI:mysql:database=amavisd;host=127.0.0.1;port=3306'
Aug 16 23:01:45 server amavis[4251]: (04251-01) connect_to_sql: 'DBI:mysql:database=amavisd;host=127.0.0.1;port=3306' succeeded
Aug 16 23:01:45 server amavis[4251]: (04251-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
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup_sql, "emailcheck-robot@ct.de" no match
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup_sql_field(local), "emailcheck-robot@ct.de" no matching records
Aug 16 23:01:45 server amavis[4251]: (04251-01) query_keys: emailcheck-robot@ct.de, emailcheck-robot@, ct.de, .ct.de, .de, .
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup_hash(emailcheck-robot@ct.de), no matches
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup_acl(emailcheck-robot@ct.de), no match
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup [local_domains] => undef, "emailcheck-robot@ct.de" does not match
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup [debug_sender] => undef, "emailcheck-robot@ct.de" does not match
Aug 16 23:01:45 server amavis[4251]: (04251-01) ESMTP> 250 2.1.0 Sender <emailcheck-robot@ct.de> OK
Aug 16 23:01:45 server amavis[4251]: (04251-01) switch_to_client_time 480 s, smtp response sent
Aug 16 23:01:45 server amavis[4251]: (04251-01) idle_proc, 6: was busy, 10.5 ms, total idle 0.001 s, busy 0.026 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) idle_proc, 5: was idle, 0.2 ms, total idle 0.001 s, busy 0.026 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) ESMTP< RCPT TO:<myuser@mydomain.de> ORCPT=rfc822;myuser@mydomain.de\r\n
Aug 16 23:01:45 server amavis[4251]: (04251-01) get_deadline switch_to_my_time(rx SMTP RCPT) - deadline in 480.0 s, set to 336.000 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) prolong_timer switch_to_my_time(rx SMTP RCPT): timer 336, was 480, deadline in 480.0 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup => undef, "myuser@mydomain.de", no lookup tables
Aug 16 23:01:45 server amavis[4251]: (04251-01) query_keys: myuser@mydomain.de, myuser@, mydomain.de, .mydomain.de, .de, .
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup_hash(myuser@mydomain.de) matches key "mydomain.de", result=1
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup [local_domains] => true, "myuser@mydomain.de" matches, result="1", matching_key="mydomain.de"
Aug 16 23:01:45 server amavis[4251]: (04251-01) query_keys: myuser@mydomain.de, myuser, @mydomain.de, @.mydomain.de, @.de, @.
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup_sql sel_policy "myuser@mydomain.de", query args: [myuser@mydomain.de,-3], [myuser,-3], [@mydomain.de,-3], [@.mydomain.de,-3], [@.de,-3], [@.,-3]
Aug 16 23:01:45 server amavis[4251]: (04251-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
Aug 16 23:01:45 server amavis[4251]: (04251-01) sql begin, nontransaction
Aug 16 23:01:45 server amavis[4251]: (04251-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
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup_sql(myuser@mydomain.de) matches, result=(id=>"1", priority=>"5", policy_id=>"0", email=>"@mydomain.de", fullname=>-, id=>"1", policy_name=>-, virus_lover=>-, spam_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=>-, bad_header_quarantine_to=>-, clean_quarantine_to=>-, other_quarantine_to=>-, spam_tag_level=>-, spam_tag2_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=>-, message_size_limit=>-, banned_rulenames=>-, id=>"1")
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup_sql_field(message_size_limit) rec=0, "myuser@mydomain.de" result: undef
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup [message_size_limit] => undef, "myuser@mydomain.de" does not match
Aug 16 23:01:45 server amavis[4251]: (04251-01) ESMTP> 250 2.1.5 Recipient <myuser@mydomain.de> OK
Aug 16 23:01:45 server amavis[4251]: (04251-01) switch_to_client_time 480 s, smtp response sent
Aug 16 23:01:45 server amavis[4251]: (04251-01) idle_proc, 6: was busy, 7.2 ms, total idle 0.001 s, busy 0.033 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) idle_proc, 5: was idle, 0.1 ms, total idle 0.002 s, busy 0.033 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) ESMTP< DATA\r\n
Aug 16 23:01:45 server amavis[4251]: (04251-01) get_deadline switch_to_my_time(rx SMTP DATA) - deadline in 480.0 s, set to 336.000 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) prolong_timer switch_to_my_time(rx SMTP DATA): timer 336, was 480, deadline in 480.0 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) ESMTP::10024 /var/lib/amavis/tmp/amavis-20150816T230145-04251-AOdFzQgZ: <emailcheck-robot@ct.de> -> <myuser@mydomain.de> SIZE=2295 Received: from server.mydomain.de ([127.0.0.1]) by localhost (server.mydomain.de [127.0.0.1]) (amavisd-new, port 10024) with ESMTP for <myuser@mydomain.de>; Sun, 16 Aug 2015 23:01:45 +0200 (CEST)
Aug 16 23:01:45 server amavis[4251]: (04251-01) ESMTP> 354 End data with <CR><LF>.<CR><LF>
Aug 16 23:01:45 server amavis[4251]: (04251-01) switch_to_client_time 480 s, smtp response sent
Aug 16 23:01:45 server amavis[4251]: (04251-01) switch_to_client_time 480 s, receiving data
Aug 16 23:01:45 server amavis[4251]: (04251-01) smtp copy: read 2304 bytes into buffer, new size: 2304
Aug 16 23:01:45 server amavis[4251]: (04251-01) smtp copy: 6 bytes still buffered at end
Aug 16 23:01:45 server amavis[4251]: (04251-01) get_deadline switch_to_my_time(rx data-end) - deadline in 480.0 s, set to 336.000 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) prolong_timer switch_to_my_time(rx data-end): timer 336, was 480, deadline in 480.0 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) ESMTP< .<CR><LF>
Aug 16 23:01:45 server amavis[4251]: (04251-01) get_deadline get_body_digest - deadline in 480.0 s, set to 30.000 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) get_deadline digest_pre - deadline in 480.0 s, set to 336.000 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) prolong_timer digest_pre: timer 336, was 336, deadline in 480.0 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) get_body_digest: reading header section
Aug 16 23:01:45 server amavis[4251]: (04251-01) get_deadline digest_hdr - deadline in 480.0 s, set to 336.000 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) prolong_timer digest_hdr: timer 336, was 336, deadline in 480.0 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) get_body_digest: reading mail body
Aug 16 23:01:45 server amavis[4251]: (04251-01) get_deadline digest_body - deadline in 480.0 s, set to 336.000 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) prolong_timer digest_body: timer 336, was 336, deadline in 480.0 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) body type (ESMTP BODY): unlabeled, good (h=0, b=0)
Aug 16 23:01:45 server amavis[4251]: (04251-01) body hash: 4a66af62cb9a8607453239aa4bc3e7a3
Aug 16 23:01:45 server amavis[4251]: (04251-01) Original mail size: 2295; quota set to: 1147500 bytes
Aug 16 23:01:45 server amavis[4251]: (04251-01) sql begin, nontransaction
Aug 16 23:01:45 server amavis[4251]: (04251-01) sql: preparing and executing: SELECT id FROM maddr WHERE partition_tag=? AND email=?
Aug 16 23:01:45 server amavis[4251]: (04251-01) save_info_preliminary G75u1XxtAUAZ, sender id: 6073, emailcheck-robot@ct.de, exists
Aug 16 23:01:45 server amavis[4251]: (04251-01) sql begin, nontransaction
Aug 16 23:01:45 server amavis[4251]: (04251-01) sql: executing clause: SELECT id FROM maddr WHERE partition_tag=? AND email=?
Aug 16 23:01:45 server amavis[4251]: (04251-01) save_info_preliminary G75u1XxtAUAZ, recip id: 6047, myuser@mydomain.de, exists
Aug 16 23:01:45 server amavis[4251]: (04251-01) sql begin transaction
Aug 16 23:01:45 server amavis[4251]: (04251-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 (?,?,?,?,?,?,?,?,?,?,?)
Aug 16 23:01:45 server amavis[4251]: (04251-01) sql commit
Aug 16 23:01:45 server amavis[4251]: (04251-01) Checking: G75u1XxtAUAZ [193.99.144.71] <emailcheck-robot@ct.de> -> <myuser@mydomain.de>
Aug 16 23:01:45 server amavis[4251]: (04251-01) 2822.From: <emailcheck-robot@ct.de>
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup_sql_field(local) rec=0, "myuser@mydomain.de" result: "1"
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup_sql_field, no such fields: local
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup [local_domains] => true, "myuser@mydomain.de" matches, result="1", matching_key="/cached/"
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup_sql_field(bypass_virus_checks) rec=0, "myuser@mydomain.de" result: undef
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup [bypass_virus_checks] => undef, "myuser@mydomain.de" does not match
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup_sql_field(bypass_banned_checks) rec=0, "myuser@mydomain.de" result: undef
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup [bypass_banned_checks] => undef, "myuser@mydomain.de" does not match
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup_sql_field(bypass_spam_checks) rec=0, "myuser@mydomain.de" result: undef
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup [bypass_spam_checks] => undef, "myuser@mydomain.de" does not match
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup_sql_field(id) rec=0, "myuser@mydomain.de" result: "1"
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup [users.id], 1 matches for "myuser@mydomain.de", results: "/cached/"=>"1"
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup_sql_field(policy_id) rec=0, "myuser@mydomain.de" result: "0"
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup [users.policy_id] => false, "myuser@mydomain.de" matches, result="0", matching_key="/cached/"
Aug 16 23:01:45 server amavis[4251]: (04251-01) Extracting mime components
Aug 16 23:01:45 server amavis[4251]: (04251-01) Issued a new file name: p001
Aug 16 23:01:45 server amavis[4251]: (04251-01) Issued a new file name: p002
Aug 16 23:01:45 server amavis[4251]: (04251-01) mime_decode_preamble: 1 lines
Aug 16 23:01:45 server amavis[4251]: (04251-01) Issued a new pseudo part: p003
Aug 16 23:01:45 server amavis[4251]: (04251-01) p003 1 Content-Type: multipart/mixed
Aug 16 23:01:45 server amavis[4251]: (04251-01) mime_decode_epilogue: 2 lines
Aug 16 23:01:45 server amavis[4251]: (04251-01) Charging 794 bytes to remaining quota 1147500 (out of 1147500, (0%)) - by mime_decode
Aug 16 23:01:45 server amavis[4251]: (04251-01) p001 1/1 Content-Type: text/plain, size: 794 B, name:
Aug 16 23:01:45 server amavis[4251]: (04251-01) reparenting p001 from p000 to p003
Aug 16 23:01:45 server amavis[4251]: (04251-01) Charging 140 bytes to remaining quota 1146706 (out of 1147500, (0%)) - by mime_decode
Aug 16 23:01:45 server amavis[4251]: (04251-01) p002 1/2 Content-Type: application/octet-stream, size: 140 B, name: eicar.rar
Aug 16 23:01:45 server amavis[4251]: (04251-01) reparenting p002 from p000 to p003
Aug 16 23:01:45 server amavis[4251]: (04251-01) get_deadline mime_decode - deadline in 480.0 s, set to 336.000 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) prolong_timer mime_decode: timer 336, was 336, deadline in 480.0 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) get_deadline mime_decode-1 - deadline in 480.0 s, set to 336.000 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) prolong_timer mime_decode-1: timer 336, was 336, deadline in 480.0 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) decode_parts: level=1, #parts=3 : p001, p002, p003
Aug 16 23:01:45 server amavis[4251]: (04251-01) running file(1) on 2 files, arglist size 23
Aug 16 23:01:45 server amavis[4251]: (04251-01) run_command: [4289] /usr/bin/file p001 p002 </dev/null 2>&1
Aug 16 23:01:45 server amavis[4289]: (04251-01) open_on_specific_fd: target fd0 closing, to become < /dev/null
Aug 16 23:01:45 server amavis[4289]: (04251-01) open_on_specific_fd: target fd1 closing, to become > &=17
Aug 16 23:01:45 server amavis[4289]: (04251-01) open_on_specific_fd: target fd1 dup2 from fd17 > &=17
Aug 16 23:01:45 server amavis[4289]: (04251-01) open_on_specific_fd: source fd17 closed
Aug 16 23:01:45 server amavis[4289]: (04251-01) open_on_specific_fd: target fd2 closing, to become > &1
Aug 16 23:01:45 server amavis[4289]: (04251-01) open_on_specific_fd: target fd2 dup2 from fd1 > &1
Aug 16 23:01:45 server amavis[4251]: (04251-01) result line from file(1): p001: ISO-8859 text\n
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup_re("ISO-8859 text") matches key "(?^:^ISO-8859.*\btext\b)", result="txt"
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup [map_full_type_to_short_type] => true, "ISO-8859 text" matches, result="txt", matching_key="(?^:^ISO-8859.*\\btext\\b)"
Aug 16 23:01:45 server amavis[4251]: (04251-01) File-type of p001: ISO-8859 text; (txt)
Aug 16 23:01:45 server amavis[4251]: (04251-01) result line from file(1): p002: RAR archive data, v1d, os: Unix\n
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup_re("RAR archive data, v1d, os: Unix") matches key "(?^i:^RAR archive\b)", result="rar"
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup [map_full_type_to_short_type] => true, "RAR archive data, v1d, os: Unix" matches, result="rar", matching_key="(?^i:^RAR archive\\b)"
Aug 16 23:01:45 server amavis[4251]: (04251-01) File-type of p002: RAR archive data, v1d, os: Unix; (rar)
Aug 16 23:01:45 server amavis[4251]: (04251-01) decompose_part: p001 - atomic
Aug 16 23:01:45 server amavis[4251]: (04251-01) Expanding RAR archive p002
Aug 16 23:01:45 server amavis[4251]: (04251-01) get_deadline do_unrar_pre - deadline in 480.0 s, set to 336.000 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) prolong_timer do_unrar_pre: timer 336, was 336, deadline in 480.0 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) run_command: [4290] /usr/bin/unrar-nonfree v -c- -p- -idcdp -- /var/lib/amavis/tmp/amavis-20150816T230145-04251-AOdFzQgZ/parts/p002 </dev/null 2>&1
Aug 16 23:01:45 server amavis[4290]: (04251-01) open_on_specific_fd: target fd0 closing, to become < /dev/null
Aug 16 23:01:45 server amavis[4290]: (04251-01) open_on_specific_fd: target fd1 closing, to become > &=17
Aug 16 23:01:45 server amavis[4290]: (04251-01) open_on_specific_fd: target fd1 dup2 from fd17 > &=17
Aug 16 23:01:45 server amavis[4290]: (04251-01) open_on_specific_fd: source fd17 closed
Aug 16 23:01:45 server amavis[4290]: (04251-01) open_on_specific_fd: target fd2 closing, to become > &1
Aug 16 23:01:45 server amavis[4290]: (04251-01) open_on_specific_fd: target fd2 dup2 from fd1 > &1
Aug 16 23:01:45 server amavis[4251]: (04251-01) Charging 72 bytes to remaining quota 1146566 (out of 1147500, (0%)) - by do_unrar-pre
Aug 16 23:01:45 server amavis[4251]: (04251-01) do_unrar: no archive members, or not an archive at all
Aug 16 23:01:45 server amavis[4251]: (04251-01) get_deadline do_unrar - deadline in 480.0 s, set to 336.000 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) prolong_timer do_unrar: timer 336, was 336, deadline in 480.0 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup_re("RAR archive data, v1d, os: Unix"), no matches
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup [keep_decoded_original] => undef, "RAR archive data, v1d, os: Unix" does not match
Aug 16 23:01:45 server amavis[4251]: (04251-01) decompose_part: deleting /var/lib/amavis/tmp/amavis-20150816T230145-04251-AOdFzQgZ/parts/p002
Aug 16 23:01:45 server amavis[4251]: (04251-01) decompose_part: p002 - archive, unpacked
Aug 16 23:01:45 server amavis[4251]: (04251-01) get_deadline parts_decode - deadline in 480.0 s, set to 336.000 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) prolong_timer parts_decode: timer 336, was 336, deadline in 480.0 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup_sql_field(bypass_header_checks) rec=0, "myuser@mydomain.de" result: undef
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup [bypass_header_checks] => undef, "myuser@mydomain.de" does not match
Aug 16 23:01:45 server amavis[4251]: (04251-01) check_header: 0, OK
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup_sql_field(bypass_header_checks) rec=0, "myuser@mydomain.de" result: undef
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup [bypass_header_checks] => undef, "myuser@mydomain.de" does not match
Aug 16 23:01:45 server amavis[4251]: (04251-01) Checking for banned types and filenames
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup_sql_field(banned_rulenames) rec=0, "myuser@mydomain.de" result: undef
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup: (scalar) matches, result="DEFAULT"
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup [banned_filename], 1 matches for "myuser@mydomain.de", results: "(constant:DEFAULT)"=>"DEFAULT"
Aug 16 23:01:45 server amavis[4251]: (04251-01) collect banned table[0]: myuser@mydomain.de, tables: DEFAULT=>Amavis::Lookup::RE=ARRAY(0x3070360)
Aug 16 23:01:45 server amavis[4251]: (04251-01) starting banned checks - traversing message structure tree
Aug 16 23:01:45 server amavis[4251]: (04251-01) check_for_banned (p003,p001) multipart/mixed | text/plain,.txt
Aug 16 23:01:45 server amavis[4251]: (04251-01) doing banned check for myuser@mydomain.de on multipart/mixed | text/plain,.txt
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup_re(["multipart/mixed","text/plain",".txt"]), no matches
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup [check_bann:myuser@mydomain.de] => undef, ["multipart/mixed","text/plain",".txt"] does not match
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup [banned_namepath_re] => undef, "P=p003\tL=1\tM=multipart/mixed\nP=p001\tL=1/1\tM=text/plain\tT=txt" does not match
Aug 16 23:01:45 server amavis[4251]: (04251-01) p.path myuser@mydomain.de: "P=p003,L=1,M=multipart/mixed | P=p001,L=1/1,M=text/plain,T=txt"
Aug 16 23:01:45 server amavis[4251]: (04251-01) check_for_banned (p003,p002) multipart/mixed | application/octet-stream,.rar,eicar.rar,UNDECIPHERABLE
Aug 16 23:01:45 server amavis[4251]: (04251-01) doing banned check for myuser@mydomain.de on multipart/mixed | application/octet-stream,.rar,eicar.rar,UNDECIPHERABLE
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup_re(["multipart/mixed","application/octet-stream",".rar","eicar.rar","UNDECIPHERABLE"]), no matches
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup [check_bann:myuser@mydomain.de] => undef, ["multipart/mixed","application/octet-stream",".rar","eicar.rar","UNDECIPHERABLE"] does not match
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup [banned_namepath_re] => undef, "P=p003\tL=1\tM=multipart/mixed\nP=p002\tL=1/2\tM=application/octet-stream\tT=rar\tN=eicar.rar\tA=U" does not match
Aug 16 23:01:45 server amavis[4251]: (04251-01) p.path myuser@mydomain.de: "P=p003,L=1,M=multipart/mixed | P=p002,L=1/2,M=application/octet-stream,T=rar,N=eicar.rar,A=U"
Aug 16 23:01:45 server amavis[4251]: (04251-01) banned check: any=0, all=N (1)
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup_re("MAIL"), no matches
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup [keep_decoded_original] => undef, "MAIL" does not match
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup_re("MAIL-UNDECIPHERABLE") matches key "(?^:^MAIL-UNDECIPHERABLE$)", result="1"
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup [keep_decoded_original] => true, "MAIL-UNDECIPHERABLE" matches, result="1", matching_key="(?^:^MAIL-UNDECIPHERABLE$)"
Aug 16 23:01:45 server amavis[4251]: (04251-01) Issued a new file name: p004
Aug 16 23:01:45 server amavis[4251]: (04251-01) presenting full original message to scanners as /var/lib/amavis/tmp/amavis-20150816T230145-04251-AOdFzQgZ/parts/p004, 1 undecipherable
Aug 16 23:01:45 server amavis[4251]: (04251-01) files_to_scan: info: part p002 (rar) no longer present
Aug 16 23:01:45 server amavis[4251]: (04251-01) Calling virus scanners, 2 files to scan in /var/lib/amavis/tmp/amavis-20150816T230145-04251-AOdFzQgZ/parts
Aug 16 23:01:45 server amavis[4251]: (04251-01) invoking av-scanner ClamAV-clamd
Aug 16 23:01:45 server amavis[4251]: (04251-01) ask_daemon: proto=DFLT, spawn=0, (ClamAV-clamd) /tmp/clamd.socket
Aug 16 23:01:45 server amavis[4251]: (04251-01) run_av (ClamAV-clamd): query template(1,1): CONTSCAN {}\n
Aug 16 23:01:45 server amavis[4251]: (04251-01) get_deadline run_av_pre - deadline in 480.0 s, set to 336.000 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) prolong_timer run_av_pre: timer 336, was 336, deadline in 480.0 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) get_deadline run_av_scan - deadline in 480.0 s, set to 336.000 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) prolong_timer run_av_scan: timer 336, was 336, deadline in 480.0 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) run_av Using (ClamAV-clamd): (code) CONTSCAN /var/lib/amavis/tmp/amavis-20150816T230145-04251-AOdFzQgZ/parts\n
Aug 16 23:01:45 server amavis[4251]: (04251-01) get_deadline ask_daemon_internal_connect_pre - deadline in 480.0 s, set to 336.000 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) get_deadline ask_daemon_internal_connect - deadline in 480.0 s, set to 10.000 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) prolong_timer ask_daemon_internal_connect: timer 10, was 336, deadline in 480.0 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) ClamAV-clamd: Connecting to socket /tmp/clamd.socket
Aug 16 23:01:45 server amavis[4251]: (04251-01) new socket by IO::Socket::UNIX to /tmp/clamd.socket, timeout 10
Aug 16 23:01:45 server amavis[4251]: (04251-01) connected to /tmp/clamd.socket successfully
Aug 16 23:01:45 server amavis[4251]: (04251-01) ClamAV-clamd: Sending CONTSCAN /var/lib/amavis/tmp/amavis-20150816T230145-04251-AOdFzQgZ/parts\n to socket /tmp/clamd.socket
Aug 16 23:01:45 server amavis[4251]: (04251-01) rw_loop: needline=0, flush=1, wr=1, timeout=10
Aug 16 23:01:45 server amavis[4251]: (04251-01) rw_loop: sending
Aug 16 23:01:45 server amavis[4251]: (04251-01) rw_loop sent 73> CONTSCAN /var/lib/amavis/tmp/amavis-20150816T230145-04251-AOdFzQgZ/parts\n
Aug 16 23:01:45 server amavis[4251]: (04251-01) get_deadline ask_daemon_internal_scan - deadline in 479.9 s, set to 336.000 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) prolong_timer ask_daemon_internal_scan: timer 336, was 10, deadline in 479.9 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) rw_loop: needline=0, flush=0, wr=0, timeout=335.997
Aug 16 23:01:45 server amavis[4251]: (04251-01) rw_loop: receiving
Aug 16 23:01:45 server amavis[4251]: (04251-01) rw_loop read 68 chars< /var/lib/amavis/tmp/amavis-20150816T230145-04251-AOdFzQgZ/parts: OK\n
Aug 16 23:01:45 server amavis[4251]: (04251-01) rw_loop: needline=0, flush=0, wr=0, timeout=335.997
Aug 16 23:01:45 server amavis[4251]: (04251-01) rw_loop: receiving
Aug 16 23:01:45 server amavis[4251]: (04251-01) rw_loop read: got eof
Aug 16 23:01:45 server amavis[4251]: (04251-01) get_deadline ask_daemon_internal - deadline in 479.9 s, set to 336.000 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) prolong_timer ask_daemon_internal: timer 336, was 336, deadline in 479.9 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) get_deadline run_av_3 - deadline in 479.9 s, set to 336.000 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) prolong_timer run_av_3: timer 336, was 336, deadline in 479.9 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) run_av (ClamAV-clamd) result: /var/lib/amavis/tmp/amavis-20150816T230145-04251-AOdFzQgZ/parts: OK\n
Aug 16 23:01:45 server amavis[4251]: (04251-01) run_av (ClamAV-clamd): CLEAN
Aug 16 23:01:45 server amavis[4251]: (04251-01) run_av (ClamAV-clamd) result: clean
Aug 16 23:01:45 server amavis[4251]: (04251-01) wbl: checking sender <emailcheck-robot@ct.de>
Aug 16 23:01:45 server amavis[4251]: (04251-01) wbl: (SQL) recip <myuser@mydomain.de>, 1 matches
Aug 16 23:01:45 server amavis[4251]: (04251-01) query_keys: emailcheck-robot@ct.de, emailcheck-robot@, ct.de, .ct.de, .de, .
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup_hash(emailcheck-robot@ct.de), no matches
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup_acl(emailcheck-robot@ct.de), no match
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup [local_domains] => undef, "emailcheck-robot@ct.de" does not match
Aug 16 23:01:45 server amavis[4251]: (04251-01) query_keys: emailcheck-robot@ct.de, @ct.de, @.ct.de, @.de, @.
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup_sql sel_wblist "emailcheck-robot@ct.de", query args: "1", [emailcheck-robot@ct.de,-3], [@ct.de,-3], [@.ct.de,-3], [@.de,-3], [@.,-3]
Aug 16 23:01:45 server amavis[4251]: (04251-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
Aug 16 23:01:45 server amavis[4251]: (04251-01) sql begin, nontransaction
Aug 16 23:01:45 server amavis[4251]: (04251-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
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup_sql, "emailcheck-robot@ct.de" no match
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup_sql_field(wb), "emailcheck-robot@ct.de" no matching records
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup => undef, "emailcheck-robot@ct.de" does not match
Aug 16 23:01:45 server amavis[4251]: (04251-01) wbl: (SQL) recip <myuser@mydomain.de>, rid=1, got: ""
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup [blacklist_recip<myuser@mydomain.de>] => undef, "myuser@mydomain.de" does not match
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup [blacklist_sender<emailcheck-robot@ct.de>,blacklist_sender] => undef, "emailcheck-robot@ct.de" does not match
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup [whitelist_recip<myuser@mydomain.de>] => undef, "myuser@mydomain.de" does not match
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup_acl(emailcheck-robot@ct.de), no match
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup [whitelist_sender<emailcheck-robot@ct.de>,whitelist_sender] => undef, "emailcheck-robot@ct.de" does not match
Aug 16 23:01:45 server amavis[4251]: (04251-01) query_keys: myuser@mydomain.de, myuser@, mydomain.de, .mydomain.de, .de, .
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup_hash(myuser@mydomain.de) matches keys: "."=>ARRAY(0x3489788)
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup [score_recip<myuser@mydomain.de>,score_sender], 1 matches for "myuser@mydomain.de", results: "."=>[Amavis::Lookup::RE=ARRAY(0x34898f0),{}]
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup_re("emailcheck-robot@ct.de"), no matches
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup [score_sender<emailcheck-robot@ct.de>] => undef, "emailcheck-robot@ct.de" does not match
Aug 16 23:01:45 server amavis[4251]: (04251-01) SpamControl: calling spam scanner SpamAssassin
Aug 16 23:01:45 server amavis[4251]: (04251-01) get_deadline spam_scan_sa_pre - deadline in 479.9 s, set to 476.000 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) prolong_timer spam_scan_sa_pre: timer 476, was 336, deadline in 479.9 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup_sql_field(sa_userconf) rec=0, "myuser@mydomain.de" result: undef
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup_sql_field, no such fields: sa_userconf
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup [sa_userconf] => undef, "myuser@mydomain.de" does not match
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup_sql_field(sa_username) rec=0, "myuser@mydomain.de" result: undef
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup_sql_field, no such fields: sa_username
Aug 16 23:01:45 server amavis[4251]: (04251-01) lookup [sa_username] => undef, "myuser@mydomain.de" does not match
Aug 16 23:01:45 server amavis[4251]: (04251-01) SA user config: "", username: "amavis", 0
Aug 16 23:01:45 server amavis[4251]: (04251-01) calling SA parse (0), SA vers 3.4.0, 3.004000, data as GLOB, recips_ind [0], user: "amavis"
Aug 16 23:01:45 server amavis[4251]: (04251-01) get_deadline SA check - deadline in 479.9 s, set to 475.000 s
Aug 16 23:01:45 server amavis[4251]: (04251-01) CALLING SA check (0)
Aug 16 23:01:46 server amavis[4251]: (04251-01) DONE SA check (0)
Aug 16 23:01:46 server amavis[4251]: (04251-01) get_deadline spam_scan_sa - deadline in 479.8 s, set to 336.000 s
Aug 16 23:01:46 server amavis[4251]: (04251-01) prolong_timer spam_scan_sa: timer 336, was 476, deadline in 479.8 s
Aug 16 23:01:46 server amavis[4251]: (04251-01) spam_scan: score=-0.019 autolearn=ham autolearn_force=no tests=[RCVD_IN_MSPIKE_H3=-0.01,RCVD_IN_MSPIKE_WL=-0.01,URIBL_BLOCKED=0.001] recips=0
Aug 16 23:01:46 server amavis[4251]: (04251-01) get_deadline spam_scan - deadline in 479.8 s, set to 336.000 s
Aug 16 23:01:46 server amavis[4251]: (04251-01) prolong_timer spam_scan: timer 336, was 336, deadline in 479.8 s
Aug 16 23:01:46 server amavis[4251]: (04251-01) lookup_sql_field(spam_tag_level) rec=0, "myuser@mydomain.de" result: undef
Aug 16 23:01:46 server amavis[4251]: (04251-01) lookup: (scalar) matches, result="2"
Aug 16 23:01:46 server amavis[4251]: (04251-01) lookup [spam_tag_level] => true, "myuser@mydomain.de" matches, result="2", matching_key="(constant:2)"
Aug 16 23:01:46 server amavis[4251]: (04251-01) lookup_sql_field(spam_tag2_level) rec=0, "myuser@mydomain.de" result: undef
Aug 16 23:01:46 server amavis[4251]: (04251-01) lookup: (scalar) matches, result="6.31"
Aug 16 23:01:46 server amavis[4251]: (04251-01) lookup [spam_tag2_level] => true, "myuser@mydomain.de" matches, result="6.31", matching_key="(constant:6.31)"
Aug 16 23:01:46 server amavis[4251]: (04251-01) lookup_sql_field(spam_tag3_level) rec=0, "myuser@mydomain.de" result: undef
Aug 16 23:01:46 server amavis[4251]: (04251-01) lookup_sql_field, no such fields: spam_tag3_level
Aug 16 23:01:46 server amavis[4251]: (04251-01) lookup [spam_tag3_level] => undef, "myuser@mydomain.de" does not match
Aug 16 23:01:46 server amavis[4251]: (04251-01) lookup_sql_field(spam_kill_level) rec=0, "myuser@mydomain.de" result: undef
Aug 16 23:01:46 server amavis[4251]: (04251-01) lookup: (scalar) matches, result="6.31"
Aug 16 23:01:46 server amavis[4251]: (04251-01) lookup [spam_kill_level] => true, "myuser@mydomain.de" matches, result="6.31", matching_key="(constant:6.31)"
Aug 16 23:01:46 server amavis[4251]: (04251-01) lookup_sql_field(message_size_limit) rec=0, "myuser@mydomain.de" result: undef
Aug 16 23:01:46 server amavis[4251]: (04251-01) lookup [message_size_limit] => undef, "myuser@mydomain.de" does not match
Aug 16 23:01:46 server amavis[4251]: (04251-01) final_destiny (ccat=7) is PASS, recip myuser@mydomain.de
Aug 16 23:01:46 server amavis[4251]: (04251-01) final_destiny (ccat=0) is PASS, recip myuser@mydomain.de
Aug 16 23:01:46 server amavis[4251]: (04251-01) final_destiny PASS, recip myuser@mydomain.de
Aug 16 23:01:46 server amavis[4251]: (04251-01) do_notify_and_quar: ccat=Unchecked (7,0) ("7":Unchecked, "1":Clean, "0":CatchAll) ccat_block=(), qar_mth=
Aug 16 23:01:46 server amavis[4251]: (04251-01) do_notify_and_quarantine: not quarantining, q_method off
Aug 16 23:01:46 server amavis[4251]: (04251-01) skip admin notification, no administrators
Aug 16 23:01:46 server amavis[4251]: (04251-01) do_notify_and_quarantine - done
Aug 16 23:01:46 server amavis[4251]: (04251-01) lookup_sql_field(forward_method) rec=0, "myuser@mydomain.de" result: undef
Aug 16 23:01:46 server amavis[4251]: (04251-01) lookup_sql_field, no such fields: forward_method
Aug 16 23:01:46 server amavis[4251]: (04251-01) lookup: (opaque) matches, result="smtp:[127.0.0.1]:10025"
Aug 16 23:01:46 server amavis[4251]: (04251-01) lookup [forward_method] => true, "myuser@mydomain.de" matches, result="smtp:[127.0.0.1]:10025", matching_key="(opaque:smtp:[127.0.0.1]:10025)"
Aug 16 23:01:46 server amavis[4251]: (04251-01) delivery method is smtp:[127.0.0.1]:10025, recips: myuser@mydomain.de
Aug 16 23:01:46 server amavis[4251]: (04251-01) lookup_sql_field(spam_tag_level) rec=0, "myuser@mydomain.de" result: undef
Aug 16 23:01:46 server amavis[4251]: (04251-01) lookup: (scalar) matches, result="2"
Aug 16 23:01:46 server amavis[4251]: (04251-01) lookup [spam_tag_level] => true, "myuser@mydomain.de" matches, result="2", matching_key="(constant:2)"
Aug 16 23:01:46 server amavis[4251]: (04251-01) lookup_sql_field(spam_tag2_level) rec=0, "myuser@mydomain.de" result: undef
Aug 16 23:01:46 server amavis[4251]: (04251-01) lookup: (scalar) matches, result="6.31"
Aug 16 23:01:46 server amavis[4251]: (04251-01) lookup [spam_tag2_level] => true, "myuser@mydomain.de" matches, result="6.31", matching_key="(constant:6.31)"
Aug 16 23:01:46 server amavis[4251]: (04251-01) lookup => undef, "myuser@mydomain.de" does not match
Aug 16 23:01:46 server amavis[4251]: (04251-01) headers CLUSTERING: NEW CLUSTER <myuser@mydomain.de>: score=-0.019, tag=0, tag2=0, local=1, bl=, s=, mangle=
Aug 16 23:01:46 server amavis[4251]: (04251-01) header: X-Virus-Scanned: Debian amavisd-new at server.mydomain.de\n
Aug 16 23:01:46 server amavis[4251]: (04251-01) fwd: scanner provided X-Spam-Checker-Version, inhibited by %allowed_added_header_fields
Aug 16 23:01:46 server amavis[4251]: (04251-01) fwd: scanner provided X-Spam-Level, but we preferred our own
Aug 16 23:01:46 server amavis[4251]: (04251-01) fwd: scanner provided X-Spam-Status, but we preferred our own
Aug 16 23:01:46 server amavis[4251]: (04251-01) header: Received: from server.mydomain.de ([127.0.0.1])\n\tby localhost (server.mydomain.de [127.0.0.1]) (amavisd-new, port 10024)\n\twith ESMTP id G75u1XxtAUAZ for <myuser@mydomain.de>;\n\tSun, 16 Aug 2015 23:01:45 +0200 (CEST)\n
Aug 16 23:01:46 server amavis[4251]: (04251-01) headers CLUSTERING: done all 1 recips in one go
Aug 16 23:01:46 server amavis[4251]: (04251-01) dkim: candidate originators: From:<emailcheck-robot@ct.de>
Aug 16 23:01:46 server amavis[4251]: (04251-01) query_keys: emailcheck-robot@ct.de, emailcheck-robot@, ct.de, .ct.de, .de, .
Aug 16 23:01:46 server amavis[4251]: (04251-01) lookup_hash(emailcheck-robot@ct.de) matches keys: "."=>HASH(0x3070bd0)
Aug 16 23:01:46 server amavis[4251]: (04251-01) lookup [dkim_signature_options_bysender], 1 matches for "emailcheck-robot@ct.de", results: "."=>{a=>"rsa-sha256",ttl=>"2592000",c=>"relaxed/simple"}
Aug 16 23:01:46 server amavis[4251]: (04251-01) dkim: signature options for emailcheck-robot@ct.de(From): d=ct.de; a=rsa-sha256; ttl=2592000; c=relaxed/simple
Aug 16 23:01:46 server amavis[4251]: (04251-01) dkim: not signing, empty signing domain, From: <emailcheck-robot@ct.de>
Aug 16 23:01:46 server amavis[4251]: (04251-01) about to connect to smtp:[127.0.0.1]:10025, FWD from <emailcheck-robot@ct.de> -> <myuser@mydomain.de>
Aug 16 23:01:46 server amavis[4251]: (04251-01) get_deadline fwd_init - deadline in 479.8 s, set to 480.000 s
Aug 16 23:01:46 server amavis[4251]: (04251-01) smtp session: setting up a new session
Aug 16 23:01:46 server amavis[4251]: (04251-01) establish_or_refresh, state: down
Aug 16 23:01:46 server amavis[4251]: (04251-01) new socket by IO::Socket::INET to [127.0.0.1]:10025, timeout 35, blocking
Aug 16 23:01:46 server postfix/smtpd[4283]: connect from localhost.localdomain[127.0.0.1]
Aug 16 23:01:46 server amavis[4251]: (04251-01) connected to [127.0.0.1]:10025 successfully
Aug 16 23:01:46 server amavis[4251]: (04251-01) rw_loop: needline=1, flush=0, wr=0, timeout=35
Aug 16 23:01:46 server amavis[4251]: (04251-01) rw_loop: receiving
Aug 16 23:01:46 server amavis[4251]: (04251-01) rw_loop read 46 chars< 220 server.mydomain.de ESMTP Postfix (Ubuntu)\r\n
Aug 16 23:01:46 server amavis[4251]: (04251-01) smtp greeting: 220 server.mydomain.de ESMTP Postfix (Ubuntu)
Aug 16 23:01:46 server amavis[4251]: (04251-01) smtp cmd> EHLO localhost
Aug 16 23:01:46 server amavis[4251]: (04251-01) rw_loop: needline=0, flush=1, wr=1, timeout=300
Aug 16 23:01:46 server amavis[4251]: (04251-01) rw_loop: sending
Aug 16 23:01:46 server amavis[4251]: (04251-01) rw_loop sent 16> EHLO localhost\r\n
Aug 16 23:01:46 server amavis[4251]: (04251-01) rw_loop: needline=1, flush=0, wr=0, timeout=300
Aug 16 23:01:46 server amavis[4251]: (04251-01) rw_loop: receiving
Aug 16 23:01:46 server amavis[4251]: (04251-01) rw_loop read 160 chars< 250-server.mydomain.de\r\n250-PIPELINING\r\n250-SIZE 54800000\r\n250-ETRN\r\n250-AUTH PLAIN LOGIN\r\n250-AUTH=PLAIN LOGIN\r\n250-ENHANCEDSTATUSCODES\r\n250-8BITMIME\r\n250 DSN\r\n
Aug 16 23:01:46 server amavis[4251]: (04251-01) smtp resp to EHLO: 250 server.mydomain.de\nPIPELINING\nSIZE 54800000\nETRN\nAUTH PLAIN LOGIN\nAUTH=PLAIN LOGIN\nENHANCEDSTATUSCODES\n8BITMIME\nDSN
Aug 16 23:01:46 server amavis[4251]: (04251-01) tls active=0, capable=, sec_level=0
Aug 16 23:01:46 server amavis[4251]: (04251-01) Remote host presents itself as: server.mydomain.de, handles DSN, handles PIPELINING
Aug 16 23:01:46 server amavis[4251]: (04251-01) AUTH not needed, user='', MTA offers 'PLAIN LOGIN'
Aug 16 23:01:46 server amavis[4251]: (04251-01) smtp cmd> MAIL FROM:<emailcheck-robot@ct.de> BODY=7BIT
Aug 16 23:01:46 server amavis[4251]: (04251-01) smtp cmd> RCPT TO:<myuser@mydomain.de> ORCPT=rfc822;myuser@mydomain.de
Aug 16 23:01:46 server amavis[4251]: (04251-01) smtp cmd> DATA
Aug 16 23:01:46 server amavis[4251]: (04251-01) rw_loop: needline=0, flush=1, wr=1, timeout=120
Aug 16 23:01:46 server amavis[4251]: (04251-01) rw_loop: sending
Aug 16 23:01:46 server amavis[4251]: (04251-01) rw_loop sent 108> MAIL FROM:<emailcheck-robot@ct.de> BODY=7BIT\r\nRCPT TO:<myuser@mydomain.de> ORCPT=rfc822;myuser@mydomain.de\r\nDATA\r\n
Aug 16 23:01:46 server postfix/smtpd[4283]: 0DE2940DCA: client=localhost.localdomain[127.0.0.1]
Aug 16 23:01:46 server amavis[4251]: (04251-01) rw_loop: needline=1, flush=0, wr=0, timeout=300
Aug 16 23:01:46 server amavis[4251]: (04251-01) rw_loop: receiving
Aug 16 23:01:46 server amavis[4251]: (04251-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
Aug 16 23:01:46 server amavis[4251]: (04251-01) smtp resp to MAIL (pip): 250 2.1.0 Ok
Aug 16 23:01:46 server amavis[4251]: (04251-01) smtp resp to RCPT (pip) (<myuser@mydomain.de>): 250 2.1.5 Ok
Aug 16 23:01:46 server amavis[4251]: (04251-01) smtp resp to DATA: 354 End data with <CR><LF>.<CR><LF>
Aug 16 23:01:46 server amavis[4251]: (04251-01) write_header: 0, Amavis::Out::SMTP::Protocol=HASH(0x8873ad8)
Aug 16 23:01:46 server amavis[4251]: (04251-01) smtp connection_cache disabled, sending QUIT
Aug 16 23:01:46 server amavis[4251]: (04251-01) smtp cmd> QUIT
Aug 16 23:01:46 server amavis[4251]: (04251-01) rw_loop: needline=0, flush=1, wr=1, timeout=479.994
Aug 16 23:01:46 server amavis[4251]: (04251-01) rw_loop: sending
Aug 16 23:01:46 server postfix/cleanup[4276]: 0DE2940DCA: message-id=<E1ZR53o-000CRu-HO.octo15@web.heise.de>
Aug 16 23:01:46 server amavis[4251]: (04251-01) rw_loop sent 2576> X-Virus-Scanned: Debian amavisd-new at server.mydomain.de\r\nReceived: from server.mydomain.de ([127.0.0.1])\r\n\tby localhost (server.mydomain.de [127.0.0.1]) (amavisd-new, port 10024)\r\n\twith ESMTP id G75u1X [...]
Aug 16 23:01:46 server amavis[4251]: (04251-01) rw_loop: needline=1, flush=0, wr=0, timeout=479.994
Aug 16 23:01:46 server postfix/qmgr[2344]: 0DE2940DCA: from=<emailcheck-robot@ct.de>, size=2751, nrcpt=1 (queue active)
Aug 16 23:01:46 server postfix/smtpd[4283]: disconnect from localhost.localdomain[127.0.0.1]
Aug 16 23:01:46 server amavis[4251]: (04251-01) rw_loop: receiving
Aug 16 23:01:46 server amavis[4251]: (04251-01) rw_loop read 51 chars< 250 2.0.0 Ok: queued as 0DE2940DCA\r\n221 2.0.0 Bye\r\n
Aug 16 23:01:46 server amavis[4251]: (04251-01) smtp resp to data-dot (<myuser@mydomain.de>): 250 2.0.0 Ok: queued as 0DE2940DCA
Aug 16 23:01:46 server amavis[4251]: (04251-01) Amavis::Out::SMTP::Session close, disconnecting
Aug 16 23:01:46 server amavis[4251]: (04251-01) get_deadline fwd-end-chkpnt - deadline in 479.7 s, set to 336.000 s
Aug 16 23:01:46 server amavis[4251]: (04251-01) prolong_timer fwd-end-chkpnt: timer 336, was 0, deadline in 479.7 s
Aug 16 23:01:46 server amavis[4251]: (04251-01) FWD from <emailcheck-robot@ct.de> -> <myuser@mydomain.de>,BODY=7BIT 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 0DE2940DCA
Aug 16 23:01:46 server amavis[4251]: (04251-01) get_deadline forwarding - deadline in 479.7 s, set to 336.000 s
Aug 16 23:01:46 server amavis[4251]: (04251-01) prolong_timer forwarding: timer 336, was 336, deadline in 479.7 s
Aug 16 23:01:46 server amavis[4251]: (04251-01) DSN: sender is credible (orig), SA: -0.019, <emailcheck-robot@ct.de>
Aug 16 23:01:46 server amavis[4251]: (04251-01) lookup [spam_crediblefrom_dsn_cutoff_level_bysender] => undef, "emailcheck-robot@ct.de" does not match
Aug 16 23:01:46 server amavis[4251]: (04251-01) dsn: from MTA 250 NonBlocking:Unchecked <emailcheck-robot@ct.de> -> <myuser@mydomain.de>: 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 0DE2940DCA"
Aug 16 23:01:46 server amavis[4251]: (04251-01) DSN: SUCC from MTA 250 NonBlocking:Unchecked, no DSN requested: <emailcheck-robot@ct.de> -> <myuser@mydomain.de>
Aug 16 23:01:46 server amavis[4251]: (04251-01) one_response_for_all <emailcheck-robot@ct.de>: 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 0DE2940DCA'
Aug 16 23:01:46 server amavis[4251]: (04251-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 0DE2940DCA
Aug 16 23:01:46 server amavis[4251]: (04251-01) status counters: InMsgsStatus{Relayed,RelayedUntagged,RelayedUntaggedInternal,RelayedUntaggedOriginating}
Aug 16 23:01:46 server amavis[4251]: (04251-01) get_deadline delivery-notification - deadline in 479.7 s, set to 336.000 s
Aug 16 23:01:46 server amavis[4251]: (04251-01) prolong_timer delivery-notification: timer 336, was 336, deadline in 479.7 s
Aug 16 23:01:46 server amavis[4251]: (04251-01) fish_out_ip_from_received: 193.99.144.71
Aug 16 23:01:46 server amavis[4251]: (04251-01) lookup_ip_acl (publicnetworks) arr.obj: key="193.99.144.71" matches "::FFFF:0:0/96", result=1
Aug 16 23:01:46 server postfix/lmtp[4284]: 0DE2940DCA: to=<myuser@mydomain.de>, relay=server.mydomain.de[private/dovecot-lmtp], delay=0.01, delays=0/0/0/0.01, dsn=2.0.0, status=sent (250 2.0.0 <myuser@mydomain.de> eTOhAzr60FWTDwAAdZMi1A Saved)
Aug 16 23:01:46 server postfix/qmgr[2344]: 0DE2940DCA: removed
Aug 16 23:01:46 server amavis[4251]: (04251-01) parse_ip_address_from_received: 193.99.144.71
Aug 16 23:01:46 server amavis[4251]: (04251-01) Passed UNCHECKED {RelayedInternal}, LOCAL [193.99.144.71]:57077 [193.99.144.71] <emailcheck-robot@ct.de> -> <myuser@mydomain.de>, Queue-ID: B4DD440281, Message-ID: <E1ZR53o-000CRu-HO.octo15@web.heise.de>, mail_id: G75u1XxtAUAZ, Hits: -0.019, size: 2295, queued_as: 0DE2940DCA, 314 ms
Aug 16 23:01:46 server amavis[4251]: (04251-01) get_deadline main_log_entry - deadline in 479.7 s, set to 336.000 s
Aug 16 23:01:46 server amavis[4251]: (04251-01) prolong_timer main_log_entry: timer 336, was 336, deadline in 479.7 s
Aug 16 23:01:46 server amavis[4251]: (04251-01) sql begin transaction
Aug 16 23:01:46 server amavis[4251]: (04251-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 (?,?,?,?,?,?,?,?,?,?,?,?)
Aug 16 23:01:46 server amavis[4251]: (04251-01) save_info_final G75u1XxtAUAZ, orig=Y, chks=VSHB, cont.ty=U, q.type= , q.to=, dsn=N, score=-0.019, Message-ID: <E1ZR53o-000CRu-HO.octo15@web.heise.de>, From: 'Heise Emailcheck <emailcheck-robot@ct.de>', Subject: 'c't-Emailcheck: EICAR-RAR (osldqgi)'
Aug 16 23:01:46 server amavis[4251]: (04251-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=?
Aug 16 23:01:46 server amavis[4251]: (04251-01) sql commit
Aug 16 23:01:46 server amavis[4251]: (04251-01) TIMING-SA total 178 ms - parse: 0.90 (0.5%), b_tie_ro: 0.90 (0.5%), extract_message_metadata: 15 (8.6%), get_uri_detail_list: 1.83 (1.0%), tests_pri_-1000: 21 (11.8%), tests_pri_-950: 0.59 (0.3%), tests_pri_-900: 0.66 (0.4%), tests_pri_-400: 0.54 (0.3%), tests_pri_0: 57 (32.0%), check_spf: 10 (5.6%), poll_dns_idle: 42 (23.3%), check_dkim_adsp: 8 (4.6%), check_pyzor: 0.12 (0.1%), tests_pri_500: 43 (23.9%), learn: 29 (16.1%), b_learn: 27 (14.9%), b_tie_rw: 0.90 (0.5%), b_count_change: 21 (11.9%), get_report: 0.36 (0.2%)
Aug 16 23:01:46 server amavis[4251]: (04251-01) updating snmp variables
Aug 16 23:01:46 server amavis[4251]: (04251-01) get_deadline check done - deadline in 479.7 s, set to 336.000 s
Aug 16 23:01:46 server amavis[4251]: (04251-01) prolong_timer check done: timer 336, was 336, deadline in 479.7 s
Aug 16 23:01:46 server amavis[4251]: (04251-01) sending SMTP response: "250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 0DE2940DCA"
Aug 16 23:01:46 server amavis[4251]: (04251-01) ESMTP> 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 0DE2940DCA
Aug 16 23:01:46 server postfix/smtp[4279]: B4DD440281: to=<myuser@mydomain.de>, relay=127.0.0.1[127.0.0.1]:10024, delay=1.4, delays=1.1/0/0.01/0.32, 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 0DE2940DCA)
Aug 16 23:01:46 server postfix/qmgr[2344]: B4DD440281: removed
Aug 16 23:01:46 server amavis[4251]: (04251-01) switch_to_client_time 480 s, smtp response sent
Aug 16 23:01:46 server amavis[4251]: (04251-01) TempDir::strip: /var/lib/amavis/tmp/amavis-20150816T230145-04251-AOdFzQgZ
Aug 16 23:01:46 server amavis[4251]: (04251-01) rmdir_recursively: /var/lib/amavis/tmp/amavis-20150816T230145-04251-AOdFzQgZ/parts, excl=1
Aug 16 23:01:46 server amavis[4251]: (04251-01) size: 2295, TIMING [total 325 ms] - sql-prepare: 3 (1%)1, SMTP greeting: 2 (1%)2, SMTP EHLO: 4 (1%)3, SMTP pre-MAIL: 8 (3%)5, mkdir tempdir: 1 (0%)5, create email.txt: 0 (0%)6, sql-connect: 6 (2%)7, lookup_sql: 1 (0%)8, lookup_sql: 8 (2%)10, SMTP pre-DATA-flush: 3 (1%)11, SMTP DATA: 13 (4%)15, check_init: 0 (0%)15, digest_hdr: 1 (0%)16, digest_body_dkim: 2 (1%)16, gen_mail_id: 5 (1%)18, mkdir parts: 2 (1%)18, mime_decode: 8 (3%)21, get-file-type2: 14 (4%)25, decompose_part: 10 (3%)28, parts_decode: 0 (0%)28, check_header: 1 (0%)29, AV-scan-1: 10 (3%)32, lookup_sql: 2 (1%)32, spam-wb-list: 2 (1%)33, SA parse: 3 (1%)34, SA check: 176 (54%)88, decide_mail_destiny: 6 (2%)90, notif-quar: 0 (0%)90, fwd-connect: 8 (2%)92, fwd-mail-pip: 2 (1%)93, fwd-rcpt-pip: 0 (0%)93, fwd-data-chkpnt: 0 (0%)93, write-header: 0 (0%)93, fwd-data-contents: 0 (0%)93, fwd-end-chkpnt: 3 (1%)94, prepare-dsn: 1 (0%)95, main_log_entry: 7 (2%)97, sql-update: 3 (1%)98, update_snmp: 5 (...
Aug 16 23:01:46 server amavis[4251]: (04251-01) ...1%)99, SMTP pre-response: 0 (0%)99, SMTP response: 2 (1%)100, unlink-2-files: 0 (0%)100, rundown: 0 (0%)100
Aug 16 23:01:46 server amavis[4251]: (04251-01) idle_proc, 6: was busy, 291.2 ms, total idle 0.002 s, busy 0.324 s
Aug 16 23:01:46 server amavis[4251]: (04251-01) idle_proc, 5: was idle, 0.6 ms, total idle 0.002 s, busy 0.324 s
Aug 16 23:01:46 server amavis[4251]: (04251-01) ESMTP< QUIT\r\n
Aug 16 23:01:46 server amavis[4251]: (04251-01) get_deadline switch_to_my_time(rx SMTP QUIT) - deadline in 480.0 s, set to 336.000 s
Aug 16 23:01:46 server amavis[4251]: (04251-01) prolong_timer switch_to_my_time(rx SMTP QUIT): timer 336, was 480, deadline in 480.0 s
Aug 16 23:01:46 server amavis[4251]: (04251-01) ESMTP> 221 2.0.0 [127.0.0.1] amavisd-new closing transmission channel
Aug 16 23:01:46 server amavis[4251]: (04251-01) switch_to_client_time 480 s, smtp response sent
Aug 16 23:01:46 server amavis[4251]: (04251-01) SMTP session over, timer stopped
Aug 16 23:01:46 server amavis[4251]: (04251-01) exiting process_request
Aug 16 23:01:46 server amavis[4251]: (04251-01) idle_proc, bye: was busy, 3.1 ms, total idle 0.002 s, busy 0.327 s
Aug 16 23:01:46 server amavis[4251]: (04251-01) load: 99 %, total idle 0.002 s, busy 0.327 s
