[Date Prev][Date Next] [Chronological] [Thread] [Top]

(ITS#6427) ldapsearch with delay (on the same machine over TLS/SSL only)

Full_Name: Pavel Lisy
Version: 2.4.19 or 2.4.20
OS: linux - CentOS4/5
URL: ftp://ftp.openldap.org/incoming/
Submission from: (NULL) (85.132.159.239)


I have my rpm built on source from Fedora 12. 

ldapsearch have delay on start, slapd is heavy loaded (up to 90% proc)
 on the same machine over TLS/SSL only (numbers below)
 
[root@ldap1 ~]# time ldapsearch24 -ZZ -h ldap1.ldapnet.tmapy.cz -x -s sub -D
"cn=Manager,dc=tmapy,dc=cz" -b 'dc=tmapy,dc=cz' -w heslo -d 1 > search-zz.log
2>&1

real    0m2.610s
user    0m0.029s
sys     0m0.014s

[root@ldap1 ~]# time ldapsearch24 -Z -h ldap1.ldapnet.tmapy.cz -x -s sub -D
"cn=Manager,dc=tmapy,dc=cz" -b 'dc=tmapy,dc=cz' -w heslo -d 1 > search-z.log
2>&1

real    0m2.700s
user    0m0.026s
sys     0m0.013s

[root@ldap1 ~]# time ldapsearch24 -h ldap1.ldapnet.tmapy.cz -x -s sub -D
"cn=Manager,dc=tmapy,dc=cz" -b 'dc=tmapy,dc=cz' -w heslo -d 1 > search.log 2>&1

real    0m0.021s
user    0m0.010s
sys     0m0.008s

[root@ldap1 ~]# time ldapsearch24 -h ldap2.ldapnet.tmapy.cz -x -s sub -D
"cn=Manager,dc=tmapy,dc=cz" -b 'dc=tmapy,dc=cz' -w heslo -d 1 > search-l2.log
2>&1

real    0m0.027s
user    0m0.009s
sys     0m0.014s

[root@ldap1 ~]# time ldapsearch24 -Z -h ldap2.ldapnet.tmapy.cz -x -s sub -D
"cn=Manager,dc=tmapy,dc=cz" -b 'dc=tmapy,dc=cz' -w heslo -d 1 > search-l2-z.log
2>&1 

real    0m0.070s
user    0m0.028s
sys     0m0.020s

[root@ldap1 ~]# time ldapsearch24 -ZZ -h ldap2.ldapnet.tmapy.cz -x -s sub -D
"cn=Manager,dc=tmapy,dc=cz" -b 'dc=tmapy,dc=cz' -w heslo -d 1 > search-l2-zz.log
2>&1

real    0m0.048s
user    0m0.026s
sys     0m0.017s


This means: delay is there when I query from the same machine over
TLS/SSL, not across machines. I suppose it is bug but I cannot find where it
is.

When I've changed in slapd.conf "loglevel 0" to "loglevel 1" 
delay is gone

[root@ldap1 ~]# time ldapsearch24 -ZZ -h ldap1.ldapnet.tmapy.cz -x -s sub -D
"cn=Manager,dc=tmapy,dc=cz" -b 'dc=tmapy,dc=cz' -w heslo -d 1 > search-zz.log
2>&1

real	0m0.315s
user	0m0.030s
sys	0m0.025s


When I start ldapsearch24 through strace delay was in part with stars:
------------ cut ---------------
munmap(0x2b2edf8b1000, 4096)            = 0
brk(0x15747000)                         = 0x15747000
write(2, "TLS trace: SSL_connect:before/co"..., 53TLS trace:
SSL_connect:before/connect initialization
) = 53
open("/dev/urandom", O_RDONLY|O_NOCTTY|O_NONBLOCK) = 4
fstat(4, {st_mode=S_IFCHR|0444, st_rdev=makedev(1, 9), ...}) = 0
poll([{fd=4, events=POLLIN}], 1, 10)    = 1 ([{fd=4, revents=POLLIN}])
read(4, "D~j?,\274k\310mx\336\t\17k\207Q\322\0369SDB\260\241bd6[R}6\201"..., 48)
= 48
close(4)                                = 0
getuid()                                = 0
write(3, "\200t\1\3\1\0K\0\0\0
\0\0009\0\0008\0\0005\0\0\26\0\0\23\0\0\n\7\0\300"..., 118
***********************************************
DELAY 2s HERE
***********************************************
) = 118
write(2, "TLS trace: SSL_connect:SSLv2/v3 "..., 53TLS trace:
SSL_connect:SSLv2/v3 write client hello A
) = 53
read(3, "\26\3\1\0J\2\0", 7)            = 7
read(3, "\0F\3\1K \10\5\232\0\3\2\354\235\351\233\276\31\242\302\217\214\35\32\370cGH\342\277\7;"...,
72) = 7
write(2, "TLS trace: SSL_connect:SSLv3 rea"..., 49TLS trace: SSL_connect:SSLv3
read server hello A
) = 49
read(3, "\26\3\1\6\303", 5)             = 5
read(3, "\v\0\6\277\0\6\274\0\2\2500\202\2\2440\202\2\r\2\3\20\0\0010\r\6\t*\206H\206\367"...,
1731) = 1731
write(2, "TLS certificate verification: de"..., 191TLS certificate verification:
depth: 1, err: 0, subject: /
write(2, " issuer: /O=T-MAPY spol. s r.o./"..., 143 issuer: /O=T-MAPY spol. s
r.o./OU=ldapnet/emailAddress=pa
) = 143
write(2, "TLS certificate verification: de"..., 146TLS certificate verification:
depth: 0, err: 0, subject: /
write(2, " issuer: /O=T-MAPY spol. s r.o./"..., 143 issuer: /O=T-MAPY spol. s
r.o./OU=ldapnet/emailAddress=pa
) = 143
write(2, "TLS trace: SSL_connect:SSLv3 rea"..., 55TLS trace: SSL_connect:SSLv3
read server certificate A
) = 55
read(3, "\26\3\1\0\4", 5)               = 5
read(3, "\16\0\0\0", 4)                 = 4
write(2, "TLS trace: SSL_connect:SSLv3 rea"..., 48TLS trace: SSL_connect:SSLv3
read server done A
) = 48
write(2, "TLS trace: SSL_connect:SSLv3 wri"..., 57TLS trace: SSL_connect:SSLv3
write client key exchange A
) = 57
write(2, "TLS trace: SSL_connect:SSLv3 wri"..., 56TLS trace: SSL_connect:SSLv3
write change cipher spec A
) = 56
write(2, "TLS trace: SSL_connect:SSLv3 wri"..., 46TLS trace: SSL_connect:SSLv3
write finished A
) = 46
write(3, "\26\3\1\0\206\20\0\0\202\0\200\202\365\233\356\r\26\27\330\251\17\330\331\3362\23\231\211`\\\262\32
write(2, "TLS trace: SSL_connect:SSLv3 flu"..., 40TLS trace: SSL_connect:SSLv3
flush data
) = 40
read(3, "\24\3\1\0\1", 5)               = 5
read(3, "\1", 1)                        = 1
read(3, "\26\3\1\0000", 5)              = 5
read(3, "\353;\20\337y\307&\331\207@#\265\314\267\240\244\177P\223\216\221\216!\"G
\27\265R\3078l"..., 48) =
write(2, "TLS trace: SSL_connect:SSLv3 rea"..., 45TLS trace: SSL_connect:SSLv3
read finished A
) = 45
write(2, "ldap_sasl_bind\n", 15ldap_sasl_bind
)        = 15
write(2, "ldap_send_initial_request\n", 26ldap_send_initial_request
) = 26
write(2, "ldap_send_server_request\n", 25ldap_send_server_request
) = 25
write(2, "ber_scanf fmt ({it) ber:\n", 25ber_scanf fmt ({it) ber:
) = 25
write(2, "ber_scanf fmt ({i) ber:\n", 24ber_scanf fmt ({i) ber:
) = 24
write(2, "ber_flush2: 44 bytes to sd 3\n", 29ber_flush2: 44 bytes to sd 3
) = 29
write(3, "\27\3\1\0 \217\244v\31\275A\232=\300\357\330\312*\316)\311\23\242\260\350n\353\373\221\204B\v"...,
write(2, "ldap_result ld 0x156816c0 msgid "..., 34ldap_result ld 0x156816c0
msgid 2
) = 34
write(2, "wait4msg ld 0x156816c0 msgid 2 ("..., 50wait4msg ld 0x156816c0 msgid 2
(infinite timeout)
) = 50
write(2, "wait4msg continue ld 0x156816c0 "..., 46wait4msg continue ld
0x156816c0 msgid 2 all 1
) = 46
write(2, "** ld 0x156816c0 Connections:\n", 30** ld 0x156816c0 Connections:
) = 30
write(2, "* host: ldap1.ldapnet.tmapy.cz  "..., 53* host: ldap1.ldapnet.tmapy.cz
 port: 389  (default)
) = 53
write(2, "  refcnt: 2  status: Connected\n", 31  refcnt: 2  status: Connected
) = 31
write(2, "  last used: Wed Dec  9 21:26:51"..., 39  last used: Wed Dec  9
21:26:51 2009
------------ cut ---------------

How can I debug it more? I will send more details if you want.