Mailing List CGatePro@mail.stalker.com Message #100490
From: Jeff Wark <jwark@tbaytel.net>
Subject: Re: 532 access from your network is restricted, try later
Date: Tue, 03 Aug 2010 10:11:19 -0400
To: CommuniGate Pro Discussions <CGatePro@mail.stalker.com>
Are those google.com name servers you are using?  If so, would non-local name servers introduce a delay in the initial SMTP connection?  I don't really know what the speeds for you would be, but my testing shows 0-4ms for a host lookup to a local name server and 40-50ms to 8.8.8.8 -- ~12x longer.  The google name server also peaks out at >80ms sometimes.  That should add up fairly quickly when handling 850 concurrent SMTP connections.

I do like the mention of 3 connections per IP address as the culprit though.  That seems pretty relevant to the issue at hand.

On 8/3/2010 9:21 AM, Kee Hinckley wrote:
Here's the problem. My mail server is under heavy load (stats in a moment). An authenticated user attempts to send mail on the submit port. I've reserved slots for authenticated users, but you can't reserve them by *port*, so apparently they share resources with whatever comes in on port 25. For whatever reason, CGP "randomly" tells the user to go away with the bogus error: "532 access from your network is restricted, try later". This started happening a couple weeks ago, prior to that it had been running fine for 10 months, and I haven't touched the settings for nearly as long. Sometimes they get this error immediately after sending previous mail. Sometimes they get it the first time they connect. Sometimes they've fetched mail first. Sometimes they haven't. It has all appearances of being a resource problem, but a) there shouldn't be a resource problem for authenticated users and b) that's the wrong error message. See the log at the bottom for details.

At this point the only solution I can think of is to reduce the load on my machine by putting a graylisting server in-front of it. I'd *really* rather not complicate my situation by adding a whole piece of non-CGP software on a dedicated machine. I use CGP because it answers all my problems in one easy package. Furthermore, this looks like a DoS problem that any CGP installation could suffer from, and that's not good news for anybody.

So here are my SMTP Receiving settings:
850 Channels*
Advertise AUTH to everybody, ditto 8bitmime
Verify return-path for non-clients, help for non-clients.
I've turned off SPF (it was blocking a minuscule number of messages)
I've disabled Reverse Connect
Message Limits 100M
Recipients 100
Non-Client Sender:
Recipients 5 in 30 seconds
Delay prompt for 0 seconds (delays flood my queue)
Disconnect after 1 error and deny access for 0 seconds**
Listener
Init SSL/TLS off on 25, off on 587, on on 465
Limit connections from same address is 3
Reserve connections for Clients is 10***

* I can't pump it up to more than 850 channels without running out of sockets. I could configure the machine with more, but the spam flow is only increasing, so it's just a matter of time before I hit the problem again.
**I had set deny access to 5 minutes, but then I got reports that when a user got the 532 error, they couldn't *fetch* mail either, so until I've solved this problem, I've had to put it at 0 seconds.
*** The reserved connections may seem low, but I have a minimal license. I'm not getting more than 10 authenticated clients at a time. And I've tried 30, that didn't help.

Server Info
Main Domain Name: somewhere.com <http://somewhere.com>
Server Internals Log:
Crash Recovery:
Separate WebAdmin Realms:
Server Time: Thu, 29 Jul 2010 17:33:06 -0400
Server Up-time: 13 day(s) 7 hour(s) 55 min 13 sec
Server OS: Linux
Server Hardware: x86-64 (64-bit)
Server Version: 5.2.16
MAPI Version: 1.52.15.3
IPv6 Support: Disabled
Name Server(s) IP Address(es): [8.8.8.8], [8.8.4.4]
Server IP Address(es):
[127.0.0.1] somewhere.com <https://mail.somewhere.com:9010/Domains/DomainSettings.html?domainName=somewhere.com> [136.248.126.131] somewhere.com <https://mail.somewhere.com:9010/Domains/DomainSettings.html?domainName=somewhere.com> FWIW, I'm running the Debian version of CGP on Ubuntu.


So what's my load that's causing this problem? Here's a snapshot.

smtpInputActive <https://mail.somewhere.com:9010/Monitors/SNMPElement.html?id=1.3.6.1.4.1.5678.2.1.1.1.1.1> 825 smtpInputTotal <https://mail.somewhere.com:9010/Monitors/SNMPElement.html?id=1.3.6.1.4.1.5678.2.1.1.1.1.2> 850
smtpInputJobs <https://mail.somewhere.com:9010/Monitors/SNMPElement.html?id=1.3.6.1.4.1.5678.2.1.1.1.1.3> 34M smtpInputTrafficIn <https://mail.somewhere.com:9010/Monitors/SNMPElement.html?id=1.3.6.1.4.1.5678.2.1.1.1.1.8> 1972M
smtpInputTrafficOut <https://mail.somewhere.com:9010/Monitors/SNMPElement.html?id=1.3.6.1.4.1.5678.2.1.1.1.1.9> 7114M smtpInputMessagesReceived <https://mail.somewhere.com:9010/Monitors/SNMPElement.html?id=1.3.6.1.4.1.5678.2.1.1.1.1.10> 13K
smtpInputMessageBytesReceived <https://mail.somewhere.com:9010/Monitors/SNMPElement.html?id=1.3.6.1.4.1.5678.2.1.1.1.1.11> 300M smtpInputRecipientsAccepted <https://mail.somewhere.com:9010/Monitors/SNMPElement.html?id=1.3.6.1.4.1.5678.2.1.1.1.1.12> 22K
smtpInputRecipientsRejected <https://mail.somewhere.com:9010/Monitors/SNMPElement.html?id=1.3.6.1.4.1.5678.2.1.1.1.1.13> 8897K smtpInputReturnPathsRejected <https://mail.somewhere.com:9010/Monitors/SNMPElement.html?id=1.3.6.1.4.1.5678.2.1.1.1.1.14> 5871K
smtpInputDataCommandsRejected <https://mail.somewhere.com:9010/Monitors/SNMPElement.html?id=1.3.6.1.4.1.5678.2.1.1.1.1.15> 16K smtpInputMessageBodiesRejected <https://mail.somewhere.com:9010/Monitors/SNMPElement.html?id=1.3.6.1.4.1.5678.2.1.1.1.1.16> 1
smtpInputAuthenticationsAccepted <https://mail.somewhere.com:9010/Monitors/SNMPElement.html?id=1.3.6.1.4.1.5678.2.1.1.1.1.17> 948 smtpInputAuthenticationsRejected <https://mail.somewhere.com:9010/Monitors/SNMPElement.html?id=1.3.6.1.4.1.5678.2.1.1.1.1.18> 125
smtpInputMessageSubmitRejected <https://mail.somewhere.com:9010/Monitors/SNMPElement.html?id=1.3.6.1.4.1.5678.2.1.1.1.1.19> 1 smtpInputRBLFailed <https://mail.somewhere.com:9010/Monitors/SNMPElement.html?id=1.3.6.1.4.1.5678.2.1.1.1.1.30> 26M
smtpInputSPFFailed <https://mail.somewhere.com:9010/Monitors/SNMPElement.html?id=1.3.6.1.4.1.5678.2.1.1.1.1.31> 341 smtpInputReverseFailed <https://mail.somewhere.com:9010/Monitors/SNMPElement.html?id=1.3.6.1.4.1.5678.2.1.1.1.1.32> 0



I'm processing about 25-30 SMTP connections per-second. 99% of them are rejected.




Here are the log files. I've sanitized the email addresses.

First connection from 136.248.126.131, we trust them (because I trust IPs where authentication has occurred in the last several hours). Mail is delivered just fine.

14:38:16.099 5 SMTP [136.248.126.131]:587 <- [71.174.98.115]:55128 connection request. socket=426
14:38:16.099 4 SMTPI-659595([71.174.98.115]) got connection on [136.248.126.131]:587(somewhere.com <http://somewhere.com>) from [71.174.98.115]:55128
14:38:16.099 5 SMTPI-659595([71.174.98.115]) out: 220 somewhere.com <http://somewhere.com> ESMTP CommuniGate Pro 5.2.16 is glad to see you!\r\n
14:38:16.149 5 SMTPI-659595([71.174.98.115]) inp: EHLO [172.16.1.141]
*14:38:16.149 5 SMTPI-659595([71.174.98.115]) out: 250-somewhere.com <http://250-somewhere.com> we trust you [172.16.1.141]\r\n250-DSN\r\n250-SIZE 104857600\r\n250-STARTTLS\r\n250-AUTH LOGIN PLAIN CRAM-MD5 DIGEST-MD5 GSSAPI MSN NTLM\r\n250-ETRN\r\n250-TURN\r\n250-ATRN\r\n250-NO-SOLICITING\r\n250-8BITMIME\r\n250-HELP\r\n250-PIP*
*14:38:16.194 5 SMTPI-659595([71.174.98.115]) inp: AUTH CRAM-MD5*
*14:38:16.194 5 SMTPI-659595([71.174.98.115]) SASL-0(CRAM-MD5) out: <659595.1279305496@somewhere.com <mailto:659595.1279305496@somewhere.com>>*
14:38:16.194 5 SMTPI-659595([71.174.98.115]) out: 334 PDY1OTU5NS4xMjc5MzA1NDk2QHNvbWV3aGVyZS5jb20+\r\n
14:38:16.244 5 SMTPI-659595([71.174.98.115]) inp: bmF6Z3VsIDFhYjljNjkzZDgyM2U2YmRmMmEzNzYyM2QzMGI5OTg4
14:38:16.244 5 SMTPI-659595([71.174.98.115]) SASL-0(CRAM-MD5) inp: YYY 1ab9c693d823e6bdf2a37623d30b9988
14:38:16.245 2 SMTPI-659595([71.174.98.115]) 'YYY@somewhere.com <mailto:%27YYY@somewhere.com>' connected from [71.174.98.115]:55128(temp client)
14:38:16.245 2 SMTPI-659595([71.174.98.115]) 'YYY@somewhere.com <mailto:%27YYY@somewhere.com>' disconnected ([71.174.98.115]:55128)
14:38:16.245 5 SMTPI-659595([71.174.98.115]) out: 235 YYY relaying authenticated\r\n
14:38:16.294 5 SMTPI-659595([71.174.98.115]) inp: MAIL FROM:<ZZZ@example.com <mailto:ZZZ@example.com>>
14:38:16.294 5 SMTPI-659595([71.174.98.115]) out: 250 ZZZ@example.com <mailto:ZZZ@example.com> sender accepted\r\n
14:38:16.342 5 SMTPI-659595([71.174.98.115]) inp: RCPT TO:<XXX@gmail.com <mailto:XXX@gmail.com>>
14:38:16.342 5 SMTPI-659595([71.174.98.115]) out: 250 XXX@gmail.com <mailto:XXX@gmail.com> will relay mail for an authenticated user\r\n
14:38:16.409 5 SMTPI-659595([71.174.98.115]) inp: DATA
14:38:16.409 5 SMTPI-659595([71.174.98.115]) out: 354 Enter mail, end with "." on a line by itself\r\n
14:38:16.467 2 SMTPI-659595([71.174.98.115]) [7780603] received(YYY), 1146 bytes
14:38:16.467 5 SMTPI-659595([71.174.98.115]) out: 250 7780603 message accepted for delivery\r\n
14:38:17.850 5 SMTP-000114(gmail.com <http://gmail.com>) out: Received: from [71.174.98.115] (account YYY HELO [172.16.1.141])\r\n  by somewhere.com <http://somewhere.com> (CommuniGate Pro SMTP 5.2.16)\r\n  with ESMTPA id 7780603 for XXX@gmail.com <mailto:XXX@gmail.com>; Fri, 16 Jul 2010 14:38:16 -0400\r\nContent-Type: text/plain; charset=us-ascii\r\nMime
14:39:16.733 5 SMTPI-659595([71.174.98.115]) inp: QUIT
14:39:16.733 5 SMTPI-659595([71.174.98.115]) out: 221 somewhere.com <http://somewhere.com> CommuniGate Pro SMTP closing connection\r\n
14:39:16.733 4 SMTPI-659595([71.174.98.115]) closing connection
14:39:16.733 4 SMTPI-659595([71.174.98.115]) releasing stream

50 seconds later. Another SMTP connection from the same user and same IP. (In between there have been plenty of spam connections, but nothing on port 587. Still trusted, but we get "532 access from your network is restricted, try later" instead. Annoyingly, Apple's mail products (Mac and iPhone) interpret this as "incorrect password", which led me on a wild goose chase for some time, never mind making the process of resubmitting (re-enter password every time) a royal pain.

14:39:56.205 5 SMTP [136.248.126.131]:587 <- [71.174.98.115]:55157 connection request. socket=293
14:39:56.205 4 SMTPI-663062([71.174.98.115]) got connection on [136.248.126.131]:587(somewhere.com <http://somewhere.com>) from [71.174.98.115]:55157
14:39:56.205 5 SMTPI-663062([71.174.98.115]) out: 220 somewhere.com <http://somewhere.com> ESMTP CommuniGate Pro 5.2.16 is glad to see you!\r\n
14:39:56.263 5 SMTPI-663062([71.174.98.115]) inp: EHLO [172.16.1.141]
*14:39:56.263 5 SMTPI-663062([71.174.98.115]) out: 250-somewhere.com <http://250-somewhere.com> we trust you [172.16.1.141]\r\n250-DSN\r\n250-SIZE 104857600\r\n250-STARTTLS\r\n250-AUTH LOGIN PLAIN CRAM-MD5 DIGEST-MD5 GSSAPI MSN NTLM\r\n250-ETRN\r\n250-TURN\r\n250-ATRN\r\n250-NO-SOLICITING\r\n250-8BITMIME\r\n250-HELP\r\n250-PIP*
*14:39:56.310 5 SMTPI-663062([71.174.98.115]) inp: AUTH CRAM-MD5*
*14:39:58.307 5 SMTPI-663062([71.174.98.115]) out: 532 access from your network is restricted, try later\r\n*
14:39:58.350 3 SMTPI-663062([71.174.98.115]) read failed. Error Code=connection closed by peer
14:39:58.350 4 SMTPI-663062([71.174.98.115]) closing connection
14:39:58.350 4 SMTPI-663062([71.174.98.115]) releasing stream

And again, 4 seconds later.

14:40:02.618 5 SMTP [136.248.126.131]:587 <- [71.174.98.115]:55158 connection request. socket=266
14:40:02.618 4 SMTPI-663276([71.174.98.115]) got connection on [136.248.126.131]:587(somewhere.com <http://somewhere.com>) from [71.174.98.115]:55158
14:40:02.618 5 SMTPI-663276([71.174.98.115]) out: 220 somewhere.com <http://somewhere.com> ESMTP CommuniGate Pro 5.2.16 is glad to see you!\r\n
14:40:02.671 5 SMTPI-663276([71.174.98.115]) inp: EHLO [172.16.1.141]
*14:40:02.671 5 SMTPI-663276([71.174.98.115]) out: 250-somewhere.com <http://250-somewhere.com> we trust you [172.16.1.141]\r\n250-DSN\r\n250-SIZE 104857600\r\n250-STARTTLS\r\n250-AUTH LOGIN PLAIN CRAM-MD5 DIGEST-MD5 GSSAPI MSN NTLM\r\n250-ETRN\r\n250-TURN\r\n250-ATRN\r\n250-NO-SOLICITING\r\n250-8BITMIME\r\n250-HELP\r\n250-PIP*
*14:40:02.719 5 SMTPI-663276([71.174.98.115]) inp: AUTH CRAM-MD5*
*14:40:04.719 5 SMTPI-663276([71.174.98.115]) out: 532 access from your network is restricted, try later\r\n*
14:40:04.765 3 SMTPI-663276([71.174.98.115]) read failed. Error Code=connection closed by peer
14:40:04.765 4 SMTPI-663276([71.174.98.115]) closing connection
14:40:04.765 4 SMTPI-663276([71.174.98.115]) releasing stream

Eventually they can get through. But there's no rhyme or reason to it that I can see. They just have to keep trying until it works.
------------------------------------------------------------------------
Kee Hinckley
Owner, Somewhere LLC. Somewhere: http://www.somewhere.com/ TechnoSocial: http://xrl.us/bh35i <http://www.marrowbones.com/commons/technosocial/>



Subscribe (FEED) Subscribe (DIGEST) Subscribe (INDEX) Unsubscribe Mail to Listmaster