I'm experiencing crashes in slapd when attempting to bind via
SASL using the OTP mech.
I'm using openldap version 2.3.39 for both slapd and my ldap
utils (ldapsearch). I'm using the bdb backend.
I'm also using Debian Etch with the following versions of software:
Cyrus SASL 2.1.22(.dfsg1-8)
libdb 4.2.52(+dfsg-2)
libc6 2.3.6(.ds1-13etch2)
I've compiled cyrus sasl to use it's internal implementation of
OTP, rather than OPIE:
--enable-otp
(--with-opie is not enabled)
The problem I'm experiencing isn't when I successfully
authenticate; that seems to work fine. It's when I run an
ldapsearch, but instead of entering an OTP password, I press
ctrl-c to cancel the search.
From the shell, when I perform an LDAP search, all appears normal:
hiro:~# ldapsearch -Y OTP -U abrown(a)olp.net
SASL/OTP authentication started
Challenge: otp-md5 497 hi3182 ext
Please enter your one-time password:<ctrl-c>
hiro:~#
However my slapd process dies.
Here's a gdb backtrace of the server process:
...
Core was generated by `/usr/sbin/slapd'.
Program terminated with signal 11, Segmentation fault.
#0 0x080b448e in slap_auxprop_store (glob_context=0x0,
sparams=0x820b2a0, prctx=0x82351c0, user=0x820a148
"abrown(a)olp.net", ulen=14)
at
/usr/src/build/openldap/openldap2.3-2.3.39/servers/slapd/sasl.c:478
478 op.o_hdr =
conn->c_sasl_bindop->o_hdr;
(gdb) bt
#0 0x080b448e in slap_auxprop_store (glob_context=0x0,
sparams=0x820b2a0, prctx=0x82351c0, user=0x820a148
"abrown(a)olp.net", ulen=14)
at
/usr/src/build/openldap/openldap2.3-2.3.39/servers/slapd/sasl.c:478
#1 0xb7eb17d7 in sasl_auxprop_store () from /usr/lib/libsasl2.so.2
#2 0xb7973c89 in otp_server_plug_init () from
/usr/lib/sasl2/libotp.so.2
#3 0xb7ebde36 in sasl_server_new () from /usr/lib/libsasl2.so.2
#4 0xb7eb6194 in sasl_dispose () from /usr/lib/libsasl2.so.2
#5 0x080b2992 in slap_sasl_close (conn=0xb7ec3618) at
/usr/src/build/openldap/openldap2.3-2.3.39/servers/slapd/sasl.c:1331
#6 0x0806cf27 in connection_close (c=0xb75b1148) at
/usr/src/build/openldap/openldap2.3-2.3.39/servers/slapd/connection.c:715
#7 0x0806e116 in connection_read (s=12) at
/usr/src/build/openldap/openldap2.3-2.3.39/servers/slapd/connection.c:1458
#8 0x0806a49f in slapd_daemon_task (ptr=0x0) at
/usr/src/build/openldap/openldap2.3-2.3.39/servers/slapd/daemon.c:2468
#9 0xb7cd3240 in start_thread () from
/lib/tls/i686/cmov/libpthread.so.0
#10 0xb7c674ae in clone () from /lib/tls/i686/cmov/libc.so.6
(gdb) quit
I've added a debug statement within slap_auxprop_store, so the
openldap debug information below will include some additional
information about what's being modified.
Here's output from an attempt that crashed (when I pressed ctrl-c
in my ldapsearch):
Dec 3 13:39:06 hiro slapd[11134]: daemon: activity on 1 descriptor
Dec 3 13:39:06 hiro slapd[11134]: daemon: activity on:
Dec 3 13:39:06 hiro slapd[11134]:
Dec 3 13:39:06 hiro slapd[11134]: >>> slap_listener(ldapi:///)
Dec 3 13:39:06 hiro slapd[11134]: daemon: listen=12, new
connection on 16
Dec 3 13:39:06 hiro slapd[11134]: daemon: added 16r (active)
listener=(nil)
Dec 3 13:39:06 hiro slapd[11134]: conn=3 fd=16 ACCEPT from
PATH=/var/run/slapd/ldapi (PATH=/var/run/slapd/ldapi)
Dec 3 13:39:06 hiro slapd[11134]: daemon: epoll: listen=8
active_threads=0 tvp=NULL
Dec 3 13:39:06 hiro slapd[11134]: daemon: epoll: listen=9
active_threads=0 tvp=NULL
Dec 3 13:39:06 hiro slapd[11134]: daemon: epoll: listen=10
active_threads=0 tvp=NULL
Dec 3 13:39:06 hiro slapd[11134]: daemon: epoll: listen=11
active_threads=0 tvp=NULL
Dec 3 13:39:06 hiro slapd[11134]: daemon: epoll: listen=12
active_threads=0 tvp=NULL
Dec 3 13:39:06 hiro slapd[11134]: daemon: activity on 1 descriptor
Dec 3 13:39:06 hiro slapd[11134]: daemon: activity on:
Dec 3 13:39:06 hiro slapd[11134]: 16r
Dec 3 13:39:06 hiro slapd[11134]:
Dec 3 13:39:06 hiro slapd[11134]: daemon: read active on 16
Dec 3 13:39:06 hiro slapd[11134]: connection_get(16)
Dec 3 13:39:06 hiro slapd[11134]: connection_get(16): got connid=3
Dec 3 13:39:06 hiro slapd[11134]: connection_read(16): checking
for input on id=3
Dec 3 13:39:06 hiro slapd[11134]: daemon: epoll: listen=8
active_threads=0 tvp=NULL
Dec 3 13:39:06 hiro slapd[11134]: daemon: epoll: listen=9
active_threads=0 tvp=NULL
Dec 3 13:39:06 hiro slapd[11134]: do_bind
Dec 3 13:39:06 hiro slapd[11134]: daemon: epoll: listen=10
active_threads=0 tvp=NULL
Dec 3 13:39:06 hiro slapd[11134]: >>> dnPrettyNormal: <>
Dec 3 13:39:06 hiro slapd[11134]: daemon: epoll: listen=11
active_threads=0 tvp=NULL
Dec 3 13:39:06 hiro slapd[11134]: <<< dnPrettyNormal: <>, <>
Dec 3 13:39:06 hiro slapd[11134]: daemon: epoll: listen=12
active_threads=0 tvp=NULL
Dec 3 13:39:06 hiro slapd[11134]: do_sasl_bind: dn () mech OTP
Dec 3 13:39:06 hiro slapd[11134]: conn=3 op=0 BIND dn="" method=163
Dec 3 13:39:06 hiro slapd[11134]: ==> sasl_bind: dn="" mech=OTP
datalen=29
Dec 3 13:39:06 hiro slapd[11134]: SASL Canonicalize [conn=3]:
authcid="abrown(a)olp.net"
Dec 3 13:39:06 hiro slapd[11134]: slap_sasl_getdn: conn 3
id=abrown(a)olp.net [len=14]
Dec 3 13:39:06 hiro slapd[11134]: slap_sasl_getdn: u:id
converted to uid=abrown(a)olp.net,cn=OTP,cn=auth
Dec 3 13:39:06 hiro slapd[11134]: >>> dnNormalize:
<uid=abrown(a)olp.net,cn=OTP,cn=auth>
Dec 3 13:39:06 hiro slapd[11134]: <<< dnNormalize:
<uid=abrown(a)olp.net,cn=otp,cn=auth>
Dec 3 13:39:06 hiro slapd[11134]: ==>slap_sasl2dn: converting
SASL name uid=abrown(a)olp.net,cn=otp,cn=auth to a DN
Dec 3 13:39:06 hiro slapd[11134]: slap_authz_regexp: converting
SASL name uid=abrown(a)olp.net,cn=otp,cn=auth
Dec 3 13:39:06 hiro slapd[11134]: slap_authz_regexp: converted
SASL name to
ldap:///ou=people,dc=olp,dc=net??one?(btcAltUid=abrown@olp.net)
Dec 3 13:39:06 hiro slapd[11134]: slap_parseURI: parsing
ldap:///ou=people,dc=olp,dc=net??one?(btcAltUid=abrown@olp.net)
Dec 3 13:39:06 hiro slapd[11134]: str2filter
"(btcAltUid=abrown(a)olp.net)"
Dec 3 13:39:06 hiro slapd[11134]: begin get_filter
Dec 3 13:39:06 hiro slapd[11134]: EQUALITY
Dec 3 13:39:06 hiro slapd[11134]: end get_filter 0
Dec 3 13:39:06 hiro slapd[11134]: >>> dnNormalize:
<ou=people,dc=olp,dc=net>
Dec 3 13:39:06 hiro slapd[11134]: <<< dnNormalize:
<ou=people,dc=olp,dc=net>
Dec 3 13:39:06 hiro slapd[11134]: slap_sasl2dn: performing
internal search (base=ou=people,dc=olp,dc=net, scope=1)
Dec 3 13:39:06 hiro slapd[11134]: => bdb_search
Dec 3 13:39:06 hiro slapd[11134]:
bdb_dn2entry("ou=people,dc=olp,dc=net")
Dec 3 13:39:06 hiro slapd[11134]: search_candidates:
base="ou=people,dc=olp,dc=net" (0x00000003) scope=1
Dec 3 13:39:06 hiro slapd[11134]: =>
bdb_dn2idl("ou=people,dc=olp,dc=net")
Dec 3 13:39:06 hiro slapd[11134]: bdb_idl_fetch_key:
%ou=people,dc=olp,dc=net
Dec 3 13:39:06 hiro slapd[11134]: <= bdb_dn2idl: id=68 first=7
last=136
Dec 3 13:39:06 hiro slapd[11134]: => bdb_filter_candidates
Dec 3 13:39:06 hiro slapd[11134]: ^IAND
Dec 3 13:39:06 hiro slapd[11134]: => bdb_list_candidates 0xa0
Dec 3 13:39:06 hiro slapd[11134]: => bdb_filter_candidates
Dec 3 13:39:06 hiro slapd[11134]: ^IOR
Dec 3 13:39:06 hiro slapd[11134]: => bdb_list_candidates 0xa1
Dec 3 13:39:06 hiro slapd[11134]: => bdb_filter_candidates
Dec 3 13:39:06 hiro slapd[11134]: ^IEQUALITY
Dec 3 13:39:06 hiro slapd[11134]: => bdb_equality_candidates
(objectClass)
Dec 3 13:39:06 hiro slapd[11134]: => key_read
Dec 3 13:39:06 hiro slapd[11134]: bdb_idl_fetch_key: [b49d1940]
Dec 3 13:39:06 hiro slapd[11134]: <= bdb_index_read: failed
(-30990)
Dec 3 13:39:06 hiro slapd[11134]: <= bdb_equality_candidates:
id=0, first=0, last=0
Dec 3 13:39:06 hiro slapd[11134]: <= bdb_filter_candidates: id=0
first=0 last=0
Dec 3 13:39:06 hiro slapd[11134]: => bdb_filter_candidates
Dec 3 13:39:06 hiro slapd[11134]: ^IEQUALITY
Dec 3 13:39:06 hiro slapd[11134]: => bdb_equality_candidates
(btcAltUID)
Dec 3 13:39:06 hiro slapd[11134]: => key_read
Dec 3 13:39:06 hiro slapd[11134]: bdb_idl_fetch_key: [b0f0ea63]
Dec 3 13:39:06 hiro slapd[11134]: <= bdb_index_read 1 candidates
Dec 3 13:39:06 hiro slapd[11134]: <= bdb_equality_candidates:
id=1, first=7, last=7
Dec 3 13:39:06 hiro slapd[11134]: <= bdb_filter_candidates: id=1
first=7 last=7
Dec 3 13:39:06 hiro slapd[11134]: <= bdb_list_candidates: id=1
first=7 last=7
Dec 3 13:39:06 hiro slapd[11134]: <= bdb_filter_candidates: id=1
first=7 last=7
Dec 3 13:39:06 hiro slapd[11134]: <= bdb_list_candidates: id=1
first=7 last=7
Dec 3 13:39:06 hiro slapd[11134]: <= bdb_filter_candidates: id=1
first=7 last=7
Dec 3 13:39:06 hiro slapd[11134]: bdb_search_candidates: id=1
first=7 last=7
Dec 3 13:39:06 hiro slapd[11134]: => test_filter
Dec 3 13:39:06 hiro slapd[11134]: EQUALITY
Dec 3 13:39:06 hiro slapd[11134]: => access_allowed: auth access
to "uid=abrown(a)olp.net,ou=People,dc=olp,dc=net" "btcAltUID"
requested
Dec 3 13:39:06 hiro slapd[11134]: => dnpat: [1]
ou=addressbooks,uid=([^,]+),ou=people,dc=olp,dc=net$ nsub: 1
Dec 3 13:39:06 hiro slapd[11134]: => dnpat: [2]
.*,ou=addressbooks,uid=([^,]+),ou=people,dc=olp,dc=net$ nsub: 1
Dec 3 13:39:06 hiro slapd[11134]: => dn: [3]
ou=people,dc=olp,dc=net
Dec 3 13:39:06 hiro slapd[11134]: => dn: [4]
ou=groups,dc=olp,dc=net
Dec 3 13:39:06 hiro slapd[11134]: => acl_get: [7] attr btcAltUID
Dec 3 13:39:06 hiro slapd[11134]: => acl_mask: access to entry
"uid=abrown(a)olp.net,ou=People,dc=olp,dc=net", attr "btcAltUID"
requested
Dec 3 13:39:06 hiro slapd[11134]: => acl_mask: to value by "",
(=0)
Dec 3 13:39:06 hiro slapd[11134]: <= check a_dn_pat: anonymous
Dec 3 13:39:06 hiro slapd[11134]: <= acl_mask: [1] applying
auth(=xd) (stop)
Dec 3 13:39:06 hiro slapd[11134]: <= acl_mask: [1] mask: auth(=xd)
Dec 3 13:39:06 hiro slapd[11134]: => slap_access_allowed: auth
access granted by auth(=xd)
Dec 3 13:39:06 hiro slapd[11134]: => access_allowed: auth access
granted by auth(=xd)
Dec 3 13:39:06 hiro slapd[11134]: <= test_filter 6
Dec 3 13:39:06 hiro slapd[11134]: send_ldap_result: conn=3 op=0 p=3
Dec 3 13:39:06 hiro slapd[11134]: send_ldap_result: err=0
matched="" text=""
Dec 3 13:39:06 hiro slapd[11134]: <==slap_sasl2dn: Converted
SASL name to uid=abrown(a)olp.net,ou=people,dc=olp,dc=net
Dec 3 13:39:06 hiro slapd[11134]: slap_sasl_getdn: dn:id
converted to uid=abrown(a)olp.net,ou=people,dc=olp,dc=net
Dec 3 13:39:06 hiro slapd[11134]: SASL Canonicalize [conn=3]:
slapAuthcDN="uid=abrown(a)olp.net,ou=people,dc=olp,dc=net"
Dec 3 13:39:06 hiro slapd[11134]: => bdb_search
Dec 3 13:39:06 hiro slapd[11134]:
bdb_dn2entry("uid=abrown(a)olp.net,ou=people,dc=olp,dc=net")
Dec 3 13:39:06 hiro slapd[11134]: base_candidates: base:
"uid=abrown(a)olp.net,ou=people,dc=olp,dc=net" (0x00000007)
Dec 3 13:39:06 hiro slapd[11134]: => test_filter
Dec 3 13:39:06 hiro slapd[11134]: PRESENT
Dec 3 13:39:06 hiro slapd[11134]: => access_allowed: auth access
to "uid=abrown(a)olp.net,ou=People,dc=olp,dc=net" "objectClass"
requested
Dec 3 13:39:06 hiro slapd[11134]: => dnpat: [1]
ou=addressbooks,uid=([^,]+),ou=people,dc=olp,dc=net$ nsub: 1
Dec 3 13:39:06 hiro slapd[11134]: => dnpat: [2]
.*,ou=addressbooks,uid=([^,]+),ou=people,dc=olp,dc=net$ nsub: 1
Dec 3 13:39:06 hiro slapd[11134]: => dn: [3]
ou=people,dc=olp,dc=net
Dec 3 13:39:06 hiro slapd[11134]: => dn: [4]
ou=groups,dc=olp,dc=net
Dec 3 13:39:06 hiro slapd[11134]: => dnpat: [12]
.*n=([^,]+),ou=groups,dc=olp,dc=net$ nsub: 1
Dec 3 13:39:06 hiro slapd[11134]: => dnpat: [13]
.*n=([^,]+),ou=groups,dc=olp,dc=net$ nsub: 1
Dec 3 13:39:06 hiro slapd[11134]: => dnpat: [14]
^cn=admin,cn=([^,]+),ou=groups,dc=olp,dc=net$ nsub: 1
Dec 3 13:39:06 hiro slapd[11134]: => dnpat: [15]
^cn=([^,]+),ou=groups,dc=olp,dc=net$ nsub: 1
Dec 3 13:39:06 hiro slapd[11134]: => dnpat: [16]
^cn=admin,cn=([^,]+),ou=groups,dc=olp,dc=net$ nsub: 1
Dec 3 13:39:06 hiro slapd[11134]: => acl_get: [17] attr objectClass
Dec 3 13:39:06 hiro slapd[11134]: => acl_mask: access to entry
"uid=abrown(a)olp.net,ou=People,dc=olp,dc=net", attr "objectClass"
requested
Dec 3 13:39:06 hiro slapd[11134]: => acl_mask: to all values by
"", (=0)
Dec 3 13:39:06 hiro slapd[11134]: <= check a_dn_pat: self
Dec 3 13:39:06 hiro slapd[11134]: <= check a_dn_pat: anonymous
Dec 3 13:39:06 hiro slapd[11134]: <= acl_mask: [8] applying
auth(=xd) (stop)
Dec 3 13:39:06 hiro slapd[11134]: <= acl_mask: [8] mask: auth(=xd)
Dec 3 13:39:06 hiro slapd[11134]: => slap_access_allowed: auth
access granted by auth(=xd)
Dec 3 13:39:06 hiro slapd[11134]: => access_allowed: auth access
granted by auth(=xd)
Dec 3 13:39:06 hiro slapd[11134]: <= test_filter 6
Dec 3 13:39:06 hiro slapd[11134]: => access_allowed: auth access
to "uid=abrown(a)olp.net,ou=People,dc=olp,dc=net"
"cmusaslsecretOTP" requested
Dec 3 13:39:06 hiro slapd[11134]: => dnpat: [1]
ou=addressbooks,uid=([^,]+),ou=people,dc=olp,dc=net$ nsub: 1
Dec 3 13:39:06 hiro slapd[11134]: => dnpat: [2]
.*,ou=addressbooks,uid=([^,]+),ou=people,dc=olp,dc=net$ nsub: 1
Dec 3 13:39:06 hiro slapd[11134]: => dn: [3]
ou=people,dc=olp,dc=net
Dec 3 13:39:06 hiro slapd[11134]: => dn: [4]
ou=groups,dc=olp,dc=net
Dec 3 13:39:06 hiro slapd[11134]: => acl_get: [8] attr
cmusaslsecretOTP
Dec 3 13:39:06 hiro slapd[11134]: => acl_mask: access to entry
"uid=abrown(a)olp.net,ou=People,dc=olp,dc=net", attr
"cmusaslsecretOTP" requested
Dec 3 13:39:06 hiro slapd[11134]: => acl_mask: to all values by
"", (=0)
Dec 3 13:39:06 hiro slapd[11134]: <= check a_dn_pat: anonymous
Dec 3 13:39:06 hiro slapd[11134]: <= acl_mask: [1] applying
auth(=xd) (stop)
Dec 3 13:39:06 hiro slapd[11134]: <= acl_mask: [1] mask: auth(=xd)
Dec 3 13:39:06 hiro slapd[11134]: => slap_access_allowed: auth
access granted by auth(=xd)
Dec 3 13:39:06 hiro slapd[11134]: => access_allowed: auth access
granted by auth(=xd)
Dec 3 13:39:06 hiro slapd[11134]: send_ldap_result: conn=3 op=0 p=3
Dec 3 13:39:06 hiro slapd[11134]: send_ldap_result: err=0
matched="" text=""
Dec 3 13:39:06 hiro slapd[11134]: SASL Canonicalize [conn=3]:
authzid="abrown(a)olp.net"
Dec 3 13:39:06 hiro slapd[11134]: slap_auxprop_store [conn=3]:
Getting ready to set cmusaslsecretOTP to
md5^I0499^Ihi5935^I0e81b33e30182715^I00000000001196711046.
Dec 3 13:39:06 hiro slapd[11134]: bdb_modify:
uid=abrown(a)olp.net,ou=people,dc=olp,dc=net
Dec 3 13:39:06 hiro slapd[11134]:
bdb_dn2entry("uid=abrown(a)olp.net,ou=people,dc=olp,dc=net")
Dec 3 13:39:06 hiro slapd[11134]: bdb_modify_internal:
0x00000007: uid=abrown(a)olp.net,ou=People,dc=olp,dc=net
Dec 3 13:39:06 hiro slapd[11134]: => access_allowed: delete
access to "uid=abrown(a)olp.net,ou=People,dc=olp,dc=net"
"cmusaslsecretOTP" requested
Dec 3 13:39:06 hiro slapd[11134]: => dnpat: [1]
ou=addressbooks,uid=([^,]+),ou=people,dc=olp,dc=net$ nsub: 1
Dec 3 13:39:06 hiro slapd[11134]: => dnpat: [2]
.*,ou=addressbooks,uid=([^,]+),ou=people,dc=olp,dc=net$ nsub: 1
Dec 3 13:39:06 hiro slapd[11134]: => dn: [3]
ou=people,dc=olp,dc=net
Dec 3 13:39:06 hiro slapd[11134]: => dn: [4]
ou=groups,dc=olp,dc=net
Dec 3 13:39:06 hiro slapd[11134]: => acl_get: [8] attr
cmusaslsecretOTP
Dec 3 13:39:06 hiro slapd[11134]: => slap_access_allowed: no res
from state (cmusaslsecretOTP)
Dec 3 13:39:06 hiro slapd[11134]: => acl_mask: access to entry
"uid=abrown(a)olp.net,ou=People,dc=olp,dc=net", attr
"cmusaslsecretOTP" requested
Dec 3 13:39:06 hiro slapd[11134]: => acl_mask: to all values by
"uid=abrown(a)olp.net,ou=people,dc=olp,dc=net", (=0)
Dec 3 13:39:06 hiro slapd[11134]: <= check a_dn_pat: anonymous
Dec 3 13:39:06 hiro slapd[11134]: <= check a_dn_pat: self
Dec 3 13:39:06 hiro slapd[11134]: <= acl_mask: [2] applying
write(=wrscxd) (stop)
Dec 3 13:39:06 hiro slapd[11134]: <= acl_mask: [2] mask:
write(=wrscxd)
Dec 3 13:39:06 hiro slapd[11134]: => slap_access_allowed: delete
access granted by write(=wrscxd)
Dec 3 13:39:06 hiro slapd[11134]: => access_allowed: delete
access granted by write(=wrscxd)
Dec 3 13:39:06 hiro slapd[11134]: acl: internal mod entryCSN:
modify access granted
Dec 3 13:39:06 hiro slapd[11134]: acl: internal mod
modifiersName: modify access granted
Dec 3 13:39:06 hiro slapd[11134]: acl: internal mod
modifyTimestamp: modify access granted
Dec 3 13:39:06 hiro slapd[11134]: bdb_modify_internal: replace
cmusaslsecretOTP
Dec 3 13:39:06 hiro slapd[11134]: bdb_modify_internal: replace
entryCSN
Dec 3 13:39:06 hiro slapd[11134]: bdb_modify_internal: replace
modifiersName
Dec 3 13:39:06 hiro slapd[11134]: bdb_modify_internal: replace
modifyTimestamp
Dec 3 13:39:06 hiro slapd[11134]: oc_check_required entry
(uid=abrown(a)olp.net,ou=People,dc=olp,dc=net), objectClass "account"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_required entry
(uid=abrown(a)olp.net,ou=People,dc=olp,dc=net), objectClass
"posixAccount"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_required entry
(uid=abrown(a)olp.net,ou=People,dc=olp,dc=net), objectClass
"shadowAccount"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_required entry
(uid=abrown(a)olp.net,ou=People,dc=olp,dc=net), objectClass
"krb5KDCEntry"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_required entry
(uid=abrown(a)olp.net,ou=People,dc=olp,dc=net), objectClass
"krb5Principal"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_required entry
(uid=abrown(a)olp.net,ou=People,dc=olp,dc=net), objectClass
"sambaSamAccount"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_required entry
(uid=abrown(a)olp.net,ou=People,dc=olp,dc=net), objectClass
"radiusprofile"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_required entry
(uid=abrown(a)olp.net,ou=People,dc=olp,dc=net), objectClass
"btcAuthUser"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_required entry
(uid=abrown(a)olp.net,ou=People,dc=olp,dc=net), objectClass
"cmuSaslUser"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_required entry
(uid=abrown(a)olp.net,ou=People,dc=olp,dc=net), objectClass "pkiUser"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_allowed type "uid"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_allowed type "cn"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_allowed type "uidNumber"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_allowed type "gidNumber"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_allowed type
"homeDirectory"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_allowed type
"loginShell"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_allowed type "shadowMin"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_allowed type "shadowMax"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_allowed type
"shadowWarning"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_allowed type
"shadowExpire"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_allowed type "gecos"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_allowed type
"structuralObjectClass"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_allowed type "entryUUID"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_allowed type
"creatorsName"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_allowed type
"createTimestamp"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_allowed type
"krb5PrincipalName"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_allowed type
"krb5MaxLife"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_allowed type
"krb5MaxRenew"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_allowed type
"krb5KDCFlags"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_allowed type "sambaSID"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_allowed type
"sambaAcctFlags"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_allowed type
"sambaPrimaryGroupSID"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_allowed type
"shadowLastChange"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_allowed type
"radiusGroupName"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_allowed type
"btcCertificatePassword"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_allowed type "btcAltUID"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_allowed type "UNDEFINED"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_allowed type
"userPassword"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_allowed type
"sambaPwdLastSet"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_allowed type
"sambaLMPassword"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_allowed type
"sambaNTPassword"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_allowed type
"krb5KeyVersionNumber"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_allowed type "krb5Key"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_allowed type "UNDEFINED"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_allowed type
"objectClass"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_allowed type "UNDEFINED"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_allowed type
"cmusaslsecretOTP"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_allowed type "entryCSN"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_allowed type
"modifiersName"
Dec 3 13:39:06 hiro slapd[11134]: oc_check_allowed type
"modifyTimestamp"
Dec 3 13:39:06 hiro slapd[11134]: => entry_encode(0x00000007):
uid=abrown(a)olp.net,ou=People,dc=olp,dc=net
Dec 3 13:39:06 hiro slapd[11134]: bdb_modify: updated
id=00000007 dn="uid=abrown(a)olp.net,ou=people,dc=olp,dc=net"
Dec 3 13:39:06 hiro slapd[11134]: send_ldap_result: conn=3 op=0 p=3
Dec 3 13:39:06 hiro slapd[11134]: send_ldap_result: err=0
matched="" text=""
Dec 3 13:39:06 hiro slapd[11134]: send_ldap_sasl: err=14 len=22
Dec 3 13:39:06 hiro slapd[11134]: send_ldap_response: msgid=1
tag=97 err=14
Dec 3 13:39:06 hiro slapd[11134]: conn=3 op=0 RESULT tag=97
err=14 text=
Dec 3 13:39:06 hiro slapd[11134]: <== slap_sasl_bind: rc=14
Dec 3 13:39:07 hiro slapd[11134]: daemon: activity on 1 descriptor
Dec 3 13:39:07 hiro slapd[11134]: daemon: activity on:
Dec 3 13:39:07 hiro slapd[11134]: 16r
Dec 3 13:39:07 hiro slapd[11134]:
Dec 3 13:39:07 hiro slapd[11134]: daemon: read active on 16
Dec 3 13:39:07 hiro slapd[11134]: connection_get(16)
Dec 3 13:39:07 hiro slapd[11134]: connection_get(16): got connid=3
Dec 3 13:39:07 hiro slapd[11134]: connection_read(16): checking
for input on id=3
Dec 3 13:39:07 hiro slapd[11134]: ber_get_next on fd 16 failed
errno=0 (Success)
Dec 3 13:39:07 hiro slapd[11134]: connection_read(16): input
error=-2 id=3, closing.
Dec 3 13:39:07 hiro slapd[11134]: connection_closing: readying
conn=3 sd=16 for close
Dec 3 13:39:07 hiro slapd[11134]: connection_close: conn=3 sd=-1
Dec 3 13:39:07 hiro slapd[11134]: slap_auxprop_store [conn=-1]:
Getting ready to set cmusaslsecretOTP to
md5^I0499^Ihi5935^I0e81b33e30182715^I00000000000000000000.
If I enter a good OTP password, I get this in my logs:
Dec 3 13:43:26 hiro slapd[11159]: slap_auxprop_store [conn=3]:
Getting ready to set cmusaslsecretOTP to
md5^I0499^Ihi5865^Iec8123986aec6550^I00000000001196711306.
Dec 3 13:44:26 hiro slapd[11159]: slap_auxprop_store [conn=3]:
Getting ready to set cmusaslsecretOTP to
md5^I0498^Ihi5865^Ic3570f027cf46ed0^I00000000000000000000.
If I enter an incorrect password, I get this:
Dec 3 13:45:21 hiro slapd[11159]: slap_auxprop_store [conn=4]:
Getting ready to set cmusaslsecretOTP to
md5^I0498^Ihi5865^Ic3570f027cf46ed0^I00000000001196711421.
Dec 3 13:45:22 hiro slapd[11159]: slap_auxprop_store [conn=4]:
Getting ready to set cmusaslsecretOTP to
md5^I0498^Ihi5865^Ic3570f027cf46ed0^I00000000000000000000.
So in the case where it's crashing, it appears the Cyrus SASL is
attempting to revert the OTP entry back to the previous version
to "unlock" it. I assume that the connection id of '-1' is
relevant to the crash.
You should be able to reproduce this error with the following steps:
Compile SASL with OTP, but without OPIE
Configure a dummy SASL service configuration file, e.g.:
hiro:~# cat > /usr/lib/sasl2/test.conf <<EOF
> auxprop_plugin: ldapdb
> ldapdb_uri: ldapi:///
> ldapdb_mech: EXTERNAL
> EOF
hiro:~#
Create a schema including an attribute of cmusaslsecretOTP, and
create an entry in the directory which can use this attribute.
Configure slapd.conf with the appropriate sasl configuration to
convert both the openldap user (connecting via ldapi:///) and the
user specified in the ldapsearch, for example:
sasl-regexp
"gidNumber=0\\\+uidNumber=0,cn=peercred,cn=external,cn=auth"
cn=admin,dc=olp,dc=net
sasl-regexp
"uid=([^,]+),cn=otp,cn=auth"
ldap:///ou=people,dc=olp,dc=net??one?(btcAltUid=$1)
Issue a saslpasswd2 to initialize the cmusaslsecretOTP attribute
for the user:
hiro:~# saslpasswd2 -a test -n abrown(a)olp.net
Password:
Again (for verification):
The cmusaslsecretOTP attribute should look something like:
md5 0499 hi8351 1c19abc81f35dc63
00000000000000000000
opiekey can be used to convert the OTP challenge into the
appropriate response. For instance:
hiro:~# ldapsearch -Y OTP -U abrown(a)olp.net
SASL/OTP authentication started
Challenge: otp-md5 498 hi8351 ext
Please enter your one-time password:
Using opiekey to obtain response:
dwhite@zek:~$ opiekey -5 -x 498 hi8351
Using the MD5 algorithm to compute response.
Reminder: Don't use opiekey from telnet or dial-in sessions.
Enter secret pass phrase:
556A 99B3 52FA CEB1
Feed the secret pass phrase back into ldapsearch for a successful
bind.
To reproduce the bug, of course just kill the ldapsearch before
entering any response.
- Dan White
BTC Broadband
