On Mar 23, 2006, at 8:27 AM, Ken Murchison wrote:
Patrick Radtke wrote:
Every day we get a number of 'terminated abnormally' messages on
our frontends.
When they happen just occasionally then everything still seems to
run fine.
However sometimes, there will be a large number of them in a short
time span and this is a sure sign that people are having trouble
logging in or are being disconnected.
here is examples from the log
Mar 22 10:50:07 tofu master[19506]: service pop3s pid 18311 in
READY state: terminated abnormally
Mar 22 10:50:10 tofu master[19506]: service imaps pid 18128 in
READY state: terminated abnormally
Mar 22 10:50:20 tofu master[19506]: service imaps pid 18348 in
READY state: terminated abnormally
Mar 22 10:50:23 tofu master[19506]: service imaps pid 13063 in
READY state: terminated abnormally
Mar 22 10:50:32 tofu master[19506]: service pop3s pid 18404 in
READY state: terminated abnormally
Mar 22 10:50:33 tofu master[19506]: service pop3s pid 18218 in
READY state: terminated abnormally
Mar 22 11:01:42 valoney master[2581]: service imaps pid 25617 in
READY state: terminated abnormally
Mar 22 11:01:46 valoney master[2581]: service pop3s pid 25682 in
READY state: terminated abnormally
Mar 22 11:01:47 valoney master[2581]: service imaps pid 25903 in
READY state: terminated abnormally
searching on just a fail process id shows
Mar 22 11:01:38 valoney imaps[25903]: imaps failed: [local]
Mar 22 11:01:47 valoney master[2581]: service imaps pid 25903 in
READY state: terminated abnormally
Mar 22 11:01:51 valoney master[2581]: service imaps pid 25903:
while trying to process message 0x2: not registered yet
Mar 22 11:01:52 valoney master[2581]: service imaps pid 25903 in
UNKNOWN state: processing message 0x2
ar 22 11:01:04 valoney pop3s[25440]: starttls: TLSv1 with cipher
RC4-MD5 (128/128 bits new) no authentication
Mar 22 11:01:20 valoney pop3s[25440]: login:
pool-141-155-147-109.ny5030.east.verizon.net [141.155.147.109]
jg2378 plaintext+TLS User logged in
Mar 22 11:01:21 valoney pop3s[25440]: failed to bind to address
128.59.48.36: Cannot assign requested address
Mar 22 11:01:21 valoney pop3s[25440]: Doing a peer verify
Mar 22 11:01:21 valoney pop3s[25440]: Doing a peer verify
Mar 22 11:01:21 valoney pop3s[25440]: starttls: TLSv1 with cipher
AES256-SHA (256/256 bits new) no authentication
Mar 22 11:01:36 valoney pop3s[25440]: pop3s failed: [local]
Mar 22 11:01:37 valoney pop3s[25440]: Fatal error:
tls_start_servertls() failed
Mar 22 11:01:41 valoney master[2581]: service pop3s pid 25440 in
READY state: terminated abnormally
Mar 22 11:01:52 valoney master[2581]: service pop3s pid 25440:
while trying to process message 0x2: not registered yet
Mar 22 11:01:52 valoney master[2581]: service pop3s pid 25440 in
UNKNOWN state: processing message 0x2
I've never seen behavior like this before. You have a pop3d which
looks like it successfully does TLS+PLAIN, but then attempts TLS
again. What I don't know is if the client has disconnected in
between, or if there is some kind of race condition.
Hmm. That seems to happen on all our connections.
Mar 23 02:00:14 tempeh imaps[5651]: starttls: TLSv1 with cipher RC4-
MD5 (128/128 bits new) no authentication
Mar 23 02:00:14 tempeh imaps[5651]: login:
dyn-128-59-150-148.dyn.columbia.edu [128.59.150.148] yc587 plaintext+TLS
Mar 23 02:00:14 tempeh imaps[5651]: failed to bind to address
128.59.48.36: Cannot assign requested address
Mar 23 02:00:14 tempeh imaps[5651]: Doing a peer verify
Mar 23 02:00:14 tempeh imaps[5651]: Doing a peer verify
Mar 23 02:00:14 tempeh imaps[5651]: starttls: TLSv1 with cipher
AES256-SHA (256/256 bits new) no authentication
We apply a starttls patch to our builds but it looks like the patch
only affects the perl libraries and sieve.
I'll try to find out why it does the double auth on our test machines.
Thanks for the tip!
-Patrick
----
Cyrus Home Page: http://asg.web.cmu.edu/cyrus
Cyrus Wiki/FAQ: http://cyruswiki.andrew.cmu.edu
List Archives/Info: http://asg.web.cmu.edu/cyrus/mailing-list.html
