| Main Domain Name: | 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): |
| |||||
| Owner, Somewhere LLC. | Somewhere:Â http://www.somewhere.com/ | TechnoSocial:Â http://xrl.us/bh35i |
I do like the mention of 3 connections per IP address as the culprit
though. That seems pretty relevant to the issue at hand.
> 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.1...@somewhere.com
> <mailto:659595.1...@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]) 'Y...@somewhere.com
> <mailto:%27...@somewhere.com>' connected from
> [71.174.98.115]:55128(temp client)
> 14:38:16.245 2 SMTPI-659595([71.174.98.115]) 'Y...@somewhere.com
> <mailto:%27...@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:<Z...@example.com <mailto:Z...@example.com>>
> 14:38:16.294 5 SMTPI-659595([71.174.98.115]) out: 250 Z...@example.com
> <mailto:Z...@example.com> sender accepted\r\n
> 14:38:16.342 5 SMTPI-659595([71.174.98.115]) inp: RCPT
> TO:<X...@gmail.com <mailto:X...@gmail.com>>
> 14:38:16.342 5 SMTPI-659595([71.174.98.115]) out: 250 X...@gmail.com
> <mailto:X...@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 X...@gmail.com
> <mailto:X...@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/>
>
>
#############################################################
This message is sent to you because you are subscribed to
the mailing list <CGat...@mail.stalker.com>.
To unsubscribe, E-mail to: <CGateP...@mail.stalker.com>
To switch to the DIGEST mode, E-mail to <CGatePr...@mail.stalker.com>
To switch to the INDEX mode, E-mail to <CGatePr...@mail.stalker.com>
Send administrative queries to <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.
That's a good point. I really didn't want to get back into the business of running a DNS server, and I shouldn't think a caching server would give me any benefit over CGP's own caching, but I'll see if I can find some other options.
> I do like the mention of 3 connections per IP address as the culprit though. That seems pretty relevant to the issue at hand.
I only have a 25 user license, and of those accounts, less than a dozen actually send mail, and they are scattered around the country, but it's easy enough for me to up that limit and see what happens. I'll give it a shot.
Thanks.
Kee Hinckley
Owner, Somewhere LLC. Somewhere: http://www.somewhere.com/ TechnoSocial: http://xrl.us/bh35i
FYI We had all sorts of problems a while back and adding our own caching
server made all the difference. The machine in question only has 70 active
accounts so pretty small scale in the same way yours is.
David