Could you send:
- a stack backtrace of a crash (please keep the binaries and the core, so that we can ask you to print some of the values, if needed)
- the output obtained by running slapd under valgrind --tool=memcheck --trace-children=yes --leak-check=full
- in any case, apart from some indications about where to look, you won't get much help if you work with an outdated version of an obsolete version of OpenLDAP.
p.
----- "Francesco Grossi ITQL" f.grossi@itql.it wrote:
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 http://www.sys-net.it ----------------------------------- Office: +39 02 23998309 Mobile: +39 333 4963172 Fax: +39 0382 476497 Email: ando@sys-net.it -----------------------------------