Make -dvv flags produce debug traces of decoded BER messages on stderr.

Also shows a hexdump of the input buffer if BER decoding fails.
Useful when debugging protocol issues.

7 files changed, 309 insertions, 9 deletions

diff --git a/usr.sbin/ldapd/conn.c b/usr.sbin/ldapd/conn.c
index e9a69300e25..6936086c221 100644
--- a/usr.sbin/ldapd/conn.c
+++ b/usr.sbin/ldapd/conn.c
@@ -1,4 +1,4 @@
-/*	$OpenBSD: conn.c,v 1.7 2010/11/05 07:49:03 martinh Exp $ */
+/*	$OpenBSD: conn.c,v 1.8 2010/11/10 08:00:54 martinh Exp $ */
 
 /*
  * Copyright (c) 2009, 2010 Martin Hedenfalk <martin@bzero.se>
@@ -132,6 +132,7 @@ conn_dispatch(struct conn *conn)
 {
 	int			 class;
 	struct request		*req;
+	u_char			*rptr;
 
 	++stats.requests;
 
@@ -142,26 +143,36 @@ 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);
 
 	/* Read message id and request type.
 	 */
 	if (ber_scanf_elements(req->root, "{ite",
 	    &req->msgid, &class, &req->type, &req->op) != 0) {
 		log_warnx("protocol error");
+		ldap_debug_elements(req->root, -1,
+		    "received invalid request on fd %d", conn->fd);
 		conn_disconnect(conn);
 		request_free(req);
 		return -1;
 	}
 
+	ldap_debug_elements(req->root, req->type,
+	    "received request on fd %d", conn->fd);
+
 	log_debug("got request type %d, id %lld", req->type, req->msgid);
 	request_dispatch(req);
 	return 0;
diff --git a/usr.sbin/ldapd/ldapd.8 b/usr.sbin/ldapd/ldapd.8
index 3864ba7c919..e6bd09d153e 100644
--- a/usr.sbin/ldapd/ldapd.8
+++ b/usr.sbin/ldapd/ldapd.8
@@ -1,4 +1,4 @@
-.\"	$OpenBSD: ldapd.8,v 1.7 2010/11/05 07:18:30 martinh Exp $
+.\"	$OpenBSD: ldapd.8,v 1.8 2010/11/10 08:00:54 martinh Exp $
 .\"
 .\" Copyright (c) 2009, 2010 Martin Hedenfalk <martin@bzero.se>
 .\"
@@ -14,7 +14,7 @@
 .\" ACTION OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT OF
 .\" OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE.
 .\"
-.Dd $Mdocdate: November 5 2010 $
+.Dd $Mdocdate: November 10 2010 $
 .Dt LDAPD 8
 .Os
 .Sh NAME
@@ -64,6 +64,11 @@ Only check the configuration file for validity.
 Specify an alternative location for the socket file.
 .It Fl v
 Produce more verbose output.
+A second
+.Fl v
+together with the
+.Fl d
+flag produces debug traces of decoded BER messages on stderr.
 .El
 .Sh FILES
 .Bl -tag -width "/var/run/ldapd.sockXXXXXXX" -compact
diff --git a/usr.sbin/ldapd/ldapd.c b/usr.sbin/ldapd/ldapd.c
index c1d325de362..78b1b4f9ad1 100644
--- a/usr.sbin/ldapd/ldapd.c
+++ b/usr.sbin/ldapd/ldapd.c
@@ -1,4 +1,4 @@
-/*	$OpenBSD: ldapd.c,v 1.7 2010/10/26 01:58:22 william Exp $ */
+/*	$OpenBSD: ldapd.c,v 1.8 2010/11/10 08:00:54 martinh Exp $ */
 
 /*
  * Copyright (c) 2009, 2010 Martin Hedenfalk <martin@bzero.se>
@@ -152,7 +152,7 @@ main(int argc, char *argv[])
 			csockpath = optarg;
 			break;
 		case 'v':
-			verbose = 1;
+			verbose++;
 			break;
 		default:
 			usage();
diff --git a/usr.sbin/ldapd/ldapd.h b/usr.sbin/ldapd/ldapd.h
index 4a5d30fcdb7..d76e6f8ff45 100644
--- a/usr.sbin/ldapd/ldapd.h
+++ b/usr.sbin/ldapd/ldapd.h
@@ -1,4 +1,4 @@
-/*	$OpenBSD: ldapd.h,v 1.20 2010/11/03 10:33:17 martinh Exp $ */
+/*	$OpenBSD: ldapd.h,v 1.21 2010/11/10 08:00:54 martinh Exp $ */
 
 /*
  * Copyright (c) 2009, 2010 Martin Hedenfalk <martin@bzero.se>
@@ -472,6 +472,9 @@ __dead void		 fatal(const char *);
 __dead void		 fatalx(const char *);
 const char		*print_host(struct sockaddr_storage *ss, char *buf,
 				size_t len);
+void			 hexdump(void *data, size_t len, const char *fmt, ...);
+void			 ldap_debug_elements(struct ber_element *root,
+			    int context, const char *fmt, ...);
 
 /* util.c */
 int			 bsnprintf(char *str, size_t size,
diff --git a/usr.sbin/ldapd/ldape.c b/usr.sbin/ldapd/ldape.c
index 81eaac32f74..4cc157d904c 100644
--- a/usr.sbin/ldapd/ldape.c
+++ b/usr.sbin/ldapd/ldape.c
@@ -1,4 +1,4 @@
-/*	$OpenBSD: ldape.c,v 1.13 2010/09/01 17:34:15 martinh Exp $ */
+/*	$OpenBSD: ldape.c,v 1.14 2010/11/10 08:00:54 martinh Exp $ */
 
 /*
  * Copyright (c) 2009, 2010 Martin Hedenfalk <martin@bzero.se>
@@ -88,6 +88,8 @@ send_ldap_extended_response(struct conn *conn, int msgid, unsigned long type,
 		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);
 
diff --git a/usr.sbin/ldapd/log.c b/usr.sbin/ldapd/log.c
index 9560cfcead8..b126229e24d 100644
--- a/usr.sbin/ldapd/log.c
+++ b/usr.sbin/ldapd/log.c
@@ -1,4 +1,4 @@
-/*	$OpenBSD: log.c,v 1.2 2010/11/10 07:32:50 martinh Exp $	*/
+/*	$OpenBSD: log.c,v 1.3 2010/11/10 08:00:54 martinh Exp $	*/
 
 /*
  * Copyright (c) 2003, 2004 Henning Brauer <henning@openbsd.org>
@@ -30,6 +30,7 @@
 #include <syslog.h>
 #include <time.h>
 #include <unistd.h>
+#include <vis.h>
 
 #include "ldapd.h"
 
@@ -185,3 +186,278 @@ print_host(struct sockaddr_storage *ss, char *buf, size_t len)
 	}
 	return (buf);
 }
+
+void
+hexdump(void *data, size_t len, const char *fmt, ...)
+{
+	uint8_t *p = data;
+	va_list ap;
+
+	if (verbose < 2 || !debug)
+		return;
+
+	va_start(ap, fmt);
+	vlog(LOG_DEBUG, fmt, ap);
+	va_end(ap);
+
+	while (len--) {
+		size_t ofs = p - (uint8_t *)data;
+		if (ofs % 16 == 0)
+			fprintf(stderr, "%s%04lx:", ofs == 0 ? "" : "\n", ofs);
+		else if (ofs % 8 == 0)
+			fprintf(stderr, " ");
+		fprintf(stderr, " %02x", *p++);
+	}
+	fprintf(stderr, "\n");
+}
+
+/*
+ * Display a list of ber elements.
+ *
+ */
+void
+ldap_debug_elements(struct ber_element *root, int context, const char *fmt, ...)
+{
+	va_list		 ap;
+	static int	 indent = 0;
+	long long	 v;
+	int		 d;
+	char		*buf, *visbuf;
+	size_t		 len;
+	u_int		 i;
+	int		 constructed;
+	struct ber_oid	 o;
+
+	if (verbose < 2 || !debug)
+		return;
+
+	if (fmt != NULL) {
+		va_start(ap, fmt);
+		vlog(LOG_DEBUG, fmt, ap);
+		va_end(ap);
+	}
+
+	/* calculate lengths */
+	ber_calc_len(root);
+
+	switch (root->be_encoding) {
+	case BER_TYPE_SEQUENCE:
+	case BER_TYPE_SET:
+		constructed = root->be_encoding;
+		break;
+	default:
+		constructed = 0;
+		break;
+	}
+
+	fprintf(stderr, "%*slen %lu ", indent, "", root->be_len);
+	switch (root->be_class) {
+	case BER_CLASS_UNIVERSAL:
+		fprintf(stderr, "class: universal(%u) type: ", root->be_class);
+		switch (root->be_type) {
+		case BER_TYPE_EOC:
+			fprintf(stderr, "end-of-content");
+			break;
+		case BER_TYPE_BOOLEAN:
+			fprintf(stderr, "boolean");
+			break;
+		case BER_TYPE_INTEGER:
+			fprintf(stderr, "integer");
+			break;
+		case BER_TYPE_BITSTRING:
+			fprintf(stderr, "bit-string");
+			break;
+		case BER_TYPE_OCTETSTRING:
+			fprintf(stderr, "octet-string");
+			break;
+		case BER_TYPE_NULL:
+			fprintf(stderr, "null");
+			break;
+		case BER_TYPE_OBJECT:
+			fprintf(stderr, "object");
+			break;
+		case BER_TYPE_ENUMERATED:
+			fprintf(stderr, "enumerated");
+			break;
+		case BER_TYPE_SEQUENCE:
+			fprintf(stderr, "sequence");
+			break;
+		case BER_TYPE_SET:
+			fprintf(stderr, "set");
+			break;
+		}
+		break;
+	case BER_CLASS_APPLICATION:
+		fprintf(stderr, "class: application(%u) type: ",
+		    root->be_class);
+		switch (root->be_type) {
+		case LDAP_REQ_BIND:
+		case LDAP_RES_BIND:
+			fprintf(stderr, "bind");
+			break;
+		case LDAP_REQ_UNBIND_30:
+			fprintf(stderr, "unbind");
+			break;
+		case LDAP_REQ_SEARCH:
+			fprintf(stderr, "search");
+			break;
+		case LDAP_RES_SEARCH_ENTRY:
+			fprintf(stderr, "search entry");
+			break;
+		case LDAP_RES_SEARCH_RESULT:
+			fprintf(stderr, "search result");
+			break;
+		case LDAP_REQ_MODIFY:
+		case LDAP_RES_MODIFY:
+			fprintf(stderr, "modify");
+			break;
+		case LDAP_REQ_ADD:
+		case LDAP_RES_ADD:
+			fprintf(stderr, "add");
+			break;
+		case LDAP_REQ_DELETE_30:
+		case LDAP_RES_DELETE:
+			fprintf(stderr, "delete");
+			break;
+		case LDAP_REQ_MODRDN:
+		case LDAP_RES_MODRDN:
+			fprintf(stderr, "modrdn");
+			break;
+		case LDAP_REQ_COMPARE:
+		case LDAP_RES_COMPARE:
+			fprintf(stderr, "compare");
+			break;
+		case LDAP_REQ_ABANDON_30:
+			fprintf(stderr, "abandon");
+			break;
+		case LDAP_REQ_EXTENDED:
+		case LDAP_RES_EXTENDED:
+			fprintf(stderr, "extended");
+			break;
+		}
+		break;
+	case BER_CLASS_PRIVATE:
+		fprintf(stderr, "class: private(%u) type: ", root->be_class);
+		fprintf(stderr, "encoding (%lu) type: ", root->be_encoding);
+		break;
+	case BER_CLASS_CONTEXT:
+		fprintf(stderr, "class: context(%u) type: ", root->be_class);
+		switch (context) {
+		case LDAP_REQ_BIND:
+			switch(root->be_type) {
+			case LDAP_AUTH_SIMPLE:
+				fprintf(stderr, "auth simple");
+				break;
+			}
+			break;
+		case LDAP_REQ_SEARCH:
+			switch(root->be_type) {
+			case LDAP_FILT_AND:
+				fprintf(stderr, "and");
+				break;
+			case LDAP_FILT_OR:
+				fprintf(stderr, "or");
+				break;
+			case LDAP_FILT_NOT:
+				fprintf(stderr, "not");
+				break;
+			case LDAP_FILT_EQ:
+				fprintf(stderr, "equal");
+				break;
+			case LDAP_FILT_SUBS:
+				fprintf(stderr, "substring");
+				break;
+			case LDAP_FILT_GE:
+				fprintf(stderr, "greater-or-equal");
+				break;
+			case LDAP_FILT_LE:
+				fprintf(stderr, "less-or-equal");
+				break;
+			case LDAP_FILT_PRES:
+				fprintf(stderr, "presence");
+				break;
+			case LDAP_FILT_APPR:
+				fprintf(stderr, "approximate");
+				break;
+			}
+			break;
+		}
+		break;
+	default:
+		fprintf(stderr, "class: <INVALID>(%u) type: ", root->be_class);
+		break;
+	}
+	fprintf(stderr, "(%lu) encoding %lu ",
+	    root->be_type, root->be_encoding);
+
+	if (constructed)
+		root->be_encoding = constructed;
+
+	switch (root->be_encoding) {
+	case BER_TYPE_BOOLEAN:
+		if (ber_get_boolean(root, &d) == -1) {
+			fprintf(stderr, "<INVALID>\n");
+			break;
+		}
+		fprintf(stderr, "%s(%d)\n", d ? "true" : "false", d);
+		break;
+	case BER_TYPE_INTEGER:
+		if (ber_get_integer(root, &v) == -1) {
+			fprintf(stderr, "<INVALID>\n");
+			break;
+		}
+		fprintf(stderr, "value %lld\n", v);
+		break;
+	case BER_TYPE_ENUMERATED:
+		if (ber_get_enumerated(root, &v) == -1) {
+			fprintf(stderr, "<INVALID>\n");
+			break;
+		}
+		fprintf(stderr, "value %lld\n", v);
+		break;
+	case BER_TYPE_BITSTRING:
+		if (ber_get_bitstring(root, (void *)&buf, &len) == -1) {
+			fprintf(stderr, "<INVALID>\n");
+			break;
+		}
+		fprintf(stderr, "hexdump ");
+		for (i = 0; i < len; i++)
+			fprintf(stderr, "%02x", buf[i]);
+		fprintf(stderr, "\n");
+		break;
+	case BER_TYPE_OBJECT:
+		if (ber_get_oid(root, &o) == -1) {
+			fprintf(stderr, "<INVALID>\n");
+			break;
+		}
+		fprintf(stderr, "\n");
+		break;
+	case BER_TYPE_OCTETSTRING:
+		if (ber_get_nstring(root, (void *)&buf, &len) == -1) {
+			fprintf(stderr, "<INVALID>\n");
+			break;
+		}
+		if ((visbuf = malloc(len * 4 + 1)) != NULL) {
+			strvisx(visbuf, buf, len, 0);
+			fprintf(stderr, "string \"%s\"\n",  visbuf);
+			free(visbuf);
+		}
+		break;
+	case BER_TYPE_NULL:	/* no payload */
+	case BER_TYPE_EOC:
+	case BER_TYPE_SEQUENCE:
+	case BER_TYPE_SET:
+	default:
+		fprintf(stderr, "\n");
+		break;
+	}
+
+	if (constructed && root->be_sub) {
+		indent += 2;
+		ldap_debug_elements(root->be_sub, context, NULL);
+		indent -= 2;
+	}
+	if (root->be_next)
+		ldap_debug_elements(root->be_next, context, NULL);
+}
+
diff --git a/usr.sbin/ldapd/search.c b/usr.sbin/ldapd/search.c
index 9fe2a0d95a0..3afd62561c0 100644
--- a/usr.sbin/ldapd/search.c
+++ b/usr.sbin/ldapd/search.c
@@ -1,4 +1,4 @@
-/*	$OpenBSD: search.c,v 1.13 2010/11/05 08:17:46 martinh Exp $ */
+/*	$OpenBSD: search.c,v 1.14 2010/11/10 08:00:54 martinh Exp $ */
 
 /*
  * Copyright (c) 2009, 2010 Martin Hedenfalk <martin@bzero.se>
@@ -134,6 +134,9 @@ search_result(const char *dn, size_t dnlen, struct ber_element *attrs,
 	if (elm == NULL)
 		goto fail;
 
+	ldap_debug_elements(root, LDAP_RES_SEARCH_ENTRY,
+	    "sending search entry on fd %d", conn->fd);
+
 	rc = ber_write_elements(&conn->ber, root);
 	ber_free_elements(root);