terminated abnormally

[Ken Murchison]

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.

-- 
Kenneth Murchison
Project Cyrus Developer/Maintainer
Carnegie Mellon University