Patrick Radtke wrote:
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.
Ken, is the second TLS just proxyd connecting to a backend?
Yes, you're right.
Increasing the log level to debug shows a lot of
Mar 30 13:20:09 mockmeat master[23360]: service imaps pid 26574 in BUSY
state: terminated abnormally
is that normal? (These ones are being terminated while BUSY instead of
when READY). These logs are from 2.2.12
The BUSY ones look like
Mar 30 13:20:05 mockmeat imaps[26574]: accepted connection
Mar 30 13:20:05 mockmeat imaps[26574]: imaps failed: [local]
Mar 30 13:20:08 mockmeat master[23360]: process 26574 exited, status 75
Mar 30 13:20:09 mockmeat master[23360]: service imaps pid 26574 in BUSY
state: terminated abnormally
here is a different (different from my initial email) looking READY error
Mar 30 13:19:01 mockmeat master[1494]: about to exec /usr/bin/proxyd
Mar 30 13:19:02 mockmeat imaps[1494]: executed
Mar 30 13:19:55 mockmeat imaps[1494]: accepted connection
Mar 30 13:19:56 mockmeat imaps[1494]: imaps failed: [local]
Mar 30 13:19:59 mockmeat master[23360]: process 1494 exited, status 75
Mar 30 13:20:01 mockmeat master[23360]: service imaps pid 1494 in READY
state: terminated abnormally
In these one is looks like something is failing in 'tls_start_servertls'.
Does [local] just mean the client's host couldn't be determined?
Its means that it might not be set yet. I took me a while to figure out
where the 'imaps failed' message came from, until I realized that you're
still using 2.2 proxyd.
The only guess that I have at the moment is that your server if running
out of entropy.
--
Kenneth Murchison
Systems Programmer
Project Cyrus Developer/Maintainer
Carnegie Mellon University
----
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
