Discussion:
ldapd(8) hangs when receiving large data
Seiya Kawashima
2017-02-18 02:11:32 UTC
Permalink
Synopsis: ldapd(8) hangs when receiving large data
Category: system
System : OpenBSD 6.0
Details : OpenBSD 6.0-current (GENERIC.MP) #0: Thu Feb 16 19:58:50 CST 2017
***@amd64.openbsd.org:/usr/src/sys/arch/amd64/compile/GENERIC.MP

Architecture: OpenBSD.amd64
Machine : amd64
Hi,

Thank you for your time to look at this bug report.

ldapd(8) hangs when it receives partial LDAPMessages due to the message
sizes. conn_read() in /ldapd/conn.c is supposed to be called to read
partial LDAPMessages by libevent until it receives complete LDAPMessages
. In theory, conn_read() is called by libevent whenever data for reading
is available. However, it doesn't work this way. What happens is that
conn_read() is called once and nothing happens any further. As the
result, ldapd(8) hangs. It seemed to me that ldapd(8) was waiting for
more data from ldapadd as expected but ldapadd was also waiting for
something to send the rest of the data to ldapd(8). So ldapadd was the
one that didn't send the rest of the data to ldapd(8). To prove this
point, once I killed ldapadd while they were hanging, ldapd(8) started
receiving the rest of the data and stored the data without hanging at
this time. ldapd(8) can't simply wait for more data to read but needs
to do something to let ldapadd keep sending the rest of the data. I
found a fix for this issue but I've not yet found any references about
the fix on RFCs 4511, 4513 and 4514 and the source code at
https://github.com/openldap/openldap so unfortunately I'm not quite sure
if this one would be the right fix. The fix came from my experiments.

Thank you
Seiya
1. Make ldapadd work with self signed certificates for this bug. Please
use the content below for your ~/.ldaprc, otherwise ldapadd would not
work with self signed certificates.

# This is a LDAP client configuration file.
URI ldap:// ldaps://
TLS_REQCERT allow

2. Generate a self signed certificate for this bug. Please type the
command, starttls(8) below to generate a self signed certificate.
Please change the interface, re0 for your environment.

openssl genrsa -out /etc/ldap/certs/re0.key 4096
openssl req -x509 -new -key /etc/ldap/certs/re0.key \
-out /etc/ldap/certs/re0.crt -days 365

3. Set up a simple /etc/ldapd.conf. Please use the content below for
your /etc/ldapd.conf.

schema "/etc/ldap/core.schema"
schema "/etc/ldap/inetorgperson.schema"
schema "/etc/ldap/nis.schema"

# Please change the interface accordingly for your environment.
listen on re0 ldaps

namespace "dc=example,dc=com" {
rootdn "cn=admin,dc=example,dc=com"
rootpw "secret"
index objectClass
index cn
index ou
index uid
index uidNumber
index gidNumber
index mail
index sn
deny access to any by any
allow bind access to children of "ou=people,dc=example,dc=com" by any
allow read access to any by self
allow write access to any by self
}

4. Type the command below to run ldapd(8) in verbose debug mode.

/usr/sbin/ldapd -vv -d

5. Create a simple DIT via ldapadd. Please type the command like below
and adjust the values for -H and -f flags accordingly for your
environment.

ldapadd -vv -H ldaps://192.168.0.118 -x -D "cn=admin,dc=example,dc=com" \
-w secret -f ./sample-1-people-create.txt

Please use the content below as an LDIF file to reproduce the issue.

## This LDIF is from http://www.zytrax.com/books/ldap/ch5/index.html#step1-ldif
## DEFINE DIT ROOT/BASE/SUFFIX ####
## uses RFC 2377 format
## replace example and com as necessary below
## or for experimentation leave as is

## dcObject is an AUXILLIARY objectclass and MUST
## have a STRUCTURAL objectclass (organization in this case)
## this is an ENTRY sequence and is preceded by a BLANK line

dn: dc=example,dc=com
dc: example
description: My wonderful company as much text as you want to place
in this line up to 32K continuation data for the line above must
have <CR> or <CR><LF> i.e. ENTER works
on both Windows and *nix system - new line MUST begin with ONE SPACE
objectClass: dcObject
objectClass: organization
o: Example, Inc.

## FIRST Level hierarchy - people
## uses mixed upper and lower case for objectclass
## this is an ENTRY sequence and is preceded by a BLANK line

dn: ou=people, dc=example,dc=com
ou: people
description: All people in organisation
objectclass: organizationalunit

6. Add a person as inetOrgPerson objectClass under ou=people specifying
a file for the person's jpegPhoto attribute. Please type the command
below to add the person. Also please specify a large enough file for
the jpegPhoto attribute so that conn_read() in /ldapd/conn.c needs to
be called multiple times to get a complete LDAPMessage. If it's
successful at the first time, try it a couple of more times. You will
be able to see the hang. Please adjust the values for -H and -f flags
accordingly for your environment.

ldapadd -vv -H ldaps://192.168.0.118 -x -D "cn=admin,dc=example,dc=com" \
-w secret -f ./sample-1-people-add.txt

Please use the content below as an LDIF file to make ldapd(8) and
ldapadd hang.

dn: cn=Robert Smith,ou=people,dc=example,dc=com
objectclass: inetOrgPerson
cn: Robert Smith
cn: Robert J Smith
cn: bob smith
sn: smith
uid: rjsmith
## Please specify a file that would cause conn_read() to be called
## multiple times. I tried around 2KB, 3KB, 5KB and 13KB files for
## jpegPhoto attribute.
jpegPhoto:< file:///home/seiyak/Documents/samples/LDAP/sample.jpeg
userpassword: rJsmitH
carlicense: HISCAR 123
homephone: 555-111-2222
mail: ***@example.com
mail: ***@example.com
mail: ***@example.com
description: swell guy
ou: Human Resources

This is the output when the hang happens on ldapd(8).

Feb 17 04:01:28.030 [79095] accepted connection from 192.168.0.115 on fd 12
Feb 17 04:01:28.030 [79095] conn_tls_init: switching to TLS
Feb 17 04:01:28.062 [79095] consumed 46 bytes
Feb 17 04:01:28.062 [79095] received request on fd 12
len 44 class: universal(0) type: sequence(16) encoding 16
len 1 class: universal(0) type: integer(2) encoding 2 value 1
len 39 class: application(1) type: bind(0) encoding 16
len 1 class: universal(0) type: integer(2) encoding 2 value 3
len 26 class: universal(0) type: octet-string(4) encoding 4 string "cn=admin,dc=example,dc=com"
len 6 class: context(2) type: auth simple(0) encoding 4 string "secret"
Feb 17 04:01:28.062 [79095] got request type 0, id 1
Feb 17 04:01:28.062 [79095] bind dn = cn=admin,dc=example,dc=com
Feb 17 04:01:28.062 [79095] successfully authenticated as cn=admin,dc=example,dc=com
Feb 17 04:01:28.062 [79095] sending response 1 with result 0
Feb 17 04:01:28.062 [79095] sending response on fd 12
len 12 class: universal(0) type: sequence(16) encoding 16
len 1 class: universal(0) type: integer(2) encoding 2 value 1
len 7 class: application(1) type: bind(1) encoding 16
len 1 class: universal(0) type: enumerated(10) encoding 10 value 0
len 0 class: universal(0) type: octet-string(4) encoding 4 string ""
len 0 class: universal(0) type: octet-string(4) encoding 4 string ""
# ldapd(8) hangs here and no more output is produced until I kill ladpadd.

This is the output when the hang happens on ldapadd.

ldap_initialize( ldaps://192.168.0.118:636/??base )
add objectclass:
inetOrgPerson
add cn:
Robert Smith
Robert J Smith
bob smith
add sn:
smith
add uid:
rjsmith
add jpegPhoto:
NOT ASCII (2568 bytes)
add userpassword:
rJsmitH
add carlicense:
HISCAR 123
add homephone:
555-111-2222
add mail:
***@example.com
***@example.com
***@example.com
add description:
swell guy
add ou:
Human Resources
adding new entry "cn=Robert Smith,ou=people,dc=example,dc=com"
# ldapadd hangs here and no more output is produced. Once I kill
# ldapadd, the rest of the data is sent to ldapd(8) and it can
# process the complete LDAPMessage escaping from the hang.

The code from /ldapd/ber.c below is where ldapd(8) tries to read
complete LDAPMessages calling conn_read() multiple times. You might
want to put a debug message to show r and totlen before line 1102 on
/ldapd/ber.c to see how many bytes are currently available and how
many more bytes need to be read for a complete LDAPMessage.

1095 DPRINTF("ber read element size %zd\n", len);
1096 totlen += r + len;
1097
1098 /* If using an external buffer and the total size of the element
1099 * is larger then the external buffer don't bother to continue. */
1100 if (ber->fd == -1 && len > ber->br_rend - ber->br_rptr) {
1101 errno = ECANCELED;
1102 return -1;
1103 }
Based on my experiments, ldapd(8) needs to send a response via
send_result_ldap() or send_ldap_extended_response() in /ldapd/ldape.c
every time ldapd(8) reads partial LDAPMessages. For this purpose, I
modified ber_read_elements() and ber_read_element() in /ldapd/ber.c,
conn_dispatch() in /ldapd/conn.c and copied send_ldap_extended_response()
as send_ldap_extended_response2() in /ldapd/conn.c. Please take a look
at the diffs below. Once the fix is in place, please recompile ldapd(8)
and return ldapd(8) and ldapadd. At this time, no hang happens. Please
type the command below to search and verify the value for the jpegPhoto
attribute. Please also adjust the values for -H flag and
ldapsearch-jpegPhoto-HO0LQD accordingly for your environment.

ldapsearch -tt -T ./ -LLL -H ldaps://192.168.0.118 -x -D "cn=admin,dc=example,dc=com" \
-w secret -b "cn=Robert Smith,ou=people,dc=example,dc=com" jpegPhoto
openssl dgst -sha1 ldapsearch-jpegPhoto-HO0LQD
openssl dgst -sha1 /home/seiyak/Documents/samples/LDAP/sample.jpeg

Index: ber.c
===================================================================
RCS file: /cvs/src/usr.sbin/ldapd/ber.c,v
retrieving revision 1.12
diff -u -p -r1.12 ber.c
--- ber.c 11 Feb 2017 20:40:03 -0000 1.12
+++ ber.c 18 Feb 2017 01:36:05 -0000
@@ -815,12 +815,13 @@ ber_read_elements(struct ber *ber, struc

DPRINTF("read ber elements, root %p\n", root);

- if (ber_read_element(ber, root) == -1) {
- /* Cleanup if root was allocated by us */
- if (elm == NULL)
- ber_free_elements(root);
- return NULL;
- }
+ /* ber elements might be spread over multiple buffers. In such a case,
+ * parsing ber fails since it's a partial message but the caller still
+ * needs to send a response to the client. Otherwise a hang would
+ * occur. the caller needs to free root no matter parsing ber is
+ * succeesful or not.
+ */
+ ber_read_element(ber, root);

return root;
}
@@ -1081,7 +1082,7 @@ ber_read_element(struct ber *ber, struct
long long val = 0;
struct ber_element *next;
unsigned long type;
- int i, class, cstruct;
+ int i, class, cstruct, err = -1;
ssize_t len, r, totlen = 0;
u_char c;

@@ -1098,8 +1099,10 @@ ber_read_element(struct ber *ber, struct
/* If using an external buffer and the total size of the element
* is larger then the external buffer don't bother to continue. */
if (ber->fd == -1 && len > ber->br_rend - ber->br_rptr) {
+ /* Keep working on partial message. */
errno = ECANCELED;
- return -1;
+ len = ber->br_rend - ber->br_rptr;
+ err = 0;
}

elm->be_type = type;
@@ -1186,6 +1189,12 @@ ber_read_element(struct ber *ber, struct
next = next->be_next;
}
break;
+ }
+
+ if(err == 0){
+ /* Let the caller know it's a partial message. */
+ errno = ECANCELED;
+ totlen = -1;
}
return totlen;
}
Index: conn.c
===================================================================
RCS file: /cvs/src/usr.sbin/ldapd/conn.c,v
retrieving revision 1.14
diff -u -p -r1.14 conn.c
--- conn.c 20 Jan 2017 11:55:08 -0000 1.14
+++ conn.c 18 Feb 2017 01:36:05 -0000
@@ -29,6 +29,11 @@
int conn_dispatch(struct conn *conn);
int conn_tls_init(struct conn *);
unsigned long ldap_application(struct ber_element *elm);
+/* Copied from /ldapd/ldape.c and renamed to send_ldap_extended_response2(). */
+void send_ldap_extended_response2(struct conn *conn,
+ int msgid, unsigned long type,
+ long long result_code,
+ const char *extended_oid);

struct conn_list conn_list;

@@ -137,10 +142,53 @@ request_dispatch(struct request *req)
}
}

+/* Copied from /ldapd/ldape.c and renamed to send_ldap_extended_response2().
+ */
+void
+send_ldap_extended_response2(struct conn *conn, int msgid, unsigned long type,
+ long long result_code, const char *extended_oid)
+{
+ int rc;
+ struct ber_element *root, *elm;
+ void *buf;
+
+ log_debug("sending response %u with result %lld", type, result_code);
+
+ if ((root = ber_add_sequence(NULL)) == NULL)
+ goto fail;
+
+ elm = ber_printf_elements(root, "d{tEss",
+ msgid, BER_CLASS_APP, type, result_code, "", "");
+ if (elm == NULL)
+ goto fail;
+
+ if (extended_oid)
+ if (ber_add_string(elm, extended_oid) == NULL)
+ goto fail;
+
+ ldap_debug_elements(root, type, "sending response on fd %d", conn->fd);
+
+ rc = ber_write_elements(&conn->ber, root);
+ ber_free_elements(root);
+
+ if (rc < 0)
+ log_warn("failed to create ldap result");
+ else {
+ ber_get_writebuf(&conn->ber, &buf);
+ if (bufferevent_write(conn->bev, buf, rc) != 0)
+ log_warn("failed to send ldap result");
+ }
+
+ return;
+fail:
+ if (root)
+ ber_free_elements(root);
+}
+
int
conn_dispatch(struct conn *conn)
{
- int class;
+ int class, err;
struct request *req;
u_char *rptr;

@@ -155,18 +203,9 @@ conn_dispatch(struct conn *conn)
req->conn = conn;
rptr = conn->ber.br_rptr; /* save where we start reading */

- if ((req->root = ber_read_elements(&conn->ber, NULL)) == NULL) {
- if (errno != ECANCELED) {
- log_warnx("protocol error");
- hexdump(rptr, conn->ber.br_rend - rptr,
- "failed to parse request from %zi bytes:",
- conn->ber.br_rend - rptr);
- conn_disconnect(conn);
- }
- request_free(req);
- return -1;
- }
- log_debug("consumed %d bytes", conn->ber.br_rptr - rptr);
+ req->root = ber_read_elements(&conn->ber, NULL);
+ /* Store errno from ber_read_elements(). */
+ err = errno;

/* Read message id and request type.
*/
@@ -179,6 +218,19 @@ conn_dispatch(struct conn *conn)
request_free(req);
return -1;
}
+
+ if(err == ECANCELED){
+ /* Let LDAP client keep sending leftover data to ldapd.
+ * Need to respond to each partial LDAPMessage, otherwise
+ * the client would not send the rest of the message.
+ */
+ send_ldap_extended_response2(conn, req->msgid, req->type + 1,
+ LDAP_SUCCESS, NULL);
+ request_free(req);
+ return -1;
+ }
+
+ log_debug("consumed %d bytes", conn->ber.br_rptr - rptr);

ldap_debug_elements(req->root, req->type,
"received request on fd %d", conn->fd);

dmesg:
OpenBSD 6.0-current (GENERIC.MP) #0: Thu Feb 16 19:58:50 CST 2017
***@amd64.openbsd.org:/usr/src/sys/arch/amd64/compile/GENERIC.MP
real mem = 4152004608 (3959MB)
avail mem = 4021501952 (3835MB)
mpath0 at root
scsibus0 at mpath0: 256 targets
mainbus0 at root
bios0 at mainbus0: SMBIOS rev. 2.8 @ 0xebe20 (44 entries)
bios0: vendor AMI version "80.06" date 04/11/2014
bios0: Hewlett-Packard HP 200 G1 MT
acpi0 at bios0: rev 2
acpi0: sleep states S0 S3 S4 S5
acpi0: tables DSDT FACP APIC FPDT MSDM MCFG LPIT SLIC HPET SSDT SSDT SSDT UEFI DBGP
acpi0: wakeup devices XHC1(S4) PXSX(S4) PXSX(S4) PXSX(S4) PXSX(S4) PWRB(S0)
acpitimer0 at acpi0: 3579545 Hz, 24 bits
acpimadt0 at acpi0 addr 0xfee00000: PC-AT compat
cpu0 at mainbus0: apid 0 (boot processor)
cpu0: Intel(R) Pentium(R) CPU J2850 @ 2.41GHz, 2417.21 MHz
cpu0: FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CFLUSH,DS,ACPI,MMX,FXSR,SSE,SSE2,SS,HTT,TM,PBE,SSE3,PCLMUL,DTES64,MWAIT,DS-CPL,VMX,EST,TM2,SSSE3,CX16,xTPR,PDCM,SSE4.1,SSE4.2,MOVBE,POPCNT,DEADLINE,RDRAND,NXE,LONG,LAHF,3DNOWP,PERF,ITSC,SMEP,ERMS,SENSOR,ARAT
cpu0: 1MB 64b/line 16-way L2 cache
cpu0: TSC frequency 2417213510 Hz
cpu0: smt 0, core 0, package 0
mtrr: Pentium Pro MTRR support, 8 var ranges, 88 fixed ranges
cpu0: apic clock running at 83MHz
cpu0: mwait min=64, max=64, C-substates=0.2.0.0.0.0.3.3, IBE
cpu1 at mainbus0: apid 2 (application processor)
cpu1: Intel(R) Pentium(R) CPU J2850 @ 2.41GHz, 2416.67 MHz
cpu1: FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CFLUSH,DS,ACPI,MMX,FXSR,SSE,SSE2,SS,HTT,TM,PBE,SSE3,PCLMUL,DTES64,MWAIT,DS-CPL,VMX,EST,TM2,SSSE3,CX16,xTPR,PDCM,SSE4.1,SSE4.2,MOVBE,POPCNT,DEADLINE,RDRAND,NXE,LONG,LAHF,3DNOWP,PERF,ITSC,SMEP,ERMS,SENSOR,ARAT
cpu1: 1MB 64b/line 16-way L2 cache
cpu1: smt 0, core 1, package 0
cpu2 at mainbus0: apid 4 (application processor)
cpu2: Intel(R) Pentium(R) CPU J2850 @ 2.41GHz, 2416.67 MHz
cpu2: FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CFLUSH,DS,ACPI,MMX,FXSR,SSE,SSE2,SS,HTT,TM,PBE,SSE3,PCLMUL,DTES64,MWAIT,DS-CPL,VMX,EST,TM2,SSSE3,CX16,xTPR,PDCM,SSE4.1,SSE4.2,MOVBE,POPCNT,DEADLINE,RDRAND,NXE,LONG,LAHF,3DNOWP,PERF,ITSC,SMEP,ERMS,SENSOR,ARAT
cpu2: 1MB 64b/line 16-way L2 cache
cpu2: smt 0, core 2, package 0
cpu3 at mainbus0: apid 6 (application processor)
cpu3: Intel(R) Pentium(R) CPU J2850 @ 2.41GHz, 2416.67 MHz
cpu3: FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CFLUSH,DS,ACPI,MMX,FXSR,SSE,SSE2,SS,HTT,TM,PBE,SSE3,PCLMUL,DTES64,MWAIT,DS-CPL,VMX,EST,TM2,SSSE3,CX16,xTPR,PDCM,SSE4.1,SSE4.2,MOVBE,POPCNT,DEADLINE,RDRAND,NXE,LONG,LAHF,3DNOWP,PERF,ITSC,SMEP,ERMS,SENSOR,ARAT
cpu3: 1MB 64b/line 16-way L2 cache
cpu3: smt 0, core 3, package 0
ioapic0 at mainbus0: apid 1 pa 0xfec00000, version 20, 87 pins
acpimadt0: bogus nmi for apid 0
acpimadt0: bogus nmi for apid 4
acpimadt0: bogus nmi for apid 6
acpimcfg0 at acpi0 addr 0xe0000000, bus 0-255
acpihpet0 at acpi0: 14318179 Hz
acpiprt0 at acpi0: bus 0 (PCI0)
acpiprt1 at acpi0: bus 1 (RP01)
acpiprt2 at acpi0: bus -1 (ITPC)
acpiprt3 at acpi0: bus 3 (RP02)
acpiprt4 at acpi0: bus 4 (RP03)
acpiprt5 at acpi0: bus 9 (RP04)
acpiec0 at acpi0: not present
acpicpu0 at acpi0: C1(***@1 mwait.1), PSS
acpicpu1 at acpi0: C1(***@1 mwait.1), PSS
acpicpu2 at acpi0: C1(***@1 mwait.1), PSS
acpicpu3 at acpi0: C1(***@1 mwait.1), PSS
acpipwrres0 at acpi0: PLPE
acpipwrres1 at acpi0: PLPE
acpipwrres2 at acpi0: USBC, resource for EHC1, OTG1
acpipwrres3 at acpi0: FN00, resource for FAN0
acpitz0 at acpi0: critical temperature is 90 degC
"PNP0501" at acpi0 not configured
"DMA0F28" at acpi0 not configured
acpibtn0 at acpi0: PWRB
acpibtn1 at acpi0: SLPB
"PNP0C14" at acpi0 not configured
"PNP0C0B" at acpi0 not configured
acpivideo0 at acpi0: GFX0
cpu0: Enhanced SpeedStep 2417 MHz: speeds: 2407, 2324, 2241, 2158, 2075, 1992, 1909, 1826, 1743, 1660, 1577, 1494, 1411, 1328 MHz
pci0 at mainbus0 bus 0
pchb0 at pci0 dev 0 function 0 "Intel Bay Trail Host" rev 0x0a
inteldrm0 at pci0 dev 2 function 0 "Intel Bay Trail Video" rev 0x0a
drm0 at inteldrm0
inteldrm0: msi
inteldrm0: 1024x768, 32bpp
wsdisplay0 at inteldrm0 mux 1: console (std, vt100 emulation)
wsdisplay0: screen 1-5 added (std, vt100 emulation)
ahci0 at pci0 dev 19 function 0 "Intel Bay Trail AHCI" rev 0x0a: msi, AHCI 1.3
ahci0: port 0: 3.0Gb/s
ahci0: port 1: 1.5Gb/s
scsibus1 at ahci0: 32 targets
sd0 at scsibus1 targ 0 lun 0: <ATA, TOSHIBA DT01ACA0, MS1O> SCSI3 0/direct fixed naa.5000039ffcc7f26b
sd0: 476940MB, 512 bytes/sector, 976773168 sectors
cd0 at scsibus1 targ 1 lun 0: <hp, DVD-RAM GHB0N, RK03> ATAPI 5/cdrom removable
xhci0 at pci0 dev 20 function 0 "Intel Bay Trail xHCI" rev 0x0a: msi
usb0 at xhci0: USB revision 3.0
uhub0 at usb0 configuration 1 interface 0 "Intel xHCI root hub" rev 3.00/1.00 addr 1
"Intel Bay Trail TXE" rev 0x0a at pci0 dev 26 function 0 not configured
azalia0 at pci0 dev 27 function 0 "Intel Bay Trail HD Audio" rev 0x0a: msi
azalia0: codecs: Realtek ALC221, Intel/0x2882, using Realtek ALC221
audio0 at azalia0
ppb0 at pci0 dev 28 function 0 "Intel Bay Trail I2C" rev 0x0a: msi
pci1 at ppb0 bus 1
ppb1 at pci1 dev 0 function 0 "ITExpress IT8893E PCIE-PCI" rev 0x52
pci2 at ppb1 bus 2
re0 at pci2 dev 0 function 0 "D-Link DGE-528T" rev 0x10: RTL8169/8110SB (0x1000), apic 1 int 16, address 1c:7e:e5:2a:a0:50
rgephy0 at re0 phy 7: RTL8169S/8110S/8211 PHY, rev. 3
ppb2 at pci0 dev 28 function 1 "Intel Bay Trail PCIE" rev 0x0a: msi
pci3 at ppb2 bus 3
re1 at pci3 dev 0 function 0 "Realtek 8168" rev 0x0c: RTL8168G/8111G (0x4c00), msi, address 10:60:4b:91:85:83
rgephy1 at re1 phy 7: RTL8251 PHY, rev. 0
ppb3 at pci0 dev 28 function 2 "Intel Bay Trail PCIE" rev 0x0a: msi
pci4 at ppb3 bus 4
ppb4 at pci4 dev 0 function 0 "TI XIO3130 PCIE-PCIE upstream" rev 0x02
pci5 at ppb4 bus 5
ppb5 at pci5 dev 0 function 0 "TI XIO3130 PCIE-PCIE downstream" rev 0x02
pci6 at ppb5 bus 6
re2 at pci6 dev 0 function 0 "Realtek 8168" rev 0x06: RTL8168E/8111E (0x2c00), msi, address 00:e0:4c:80:62:93
rgephy2 at re2 phy 7: RTL8169S/8110S/8211 PHY, rev. 4
ppb6 at pci5 dev 1 function 0 "TI XIO3130 PCIE-PCIE downstream" rev 0x02
pci7 at ppb6 bus 7
re3 at pci7 dev 0 function 0 "Realtek 8168" rev 0x06: RTL8168E/8111E (0x2c00), msi, address 00:e0:4c:80:62:94
rgephy3 at re3 phy 7: RTL8169S/8110S/8211 PHY, rev. 4
ppb7 at pci5 dev 2 function 0 "TI XIO3130 PCIE-PCIE downstream" rev 0x02
pci8 at ppb7 bus 8
ppb8 at pci0 dev 28 function 3 "Intel Bay Trail PCIE" rev 0x0a: msi
pci9 at ppb8 bus 9
ppb9 at pci9 dev 0 function 0 "TI XIO3130 PCIE-PCIE upstream" rev 0x02
pci10 at ppb9 bus 10
ppb10 at pci10 dev 0 function 0 "TI XIO3130 PCIE-PCIE downstream" rev 0x02
pci11 at ppb10 bus 11
re4 at pci11 dev 0 function 0 "Realtek 8168" rev 0x06: RTL8168E/8111E (0x2c00), msi, address 00:e0:4c:80:59:28
rgephy4 at re4 phy 7: RTL8169S/8110S/8211 PHY, rev. 4
ppb11 at pci10 dev 1 function 0 "TI XIO3130 PCIE-PCIE downstream" rev 0x02
pci12 at ppb11 bus 12
re5 at pci12 dev 0 function 0 "Realtek 8168" rev 0x06: RTL8168E/8111E (0x2c00), msi, address 00:e0:4c:80:59:29
rgephy5 at re5 phy 7: RTL8169S/8110S/8211 PHY, rev. 4
ppb12 at pci10 dev 2 function 0 "TI XIO3130 PCIE-PCIE downstream" rev 0x02
pci13 at ppb12 bus 13
ehci0 at pci0 dev 29 function 0 "Intel Bay Trail EHCI" rev 0x0a: apic 1 int 23
ehci0: halt timeout
usb1 at ehci0: USB revision 2.0
uhub1 at usb1 configuration 1 interface 0 "Intel EHCI root hub" rev 2.00/1.00 addr 1
pcib0 at pci0 dev 31 function 0 "Intel Bay Trail LPC" rev 0x0a
ichiic0 at pci0 dev 31 function 3 "Intel Bay Trail SMBus" rev 0x0a: apic 1 int 18
iic0 at ichiic0
spdmem0 at iic0 addr 0x50: 4GB DDR3 SDRAM PC3-12800 SO-DIMM
isa0 at pcib0
isadma0 at isa0
com0 at isa0 port 0x3f8/8 irq 4: ns16550a, 16 byte fifo
pckbc0 at isa0 port 0x60/5 irq 1 irq 12
pckbd0 at pckbc0 (kbd slot)
wskbd0 at pckbd0: console keyboard, using wsdisplay0
pcppi0 at isa0 port 0x61
spkr0 at pcppi0
vmm disabled by firmware
vmm at mainbus0 not configured
uhidev0 at uhub0 port 2 configuration 1 interface 0 "Hewlett Packard HP USB Keyboard" rev 1.10/2.07 addr 2
uhidev0: iclass 3/1
ukbd0 at uhidev0: 8 variable keys, 6 key codes
wskbd1 at ukbd0 mux 1
wskbd1: connecting to wsdisplay0
uhidev1 at uhub0 port 2 configuration 1 interface 1 "Hewlett Packard HP USB Keyboard" rev 1.10/2.07 addr 2
uhidev1: iclass 3/0, 2 report ids
uhid0 at uhidev1 reportid 1: input=1, output=0, feature=0
uhid1 at uhidev1 reportid 2: input=3, output=0, feature=0
uhidev2 at uhub0 port 3 configuration 1 interface 0 "PixArt HP USB Optical Mouse" rev 2.00/1.00 addr 3
uhidev2: iclass 3/1
ums0 at uhidev2: 3 buttons, Z dir
wsmouse0 at ums0 mux 0
uhub2 at uhub0 port 4 configuration 1 interface 0 "Alcor Micro product 0x6254" rev 2.00/1.00 addr 4
uhub3 at uhub1 port 1 configuration 1 interface 0 "Intel product 0x07e6" rev 2.00/0.10 addr 2
vscsi0 at root
scsibus2 at vscsi0: 256 targets
softraid0 at root
scsibus3 at softraid0: 256 targets
root on sd0a (0aa09e87b165e337.a) swap on sd0b dump on sd0b

usbdevs:
Controller /dev/usb0:
addr 1: super speed, self powered, config 1, xHCI root hub(0x0000), Intel(0x8086), rev 1.00
port 1 disabled
port 2 addr 2: low speed, power 100 mA, config 1, HP USB Keyboard(0x0d4a), Hewlett Packard(0x03f0), rev 2.07
port 3 addr 3: low speed, power 100 mA, config 1, HP USB Optical Mouse(0x094a), PixArt(0x03f0), rev 1.00
port 4 addr 4: high speed, self powered, config 1, product 0x6254(0x6254), Alcor Micro(0x058f), rev 1.00
port 1 powered
port 2 powered
port 3 powered
port 4 powered
port 5 disabled
port 6 disabled
port 7 disabled
Controller /dev/usb1:
addr 1: high speed, self powered, config 1, EHCI root hub(0x0000), Intel(0x8086), rev 1.00
port 1 addr 2: high speed, self powered, config 1, product 0x07e6(0x07e6), Intel(0x8087), rev 0.10
port 1 powered
port 2 powered
port 3 powered
port 4 powered
port 2 powered
port 3 powered
port 4 powered
port 5 powered
port 6 powered
port 7 powered
port 8 powered
Seiya Kawashima
2017-02-18 12:46:06 UTC
Permalink
Synopsis: ldapd(8) hangs when receiving large data
Category: system
System : OpenBSD 6.0
Details : OpenBSD 6.0-current (GENERIC.MP) #0: Thu Feb 16 19:58:50 CST 2017
***@amd64.openbsd.org:/usr/src/sys/arch/amd64/compile/GENERIC.MP

Architecture: OpenBSD.amd64
Machine : amd64
Hi,

Thank you for your time to look at this bug report.

ldapd(8) hangs when it receives partial LDAPMessages due to the message
sizes. conn_read() in /ldapd/conn.c is supposed to be called to read
partial LDAPMessages by libevent until it receives complete LDAPMessages
. In theory, conn_read() is called by libevent whenever data for reading
is available. However, it doesn't work this way. What happens is that
conn_read() is called once and nothing happens any further. As the
result, ldapd(8) hangs. It seemed to me that ldapd(8) was waiting for
more data from ldapadd as expected but ldapadd was also waiting for
something to send the rest of the data to ldapd(8). So ldapadd was the
one that didn't send the rest of the data to ldapd(8). To prove this
point, once I killed ldapadd while they were hanging, ldapd(8) started
receiving the rest of the data and stored the data without hanging at
this time. ldapd(8) can't simply wait for more data to read but needs
to do something to let ldapadd keep sending the rest of the data. I
found a fix for this issue but I've not yet found any references about
the fix on RFCs 4511, 4513 and 4514 and the source code at
https://github.com/openldap/openldap so unfortunately I'm not quite sure
if this one would be the right fix. The fix came from my experiments.

Thank you
Seiya
1. Make ldapadd work with self signed certificates for this bug. Please
use the content below for your ~/.ldaprc, otherwise ldapadd would not
work with self signed certificates.

# This is a LDAP client configuration file.
URI ldap:// ldaps://
TLS_REQCERT allow

2. Generate a self signed certificate for this bug. Please type the
command, starttls(8) below to generate a self signed certificate.
Please change the interface, re0 for your environment.

openssl genrsa -out /etc/ldap/certs/re0.key 4096
openssl req -x509 -new -key /etc/ldap/certs/re0.key \
-out /etc/ldap/certs/re0.crt -days 365

3. Set up a simple /etc/ldapd.conf. Please use the content below for
your /etc/ldapd.conf.

schema "/etc/ldap/core.schema"
schema "/etc/ldap/inetorgperson.schema"
schema "/etc/ldap/nis.schema"

# Please change the interface accordingly for your environment.
listen on re0 ldaps

namespace "dc=example,dc=com" {
rootdn "cn=admin,dc=example,dc=com"
rootpw "secret"
index objectClass
index cn
index ou
index uid
index uidNumber
index gidNumber
index mail
index sn
deny access to any by any
allow bind access to children of "ou=people,dc=example,dc=com" by any
allow read access to any by self
allow write access to any by self
}

4. Type the command below to run ldapd(8) in verbose debug mode.

/usr/sbin/ldapd -vv -d

5. Create a simple DIT via ldapadd. Please type the command like below
and adjust the values for -H and -f flags accordingly for your
environment.

ldapadd -vv -H ldaps://192.168.0.118 -x -D "cn=admin,dc=example,dc=com" \
-w secret -f ./sample-1-people-create.txt

Please use the content below as an LDIF file to reproduce the issue.

## This LDIF is from http://www.zytrax.com/books/ldap/ch5/index.html#step1-ldif
## DEFINE DIT ROOT/BASE/SUFFIX ####
## uses RFC 2377 format
## replace example and com as necessary below
## or for experimentation leave as is

## dcObject is an AUXILLIARY objectclass and MUST
## have a STRUCTURAL objectclass (organization in this case)
## this is an ENTRY sequence and is preceded by a BLANK line

dn: dc=example,dc=com
dc: example
description: My wonderful company as much text as you want to place
in this line up to 32K continuation data for the line above must
have &lt;CR> or &lt;CR>&lt;LF> i.e. ENTER works
on both Windows and *nix system - new line MUST begin with ONE SPACE
objectClass: dcObject
objectClass: organization
o: Example, Inc.

## FIRST Level hierarchy - people
## uses mixed upper and lower case for objectclass
## this is an ENTRY sequence and is preceded by a BLANK line

dn: ou=people, dc=example,dc=com
ou: people
description: All people in organisation
objectclass: organizationalunit

6. Add a person as inetOrgPerson objectClass under ou=people specifying
a file for the person's jpegPhoto attribute. Please type the command
below to add the person. Also please specify a large enough file for
the jpegPhoto attribute so that conn_read() in /ldapd/conn.c needs to
be called multiple times to get a complete LDAPMessage. If it's
successful at the first time, try it a couple of more times. You will
be able to see the hang. Please adjust the values for -H and -f flags
accordingly for your environment.

ldapadd -vv -H ldaps://192.168.0.118 -x -D "cn=admin,dc=example,dc=com" \
-w secret -f ./sample-1-people-add.txt

Please use the content below as an LDIF file to make ldapd(8) and
ldapadd hang.

dn: cn=Robert Smith,ou=people,dc=example,dc=com
objectclass: inetOrgPerson
cn: Robert Smith
cn: Robert J Smith
cn: bob smith
sn: smith
uid: rjsmith
## Please specify a file that would cause conn_read() to be called
## multiple times. I tried around 2KB, 3KB, 5KB and 13KB files for
## jpegPhoto attribute.
jpegPhoto:< file:///home/seiyak/Documents/samples/LDAP/sample.jpeg
userpassword: rJsmitH
carlicense: HISCAR 123
homephone: 555-111-2222
mail: ***@example.com
mail: ***@example.com
mail: ***@example.com
description: swell guy
ou: Human Resources

This is the output when the hang happens on ldapd(8).

Feb 17 04:01:28.030 [79095] accepted connection from 192.168.0.115 on fd 12
Feb 17 04:01:28.030 [79095] conn_tls_init: switching to TLS
Feb 17 04:01:28.062 [79095] consumed 46 bytes
Feb 17 04:01:28.062 [79095] received request on fd 12
len 44 class: universal(0) type: sequence(16) encoding 16
len 1 class: universal(0) type: integer(2) encoding 2 value 1
len 39 class: application(1) type: bind(0) encoding 16
len 1 class: universal(0) type: integer(2) encoding 2 value 3
len 26 class: universal(0) type: octet-string(4) encoding 4 string "cn=admin,dc=example,dc=com"
len 6 class: context(2) type: auth simple(0) encoding 4 string "secret"
Feb 17 04:01:28.062 [79095] got request type 0, id 1
Feb 17 04:01:28.062 [79095] bind dn = cn=admin,dc=example,dc=com
Feb 17 04:01:28.062 [79095] successfully authenticated as cn=admin,dc=example,dc=com
Feb 17 04:01:28.062 [79095] sending response 1 with result 0
Feb 17 04:01:28.062 [79095] sending response on fd 12
len 12 class: universal(0) type: sequence(16) encoding 16
len 1 class: universal(0) type: integer(2) encoding 2 value 1
len 7 class: application(1) type: bind(1) encoding 16
len 1 class: universal(0) type: enumerated(10) encoding 10 value 0
len 0 class: universal(0) type: octet-string(4) encoding 4 string ""
len 0 class: universal(0) type: octet-string(4) encoding 4 string ""
# ldapd(8) hangs here and no more output is produced until I kill ladpadd.

This is the output when the hang happens on ldapadd.

ldap_initialize( ldaps://192.168.0.118:636/??base )
add objectclass:
inetOrgPerson
add cn:
Robert Smith
Robert J Smith
bob smith
add sn:
smith
add uid:
rjsmith
add jpegPhoto:
NOT ASCII (2568 bytes)
add userpassword:
rJsmitH
add carlicense:
HISCAR 123
add homephone:
555-111-2222
add mail:
***@example.com
***@example.com
***@example.com
add description:
swell guy
add ou:
Human Resources
adding new entry "cn=Robert Smith,ou=people,dc=example,dc=com"
# ldapadd hangs here and no more output is produced. Once I kill
# ldapadd, the rest of the data is sent to ldapd(8) and it can
# process the complete LDAPMessage escaping from the hang.

The code from /ldapd/ber.c below is where ldapd(8) tries to read
complete LDAPMessages calling conn_read() multiple times. You might
want to put a debug message to show r and totlen before line 1102 on
/ldapd/ber.c to see how many bytes are currently available and how
many more bytes need to be read for a complete LDAPMessage.

1095 DPRINTF("ber read element size %zd\n", len);
1096 totlen += r + len;
1097
1098 /* If using an external buffer and the total size of the element
1099 * is larger then the external buffer don't bother to continue. */
1100 if (ber->fd == -1 && len > ber->br_rend - ber->br_rptr) {
1101 errno = ECANCELED;
1102 return -1;
1103 }
Based on my experiments, ldapd(8) needs to send a response via
send_result_ldap() or send_ldap_extended_response() in /ldapd/ldape.c
every time ldapd(8) reads partial LDAPMessages. For this purpose, I
modified ber_read_elements() and ber_read_element() in /ldapd/ber.c,
conn_dispatch() in /ldapd/conn.c and copied send_ldap_extended_response()
as send_ldap_extended_response2() in /ldapd/conn.c. Please take a look
at the diffs below. Once the fix is in place, please recompile ldapd(8)
and return ldapd(8) and ldapadd. At this time, no hang happens. Please
type the command below to search and verify the value for the jpegPhoto
attribute. Please also adjust the values for -H flag and
ldapsearch-jpegPhoto-HO0LQD accordingly for your environment.

ldapsearch -tt -T ./ -LLL -H ldaps://192.168.0.118 -x -D "cn=admin,dc=example,dc=com" \
-w secret -b "cn=Robert Smith,ou=people,dc=example,dc=com" jpegPhoto
openssl dgst -sha1 ldapsearch-jpegPhoto-HO0LQD
openssl dgst -sha1 /home/seiyak/Documents/samples/LDAP/sample.jpeg

Index: ber.c
===================================================================
RCS file: /cvs/src/usr.sbin/ldapd/ber.c,v
retrieving revision 1.12
diff -u -p -r1.12 ber.c
--- ber.c 11 Feb 2017 20:40:03 -0000 1.12
+++ ber.c 18 Feb 2017 01:36:05 -0000
@@ -815,12 +815,13 @@ ber_read_elements(struct ber *ber, struc

DPRINTF("read ber elements, root %p\n", root);

- if (ber_read_element(ber, root) == -1) {
- /* Cleanup if root was allocated by us */
- if (elm == NULL)
- ber_free_elements(root);
- return NULL;
- }
+ /* ber elements might be spread over multiple buffers. In such a case,
+ * parsing ber fails since it's a partial message but the caller still
+ * needs to send a response to the client. Otherwise a hang would
+ * occur. the caller needs to free root no matter parsing ber is
+ * succeesful or not.
+ */
+ ber_read_element(ber, root);

return root;
}
@@ -1081,7 +1082,7 @@ ber_read_element(struct ber *ber, struct
long long val = 0;
struct ber_element *next;
unsigned long type;
- int i, class, cstruct;
+ int i, class, cstruct, err = -1;
ssize_t len, r, totlen = 0;
u_char c;

@@ -1098,8 +1099,10 @@ ber_read_element(struct ber *ber, struct
/* If using an external buffer and the total size of the element
* is larger then the external buffer don't bother to continue. */
if (ber->fd == -1 && len > ber->br_rend - ber->br_rptr) {
+ /* Keep working on partial message. */
errno = ECANCELED;
- return -1;
+ len = ber->br_rend - ber->br_rptr;
+ err = 0;
}

elm->be_type = type;
@@ -1186,6 +1189,12 @@ ber_read_element(struct ber *ber, struct
next = next->be_next;
}
break;
+ }
+
+ if(err == 0){
+ /* Let the caller know it's a partial message. */
+ errno = ECANCELED;
+ totlen = -1;
}
return totlen;
}
Index: conn.c
===================================================================
RCS file: /cvs/src/usr.sbin/ldapd/conn.c,v
retrieving revision 1.14
diff -u -p -r1.14 conn.c
--- conn.c 20 Jan 2017 11:55:08 -0000 1.14
+++ conn.c 18 Feb 2017 01:36:05 -0000
@@ -29,6 +29,11 @@
int conn_dispatch(struct conn *conn);
int conn_tls_init(struct conn *);
unsigned long ldap_application(struct ber_element *elm);
+/* Copied from /ldapd/ldape.c and renamed to send_ldap_extended_response2(). */
+void send_ldap_extended_response2(struct conn *conn,
+ int msgid, unsigned long type,
+ long long result_code,
+ const char *extended_oid);

struct conn_list conn_list;

@@ -137,10 +142,53 @@ request_dispatch(struct request *req)
}
}

+/* Copied from /ldapd/ldape.c and renamed to send_ldap_extended_response2().
+ */
+void
+send_ldap_extended_response2(struct conn *conn, int msgid, unsigned long type,
+ long long result_code, const char *extended_oid)
+{
+ int rc;
+ struct ber_element *root, *elm;
+ void *buf;
+
+ log_debug("sending response %u with result %lld", type, result_code);
+
+ if ((root = ber_add_sequence(NULL)) == NULL)
+ goto fail;
+
+ elm = ber_printf_elements(root, "d{tEss",
+ msgid, BER_CLASS_APP, type, result_code, "", "");
+ if (elm == NULL)
+ goto fail;
+
+ if (extended_oid)
+ if (ber_add_string(elm, extended_oid) == NULL)
+ goto fail;
+
+ ldap_debug_elements(root, type, "sending response on fd %d", conn->fd);
+
+ rc = ber_write_elements(&conn->ber, root);
+ ber_free_elements(root);
+
+ if (rc < 0)
+ log_warn("failed to create ldap result");
+ else {
+ ber_get_writebuf(&conn->ber, &buf);
+ if (bufferevent_write(conn->bev, buf, rc) != 0)
+ log_warn("failed to send ldap result");
+ }
+
+ return;
+fail:
+ if (root)
+ ber_free_elements(root);
+}
+
int
conn_dispatch(struct conn *conn)
{
- int class;
+ int class, err;
struct request *req;
u_char *rptr;

@@ -155,18 +203,9 @@ conn_dispatch(struct conn *conn)
req->conn = conn;
rptr = conn->ber.br_rptr; /* save where we start reading */

- if ((req->root = ber_read_elements(&conn->ber, NULL)) == NULL) {
- if (errno != ECANCELED) {
- log_warnx("protocol error");
- hexdump(rptr, conn->ber.br_rend - rptr,
- "failed to parse request from %zi bytes:",
- conn->ber.br_rend - rptr);
- conn_disconnect(conn);
- }
- request_free(req);
- return -1;
- }
- log_debug("consumed %d bytes", conn->ber.br_rptr - rptr);
+ req->root = ber_read_elements(&conn->ber, NULL);
+ /* Store errno from ber_read_elements(). */
+ err = errno;

/* Read message id and request type.
*/
@@ -179,6 +218,19 @@ conn_dispatch(struct conn *conn)
request_free(req);
return -1;
}
+
+ if(err == ECANCELED){
+ /* Let LDAP client keep sending leftover data to ldapd.
+ * Need to respond to each partial LDAPMessage, otherwise
+ * the client would not send the rest of the message.
+ */
+ send_ldap_extended_response2(conn, req->msgid, req->type + 1,
+ LDAP_SUCCESS, NULL);
+ request_free(req);
+ return -1;
+ }
+
+ log_debug("consumed %d bytes", conn->ber.br_rptr - rptr);

ldap_debug_elements(req->root, req->type,
"received request on fd %d", conn->fd);

dmesg:
OpenBSD 6.0-current (GENERIC.MP) #0: Thu Feb 16 19:58:50 CST 2017
***@amd64.openbsd.org:/usr/src/sys/arch/amd64/compile/GENERIC.MP
real mem = 4152004608 (3959MB)
avail mem = 4021501952 (3835MB)
mpath0 at root
scsibus0 at mpath0: 256 targets
mainbus0 at root
bios0 at mainbus0: SMBIOS rev. 2.8 @ 0xebe20 (44 entries)
bios0: vendor AMI version "80.06" date 04/11/2014
bios0: Hewlett-Packard HP 200 G1 MT
acpi0 at bios0: rev 2
acpi0: sleep states S0 S3 S4 S5
acpi0: tables DSDT FACP APIC FPDT MSDM MCFG LPIT SLIC HPET SSDT SSDT SSDT UEFI DBGP
acpi0: wakeup devices XHC1(S4) PXSX(S4) PXSX(S4) PXSX(S4) PXSX(S4) PWRB(S0)
acpitimer0 at acpi0: 3579545 Hz, 24 bits
acpimadt0 at acpi0 addr 0xfee00000: PC-AT compat
cpu0 at mainbus0: apid 0 (boot processor)
cpu0: Intel(R) Pentium(R) CPU J2850 @ 2.41GHz, 2417.21 MHz
cpu0: FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CFLUSH,DS,ACPI,MMX,FXSR,SSE,SSE2,SS,HTT,TM,PBE,SSE3,PCLMUL,DTES64,MWAIT,DS-CPL,VMX,EST,TM2,SSSE3,CX16,xTPR,PDCM,SSE4.1,SSE4.2,MOVBE,POPCNT,DEADLINE,RDRAND,NXE,LONG,LAHF,3DNOWP,PERF,ITSC,SMEP,ERMS,SENSOR,ARAT
cpu0: 1MB 64b/line 16-way L2 cache
cpu0: TSC frequency 2417213510 Hz
cpu0: smt 0, core 0, package 0
mtrr: Pentium Pro MTRR support, 8 var ranges, 88 fixed ranges
cpu0: apic clock running at 83MHz
cpu0: mwait min=64, max=64, C-substates=0.2.0.0.0.0.3.3, IBE
cpu1 at mainbus0: apid 2 (application processor)
cpu1: Intel(R) Pentium(R) CPU J2850 @ 2.41GHz, 2416.67 MHz
cpu1: FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CFLUSH,DS,ACPI,MMX,FXSR,SSE,SSE2,SS,HTT,TM,PBE,SSE3,PCLMUL,DTES64,MWAIT,DS-CPL,VMX,EST,TM2,SSSE3,CX16,xTPR,PDCM,SSE4.1,SSE4.2,MOVBE,POPCNT,DEADLINE,RDRAND,NXE,LONG,LAHF,3DNOWP,PERF,ITSC,SMEP,ERMS,SENSOR,ARAT
cpu1: 1MB 64b/line 16-way L2 cache
cpu1: smt 0, core 1, package 0
cpu2 at mainbus0: apid 4 (application processor)
cpu2: Intel(R) Pentium(R) CPU J2850 @ 2.41GHz, 2416.67 MHz
cpu2: FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CFLUSH,DS,ACPI,MMX,FXSR,SSE,SSE2,SS,HTT,TM,PBE,SSE3,PCLMUL,DTES64,MWAIT,DS-CPL,VMX,EST,TM2,SSSE3,CX16,xTPR,PDCM,SSE4.1,SSE4.2,MOVBE,POPCNT,DEADLINE,RDRAND,NXE,LONG,LAHF,3DNOWP,PERF,ITSC,SMEP,ERMS,SENSOR,ARAT
cpu2: 1MB 64b/line 16-way L2 cache
cpu2: smt 0, core 2, package 0
cpu3 at mainbus0: apid 6 (application processor)
cpu3: Intel(R) Pentium(R) CPU J2850 @ 2.41GHz, 2416.67 MHz
cpu3: FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CFLUSH,DS,ACPI,MMX,FXSR,SSE,SSE2,SS,HTT,TM,PBE,SSE3,PCLMUL,DTES64,MWAIT,DS-CPL,VMX,EST,TM2,SSSE3,CX16,xTPR,PDCM,SSE4.1,SSE4.2,MOVBE,POPCNT,DEADLINE,RDRAND,NXE,LONG,LAHF,3DNOWP,PERF,ITSC,SMEP,ERMS,SENSOR,ARAT
cpu3: 1MB 64b/line 16-way L2 cache
cpu3: smt 0, core 3, package 0
ioapic0 at mainbus0: apid 1 pa 0xfec00000, version 20, 87 pins
acpimadt0: bogus nmi for apid 0
acpimadt0: bogus nmi for apid 4
acpimadt0: bogus nmi for apid 6
acpimcfg0 at acpi0 addr 0xe0000000, bus 0-255
acpihpet0 at acpi0: 14318179 Hz
acpiprt0 at acpi0: bus 0 (PCI0)
acpiprt1 at acpi0: bus 1 (RP01)
acpiprt2 at acpi0: bus -1 (ITPC)
acpiprt3 at acpi0: bus 3 (RP02)
acpiprt4 at acpi0: bus 4 (RP03)
acpiprt5 at acpi0: bus 9 (RP04)
acpiec0 at acpi0: not present
acpicpu0 at acpi0: C1(***@1 mwait.1), PSS
acpicpu1 at acpi0: C1(***@1 mwait.1), PSS
acpicpu2 at acpi0: C1(***@1 mwait.1), PSS
acpicpu3 at acpi0: C1(***@1 mwait.1), PSS
acpipwrres0 at acpi0: PLPE
acpipwrres1 at acpi0: PLPE
acpipwrres2 at acpi0: USBC, resource for EHC1, OTG1
acpipwrres3 at acpi0: FN00, resource for FAN0
acpitz0 at acpi0: critical temperature is 90 degC
"PNP0501" at acpi0 not configured
"DMA0F28" at acpi0 not configured
acpibtn0 at acpi0: PWRB
acpibtn1 at acpi0: SLPB
"PNP0C14" at acpi0 not configured
"PNP0C0B" at acpi0 not configured
acpivideo0 at acpi0: GFX0
cpu0: Enhanced SpeedStep 2417 MHz: speeds: 2407, 2324, 2241, 2158, 2075, 1992, 1909, 1826, 1743, 1660, 1577, 1494, 1411, 1328 MHz
pci0 at mainbus0 bus 0
pchb0 at pci0 dev 0 function 0 "Intel Bay Trail Host" rev 0x0a
inteldrm0 at pci0 dev 2 function 0 "Intel Bay Trail Video" rev 0x0a
drm0 at inteldrm0
inteldrm0: msi
inteldrm0: 1024x768, 32bpp
wsdisplay0 at inteldrm0 mux 1: console (std, vt100 emulation)
wsdisplay0: screen 1-5 added (std, vt100 emulation)
ahci0 at pci0 dev 19 function 0 "Intel Bay Trail AHCI" rev 0x0a: msi, AHCI 1.3
ahci0: port 0: 3.0Gb/s
ahci0: port 1: 1.5Gb/s
scsibus1 at ahci0: 32 targets
sd0 at scsibus1 targ 0 lun 0: <ATA, TOSHIBA DT01ACA0, MS1O> SCSI3 0/direct fixed naa.5000039ffcc7f26b
sd0: 476940MB, 512 bytes/sector, 976773168 sectors
cd0 at scsibus1 targ 1 lun 0: <hp, DVD-RAM GHB0N, RK03> ATAPI 5/cdrom removable
xhci0 at pci0 dev 20 function 0 "Intel Bay Trail xHCI" rev 0x0a: msi
usb0 at xhci0: USB revision 3.0
uhub0 at usb0 configuration 1 interface 0 "Intel xHCI root hub" rev 3.00/1.00 addr 1
"Intel Bay Trail TXE" rev 0x0a at pci0 dev 26 function 0 not configured
azalia0 at pci0 dev 27 function 0 "Intel Bay Trail HD Audio" rev 0x0a: msi
azalia0: codecs: Realtek ALC221, Intel/0x2882, using Realtek ALC221
audio0 at azalia0
ppb0 at pci0 dev 28 function 0 "Intel Bay Trail I2C" rev 0x0a: msi
pci1 at ppb0 bus 1
ppb1 at pci1 dev 0 function 0 "ITExpress IT8893E PCIE-PCI" rev 0x52
pci2 at ppb1 bus 2
re0 at pci2 dev 0 function 0 "D-Link DGE-528T" rev 0x10: RTL8169/8110SB (0x1000), apic 1 int 16, address 1c:7e:e5:2a:a0:50
rgephy0 at re0 phy 7: RTL8169S/8110S/8211 PHY, rev. 3
ppb2 at pci0 dev 28 function 1 "Intel Bay Trail PCIE" rev 0x0a: msi
pci3 at ppb2 bus 3
re1 at pci3 dev 0 function 0 "Realtek 8168" rev 0x0c: RTL8168G/8111G (0x4c00), msi, address 10:60:4b:91:85:83
rgephy1 at re1 phy 7: RTL8251 PHY, rev. 0
ppb3 at pci0 dev 28 function 2 "Intel Bay Trail PCIE" rev 0x0a: msi
pci4 at ppb3 bus 4
ppb4 at pci4 dev 0 function 0 "TI XIO3130 PCIE-PCIE upstream" rev 0x02
pci5 at ppb4 bus 5
ppb5 at pci5 dev 0 function 0 "TI XIO3130 PCIE-PCIE downstream" rev 0x02
pci6 at ppb5 bus 6
re2 at pci6 dev 0 function 0 "Realtek 8168" rev 0x06: RTL8168E/8111E (0x2c00), msi, address 00:e0:4c:80:62:93
rgephy2 at re2 phy 7: RTL8169S/8110S/8211 PHY, rev. 4
ppb6 at pci5 dev 1 function 0 "TI XIO3130 PCIE-PCIE downstream" rev 0x02
pci7 at ppb6 bus 7
re3 at pci7 dev 0 function 0 "Realtek 8168" rev 0x06: RTL8168E/8111E (0x2c00), msi, address 00:e0:4c:80:62:94
rgephy3 at re3 phy 7: RTL8169S/8110S/8211 PHY, rev. 4
ppb7 at pci5 dev 2 function 0 "TI XIO3130 PCIE-PCIE downstream" rev 0x02
pci8 at ppb7 bus 8
ppb8 at pci0 dev 28 function 3 "Intel Bay Trail PCIE" rev 0x0a: msi
pci9 at ppb8 bus 9
ppb9 at pci9 dev 0 function 0 "TI XIO3130 PCIE-PCIE upstream" rev 0x02
pci10 at ppb9 bus 10
ppb10 at pci10 dev 0 function 0 "TI XIO3130 PCIE-PCIE downstream" rev 0x02
pci11 at ppb10 bus 11
re4 at pci11 dev 0 function 0 "Realtek 8168" rev 0x06: RTL8168E/8111E (0x2c00), msi, address 00:e0:4c:80:59:28
rgephy4 at re4 phy 7: RTL8169S/8110S/8211 PHY, rev. 4
ppb11 at pci10 dev 1 function 0 "TI XIO3130 PCIE-PCIE downstream" rev 0x02
pci12 at ppb11 bus 12
re5 at pci12 dev 0 function 0 "Realtek 8168" rev 0x06: RTL8168E/8111E (0x2c00), msi, address 00:e0:4c:80:59:29
rgephy5 at re5 phy 7: RTL8169S/8110S/8211 PHY, rev. 4
ppb12 at pci10 dev 2 function 0 "TI XIO3130 PCIE-PCIE downstream" rev 0x02
pci13 at ppb12 bus 13
ehci0 at pci0 dev 29 function 0 "Intel Bay Trail EHCI" rev 0x0a: apic 1 int 23
ehci0: halt timeout
usb1 at ehci0: USB revision 2.0
uhub1 at usb1 configuration 1 interface 0 "Intel EHCI root hub" rev 2.00/1.00 addr 1
pcib0 at pci0 dev 31 function 0 "Intel Bay Trail LPC" rev 0x0a
ichiic0 at pci0 dev 31 function 3 "Intel Bay Trail SMBus" rev 0x0a: apic 1 int 18
iic0 at ichiic0
spdmem0 at iic0 addr 0x50: 4GB DDR3 SDRAM PC3-12800 SO-DIMM
isa0 at pcib0
isadma0 at isa0
com0 at isa0 port 0x3f8/8 irq 4: ns16550a, 16 byte fifo
pckbc0 at isa0 port 0x60/5 irq 1 irq 12
pckbd0 at pckbc0 (kbd slot)
wskbd0 at pckbd0: console keyboard, using wsdisplay0
pcppi0 at isa0 port 0x61
spkr0 at pcppi0
vmm disabled by firmware
vmm at mainbus0 not configured
uhidev0 at uhub0 port 2 configuration 1 interface 0 "Hewlett Packard HP USB Keyboard" rev 1.10/2.07 addr 2
uhidev0: iclass 3/1
ukbd0 at uhidev0: 8 variable keys, 6 key codes
wskbd1 at ukbd0 mux 1
wskbd1: connecting to wsdisplay0
uhidev1 at uhub0 port 2 configuration 1 interface 1 "Hewlett Packard HP USB Keyboard" rev 1.10/2.07 addr 2
uhidev1: iclass 3/0, 2 report ids
uhid0 at uhidev1 reportid 1: input=1, output=0, feature=0
uhid1 at uhidev1 reportid 2: input=3, output=0, feature=0
uhidev2 at uhub0 port 3 configuration 1 interface 0 "PixArt HP USB Optical Mouse" rev 2.00/1.00 addr 3
uhidev2: iclass 3/1
ums0 at uhidev2: 3 buttons, Z dir
wsmouse0 at ums0 mux 0
uhub2 at uhub0 port 4 configuration 1 interface 0 "Alcor Micro product 0x6254" rev 2.00/1.00 addr 4
uhub3 at uhub1 port 1 configuration 1 interface 0 "Intel product 0x07e6" rev 2.00/0.10 addr 2
vscsi0 at root
scsibus2 at vscsi0: 256 targets
softraid0 at root
scsibus3 at softraid0: 256 targets
root on sd0a (0aa09e87b165e337.a) swap on sd0b dump on sd0b

usbdevs:
Controller /dev/usb0:
addr 1: super speed, self powered, config 1, xHCI root hub(0x0000), Intel(0x8086), rev 1.00
port 1 disabled
port 2 addr 2: low speed, power 100 mA, config 1, HP USB Keyboard(0x0d4a), Hewlett Packard(0x03f0), rev 2.07
port 3 addr 3: low speed, power 100 mA, config 1, HP USB Optical Mouse(0x094a), PixArt(0x03f0), rev 1.00
port 4 addr 4: high speed, self powered, config 1, product 0x6254(0x6254), Alcor Micro(0x058f), rev 1.00
port 1 powered
port 2 powered
port 3 powered
port 4 powered
port 5 disabled
port 6 disabled
port 7 disabled
Controller /dev/usb1:
addr 1: high speed, self powered, config 1, EHCI root hub(0x0000), Intel(0x8086), rev 1.00
port 1 addr 2: high speed, self powered, config 1, product 0x07e6(0x07e6), Intel(0x8087), rev 0.10
port 1 powered
port 2 powered
port 3 powered
port 4 powered
port 2 powered
port 3 powered
port 4 powered
port 5 powered
port 6 powered
port 7 powered
port 8 powered
Robert Klein
2017-02-27 21:11:53 UTC
Permalink
Hi Seiya,

On Sat, 18 Feb 2017 12:46:06 +0000
Post by Seiya Kawashima
Synopsis: ldapd(8) hangs when receiving large data
Category: system
System : OpenBSD 6.0
Details : OpenBSD 6.0-current (GENERIC.MP) #0: Thu Feb 16 19:58:50 CST 2017
Architecture: OpenBSD.amd64
Machine : amd64
Hi,
Thank you for your time to look at this bug report.
ldapd(8) hangs when it receives partial LDAPMessages due to
the message sizes. conn_read() in /ldapd/conn.c is supposed to be
called to read partial LDAPMessages by libevent until it receives
complete LDAPMessages . In theory, conn_read() is called by libevent
whenever data for reading is available. However, it doesn't work this
way. What happens is that conn_read() is called once and nothing
happens any further. As the result, ldapd(8) hangs. It seemed to me
that ldapd(8) was waiting for more data from ldapadd as expected but
ldapadd was also waiting for something to send the rest of the data
to ldapd(8). So ldapadd was the one that didn't send the rest of the
data to ldapd(8). To prove this point, once I killed ldapadd while
they were hanging, ldapd(8) started receiving the rest of the data
and stored the data without hanging at this time. ldapd(8) can't
simply wait for more data to read but needs to do something to let
ldapadd keep sending the rest of the data. I found a fix for this
issue but I've not yet found any references about the fix on RFCs
4511, 4513 and 4514 and the source code at
https://github.com/openldap/openldap so unfortunately I'm not quite
sure if this one would be the right fix. The fix came from my
experiments.
Thank you
Seiya
I reproduced the issue with both OpenBSD 6.0 plus patches 1 through 17
applied and OpenBSD current (as of today).

The image I used show the issue for both versions.

When switching TLS off, however, the issue doesn't show up. I didn't
try with non-self-signed certificates, however (will probably try
tomorrow). Differences in the ldapd(8) output (self-signed TLS
certificate, no TLS) are below for both OpenBSD versions.

Anyway, the ldapadd operation completes, even when ldapadd hangs (you
can check with ldapsearch afterwards; ldapadd gives a lot more output if
you use the "-d 7" switch, where you can see the jpeg image is
transported to the ldapd(8) server. It doesn't show the "add:..."
output though, because it's running in a loop. With "-d 7" it repeats
the following output over and over:

--- snip ---
** ld 0x557e29a78770 Outstanding Requests:
* msgid 2, origid 2, status InProgress
outstanding referrals 0, parent count 0
ld 0x557e29a78770 request count 1 (abandoned 0)
** ld 0x557e29a78770 Response Queue:
Empty
ld 0x557e29a78770 response count 0
ldap_chkResponseList ld 0x557e29a78770 msgid 2 all 1
ldap_chkResponseList returns ld 0x557e29a78770 NULL
ldap_int_select
ldap_result ld 0x557e29a78770 msgid 2
wait4msg ld 0x557e29a78770 msgid 2 (timeout 100000 usec)
wait4msg continue ld 0x557e29a78770 msgid 2 all 1
** ld 0x557e29a78770 Connections:
* host: r310 port: 636 (default)
refcnt: 2 status: Connected
last used: Mon Feb 27 20:14:07 2017


--- snip ---


I'm very hesitant about patching the file ber.c; BER is the encoding of
LDAP messages, and shouldn't concern itself about transport and getting
full or partial messages. I'll dig a little more the next couple of
days.



--- Differences of ldapd(8) output tls / without tls
--- ldapd OpenBSD 6.0 w/ Patches 1 through 17 applied
--- (OpenBSD 6.0 (GENERIC) #2: Tue Feb 21 08:31:58 CET 2017)

--- without-tls.log Mon Feb 27 16:56:58 2017
+++ with-tls.log Mon Feb 27 16:57:08 2017
@@ -2,16 +2,19 @@
[--------------------] parsing schema file '/etc/ldap/core.schema'
[--------------------] parsing schema file
'/etc/ldap/inetorgperson.schema' [--------------------] parsing schema
file '/etc/ldap/nis.schema'
+ [--------------------] loading certificate
file /etc/ldap/certs/vio0.crt
+ [--------------------] loading key file /etc/ldap/certs/vio0.key
[--------------------] parsing namespace dc=example,dc=com
[--------------------] deny 1F access to any scope 0 by any
[--------------------] allow 10 access to ou=people,dc=example,dc=com
scope 1 by any [--------------------] allow 01 access to any scope 0 by
@ [--------------------] allow 02 access to any scope 0 by @
[--------------------] startup
- [--------------------] listening on 192.168.131.146:389
+ [--------------------] listening on 192.168.131.146:636
[--------------------] opening namespace dc=example,dc=com
[--------------------] ldape: entering event loop
[--------------------] accepted connection from 192.168.131.26 on fd 9
+ [--------------------] conn_tls_init: switching to TLS
[--------------------] consumed 46 bytes
[--------------------] received request on fd 9
len 44 class: universal(0) type: sequence(16) encoding 16
@@ -141,12 +144,5 @@
len 1 class: universal(0) type: enumerated(10) encoding 10 value 0
len 0 class: universal(0) type: octet-string(4) encoding 4 string
"" len 0 class: universal(0) type: octet-string(4) encoding 4 string ""
- [--------------------] consumed 7 bytes
- [--------------------] received request on fd 9
-len 5 class: universal(0) type: sequence(16) encoding 16
- len 1 class: universal(0) type: integer(2) encoding 2 value 3
- len 0 class: application(1) type: unbind(2) encoding 4 string ""
- [--------------------] got request type 2, id 3
- [--------------------] current bind dn = cn=admin,dc=example,dc=com
[--------------------] end-of-file on connection 9
[--------------------] closing connection 9


--- Differences of ldapd(8) output tls / without tls
--- ldapd OpenBSD current
--- (OpenBSD 6.0-current (GENERIC) #0: Mon Feb 27 17:15:05 CET 2017)

--- wotls.log Mon Feb 27 20:20:48 2017
+++ wtls.log Mon Feb 27 20:20:40 2017
@@ -1,4 +1,6 @@
[---------------------] parsing config /etc/ldapd.conf
+ [---------------------] loading certificate
file /etc/ldap/certs/bnx0.crt
+ [---------------------] loading key file /etc/ldap/certs/bnx0.key
[---------------------] parsing schema file '/etc/ldap/core.schema'
[---------------------] parsing schema file
'/etc/ldap/inetorgperson.schema' [---------------------] parsing schema
file '/etc/ldap/nis.schema' @@ -13,6 +15,8 @@
[---------------------] allow 02 access to any scope 0 by @
[---------------------] startup
[---------------------] parsing config /etc/ldapd.conf
+ [---------------------] loading certificate
file /etc/ldap/certs/bnx0.crt
+ [---------------------] loading key file /etc/ldap/certs/bnx0.key
[---------------------] parsing schema file '/etc/ldap/core.schema'
[---------------------] parsing schema file
'/etc/ldap/inetorgperson.schema' [---------------------] parsing schema
file '/etc/ldap/nis.schema' @@ -25,7 +29,7 @@
[---------------------] allow 10 access to
ou=people,dc=example,dc=com scope 1 by any [---------------------]
allow 01 access to any scope 0 by @ [---------------------] allow 02
access to any scope 0 by @
- [---------------------] listening on 192.168.131.129:389
+ [---------------------] listening on 192.168.131.129:636
[---------------------] listening on 127.0.0.1:389
[---------------------] listening on fe80:2::1:389
[---------------------] listening on ::1:389
@@ -34,6 +38,7 @@
[---------------------] opening namespace dc=example,dc=com
[---------------------] ldape: entering event loop
[---------------------] accepted connection from 192.168.131.26 on fd
16
+ [---------------------] conn_tls_init: switching to TLS
[---------------------] consumed 46 bytes
[---------------------] got request type 0, id 1
[---------------------] bind dn = cn=admin,dc=example,dc=com
@@ -50,8 +55,5 @@
[---------------------] indexing cn=robert
smith,ou=people,dc=example,dc=com on sn [---------------------]
indexing rdn on @ou=people,cn=robert smith [---------------------]
sending response 9 with result 0
- [---------------------] consumed 7 bytes
- [---------------------] got request type 2, id 3
- [---------------------] current bind dn = cn=admin,dc=example,dc=com
[---------------------] end-of-file on connection 16
[---------------------] closing connection 16



Best regards
Robert
Post by Seiya Kawashima
1. Make ldapadd work with self signed certificates for this
bug. Please use the content below for your ~/.ldaprc, otherwise
ldapadd would not work with self signed certificates.
# This is a LDAP client configuration file.
URI ldap:// ldaps://
TLS_REQCERT allow
2. Generate a self signed certificate for this bug. Please
type the command, starttls(8) below to generate a self signed
certificate. Please change the interface, re0 for your environment.
openssl genrsa -out /etc/ldap/certs/re0.key 4096
openssl req -x509 -new -key /etc/ldap/certs/re0.key \
-out /etc/ldap/certs/re0.crt -days 365
3. Set up a simple /etc/ldapd.conf. Please use the content
below for your /etc/ldapd.conf.
schema "/etc/ldap/core.schema"
schema "/etc/ldap/inetorgperson.schema"
schema "/etc/ldap/nis.schema"
# Please change the interface accordingly for your
environment. listen on re0 ldaps
namespace "dc=example,dc=com" {
rootdn "cn=admin,dc=example,dc=com"
rootpw "secret"
index objectClass
index cn
index ou
index uid
index uidNumber
index gidNumber
index mail
index sn
deny access to any by any
allow bind access to children of
"ou=people,dc=example,dc=com" by any allow read access to any by self
allow write access to any by self
}
4. Type the command below to run ldapd(8) in verbose debug mode.
/usr/sbin/ldapd -vv -d
5. Create a simple DIT via ldapadd. Please type the command
like below and adjust the values for -H and -f flags accordingly for
your environment.
ldapadd -vv -H ldaps://192.168.0.118 -x -D
"cn=admin,dc=example,dc=com" \ -w secret
-f ./sample-1-people-create.txt
Please use the content below as an LDIF file to reproduce the issue.
## This LDIF is from
http://www.zytrax.com/books/ldap/ch5/index.html#step1-ldif ## DEFINE
DIT ROOT/BASE/SUFFIX #### ## uses RFC 2377 format
## replace example and com as necessary below
## or for experimentation leave as is
## dcObject is an AUXILLIARY objectclass and MUST
## have a STRUCTURAL objectclass (organization in this
case) ## this is an ENTRY sequence and is preceded by a BLANK line
dn: dc=example,dc=com
dc: example
description: My wonderful company as much text as you want
to place in this line up to 32K continuation data for the line above
must have &lt;CR> or &lt;CR>&lt;LF> i.e. ENTER works
on both Windows and *nix system - new line MUST begin
with ONE SPACE objectClass: dcObject
objectClass: organization
o: Example, Inc.
## FIRST Level hierarchy - people
## uses mixed upper and lower case for objectclass
## this is an ENTRY sequence and is preceded by a BLANK line
dn: ou=people, dc=example,dc=com
ou: people
description: All people in organisation
objectclass: organizationalunit
6. Add a person as inetOrgPerson objectClass under ou=people
specifying a file for the person's jpegPhoto attribute. Please type
the command below to add the person. Also please specify a large
enough file for the jpegPhoto attribute so that conn_read()
in /ldapd/conn.c needs to be called multiple times to get a complete
LDAPMessage. If it's successful at the first time, try it a couple of
more times. You will be able to see the hang. Please adjust the
values for -H and -f flags accordingly for your environment.
ldapadd -vv -H ldaps://192.168.0.118 -x -D
"cn=admin,dc=example,dc=com" \ -w secret -f ./sample-1-people-add.txt
Please use the content below as an LDIF file to make
ldapd(8) and ldapadd hang.
dn: cn=Robert Smith,ou=people,dc=example,dc=com
objectclass: inetOrgPerson
cn: Robert Smith
cn: Robert J Smith
cn: bob smith
sn: smith
uid: rjsmith
## Please specify a file that would cause conn_read() to
be called ## multiple times. I tried around 2KB, 3KB, 5KB and 13KB
files for ## jpegPhoto attribute.
jpegPhoto:<
rJsmitH carlicense: HISCAR 123
homephone: 555-111-2222
description: swell guy
ou: Human Resources
This is the output when the hang happens on ldapd(8).
Feb 17 04:01:28.030 [79095] accepted connection from
switching to TLS Feb 17 04:01:28.062 [79095] consumed 46 bytes
Feb 17 04:01:28.062 [79095] received request on fd 12
len 44 class: universal(0) type: sequence(16) encoding 16
len 1 class: universal(0) type: integer(2) encoding 2
value 1 len 39 class: application(1) type: bind(0) encoding 16
len 1 class: universal(0) type: integer(2) encoding 2
value 3 len 26 class: universal(0) type: octet-string(4) encoding 4
auth simple(0) encoding 4 string "secret" Feb 17 04:01:28.062 [79095]
got request type 0, id 1 Feb 17 04:01:28.062 [79095] bind dn =
cn=admin,dc=example,dc=com Feb 17 04:01:28.062 [79095] successfully
authenticated as cn=admin,dc=example,dc=com Feb 17 04:01:28.062
[79095] sending response 1 with result 0 Feb 17 04:01:28.062 [79095]
sequence(16) encoding 16 len 1 class: universal(0) type: integer(2)
encoding 2 value 1 len 7 class: application(1) type: bind(1) encoding
16 len 1 class: universal(0) type: enumerated(10) encoding 10 value 0
len 0 class: universal(0) type: octet-string(4)
encoding 4 string "" len 0 class: universal(0) type: octet-string(4)
encoding 4 string "" # ldapd(8) hangs here and no more output is
produced until I kill ladpadd.
This is the output when the hang happens on ldapadd.
ldap_initialize( ldaps://192.168.0.118:636/??base )
inetOrgPerson
Robert Smith
Robert J Smith
bob smith
smith
rjsmith
NOT ASCII (2568 bytes)
rJsmitH
HISCAR 123
555-111-2222
swell guy
Human Resources
adding new entry "cn=Robert
Smith,ou=people,dc=example,dc=com" # ldapadd hangs here and no more
output is produced. Once I kill # ldapadd, the rest of the data is
sent to ldapd(8) and it can # process the complete LDAPMessage
escaping from the hang.
The code from /ldapd/ber.c below is where ldapd(8) tries
to read complete LDAPMessages calling conn_read() multiple times. You
might want to put a debug message to show r and totlen before line
1102 on /ldapd/ber.c to see how many bytes are currently available
and how many more bytes need to be read for a complete LDAPMessage.
1095 DPRINTF("ber read element size %zd\n", len);
1096 totlen += r + len;
1097
1098 /* If using an external buffer and the total size
of the element 1099 * is larger then the external buffer don't
bother to continue. */ 1100 if (ber->fd == -1 && len >
ber->br_rend - ber->br_rptr) { 1101 errno = ECANCELED;
1102 return -1;
1103 }
Based on my experiments, ldapd(8) needs to send a response via
send_result_ldap() or send_ldap_extended_response()
in /ldapd/ldape.c every time ldapd(8) reads partial LDAPMessages. For
this purpose, I modified ber_read_elements() and ber_read_element()
in /ldapd/ber.c, conn_dispatch() in /ldapd/conn.c and copied
send_ldap_extended_response() as send_ldap_extended_response2()
in /ldapd/conn.c. Please take a look at the diffs below. Once the fix
is in place, please recompile ldapd(8) and return ldapd(8) and
ldapadd. At this time, no hang happens. Please type the command below
to search and verify the value for the jpegPhoto attribute. Please
also adjust the values for -H flag and ldapsearch-jpegPhoto-HO0LQD
accordingly for your environment.
ldapsearch -tt -T ./ -LLL -H ldaps://192.168.0.118 -x -D
"cn=admin,dc=example,dc=com" \ -w secret -b "cn=Robert
Smith,ou=people,dc=example,dc=com" jpegPhoto openssl dgst -sha1
ldapsearch-jpegPhoto-HO0LQD openssl dgst
-sha1 /home/seiyak/Documents/samples/LDAP/sample.jpeg
Index: ber.c
===================================================================
RCS file: /cvs/src/usr.sbin/ldapd/ber.c,v
retrieving revision 1.12
diff -u -p -r1.12 ber.c
--- ber.c 11 Feb 2017 20:40:03 -0000 1.12
+++ ber.c 18 Feb 2017 01:36:05 -0000
@@ -815,12 +815,13 @@ ber_read_elements(struct ber *ber, struc
DPRINTF("read ber elements, root %p\n", root);
- if (ber_read_element(ber, root) == -1) {
- /* Cleanup if root was allocated by us */
- if (elm == NULL)
- ber_free_elements(root);
- return NULL;
- }
+ /* ber elements might be spread over multiple buffers. In such a case,
+ * parsing ber fails since it's a partial message but the caller still
+ * needs to send a response to the client. Otherwise a hang would
+ * occur. the caller needs to free root no matter parsing ber is
+ * succeesful or not.
+ */
+ ber_read_element(ber, root);
return root;
}
@@ -1081,7 +1082,7 @@ ber_read_element(struct ber *ber, struct
long long val = 0;
struct ber_element *next;
unsigned long type;
- int i, class, cstruct;
+ int i, class, cstruct, err = -1;
ssize_t len, r, totlen = 0;
u_char c;
@@ -1098,8 +1099,10 @@ ber_read_element(struct ber *ber, struct
/* If using an external buffer and the total size of the element
* is larger then the external buffer don't bother to
continue. */ if (ber->fd == -1 && len > ber->br_rend - ber->br_rptr) {
+ /* Keep working on partial message. */
errno = ECANCELED;
- return -1;
+ len = ber->br_rend - ber->br_rptr;
+ err = 0;
}
elm->be_type = type;
@@ -1186,6 +1189,12 @@ ber_read_element(struct ber *ber, struct
next = next->be_next;
}
break;
+ }
+
+ if(err == 0){
+ /* Let the caller know it's a partial message. */
+ errno = ECANCELED;
+ totlen = -1;
}
return totlen;
}
Index: conn.c
===================================================================
RCS file: /cvs/src/usr.sbin/ldapd/conn.c,v
retrieving revision 1.14
diff -u -p -r1.14 conn.c
--- conn.c 20 Jan 2017 11:55:08 -0000 1.14
+++ conn.c 18 Feb 2017 01:36:05 -0000
@@ -29,6 +29,11 @@
int conn_dispatch(struct conn *conn);
int conn_tls_init(struct conn *);
unsigned long ldap_application(struct ber_element *elm);
+/* Copied from /ldapd/ldape.c and renamed to
send_ldap_extended_response2(). */ +void
send_ldap_extended_response2(struct conn *conn,
+ int msgid, unsigned long type,
+ long long result_code,
+ const char *extended_oid);
struct conn_list conn_list;
@@ -137,10 +142,53 @@ request_dispatch(struct request *req)
}
}
+/* Copied from /ldapd/ldape.c and renamed to
send_ldap_extended_response2().
+ */
+void
+send_ldap_extended_response2(struct conn *conn, int msgid, unsigned long type,
+ long long result_code, const char *extended_oid)
+{
+ int rc;
+ struct ber_element *root, *elm;
+ void *buf;
+
+ log_debug("sending response %u with result %lld", type,
result_code); +
+ if ((root = ber_add_sequence(NULL)) == NULL)
+ goto fail;
+
+ elm = ber_printf_elements(root, "d{tEss",
+ msgid, BER_CLASS_APP, type, result_code, "", "");
+ if (elm == NULL)
+ goto fail;
+
+ if (extended_oid)
+ if (ber_add_string(elm, extended_oid) == NULL)
+ goto fail;
+
+ ldap_debug_elements(root, type, "sending response on fd %d",
conn->fd); +
+ rc = ber_write_elements(&conn->ber, root);
+ ber_free_elements(root);
+
+ if (rc < 0)
+ log_warn("failed to create ldap result");
+ else {
+ ber_get_writebuf(&conn->ber, &buf);
+ if (bufferevent_write(conn->bev, buf, rc) != 0)
+ log_warn("failed to send ldap result");
+ }
+
+ return;
+ if (root)
+ ber_free_elements(root);
+}
+
int
conn_dispatch(struct conn *conn)
{
- int class;
+ int class, err;
struct request *req;
u_char *rptr;
@@ -155,18 +203,9 @@ conn_dispatch(struct conn *conn)
req->conn = conn;
rptr = conn->ber.br_rptr; /* save where we start
reading */
- if ((req->root = ber_read_elements(&conn->ber, NULL)) == NULL) {
- if (errno != ECANCELED) {
- log_warnx("protocol error");
- hexdump(rptr, conn->ber.br_rend - rptr,
- "failed to parse request from %zi bytes:",
- conn->ber.br_rend - rptr);
- conn_disconnect(conn);
- }
- request_free(req);
- return -1;
- }
- log_debug("consumed %d bytes", conn->ber.br_rptr - rptr);
+ req->root = ber_read_elements(&conn->ber, NULL);
+ /* Store errno from ber_read_elements(). */
+ err = errno;
/* Read message id and request type.
*/
@@ -179,6 +218,19 @@ conn_dispatch(struct conn *conn)
request_free(req);
return -1;
}
+
+ if(err == ECANCELED){
+ /* Let LDAP client keep sending leftover data to ldapd.
+ * Need to respond to each partial LDAPMessage, otherwise
+ * the client would not send the rest of the message.
+ */
+ send_ldap_extended_response2(conn, req->msgid,
req->type + 1,
+ LDAP_SUCCESS, NULL);
+ request_free(req);
+ return -1;
+ }
+
+ log_debug("consumed %d bytes", conn->ber.br_rptr - rptr);
ldap_debug_elements(req->root, req->type,
"received request on fd %d", conn->fd);
OpenBSD 6.0-current (GENERIC.MP) #0: Thu Feb 16 19:58:50 CST 2017
real mem = 4152004608 (3959MB)
avail mem = 4021501952 (3835MB)
mpath0 at root
scsibus0 at mpath0: 256 targets
mainbus0 at root
bios0: vendor AMI version "80.06" date 04/11/2014
bios0: Hewlett-Packard HP 200 G1 MT
acpi0 at bios0: rev 2
acpi0: sleep states S0 S3 S4 S5
acpi0: tables DSDT FACP APIC FPDT MSDM MCFG LPIT SLIC HPET SSDT SSDT
SSDT UEFI DBGP acpi0: wakeup devices XHC1(S4) PXSX(S4) PXSX(S4)
PXSX(S4) PXSX(S4) PWRB(S0) acpitimer0 at acpi0: 3579545 Hz, 24 bits
acpimadt0 at acpi0 addr 0xfee00000: PC-AT compat
cpu0 at mainbus0: apid 0 (boot processor)
FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CFLUSH,DS,ACPI,MMX,FXSR,SSE,SSE2,SS,HTT,TM,PBE,SSE3,PCLMUL,DTES64,MWAIT,DS-CPL,VMX,EST,TM2,SSSE3,CX16,xTPR,PDCM,SSE4.1,SSE4.2,MOVBE,POPCNT,DEADLINE,RDRAND,NXE,LONG,LAHF,3DNOWP,PERF,ITSC,SMEP,ERMS,SENSOR,ARAT
cpu0: 1MB 64b/line 16-way L2 cache cpu0: TSC frequency 2417213510 Hz
cpu0: smt 0, core 0, package 0
mtrr: Pentium Pro MTRR support, 8 var ranges, 88 fixed ranges
cpu0: apic clock running at 83MHz
cpu0: mwait min=64, max=64, C-substates=0.2.0.0.0.0.3.3, IBE
cpu1 at mainbus0: apid 2 (application processor)
FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CFLUSH,DS,ACPI,MMX,FXSR,SSE,SSE2,SS,HTT,TM,PBE,SSE3,PCLMUL,DTES64,MWAIT,DS-CPL,VMX,EST,TM2,SSSE3,CX16,xTPR,PDCM,SSE4.1,SSE4.2,MOVBE,POPCNT,DEADLINE,RDRAND,NXE,LONG,LAHF,3DNOWP,PERF,ITSC,SMEP,ERMS,SENSOR,ARAT
cpu1: 1MB 64b/line 16-way L2 cache cpu1: smt 0, core 1, package 0
cpu2 at mainbus0: apid 4 (application processor)
FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CFLUSH,DS,ACPI,MMX,FXSR,SSE,SSE2,SS,HTT,TM,PBE,SSE3,PCLMUL,DTES64,MWAIT,DS-CPL,VMX,EST,TM2,SSSE3,CX16,xTPR,PDCM,SSE4.1,SSE4.2,MOVBE,POPCNT,DEADLINE,RDRAND,NXE,LONG,LAHF,3DNOWP,PERF,ITSC,SMEP,ERMS,SENSOR,ARAT
cpu2: 1MB 64b/line 16-way L2 cache cpu2: smt 0, core 2, package 0
cpu3 at mainbus0: apid 6 (application processor)
FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CFLUSH,DS,ACPI,MMX,FXSR,SSE,SSE2,SS,HTT,TM,PBE,SSE3,PCLMUL,DTES64,MWAIT,DS-CPL,VMX,EST,TM2,SSSE3,CX16,xTPR,PDCM,SSE4.1,SSE4.2,MOVBE,POPCNT,DEADLINE,RDRAND,NXE,LONG,LAHF,3DNOWP,PERF,ITSC,SMEP,ERMS,SENSOR,ARAT
cpu3: 1MB 64b/line 16-way L2 cache cpu3: smt 0, core 3, package 0
ioapic0 at mainbus0: apid 1 pa 0xfec00000, version 20, 87 pins
acpimadt0: bogus nmi for apid 0
acpimadt0: bogus nmi for apid 4
acpimadt0: bogus nmi for apid 6
acpimcfg0 at acpi0 addr 0xe0000000, bus 0-255
acpihpet0 at acpi0: 14318179 Hz
acpiprt0 at acpi0: bus 0 (PCI0)
acpiprt1 at acpi0: bus 1 (RP01)
acpiprt2 at acpi0: bus -1 (ITPC)
acpiprt3 at acpi0: bus 3 (RP02)
acpiprt4 at acpi0: bus 4 (RP03)
acpiprt5 at acpi0: bus 9 (RP04)
acpiec0 at acpi0: not present
acpipwrres0 at acpi0: PLPE
acpipwrres1 at acpi0: PLPE
acpipwrres2 at acpi0: USBC, resource for EHC1, OTG1
acpipwrres3 at acpi0: FN00, resource for FAN0
acpitz0 at acpi0: critical temperature is 90 degC
"PNP0501" at acpi0 not configured
"DMA0F28" at acpi0 not configured
acpibtn0 at acpi0: PWRB
acpibtn1 at acpi0: SLPB
"PNP0C14" at acpi0 not configured
"PNP0C0B" at acpi0 not configured
acpivideo0 at acpi0: GFX0
cpu0: Enhanced SpeedStep 2417 MHz: speeds: 2407, 2324, 2241, 2158,
2075, 1992, 1909, 1826, 1743, 1660, 1577, 1494, 1411, 1328 MHz pci0
at mainbus0 bus 0 pchb0 at pci0 dev 0 function 0 "Intel Bay Trail
Host" rev 0x0a inteldrm0 at pci0 dev 2 function 0 "Intel Bay Trail
Video" rev 0x0a drm0 at inteldrm0
inteldrm0: msi
inteldrm0: 1024x768, 32bpp
wsdisplay0 at inteldrm0 mux 1: console (std, vt100 emulation)
wsdisplay0: screen 1-5 added (std, vt100 emulation)
ahci0 at pci0 dev 19 function 0 "Intel Bay Trail AHCI" rev 0x0a: msi,
AHCI 1.3 ahci0: port 0: 3.0Gb/s
ahci0: port 1: 1.5Gb/s
scsibus1 at ahci0: 32 targets
sd0 at scsibus1 targ 0 lun 0: <ATA, TOSHIBA DT01ACA0, MS1O> SCSI3
0/direct fixed naa.5000039ffcc7f26b sd0: 476940MB, 512 bytes/sector,
976773168 sectors cd0 at scsibus1 targ 1 lun 0: <hp, DVD-RAM GHB0N,
RK03> ATAPI 5/cdrom removable xhci0 at pci0 dev 20 function 0 "Intel
RK03> Bay Trail xHCI" rev 0x0a: msi
usb0 at xhci0: USB revision 3.0
uhub0 at usb0 configuration 1 interface 0 "Intel xHCI root hub" rev
3.00/1.00 addr 1 "Intel Bay Trail TXE" rev 0x0a at pci0 dev 26
function 0 not configured azalia0 at pci0 dev 27 function 0 "Intel
Bay Trail HD Audio" rev 0x0a: msi azalia0: codecs: Realtek ALC221,
Intel/0x2882, using Realtek ALC221 audio0 at azalia0
ppb0 at pci0 dev 28 function 0 "Intel Bay Trail I2C" rev 0x0a: msi
pci1 at ppb0 bus 1
ppb1 at pci1 dev 0 function 0 "ITExpress IT8893E PCIE-PCI" rev 0x52
pci2 at ppb1 bus 2
RTL8169/8110SB (0x1000), apic 1 int 16, address 1c:7e:e5:2a:a0:50
rgephy0 at re0 phy 7: RTL8169S/8110S/8211 PHY, rev. 3 ppb2 at pci0
dev 28 function 1 "Intel Bay Trail PCIE" rev 0x0a: msi pci3 at ppb2
RTL8168G/8111G (0x4c00), msi, address 10:60:4b:91:85:83 rgephy1 at
re1 phy 7: RTL8251 PHY, rev. 0 ppb3 at pci0 dev 28 function 2 "Intel
Bay Trail PCIE" rev 0x0a: msi pci4 at ppb3 bus 4
ppb4 at pci4 dev 0 function 0 "TI XIO3130 PCIE-PCIE upstream" rev 0x02
pci5 at ppb4 bus 5
ppb5 at pci5 dev 0 function 0 "TI XIO3130 PCIE-PCIE downstream" rev
0x02 pci6 at ppb5 bus 6
re2 at pci6 dev 0 function 0 "Realtek 8168" rev 0x06: RTL8168E/8111E
RTL8169S/8110S/8211 PHY, rev. 4 ppb6 at pci5 dev 1 function 0 "TI
XIO3130 PCIE-PCIE downstream" rev 0x02 pci7 at ppb6 bus 7
re3 at pci7 dev 0 function 0 "Realtek 8168" rev 0x06: RTL8168E/8111E
RTL8169S/8110S/8211 PHY, rev. 4 ppb7 at pci5 dev 2 function 0 "TI
XIO3130 PCIE-PCIE downstream" rev 0x02 pci8 at ppb7 bus 8
ppb8 at pci0 dev 28 function 3 "Intel Bay Trail PCIE" rev 0x0a: msi
pci9 at ppb8 bus 9
ppb9 at pci9 dev 0 function 0 "TI XIO3130 PCIE-PCIE upstream" rev 0x02
pci10 at ppb9 bus 10
ppb10 at pci10 dev 0 function 0 "TI XIO3130 PCIE-PCIE downstream" rev
0x02 pci11 at ppb10 bus 11
re4 at pci11 dev 0 function 0 "Realtek 8168" rev 0x06: RTL8168E/8111E
RTL8169S/8110S/8211 PHY, rev. 4 ppb11 at pci10 dev 1 function 0 "TI
XIO3130 PCIE-PCIE downstream" rev 0x02 pci12 at ppb11 bus 12
re5 at pci12 dev 0 function 0 "Realtek 8168" rev 0x06: RTL8168E/8111E
RTL8169S/8110S/8211 PHY, rev. 4 ppb12 at pci10 dev 2 function 0 "TI
XIO3130 PCIE-PCIE downstream" rev 0x02 pci13 at ppb12 bus 13
ehci0 at pci0 dev 29 function 0 "Intel Bay Trail EHCI" rev 0x0a: apic
1 int 23 ehci0: halt timeout
usb1 at ehci0: USB revision 2.0
uhub1 at usb1 configuration 1 interface 0 "Intel EHCI root hub" rev
2.00/1.00 addr 1 pcib0 at pci0 dev 31 function 0 "Intel Bay Trail
LPC" rev 0x0a ichiic0 at pci0 dev 31 function 3 "Intel Bay Trail
SMBus" rev 0x0a: apic 1 int 18 iic0 at ichiic0
spdmem0 at iic0 addr 0x50: 4GB DDR3 SDRAM PC3-12800 SO-DIMM
isa0 at pcib0
isadma0 at isa0
com0 at isa0 port 0x3f8/8 irq 4: ns16550a, 16 byte fifo
pckbc0 at isa0 port 0x60/5 irq 1 irq 12
pckbd0 at pckbc0 (kbd slot)
wskbd0 at pckbd0: console keyboard, using wsdisplay0
pcppi0 at isa0 port 0x61
spkr0 at pcppi0
vmm disabled by firmware
vmm at mainbus0 not configured
uhidev0 at uhub0 port 2 configuration 1 interface 0 "Hewlett Packard
HP USB Keyboard" rev 1.10/2.07 addr 2 uhidev0: iclass 3/1
ukbd0 at uhidev0: 8 variable keys, 6 key codes
wskbd1 at ukbd0 mux 1
wskbd1: connecting to wsdisplay0
uhidev1 at uhub0 port 2 configuration 1 interface 1 "Hewlett Packard
HP USB Keyboard" rev 1.10/2.07 addr 2 uhidev1: iclass 3/0, 2 report
ids uhid0 at uhidev1 reportid 1: input=1, output=0, feature=0
uhid1 at uhidev1 reportid 2: input=3, output=0, feature=0
uhidev2 at uhub0 port 3 configuration 1 interface 0 "PixArt HP USB
Optical Mouse" rev 2.00/1.00 addr 3 uhidev2: iclass 3/1
ums0 at uhidev2: 3 buttons, Z dir
wsmouse0 at ums0 mux 0
uhub2 at uhub0 port 4 configuration 1 interface 0 "Alcor Micro
product 0x6254" rev 2.00/1.00 addr 4 uhub3 at uhub1 port 1
configuration 1 interface 0 "Intel product 0x07e6" rev 2.00/0.10 addr
2 vscsi0 at root scsibus2 at vscsi0: 256 targets
softraid0 at root
scsibus3 at softraid0: 256 targets
root on sd0a (0aa09e87b165e337.a) swap on sd0b dump on sd0b
addr 1: super speed, self powered, config 1, xHCI root hub(0x0000),
Intel(0x8086), rev 1.00 port 1 disabled
port 2 addr 2: low speed, power 100 mA, config 1, HP USB
low speed, power 100 mA, config 1, HP USB Optical Mouse(0x094a),
PixArt(0x03f0), rev 1.00 port 4 addr 4: high speed, self powered,
config 1, product 0x6254(0x6254), Alcor Micro(0x058f), rev 1.00 port
1 powered port 2 powered port 3 powered
port 4 powered
port 5 disabled
port 6 disabled
port 7 disabled
addr 1: high speed, self powered, config 1, EHCI root hub(0x0000),
Intel(0x8086), rev 1.00 port 1 addr 2: high speed, self powered,
config 1, product 0x07e6(0x07e6), Intel(0x8087), rev 0.10 port 1
powered port 2 powered
port 3 powered
port 4 powered
port 2 powered
port 3 powered
port 4 powered
port 5 powered
port 6 powered
port 7 powered
port 8 powered
Gleydson Soares
2017-03-01 03:59:11 UTC
Permalink
Hi,

I can't reproduce... this just works fine here without hangs,
I'm using OpenBSD -current, ldapd(as of today) + TLS (self-signed
TLS certificate).

The ldifs and image(54.7K) are available at:
http://shutupandhack.org/~gsoares/tmp/1.ldif
http://shutupandhack.org/~gsoares/tmp/2.ldif
Loading Image...

could you try to reproduce using the files above?
let me know if I missed anything.
following more details about my tests:

*ldif*

dn: cn=Robert1 Smith,ou=people,dc=example,dc=com
objectclass: inetOrgPerson
cn: Robert1 Smith
cn: Robert1 J Smith
cn: bob smith
sn: smith
uid: rjsmith
## Please specify a file that would cause conn_read() to be called
## multiple times. I tried around 2KB, 3KB, 5KB and 13KB files for
## jpegPhoto attribute.
jpegPhoto:< file:///home/gsoares/sample.jpeg
userpassword: rJsmitH
carlicense: HISCAR 123
homephone: 555-111-2222
mail: ***@example.com
mail: ***@example.com
mail: ***@example.com
description: swell guy
ou: Human Resources

*Adding(no hangs)*

% ldapadd -vv -H ldaps://127.0.0.1 -x -D 'cn=admin,dc=example,dc=com' -w secret -f ./2.ldif
ldap_initialize( ldaps://127.0.0.1:636/??base )
add objectclass:
inetOrgPerson
add cn:
Robert1 Smith
Robert1 J Smith
bob smith
add sn:
smith
add uid:
rjsmith
add jpegPhoto:
NOT ASCII (56060 bytes)
add userpassword:
rJsmitH
add carlicense:
HISCAR 123
add homephone:
555-111-2222
add mail:
***@example.com
***@example.com
***@example.com
add description:
swell guy
add ou:
Human Resources
adding new entry "cn=Robert1 Smith,ou=people,dc=example,dc=com"
modify complete

*Searching*

% ldapsearch -tt -T ./ -LLL -H ldaps://127.0.0.1 -x -D 'cn=admin,dc=example,dc=com' -w secret -b 'cn=Robert1 Smith,ou=people,dc=example,dc=com' jpegPhoto
dn: cn=robert1 smith,ou=people,dc=example,dc=com
jpegPhoto:< file:///.//ldapsearch-jpegPhoto-38ROnW


*ldapd debug*

Mar 1 00:11:30.650 [6247] accepted connection from 127.0.0.1 on fd 11
Mar 1 00:11:30.650 [6247] conn_tls_init: switching to TLS
Mar 1 00:11:30.683 [6247] consumed 46 bytes
Mar 1 00:11:30.683 [6247] got request type 0, id 1
Mar 1 00:11:30.683 [6247] bind dn = cn=admin,dc=example,dc=com
Mar 1 00:11:30.683 [6247] successfully authenticated as cn=admin,dc=example,dc=com
Mar 1 00:11:30.683 [6247] sending response 1 with result 0
Mar 1 00:11:30.684 [6247] consumed 43997 bytes
Mar 1 00:11:30.684 [6247] got request type 8, id 2
Mar 1 00:11:30.684 [6247] adding entry cn=robert smith,ou=people,dc=example,dc=com
Mar 1 00:11:30.685 [6247] indexing cn=robert smith,ou=people,dc=example,dc=com on objectClass
Mar 1 00:11:30.685 [6247] indexing cn=robert smith,ou=people,dc=example,dc=com on cn
Mar 1 00:11:30.685 [6247] indexing cn=robert smith,ou=people,dc=example,dc=com on ou
Mar 1 00:11:30.685 [6247] indexing cn=robert smith,ou=people,dc=example,dc=com on uid
Mar 1 00:11:30.685 [6247] indexing cn=robert smith,ou=people,dc=example,dc=com on mail
Mar 1 00:11:30.685 [6247] indexing cn=robert smith,ou=people,dc=example,dc=com on sn
Mar 1 00:11:30.685 [6247] indexing rdn on @ou=people,cn=robert smith
Mar 1 00:11:30.697 [6247] sending response 9 with result 0
Mar 1 00:11:30.698 [6247] consumed 7 bytes
Mar 1 00:11:30.698 [6247] got request type 2, id 3
Mar 1 00:11:30.698 [6247] current bind dn = cn=admin,dc=example,dc=com
Mar 1 00:11:30.698 [6247] end-of-file on connection 11
Mar 1 00:11:30.698 [6247] closing connection 11
Mar 1 00:16:11.313 [6247] accepted connection from 127.0.0.1 on fd 11
Mar 1 00:16:11.313 [6247] conn_tls_init: switching to TLS
Mar 1 00:16:11.346 [6247] consumed 46 bytes
Mar 1 00:16:11.346 [6247] got request type 0, id 1
Mar 1 00:16:11.346 [6247] bind dn = cn=admin,dc=example,dc=com
Mar 1 00:16:11.346 [6247] successfully authenticated as cn=admin,dc=example,dc=com
Mar 1 00:16:11.346 [6247] sending response 1 with result 0
Mar 1 00:16:11.347 [6247] consumed 56469 bytes
Mar 1 00:16:11.347 [6247] got request type 8, id 2
Mar 1 00:16:11.347 [6247] adding entry cn=robert smith,ou=people,dc=example,dc=com
Mar 1 00:16:11.347 [6247] cn=robert smith,ou=people,dc=example,dc=com: already exists
Mar 1 00:16:11.347 [6247] sending response 9 with result 68
Mar 1 00:16:11.348 [6247] consumed 7 bytes
Mar 1 00:16:11.348 [6247] got request type 2, id 3
Mar 1 00:16:11.348 [6247] current bind dn = cn=admin,dc=example,dc=com
Mar 1 00:16:11.348 [6247] end-of-file on connection 11
Mar 1 00:16:11.348 [6247] closing connection 11
Mar 1 00:16:35.836 [6247] accepted connection from 127.0.0.1 on fd 11
Mar 1 00:16:35.836 [6247] conn_tls_init: switching to TLS
Mar 1 00:16:35.872 [6247] consumed 46 bytes
Mar 1 00:16:35.872 [6247] got request type 0, id 1
Mar 1 00:16:35.873 [6247] bind dn = cn=admin,dc=example,dc=com
Mar 1 00:16:35.873 [6247] successfully authenticated as cn=admin,dc=example,dc=com
Mar 1 00:16:35.873 [6247] sending response 1 with result 0
Mar 1 00:16:35.874 [6247] consumed 56472 bytes
Mar 1 00:16:35.874 [6247] got request type 8, id 2
Mar 1 00:16:35.874 [6247] adding entry cn=robert1 smith,ou=people,dc=example,dc=com
Mar 1 00:16:35.874 [6247] indexing cn=robert1 smith,ou=people,dc=example,dc=com on objectClass
Mar 1 00:16:35.874 [6247] indexing cn=robert1 smith,ou=people,dc=example,dc=com on cn
Mar 1 00:16:35.874 [6247] indexing cn=robert1 smith,ou=people,dc=example,dc=com on ou
Mar 1 00:16:35.874 [6247] indexing cn=robert1 smith,ou=people,dc=example,dc=com on uid
Mar 1 00:16:35.874 [6247] indexing cn=robert1 smith,ou=people,dc=example,dc=com on mail
Mar 1 00:16:35.874 [6247] indexing cn=robert1 smith,ou=people,dc=example,dc=com on sn
Mar 1 00:16:35.874 [6247] indexing rdn on @ou=people,cn=robert1 smith
Mar 1 00:16:35.876 [6247] sending response 9 with result 0
Mar 1 00:16:35.876 [6247] consumed 7 bytes
Mar 1 00:16:35.877 [6247] got request type 2, id 3
Mar 1 00:16:35.877 [6247] current bind dn = cn=admin,dc=example,dc=com
Mar 1 00:16:35.877 [6247] closing connection 11
Mar 1 00:19:29.363 [6247] accepted connection from 127.0.0.1 on fd 11
Mar 1 00:19:29.363 [6247] conn_tls_init: switching to TLS
Mar 1 00:19:29.408 [6247] consumed 46 bytes
Mar 1 00:19:29.408 [6247] got request type 0, id 1
Mar 1 00:19:29.408 [6247] bind dn = cn=admin,dc=example,dc=com
Mar 1 00:19:29.408 [6247] successfully authenticated as cn=admin,dc=example,dc=com
Mar 1 00:19:29.408 [6247] sending response 1 with result 0
Mar 1 00:19:29.409 [6247] consumed 94 bytes
Mar 1 00:19:29.409 [6247] got request type 3, id 2
Mar 1 00:19:29.409 [6247] base dn = cn=robert1 smith,ou=people,dc=example,dc=com, scope = 2
Mar 1 00:19:29.409 [6247] init full scan
Mar 1 00:19:29.409 [6247] found dn cn=robert1 smith,ou=people,dc=example,dc=com
Mar 1 00:19:29.410 [6247] found dn cn=robert smith,ou=people,dc=example,dc=com
Mar 1 00:19:29.410 [6247] scanned past basedn suffix
Mar 1 00:19:29.410 [6247] 2 scanned, 1 matched, 0 dups
Mar 1 00:19:29.410 [6247] sending response 5 with result 0
Mar 1 00:19:29.410 [6247] search failed: Invalid argument
Mar 1 00:19:29.410 [6247] finished search on msgid 2
Mar 1 00:19:29.412 [6247] consumed 7 bytes
Mar 1 00:19:29.412 [6247] got request type 2, id 3
Mar 1 00:19:29.412 [6247] current bind dn = cn=admin,dc=example,dc=com
Mar 1 00:19:29.412 [6247] end-of-file on connection 11
Mar 1 00:19:29.412 [6247] closing connection 11
Gleydson Soares
2017-03-01 04:25:20 UTC
Permalink
Forgot to mention openldap-client version:
I've installed from OpenBSD ports (-current)

% pkg_info openldap-client
Information for inst:openldap-client-2.4.44p3

% ldapadd -VV
ldapadd: @(#) $OpenLDAP: ldapmodify 2.4.44 (Feb 21 2017 14:12:00) $
@amd64-2.ports.openbsd.org:/usr/obj/ports/openldap-2.4.44/build-amd64/clients/tools
(LDAP library: OpenLDAP 20444)
Post by Gleydson Soares
Hi,
I can't reproduce... this just works fine here without hangs,
I'm using OpenBSD -current, ldapd(as of today) + TLS (self-signed
TLS certificate).
http://shutupandhack.org/~gsoares/tmp/1.ldif
http://shutupandhack.org/~gsoares/tmp/2.ldif
http://shutupandhack.org/~gsoares/tmp/sample.jpeg
could you try to reproduce using the files above?
let me know if I missed anything.
*ldif*
dn: cn=Robert1 Smith,ou=people,dc=example,dc=com
objectclass: inetOrgPerson
cn: Robert1 Smith
cn: Robert1 J Smith
cn: bob smith
sn: smith
uid: rjsmith
## Please specify a file that would cause conn_read() to be called
## multiple times. I tried around 2KB, 3KB, 5KB and 13KB files for
## jpegPhoto attribute.
jpegPhoto:< file:///home/gsoares/sample.jpeg
userpassword: rJsmitH
carlicense: HISCAR 123
homephone: 555-111-2222
description: swell guy
ou: Human Resources
*Adding(no hangs)*
% ldapadd -vv -H ldaps://127.0.0.1 -x -D 'cn=admin,dc=example,dc=com' -w secret -f ./2.ldif
ldap_initialize( ldaps://127.0.0.1:636/??base )
inetOrgPerson
Robert1 Smith
Robert1 J Smith
bob smith
smith
rjsmith
NOT ASCII (56060 bytes)
rJsmitH
HISCAR 123
555-111-2222
swell guy
Human Resources
adding new entry "cn=Robert1 Smith,ou=people,dc=example,dc=com"
modify complete
*Searching*
% ldapsearch -tt -T ./ -LLL -H ldaps://127.0.0.1 -x -D 'cn=admin,dc=example,dc=com' -w secret -b 'cn=Robert1 Smith,ou=people,dc=example,dc=com' jpegPhoto
dn: cn=robert1 smith,ou=people,dc=example,dc=com
jpegPhoto:< file:///.//ldapsearch-jpegPhoto-38ROnW
*ldapd debug*
Mar 1 00:11:30.650 [6247] accepted connection from 127.0.0.1 on fd 11
Mar 1 00:11:30.650 [6247] conn_tls_init: switching to TLS
Mar 1 00:11:30.683 [6247] consumed 46 bytes
Mar 1 00:11:30.683 [6247] got request type 0, id 1
Mar 1 00:11:30.683 [6247] bind dn = cn=admin,dc=example,dc=com
Mar 1 00:11:30.683 [6247] successfully authenticated as cn=admin,dc=example,dc=com
Mar 1 00:11:30.683 [6247] sending response 1 with result 0
Mar 1 00:11:30.684 [6247] consumed 43997 bytes
Mar 1 00:11:30.684 [6247] got request type 8, id 2
Mar 1 00:11:30.684 [6247] adding entry cn=robert smith,ou=people,dc=example,dc=com
Mar 1 00:11:30.685 [6247] indexing cn=robert smith,ou=people,dc=example,dc=com on objectClass
Mar 1 00:11:30.685 [6247] indexing cn=robert smith,ou=people,dc=example,dc=com on cn
Mar 1 00:11:30.685 [6247] indexing cn=robert smith,ou=people,dc=example,dc=com on ou
Mar 1 00:11:30.685 [6247] indexing cn=robert smith,ou=people,dc=example,dc=com on uid
Mar 1 00:11:30.685 [6247] indexing cn=robert smith,ou=people,dc=example,dc=com on mail
Mar 1 00:11:30.685 [6247] indexing cn=robert smith,ou=people,dc=example,dc=com on sn
Mar 1 00:11:30.697 [6247] sending response 9 with result 0
Mar 1 00:11:30.698 [6247] consumed 7 bytes
Mar 1 00:11:30.698 [6247] got request type 2, id 3
Mar 1 00:11:30.698 [6247] current bind dn = cn=admin,dc=example,dc=com
Mar 1 00:11:30.698 [6247] end-of-file on connection 11
Mar 1 00:11:30.698 [6247] closing connection 11
Mar 1 00:16:11.313 [6247] accepted connection from 127.0.0.1 on fd 11
Mar 1 00:16:11.313 [6247] conn_tls_init: switching to TLS
Mar 1 00:16:11.346 [6247] consumed 46 bytes
Mar 1 00:16:11.346 [6247] got request type 0, id 1
Mar 1 00:16:11.346 [6247] bind dn = cn=admin,dc=example,dc=com
Mar 1 00:16:11.346 [6247] successfully authenticated as cn=admin,dc=example,dc=com
Mar 1 00:16:11.346 [6247] sending response 1 with result 0
Mar 1 00:16:11.347 [6247] consumed 56469 bytes
Mar 1 00:16:11.347 [6247] got request type 8, id 2
Mar 1 00:16:11.347 [6247] adding entry cn=robert smith,ou=people,dc=example,dc=com
Mar 1 00:16:11.347 [6247] cn=robert smith,ou=people,dc=example,dc=com: already exists
Mar 1 00:16:11.347 [6247] sending response 9 with result 68
Mar 1 00:16:11.348 [6247] consumed 7 bytes
Mar 1 00:16:11.348 [6247] got request type 2, id 3
Mar 1 00:16:11.348 [6247] current bind dn = cn=admin,dc=example,dc=com
Mar 1 00:16:11.348 [6247] end-of-file on connection 11
Mar 1 00:16:11.348 [6247] closing connection 11
Mar 1 00:16:35.836 [6247] accepted connection from 127.0.0.1 on fd 11
Mar 1 00:16:35.836 [6247] conn_tls_init: switching to TLS
Mar 1 00:16:35.872 [6247] consumed 46 bytes
Mar 1 00:16:35.872 [6247] got request type 0, id 1
Mar 1 00:16:35.873 [6247] bind dn = cn=admin,dc=example,dc=com
Mar 1 00:16:35.873 [6247] successfully authenticated as cn=admin,dc=example,dc=com
Mar 1 00:16:35.873 [6247] sending response 1 with result 0
Mar 1 00:16:35.874 [6247] consumed 56472 bytes
Mar 1 00:16:35.874 [6247] got request type 8, id 2
Mar 1 00:16:35.874 [6247] adding entry cn=robert1 smith,ou=people,dc=example,dc=com
Mar 1 00:16:35.874 [6247] indexing cn=robert1 smith,ou=people,dc=example,dc=com on objectClass
Mar 1 00:16:35.874 [6247] indexing cn=robert1 smith,ou=people,dc=example,dc=com on cn
Mar 1 00:16:35.874 [6247] indexing cn=robert1 smith,ou=people,dc=example,dc=com on ou
Mar 1 00:16:35.874 [6247] indexing cn=robert1 smith,ou=people,dc=example,dc=com on uid
Mar 1 00:16:35.874 [6247] indexing cn=robert1 smith,ou=people,dc=example,dc=com on mail
Mar 1 00:16:35.874 [6247] indexing cn=robert1 smith,ou=people,dc=example,dc=com on sn
Mar 1 00:16:35.876 [6247] sending response 9 with result 0
Mar 1 00:16:35.876 [6247] consumed 7 bytes
Mar 1 00:16:35.877 [6247] got request type 2, id 3
Mar 1 00:16:35.877 [6247] current bind dn = cn=admin,dc=example,dc=com
Mar 1 00:16:35.877 [6247] closing connection 11
Mar 1 00:19:29.363 [6247] accepted connection from 127.0.0.1 on fd 11
Mar 1 00:19:29.363 [6247] conn_tls_init: switching to TLS
Mar 1 00:19:29.408 [6247] consumed 46 bytes
Mar 1 00:19:29.408 [6247] got request type 0, id 1
Mar 1 00:19:29.408 [6247] bind dn = cn=admin,dc=example,dc=com
Mar 1 00:19:29.408 [6247] successfully authenticated as cn=admin,dc=example,dc=com
Mar 1 00:19:29.408 [6247] sending response 1 with result 0
Mar 1 00:19:29.409 [6247] consumed 94 bytes
Mar 1 00:19:29.409 [6247] got request type 3, id 2
Mar 1 00:19:29.409 [6247] base dn = cn=robert1 smith,ou=people,dc=example,dc=com, scope = 2
Mar 1 00:19:29.409 [6247] init full scan
Mar 1 00:19:29.409 [6247] found dn cn=robert1 smith,ou=people,dc=example,dc=com
Mar 1 00:19:29.410 [6247] found dn cn=robert smith,ou=people,dc=example,dc=com
Mar 1 00:19:29.410 [6247] scanned past basedn suffix
Mar 1 00:19:29.410 [6247] 2 scanned, 1 matched, 0 dups
Mar 1 00:19:29.410 [6247] sending response 5 with result 0
Mar 1 00:19:29.410 [6247] search failed: Invalid argument
Mar 1 00:19:29.410 [6247] finished search on msgid 2
Mar 1 00:19:29.412 [6247] consumed 7 bytes
Mar 1 00:19:29.412 [6247] got request type 2, id 3
Mar 1 00:19:29.412 [6247] current bind dn = cn=admin,dc=example,dc=com
Mar 1 00:19:29.412 [6247] end-of-file on connection 11
Mar 1 00:19:29.412 [6247] closing connection 11
Robert Klein
2017-03-01 12:10:51 UTC
Permalink
Hi,

On Wed, 1 Mar 2017 01:25:20 -0300 (BRT)
Post by Gleydson Soares
I've installed from OpenBSD ports (-current)
% pkg_info openldap-client
Information for inst:openldap-client-2.4.44p3
% ldapadd -VV
@amd64-2.ports.openbsd.org:/usr/obj/ports/openldap-2.4.44/build-amd64/clients/tools
(LDAP library: OpenLDAP 20444)
I used

~> ldapadd -VV
ldapadd: @(#) $OpenLDAP: ldapmodify 2.4.41 $
opensuse-***@opensuse.org
(LDAP library: OpenLDAP 20441)


I'd like to use another client to see, if this crops up there, too,
but there don't seem to be many LDAP client libraries around that don't
depend on openLDAP deep in their bowels, unfortunately (except probably
Java JNDI, but let's not go there).


In reply to your other mail, not every image triggers the issue. Could
you try this one: Loading Image... It is 7155
bytes large.


I now tested with a “real” (i.e. not self-certified) certificate, now,
and ldapadd gets stuck, too.


Side note, if you CTRL-C ldapd(8), "ldapadd -v -d7" spits out the
following at the end:

** ld 0x55f6bdcb5770 Outstanding Requests:
* msgid 2, origid 2, status InProgress
outstanding referrals 0, parent count 0
ld 0x55f6bdcb5770 request count 1 (abandoned 0)
** ld 0x55f6bdcb5770 Response Queue:
Empty
ld 0x55f6bdcb5770 response count 0
ldap_chkResponseList ld 0x55f6bdcb5770 msgid 2 all 1
ldap_chkResponseList returns ld 0x55f6bdcb5770 NULL
ldap_int_select
read1msg: ld 0x55f6bdcb5770 msgid 2 all 1
ber_get_next
tls_read: want=5, got=0

ldap_read: want=8, got=0

ldap_err2string
ldap_result: Can't contact LDAP server (-1)
ldap_free_request (origid 2, msgid 2)
ldap_free_connection 1 1
tls_write: want=31, written=31
0000: 15 03 03 00 1a 4c 46 29 c5 c3 4a 16 e8 c2 d3
61 .....LF)..J....a 0010: ef c6 c0 d0 5d a5 40 ad 7b 23 db e2 88 4f
39 ....]***@.{#...O9 TLS trace: SSL3 alert write:warning:close notify
ldap_free_connection: actually freed
tls_read: want=5 error=Bad file descriptor
add objectclass:
inetOrgPerson
add cn:
Robert Smith
Robert J Smith
bob smith
add sn:
smith
add uid:
rjsmith
add jpegPhoto:
NOT ASCII (7155 bytes)
add userpassword:
rJsmitH
add carlicense:
HISCAR 123
add homephone:
555-111-2222
add mail:
***@example.com
***@example.com
***@example.com
add description:
swell guy
add ou:
Human Resources
adding new entry "cn=Robert Smith,ou=people,dc=example,dc=com"



Best regards
Robert
Post by Gleydson Soares
Post by Gleydson Soares
Hi,
I can't reproduce... this just works fine here without hangs,
I'm using OpenBSD -current, ldapd(as of today) + TLS (self-signed
TLS certificate).
http://shutupandhack.org/~gsoares/tmp/1.ldif
http://shutupandhack.org/~gsoares/tmp/2.ldif
http://shutupandhack.org/~gsoares/tmp/sample.jpeg
could you try to reproduce using the files above?
let me know if I missed anything.
*ldif*
dn: cn=Robert1 Smith,ou=people,dc=example,dc=com
objectclass: inetOrgPerson
cn: Robert1 Smith
cn: Robert1 J Smith
cn: bob smith
sn: smith
uid: rjsmith
## Please specify a file that would cause conn_read() to be called
## multiple times. I tried around 2KB, 3KB, 5KB and 13KB files for
## jpegPhoto attribute.
jpegPhoto:< file:///home/gsoares/sample.jpeg
userpassword: rJsmitH
carlicense: HISCAR 123
homephone: 555-111-2222
description: swell guy
ou: Human Resources
*Adding(no hangs)*
% ldapadd -vv -H ldaps://127.0.0.1 -x -D
'cn=admin,dc=example,dc=com' -w secret -f ./2.ldif
inetOrgPerson
Robert1 Smith
Robert1 J Smith
bob smith
smith
rjsmith
NOT ASCII (56060 bytes)
rJsmitH
HISCAR 123
555-111-2222
swell guy
Human Resources
adding new entry "cn=Robert1 Smith,ou=people,dc=example,dc=com"
modify complete
*Searching*
% ldapsearch -tt -T ./ -LLL -H ldaps://127.0.0.1 -x -D
'cn=admin,dc=example,dc=com' -w secret -b 'cn=Robert1
Smith,ou=people,dc=example,dc=com' jpegPhoto dn: cn=robert1
smith,ou=people,dc=example,dc=com jpegPhoto:<
file:///.//ldapsearch-jpegPhoto-38ROnW
*ldapd debug*
Mar 1 00:11:30.650 [6247] accepted connection from 127.0.0.1 on fd
11 Mar 1 00:11:30.650 [6247] conn_tls_init: switching to TLS
Mar 1 00:11:30.683 [6247] consumed 46 bytes
Mar 1 00:11:30.683 [6247] got request type 0, id 1
Mar 1 00:11:30.683 [6247] bind dn = cn=admin,dc=example,dc=com
Mar 1 00:11:30.683 [6247] successfully authenticated as
cn=admin,dc=example,dc=com Mar 1 00:11:30.683 [6247] sending
response 1 with result 0 Mar 1 00:11:30.684 [6247] consumed 43997
bytes Mar 1 00:11:30.684 [6247] got request type 8, id 2
Mar 1 00:11:30.684 [6247] adding entry cn=robert
smith,ou=people,dc=example,dc=com Mar 1 00:11:30.685 [6247]
indexing cn=robert smith,ou=people,dc=example,dc=com on objectClass
Mar 1 00:11:30.685 [6247] indexing cn=robert
smith,ou=people,dc=example,dc=com on cn Mar 1 00:11:30.685 [6247]
indexing cn=robert smith,ou=people,dc=example,dc=com on ou Mar 1
00:11:30.685 [6247] indexing cn=robert
smith,ou=people,dc=example,dc=com on uid Mar 1 00:11:30.685 [6247]
indexing cn=robert smith,ou=people,dc=example,dc=com on mail Mar 1
00:11:30.685 [6247] indexing cn=robert
smith,ou=people,dc=example,dc=com on sn Mar 1 00:11:30.685 [6247]
[6247] sending response 9 with result 0 Mar 1 00:11:30.698 [6247]
consumed 7 bytes Mar 1 00:11:30.698 [6247] got request type 2, id
3 Mar 1 00:11:30.698 [6247] current bind dn =
cn=admin,dc=example,dc=com Mar 1 00:11:30.698 [6247] end-of-file
on connection 11 Mar 1 00:11:30.698 [6247] closing connection 11
Mar 1 00:16:11.313 [6247] accepted connection from 127.0.0.1 on fd
11 Mar 1 00:16:11.313 [6247] conn_tls_init: switching to TLS Mar
1 00:16:11.346 [6247] consumed 46 bytes Mar 1 00:16:11.346 [6247]
got request type 0, id 1 Mar 1 00:16:11.346 [6247] bind dn =
cn=admin,dc=example,dc=com Mar 1 00:16:11.346 [6247] successfully
authenticated as cn=admin,dc=example,dc=com Mar 1 00:16:11.346
[6247] sending response 1 with result 0 Mar 1 00:16:11.347 [6247]
consumed 56469 bytes Mar 1 00:16:11.347 [6247] got request type 8,
id 2 Mar 1 00:16:11.347 [6247] adding entry cn=robert
smith,ou=people,dc=example,dc=com Mar 1 00:16:11.347 [6247]
cn=robert smith,ou=people,dc=example,dc=com: already exists Mar 1
00:16:11.347 [6247] sending response 9 with result 68 Mar 1
00:16:11.348 [6247] consumed 7 bytes Mar 1 00:16:11.348 [6247] got
request type 2, id 3 Mar 1 00:16:11.348 [6247] current bind dn =
cn=admin,dc=example,dc=com Mar 1 00:16:11.348 [6247] end-of-file
on connection 11 Mar 1 00:16:11.348 [6247] closing connection 11
Mar 1 00:16:35.836 [6247] accepted connection from 127.0.0.1 on fd
11 Mar 1 00:16:35.836 [6247] conn_tls_init: switching to TLS Mar
1 00:16:35.872 [6247] consumed 46 bytes Mar 1 00:16:35.872 [6247]
got request type 0, id 1 Mar 1 00:16:35.873 [6247] bind dn =
cn=admin,dc=example,dc=com Mar 1 00:16:35.873 [6247] successfully
authenticated as cn=admin,dc=example,dc=com Mar 1 00:16:35.873
[6247] sending response 1 with result 0 Mar 1 00:16:35.874 [6247]
consumed 56472 bytes Mar 1 00:16:35.874 [6247] got request type 8,
id 2 Mar 1 00:16:35.874 [6247] adding entry cn=robert1
smith,ou=people,dc=example,dc=com Mar 1 00:16:35.874 [6247]
indexing cn=robert1 smith,ou=people,dc=example,dc=com on
objectClass Mar 1 00:16:35.874 [6247] indexing cn=robert1
smith,ou=people,dc=example,dc=com on cn Mar 1 00:16:35.874 [6247]
indexing cn=robert1 smith,ou=people,dc=example,dc=com on ou Mar 1
00:16:35.874 [6247] indexing cn=robert1
smith,ou=people,dc=example,dc=com on uid Mar 1 00:16:35.874 [6247]
indexing cn=robert1 smith,ou=people,dc=example,dc=com on mail Mar
1 00:16:35.874 [6247] indexing cn=robert1
smith,ou=people,dc=example,dc=com on sn Mar 1 00:16:35.874 [6247]
[6247] sending response 9 with result 0 Mar 1 00:16:35.876 [6247]
consumed 7 bytes Mar 1 00:16:35.877 [6247] got request type 2, id
3 Mar 1 00:16:35.877 [6247] current bind dn =
cn=admin,dc=example,dc=com Mar 1 00:16:35.877 [6247] closing
connection 11 Mar 1 00:19:29.363 [6247] accepted connection from
switching to TLS Mar 1 00:19:29.408 [6247] consumed 46 bytes Mar
1 00:19:29.408 [6247] got request type 0, id 1 Mar 1 00:19:29.408
[6247] bind dn = cn=admin,dc=example,dc=com Mar 1 00:19:29.408
[6247] successfully authenticated as cn=admin,dc=example,dc=com
Mar 1 00:19:29.408 [6247] sending response 1 with result 0 Mar 1
00:19:29.409 [6247] consumed 94 bytes Mar 1 00:19:29.409 [6247]
got request type 3, id 2 Mar 1 00:19:29.409 [6247] base dn =
cn=robert1 smith,ou=people,dc=example,dc=com, scope = 2 Mar 1
00:19:29.409 [6247] init full scan Mar 1 00:19:29.409 [6247] found
dn cn=robert1 smith,ou=people,dc=example,dc=com Mar 1 00:19:29.410
[6247] found dn cn=robert smith,ou=people,dc=example,dc=com Mar 1
00:19:29.410 [6247] scanned past basedn suffix Mar 1 00:19:29.410
[6247] 2 scanned, 1 matched, 0 dups Mar 1 00:19:29.410 [6247]
sending response 5 with result 0 Mar 1 00:19:29.410 [6247] search
failed: Invalid argument Mar 1 00:19:29.410 [6247] finished search
on msgid 2 Mar 1 00:19:29.412 [6247] consumed 7 bytes Mar 1
00:19:29.412 [6247] got request type 2, id 3 Mar 1 00:19:29.412
[6247] current bind dn = cn=admin,dc=example,dc=com Mar 1
00:19:29.412 [6247] end-of-file on connection 11 Mar 1
00:19:29.412 [6247] closing connection 11
Gleydson Soares
2017-03-02 18:51:04 UTC
Permalink
Post by Robert Klein
In reply to your other mail, not every image triggers the issue. Could
you try this one: http://www.roklein.de/new_theory_logo.jpg It is 7155
bytes large.
oddly, i reproduced using the jpeg you provided.
i'll take a closer look at it tonight. thanks for the details.
Robert Klein
2017-03-02 19:39:53 UTC
Permalink
On Thu, 2 Mar 2017 15:51:04 -0300 (BRT)
Post by Gleydson Soares
Post by Robert Klein
In reply to your other mail, not every image triggers the issue.
Could you try this one: http://www.roklein.de/new_theory_logo.jpg
It is 7155 bytes large.
oddly, i reproduced using the jpeg you provided.
i'll take a closer look at it tonight. thanks for the details.
just note, the issue doesn't show up with my jpeg on older OpenBSD
versions I tested (5.9, 5.8, 5.5).

It might be a corner case overlooked by the current libtls code; 5.9
still used libssl.

Best regards
Robert
Gleydson Soares
2017-03-02 21:08:45 UTC
Permalink
Post by Robert Klein
Post by Gleydson Soares
Post by Robert Klein
In reply to your other mail, not every image triggers the issue.
Could you try this one: http://www.roklein.de/new_theory_logo.jpg
It is 7155 bytes large.
oddly, i reproduced using the jpeg you provided.
i'll take a closer look at it tonight. thanks for the details.
just note, the issue doesn't show up with my jpeg on older OpenBSD
versions I tested (5.9, 5.8, 5.5).
It might be a corner case overlooked by the current libtls code; 5.9
still used libssl.
Yes, it's using libtls and evbuffer_tls(came from syslogd).

I did some tests and I think this hangs with jpeg >=4k and <=15k,
other image sizes not triggers the issue.
..weird

could you try this diff? meanwhile i'll dig a bit more.
thanks,

diff --git a/evbuffer_tls.c b/evbuffer_tls.c
index 1fec73e..28faea8 100644
--- a/evbuffer_tls.c
+++ b/evbuffer_tls.c
@@ -314,7 +314,7 @@ evtls_read(struct evbuffer *buf, int fd, int howmuch, struct tls *ctx)
n = EVBUFFER_MAX_READ;
}
if (howmuch < 0 || howmuch > n)
- howmuch = n;
+ howmuch = n << 2;

/* If we don't have FIONREAD, we might waste some space here */
if (evbuffer_expand(buf, howmuch) == -1)
Alexander Bluhm
2017-03-02 21:43:41 UTC
Permalink
Post by Gleydson Soares
Yes, it's using libtls and evbuffer_tls(came from syslogd).
I have copied it from libevent and adapted it to tls.
Post by Gleydson Soares
I did some tests and I think this hangs with jpeg >=4k and <=15k,
other image sizes not triggers the issue.
..weird
libevent uses 4k read blocks and libssl 16k blocks internally.
This is at least inefficent and I guess could lead to hangs.

Could you test this diff?

bluhm

Index: usr.sbin/ldapd/evbuffer_tls.c
===================================================================
RCS file: /data/mirror/openbsd/cvs/src/usr.sbin/ldapd/evbuffer_tls.c,v
retrieving revision 1.1
diff -u -p -r1.1 evbuffer_tls.c
--- usr.sbin/ldapd/evbuffer_tls.c 1 May 2016 00:32:37 -0000 1.1
+++ usr.sbin/ldapd/evbuffer_tls.c 2 Mar 2017 21:36:35 -0000
@@ -289,7 +289,7 @@ buffertls_connect(struct buffertls *buft
* Reads data from a file descriptor into a buffer.
*/

-#define EVBUFFER_MAX_READ 4096
+#define EVBUFFER_MAX_READ 16384

int
evtls_read(struct evbuffer *buf, int fd, int howmuch, struct tls *ctx)
Robert Klein
2017-03-03 10:45:19 UTC
Permalink
On Thu, 2 Mar 2017 22:43:41 +0100
Post by Alexander Bluhm
Post by Gleydson Soares
Yes, it's using libtls and evbuffer_tls(came from syslogd).
I have copied it from libevent and adapted it to tls.
Post by Gleydson Soares
I did some tests and I think this hangs with jpeg >=4k and <=15k,
other image sizes not triggers the issue.
..weird
libevent uses 4k read blocks and libssl 16k blocks internally.
This is at least inefficent and I guess could lead to hangs.
Could you test this diff?
The issue still shows up, but more erratically: When you can't ldapadd
with a certain image size it may well work when you try a second time
(at least for small size; see below).

First, when using ldap instead of ldaps all image sizes up to at least
70000 bytes succeed (that is the maximum size I tested).

When using ldaps it hangs at different image sizes. I had hangs at:
4339, 4603, 3600, 3179, 3414, 3700, and 5239 byte-sized images using the
script attached, using the default values.

When trying image sizes from upwards down, e.g.:
FIRST_IMAGE_SIZE=48750 LAST_IMAGE_SIZE=10000 DEBUG= ./test2.sh

(test script attached)

I found there seems to be a boundary 16384*n - 409 and less for 16K
sizes where ldapadd may fail:

size 16500 and lower had failures at image sizes of:
- 15974
- 15975 (almost always 15975)

size 33000 and lower (I lowered the upper limit after the first couple
of times):
- 32358
- 32359 (almost always 32358)

size 49152 and lower:
- 48743 (thrice)
- 48742 (twice)
- 48733 (once)
- 48742 (once)

size 65536 and lower (order of appearance):
- 65126
- 65121
- 65126
- 65127
- 65117
- 65124
- 65112
- 65117
- 65122
- 65124
- 65119
- 65125
- 65126
- 65116
- 65117


I also checked sizes around 8K; failures above and below (8163,
8297, 8187) with a command line of

FIRST_IMAGE_SIZE=8200 LAST_IMAGE_SIZE=1 DEBUG= ./test2.sh


ldapadd trace always shows a repeated output of
--- snip ---
poll([{fd=4, events=POLLIN|POLLPRI}], 1, 100) = 0 (Timeout)
--- snip ---

or, with debugging enabled:

--- snip ---
poll([{fd=4, events=POLLIN|POLLPRI}], 1, 100) = 0 (Timeout)
write(2, "ldap_result ld 0x563bac634770 ms"..., 38) = 38
write(2, "wait4msg ld 0x563bac634770 msgid"..., 57) = 57
write(2, "wait4msg continue ld 0x563bac634"..., 50) = 50
write(2, "** ld 0x563bac634770 Connections"..., 34) = 34
write(2, "* host: r310 port: 636 (defaul"..., 35) = 35
write(2, " refcnt: 2 status: Connected\n", 31) = 31
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
write(2, " last used: Fri Mar 3 08:26:00"..., 39) = 39
write(2, "\n", 1) = 1
write(2, "** ld 0x563bac634770 Outstanding"..., 43) = 43
write(2, " * msgid 2, origid 2, status In"..., 41) = 41
write(2, " outstanding referrals 0, pare"..., 43) = 43
write(2, " ld 0x563bac634770 request coun"..., 50) = 50
write(2, "** ld 0x563bac634770 Response Qu"..., 37) = 37
write(2, " Empty\n", 9) = 9
write(2, " ld 0x563bac634770 response cou"..., 37) = 37
write(2, "ldap_chkResponseList ld 0x563bac"..., 53) = 53
write(2, "ldap_chkResponseList returns ld "..., 52) = 52
write(2, "ldap_int_select\n", 16) = 16
poll([{fd=4, events=POLLIN|POLLPRI}], 1, 100^CProcess 22140 detached
--- snip ---

Best regards
Robert
Post by Alexander Bluhm
bluhm
Index: usr.sbin/ldapd/evbuffer_tls.c
===================================================================
RCS file: /data/mirror/openbsd/cvs/src/usr.sbin/ldapd/evbuffer_tls.c,v
retrieving revision 1.1
diff -u -p -r1.1 evbuffer_tls.c
--- usr.sbin/ldapd/evbuffer_tls.c 1 May 2016 00:32:37
-0000 1.1 +++ usr.sbin/ldapd/evbuffer_tls.c 2 Mar 2017
*buft
* Reads data from a file descriptor into a buffer.
*/
-#define EVBUFFER_MAX_READ 4096
+#define EVBUFFER_MAX_READ 16384
int
evtls_read(struct evbuffer *buf, int fd, int howmuch, struct tls *ctx)
Seiya Kawashima
2017-05-05 18:05:28 UTC
Permalink
Thank you for spending time on this issue.


I spent some time to work on this ldapd(8) hang issue again. It would be appreciated
if I could get some clarification on my modification. With my modification,
test2.sh from Robert Klein works without any hangs from 1 to 16500 bytes of data.


This issue seems to be caused by a size mismatch between ber_read_element() on
ber.c and the size of LDAP messages that ldapd(8) receives from the client such
as ldapadd(1). This happens once tls_read() in evtls_read() returns
TLS_WANT_POLLIN. The buffer to receive the LDAP messages is set by ioctl(2) in
evtls_read().

if (ioctl(fd, FIONREAD, &n) == -1 || n <= 0) {
...
if (howmuch < 0 || howmuch > n)
howmuch = n;
...
/* If we don't have FIONREAD, we might waste some space here */
if (evbuffer_expand(buf, howmuch) == -1)
return (-1);
...
/* We can append new data at this point */
p = buf->buffer + buf->off;
...
n = tls_read(ctx, p, howmuch);


To see the mismatch, I put several printf() calls on conn.c and
evbuffer_tls.c. The outputs are like below and the lines starting with '*'
are from the printf().

May 5 12:13:05.512 [82850] conn_tls_init: switching to TLS

* n: 46 howmuch: 75 for evbuffer_expand() and tls_read() in evtls_read,333,evbuffer_tls.c
*EVBUFFER_LENGTH(bufev->input): 46 fd: 17 howmuch: -1 in buffertls_readcb,101,evbuffer_tls.c
read ber elements, root 0x19b04aae7700
...
May 5 12:13:05.539 [82850] consumed 46 bytes
...
write ber element of 14 bytes length
*EVBUFFER_LENGTH(input): 46 nused: 46 before evbuffer_drain() in conn_read,210,conn.c
*EVBUFFER_LENGTH(input): 0 nused: 46 after evbuffer_drain() in conn_read,213,conn.c

* n: -2 howmuch: 2856 for evbuffer_expand() and tls_read() in evtls_read,333,evbuffer_tls.c
*EVBUFFER_LENGTH(bufev->input): 0 fd: 17 howmuch: -1 in buffertls_readcb,101,evbuffer_tls.c
*res from evtls_read() == TLS_WANT_POLLIN in buffertls_readcb,105,evbuffer_tls.c

* n: 1066 howmuch: 1066 for evbuffer_expand() and tls_read() in evtls_read,333,evbuffer_tls.c
*EVBUFFER_LENGTH(bufev->input): 1066 fd: 17 howmuch: -1 in buffertls_readcb,101,evbuffer_tls.c
read ber elements, root 0x19b04aae7e00
ber read got class 0 type 16, constructive
ber read element size 3889
*EVBUFFER_LENGTH(input): 1066 nused: 0 before evbuffer_drain() in conn_read,210,conn.c
*EVBUFFER_LENGTH(input): 1066 nused: 0 after evbuffer_drain() in conn_read,213,conn.c
^CMay 5 12:14:05.967 [82850] May 5 12:14:05.967 [47727] ldape: got signal 2
...
May 5 12:14:05.968 [82850] ldape: exiting


The diffs for the printf() calls are

Index: conn.c
===================================================================
RCS file: /cvs/src/usr.sbin/ldapd/conn.c,v
retrieving revision 1.14
diff -u -p -r1.14 conn.c
--- conn.c 20 Jan 2017 11:55:08 -0000 1.14
+++ conn.c 5 May 2017 14:33:50 -0000
@@ -206,7 +206,11 @@ conn_read(struct bufferevent *bev, void
break;
}

+ printf("*EVBUFFER_LENGTH(input): %zu nused: %zu before evbuffer_drain() in %s,%d,%s\n",
+ EVBUFFER_LENGTH(input),nused,__func__,__LINE__,__FILE__);
evbuffer_drain(input, nused);
+ printf("*EVBUFFER_LENGTH(input): %zu nused: %zu after evbuffer_drain() in %s,%d,%s\n",
+ EVBUFFER_LENGTH(input),nused,__func__,__LINE__,__FILE__);
}

Index: evbuffer_tls.c
===================================================================
RCS file: /cvs/src/usr.sbin/ldapd/evbuffer_tls.c,v
retrieving revision 1.2
diff -u -p -r1.2 evbuffer_tls.c
--- evbuffer_tls.c 3 Mar 2017 20:26:23 -0000 1.2
+++ evbuffer_tls.c 5 May 2017 14:33:50 -0000
@@ -97,8 +97,12 @@ buffertls_readcb(int fd, short event, vo
}

res = evtls_read(bufev->input, fd, howmuch, ctx);
+ printf("*EVBUFFER_LENGTH(bufev->input): %zu fd: %d howmuch: %d in %s,%d,%s\n",
+ EVBUFFER_LENGTH(bufev->input),fd,howmuch,__func__,__LINE__,__FILE__);
switch (res) {
case TLS_WANT_POLLIN:
+ printf("*res from evtls_read() == TLS_WANT_POLLIN in %s,%d,%s\n",
+ __func__,__LINE__,__FILE__);
bufferevent_add(&bufev->ev_read, bufev->timeout_read);
return;
case TLS_WANT_POLLOUT:

@@ -324,6 +328,10 @@ evtls_read(struct evbuffer *buf, int fd,
p = buf->buffer + buf->off;

n = tls_read(ctx, p, howmuch);
+
+ printf("\n* n: %d howmuch: %d for evbuffer_expand() and tls_read() in %s,%d,%s\n",
+ n,howmuch,__func__,__LINE__,__FILE__);
+
if (n <= 0)
return (n);


2856 bytes of data from the client was missing. It was not accumulated correctly when
evtls_read() was called again. The LDAP client did send the data and ldapd(8) did receive
the data but somehow ldapd(8) didn't store the data. As the result, the client was waiting for
the response and ldapd(8) was also waiting for more data from the client to read the entire
LDAP message.

*EVBUFFER_LENGTH(bufev->input): 1066 fd: 17 howmuch: -1 in buffertls_readcb,101,evbuffer_tls.c
...
ber read element size 3889
*EVBUFFER_LENGTH(input): 1066 nused: 0 before evbuffer_drain() in conn_read,210,conn.c
*EVBUFFER_LENGTH(input): 1066 nused: 0 after evbuffer_drain() in conn_read,213,conn.c

ldapd(8) needed 3889 bytes of data but it had only 1066 bytes of data in the buffer.


Then I started to change howmuch, the buffer size, in evtls_read() adding 1,10,100 and
others to the size of the immediately available data for reading. However I still had hangs.
Eventually I used EVBUFFER_MAX_READ as the buffer size without ioctl(2) like below.
It didn't hang at this time. The output with my modification is as follows:

May 5 12:28:58.766 [52462] conn_tls_init: switching to TLS

* n: 46 howmuch: 16384 for evbuffer_expand() and tls_read() in evtls_read,319,evbuffer_tls.c
*EVBUFFER_LENGTH(bufev->input): 46 fd: 17 howmuch: -1 in buffertls_readcb,101,evbuffer_tls.c
read ber elements, root 0x1f0e5a06dc80
...
May 5 12:28:58.793 [52462] consumed 46 bytes
...
write ber element of 14 bytes length
*EVBUFFER_LENGTH(input): 46 nused: 46 before evbuffer_drain() in conn_read,210,conn.c
*EVBUFFER_LENGTH(input): 0 nused: 46 after evbuffer_drain() in conn_read,213,conn.c

* n: -2 howmuch: 16384 for evbuffer_expand() and tls_read() in evtls_read,319,evbuffer_tls.c
*EVBUFFER_LENGTH(bufev->input): 0 fd: 17 howmuch: -1 in buffertls_readcb,101,evbuffer_tls.c
*res from evtls_read() == TLS_WANT_POLLIN in buffertls_readcb,105,evbuffer_tls.c

* n: 3893 howmuch: 16384 for evbuffer_expand() and tls_read() in evtls_read,319,evbuffer_tls.c
*EVBUFFER_LENGTH(bufev->input): 3893 fd: 17 howmuch: -1 in buffertls_readcb,101,evbuffer_tls.c
read ber elements, root 0x1f0e82f35780
ber read got class 0 type 16, constructive
ber read element size 3889
...
May 5 12:28:58.795 [52462] consumed 3893 bytes
May 5 12:28:58.795 [52462] got request type 8, id 2
May 5 12:28:58.795 [52462] adding entry cn=robert 3 smith,ou=people,dc=example,dc=com
btree_txn_begin:666: taking write lock on txn 0x1f0e405804a0
...
*EVBUFFER_LENGTH(input): 3893 nused: 3893 before evbuffer_drain() in conn_read,210,conn.c
*EVBUFFER_LENGTH(input): 0 nused: 3893 after evbuffer_drain() in conn_read,213,conn.c

I'm not quite sure if this is the right way to fix the issue but it looks like that
this issue is related to how ldapd(8) buffers LDAP messages from the client.


Index: evbuffer_tls.c
===================================================================
RCS file: /cvs/src/usr.sbin/ldapd/evbuffer_tls.c,v
retrieving revision 1.2
diff -u -p -r1.2 evbuffer_tls.c
--- evbuffer_tls.c 3 Mar 2017 20:26:23 -0000 1.2
+++ evbuffer_tls.c 5 May 2017 16:03:04 -0000
@@ -296,25 +296,9 @@ evtls_read(struct evbuffer *buf, int fd,
{
u_char *p;
size_t oldoff = buf->off;
- int n = EVBUFFER_MAX_READ;

- if (ioctl(fd, FIONREAD, &n) == -1 || n <= 0) {
- n = EVBUFFER_MAX_READ;
- } else if (n > EVBUFFER_MAX_READ && n > howmuch) {
- /*
- * It's possible that a lot of data is available for
- * reading. We do not want to exhaust resources
- * before the reader has a chance to do something
- * about it. If the reader does not tell us how much
- * data we should read, we artifically limit it.
- */
- if ((size_t)n > buf->totallen << 2)
- n = buf->totallen << 2;
- if (n < EVBUFFER_MAX_READ)
- n = EVBUFFER_MAX_READ;
- }
- if (howmuch < 0 || howmuch > n)
- howmuch = n;
+ if (howmuch < 0 || howmuch > EVBUFFER_MAX_READ)
+ howmuch = EVBUFFER_MAX_READ;

/* If we don't have FIONREAD, we might waste some space here */
if (evbuffer_expand(buf, howmuch) == -1)
@@ -323,7 +307,7 @@ evtls_read(struct evbuffer *buf, int fd,
/* We can append new data at this point */
p = buf->buffer + buf->off;

- n = tls_read(ctx, p, howmuch);
+ int n = tls_read(ctx, p, howmuch);
if (n <= 0)
return (n);

Thank you
Seiya

________________________________________
From: Robert Klein [***@roklein.de]
Sent: Friday, March 03, 2017 4:45 AM
To: Alexander Bluhm
Cc: Gleydson Soares; Seiya Kawashima; ***@openbsd.org; ***@openbsd.org
Subject: Re: ldapd(8) hangs when receiving large data

On Thu, 2 Mar 2017 22:43:41 +0100
Post by Alexander Bluhm
Post by Gleydson Soares
Yes, it's using libtls and evbuffer_tls(came from syslogd).
I have copied it from libevent and adapted it to tls.
Post by Gleydson Soares
I did some tests and I think this hangs with jpeg >=4k and <=15k,
other image sizes not triggers the issue.
..weird
libevent uses 4k read blocks and libssl 16k blocks internally.
This is at least inefficent and I guess could lead to hangs.
Could you test this diff?
The issue still shows up, but more erratically: When you can't ldapadd
with a certain image size it may well work when you try a second time
(at least for small size; see below).

First, when using ldap instead of ldaps all image sizes up to at least
70000 bytes succeed (that is the maximum size I tested).

When using ldaps it hangs at different image sizes. I had hangs at:
4339, 4603, 3600, 3179, 3414, 3700, and 5239 byte-sized images using the
script attached, using the default values.

When trying image sizes from upwards down, e.g.:
FIRST_IMAGE_SIZE=48750 LAST_IMAGE_SIZE=10000 DEBUG= ./test2.sh

(test script attached)

I found there seems to be a boundary 16384*n - 409 and less for 16K
sizes where ldapadd may fail:

size 16500 and lower had failures at image sizes of:
- 15974
- 15975 (almost always 15975)

size 33000 and lower (I lowered the upper limit after the first couple
of times):
- 32358
- 32359 (almost always 32358)

size 49152 and lower:
- 48743 (thrice)
- 48742 (twice)
- 48733 (once)
- 48742 (once)

size 65536 and lower (order of appearance):
- 65126
- 65121
- 65126
- 65127
- 65117
- 65124
- 65112
- 65117
- 65122
- 65124
- 65119
- 65125
- 65126
- 65116
- 65117


I also checked sizes around 8K; failures above and below (8163,
8297, 8187) with a command line of

FIRST_IMAGE_SIZE=8200 LAST_IMAGE_SIZE=1 DEBUG= ./test2.sh


ldapadd trace always shows a repeated output of
--- snip ---
poll([{fd=4, events=POLLIN|POLLPRI}], 1, 100) = 0 (Timeout)
--- snip ---

or, with debugging enabled:

--- snip ---
poll([{fd=4, events=POLLIN|POLLPRI}], 1, 100) = 0 (Timeout)
write(2, "ldap_result ld 0x563bac634770 ms"..., 38) = 38
write(2, "wait4msg ld 0x563bac634770 msgid"..., 57) = 57
write(2, "wait4msg continue ld 0x563bac634"..., 50) = 50
write(2, "** ld 0x563bac634770 Connections"..., 34) = 34
write(2, "* host: r310 port: 636 (defaul"..., 35) = 35
write(2, " refcnt: 2 status: Connected\n", 31) = 31
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2335, ...}) = 0
write(2, " last used: Fri Mar 3 08:26:00"..., 39) = 39
write(2, "\n", 1) = 1
write(2, "** ld 0x563bac634770 Outstanding"..., 43) = 43
write(2, " * msgid 2, origid 2, status In"..., 41) = 41
write(2, " outstanding referrals 0, pare"..., 43) = 43
write(2, " ld 0x563bac634770 request coun"..., 50) = 50
write(2, "** ld 0x563bac634770 Response Qu"..., 37) = 37
write(2, " Empty\n", 9) = 9
write(2, " ld 0x563bac634770 response cou"..., 37) = 37
write(2, "ldap_chkResponseList ld 0x563bac"..., 53) = 53
write(2, "ldap_chkResponseList returns ld "..., 52) = 52
write(2, "ldap_int_select\n", 16) = 16
poll([{fd=4, events=POLLIN|POLLPRI}], 1, 100^CProcess 22140 detached
--- snip ---

Best regards
Robert
Post by Alexander Bluhm
bluhm
Index: usr.sbin/ldapd/evbuffer_tls.c
===================================================================
RCS file: /data/mirror/openbsd/cvs/src/usr.sbin/ldapd/evbuffer_tls.c,v
retrieving revision 1.1
diff -u -p -r1.1 evbuffer_tls.c
--- usr.sbin/ldapd/evbuffer_tls.c 1 May 2016 00:32:37
-0000 1.1 +++ usr.sbin/ldapd/evbuffer_tls.c 2 Mar 2017
*buft
* Reads data from a file descriptor into a buffer.
*/
-#define EVBUFFER_MAX_READ 4096
+#define EVBUFFER_MAX_READ 16384
int
evtls_read(struct evbuffer *buf, int fd, int howmuch, struct tls
*ctx)
Alexander Bluhm
2017-05-15 22:39:40 UTC
Permalink
Post by Seiya Kawashima
I'm not quite sure if this is the right way to fix the issue but it looks like that
this issue is related to how ldapd(8) buffers LDAP messages from the client.
Thanks for the analysis. I have copied the code from libevent to
syslogd. While adapting to TLS, I did not think about that
ioctl(FIONREAD) does not make sense for TLS. Then it was copied
to ldapd again without realizing the problem.

I would like to keep this as much a possible in sync with libevent.
So just remove the problematic code in ldapd(8) and syslogd(8).

ok?

bluhm

Index: usr.sbin/ldapd/evbuffer_tls.c
===================================================================
RCS file: /data/mirror/openbsd/cvs/src/usr.sbin/ldapd/evbuffer_tls.c,v
retrieving revision 1.2
diff -u -p -r1.2 evbuffer_tls.c
--- usr.sbin/ldapd/evbuffer_tls.c 3 Mar 2017 20:26:23 -0000 1.2
+++ usr.sbin/ldapd/evbuffer_tls.c 15 May 2017 22:32:32 -0000
@@ -298,21 +298,6 @@ evtls_read(struct evbuffer *buf, int fd,
size_t oldoff = buf->off;
int n = EVBUFFER_MAX_READ;

- if (ioctl(fd, FIONREAD, &n) == -1 || n <= 0) {
- n = EVBUFFER_MAX_READ;
- } else if (n > EVBUFFER_MAX_READ && n > howmuch) {
- /*
- * It's possible that a lot of data is available for
- * reading. We do not want to exhaust resources
- * before the reader has a chance to do something
- * about it. If the reader does not tell us how much
- * data we should read, we artifically limit it.
- */
- if ((size_t)n > buf->totallen << 2)
- n = buf->totallen << 2;
- if (n < EVBUFFER_MAX_READ)
- n = EVBUFFER_MAX_READ;
- }
if (howmuch < 0 || howmuch > n)
howmuch = n;

Index: usr.sbin/syslogd/evbuffer_tls.c
===================================================================
RCS file: /data/mirror/openbsd/cvs/src/usr.sbin/syslogd/evbuffer_tls.c,v
retrieving revision 1.10
diff -u -p -r1.10 evbuffer_tls.c
--- usr.sbin/syslogd/evbuffer_tls.c 3 Mar 2017 20:26:23 -0000 1.10
+++ usr.sbin/syslogd/evbuffer_tls.c 15 May 2017 22:32:15 -0000
@@ -298,21 +298,6 @@ evtls_read(struct evbuffer *buf, int fd,
size_t oldoff = buf->off;
int n = EVBUFFER_MAX_READ;

- if (ioctl(fd, FIONREAD, &n) == -1 || n <= 0) {
- n = EVBUFFER_MAX_READ;
- } else if (n > EVBUFFER_MAX_READ && n > howmuch) {
- /*
- * It's possible that a lot of data is available for
- * reading. We do not want to exhaust resources
- * before the reader has a chance to do something
- * about it. If the reader does not tell us how much
- * data we should read, we artifically limit it.
- */
- if ((size_t)n > buf->totallen << 2)
- n = buf->totallen << 2;
- if (n < EVBUFFER_MAX_READ)
- n = EVBUFFER_MAX_READ;
- }
if (howmuch < 0 || howmuch > n)
howmuch = n;
Robert Klein
2017-07-04 10:55:33 UTC
Permalink
Hi,

On Tue, 16 May 2017 00:39:40 +0200
Post by Alexander Bluhm
Post by Seiya Kawashima
I'm not quite sure if this is the right way to fix the issue but it
looks like that this issue is related to how ldapd(8) buffers LDAP
messages from the client.
Thanks for the analysis. I have copied the code from libevent to
syslogd. While adapting to TLS, I did not think about that
ioctl(FIONREAD) does not make sense for TLS. Then it was copied
to ldapd again without realizing the problem.
I would like to keep this as much a possible in sync with libevent.
So just remove the problematic code in ldapd(8) and syslogd(8).
I ran tests with a patched ldapd around the critical range (15950 to
16000 byte "image" file) to fill up 7GB of disk space in /var/db/ldap
three times and had no issues. (Snapshot from June 25 "6.1 GENERIC.MP#48
amd64").

Who has permission to ok the Patch?

Thanks and best regards
Robert
Post by Alexander Bluhm
ok?
bluhm
Index: usr.sbin/ldapd/evbuffer_tls.c
===================================================================
RCS file: /data/mirror/openbsd/cvs/src/usr.sbin/ldapd/evbuffer_tls.c,v
retrieving revision 1.2
diff -u -p -r1.2 evbuffer_tls.c
--- usr.sbin/ldapd/evbuffer_tls.c 3 Mar 2017 20:26:23
-0000 1.2 +++ usr.sbin/ldapd/evbuffer_tls.c 15 May 2017
int fd, size_t oldoff = buf->off;
int n = EVBUFFER_MAX_READ;
- if (ioctl(fd, FIONREAD, &n) == -1 || n <= 0) {
- n = EVBUFFER_MAX_READ;
- } else if (n > EVBUFFER_MAX_READ && n > howmuch) {
- /*
- * It's possible that a lot of data is available for
- * reading. We do not want to exhaust resources
- * before the reader has a chance to do something
- * about it. If the reader does not tell us how much
- * data we should read, we artifically limit it.
- */
- if ((size_t)n > buf->totallen << 2)
- n = buf->totallen << 2;
- if (n < EVBUFFER_MAX_READ)
- n = EVBUFFER_MAX_READ;
- }
if (howmuch < 0 || howmuch > n)
howmuch = n;
Index: usr.sbin/syslogd/evbuffer_tls.c
===================================================================
RCS
file: /data/mirror/openbsd/cvs/src/usr.sbin/syslogd/evbuffer_tls.c,v
retrieving revision 1.10 diff -u -p -r1.10 evbuffer_tls.c
--- usr.sbin/syslogd/evbuffer_tls.c 3 Mar 2017 20:26:23
-0000 1.10 +++ usr.sbin/syslogd/evbuffer_tls.c 15 May
*buf, int fd, size_t oldoff = buf->off;
int n = EVBUFFER_MAX_READ;
- if (ioctl(fd, FIONREAD, &n) == -1 || n <= 0) {
- n = EVBUFFER_MAX_READ;
- } else if (n > EVBUFFER_MAX_READ && n > howmuch) {
- /*
- * It's possible that a lot of data is available for
- * reading. We do not want to exhaust resources
- * before the reader has a chance to do something
- * about it. If the reader does not tell us how much
- * data we should read, we artifically limit it.
- */
- if ((size_t)n > buf->totallen << 2)
- n = buf->totallen << 2;
- if (n < EVBUFFER_MAX_READ)
- n = EVBUFFER_MAX_READ;
- }
if (howmuch < 0 || howmuch > n)
howmuch = n;
Alexander Bluhm
2017-07-04 15:56:29 UTC
Permalink
Post by Robert Klein
I ran tests with a patched ldapd around the critical range (15950 to
16000 byte "image" file) to fill up 7GB of disk space in /var/db/ldap
three times and had no issues. (Snapshot from June 25 "6.1 GENERIC.MP#48
amd64").
Who has permission to ok the Patch?
Thanks and best regards
Robert
Finally I have commited it. Thanks everybody for testing and
insisting on a fix.

bluhm

Gleydson Soares
2017-03-02 23:39:45 UTC
Permalink
Post by Alexander Bluhm
libevent uses 4k read blocks and libssl 16k blocks internally.
This is at least inefficent and I guess could lead to hangs.
Could you test this diff?
works for me, OK gsoares@ Thanks!
Loading...