https://bugs.openldap.org/show_bug.cgi?id=9803
Issue ID: 9803 Summary: liblber: assertion( ber->ber_buf == NULL ); failed Product: OpenLDAP Version: 2.4.46 Hardware: x86_64 OS: Linux Status: UNCONFIRMED Keywords: needs_review Severity: normal Priority: --- Component: libraries Assignee: bugs@openldap.org Reporter: jengelh@inai.de Target Milestone: ---
libraries/liblber/io.c function ber_get_next contains a line
assert( ber->ber_buf == NULL );
and with a larger application that uses libldap-2.4.46, I am running into that sporadically. I have no idea how that happens, but it seems probable the LDAP server (of which there is also no info on) is sending something that is interpreted as invalid and ber_buf does not get freed, so it's set on the next invocation.
``` (gdb)
zcore: io.c:514: ber_get_next: Assertion `ber->ber_buf == NULL' failed.
Thread 40 "rpc/34" received signal SIGABRT, Aborted. [Switching to Thread 0x7fffd6ff8700 (LWP 18485)] (gdb) up #1 0x00007ffff20fb585 in abort () from /lib64/libc.so.6 (gdb) #2 0x00007ffff20f285a in __assert_fail_base () from /lib64/libc.so.6 (gdb) #3 0x00007ffff20f28d2 in __assert_fail () from /lib64/libc.so.6 (gdb) #4 0x00007fffee0f48a1 in ber_get_next (sb=0x6040000aa650, len=len@entry=0x7fffd6ff61c8, ber=ber@entry=0x6070000b0360) at io.c:514 514 assert( ber->ber_buf == NULL ); (gdb) p ber $1 = (BerElement *) 0x6070000b0360 (gdb) p *ber $2 = {ber_opts = {lbo_valid = 2, lbo_options = 1, lbo_debug = 0}, ber_tag = 116, ber_len = 78, ber_usertag = 0, ber_buf = 0x6070000b03d0 "cP", ber_ptr = 0x6070000b03d0 "cP", ber_end = 0x6070000b041e "", ber_sos_ptr = 0x0, ber_rwptr = 0x0, ber_memctx = 0x0} (gdb) up #5 0x00007fffee310c91 in try_read1msg (result=0x7fffd6ff6348, lc=0x6080001182a0, all=1, msgid=18, ld=0x6040000aa610) at result.c:494 494 tag = ber_get_next( lc->lconn_sb, &len, ber ); (gdb) up #6 wait4msg (result=0x7fffd6ff6348, timeout=<optimized out>, all=1, msgid=<optimized out>, ld=0x6040000aa610) at result.c:365 365 rc = try_read1msg( ld, msgid, all, lc, result ); (gdb) #7 ldap_result (ld=ld@entry=0x6040000aa610, msgid=<optimized out>, all=all@entry=1, timeout=timeout@entry=0x0, result=result@entry=0x7fffd6ff6348) at result.c:120 120 rc = wait4msg( ld, msgid, all, timeout, result ); (gdb) p result $3 = (LDAPMessage **) 0x7fffd6ff6348 (gdb) p result[0] $4 = (LDAPMessage *) 0x0 (gdb) dow #6 wait4msg (result=0x7fffd6ff6348, timeout=<optimized out>, all=1, msgid=<optimized out>, ld=0x6040000aa610) at result.c:365 365 rc = try_read1msg( ld, msgid, all, lc, result ); (gdb) dow #5 0x00007fffee310c91 in try_read1msg (result=0x7fffd6ff6348, lc=0x6080001182a0, all=1, msgid=18, ld=0x6040000aa610) at result.c:494 494 tag = ber_get_next( lc->lconn_sb, &len, ber ); (gdb) p ber $5 = <optimized out> (gdb) dow #4 0x00007fffee0f48a1 in ber_get_next (sb=0x6040000aa650, len=len@entry=0x7fffd6ff61c8, ber=ber@entry=0x6070000b0360) at io.c:514 514 assert( ber->ber_buf == NULL ); (gdb) l 509 * 510 * We expect tag and len to be at most 32 bits wide. 511 */ 512 513 if (ber->ber_rwptr == NULL) { 514 assert( ber->ber_buf == NULL ); 515 ber->ber_rwptr = (char *) &ber->ber_len-1; 516 ber->ber_ptr = ber->ber_rwptr; 517 ber->ber_tag = 0; 518 } (gdb) p ber $6 = (BerElement *) 0x6070000b0360 (gdb) p ber[0] $7 = {ber_opts = {lbo_valid = 2, lbo_options = 1, lbo_debug = 0}, ber_tag = 116, ber_len = 78, ber_usertag = 0, ber_buf = 0x6070000b03d0 "cP", ber_ptr = 0x6070000b03d0 "cP", ber_end = 0x6070000b041e "", ber_sos_ptr = 0x0, ber_rwptr = 0x0, ber_memctx = 0x0} (gdb) p ber->ber_buf $8 = 0x6070000b03d0 "cP" (gdb) up #5 0x00007fffee310c91 in try_read1msg (result=0x7fffd6ff6348, lc=0x6080001182a0, all=1, msgid=18, ld=0x6040000aa610) at result.c:494 494 tag = ber_get_next( lc->lconn_sb, &len, ber ); (gdb) p len $10 = 99 (gdb) p lc $11 = (LDAPConn *) 0x6080001182a0 ```
https://bugs.openldap.org/show_bug.cgi?id=9803
--- Comment #1 from Howard Chu hyc@openldap.org --- 2.4.46 is 4 years old; the 2.4 release stream is no longer supported. If you can reproduce this in the current OpenLDAP 2.6 release we may investigate it. Otherwise this ticket will be closed.
https://bugs.openldap.org/show_bug.cgi?id=9803
--- Comment #2 from jengelh@inai.de jengelh@inai.de --- I have reproduced it with the current master, 73e882c87ff7a9e822b2ccc737faeb91250f345f. (Considering that io.c did not really change since 2.4.46, this was expected.)
#0 0x00007ffff4d2b18b in raise () from /lib64/libc.so.6 #1 0x00007ffff4d2c585 in abort () from /lib64/libc.so.6 #2 0x00007ffff4d2385a in __assert_fail_base () from /lib64/libc.so.6 #3 0x00007ffff4d238d2 in __assert_fail () from /lib64/libc.so.6 #4 0x00007ffff3a72551 in ber_get_next (sb=0x7fff60006d50, len=len@entry=0x7fffc71330b8, ber=ber@entry=0x7fff8c004bf0) at io.c:517 #5 0x00007ffff3c8f6d1 in try_read1msg (result=0x7fffc7133250, lc=0x7fff60032750, all=1, msgid=6, ld=0x7fff60032110) at result.c:499 #6 wait4msg (result=0x7fffc7133250, timeout=<optimized out>, all=1, msgid=<optimized out>, ld=0x7fff60032110) at result.c:369 #7 ldap_result (ld=ld@entry=0x7fff60032110, msgid=<optimized out>, all=all@entry=1, timeout=timeout@entry=0x0, result=result@entry=0x7fffc7133250) at result.c:120 #8 0x00007ffff3c97d48 in ldap_sasl_bind_s (ld=0x7fff60032110, dn=<optimized out>, mechanism=0x0, cred=<optimized out>, sctrls=<optimized out>, cctrls=<optimized out>, servercredp=0x0) at sasl.c:210
What I happen to observe now is that this is the second ldap_sasl_bind_s on an LDAP connection in a row; the first attempt ended with LDAP_LOCAL_ERROR.
https://bugs.openldap.org/show_bug.cgi?id=9803
--- Comment #3 from Howard Chu hyc@openldap.org --- Since you're able to reproduce it, please provide the exact sequence of API calls used, along with their parameters.
Note that this is likely a WONTFIX, as getting a LOCAL_ERROR means you've misused something in the API.
https://bugs.openldap.org/show_bug.cgi?id=9803
--- Comment #4 from Quanah Gibson-Mount quanah@openldap.org --- Please generate logs with the LDAP DEBUG LEVEL set to "all" on the client side reproducing the issue and attach them here. Make sure to use a dummy account + dummy password.
https://bugs.openldap.org/show_bug.cgi?id=9803
--- Comment #5 from jengelh@inai.de jengelh@inai.de --- Created attachment 879 --> https://bugs.openldap.org/attachment.cgi?id=879&action=edit testcase
# g++ t.cpp -Wall -O0 -ggdb3 -std=gnu++17 -lldap -lpthread && ./a.out 6217 searches 6221 searches ret -2 a.out: io.c:514: ber_get_next: Assertion `ber->ber_buf == NULL' failed. Aborted (core dumped)
I don't see an immediate API misuse, so maybe this is a race/threading issue. The ldap_debug outputs text, but not all lines contain "ld 0x" to tell which thread it comes from.
ldap_search_ext put_filter: "mail=xx" put_filter: default put_simple_filter: "mail=xx" ldap_build_search_req ATTRS: ldap_send_initial_request ldap_send_server_request ldap_result ld 0x7fff8c003ef0 msgid 7 wait4msg ld 0x7fff8c003ef0 msgid 7 (infinite timeout) wait4msg continue ld 0x7fff8c003ef0 msgid 7 all 1 ** ld 0x7fff8c003ef0 Connections: * host: x1 port: 389 (default) * from: IP=192.168.129.200:60382 refcnt: 2 status: Connected last used: Fri Mar 4 00:00:18 2022
** ld 0x7fff8c003ef0 Outstanding Requests: * msgid 7, origid 7, status InProgress outstanding referrals 0, parent count 0 ld 0x7fff8c003ef0 request count 1 (abandoned 0) ** ld 0x7fff8c003ef0 Response Queue: Empty ld 0x7fff8c003ef0 response count 0 ldap_chkResponseList ld 0x7fff8c003ef0 msgid 7 all 1 ldap_chkResponseList returns ld 0x7fff8c003ef0 NULL ldap_int_select read1msg: ld 0x7fff8c003ef0 msgid 7 all 1 wait4msg continue ld 0x7fff8c003ef0 msgid 7 all 1 ** ld 0x7fff8c003ef0 Connections: * host: x1 port: 389 (default) * from: IP=192.168.129.200:60382 refcnt: 2 status: Connected last used: Fri Mar 4 00:00:18 2022
** ld 0x7fff8c003ef0 Outstanding Requests: * msgid 7, origid 7, status InProgress outstanding referrals 0, parent count 0 ld 0x7fff8c003ef0 request count 1 (abandoned 0) ** ld 0x7fff8c003ef0 Response Queue: Empty ld 0x7fff8c003ef0 response count 0 ldap_chkResponseList ld 0x7fff8c003ef0 msgid 7 all 1 ldap_chkResponseList returns ld 0x7fff8c003ef0 NULL ldap_int_select read1msg: ld 0x7fff8c003ef0 msgid 7 all 1 (ret=-2 occurring)
https://bugs.openldap.org/show_bug.cgi?id=9803
jengelh@inai.de jengelh@inai.de changed:
What |Removed |Added ---------------------------------------------------------------------------- Version|2.4.46 |2.6.1
https://bugs.openldap.org/show_bug.cgi?id=9803
--- Comment #6 from Ondřej Kuzník ondra@mistotebe.net --- On Fri, Mar 04, 2022 at 02:37:03AM +0000, openldap-its@openldap.org wrote:
read1msg: ld 0x7fff8c003ef0 msgid 7 all 1 (ret=-2 occurring)
Are you sure the server is responding with a valid LDAP message? If this[0] branch is taken, I could see lc->lconn_ber not being cleared which might lead to the assert you're talking about.
If that's the case, you can check that putting ber_free( ber, 1 ); lc->lconn_ber = NULL; at that point should make the assert go away.
[0]. https://git.openldap.org/openldap/openldap/-/blob/master/libraries/libldap/r...
https://bugs.openldap.org/show_bug.cgi?id=9803
--- Comment #7 from jengelh@inai.de jengelh@inai.de --- (In reply to Ondřej Kuzník from comment #6)
Are you sure the server is responding with a valid LDAP message?
Not at all. It's some Novell eDirectory, and for all I know, it could be sending junk every now and then due bugs of its own.
If that's the case, you can check that putting ber_free( ber, 1 ); lc->lconn_ber = NULL; at that point should make the assert go away.
Looks good so far, I have not seen SIGABRT occurring in a while with these two lines.
https://bugs.openldap.org/show_bug.cgi?id=9803
Ondřej Kuzník ondra@mistotebe.net changed:
What |Removed |Added ---------------------------------------------------------------------------- Status|UNCONFIRMED |IN_PROGRESS Ever confirmed|0 |1 Assignee|bugs@openldap.org |ondra@mistotebe.net
--- Comment #8 from Ondřej Kuzník ondra@mistotebe.net --- https://git.openldap.org/openldap/openldap/-/merge_requests/501
https://bugs.openldap.org/show_bug.cgi?id=9803
Quanah Gibson-Mount quanah@openldap.org changed:
What |Removed |Added ---------------------------------------------------------------------------- Target Milestone|--- |2.5.12
https://bugs.openldap.org/show_bug.cgi?id=9803
Quanah Gibson-Mount quanah@openldap.org changed:
What |Removed |Added ---------------------------------------------------------------------------- Keywords|needs_review |
https://bugs.openldap.org/show_bug.cgi?id=9803
--- Comment #9 from Quanah Gibson-Mount quanah@openldap.org --- head:
• e8813b12 by Ondřej Kuzník at 2022-03-08T17:28:05+00:00 ITS#9803 Drop connection when receiving non-LDAP data
https://bugs.openldap.org/show_bug.cgi?id=9803
--- Comment #10 from Quanah Gibson-Mount quanah@openldap.org --- RE26:
• 214c1f2d by Ondřej Kuzník at 2022-03-21T16:38:59+00:00 ITS#9803 Drop connection when receiving non-LDAP data
RE25:
• 082ba67a by Ondřej Kuzník at 2022-03-21T16:46:31+00:00 ITS#9803 Drop connection when receiving non-LDAP data
https://bugs.openldap.org/show_bug.cgi?id=9803
Quanah Gibson-Mount quanah@openldap.org changed:
What |Removed |Added ---------------------------------------------------------------------------- Resolution|--- |FIXED Status|IN_PROGRESS |RESOLVED
https://bugs.openldap.org/show_bug.cgi?id=9803
Quanah Gibson-Mount quanah@openldap.org changed:
What |Removed |Added ---------------------------------------------------------------------------- Status|RESOLVED |VERIFIED