Can't send PDF attachments

Sruli Saurymper sruli at saurymper.com
Wed Feb 11 22:23:06 CET 2015


Hi all,
I urgently need some help with my following problem,

I have a newly setup live instance of kolab 3.3 on centos 7 multi-domain 
all seems to work fine, but one weird and urgent issue, whenever someone 
sends a PDF attachment postfix reports a time-out when trying to connect 
to the remote server, when sending to local addresses it goes through 
fine, only remote addresses seem to be the problem and all other 
attachment types I tried so far work fine (I tried dozens of different 
PDF files, all same problem, size ranging from 10kb to 10MB, other file 
types work upto 20MB)

I attach the log of 1 smtp session (IP and email addressed replaced with 
dummy details)

In my postqueue i see this (3 different email attempts);

38D3918004A21   981561 Wed Feb 11 20:09:56 myname at mydomain.com
(conversation with alt1.gmail-smtp-in.l.google.com[173.194.71.27] timed 
out while sending end of data -- message may be sent more than once)
                                          mygmailaccount at gmail.com

2F5B218004A1E   981561 Wed Feb 11 19:48:35  myname at mydomain.com
(delivery temporarily suspended: conversation with 
alt1.gmail-smtp-in.l.google.com[173.194.71.27] timed out while sending 
end of data -- message may be sent more than once)
                                          mygmailaccount at gmail.com

76A8218004A1F   981561 Wed Feb 11 20:04:33  myname at mydomain.com
(conversation with alt1.gmail-smtp-in.l.google.com[173.194.71.27] timed 
out while sending end of data -- message may be sent more than once)
                                          mygmailaccount at gmail.com

Please can someone help me out with this problem.

Many Thanks
Sruli

-------------- next part --------------
Feb 11 20:09:51 mail postfix/submission/smtpd[3446]: connect from unknown[xx.xx.xx.xx]
Feb 11 20:09:52 mail postfix/submission/smtpd[3446]: B1FA718004A21: client=unknown[xx.xx.xx.xx], sasl_method=PLAIN, sasl_username=myname at mydomain.com
Feb 11 20:09:52 mail postfix/cleanup[3451]: B1FA718004A21: message-id=<54DBB716.2090403 at mydomain.com>
Feb 11 20:09:53 mail postfix/qmgr[3190]: B1FA718004A21: from=<myname at mydomain.com>, size=981305, nrcpt=1 (queue active)
Feb 11 20:09:53 mail postfix/submission/smtpd[3446]: disconnect from unknown[xx.xx.xx.xx]
Feb 11 20:09:53 mail amavis[3199]: (03199-01) Net::Server: 2015/02/11-20:09:53 CONNECT TCP Peer: "[127.0.0.1]:33630" Local: "[127.0.0.1]:10024"
Feb 11 20:09:53 mail amavis[3199]: idle_proc, hi : was idle, 320983.9 ms, total idle 320.987 s, busy 1.380 s
Feb 11 20:09:53 mail amavis[3199]: loaded base policy bank
Feb 11 20:09:53 mail amavis[3199]: lookup_ip_acl (inet_acl) arr.obj: key="127.0.0.1" matches "127.0.0.1", result=1
Feb 11 20:09:53 mail amavis[3199]: process_request: fileno sock=14, STDIN=0, STDOUT=1
Feb 11 20:09:53 mail amavis[3199]: get_deadline switch_to_my_time(new request) - deadline in 480.0 s, set to 336.000 s
Feb 11 20:09:53 mail amavis[3199]: prolong_timer switch_to_my_time(new request): timer 336, was 0, deadline in 480.0 s
Feb 11 20:09:53 mail amavis[3199]: process_request: suggested_protocol="" on a TCP socket
Feb 11 20:09:53 mail amavis[3199]: (03199-02) SMTP> 220 [127.0.0.1] ESMTP amavisd-new service ready
Feb 11 20:09:53 mail amavis[3199]: (03199-02) switch_to_client_time 480 s, smtp response sent
Feb 11 20:09:53 mail amavis[3199]: (03199-02) idle_proc, 4: was busy, 3.2 ms, total idle 320.987 s, busy 1.384 s
Feb 11 20:09:53 mail amavis[3199]: (03199-02) smtp readline: read 29 bytes, new size: 29
Feb 11 20:09:53 mail amavis[3199]: (03199-02) idle_proc, 5: was idle, 0.5 ms, total idle 320.988 s, busy 1.384 s
Feb 11 20:09:53 mail amavis[3199]: (03199-02) SMTP< EHLO mail.mydomain.co.uk\r\n
Feb 11 20:09:53 mail amavis[3199]: (03199-02) get_deadline switch_to_my_time(rx SMTP EHLO) - deadline in 480.0 s, set to 336.000 s
Feb 11 20:09:53 mail amavis[3199]: (03199-02) prolong_timer switch_to_my_time(rx SMTP EHLO): timer 336, was 480, deadline in 480.0 s
Feb 11 20:09:53 mail amavis[3199]: (03199-02) ESMTP> 250-[127.0.0.1]
Feb 11 20:09:53 mail amavis[3199]: (03199-02) ESMTP> 250-VRFY
Feb 11 20:09:53 mail amavis[3199]: (03199-02) ESMTP> 250-PIPELINING
Feb 11 20:09:53 mail amavis[3199]: (03199-02) ESMTP> 250-SIZE
Feb 11 20:09:53 mail amavis[3199]: (03199-02) ESMTP> 250-ENHANCEDSTATUSCODES
Feb 11 20:09:53 mail amavis[3199]: (03199-02) ESMTP> 250-8BITMIME
Feb 11 20:09:53 mail amavis[3199]: (03199-02) ESMTP> 250-DSN
Feb 11 20:09:53 mail amavis[3199]: (03199-02) ESMTP> 250 XFORWARD NAME ADDR PORT PROTO HELO IDENT SOURCE
Feb 11 20:09:53 mail amavis[3199]: (03199-02) switch_to_client_time 480 s, smtp response sent
Feb 11 20:09:53 mail amavis[3199]: (03199-02) idle_proc, 6: was busy, 6.4 ms, total idle 320.988 s, busy 1.390 s
Feb 11 20:09:53 mail amavis[3199]: (03199-02) smtp readline: read 234 bytes, new size: 234
Feb 11 20:09:53 mail amavis[3199]: (03199-02) idle_proc, 5: was idle, 1.3 ms, total idle 320.989 s, busy 1.390 s
Feb 11 20:09:53 mail amavis[3199]: (03199-02) ESMTP< XFORWARD ADDR=xx.xx.xx.xx PORT=64204\r\n
Feb 11 20:09:53 mail amavis[3199]: (03199-02) get_deadline switch_to_my_time(rx SMTP XFORWARD) - deadline in 480.0 s, set to 336.000 s
Feb 11 20:09:53 mail amavis[3199]: (03199-02) prolong_timer switch_to_my_time(rx SMTP XFORWARD): timer 336, was 480, deadline in 480.0 s
Feb 11 20:09:53 mail amavis[3199]: (03199-02) ESMTP> 250 2.5.0 Ok XFORWARD
Feb 11 20:09:53 mail amavis[3199]: (03199-02) switch_to_client_time 480 s, smtp response sent
Feb 11 20:09:53 mail amavis[3199]: (03199-02) idle_proc, 6: was busy, 4.2 ms, total idle 320.989 s, busy 1.394 s
Feb 11 20:09:53 mail amavis[3199]: (03199-02) idle_proc, 5: was idle, 0.7 ms, total idle 320.990 s, busy 1.394 s
Feb 11 20:09:53 mail amavis[3199]: (03199-02) ESMTP< XFORWARD PROTO=ESMTP HELO=[192.168.235.104] IDENT=B1FA718004A21 SOURCE=REMOTE\r\n
Feb 11 20:09:53 mail amavis[3199]: (03199-02) get_deadline switch_to_my_time(rx SMTP XFORWARD) - deadline in 480.0 s, set to 336.000 s
Feb 11 20:09:53 mail amavis[3199]: (03199-02) prolong_timer switch_to_my_time(rx SMTP XFORWARD): timer 336, was 480, deadline in 480.0 s
Feb 11 20:09:53 mail amavis[3199]: (03199-02) ESMTP> 250 2.5.0 Ok XFORWARD
Feb 11 20:09:53 mail amavis[3199]: (03199-02) switch_to_client_time 480 s, smtp response sent
Feb 11 20:09:53 mail amavis[3199]: (03199-02) idle_proc, 6: was busy, 4.1 ms, total idle 320.990 s, busy 1.398 s
Feb 11 20:09:53 mail amavis[3199]: (03199-02) idle_proc, 5: was idle, 0.7 ms, total idle 320.990 s, busy 1.398 s
Feb 11 20:09:53 mail amavis[3199]: (03199-02) ESMTP< MAIL FROM:<myname at mydomain.com> SIZE=981305\r\n
Feb 11 20:09:53 mail amavis[3199]: (03199-02) get_deadline switch_to_my_time(rx SMTP MAIL) - deadline in 480.0 s, set to 336.000 s
Feb 11 20:09:53 mail amavis[3199]: (03199-02) prolong_timer switch_to_my_time(rx SMTP MAIL): timer 336, was 480, deadline in 480.0 s
Feb 11 20:09:53 mail amavis[3199]: (03199-02) check_mail_begin_task: task_count=2
Feb 11 20:09:53 mail amavis[3199]: (03199-02) lookup_ip_acl (client_ipaddr_policy) arr.obj: key="xx.xx.xx.xx", no match
Feb 11 20:09:53 mail amavis[3199]: (03199-02) lookup [debug_sender] => undef, "myname at mydomain.com" does not match
Feb 11 20:09:53 mail amavis[3199]: (03199-02) mesage size set to a declared size 981305
Feb 11 20:09:53 mail amavis[3199]: (03199-02) ESMTP> 250 2.1.0 Sender <myname at mydomain.com> OK
Feb 11 20:09:53 mail amavis[3199]: (03199-02) switch_to_client_time 480 s, smtp response sent
Feb 11 20:09:53 mail amavis[3199]: (03199-02) idle_proc, 6: was busy, 7.8 ms, total idle 320.990 s, busy 1.406 s
Feb 11 20:09:53 mail amavis[3199]: (03199-02) idle_proc, 5: was idle, 0.7 ms, total idle 320.991 s, busy 1.406 s
Feb 11 20:09:53 mail amavis[3199]: (03199-02) ESMTP< RCPT TO:<mygmailaccount at gmail.com> ORCPT=rfc822;mygmailaccount at gmail.com\r\n
Feb 11 20:09:53 mail amavis[3199]: (03199-02) get_deadline switch_to_my_time(rx SMTP RCPT) - deadline in 480.0 s, set to 336.000 s
Feb 11 20:09:53 mail amavis[3199]: (03199-02) prolong_timer switch_to_my_time(rx SMTP RCPT): timer 336, was 480, deadline in 480.0 s
Feb 11 20:09:53 mail amavis[3199]: (03199-02) lookup => undef, "mygmailaccount at gmail.com", no lookup tables
Feb 11 20:09:53 mail amavis[3199]: (03199-02) lookup_re("mygmailaccount at gmail.com") matches key "(?^:.*)", result="1"
Feb 11 20:09:53 mail amavis[3199]: (03199-02) lookup [local_domains] => true,  "mygmailaccount at gmail.com" matches, result="1", matching_key="(?^:.*)"
Feb 11 20:09:53 mail amavis[3199]: (03199-02) query_keys: mygmailaccount at gmail.com, mygmailaccount at gmail.com, mygmailaccount, @gmail.com, @.gmail.com, @.com, @.
Feb 11 20:09:53 mail amavis[3199]: (03199-02) lookup_ldap "mygmailaccount at gmail.com", query keys: "mygmailaccount at gmail.com", "mygmailaccount at gmail.com", "mygmailaccount", "@gmail.com", "@.gmail.com", "@.com", "@.", base: dc=mydomain,dc=co,dc=uk, filter: (|(mail=%m)(alias=%m))
Feb 11 20:09:53 mail amavis[3199]: (03199-02) ldap begin_work
Feb 11 20:09:53 mail amavis[3199]: (03199-02) lookup_ldap: searching base="dc=mydomain,dc=co,dc=uk", scope="sub", filter="(|(|(mail=mygmailaccount at gmail.com)(mail=mygmailaccount at gmail.com)(mail=mygmailaccount)(mail=@gmail.com)(mail=@.gmail.com)(mail=@.com)(mail=@.))(|(alias=mygmailaccount at gmail.com)(alias=mygmailaccount at gmail.com)(alias=mygmailaccount)(alias=@gmail.com)(alias=@.gmail.com)(alias=@.com)(alias=@.)))"
Feb 11 20:09:53 mail amavis[3199]: (03199-02) lookup_ldap, "mygmailaccount at gmail.com" no match
Feb 11 20:09:53 mail amavis[3199]: (03199-02) lookup_ldap_attr(amavisMessageSizeLimit), "mygmailaccount at gmail.com" no matching entries
Feb 11 20:09:53 mail amavis[3199]: (03199-02) lookup [message_size_limit] => undef, "mygmailaccount at gmail.com" does not match
Feb 11 20:09:53 mail amavis[3199]: (03199-02) ESMTP> 250 2.1.5 Recipient <mygmailaccount at gmail.com> OK
Feb 11 20:09:53 mail amavis[3199]: (03199-02) switch_to_client_time 480 s, smtp response sent
Feb 11 20:09:53 mail amavis[3199]: (03199-02) idle_proc, 6: was busy, 16.1 ms, total idle 320.991 s, busy 1.422 s
Feb 11 20:09:53 mail amavis[3199]: (03199-02) idle_proc, 5: was idle, 0.1 ms, total idle 320.991 s, busy 1.422 s
Feb 11 20:09:53 mail amavis[3199]: (03199-02) ESMTP< DATA\r\n
Feb 11 20:09:53 mail amavis[3199]: (03199-02) get_deadline switch_to_my_time(rx SMTP DATA) - deadline in 480.0 s, set to 336.000 s
Feb 11 20:09:53 mail amavis[3199]: (03199-02) prolong_timer switch_to_my_time(rx SMTP DATA): timer 336, was 480, deadline in 480.0 s
Feb 11 20:09:53 mail amavis[3199]: (03199-02) ESMTP:[127.0.0.1]:10024 /var/spool/amavisd/tmp/amavis-20150211T200431-03199-llUvj6Ce: <myname at mydomain.com> -> <mygmailaccount at gmail.com> SIZE=981305 Received: from mail.mydomain.co.uk ([127.0.0.1]) by localhost (mail.mydomain.co.uk [127.0.0.1]) (amavisd-new, port 10024) with ESMTP for <mygmailaccount at gmail.com>; Wed, 11 Feb 2015 20:09:53 +0000 (GMT)
Feb 11 20:09:53 mail amavis[3199]: (03199-02) ESMTP> 354 End data with <CR><LF>.<CR><LF>
Feb 11 20:09:53 mail amavis[3199]: (03199-02) switch_to_client_time 480 s, smtp response sent
Feb 11 20:09:53 mail amavis[3199]: (03199-02) switch_to_client_time 480 s, receiving data
Feb 11 20:09:53 mail amavis[3199]: (03199-02) smtp copy: read 65536 bytes into buffer, new size: 65536
Feb 11 20:09:53 mail amavis[3199]: (03199-02) smtp copy: read 65536 bytes into buffer, new size: 65536
Feb 11 20:09:53 mail amavis[3199]: (03199-02) smtp copy: read 65536 bytes into buffer, new size: 65536
Feb 11 20:09:53 mail amavis[3199]: (03199-02) smtp copy: read 48682 bytes into buffer, new size: 48682
Feb 11 20:09:53 mail amavis[3199]: (03199-02) smtp copy: read 65536 bytes into buffer, new size: 65536
Feb 11 20:09:53 mail amavis[3199]: (03199-02) smtp copy: read 65536 bytes into buffer, new size: 65536
Feb 11 20:09:53 mail amavis[3199]: (03199-02) smtp copy: read 65536 bytes into buffer, new size: 65536
Feb 11 20:09:53 mail amavis[3199]: (03199-02) smtp copy: read 65536 bytes into buffer, new size: 65536
Feb 11 20:09:53 mail amavis[3199]: (03199-02) smtp copy: read 65536 bytes into buffer, new size: 65536
Feb 11 20:09:53 mail amavis[3199]: (03199-02) smtp copy: read 65536 bytes into buffer, new size: 65536
Feb 11 20:09:53 mail amavis[3199]: (03199-02) smtp copy: read 65536 bytes into buffer, new size: 65536
Feb 11 20:09:53 mail amavis[3199]: (03199-02) smtp copy: read 65536 bytes into buffer, new size: 65536
Feb 11 20:09:53 mail amavis[3199]: (03199-02) smtp copy: read 65536 bytes into buffer, new size: 65536
Feb 11 20:09:53 mail amavis[3199]: (03199-02) smtp copy: read 65536 bytes into buffer, new size: 65536
Feb 11 20:09:53 mail amavis[3199]: (03199-02) smtp copy: read 65536 bytes into buffer, new size: 65536
Feb 11 20:09:53 mail amavis[3199]: (03199-02) smtp copy: read 15128 bytes into buffer, new size: 15128
Feb 11 20:09:53 mail amavis[3199]: (03199-02) smtp copy: 6 bytes still buffered at end
Feb 11 20:09:53 mail amavis[3199]: (03199-02) get_deadline switch_to_my_time(rx data-end) - deadline in 480.0 s, set to 336.000 s
Feb 11 20:09:53 mail amavis[3199]: (03199-02) prolong_timer switch_to_my_time(rx data-end): timer 336, was 480, deadline in 480.0 s
Feb 11 20:09:53 mail amavis[3199]: (03199-02) ESMTP< .<CR><LF>
Feb 11 20:09:53 mail amavis[3199]: (03199-02) smtp connection cache, dt: 321.0, state: 1
Feb 11 20:09:53 mail amavis[3199]: (03199-02) smtp connection cache, dt: 321.0 -> disabling
Feb 11 20:09:53 mail amavis[3199]: (03199-02) get_deadline get_body_digest - deadline in 480.0 s, set to 30.000 s
Feb 11 20:09:53 mail amavis[3199]: (03199-02) get_deadline digest_pre - deadline in 480.0 s, set to 336.000 s
Feb 11 20:09:53 mail amavis[3199]: (03199-02) prolong_timer digest_pre: timer 336, was 336, deadline in 480.0 s
Feb 11 20:09:53 mail amavis[3199]: (03199-02) get_body_digest: reading header section from a file
Feb 11 20:09:53 mail amavis[3199]: (03199-02) get_body_digest: sending h/b separator to DKIM
Feb 11 20:09:53 mail amavis[3199]: (03199-02) get_deadline digest_hdr - deadline in 480.0 s, set to 336.000 s
Feb 11 20:09:53 mail amavis[3199]: (03199-02) prolong_timer digest_hdr: timer 336, was 336, deadline in 480.0 s
Feb 11 20:09:53 mail amavis[3199]: (03199-02) get_body_digest: reading mail body from a file
Feb 11 20:09:53 mail amavis[3199]: (03199-02) get_deadline digest_body - deadline in 480.0 s, set to 336.000 s
Feb 11 20:09:53 mail amavis[3199]: (03199-02) prolong_timer digest_body: timer 336, was 336, deadline in 480.0 s
Feb 11 20:09:53 mail amavis[3199]: (03199-02) get_body_digest: message size 981305, header+sep 303, body 981002
Feb 11 20:09:53 mail amavis[3199]: (03199-02) body type (ESMTP BODY): unlabeled, good (h=0, b=0)
Feb 11 20:09:53 mail amavis[3199]: (03199-02) body hash: b2be74ffe4d4e64c7d6d8f1ff40153b8
Feb 11 20:09:53 mail amavis[3199]: (03199-02) ip_trace:
Feb 11 20:09:53 mail amavis[3199]: (03199-02) prepending client's IP address to trace: xx.xx.xx.xx
Feb 11 20:09:53 mail amavis[3199]: (03199-02) lookup_ip_acl (public_nets) arr.obj: key="xx.xx.xx.xx" matches "::ffff:0:0/96", result=1
Feb 11 20:09:53 mail amavis[3199]: (03199-02) Original mail size: 981305; quota set to: 314572800 bytes (fmin=5, fmax=500, qmin=102400, qmax=314572800)
Feb 11 20:09:53 mail amavis[3199]: (03199-02) Checking: pHHAoMu2GQa7 [xx.xx.xx.xx] <myname at mydomain.com> -> <mygmailaccount at gmail.com>
Feb 11 20:09:53 mail amavis[3199]: (03199-02) 2822.From: <myname at mydomain.com>
Feb 11 20:09:53 mail amavis[3199]: (03199-02) lookup_ldap_attr(amavisLocal), "mygmailaccount at gmail.com" no matching entries
Feb 11 20:09:53 mail amavis[3199]: (03199-02) lookup_re("mygmailaccount at gmail.com") matches key "(?^:.*)", result="1"
Feb 11 20:09:53 mail amavis[3199]: (03199-02) lookup [local_domains] => true,  "mygmailaccount at gmail.com" matches, result="1", matching_key="(?^:.*)"
Feb 11 20:09:53 mail amavis[3199]: (03199-02) lookup_ldap_attr(amavisBypassVirusChecks), "mygmailaccount at gmail.com" no matching entries
Feb 11 20:09:53 mail amavis[3199]: (03199-02) lookup [bypass_virus_checks] => undef, "mygmailaccount at gmail.com" does not match
Feb 11 20:09:53 mail amavis[3199]: (03199-02) lookup_ldap_attr(amavisBypassBannedChecks), "mygmailaccount at gmail.com" no matching entries
Feb 11 20:09:53 mail amavis[3199]: (03199-02) lookup [bypass_banned_checks] => undef, "mygmailaccount at gmail.com" does not match
Feb 11 20:09:53 mail amavis[3199]: (03199-02) lookup_ldap_attr(amavisBypassSpamChecks), "mygmailaccount at gmail.com" no matching entries
Feb 11 20:09:53 mail amavis[3199]: (03199-02) lookup [bypass_spam_checks] => undef, "mygmailaccount at gmail.com" does not match
Feb 11 20:09:53 mail amavis[3199]: (03199-02) Extracting mime components from a file
Feb 11 20:09:53 mail amavis[3199]: (03199-02) Issued a new file name: p001
Feb 11 20:09:53 mail amavis[3199]: (03199-02) Issued a new file name: p002
Feb 11 20:09:53 mail amavis[3199]: (03199-02) mime_decode_preamble: 1 lines
Feb 11 20:09:53 mail amavis[3199]: (03199-02) Issued a new pseudo part: p003
Feb 11 20:09:53 mail amavis[3199]: (03199-02) p003 1 Content-Type: multipart/mixed
Feb 11 20:09:53 mail amavis[3199]: (03199-02) Charging 2 bytes to remaining quota 314572800 (out of 314572800, (0%)) - by mime_decode
Feb 11 20:09:53 mail amavis[3199]: (03199-02) p001 1/1 Content-Type: text/plain, size: 2 B, name:
Feb 11 20:09:53 mail amavis[3199]: (03199-02) reparenting p001 from p000 to p003
Feb 11 20:09:53 mail amavis[3199]: (03199-02) Charging 715548 bytes to remaining quota 314572798 (out of 314572800, (0%)) - by mime_decode
Feb 11 20:09:53 mail amavis[3199]: (03199-02) p002 1/2 Content-Type: application/pdf, size: 715548 B, name: pdf_attachment.pdf
Feb 11 20:09:53 mail amavis[3199]: (03199-02) reparenting p002 from p000 to p003
Feb 11 20:09:54 mail amavis[3199]: (03199-02) get_deadline mime_decode - deadline in 479.9 s, set to 336.000 s
Feb 11 20:09:54 mail amavis[3199]: (03199-02) prolong_timer mime_decode: timer 336, was 336, deadline in 479.9 s
Feb 11 20:09:54 mail amavis[3199]: (03199-02) get_deadline mime_decode-1 - deadline in 479.9 s, set to 336.000 s
Feb 11 20:09:54 mail amavis[3199]: (03199-02) prolong_timer mime_decode-1: timer 336, was 336, deadline in 479.9 s
Feb 11 20:09:54 mail amavis[3199]: (03199-02) inspect_dsn: parts: multipart/mixed, text/plain, application/pdf
Feb 11 20:09:54 mail amavis[3199]: (03199-02) inspect_dsn: not a bounce
Feb 11 20:09:54 mail amavis[3199]: (03199-02) get_deadline dsn_parse - deadline in 479.9 s, set to 336.000 s
Feb 11 20:09:54 mail amavis[3199]: (03199-02) prolong_timer dsn_parse: timer 336, was 336, deadline in 479.9 s
Feb 11 20:09:54 mail amavis[3199]: (03199-02) decode_parts: level=1, #parts=3 : p001, p002, p003
Feb 11 20:09:54 mail amavis[3199]: (03199-02) running file(1) on 2 files, arglist size 23
Feb 11 20:09:54 mail amavis[3199]: (03199-02) run_command: [3453] /usr/bin/file p001 p002 </dev/null 2>&1
Feb 11 20:09:54 mail amavis[3453]: (03199-02) open_on_specific_fd: target fd0 closing, to become < /dev/null
Feb 11 20:09:54 mail amavis[3453]: (03199-02) open_on_specific_fd: target fd1 closing, to become (65) &=19
Feb 11 20:09:54 mail amavis[3453]: (03199-02) open_on_specific_fd: target fd1 dup2 from fd19 (65) &=19
Feb 11 20:09:54 mail amavis[3453]: (03199-02) open_on_specific_fd: source fd19 closed
Feb 11 20:09:54 mail amavis[3453]: (03199-02) open_on_specific_fd: target fd2 closing, to become (65) &1
Feb 11 20:09:54 mail amavis[3453]: (03199-02) open_on_specific_fd: target fd2 dup2 from fd1 (65) &1
Feb 11 20:09:54 mail amavis[3199]: (03199-02) result line from file(1): p001: ASCII text\n
Feb 11 20:09:54 mail amavis[3199]: (03199-02) lookup_re("ASCII text") matches key "(?^i:^(ASCII|text)\b)", result="asc"
Feb 11 20:09:54 mail amavis[3199]: (03199-02) lookup [map_full_type_to_short_type] => true,  "ASCII text" matches, result="asc", matching_key="(?^i:^(ASCII|text)\134b)"
Feb 11 20:09:54 mail amavis[3199]: (03199-02) File-type of p001: ASCII text; (asc)
Feb 11 20:09:54 mail amavis[3199]: (03199-02) result line from file(1): p002: PDF document, version 1.4\n
Feb 11 20:09:54 mail amavis[3199]: (03199-02) lookup_re("PDF document, version 1.4") matches key "(?^:^PDF document\b)", result="pdf"
Feb 11 20:09:54 mail amavis[3199]: (03199-02) lookup [map_full_type_to_short_type] => true,  "PDF document, version 1.4" matches, result="pdf", matching_key="(?^:^PDF document\134b)"
Feb 11 20:09:54 mail amavis[3199]: (03199-02) File-type of p002: PDF document, version 1.4; (pdf)
Feb 11 20:09:54 mail amavis[3199]: (03199-02) do_ascii: Decoding part p001
Feb 11 20:09:54 mail amavis[3199]: (03199-02) do_ascii: Setting sigaction handler, was 0
Feb 11 20:09:54 mail amavis[3199]: (03199-02) get_deadline do_ascii_pre - deadline in 479.9 s, set to 336.000 s
Feb 11 20:09:54 mail amavis[3199]: (03199-02) prolong_timer do_ascii_pre: timer 336, was 0, deadline in 479.9 s
Feb 11 20:09:54 mail amavis[3199]: (03199-02) do_ascii: Decoding part p001 (0 items), uulib V0.5pl20
Feb 11 20:09:54 mail amavis[3199]: (03199-02) get_deadline do_ascii - deadline in 479.9 s, set to 336.000 s
Feb 11 20:09:54 mail amavis[3199]: (03199-02) prolong_timer do_ascii: timer 336, was 336, deadline in 479.9 s
Feb 11 20:09:54 mail amavis[3199]: (03199-02) decompose_part: p001 - atomic
Feb 11 20:09:54 mail amavis[3199]: (03199-02) decompose_part: p002 - atomic
Feb 11 20:09:54 mail amavis[3199]: (03199-02) get_deadline parts_decode - deadline in 479.9 s, set to 336.000 s
Feb 11 20:09:54 mail amavis[3199]: (03199-02) prolong_timer parts_decode: timer 336, was 336, deadline in 479.9 s
Feb 11 20:09:54 mail amavis[3199]: (03199-02) lookup_ldap_attr(amavisBypassHeaderChecks), "mygmailaccount at gmail.com" no matching entries
Feb 11 20:09:54 mail amavis[3199]: (03199-02) lookup [bypass_header_checks] => undef, "mygmailaccount at gmail.com" does not match
Feb 11 20:09:54 mail amavis[3199]: (03199-02) check_header: 0, OK
Feb 11 20:09:54 mail amavis[3199]: (03199-02) lookup_ldap_attr(amavisBypassHeaderChecks), "mygmailaccount at gmail.com" no matching entries
Feb 11 20:09:54 mail amavis[3199]: (03199-02) lookup [bypass_header_checks] => undef, "mygmailaccount at gmail.com" does not match
Feb 11 20:09:54 mail amavis[3199]: (03199-02) Checking for banned types and filenames
Feb 11 20:09:54 mail amavis[3199]: (03199-02) lookup_ldap_attr(amavisBannedRuleNames), "mygmailaccount at gmail.com" no matching entries
Feb 11 20:09:54 mail amavis[3199]: (03199-02) lookup: (scalar) matches, result="DEFAULT"
Feb 11 20:09:54 mail amavis[3199]: (03199-02) lookup [banned_filename], 1 matches for "mygmailaccount at gmail.com", results: "(constant:DEFAULT)"=>"DEFAULT"
Feb 11 20:09:54 mail amavis[3199]: (03199-02) collect banned table[0]: mygmailaccount at gmail.com, tables: DEFAULT=>Amavis::Lookup::RE=ARRAY(0x35b8218)
Feb 11 20:09:54 mail amavis[3199]: (03199-02) starting banned checks - traversing message structure tree
Feb 11 20:09:54 mail amavis[3199]: (03199-02) check_for_banned (p003,p001) multipart/mixed | text/plain,.asc
Feb 11 20:09:54 mail amavis[3199]: (03199-02) doing banned check for mygmailaccount at gmail.com on multipart/mixed | text/plain,.asc
Feb 11 20:09:54 mail amavis[3199]: (03199-02) lookup_re(["multipart/mixed","text/plain",".asc"]), no matches
Feb 11 20:09:54 mail amavis[3199]: (03199-02) lookup [check_bann:mygmailaccount at gmail.com] => undef, ["multipart/mixed","text/plain",".asc"] does not match
Feb 11 20:09:54 mail amavis[3199]: (03199-02) lookup [banned_namepath_re] => undef, "P=p003\tL=1\tM=multipart/mixed\nP=p001\tL=1/1\tM=text/plain\tT=asc" does not match
Feb 11 20:09:54 mail amavis[3199]: (03199-02) p.path mygmailaccount at gmail.com: "P=p003,L=1,M=multipart/mixed | P=p001,L=1/1,M=text/plain,T=asc"
Feb 11 20:09:54 mail amavis[3199]: (03199-02) check_for_banned (p003,p002) multipart/mixed | application/pdf,.pdf,pdf_attachment.pdf
Feb 11 20:09:54 mail amavis[3199]: (03199-02) doing banned check for mygmailaccount at gmail.com on multipart/mixed | application/pdf,.pdf,pdf_attachment.pdf
Feb 11 20:09:54 mail amavis[3199]: (03199-02) lookup_re(["multipart/mixed","application/pdf",".pdf","pdf_attachment.pdf"]), no matches
Feb 11 20:09:54 mail amavis[3199]: (03199-02) lookup [check_bann:mygmailaccount at gmail.com] => undef, ["multipart/mixed","application/pdf",".pdf","pdf_attachment.pdf"] does not match
Feb 11 20:09:54 mail amavis[3199]: (03199-02) lookup [banned_namepath_re] => undef, "P=p003\tL=1\tM=multipart/mixed\nP=p002\tL=1/2\tM=application/pdf\tT=pdf\tN=pdf_attachment.pdf" does not match
Feb 11 20:09:54 mail amavis[3199]: (03199-02) p.path mygmailaccount at gmail.com: "P=p003,L=1,M=multipart/mixed | P=p002,L=1/2,M=application/pdf,T=pdf,N=pdf_attachment.pdf"
Feb 11 20:09:54 mail amavis[3199]: (03199-02) banned check: any=0, all=N (1)
Feb 11 20:09:54 mail amavis[3199]: (03199-02) lookup_re("MAIL") matches key "(?^:^MAIL$)", result="1"
Feb 11 20:09:54 mail amavis[3199]: (03199-02) lookup [keep_decoded_original] => true,  "MAIL" matches, result="1", matching_key="(?^:^MAIL$)"
Feb 11 20:09:54 mail amavis[3199]: (03199-02) Issued a new file name: p004
Feb 11 20:09:54 mail amavis[3199]: (03199-02) presenting full original message to scanners as /var/spool/amavisd/tmp/amavis-20150211T200431-03199-llUvj6Ce/parts/p004
Feb 11 20:09:54 mail amavis[3199]: (03199-02) Calling virus scanners, 3 files to scan in /var/spool/amavisd/tmp/amavis-20150211T200431-03199-llUvj6Ce/parts
Feb 11 20:09:54 mail amavis[3199]: (03199-02) invoking av-scanner ClamAV-clamd
Feb 11 20:09:54 mail amavis[3199]: (03199-02) ask_daemon: proto=DFLT, spawn=0, (ClamAV-clamd) /var/run/clamd.amavisd/clamd.sock
Feb 11 20:09:54 mail amavis[3199]: (03199-02) run_av (ClamAV-clamd): query template(1,2): CONTSCAN {}\n
Feb 11 20:09:54 mail amavis[3199]: (03199-02) get_deadline run_av_pre - deadline in 479.8 s, set to 336.000 s
Feb 11 20:09:54 mail amavis[3199]: (03199-02) prolong_timer run_av_pre: timer 336, was 336, deadline in 479.8 s
Feb 11 20:09:54 mail amavis[3199]: (03199-02) get_deadline run_av_scan - deadline in 479.8 s, set to 336.000 s
Feb 11 20:09:54 mail amavis[3199]: (03199-02) prolong_timer run_av_scan: timer 336, was 336, deadline in 479.8 s
Feb 11 20:09:54 mail amavis[3199]: (03199-02) run_av Using (ClamAV-clamd): (code) CONTSCAN /var/spool/amavisd/tmp/amavis-20150211T200431-03199-llUvj6Ce/parts\n
Feb 11 20:09:54 mail amavis[3199]: (03199-02) get_deadline ask_daemon_internal_connect_pre - deadline in 479.8 s, set to 336.000 s
Feb 11 20:09:54 mail amavis[3199]: (03199-02) get_deadline ask_daemon_internal_connect - deadline in 479.8 s, set to 10.000 s
Feb 11 20:09:54 mail amavis[3199]: (03199-02) prolong_timer ask_daemon_internal_connect: timer 10, was 336, deadline in 479.8 s
Feb 11 20:09:54 mail amavis[3199]: (03199-02) ClamAV-clamd: Connecting to socket  /var/run/clamd.amavisd/clamd.sock
Feb 11 20:09:54 mail amavis[3199]: (03199-02) new socket by IO::Socket::UNIX to /var/run/clamd.amavisd/clamd.sock, timeout 10
Feb 11 20:09:54 mail amavis[3199]: (03199-02) connected to /var/run/clamd.amavisd/clamd.sock successfully
Feb 11 20:09:54 mail amavis[3199]: (03199-02) ClamAV-clamd: Sending CONTSCAN /var/spool/amavisd/tmp/amavis-20150211T200431-03199-llUvj6Ce/parts\n to socket /var/run/clamd.amavisd/clamd.sock
Feb 11 20:09:54 mail amavis[3199]: (03199-02) rw_loop: needline=0, flush=1, wr=1, timeout=10
Feb 11 20:09:54 mail clamd[1116]: SelfCheck: Database status OK.
Feb 11 20:09:54 mail amavis[3199]: (03199-02) rw_loop: sending 76 chars
Feb 11 20:09:54 mail amavis[3199]: (03199-02) rw_loop sent 76> CONTSCAN /var/spool/amavisd/tmp/amavis-20150211T200431-03199-llUvj6Ce/parts\n
Feb 11 20:09:54 mail amavis[3199]: (03199-02) get_deadline ask_daemon_internal_scan - deadline in 479.8 s, set to 336.000 s
Feb 11 20:09:54 mail amavis[3199]: (03199-02) prolong_timer ask_daemon_internal_scan: timer 336, was 10, deadline in 479.8 s
Feb 11 20:09:54 mail amavis[3199]: (03199-02) rw_loop: needline=0, flush=0, wr=0, timeout=335.990
Feb 11 20:09:54 mail amavis[3199]: (03199-02) rw_loop: receiving
Feb 11 20:09:54 mail amavis[3199]: (03199-02) rw_loop read 71 chars< /var/spool/amavisd/tmp/amavis-20150211T200431-03199-llUvj6Ce/parts: OK\n
Feb 11 20:09:54 mail amavis[3199]: (03199-02) rw_loop: needline=0, flush=0, wr=0, timeout=335.990
Feb 11 20:09:54 mail amavis[3199]: (03199-02) rw_loop: receiving
Feb 11 20:09:54 mail amavis[3199]: (03199-02) rw_loop read: got eof
Feb 11 20:09:54 mail amavis[3199]: (03199-02) get_deadline ask_daemon_internal - deadline in 479.7 s, set to 336.000 s
Feb 11 20:09:54 mail amavis[3199]: (03199-02) prolong_timer ask_daemon_internal: timer 336, was 336, deadline in 479.7 s
Feb 11 20:09:54 mail amavis[3199]: (03199-02) get_deadline run_av_3 - deadline in 479.7 s, set to 336.000 s
Feb 11 20:09:54 mail amavis[3199]: (03199-02) prolong_timer run_av_3: timer 336, was 336, deadline in 479.7 s
Feb 11 20:09:54 mail amavis[3199]: (03199-02) run_av (ClamAV-clamd) result: /var/spool/amavisd/tmp/amavis-20150211T200431-03199-llUvj6Ce/parts: OK\n
Feb 11 20:09:54 mail amavis[3199]: (03199-02) run_av (ClamAV-clamd): CLEAN
Feb 11 20:09:54 mail amavis[3199]: (03199-02) run_av (ClamAV-clamd) result: clean
Feb 11 20:09:54 mail amavis[3199]: (03199-02) wbl: checking sender <myname at mydomain.com>
Feb 11 20:09:54 mail amavis[3199]: (03199-02) query_keys: myname at mydomain.com, @mydomain.com, @.mydomain.com, @.com, @.
Feb 11 20:09:54 mail amavis[3199]: (03199-02) wbl: (LDAP) query keys: "myname at mydomain.com", "@mydomain.com", "@.mydomain.com", "@.com", "@."
Feb 11 20:09:54 mail amavis[3199]: (03199-02) lookup_ldap_attr(amavisBlacklistSender), "mygmailaccount at gmail.com" no matching entries
Feb 11 20:09:54 mail amavis[3199]: (03199-02) lookup => undef, "mygmailaccount at gmail.com" does not match
Feb 11 20:09:54 mail amavis[3199]: (03199-02) lookup_ldap_attr(amavisWhitelistSender), "mygmailaccount at gmail.com" no matching entries
Feb 11 20:09:54 mail amavis[3199]: (03199-02) lookup => undef, "mygmailaccount at gmail.com" does not match
Feb 11 20:09:54 mail amavis[3199]: (03199-02) lookup [blacklist_recip<mygmailaccount at gmail.com>] => undef, "mygmailaccount at gmail.com" does not match
Feb 11 20:09:54 mail amavis[3199]: (03199-02) lookup [blacklist_sender<myname at mydomain.com>,blacklist_sender] => undef, "myname at mydomain.com" does not match
Feb 11 20:09:54 mail amavis[3199]: (03199-02) lookup [whitelist_recip<mygmailaccount at gmail.com>] => undef, "mygmailaccount at gmail.com" does not match
Feb 11 20:09:54 mail amavis[3199]: (03199-02) lookup [whitelist_sender<myname at mydomain.com>,whitelist_sender] => undef, "myname at mydomain.com" does not match
Feb 11 20:09:54 mail amavis[3199]: (03199-02) query_keys: mygmailaccount at gmail.com, mygmailaccount at gmail.com, mygmailaccount@, gmail.com, .gmail.com, .com, .
Feb 11 20:09:54 mail amavis[3199]: (03199-02) lookup_hash(mygmailaccount at gmail.com) matches keys: "."=>ARRAY(0x35be0f8)
Feb 11 20:09:54 mail amavis[3199]: (03199-02) lookup [score_recip<mygmailaccount at gmail.com>,score_sender], 1 matches for "mygmailaccount at gmail.com", results: "."=>[Amavis::Lookup::RE=ARRAY(0x35b8380),{amavis-user-admin at lists.sourceforge.net=>"-3",owner-postfix-announce at postfix.org=>"-3",ntbugtraq at listserv.ntbugtraq.com=>"-3",donotreply at sendmail.org=>"-3",slashdot at slashdot.org=>"-3",clp-request at comp.nus.edu.sg=>"-3",nobody at cert.org=>"-3",security-alerts at linuxsecurity.com=>"-3",cvs-commits-list-admin at gnome.org=>"-3",amavis-user-bounces at lists.sourceforge.net=>"-3",notification-return at lists.sophos.com=>"-3",mailman-announce-admin at python.org=>"-3",emailnews at genomeweb.com=>"-5",owner-textbreakingnews at cnnimail12.cnn.com=>"-5",ca+envelope at sendmail.org=>"-3",cert-advisory at us-cert.gov=>"-3",returns.groups.yahoo.com=>"-3",owner-postfix-users at postfix.org=>"-3",.example.net=>"1",securityfocus.com=>"-3",yahoo-dev-null at yahoo-inc.com=>"-3",owner-alert at iss.net=>"-3",sendmail-announce-request at lists.sendmail.org=>"-3",surveys...
Feb 11 20:09:54 mail amavis[3199]: (03199-02) ...-errors at lists.nua.ie=>"-3",spamassassin.apache.org=>"-3",lvs-users-admin at linuxvirtualserver.org=>"-3",sender at example.net=>"3",owner-sendmail-announce at lists.sendmail.org=>"-3",noreply at freshmeat.net=>"-3",ietf-123-owner at loki.ietf.org=>"-3",clusternews at linuxnetworx.com=>"-3",owner-technews at postel.acm.org=>"-3",rt-users-admin at lists.fsck.com=>"-3"}]
Feb 11 20:09:54 mail amavis[3199]: (03199-02) lookup_re("myname at mydomain.com"), no matches
Feb 11 20:09:54 mail amavis[3199]: (03199-02) query_keys: myname at mydomain.com, myname@, mydomain.com, .mydomain.com, .com, .
Feb 11 20:09:54 mail amavis[3199]: (03199-02) lookup_hash(myname at mydomain.com), no matches
Feb 11 20:09:54 mail amavis[3199]: (03199-02) lookup [score_sender<myname at mydomain.com>] => undef, "myname at mydomain.com" does not match
Feb 11 20:09:54 mail amavis[3199]: (03199-02) SpamControl: calling spam scanner SpamAssassin
Feb 11 20:09:54 mail amavis[3199]: (03199-02) get_deadline spam_scan_sa_pre - deadline in 479.7 s, set to 476.000 s
Feb 11 20:09:54 mail amavis[3199]: (03199-02) prolong_timer spam_scan_sa_pre: timer 476, was 336, deadline in 479.7 s
Feb 11 20:09:54 mail amavis[3199]: (03199-02) truncating a message passed to SA at 409904 bytes, orig 981305
Feb 11 20:09:54 mail amavis[3199]: (03199-02) lookup_ldap_attr(amavisSaUserConf), "mygmailaccount at gmail.com" no matching entries
Feb 11 20:09:54 mail amavis[3199]: (03199-02) lookup [sa_userconf] => undef, "mygmailaccount at gmail.com" does not match
Feb 11 20:09:54 mail amavis[3199]: (03199-02) lookup_ldap_attr(amavisSaUserName), "mygmailaccount at gmail.com" no matching entries
Feb 11 20:09:54 mail amavis[3199]: (03199-02) lookup [sa_username] => undef, "mygmailaccount at gmail.com" does not match
Feb 11 20:09:54 mail amavis[3199]: (03199-02) SA user config: "", username: "amavis", 0, (0)mygmailaccount at gmail.com
Feb 11 20:09:54 mail amavis[3199]: (03199-02) calling SA parse (0), SA vers 3.3.2, 3.003002, data as GLOB, recips_ind [0], user: "amavis"
Feb 11 20:09:54 mail amavis[3199]: (03199-02) get_deadline SA check - deadline in 479.7 s, set to 475.000 s
Feb 11 20:09:54 mail amavis[3199]: (03199-02) CALLING SA check (0)
Feb 11 20:09:55 mail amavis[3199]: (03199-02) DONE SA check (0)
Feb 11 20:09:55 mail amavis[3199]: (03199-02) get_deadline spam_scan_sa - deadline in 478.6 s, set to 336.000 s
Feb 11 20:09:55 mail amavis[3199]: (03199-02) prolong_timer spam_scan_sa: timer 336, was 475, deadline in 478.6 s
Feb 11 20:09:55 mail amavis[3199]: (03199-02) spam_scan: score=2.436 autolearn=no tests=[DNS_FROM_AHBL_RHSBL=2.438,NO_RECEIVED=-0.001,NO_RELAYS=-0.001] recips=0
Feb 11 20:09:55 mail amavis[3199]: (03199-02) get_deadline spam_scan - deadline in 478.6 s, set to 336.000 s
Feb 11 20:09:55 mail amavis[3199]: (03199-02) prolong_timer spam_scan: timer 336, was 336, deadline in 478.6 s
Feb 11 20:09:55 mail amavis[3199]: (03199-02) lookup_ldap_attr(amavisSpamTagLevel), "mygmailaccount at gmail.com" no matching entries
Feb 11 20:09:55 mail amavis[3199]: (03199-02) lookup: (scalar) matches, result="-10"
Feb 11 20:09:55 mail amavis[3199]: (03199-02) lookup [spam_tag_level] => true,  "mygmailaccount at gmail.com" matches, result="-10", matching_key="(constant:-10)"
Feb 11 20:09:55 mail amavis[3199]: (03199-02) lookup_ldap_attr(amavisSpamTag2Level), "mygmailaccount at gmail.com" no matching entries
Feb 11 20:09:55 mail amavis[3199]: (03199-02) lookup: (scalar) matches, result="6.2"
Feb 11 20:09:55 mail amavis[3199]: (03199-02) lookup [spam_tag2_level] => true,  "mygmailaccount at gmail.com" matches, result="6.2", matching_key="(constant:6.2)"
Feb 11 20:09:55 mail amavis[3199]: (03199-02) lookup_ldap_attr(amavisSpamTag3Level), "mygmailaccount at gmail.com" no matching entries
Feb 11 20:09:55 mail amavis[3199]: (03199-02) lookup [spam_tag3_level] => undef, "mygmailaccount at gmail.com" does not match
Feb 11 20:09:55 mail amavis[3199]: (03199-02) lookup_ldap_attr(amavisSpamKillLevel), "mygmailaccount at gmail.com" no matching entries
Feb 11 20:09:55 mail amavis[3199]: (03199-02) lookup: (scalar) matches, result="6.9"
Feb 11 20:09:55 mail amavis[3199]: (03199-02) lookup [spam_kill_level] => true,  "mygmailaccount at gmail.com" matches, result="6.9", matching_key="(constant:6.9)"
Feb 11 20:09:55 mail amavis[3199]: (03199-02) lookup_ldap_attr(amavisMessageSizeLimit), "mygmailaccount at gmail.com" no matching entries
Feb 11 20:09:55 mail amavis[3199]: (03199-02) lookup [message_size_limit] => undef, "mygmailaccount at gmail.com" does not match
Feb 11 20:09:55 mail amavis[3199]: (03199-02) final_destiny (ccat=0) is PASS, recip mygmailaccount at gmail.com
Feb 11 20:09:55 mail amavis[3199]: (03199-02) final_destiny PASS, recip mygmailaccount at gmail.com
Feb 11 20:09:55 mail amavis[3199]: (03199-02) do_notify_and_quar: ccat=CleanTag (1,1) ("1,1":CleanTag, "1":Clean, "0":CatchAll) ccat_block=(), qar_mth=
Feb 11 20:09:55 mail amavis[3199]: (03199-02) do_notify_and_quarantine: not quarantining, q_method off
Feb 11 20:09:55 mail amavis[3199]: (03199-02) skip admin notification, no administrators
Feb 11 20:09:55 mail amavis[3199]: (03199-02) do_notify_and_quarantine - done
Feb 11 20:09:55 mail amavis[3199]: (03199-02) lookup_ldap_attr(amavisForwardMethod), "mygmailaccount at gmail.com" no matching entries
Feb 11 20:09:55 mail amavis[3199]: (03199-02) lookup: (opaque) matches, result="smtp:[127.0.0.1]:10025"
Feb 11 20:09:55 mail amavis[3199]: (03199-02) lookup [forward_method] => true,  "mygmailaccount at gmail.com" matches, result="smtp:[127.0.0.1]:10025", matching_key="(opaque:smtp:[127.0.0.1]:10025)"
Feb 11 20:09:55 mail amavis[3199]: (03199-02) delivery method is 1, recips: mygmailaccount at gmail.com
Feb 11 20:09:55 mail amavis[3199]: (03199-02) lookup_ldap_attr(amavisSpamTagLevel), "mygmailaccount at gmail.com" no matching entries
Feb 11 20:09:55 mail amavis[3199]: (03199-02) lookup: (scalar) matches, result="-10"
Feb 11 20:09:55 mail amavis[3199]: (03199-02) lookup [spam_tag_level] => true,  "mygmailaccount at gmail.com" matches, result="-10", matching_key="(constant:-10)"
Feb 11 20:09:55 mail amavis[3199]: (03199-02) lookup_ldap_attr(amavisSpamTag2Level), "mygmailaccount at gmail.com" no matching entries
Feb 11 20:09:55 mail amavis[3199]: (03199-02) lookup: (scalar) matches, result="6.2"
Feb 11 20:09:55 mail amavis[3199]: (03199-02) lookup [spam_tag2_level] => true,  "mygmailaccount at gmail.com" matches, result="6.2", matching_key="(constant:6.2)"
Feb 11 20:09:55 mail amavis[3199]: (03199-02) lookup_ldap_attr(amavisSpamSubjectTag), "mygmailaccount at gmail.com" no matching entries
Feb 11 20:09:55 mail amavis[3199]: (03199-02) lookup [spam_subject_tag] => undef, "mygmailaccount at gmail.com" does not match
Feb 11 20:09:55 mail amavis[3199]: (03199-02) headers CLUSTERING: NEW CLUSTER <mygmailaccount at gmail.com>: score=2.436, tag=1, tag2=0, local=1, bl=, s=, mangle=
Feb 11 20:09:55 mail amavis[3199]: (03199-02) header: X-Virus-Scanned: amavisd-new at mydomain.co.uk\n
Feb 11 20:09:55 mail amavis[3199]: (03199-02) header: X-Spam-Flag: NO\n
Feb 11 20:09:55 mail amavis[3199]: (03199-02) header: X-Spam-Score: 2.436\n
Feb 11 20:09:55 mail amavis[3199]: (03199-02) header: X-Spam-Level: **\n
Feb 11 20:09:55 mail amavis[3199]: (03199-02) header: X-Spam-Status: No, score=2.436 tagged_above=-10 required=6.2\n\ttests=[DNS_FROM_AHBL_RHSBL=2.438, NO_RECEIVED=-0.001,\n\tNO_RELAYS=-0.001] autolearn=no\n
Feb 11 20:09:55 mail amavis[3199]: (03199-02) fwd: scanner provided a header field X-Spam-Checker-Version, inhibited by %allowed_added_header_fields
Feb 11 20:09:55 mail amavis[3199]: (03199-02) fwd: scanner provided a header field X-Spam-Level, but we preferred our own
Feb 11 20:09:55 mail amavis[3199]: (03199-02) fwd: scanner provided a header field X-Spam-Status, but we preferred our own
Feb 11 20:09:55 mail amavis[3199]: (03199-02) header: Received: from mail.mydomain.co.uk ([127.0.0.1])\n\tby localhost (mail.mydomain.co.uk [127.0.0.1]) (amavisd-new, port 10024)\n\twith ESMTP id pHHAoMu2GQa7 for <mygmailaccount at gmail.com>;\n\tWed, 11 Feb 2015 20:09:53 +0000 (GMT)\n
Feb 11 20:09:55 mail amavis[3199]: (03199-02) headers CLUSTERING: done all 1 recips in one go
Feb 11 20:09:55 mail amavis[3199]: (03199-02) spam-tag, <myname at mydomain.com> -> <mygmailaccount at gmail.com>, No, score=2.436 tagged_above=-10 required=6.2 tests=[DNS_FROM_AHBL_RHSBL=2.438, NO_RECEIVED=-0.001, NO_RELAYS=-0.001] autolearn=no
Feb 11 20:09:55 mail amavis[3199]: (03199-02) dkim: not signing mail which is not originating from our site
Feb 11 20:09:55 mail amavis[3199]: (03199-02) about to connect to smtp:[127.0.0.1]:10025, pHHAoMu2GQa7 FWD from <myname at mydomain.com> -> <mygmailaccount at gmail.com>
Feb 11 20:09:55 mail amavis[3199]: (03199-02) get_deadline fwd_init - deadline in 478.6 s, set to 479.000 s
Feb 11 20:09:55 mail amavis[3199]: (03199-02) smtp session reuse (smtp:[127.0.0.1]:10025), 1 transactions so far
Feb 11 20:09:55 mail amavis[3199]: (03199-02) establish_or_refresh, state: ehlo
Feb 11 20:09:55 mail amavis[3199]: (03199-02) smtp cmd> NOOP
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: needline=0, flush=1, wr=1, timeout=15
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: receiving
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop read 58 chars< 421 4.4.2 mail.mydomain.co.uk Error: timeout exceeded\r\n
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: sending 6 chars
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop sent 6> NOOP\r\n
Feb 11 20:09:55 mail amavis[3199]: (03199-02) smtp resp to NOOP (idle 322.6 s): 421 4.4.2 mail.mydomain.co.uk Error: timeout exceeded
Feb 11 20:09:55 mail amavis[3199]: (03199-02) Amavis::Out::SMTP::Session close, disconnecting
Feb 11 20:09:55 mail amavis[3199]: (03199-02) new socket using IO::Socket::IP to [127.0.0.1]:10025, timeout 35
Feb 11 20:09:55 mail amavis[3199]: (03199-02) connected to [127.0.0.1]:10025 successfully
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: needline=1, flush=0, wr=0, timeout=35
Feb 11 20:09:55 mail postfix/smtpd[3413]: connect from localhost[127.0.0.1]
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: receiving
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop read 42 chars< 220 mail.mydomain.co.uk ESMTP Postfix\r\n
Feb 11 20:09:55 mail amavis[3199]: (03199-02) smtp greeting: 220 mail.mydomain.co.uk ESMTP Postfix, dt: 5.4 ms
Feb 11 20:09:55 mail amavis[3199]: (03199-02) smtp cmd> EHLO localhost
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: needline=0, flush=1, wr=1, timeout=300
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: sending 16 chars
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop sent 16> EHLO localhost\r\n
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: needline=1, flush=0, wr=0, timeout=300
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: receiving
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop read 198 chars< 250-mail.mydomain.co.uk\r\n250-PIPELINING\r\n250-SIZE 20480000\r\n250-VRFY\r\n250-ETRN\r\n250-STARTTLS\r\n250-XFORWARD NAME ADDR PROTO HELO SOURCE PORT IDENT\r\n250-ENHANCEDSTATUSCODES\r\n250-8BITMIME\r\n250 DSN\r\n
Feb 11 20:09:55 mail amavis[3199]: (03199-02) smtp resp to EHLO: 250 mail.mydomain.co.uk\nPIPELINING\nSIZE 20480000\nVRFY\nETRN\nSTARTTLS\nXFORWARD NAME ADDR PROTO HELO SOURCE PORT IDENT\nENHANCEDSTATUSCODES\n8BITMIME\nDSN
Feb 11 20:09:55 mail amavis[3199]: (03199-02) tls active=0, capable=1, sec_level=0
Feb 11 20:09:55 mail amavis[3199]: (03199-02) Remote host presents itself as: mail.mydomain.co.uk, handles DSN, handles PIPELINING
Feb 11 20:09:55 mail amavis[3199]: (03199-02) smtp cmd> XFORWARD ADDR=xx.xx.xx.xx PORT=64204 PROTO=ESMTP HELO=[192.168.235.104] SOURCE=REMOTE IDENT=B1FA718004A21
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: needline=0, flush=1, wr=1, timeout=300
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: sending 109 chars
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop sent 109> XFORWARD ADDR=xx.xx.xx.xx PORT=64204 PROTO=ESMTP HELO=[192.168.235.104] SOURCE=REMOTE IDENT=B1FA718004A21\r\n
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: needline=1, flush=0, wr=0, timeout=300
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: receiving
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop read 14 chars< 250 2.0.0 Ok\r\n
Feb 11 20:09:55 mail amavis[3199]: (03199-02) smtp resp to XFORWARD: 250 2.0.0 Ok
Feb 11 20:09:55 mail amavis[3199]: (03199-02) AUTH not needed, user='', MTA offers ''
Feb 11 20:09:55 mail amavis[3199]: (03199-02) smtp cmd> MAIL FROM:<myname at mydomain.com> BODY=7BIT
Feb 11 20:09:55 mail amavis[3199]: (03199-02) smtp cmd> RCPT TO:<mygmailaccount at gmail.com> ORCPT=rfc822;mygmailaccount at gmail.com
Feb 11 20:09:55 mail amavis[3199]: (03199-02) smtp cmd> DATA
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: needline=0, flush=1, wr=1, timeout=120
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: sending 113 chars
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop sent 113> MAIL FROM:<myname at mydomain.com> BODY=7BIT\r\nRCPT TO:<mygmailaccount at gmail.com> ORCPT=rfc822;mygmailaccount at gmail.com\r\nDATA\r\n
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: needline=1, flush=0, wr=0, timeout=300
Feb 11 20:09:55 mail postfix/smtpd[3413]: 6714618004A22: client=localhost[127.0.0.1], orig_queue_id=B1FA718004A21, orig_client=unknown[xx.xx.xx.xx]
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: receiving
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop read 65 chars< 250 2.1.0 Ok\r\n250 2.1.5 Ok\r\n354 End data with <CR><LF>.<CR><LF>\r\n
Feb 11 20:09:55 mail amavis[3199]: (03199-02) smtp resp to MAIL (pip): 250 2.1.0 Ok
Feb 11 20:09:55 mail amavis[3199]: (03199-02) smtp resp to RCPT (pip) (<mygmailaccount at gmail.com>): 250 2.1.5 Ok
Feb 11 20:09:55 mail amavis[3199]: (03199-02) smtp resp to DATA: 354 End data with <CR><LF>.<CR><LF>
Feb 11 20:09:55 mail amavis[3199]: (03199-02) write_header: 0, Amavis::Out::SMTP::Protocol=HASH(0x795a888)
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: needline=0, flush=1, wr=1, timeout=180
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: sending 67231 chars
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop sent 67231> X-Virus-Scanned: amavisd-new at mydomain.co.uk\r\nX-Spam-Flag: NO\r\nX-Spam-Score: 2.436\r\nX-Spam-Level: **\r\nX-Spam-Status: No, score=2.436 tagged_above=-10 required=6.2\r\n\ttests=[DNS_FROM_AHBL_RHSBL=2.4 [...]
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: needline=0, flush=1, wr=1, timeout=180
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: sending 66434 chars
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop sent 66434> FEDhBt3QogvCnCo00U7oCoWKyQQpooq\r\nEDQDVOUT0QW9ipyiIB3U9VUG6AiJwgcqeiIUFCmt0VKCcKhT808kFTZEGyByiJwgWN0KgVKB\r\nqgTRRBTunKhQIMlE50QIKBoiG/yQoJ8kREC6iqhQUIFAqUAoN0QICJwiAqiIHqgREDlCLoiC\r\nFAFSoguqnoqiAEOyeiX [...]
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: needline=0, flush=1, wr=1, timeout=180
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: sending 66434 chars
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop sent 66434> w/TMT+1HMUytyrZqSfKNe6HctuWwARcg33XeJjohgCaheHDpM\r\naVdm/HBjOv8Ae/5LznGk3X4HtH1KLhCXgzNYZLMbDhxQLFvgjNuRxdcnOYl64xoJhMoUOXdv\r\n4kGA0n01JCi2tHT+TmenPXk4SlJyJNUmdgk5XnVoLC8EjuP4r2qv1ukYfgy8WuVCHJw5mKYc\r\nJ [...]
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: needline=0, flush=1, wr=1, timeout=180
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: sending 66433 chars
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop sent 66433> H9EyUtH98EMRPeIbjbLfa1u5XZKt1nxfimRiUeRkoMuY48OIJKC4viAixbza6/TTZWn\r\nsaWspdPa07gS7Rdb6dLykpEiPk5GSlojhvBghhP0U7rryf2euns5hmSmMQ1yF4FRm4XgwID2\r\n/FBZe5J7E6fJdL9q4sOLaCxzruFPIdYa/jK/SkTM914hJ4WiakZOafDfO [...]
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: needline=0, flush=1, wr=1, timeout=180
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: sending 66434 chars
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop sent 66434> iYPos9IzM9Aa\r\n+ZmpgeGJcE2IB725Xo1Aof6Hw5ApJi+9RWyxhRIkYlwiPI1JvwVyT48TUOc34hwoPxAg2cOU\r\nxNeJ9JanibBc47CtSwrOPlpioOeycYLQ4bXWudjpoOV2nEODZ+Q6qS+NKC3xwYLmTks13xPs\r\n21gPMW+YXoD5qK+G8h5a0aArGCC0Ns672/tBDX [...]
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: needline=0, flush=1, wr=1, timeout=180
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: sending 66434 chars
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop sent 66434> jR4cQudD3GjedQER3+WtFmWQ3Ehh5C\r\n63gfHlJxnN1uTpkGagxKTEyPdGtZ+pGlvRa8CYtfiifj5qVEp8kYp9yfGuHx2AXJIO19PquH\r\n6aYyk67Dxm+SwzApz6W8h3uwGaZd8RANh3B+qpjuc1X6RK1uSosafhGqzbixks05nN+G9zbb\r\nRfBjfGNJwVAp0erwpmM2 [...]
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: needline=0, flush=1, wr=1, timeout=180
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: sending 66434 chars
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop sent 66434> my15fnDbAXXOkWKzQdR6hYQfi6UkoLJ1ssJeKIurL31WfUDA\r\n8tjGj06Wiz75ackB+pmGjS9h/ILtJ+Sm3CK8zg4Bx5MQhJVLH3/VYAa4Qr53N7f0VymFulgw\r\nni6WrNEq4fKiGWRocdt3vJ3N13gNX0whdoPCYmusVzB0ep9Q6ZiWHPQWQJVuV0Ig5iu0VCCZ\r\nyT [...]
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: needline=0, flush=1, wr=1, timeout=180
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: sending 66433 chars
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop sent 66433> Y7j5r36FFhx4EGPAcXQozBEYSNwRcIVkNDrqiqlkQT0QIgiBUqICqg0V5QRWyIEBFF\r\neUEVQqBBQonCIHoiJqgIiD6ICfdEKAqoqgnKqgVvogBERARDsnqgnqnKFEAIgRACcoqEEVCh\r\nVQfcUCFAsjr8P8IWbVhD/CFmFoYR/wC7Povpl9JSBsPhXyx/7p3ovpl/+z [...]
Feb 11 20:09:55 mail postfix/cleanup[3455]: 6714618004A22: message-id=<54DBB716.2090403 at mydomain.com>
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: needline=0, flush=1, wr=1, timeout=180
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: sending 66434 chars
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop sent 66434> Qup06OZjBOJ\r\n4sAg5mw4znMLfm3+QWFKx3jfAtclKX1Ahe9SEd+QTLwCbXtcPG6iu/db48yzpdVXSrogjENb\r\nE8Iccr5ei0lhSJgqQdRYFPjT5hgzXiNa6Ln5vfX+C77Fhy0xIvEZsONITLACIjhZzXLyLEHQ\r\naUdPxJvC1bj0uO45hCcSWtPkRqqjt/Unp9JYrw/ [...]
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: needline=0, flush=1, wr=1, timeout=180
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: sending 66434 chars
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop sent 66434> egzDIee1nOaePO1lTtuPRK/iJlHwV\r\nFxDEky8Ml2xvAD/3raX+a6HG640Uyku6nUeoT05EaHRYEJukLyzc/Rc31KuOhs5mNnCnweOf\r\ngWXRKkS1H6c0yPAhQ/eZtnjRogGriT38lBqwN1Uo+K6o6lxZOZpdRP4IUx+35A9123EFWp+H\r\nabFqFZmBBlYelzqXHsAvL [...]
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: needline=0, flush=1, wr=1, timeout=180
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: sending 66434 chars
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop sent 66434> X6QmAWzOXQ63BHK829oWkStUwRDnZKNL+9Up7YkIMii+XQW\r\nH2XY+nNfZiXA1KqTTeO1ogx9bnM3RIV5vjdgPtLUJoAHwwtjvovco2keINN14hi60T2m6E1o\r\nAtDh6/Je2RSPeImtzmQrzv2hj/8AKmmja595hi441XbKTCEPpfBaRtSSb+fh3XUvaKeB0njX\r\n5mo [...]
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: needline=0, flush=1, wr=1, timeout=180
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: sending 66433 chars
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop sent 66433> nRHEwYxzaX4+SuLmeXLT+IJGTm3SxzRIoDdRq2521XFzdarEXFMhKSUuBJRGZnWH1\r\nuVyTMOU9jnGGYhcSwguNx8Oy+uXqh97iS0zAdBcxtxEtoQn8DhathmcqGKfe3TeSm5LPhF1y\r\nXeQ4XM0ulSlLlXwZdubxHl73OG5v2X22+EOGrTsQibfCaOOYgljCRsS3ZHE [...]
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: needline=0, flush=1, wr=1, timeout=180
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: sending 66434 chars
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop sent 66434> N1RpxeGS85\r\nC+MsHY8o1e/d6K3yuswtcO0SG2JBzOhvF2m3CyAdb8J+iMM1slz+sPotQa/9130WcElsUX9C\r\noPEug0dsPHWJpV0S2cOcG33If/Ir2wNJNgDdfnOYqUDpn1nnpqdl4sSQfnLcgGbK8XuL72K5\r\nerdcanWI5ksE0VxjF1hEjNzvI7hg0H1Krk5Tbse8 [...]
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: needline=0, flush=1, wr=1, timeout=180
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: sending 66434 chars
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop sent 66434> ZkcLkG1wV5XCaQwkgm8QfFbbReh9\r\nG5N09jORjfERKw3xnuI0AtYfmux0LZ1Jjzv1Pjwvx+d5/h78RleQNbFXS9go4gxHEbXv2VsC\r\nNF7b88qakixtZZWuEbsrv6KoiuvCD0RBBr6rARWZsnxB17Wt91s50CmoN76oBuqoRohKCqE2\r\nRS1hqg5MoEKBYHXP2OVKc5 [...]
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: needline=0, flush=1, wr=1, timeout=180
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: sending 50920 chars
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop sent 50920> jqqurynCgCqI8868ydTm8EyUWhwYkWoy8/CfDLG3cwagn7\r\nhfN1CwjMSnReWkqQIhqlIhsjwSwXeX/tgeuZy9Oa5zdjZA9+pubnTVFldFl6PUYfQqFSqbCi\r\nQqoaWGthg2dnIu4epufquk4cxBgCRospT4ODo03XGQ2MiSj6b4kR0W1jd7geb6/Ze4F7s+YH\r\n4jog [...]
Feb 11 20:09:55 mail amavis[3199]: (03199-02) smtp connection_cache disabled, sending QUIT
Feb 11 20:09:55 mail amavis[3199]: (03199-02) smtp cmd> QUIT
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: needline=0, flush=1, wr=1, timeout=478.901
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: sending 11 chars
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop sent 11> \r\n.\r\nQUIT\r\n
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: needline=1, flush=0, wr=0, timeout=478.901
Feb 11 20:09:55 mail postfix/qmgr[3190]: 6714618004A22: from=<myname at mydomain.com>, size=981565, nrcpt=1 (queue active)
Feb 11 20:09:55 mail postfix/smtpd[3413]: disconnect from localhost[127.0.0.1]
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop: receiving
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rw_loop read 54 chars< 250 2.0.0 Ok: queued as 6714618004A22\r\n221 2.0.0 Bye\r\n
Feb 11 20:09:55 mail amavis[3199]: (03199-02) smtp resp to data-dot (<mygmailaccount at gmail.com>): 250 2.0.0 Ok: queued as 6714618004A22, dt: 97.9 ms
Feb 11 20:09:55 mail amavis[3199]: (03199-02) Amavis::Out::SMTP::Session close, disconnecting
Feb 11 20:09:55 mail amavis[3199]: (03199-02) get_deadline fwd-end-chkpnt - deadline in 478.4 s, set to 335.000 s
Feb 11 20:09:55 mail amavis[3199]: (03199-02) prolong_timer fwd-end-chkpnt: timer 335, was 0, deadline in 478.4 s
Feb 11 20:09:55 mail amavis[3199]: (03199-02) pHHAoMu2GQa7 FWD from <myname at mydomain.com> -> <mygmailaccount at gmail.com>, BODY=7BIT 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 6714618004A22
Feb 11 20:09:55 mail amavis[3199]: (03199-02) get_deadline forwarding - deadline in 478.4 s, set to 335.000 s
Feb 11 20:09:55 mail amavis[3199]: (03199-02) prolong_timer forwarding: timer 335, was 335, deadline in 478.4 s
Feb 11 20:09:55 mail amavis[3199]: (03199-02) DSN: sender NOT credible, SA: 2.436, <myname at mydomain.com>
Feb 11 20:09:55 mail amavis[3199]: (03199-02) lookup: (scalar) matches, result="10"
Feb 11 20:09:55 mail amavis[3199]: (03199-02) lookup [spam_dsn_cutoff_level_bysender] => true,  "myname at mydomain.com" matches, result="10", matching_key="(constant:10)"
Feb 11 20:09:55 mail amavis[3199]: (03199-02) dsn: from MTA 250 NonBlocking:CleanTag <myname at mydomain.com> -> <mygmailaccount at gmail.com>: on_succ=0, on_dly=1, on_fail=1, never=0, warn_sender=, DSN_passed_on=1, destiny=1, mta_resp: "250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 6714618004A22"
Feb 11 20:09:55 mail amavis[3199]: (03199-02) DSN: SUCC from MTA 250 NonBlocking:CleanTag, no DSN requested: <myname at mydomain.com> -> <mygmailaccount at gmail.com>
Feb 11 20:09:55 mail amavis[3199]: (03199-02) delivery_status_notification: notif 0 bytes, suppressed: no
Feb 11 20:09:55 mail amavis[3199]: (03199-02) one_response_for_all, per_recip_capable: N, suppressed: N
Feb 11 20:09:55 mail amavis[3199]: (03199-02) one_response_for_all <myname at mydomain.com>: 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 6714618004A22'
Feb 11 20:09:55 mail amavis[3199]: (03199-02) notif=N, suppressed=0, ndn_needed=0, exit=0, 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 6714618004A22
Feb 11 20:09:55 mail amavis[3199]: (03199-02) get_deadline delivery-notification - deadline in 478.4 s, set to 335.000 s
Feb 11 20:09:55 mail amavis[3199]: (03199-02) prolong_timer delivery-notification: timer 335, was 335, deadline in 478.4 s
Feb 11 20:09:55 mail amavis[3199]: (03199-02) status counters: InMsgsStatus{Relayed,RelayedUntagged,RelayedUntaggedInbound}
Feb 11 20:09:55 mail amavis[3199]: (03199-02) get_deadline snmp-counters - deadline in 478.3 s, set to 335.000 s
Feb 11 20:09:55 mail amavis[3199]: (03199-02) prolong_timer snmp-counters: timer 335, was 335, deadline in 478.3 s
Feb 11 20:09:55 mail amavis[3199]: (03199-02) oldest_public_ip_addr_from_received: xx.xx.xx.xx
Feb 11 20:09:55 mail amavis[3199]: (03199-02) Passed CLEAN {RelayedInbound}, [xx.xx.xx.xx]:64204 [xx.xx.xx.xx] <myname at mydomain.com> -> <mygmailaccount at gmail.com>, Queue-ID: B1FA718004A21, Message-ID: <54DBB716.2090403 at mydomain.com>, mail_id: pHHAoMu2GQa7, Hits: 2.436, size: 981305, queued_as: 6714618004A22, 1729 ms
Feb 11 20:09:55 mail amavis[3199]: (03199-02) get_deadline main_log_entry - deadline in 478.3 s, set to 335.000 s
Feb 11 20:09:55 mail amavis[3199]: (03199-02) prolong_timer main_log_entry: timer 335, was 335, deadline in 478.3 s
Feb 11 20:09:55 mail amavis[3199]: (03199-02) TIMING-SA total 1066 ms - parse: 27 (2.6%), extract_message_metadata: 84 (7.8%), get_uri_detail_list: 0.39 (0.0%), tests_pri_-1000: 11 (1.1%), tests_pri_-950: 1.28 (0.1%), tests_pri_-900: 1.30 (0.1%), tests_pri_-400: 1.08 (0.1%), tests_pri_0: 905 (84.8%), check_dkim_adsp: 11 (1.0%), check_spf: 0.52 (0.0%), check_razor2: 810 (76.0%), check_pyzor: 0.30 (0.0%), tests_pri_500: 4 (0.4%), get_report: 0.84 (0.1%)
Feb 11 20:09:55 mail amavis[3199]: (03199-02) updating snmp variables in BDB
Feb 11 20:09:55 mail amavis[3199]: (03199-02) get_deadline check done - deadline in 478.3 s, set to 335.000 s
Feb 11 20:09:55 mail amavis[3199]: (03199-02) prolong_timer check done: timer 335, was 335, deadline in 478.3 s
Feb 11 20:09:55 mail amavis[3199]: (03199-02) sending SMTP response: "250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 6714618004A22"
Feb 11 20:09:55 mail amavis[3199]: (03199-02) ESMTP> 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 6714618004A22
Feb 11 20:09:55 mail amavis[3199]: (03199-02) switch_to_client_time 480 s, smtp response sent
Feb 11 20:09:55 mail amavis[3199]: (03199-02) TempDir::strip: /var/spool/amavisd/tmp/amavis-20150211T200431-03199-llUvj6Ce
Feb 11 20:09:55 mail amavis[3199]: (03199-02) rmdir_recursively: /var/spool/amavisd/tmp/amavis-20150211T200431-03199-llUvj6Ce/parts, excl=1
Feb 11 20:09:55 mail amavis[3199]: (03199-02) size: 981305, TIMING [total 1740 ms] - SMTP greeting: 3.1 (0%)0, SMTP EHLO: 7 (0%)1, SMTP pre-MAIL: 14 (1%)1, lookup_ldap: 21 (1%)3, SMTP pre-DATA-flush: 2.9 (0%)3, SMTP DATA: 20 (1%)4, check_init: 0.6 (0%)4, digest_hdr: 1.8 (0%)4, digest_body_dkim: 8 (0%)4, collect_info: 1.5 (0%)5, mime_decode: 61 (3%)8, get-file-type2: 65 (4%)12, decompose_part: 3.5 (0%)12, parts_decode: 0.3 (0%)12, check_header: 3.2 (0%)12, AV-scan-1: 164 (9%)22, spam-wb-list: 12 (1%)22, SA parse: 52 (3%)25, SA check: 1029 (59%)85, decide_mail_destiny: 20 (1%)86, notif-quar: 0.9 (0%)86, fwd-connect: 39 (2%)88, fwd-xforward: 6 (0%)88, fwd-mail-pip: 42 (2%)91, fwd-rcpt-pip: 0.3 (0%)91, fwd-data-chkpnt: 0.1 (0%)91, write-header: 0.8 (0%)91, fwd-data-contents: 29 (2%)92, fwd-end-chkpnt: 103 (6%)98, prepare-dsn: 6 (0%)99, report: 6 (0%)99, main_log_entry: 7 (0%)99, update_snmp: 6 (0%)100, SMTP pre-response: 0.6 (0%)100, SMTP response: 0.8 (0%)100, unlink-3-files: 0.9 (0%)100, rundown: 1....
Feb 11 20:09:55 mail amavis[3199]: (03199-02) ...5 (0%)100
Feb 11 20:09:55 mail amavis[3199]: (03199-02) idle_proc, 6: was busy, 1695.0 ms, total idle 320.991 s, busy 3.117 s
Feb 11 20:09:55 mail amavis[3199]: (03199-02) idle_proc, 5: was idle, 0.2 ms, total idle 320.991 s, busy 3.117 s
Feb 11 20:09:55 mail amavis[3199]: (03199-02) ESMTP< QUIT\r\n
Feb 11 20:09:55 mail amavis[3199]: (03199-02) get_deadline switch_to_my_time(rx SMTP QUIT) - deadline in 480.0 s, set to 336.000 s
Feb 11 20:09:55 mail amavis[3199]: (03199-02) prolong_timer switch_to_my_time(rx SMTP QUIT): timer 336, was 480, deadline in 480.0 s
Feb 11 20:09:55 mail amavis[3199]: (03199-02) ESMTP> 221 2.0.0 [127.0.0.1] amavisd-new closing transmission channel
Feb 11 20:09:55 mail amavis[3199]: (03199-02) switch_to_client_time 480 s, smtp response sent
Feb 11 20:09:55 mail amavis[3199]: (03199-02) SMTP session over, timer stopped
Feb 11 20:09:55 mail postfix/smtp[3452]: B1FA718004A21: to=<mygmailaccount at gmail.com>, relay=127.0.0.1[127.0.0.1]:10024, delay=3.3, delays=1.5/0.03/0.01/1.7, 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 6714618004A22)
Feb 11 20:09:55 mail postfix/qmgr[3190]: B1FA718004A21: removed
Feb 11 20:09:55 mail amavis[3199]: (03199-02) exiting process_request
Feb 11 20:09:55 mail amavis[3199]: (03199-02) idle_proc, bye: was busy, 28.5 ms, total idle 320.991 s, busy 3.146 s
Feb 11 20:09:55 mail amavis[3199]: (03199-02) load: 1 %, total idle 320.991 s, busy 3.146 s
Feb 11 20:09:55 mail postfix/smtp[3456]: 6714618004A22: to=<mygmailaccount at gmail.com>, relay=127.0.0.1[127.0.0.1]:10026, delay=0.27, delays=0.17/0.04/0.01/0.05, dsn=2.0.0, status=sent (250 Ok)
Feb 11 20:09:55 mail postfix/qmgr[3190]: 6714618004A22: removed
Feb 11 20:09:56 mail postfix/smtpd[3457]: connect from localhost[127.0.0.1]
Feb 11 20:09:56 mail postfix/smtpd[3457]: 38D3918004A21: client=localhost[127.0.0.1]
Feb 11 20:09:56 mail postfix/cleanup[3455]: 38D3918004A21: message-id=<54DBB716.2090403 at mydomain.com>
Feb 11 20:09:56 mail postfix/qmgr[3190]: 38D3918004A21: from=<myname at mydomain.com>, size=981561, nrcpt=1 (queue active)
Feb 11 20:09:56 mail postfix/smtpd[3457]: disconnect from localhost[127.0.0.1]
Feb 11 20:09:56 mail postfix/smtp[3232]: connect to gmail-smtp-in.l.google.com[2a00:1450:400c:c03::1a]:25: Network is unreachable


More information about the users mailing list