SSL_read failed in a system call

[King, Michael]

I posted this to the list back in September, but was unable to chase it
then. 
http://www.mail-archive.com/freeradius-users@lists.freeradius.org/msg294
52.html

But it has returned with a vengeance.  It only seems to affect the 1.1.3
server. I have not tried any other versions, other than the 1.0.4 I've
listed below, which seems to work fine

I think it's load related, since when I test with a few clients, it
worked fine.  When I dumped 1000 of clients, with over 50 auths/sec,
things went horrible wrong.

I found this on the net with the same error string:
http://www.mail-archive.com/modssl-users@modssl.org/msg16180.html

> There is definately something wrong in openssl 0.9.7a, or, mod_ssl
2.8.14 is trying 
> to call 0.9.6 functions which are different/don't exist in 0.9.7

And I found this:
http://lists.alioth.debian.org/pipermail/pkg-openssl-devel/2005-November
/000418.html
Which has a link to:
http://www.aet.tu-cottbus.de/rt2/Ticket/Display.html?id=1204  (OpenSSL's
BugTracker?)

>Use of SSL_OP_TLS_BLOCK_PADDING_BUG, which is included in SSL_OP_ALL,
>triggers a bug in OpenSSL if both the client and server is using
version 0.9.8.

Unfortunately, I'm using 0.9.7

Here's my status
I've built a new radius server.

FreeRADIUS 1.1.3
Windbind using ntlm_auth to talk to ActiveDirectory.

Mostly XP clients using the Built-in XP supplicant. (PEAP)
Running on RedHat RHEL 4
Server has a trusted root Cert from Equifax.  (I do NOT have a
self-signed Cert)
Server name is brand new, it has never been used in my network before
OpenSSL is openssl-0.9.7a-43.11 via Up2date

I got it all setup and operating correctly (based on my 1.0.4 config
that's been in production for 1.5 years).  Tested it with a few clients,
everything looks fine.

I put some major traffic on it, and everything goes downhill.  :-(

The logs read this (per user)

Wed Oct 11 17:57:58 2006 : Error:     TLS_accept:error in SSLv3 read
client certificate A
Wed Oct 11 17:57:58 2006 : Error: rlm_eap: SSL error
error:00000000:lib(0):func(0):reason(0)
Wed Oct 11 17:57:58 2006 : Error: TLS Alert write:fatal:bad record mac
Wed Oct 11 17:57:58 2006 : Error:     TLS_accept:error in SSLv3 read
certificate verify A
Wed Oct 11 17:57:58 2006 : Error: rlm_eap: SSL error error:1408F455:SSL
routines:SSL3_GET_RECORD:decryption failed or bad record mac
Wed Oct 11 17:57:58 2006 : Error: rlm_eap_tls: SSL_read failed in a
system call (-1), TLS session fails.
Wed Oct 11 17:57:58 2006 : Auth: Login incorrect: [BSC\\mking] (from
client BUWiSM-1-2 port 29 cli 00-90-96-F4-2A-BB)

For every single user.

At the very beginning, a few users authenticate fine, nobody gets on
after that. (All this in the first second of starting the server)

So I move everyone back to my working server (version 1.0.4, OpenSSL is
0.9.7e-3 via debian)

Now, it's still in this state.  If I stop and start the server, it'll be
normal again.

Is there anykind of debugging info I can get you right now without
killing the running process?

I moved traffic to the server at:
 17:54:03
I moved traffic off at:
 17:54:36

As you can see above, I tried it with a test station at 17:57:58, and it
was still busted.  (Test station worked fine at 17:50)


Also, I checked out the /var/log/messages file, it had this weirdness in
it.  I tried restarting winbindd a few seconds before these time stamps,
so that's may be what threw all the error messages.

Oct 11 17:02:42 radius1 kernel: audit(1160600562.652:20): avc:  denied
{ search } for  pid=2831 comm="winbindd" name="lib" dev=dm-0 ino=589826
scontext=user
_u:system_r:winbind_t tcontext=system_u:object_r:var_lib_t tclass=dir
Oct 11 17:02:42 radius1 kernel: audit(1160600562.652:21): avc:  denied
{ getattr } for  pid=2831 comm="winbindd" name="samba" dev=dm-0
ino=589961 scontext=u
ser_u:system_r:winbind_t tcontext=system_u:object_r:var_lib_t tclass=dir
Oct 11 17:57:44 radius1 winbind: winbindd shutdown succeeded
Oct 11 17:57:46 radius1 kernel: audit(1160603866.541:22): avc:  denied
{ setattr } for  pid=4000 comm="winbindd" name="winbindd" dev=dm-0
ino=590836 scontex
t=root:system_r:winbind_t tcontext=root:object_r:samba_log_t tclass=dir
Oct 11 17:57:46 radius1 kernel: audit(1160603866.566:23): avc:  denied
{ write } for  pid=4000 comm="winbindd" name="secrets.tdb" dev=dm-0
ino=937186 sconte
xt=root:system_r:winbind_t tcontext=root:object_r:samba_etc_t
tclass=file
Oct 11 17:57:46 radius1 kernel: audit(1160603866.566:24): avc:  denied
{ search } for  pid=4000 comm="winbindd" name="lib" dev=dm-0 ino=589826
scontext=root
:system_r:winbind_t tcontext=system_u:object_r:var_lib_t tclass=dir
Oct 11 17:57:46 radius1 kernel: audit(1160603866.566:25): avc:  denied
{ read write } for  pid=4000 comm="winbindd" name="gencache.tdb"
dev=dm-0 ino=590838
scontext=root:system_r:winbind_t tcontext=root:object_r:var_lib_t
tclass=file
Oct 11 17:57:46 radius1 kernel: audit(1160603866.566:26): avc:  denied
{ lock } for  pid=4000 comm="winbindd" name="gencache.tdb" dev=dm-0
ino=590838 sconte
xt=root:system_r:winbind_t tcontext=root:object_r:var_lib_t tclass=file
Oct 11 17:57:46 radius1 kernel: audit(1160603866.566:27): avc:  denied
{ getattr } for  pid=4000 comm="winbindd" name="gencache.tdb" dev=dm-0
ino=590838 sco
ntext=root:system_r:winbind_t tcontext=root:object_r:var_lib_t
tclass=file
Oct 11 17:57:46 radius1 kernel: audit(1160603866.566:28): avc:  denied
{ getattr } for  pid=4000 comm="winbindd" name="samba" dev=dm-0
ino=589961 scontext=r
oot:system_r:winbind_t tcontext=system_u:object_r:var_lib_t tclass=dir
Oct 11 17:57:46 radius1 kernel: audit(1160603866.568:29): avc:  denied
{ getattr } for  pid=4001 comm="winbindd" name="winbindd_privileged"
dev=dm-0 ino=590
759 scontext=root:system_r:winbind_t tcontext=user_u:object_r:var_lib_t
tclass=dir
Oct 11 17:57:46 radius1 kernel: audit(1160603866.568:30): avc:  denied
{ search } for  pid=4001 comm="winbindd" name="winbindd_privileged"
dev=dm-0 ino=5907
59 scontext=root:system_r:winbind_t tcontext=user_u:object_r:var_lib_t
tclass=dir
Oct 11 17:57:46 radius1 kernel: audit(1160603866.568:31): avc:  denied
{ write } for  pid=4001 comm="winbindd" name="winbindd_privileged"
dev=dm-0 ino=59075
9 scontext=root:system_r:winbind_t tcontext=user_u:object_r:var_lib_t
tclass=dir
Oct 11 17:57:46 radius1 kernel: audit(1160603866.568:32): avc:  denied
{ remove_name } for  pid=4001 comm="winbindd" name="pipe" dev=dm-0
ino=590760 scontex
t=root:system_r:winbind_t tcontext=user_u:object_r:var_lib_t tclass=dir
Oct 11 17:57:46 radius1 kernel: audit(1160603866.568:33): avc:  denied
{ unlink } for  pid=4001 comm="winbindd" name="pipe" dev=dm-0 ino=590760
scontext=roo
t:system_r:winbind_t tcontext=user_u:object_r:var_lib_t tclass=sock_file
Oct 11 17:57:46 radius1 kernel: audit(1160603866.568:34): avc:  denied
{ add_name } for  pid=4001 comm="winbindd" name="pipe"
scontext=root:system_r:winbind
_t tcontext=user_u:object_r:var_lib_t tclass=dir
Oct 11 17:57:46 radius1 kernel: audit(1160603866.568:35): avc:  denied
{ create } for  pid=4001 comm="winbindd" name="pipe"
scontext=root:system_r:winbind_t
 tcontext=root:object_r:var_lib_t tclass=sock_file
Oct 11 17:57:46 radius1 winbind: winbindd startup succeeded
Oct 11 17:57:46 radius1 kernel: audit(1160603866.572:36): avc:  denied
{ write } for  pid=4002 comm="winbindd" name="krb5.conf" dev=dm-0
ino=934018 scontext
=root:system_r:winbind_t tcontext=root:object_r:etc_t tclass=file
Oct 11 17:57:46 radius1 kernel: audit(1160603866.600:37): avc:  denied
{ read write } for  pid=4002 comm="winbindd" name="winbindd_cache.tdb"
dev=dm-0 ino=5
90761 scontext=root:system_r:winbind_t
tcontext=user_u:object_r:var_lib_t tclass=file
Oct 11 17:57:46 radius1 kernel: audit(1160603866.600:38): avc:  denied
{ lock } for  pid=4002 comm="winbindd" name="winbindd_cache.tdb"
dev=dm-0 ino=590761
scontext=root:system_r:winbind_t tcontext=user_u:object_r:var_lib_t
tclass=file
Oct 11 17:57:46 radius1 kernel: audit(1160603866.600:39): avc:  denied
{ getattr } for  pid=4002 comm="winbindd" name="winbindd_cache.tdb"
dev=dm-0 ino=5907
61 scontext=root:system_r:winbind_t tcontext=user_u:object_r:var_lib_t
tclass=file