[RADIATOR] Random AuthBy LDAP2 "Undefined subroutine &main::" connect failures
Kevin Schmidt
kps at ucsb.edu
Fri Aug 24 18:34:48 CDT 2012
Greetings,
I've been using Radiator in support of a variety of services for years,
but I just ran into a really strange bug. If someone has an idea of
what's happening, or a particularly good debugging technique to find the
root cause, I'm all ears.
Briefly stated, at some apparently-random point the radius server
attempts to reconnect to the back-end ldap server, but the connection
fails with "Undefined subroutine &main:: called at
/usr/share/perl5/IO/Socket/SSL.pm line 391."
We use an LDAP server to authenticate most users. Since most of the
handlers need to use the ldap server, each handler does an Include of
the relevant configuration within their respective AuthBy LDAP2 clauses.
The contents of the Include file are:
===================================================
Identifier LDAP_SERVER_REDACTED-bind
Host LDAP_SERVER_REDACTED
UseSSL
SSLCAPath /etc/ssl/certs
FailureBackoffTime 60
HoldServerConnection
BaseDN o=ucsb
AuthDN uid=REDACTED,o=ucsb
AuthPassword REDACTED
UsernameAttr uid
AuthAttrDef ucsbCampusId,ucsbCampusId,request
AuthAttrDef ucsbAffiliation,ucsbAffiliation,request
NoDefault
PasswordAttr userPassword
ServerChecksPassword
===================================================
The problem has been observed both with and without the
HoldServerConnection option, so that does not appear to be a factor.
The server is Ubunu 12.04.1 LTS with perl v5.14.2. Radiator is 4.10
with patches current through last week.
In an attempt to capture more info than "Undefined subroutine &main", I
added the following to radius.cfg:
StartupHook sub { BEGIN { $SIG{__DIE__} = sub { require Carp;
Carp::confess(@_) } } }
I ran radius as follows:
"perl /usr/local/bin/radiusd -pid_file /var/log/radius/radiusd.pid
-config_file /etc/radiator/radius.cfg -trace 4"
The tail end of the resulting logs, with some spacing added for readability:
===================================================
Fri Aug 24 15:38:05 2012: DEBUG: Handling with Radius::AuthGROUP:
Fri Aug 24 15:38:05 2012: DEBUG: Handling with Radius::AuthLDAP2:
LDAP_SERVER_REDACTED-bind
Fri Aug 24 15:38:05 2012: INFO: Connecting to LDAP_SERVER_REDACTED:636
Undefined subroutine &main:: called at /usr/share/perl5/IO/Socket/SSL.pm
line 391.
at (eval 29) line 1
Radius::Configurable::__ANON__('Undefined subroutine &main:: called at
/usr/share/perl5/IO/So...') called at /usr/share/perl5/IO/Socket/SSL.pm
line 391
IO::Socket::SSL::connect_SSL('IO::Socket::SSL=GLOB(0x4611788)') called
at /usr/share/perl5/IO/Socket/SSL.pm line 338
IO::Socket::SSL::connect('IO::Socket::SSL=GLOB(0x4611788)',
'\x{2}\x{0}\x{2}|\x{80}o\x{a0}\x{e2}\x{0}\x{0}\x{0}\x{0}\x{0}\x{0}\x{0}\x{0}')
called at /usr/share/perl5/IO/Socket/INET6.pm line 279
IO::Socket::INET6::configure('IO::Socket::SSL=GLOB(0x4611788)',
'HASH(0x470b670)') called at /usr/share/perl5/IO/Socket/SSL.pm line 212
IO::Socket::SSL::configure('IO::Socket::SSL=GLOB(0x4611788)',
'HASH(0x470b670)') called at /usr/lib/perl/5.14/IO/Socket.pm line 48
IO::Socket::new('IO::Socket::SSL', 'PeerAddr', 'LDAP_SERVER_REDACTED',
'PeerPort', 636, 'LocalAddr', undef, 'Proto', 'tcp', ...) called at
/usr/share/perl5/IO/Socket/INET6.pm line 60
IO::Socket::INET6::new('IO::Socket::SSL', 'PeerAddr',
'LDAP_SERVER_REDACTED', 'PeerPort', 636, 'LocalAddr', undef, 'Proto',
'tcp', ...) called at /usr/share/perl5/Net/LDAP.pm line 178
Net::LDAP::connect_ldaps('Net::LDAPS=HASH(0x46278c8)',
'LDAP_SERVER_REDACTED:636', 'HASH(0x45b5188)') called at
/usr/share/perl5/Net/LDAP.pm line 111
Net::LDAP::new('Net::LDAPS', 'ARRAY(0x45d5c48)', 'inet6', 0, 'port',
636, 'timeout', 10, 'verify', ...) called at
/usr/share/perl5/Net/LDAPS.pm line 14
Net::LDAPS::new('Net::LDAPS', 'ARRAY(0x45d5c48)', 'inet6', 0, 'port',
636, 'timeout', 10, 'verify', ...) called at
/usr/local/share/perl/5.14.2/Radius/Ldap.pm line 280
Radius::Ldap::reconnect('Radius::AuthLDAP2=HASH(0x3673df8)') called at
/usr/local/share/perl/5.14.2/Radius/AuthLDAP2.pm line 263
Radius::AuthLDAP2::findUser('Radius::AuthLDAP2=HASH(0x3673df8)',
'USERNAME_REDACTED', 'Radius::Radius=HASH(0x44c60e8)',
'Radius::Radius=HASH(0x4638270)', 'USERNAME_REDACTED', undef) called at
/usr/local/share/perl/5.14.2/Radius/AuthGeneric.pm line 654
Radius::AuthGeneric::get_user('Radius::AuthLDAP2=HASH(0x3673df8)',
'USERNAME_REDACTED', 'Radius::Radius=HASH(0x44c60e8)', undef, 1) called
at /usr/local/share/perl/5.14.2/Radius/AuthGeneric.pm line 581
Radius::AuthGeneric::handle_request('Radius::AuthLDAP2=HASH(0x3673df8)', 'Radius::Radius=HASH(0x44c60e8)', 'Radius::Radius=HASH(0x4638270)', undef) called at /usr/local/share/perl/5.14.2/Radius/AuthGROUP.pm line 146
Radius::AuthGROUP::handle_request('Radius::AuthGROUP=HASH(0x3673bb8)',
'Radius::Radius=HASH(0x44c60e8)', 'Radius::Radius=HASH(0x4638270)')
called at /usr/local/share/perl/5.14.2/Radius/Handler.pm line 542
Radius::Handler::handle_request('Radius::Handler=HASH(0x35f0600)',
'Radius::Radius=HASH(0x44c60e8)') called at
/usr/local/share/perl/5.14.2/Radius/Client.pm line 524
Radius::Client::handle_request('Radius::Client=HASH(0x2e894b8)',
'Radius::Radius=HASH(0x44c60e8)') called at
/usr/local/share/perl/5.14.2/Radius/ServerConfig.pm line 635
Radius::ServerConfig::dispatch_request('Radius::ServerConfig=HASH(0x2cb6c18)', 'Radius::Radius=HASH(0x44c60e8)') called at /usr/local/bin/radiusd line 429
main::handle_radius_socket_read(11,
'*Radius::ServerRADIUS::RADIUS_SOCKET',
'Radius::ServerRADIUS=HASH(0x3d9fef0)') called at
/usr/local/share/perl/5.14.2/Radius/Select.pm line 158
Radius::Select::select(1) called at /usr/local/bin/radiusd line 405
main::handleEvents() called at /usr/local/bin/radiusd line 150
main::main called at /usr/local/bin/radiusd line 137
===================================================
At the risk of repeating myself, the above failure occurs after a number
of successful lookups, which typically look like:
===================================================
Fri Aug 24 11:09:20 2012: DEBUG: Handling with Radius::AuthLDAP2:
LDAP_SERVER_REDACTED-bind
Fri Aug 24 11:09:20 2012: INFO: Connecting to LDAP_SERVER_REDACTED:636
Fri Aug 24 11:09:20 2012: INFO: Attempting to bind to LDAP server
LDAP_SERVER_REDACTED:636
Fri Aug 24 11:09:20 2012: DEBUG: LDAP got result for
ucsbcampusid=REDACTED,o=ucsb
===================================================
Anyone seen anything like this, or have a good path for isolating this?
This might be a job for DataDumper and some forced backtraces, but I'm
really hoping I don't have to...
--
Kevin Schmidt
Office of Information Technology
University of California, Santa Barbara
North Hall 2124
Santa Barbara, CA 93106-3201
805-893-7779
kps at ucsb.edu
More information about the radiator
mailing list