> Have you set debugging on the Mac server? It was. Problem is that I cannot search the logs for the above e-mail, because they have already rolled over, but I did manage to get the amavisd log for the e-mail. It's long (despite it being only two seconds of conversation), so I won't include it all, here, but it seems to be normal, in that the mail seems to have come internally to the spam filter. Here's the beginning of the conversation:
Jul 28 14:32:46 mymxserver.com /usr/bin/amavisd[26486]: (26486-10) loaded base policy bank Jul 28 14:32:46 mymxserver.com /usr/bin/amavisd[26486]: (26486-10) lookup_ip_acl (inet_acl): key="127.0.0.1" matches "127.0.0.1", result=1 Jul 28 14:32:46 mymxserver.com /usr/bin/amavisd[26486]: (26486-10) process_request: fileno sock=13, STDIN=0, STDOUT=1 Jul 28 14:32:46 mymxserver.com /usr/bin/amavisd[26486]: (26486-11) SMTP> 220 [127.0.0.1] ESMTP amavisd-new service ready Jul 28 14:32:46 mymxserver.com /usr/bin/amavisd[26486]: (26486-11) SMTP< EHLO mymxserver.com\r\n Jul 28 14:32:46 mymxserver.com /usr/bin/amavisd[26486]: (26486-11) ESMTP> 250-[127.0.0.1] Jul 28 14:32:46 mymxserver.com /usr/bin/amavisd[26486]: (26486-11) ESMTP> 250-VRFY Jul 28 14:32:46 mymxserver.com /usr/bin/amavisd[26486]: (26486-11) ESMTP> 250-PIPELINING Jul 28 14:32:46 mymxserver.com /usr/bin/amavisd[26486]: (26486-11) ESMTP> 250-SIZE Jul 28 14:32:46 mymxserver.com /usr/bin/amavisd[26486]: (26486-11) ESMTP> 250-ENHANCEDSTATUSCODES Jul 28 14:32:46 mymxserver.com /usr/bin/amavisd[26486]: (26486-11) ESMTP> 250-8BITMIME Jul 28 14:32:46 mymxserver.com /usr/bin/amavisd[26486]: (26486-11) ESMTP> 250-DSN Jul 28 14:32:46 mymxserver.com /usr/bin/amavisd[26486]: (26486-11) ESMTP> 250 XFORWARD NAME ADDR PROTO HELO Jul 28 14:32:46 mymxserver.com /usr/bin/amavisd[26486]: (26486-11) ESMTP< XFORWARD NAME=localhost ADDR=127.0.0.1\r\n Jul 28 14:32:46 mymxserver.com /usr/bin/amavisd[26486]: (26486-11) ESMTP> 250 2.5.0 Ok XFORWARD Jul 28 14:32:46 mymxserver.com /usr/bin/amavisd[26486]: (26486-11) ESMTP< XFORWARD PROTO=ESMTP HELO=mout3.freenet.de\r\n Jul 28 14:32:46 mymxserver.com /usr/bin/amavisd[26486]: (26486-11) ESMTP> 250 2.5.0 Ok XFORWARD Jul 28 14:32:46 mymxserver.com /usr/bin/amavisd[26486]: (26486-11) ESMTP< MAIL FROM:<[email protected]> SIZE=7630\r\n Jul 28 14:32:46 mymxserver.com /usr/bin/amavisd[26486]: (26486-11) check_mail_begin_task: task_count=11 Jul 28 14:32:46 mymxserver.com /usr/bin/amavisd[26486]: (26486-11) lookup_ip_acl (mynetworks): key="127.0.0.1" matches "127.0.0.0/8", result=1 Jul 28 14:32:46 mymxserver.com /usr/bin/amavisd[26486]: (26486-11) loaded policy bank "MYNETS" Jul 28 14:32:46 mymxserver.com /usr/bin/amavisd[26486]: (26486-11) lookup (debug_sender) => undef, "[email protected]" does not match Jul 28 14:32:46 mymxserver.com /usr/bin/amavisd[26486]: (26486-11) ESMTP> 250 2.1.0 Sender <[email protected]> OK Jul 28 14:32:46 mymxserver.com /usr/bin/amavisd[26486]: (26486-11) ESMTP< RCPT TO:<[email protected]> ORCPT=rfc822;[email protected] \r\n Jul 28 14:32:46 mymxserver.com /usr/bin/amavisd[26486]: (26486-11) ESMTP> 250 2.1.5 Recipient <[email protected]> OK Jul 28 14:32:46 mymxserver.com /usr/bin/amavisd[26486]: (26486-11) ESMTP< DATA\r\n Jul 28 14:32:46 mymxserver.com /usr/bin/amavisd[26486]: (26486-11) ESMTP::10024 /var/amavis/tmp/amavis-20090728T133830-26486: <[email protected] > -> <[email protected]> SIZE=7630 Received: from mymxserver.com ([127.0.0.1]) by localhost (mymxserver.com [127.0.0.1]) (amavisd-new, port 10024) with ESMTP for <[email protected]>; Tue, 28 Jul 2009 14:32:46 -0400 (EDT) Jul 28 14:32:46 mymxserver.com /usr/bin/amavisd[26486]: (26486-11) ESMTP> 354 End data with <CR><LF>.<CR><LF> Jul 28 14:32:46 mymxserver.com /usr/bin/amavisd[26486]: (26486-11) ESMTP< .<CR><LF> : : : The only event that was even close was two seconds from the assp log: Jul 28 14:32:48 mini lmtpunix[27938]: Delivered: <[email protected] > to mailbox: user.myuser This was at the time of the end of the amavisd log processing of this message, so I imagine this accounts for the two second difference of the two log sequences above. All this seems normal, but I'm not the expert in this. It still does not indicate how the mail got to amavisd internally but without being processed through assp. The assp log only shows mail from freenet.de on 24th. July and 26th. July. :-/ In my research, I did find this: http://developer.apple.com/documentation/Darwin/Reference/ManPages/man8/lmtp.8.html Note the bugs section. Not sure if that helps in this case, but it does indicate a potential for problems. FWIW, my firewall is set up to refuse all but allowed TCP traffic in. Note that port 24 mentioned in the Apple article is not open to outside computers. I just had a thought. I don't remember the exact times of my restarts of the server box during maintenance. Perhaps it's possible that the mail managed to get through as the various processes started up? I'm not convinced that this would be the only time at which the problem is occurring, but I do see this as potential for some mail to skip past assp. Mind you, assp is the process that has the ports open to the outside, not the mail server, so I'm still confused about possible causes of this. T. ------------------------------------------------------------------------------ Let Crystal Reports handle the reporting - Free Crystal Reports 2008 30-Day trial. Simplify your report design, integration and deployment - and focus on what you do best, core application coding. Discover what's new with Crystal Reports now. http://p.sf.net/sfu/bobj-july _______________________________________________ Assp-test mailing list [email protected] https://lists.sourceforge.net/lists/listinfo/assp-test
