|
Pierangelo According to your advice we
upgraded OpenLDAP on our linux installations by moving to the latest stable
version, that is to say 2.4.11. So far everything is
working as expected with several “long term” signon transations (such as new
pin and next token) going parallel with up to 30 straight ssh signon processes (user
+ passcode). Neither processes failed
nor fault-segmented the OpenLDAP. We’d like to keep this
issue “open” a little bit longer just to confirm the same outcome on solaris9,
supposing the customer is available to face the production upgrade. As soon as we have news
on it I’ll update/close the subject. Pierangelo, So far many many thanks
for your valuable help. Francesco Grossi Da: Pierangelo
Masarati [mailto:ando@sys-net.it] Could you send: > Dear team We hope you can help us
in discovering where or how we are wrong. We are providing a new
sasl mechanism for third party strong authentication and we are in the final
delivery step. We are current with
openldap 2.3.38. We used strong
authentication server to carry out the authorization part of the mech and our
backside (sasl client) is
Openldap 2.3.38. On the client side we
have pam-ldap+ssh. sasl libs are cyrus 2.1.22 os is linux red-hat
cent-os 4.7 final During our functional
and stress tests everything works fine but once in a while when openldap
crashes and this happens only,
but not always, under a certain condition: Before explaining such a
condition we would like to establish the meaning of some terms: 1) straight
authentication session: a simple (not interactive) authentication, being either
successfull or not (right or wrong
passcode) 2) interactive
authentication session: a complex (interactive) authentication with iterated
tcp/ip requests such as next-token or new-pin Crash scenario: one ore more straight
authentication scripts are running in parallel, emulating parallel ssh
authentication sessions with either right or
wrong passcode; one interactive
authentication session: in the error-originating
session the whole user back-and-forth got his way to the authentication server,
that is to say next-token or new-pin procedure comes to a complete end: user gives its next
token or new pin (twice) and the strong authentication is fully accomplished
and reported by the authentication manager. What is wrong is that
(by average 2 attempts out of 3) make openldap crash. Sasl speaking our
server-step mechanism closes fine and we expect its dispose step to be called
by openldap (by the sasl_server_end) That is not going to
happen being Openldap crashed meanwhile. Again this happens only
but not always when the stress scripts are running. Does it smell of thread
concurrency and safety? Our different use cases
tests run almost always successfully when done individually or in parallel but
manually (real people operating). Conversely when stress
test are going on the problem arise very often but not always. We had the Opeldap crash
both on linux and solaris installations though on linux the crash happens some
steps earlier than with solaris. On linux we have had the
opportunity to rebuild openldap with some debug instruction inside. what
came out is connection.c
crashing
at: op->o_tmpfree(
op->orb_edn.bv_val, op->o_tmpmemctx ); in both successful and
error cases either the values passed and the function address look alike. op->orb_edn.bv_val
shows the distinguished name of the user just logged in (op->orb_edn.bv_len
is correctly set with its length). Based on the function
name we guess ldap is about to free the DN allocated storage. On Solaris9 we had the
segfault symptom but we have some more line on the log, one of which shows a
almost empty DN (!!!) made just of uid=”” GDB has the following
from the linux core dump: gdb -c core.5785 GNU gdb Red Hat Linux
(6.3.0.0-1.159.el4rh) Copyright 2004 Free Software Foundation, Inc. GDB is free software,
covered by the GNU General Public License, and you are welcome to change it
and/or distribute copies of it under certain conditions. Type "show
copying" to see the conditions. There is absolutely no
warranty for GDB. Type "show warranty" for details. This GDB was configured
as "i386-redhat-linux-gnu". Core was generated by
`/usr/sbin/slapd -h ldap:///'. Program terminated with
signal 11, Segmentation fault. #0 0x00268934 in
?? () THE FOLLOWING CODE IS AN
EXCERPT OF THE FINAL SERVER_MECH_STEP FUNCTION OF THE MECHANISM WHICH RUN
BEHIND THE SASL_SERVER_STEP ONLY WHEN CRASH HAPPENS: static int
mymech_server_mech_step(void *conn_context __attribute__((unused)),
sasl_server_params_t *params,
const char *clientin,
unsigned clientinlen,
const char **serverout,
unsigned *serveroutlen,
sasl_out_params_t *oparams) {
server_context_t *text =
(server_context_t *) conn_context;
*serverout = NULL;
*serveroutlen = 0;
oparams->doneflag = 1;
oparams->mech_ssf = 0;
oparams->maxoutbuf = 0;
oparams->encode_context = NULL;
oparams->encode = NULL;
oparams->decode_context = NULL;
oparams->decode = NULL;
oparams->param_version = 0;
oparams->authid = text->authid;
return SASL_OK; } SLAPD.LOG
OF THE CRASH CASE (WITH OUR ADDED SYSLOGS): Feb 4 12:09:15
yavcentos slapd: SASL [conn=48] Debug MMYMECH====================== SERVER
mymech_server_mech_step END == Feb 4 12:09:15
yavcentos mymech: sasl.c label slap_sasl_authorize Feb 4 12:09:15
yavcentos slapd: SASL proxy authorize [conn=48]:
authcid="alfredo@yavcentos" authzid="alfredo@yavcentos" Feb 4 12:09:15
yavcentos slapd: conn=48 op=4 BIND authcid="alfredo@yavcentos"
authzid="alfredo@yavcentos" Feb 4 12:09:15
yavcentos slapd: SASL Authorize [conn=48]: proxy authorization allowed
authzDN="" Feb 4 12:09:15
yavcentos mymech: sasl.c label1 Feb 4 12:09:15
yavcentos mymech: result.c label2 Feb 4 12:09:15
yavcentos slapd: send_ldap_sasl: err=0 len=-1 Feb 4 12:09:15
yavcentos mymech: result.c label6a Feb 4 12:09:15
yavcentos mymech: result.c label61 Feb 4 12:09:15
yavcentos mymech: result.c label61a (tra qui) Feb 4 12:09:15
yavcentos mymech: result.c label61b Feb 4 12:09:15
yavcentos mymech: result.c label61b2
op->o_callback->sc_response=0x805e1fc op=0x8926cb0 rs=0x17551a0 Feb 4 12:09:15
yavcentos mymech: connection.c label1 Feb 4 12:09:15
yavcentos mymech: connection.c label1a Feb 4 12:09:15
yavcentos mymech: connection.c label11a Feb 4 12:09:15 yavcentos
mymech: connection.c label111a Feb 4 12:09:15
yavcentos mymech: connection.c label12a Feb 4 12:09:15
yavcentos mymech: connection.c label12a op->o_tmpfree=0x809c3e8
op->orb_edn.bv_val=uid=alfredo@yavcentos,ou= people,dc=my-domain,dc=com
op->orb_edn.bv_len=51 op->o_tmpmemctx=0x8926c10 (slab malloc context) END SLAPD.LOG
OF A SUCCESSFUL LOGIN CASE (WITH OUR ADDED
SYSLOGS): Feb 4 12:13:13
yavcentos mymech: sasl.c label slap_sasl_authorize Feb 4 12:13:13
yavcentos slapd: SASL proxy authorize [conn=3]:
authcid="alfredo@yavcentos" authzid="alfredo@yavcentos" Feb 4 12:13:14
yavcentos slapd: conn=3 op=4 BIND authcid="alfredo@yavcentos"
authzid="alfredo@yavcentos" Feb 4 12:13:14
yavcentos slapd: SASL Authorize [conn=3]: proxy authorization allowed authzDN="" Feb 4 12:13:14
yavcentos mymech: sasl.c label1 Feb 4 12:13:14
yavcentos mymech: result.c label2 Feb 4 12:13:14
yavcentos slapd: send_ldap_sasl: err=0 len=-1 Feb 4 12:13:14
yavcentos mymech: result.c label6a Feb 4 12:13:14
yavcentos mymech: result.c label61 Feb 4 12:13:14
yavcentos mymech: result.c label61a (tra qui) Feb 4 12:13:14
yavcentos mymech: result.c label61b Feb 4 12:13:14
yavcentos mymech: result.c label61b2
op->o_callback->sc_response=0x805e1fc op=0x86667b8 rs=0x51271a0 Feb 4 12:13:14
yavcentos mymech: connection.c label1 Feb 4 12:13:14
yavcentos mymech: connection.c label1a Feb 4 12:13:14
yavcentos mymech: connection.c label11a Feb 4 12:13:14
yavcentos mymech: connection.c label111a Feb 4 12:13:14
yavcentos mymech: connection.c label12a Feb 4 12:13:14
yavcentos mymech: connection.c label12a op->o_tmpfree=0x809c3e8
op->orb_edn.bv_val=uid=alfredo@yavcentos,ou= people,dc=my-domain,dc=com
op->orb_edn.bv_len=51 op->o_tmpmemctx=0x86660c0 (slab malloc context) Feb 4 12:13:14
yavcentos mymech: connection.c label13a Feb 4 12:13:14
yavcentos mymech: connection.c label14a Feb 4 12:13:14
yavcentos mymech: connection.c label15a Feb 4 12:13:14
yavcentos mymech: connection.c label151a Feb 4 12:13:14
yavcentos mymech: connection.c label151b Feb 4 12:13:14
yavcentos mymech: connection.c label2 Feb 4 12:13:14
yavcentos slapd: conn=3 op=4 BIND
dn="uid=alfredo@yavcentos,ou=people,dc=my-domain,dc=com" mech=MYMECH
sasl_ ssf=0 ssf=0 Feb 4 12:13:14
yavcentos slapd: do_bind: SASL/MYMECH bind:
dn="uid=alfredo@yavcentos,ou=people,dc=my-domain,dc=com" sasl_ss f=0 Feb 4 12:13:14
yavcentos mymech: connection.c label3 Feb 4 12:13:14
yavcentos mymech: result.c label61c Feb 4 12:13:14
yavcentos mymech: result.c label61d Feb 4 12:13:14
yavcentos mymech: result.c label61d2 Feb 4 12:13:14
yavcentos mymech: result.c label61e Feb 4 12:13:14
yavcentos slapd: send_ldap_response: msgid=5 tag=97 err=0 Feb 4 12:13:14
yavcentos mymech: result.c label1 Feb 4 12:13:14
yavcentos mymech: result.c label11 Feb 4 12:13:14
yavcentos mymech: result.c label12 Feb 4 12:13:14
yavcentos mymech: result.c label13 Feb 4 12:13:14
yavcentos mymech: result.c label14 Feb 4 12:13:14
yavcentos mymech: result.c label14e Feb 4 12:13:14
yavcentos mymech: result.c label14f Feb 4 12:13:14
yavcentos mymech: result.c label14g Feb 4 12:13:14
yavcentos mymech: result.c label14h Feb 4 12:13:14
yavcentos mymech: result.c label15 Feb 4 12:13:14
yavcentos mymech: result.c label16 Feb 4 12:13:14
yavcentos mymech: result.c label18 Feb 4 12:13:14
yavcentos mymech: result.c label19 Feb 4 12:13:14
yavcentos mymech: result.c label20 Feb 4 12:13:14
yavcentos mymech: result.c label21 Feb 4 12:13:14
yavcentos mymech: result.c label6b e qui2 Feb 4 12:13:14
yavcentos mymech: daemon: activity on 1 descriptor Feb 4 12:13:15
yavcentos slapd: daemon: activity on: Feb 4 12:13:15
yavcentos slapd: 13r Feb 4 12:13:15
yavcentos slapd: Feb 4 12:13:15
yavcentos slapd: daemon: read active on 13 Feb 4 12:13:15
yavcentos slapd: connection_get(13) Feb 4 12:13:15
yavcentos slapd: connection_get(13): got connid=3 Feb 4 12:13:15
yavcentos slapd: connection_read(13): checking for input on id=3 Feb 4 12:13:15
yavcentos slapd: daemon: epoll: listen=7 active_threads=0 tvp=NULL Feb 4 12:13:15
yavcentos slapd: daemon: epoll: listen=8 active_threads=0 tvp=NULL Feb 4 12:13:15
yavcentos slapd: conn=3 op=4 RESULT tag=97 err=0 text= Feb 4 12:13:15
yavcentos mymech: sasl.c label4 Feb 4 12:13:15
yavcentos slapd: <== slap_sasl_bind: rc=0 Feb 4 12:13:15
yavcentos mymech: bind.c do_bind label1 Feb 4 12:13:15
yavcentos slapd: do_bind Feb 4 12:13:15
yavcentos slapd: conn=3 op=5 BIND anonymous mech=implicit ssf=0 Feb 4 12:13:15
yavcentos slapd: >>> dnPrettyNormal: <> Feb 4 12:13:15
yavcentos slapd: <<< dnPrettyNormal: <>, <> Feb 4 12:13:15
yavcentos slapd: do_bind: version=3 dn="" method=128 Feb 4 12:13:15
yavcentos slapd: conn=3 op=5 BIND dn="" method=128 Feb 4 12:13:15
yavcentos mymech: sasl.c label slap_sasl_reset Feb 4 12:13:15
yavcentos slapd: send_ldap_result: conn=3 op=5 p=3 Feb 4 12:13:15
yavcentos slapd: send_ldap_result: err=0 matched="" text="" Feb 4 12:13:15
yavcentos mymech: result.c label22a Feb 4 12:13:15
yavcentos mymech: result.c label61 Feb 4 12:13:15
yavcentos mymech: result.c label61a (tra qui) Feb 4 12:13:15
yavcentos mymech: result.c label61b Feb 4 12:13:15
yavcentos mymech: result.c label61b2
op->o_callback->sc_response=0x805e1fc op=0x8668158 rs=0x2afc1a0 Feb 4 12:13:15
yavcentos mymech: connection.c label1 Feb 4 12:13:15
yavcentos mymech: connection.c label3 Feb 4 12:13:15
yavcentos mymech: result.c label61c Feb 4 12:13:15
yavcentos mymech: result.c label61d Feb 4 12:13:15
yavcentos mymech: result.c label61d2 Feb 4 12:13:15
yavcentos mymech: result.c label61e Feb 4 12:13:15
yavcentos slapd: send_ldap_response: msgid=6 tag=97 err=0 Feb 4 12:13:15
yavcentos mymech: result.c label1 Feb 4 12:13:15
yavcentos mymech: result.c label11 Feb 4 12:13:15
yavcentos mymech: result.c label12 Feb 4 12:13:15
yavcentos mymech: result.c label13 Feb 4 12:13:15
yavcentos mymech: result.c label14 Feb 4 12:13:15
yavcentos mymech: result.c label14e Feb 4 12:13:15
yavcentos mymech: result.c label14f Feb 4 12:13:15
yavcentos mymech: result.c label14g Feb 4 12:13:15
yavcentos mymech: result.c label14h Feb 4 12:13:15
yavcentos mymech: result.c label15 Feb 4 12:13:15
yavcentos mymech: result.c label16 Feb 4 12:13:15
yavcentos mymech: result.c label18 Feb 4 12:13:15
yavcentos mymech: result.c label19 Feb 4 12:13:16
yavcentos mymech: result.c label20 Feb 4 12:13:16
yavcentos mymech: result.c label21 Feb 4 12:13:16
yavcentos mymech: result.c label22b Feb 4 12:13:16
yavcentos mymech: result.c label5 e qui1 Feb 4 12:13:16
yavcentos slapd: conn=3 op=5 RESULT tag=97 err=0 text= Feb 4 12:13:16
yavcentos slapd: do_bind: v3 anonymous bind Feb 4 12:13:15
yavcentos mymech: daemon: activity on 1 descriptor Feb 4 12:13:16
yavcentos slapd: daemon: activity on: Feb 4 12:13:16
yavcentos slapd: 13r Feb 4 12:13:16
yavcentos slapd: Feb 4 12:13:16
yavcentos slapd: daemon: read active on 13 Feb 4 12:13:16
yavcentos slapd: connection_get(13) Feb 4 12:13:16
yavcentos slapd: connection_get(13): got connid=3 Feb 4 12:13:16
yavcentos slapd: connection_read(13): checking for input on id=3 Feb 4 12:13:16
yavcentos slapd: ber_get_next on fd 13 failed errno=0 (Success) Feb 4 12:13:16
yavcentos slapd: connection_read(13): input error=-2 id=3, closing. Feb 4 12:13:16
yavcentos slapd: connection_closing: readying conn=3 sd=13 for close Feb 4 12:13:16
yavcentos slapd: connection_close: conn=3 sd=-1 Feb 4 12:13:16
yavcentos mymech: sasl.c label slap_sasl_close Feb 4 12:13:16
yavcentos mymech: sasl.c label slap_sasl_log Feb 4 12:13:16
yavcentos slapd: SASL [conn=-1]
Debug: MMYMECHSERVER
mymech_server_mech_dispose Feb 4 12:13:16
yavcentos mymech: sasl.c label slap_sasl_log Feb 4 12:13:16
yavcentos slapd: SASL [conn=-1] Error: MMYMECHSERVER mymech_server_mech_dispose:
start - receives *conn_co ntext=0x8666a10
*utils=0x8666188 Feb 4 12:13:16
yavcentos mymech: sasl.c label slap_sasl_log Feb 4 12:13:17
yavcentos slapd: SASL [conn=-1] Error: MMYMECHSERVER
mymech_server_mech_dispose Feb 4 12:13:17
yavcentos slapd: daemon: removing 13 Feb 4 12:13:17
yavcentos slapd: conn=3 fd=13 closed (connection lost) Feb 4 12:13:17
yavcentos slapd: daemon: epoll: listen=7 active_threads=0 tvp=NULL Feb 4 12:13:17
yavcentos slapd: daemon: epoll: listen=8 active_threads=0 tvp=NULL Feb 4 12:13:17
yavcentos slapd: daemon: activity on 1 descriptor Feb 4 12:13:17
yavcentos slapd: daemon: activity on: Feb 4 12:13:17
yavcentos slapd: Feb 4 12:13:17
yavcentos slapd: daemon: epoll: listen=7 active_threads=0 tvp=NULL Feb 4 12:13:17
yavcentos slapd: daemon: epoll: listen=8 active_threads=0 tvp=NULL END Compile and link options
of mymech: gcc –I ..... -v -Wall -W
-O2 -MT mymech.lo -MD -MP -MF .deps/mymech.Tpo -c mymech.c -fPIC -DPIC -o
mymech.lo gcc -shared
mymech.lo mymech _init.lo plugin_common.lo -lpthread -lcrypt -lresolv -lc
-Wl,-soname -Wl,lib mymech.so.2 -o .libs/lib mymech.so.2.0.22 Would you have a clue or
a though for us about some further check to do over either our code or compile
options, (maybe particularly on
the thread-safe topic)? Would you suggest some
thread safe programming strategy? Many many thanks Francesco Grossi Ing.
Pierangelo Masarati OpenLDAP Core Team SysNet
s.r.l. Via Dossi, 8 - 27100 Pavia - ITALIA
| ||||||||||||