Hello,
I was trying to make svnserve authenticate users using LDAP, via cyrus
SASL library. I was able to configure everything correctly (sasl, proxy
authentication and regexp in OpenLDAP), the problem is that svnserve
hangs after the query the LDAP server; this happens whether the look up
was successful or not, when svnserve has done all the work (more
precisely when the SASL library is cleaning up).
I'm not sure that the bug is actually in subversion, it might be in the way
SASL uses LDAP (but I'm successfully using SASL+LDAP for IMAP authentication).
I'll try to describe the problem and the debugging that I've done.
Please note that I used version 1.5.1 (Debian/stable), so the debug data
refers to that version. However I also confirmed the problem with 1.6.1
(and captured a stack trace, see at the end of this mail).
Let's start with a backtrace of the hung process:
#0 0x00007f2ad89db384 in __lll_lock_wait () from /lib/libpthread.so.0
#1 0x00007f2ad89d6bf0 in _L_lock_102 () from /lib/libpthread.so.0
#2 0x00007f2ad89d64fe in pthread_mutex_lock () from /lib/libpthread.so.0
#3 0x00007f2adab55e4e in ldap_pvt_sasl_mutex_lock () from /usr/lib/libldap_r-2.4.so.2
#4 0x00007f2ad87bb6e6 in sasl_dispose (pconn=0x7fffe42a0b10) at common.c:793
#5 0x00007f2adab5665c in ldap_int_sasl_close () from /usr/lib/libldap_r-2.4.so.2
#6 0x00007f2adab62dc2 in ldap_free_connection () from /usr/lib/libldap_r-2.4.so.2
#7 0x00007f2adab598cf in ldap_ld_free () from /usr/lib/libldap_r-2.4.so.2
#8 0x00007f2ad54b3ece in ldapdb_auxprop_lookup (glob_context=0x1b42d10, sparams=0x1b3fda0, flags=0,
user=0x1b60a51 "kronos_at_gfinder", ulen=14) at ldapdb.c:206
#9 0x00007f2ad87b57a1 in _sasl_auxprop_lookup (sparams=0x1b3fda0, flags=0, user=0x1b60a51 "kronos_at_gfinder", ulen=14)
at auxprop.c:898
#10 0x00007f2ad87b6229 in _sasl_canon_user (conn=0x1b5fcb0, user=0x1b60a51 "kronos_at_gfinder", ulen=14, flags=1,
oparams=0x1b60520) at canonusr.c:190
#11 0x00007f2adbe7f56b in digestmd5_server_mech_step2 (stext=0x1b400a0, sparams=0x1b3fda0,
clientin=0x1b55568 "username=\"kronos\",realm=\"gfinder\",nonce=\"...=\",cnonce=\"...=\",nc=00000001,qop=auth-conf,cipher=rc4,maxbuf=4096,digest-uri"...,
clientinlen=271, serverout=0x7fffe42a1108, serveroutlen=0x7fffe42a10f4, oparams=0x1b60520) at digestmd5.c:2301
#12 0x00007f2adbe806cc in digestmd5_server_mech_step (conn_context=0x1b400a0, sparams=0x1b3fda0,
clientin=0x1b55568 "username=\"kronos\",realm=\"gfinder\",nonce=\"...\",cnonce=\"...\",nc=00000001,qop=auth-conf,cipher=rc4,maxbuf=4096,digest-uri"...,
clientinlen=271, serverout=0x7fffe42a1108, serveroutlen=0x7fffe42a10f4, oparams=0x1b60520) at digestmd5.c:2689
#13 0x00007f2ad87c44d1 in sasl_server_step (conn=0x1b5fcb0,
clientin=0x1b55568 "username=\"kronos\",realm=\"gfinder\",nonce=\"...\",cnonce=\"...\",nc=00000001,qop=auth-conf,cipher=rc4,maxbuf=4096,digest-uri"...,
clientinlen=271, serverout=0x7fffe42a1108, serveroutlen=0x7fffe42a10f4) at server.c:1430
#14 0x00000000004055a4 in try_auth (conn=0x1b47428, sasl_ctx=0x1b5fcb0, pool=0x1b54c98, b=0x7fffe42a1430,
success=0x7fffe42a11bc) at subversion/svnserve/cyrus_auth.c:207
#15 0x0000000000405baa in cyrus_auth_request (conn=0x1b47428, pool=0x1b45418, b=0x7fffe42a1430, required=READ_ACCESS,
needs_username=0) at subversion/svnserve/cyrus_auth.c:337
#16 0x0000000000407dbc in auth_request (conn=0x1b47428, pool=0x1b45418, b=0x7fffe42a1430, required=READ_ACCESS,
needs_username=0) at subversion/svnserve/serve.c:405
#17 0x000000000040ef16 in serve (conn=0x1b47428, params=0x7fffe42a15e0, pool=0x1b45418)
at subversion/svnserve/serve.c:2676
#18 0x0000000000406fb3 in main (argc=4, argv=0x7fffe42a17d8) at subversion/svnserve/main.c:716
This happens *after* svnserve has checked the credentials of the user with the
LDAP server (via SASL). Frame 4 is interesting:
(gdb) f 4
#4 0x00007f2ad87bb6e6 in sasl_dispose (pconn=0x7fffe42a0b10) at common.c:793
793 result = sasl_MUTEX_LOCK(free_mutex);
Deadlock? Not quite ;)
The mutex is initialized at startup, via cyrus_init, in _sasl_common_init:
#0 _sasl_common_init (global_callbacks=0x7f4f3cfc7da0) at common.c:765
#1 0x00007f4f3cdbcbfd in sasl_server_init (callbacks=0x611ec0, appname=0x40f281 "svn") at server.c:712
#2 0x0000000000405136 in initialize (pool=0x16d51c8) at subversion/svnserve/cyrus_auth.c:108
#3 0x00007f4f3f7cd832 in svn_atomic__init_once (global_status=0x611f00, init_func=0x4050d2 <initialize>,
pool=0x16d51c8) at subversion/libsvn_subr/atomic.c:40
#4 0x00000000004051d3 in cyrus_init (pool=0x16d51c8) at subversion/svnserve/cyrus_auth.c:121
#5 0x00000000004061c3 in main (argc=4, argv=0x7fff4868cde8) at subversion/svnserve/main.c:347
Mutex handling is hidden behind function pointers (_sasl_mutex_utils), at
startup we can see that:
(gdb) p _sasl_mutex_utils
$4 = {alloc = 0x7f78a933a40d <sasl_mutex_alloc_cb>, lock = 0x7f78a933a4c6 <sasl_mutex_lock_cb>,
unlock = 0x7f78a933a510 <sasl_mutex_unlock_cb>, free = 0x7f78a933a55a <sasl_mutex_free_cb>}
the mutex is allocated using sasl_mutex_alloc_cb (which in turn uses APR). When
svnserve locks up, the pointers have changed:
(gdb) p _sasl_mutex_utils
$5 = {alloc = 0x7f2adab55e60 <ldap_pvt_sasl_mutex_new>, lock = 0x7f2adab55e40 <ldap_pvt_sasl_mutex_lock>,
unlock = 0x7f2adab55e20 <ldap_pvt_sasl_mutex_unlock>, free = 0x7f2adab55df0 <ldap_pvt_sasl_mutex_dispose>}
So what happens is that a mutex allocated by the SASL library (using APR) is
being used by the LDAP library callback (which thinks it's a POSIX mutex):
oops :)
How does this happen?
Hardware access (read/write) watchpoint 6: _sasl_mutex_utils.lock
Old value = (sasl_mutex_lock_t *) 0x7f78a933a4c6 <sasl_mutex_lock_cb>
New value = (sasl_mutex_lock_t *) 0x7f78a8ed8e40 <ldap_pvt_sasl_mutex_lock>
sasl_set_mutex (n=0x7f78a8ed8e60 <ldap_pvt_sasl_mutex_new>, l=0x7f78a8ed8e40 <ldap_pvt_sasl_mutex_lock>,
u=0x7f78a8ed8e20 <ldap_pvt_sasl_mutex_unlock>, d=0x7f78a8ed8df0 <ldap_pvt_sasl_mutex_dispose>) at common.c:157
157 _sasl_mutex_utils.unlock=u;
(gdb) bt
#0 sasl_set_mutex (n=0x7fd12e04ee60 <ldap_pvt_sasl_mutex_new>, l=0x7fd12e04ee40 <ldap_pvt_sasl_mutex_lock>,
u=0x7fd12e04ee20 <ldap_pvt_sasl_mutex_unlock>, d=0x7fd12e04edf0 <ldap_pvt_sasl_mutex_dispose>) at common.c:157
#1 0x00007fd12e04f81f in ldap_int_sasl_init () at cyrus.c:117
#2 0x00007fd12e04f8b1 in ldap_int_sasl_open (ld=0x150e040, lc=0x150edd0, host=0x7fd12bec69a0 "`�\004.�\177")
at cyrus.c:529
#3 0x00007fd12e04fb1c in ldap_int_sasl_bind (ld=0x150e040, dn=0x0, mechs=0x14ec1b0 "EXTERNAL", sctrls=0x0, cctrls=0x0,
flags=2, interact=0x7fd1289accc0 <ldapdb_interact>, defaults=0x14efd10) at cyrus.c:644
#4 0x00007fd12e051c29 in ldap_sasl_interactive_bind_s (ld=0x150e040, dn=0x0, mechs=0x14ec1b0 "EXTERNAL",
serverControls=0x0, clientControls=0x0, flags=2, interact=0x7fd1289accc0 <ldapdb_interact>, defaults=0x14efd10)
at sasl.c:464
#5 0x00007fd1289ac9f9 in ldapdb_connect (ctx=0x14efd10, sparams=0x14ecda0, user=0x150da51 "tettamanti_at_gfinder",
ulen=18, cp=0x7fff3758d070) at ldapdb.c:106
#6 0x00007fd1289acea8 in ldapdb_auxprop_lookup (glob_context=0x14efd10, sparams=0x14ecda0, flags=0,
user=0x150da51 "tettamanti_at_gfinder", ulen=18) at ldapdb.c:178
#7 0x00007fd12bcae7a1 in _sasl_auxprop_lookup (sparams=0x14ecda0, flags=0, user=0x150da51 "tettamanti_at_gfinder",
ulen=18) at auxprop.c:898
#8 0x00007fd12bcaf229 in _sasl_canon_user (conn=0x150ccb0, user=0x150da51 "tettamanti_at_gfinder", ulen=18, flags=1,
oparams=0x150d520) at canonusr.c:190
#9 0x00007fd128dba2c1 in digestmd5_server_mech_step2 (stext=0x14ed0a0, sparams=0x14ecda0,
clientin=<value optimized out>, clientinlen=<value optimized out>, serverout=0x7fff3758d618,
serveroutlen=0x7fff3758d604, oparams=0x150d520) at digestmd5.c:2301
#10 0x00007fd12bcbd4d1 in sasl_server_step (conn=0x150ccb0,
clientin=0x1502568 "username=\"tettamanti\",realm=\"gfinder\",nonce=\"...\",cnonce=\"...\",nc=00000001,qop=auth-conf,cipher=rc4,maxbuf=4096,digest"...,
clientinlen=275, serverout=0x7fff3758d618, serveroutlen=0x7fff3758d604) at server.c:1430
#11 0x00000000004055a4 in try_auth (conn=0x14f4428, sasl_ctx=0x150ccb0, pool=0x1501c98, b=0x7fff3758d940,
success=0x7fff3758d6cc) at subversion/svnserve/cyrus_auth.c:207
#12 0x0000000000405baa in cyrus_auth_request (conn=0x14f4428, pool=0x14f2418, b=0x7fff3758d940, required=READ_ACCESS,
needs_username=0) at subversion/svnserve/cyrus_auth.c:337
#13 0x0000000000407dbc in auth_request (conn=0x14f4428, pool=0x14f2418, b=0x7fff3758d940, required=READ_ACCESS,
needs_username=0) at subversion/svnserve/serve.c:405
#14 0x000000000040ef16 in serve (conn=0x14f4428, params=0x7fff3758daf0, pool=0x14f2418)
at subversion/svnserve/serve.c:2676
#15 0x0000000000406fb3 in main (argc=4, argv=0x7fff3758dce8) at subversion/svnserve/main.c:716
Ok, so when ldap_int_sasl_init() is called during the second step of
MD5-DIGEST, it overwrites the mutex callbacks. Doh.
Any clue on who is at fault here?
As I said above, the issue is reproducible with the latest (1.6.1) version of
subversion:
(gdb) bt
#0 __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:130
#1 0x00007f21c3d23ab0 in _L_lock_102 () from /lib/libpthread.so.0
#2 0x00007f21c3d2339e in __pthread_mutex_lock (mutex=0x24542c0) at pthread_mutex_lock.c:86
#3 0x00007f21bfc8bdae in ldap_pvt_sasl_mutex_lock () from /usr/lib/libldap_r-2.4.so.2
#4 0x00007f21c3b0abd4 in sasl_dispose () from /usr/lib/libsasl2.so.2
#5 0x00007f21bfc8c5bc in ldap_int_sasl_close () from /usr/lib/libldap_r-2.4.so.2
#6 0x00007f21bfc98d22 in ldap_free_connection () from /usr/lib/libldap_r-2.4.so.2
#7 0x00007f21bfc8f82f in ldap_ld_free () from /usr/lib/libldap_r-2.4.so.2
#8 0x00007f21bfebeece in ?? () from /usr/lib/sasl2/libldapdb.so.2
#9 0x00007f21c3b06549 in _sasl_auxprop_lookup () from /usr/lib/libsasl2.so.2
#10 0x00007f21c3b07d3b in _sasl_canon_user () from /usr/lib/libsasl2.so.2
#11 0x00007f21c0e282c1 in ?? () from /usr/lib/sasl2/libdigestmd5.so.2
#12 0x00007f21c3b10e0f in sasl_server_step () from /usr/lib/libsasl2.so.2
#13 0x00000000004062b9 in try_auth (conn=0x24634d8, sasl_ctx=0x2494c50, pool=0x247bd88, b=0x7fffce517440,
success=0x7fffce5171bc) at subversion/svnserve/cyrus_auth.c:211
#14 0x00000000004068c4 in cyrus_auth_request (conn=0x24634d8, pool=0x24614c8, b=0x7fffce517440, required=READ_ACCESS,
needs_username=0) at subversion/svnserve/cyrus_auth.c:341
#15 0x0000000000409613 in auth_request (conn=0x24634d8, pool=0x24614c8, b=0x7fffce517440, required=READ_ACCESS,
needs_username=0) at subversion/svnserve/serve.c:563
#16 0x000000000041179f in serve (conn=0x24634d8, params=0x7fffce517640, pool=0x24614c8)
at subversion/svnserve/serve.c:3010
#17 0x00000000004080eb in main (argc=4, argv=0x7fffce517858) at subversion/svnserve/main.c:779
thanks,
Luca
PS: I'm not subscribed, keep me in CC.
--
Il coraggio non mi manca.
E` la paura che mi frega...
Received on 2009-05-06 00:55:48 CEST