Skip to content

Instantly share code, notes, and snippets.

@Ratler
Created April 17, 2012 06:02
Show Gist options
  • Star 0 You must be signed in to star a gist
  • Fork 0 You must be signed in to fork a gist
  • Save Ratler/2994c23ff506ffdaf21f to your computer and use it in GitHub Desktop.
Save Ratler/2994c23ff506ffdaf21f to your computer and use it in GitHub Desktop.
openldap shutting down unexpectedly
Apr 13 15:03:14 sukat-test-ldapro02 slapd_debug: 4f882412 daemon: activity on 1 descriptor
Apr 13 15:03:14 sukat-test-ldapro02 slapd_debug: 4f882412 daemon: activity on:4f882412
Apr 13 15:03:14 sukat-test-ldapro02 slapd_debug: 4f882412 daemon: epoll: listen=7 busy
Apr 13 15:03:14 sukat-test-ldapro02 slapd_debug: 4f882412 daemon: epoll: listen=8 active_threads=0 tvp=NULL
Apr 13 15:03:14 sukat-test-ldapro02 slapd_debug: 4f882412 daemon: epoll: listen=9 active_threads=0 tvp=NULL
Apr 13 15:03:14 sukat-test-ldapro02 slapd_debug: 4f882412 daemon: epoll: listen=10 active_threads=0 tvp=NULL
Apr 13 15:03:14 sukat-test-ldapro02 slapd_debug: 4f882412 daemon: activity on 1 descriptor
Apr 13 15:03:14 sukat-test-ldapro02 slapd_debug: 4f882412 daemon: activity on:4f882412
Apr 13 15:03:14 sukat-test-ldapro02 slapd_debug: 4f882412 daemon: epoll: listen=7 active_threads=0 tvp=NULL
Apr 13 15:03:14 sukat-test-ldapro02 slapd_debug: 4f882412 daemon: epoll: listen=8 active_threads=0 tvp=NULL
Apr 13 15:03:14 sukat-test-ldapro02 slapd_debug: 4f882412 daemon: epoll: listen=9 active_threads=0 tvp=NULL
Apr 13 15:03:14 sukat-test-ldapro02 slapd_debug: 4f882412 daemon: epoll: listen=10 active_threads=0 tvp=NULL
Apr 13 15:03:14 sukat-test-ldapro02 slapd[30273]: slapd(23): setsockopt(SO_KEEPALIVE) failed errno=9 (Bad file descriptor)
Apr 13 15:03:14 sukat-test-ldapro02 slapd[30273]: slapd(23): setsockopt(TCP_NODELAY) failed errno=9 (Bad file descriptor)
Apr 13 15:03:14 sukat-test-ldapro02 slapd[30273]: daemon: epoll_ctl(ADD,fd=23) failed, errno=1, shutting down
Apr 13 15:03:14 sukat-test-ldapro02 slapd[30273]: daemon: abnormal condition, shutdown initiated.
Apr 13 15:03:14 sukat-test-ldapro02 slapd[30273]: conn=109877 fd=18 closed (slapd shutdown)
Apr 13 15:03:14 sukat-test-ldapro02 slapd[30273]: conn=109881 fd=20 closed (slapd shutdown)
Apr 13 15:03:14 sukat-test-ldapro02 slapd[30273]: conn=109879 fd=21 closed (slapd shutdown)
Apr 13 15:03:14 sukat-test-ldapro02 slapd[30273]: conn=109880 fd=22 closed (slapd shutdown)
Apr 13 15:03:14 sukat-test-ldapro02 slapd_debug: 4f882412 slapd(23): setsockopt(SO_KEEPALIVE) failed errno=9 (Bad file descriptor)
Apr 13 15:03:14 sukat-test-ldapro02 slapd_debug: 4f882412 slapd(23): setsockopt(TCP_NODELAY) failed errno=9 (Bad file descriptor)
Apr 13 15:03:14 sukat-test-ldapro02 slapd_debug: 4f882412 daemon: listen=7, new connection on 23
Apr 13 15:03:14 sukat-test-ldapro02 slapd_debug: 4f882412 daemon: epoll_ctl(ADD,fd=23) failed, errno=1, shutting down
Apr 13 15:03:14 sukat-test-ldapro02 slapd_debug: 4f882412 daemon: added 23r (active) listener=(nil)
Apr 13 15:03:14 sukat-test-ldapro02 slapd_debug: 4f882412 daemon: abnormal condition, shutdown initiated.
Apr 13 15:03:14 sukat-test-ldapro02 slapd_debug: 4f882412 daemon: closing 7
Apr 13 15:03:14 sukat-test-ldapro02 slapd_debug: 4f882412 daemon: closing 8
Apr 13 15:03:14 sukat-test-ldapro02 slapd_debug: 4f882412 daemon: closing 9
Apr 13 15:03:14 sukat-test-ldapro02 slapd_debug: 4f882412 daemon: closing 10
Apr 13 15:03:14 sukat-test-ldapro02 slapd_debug: 4f882412 connection_closing: readying conn=109876 sd=15 for close
Apr 13 15:03:14 sukat-test-ldapro02 slapd_debug: 4f882412 connection_close: deferring conn=109876 sd=15
Apr 13 15:03:14 sukat-test-ldapro02 slapd_debug: 4f882412 connection_closing: readying conn=109877 sd=18 for close
Apr 13 15:03:14 sukat-test-ldapro02 slapd_debug: 4f882412 daemon: removing 18
Apr 13 15:03:14 sukat-test-ldapro02 slapd_debug: 4f882412 connection_closing: readying conn=109878 sd=19 for close
Apr 13 15:03:14 sukat-test-ldapro02 slapd_debug: 4f882412 connection_close: deferring conn=109878 sd=19
Apr 13 15:03:14 sukat-test-ldapro02 slapd_debug: 4f882412 connection_closing: readying conn=109881 sd=20 for close
Apr 13 15:03:14 sukat-test-ldapro02 slapd_debug: 4f882412 daemon: removing 20
Apr 13 15:03:14 sukat-test-ldapro02 slapd_debug: 4f882412 connection_closing: readying conn=109879 sd=21 for close
Apr 13 15:03:14 sukat-test-ldapro02 slapd_debug: 4f882412 daemon: removing 21
Apr 13 15:03:14 sukat-test-ldapro02 slapd_debug: 4f882412 connection_closing: readying conn=109880 sd=22 for close
Apr 13 15:03:14 sukat-test-ldapro02 slapd_debug: 4f882412 daemon: removing 22
Apr 13 15:03:14 sukat-test-ldapro02 slapd[30273]: conn=109882 fd=23 closed (slapd shutdown)
Apr 13 15:03:14 sukat-test-ldapro02 slapd[30273]: slapd shutdown: waiting for 3 operations/tasks to finish
Apr 13 15:03:14 sukat-test-ldapro02 slapd_debug: 4f882412 connection_closing: readying conn=109882 sd=23 for close
Apr 13 15:03:14 sukat-test-ldapro02 slapd_debug: 4f882412 daemon: removing 23
Apr 13 15:03:14 sukat-test-ldapro02 slapd_debug: 4f882412 slapd shutdown: waiting for 3 operations/tasks to finish
Apr 13 15:03:14 sukat-test-ldapro02 slapd[30273]: conn=-1 fd=23 ACCEPT from IP=130.237.95.164:44342 (IP=0.0.0.0:389)
Apr 13 15:03:14 sukat-test-ldapro02 slapd_debug: 4f882412 connection_resched: attempting closing conn=109876 sd=15
Apr 13 15:03:14 sukat-test-ldapro02 slapd_debug: 4f882412 daemon: removing 15
Apr 13 15:03:14 sukat-test-ldapro02 slapd[30273]: conn=109876 fd=15 closed (slapd shutdown)
Apr 13 15:03:14 sukat-test-ldapro02 slapd[30273]: conn=109878 fd=19 closed (slapd shutdown)
Apr 13 15:03:14 sukat-test-ldapro02 slapd_debug: 4f882412 connection_resched: attempting closing conn=109878 sd=19
Apr 13 15:03:14 sukat-test-ldapro02 slapd_debug: 4f882412 daemon: removing 19
Apr 13 15:03:14 sukat-test-ldapro02 slapd[30273]: slapd stopped.
Apr 13 15:03:14 sukat-test-ldapro02 slapd_debug: 4f882412 slapd stopped.
@hyc
Copy link

hyc commented Oct 17, 2019

The error you're getting indicates that something closed descriptor 23 shortly after the slapd daemon was given it by the accept() syscall. No code in slapd itself did so, all of the slapd calls to close a socket are logged with "daemon: closing XX" and no such message for descriptor 23 is present here. You might try running with this patch, if you can reproduce the problem.

diff --git a/servers/slapd/daemon.c b/servers/slapd/daemon.c
index d64756a2ee..d1f7732720 100644
--- a/servers/slapd/daemon.c
+++ b/servers/slapd/daemon.c
@@ -1248,6 +1248,37 @@ slapd_set_read( ber_socket_t s, int wake )
 		WAKE_LISTENER(id,wake);
 }
 
+#ifdef DEBUG_CLOSE
+#include <dlfcn.h>
+#ifndef RTLD_NEXT
+#define RTLD_NEXT	(void *)-1L
+#endif
+static char *newconns;
+typedef int (closefunc)(int fd);
+static closefunc *close_ptr;
+int close( int s )
+{
+	if (s >= 0 && s < dtblsize)
+		assert(!newconns[s]);
+	return close_ptr ? close_ptr(s) : -1;
+}
+
+static void setup_close()
+{
+	newconns = ch_calloc(1, dtblsize);
+	close_ptr = dlsym(RTLD_NEXT, "close");
+}
+#define SETUP_CLOSE()	setup_close()
+#define CHECK_CLOSE(fd)	assert(!newconns[fd])
+#define SET_CLOSE(fd)	newconns[fd] = 1
+#define CLR_CLOSE(fd)	newconns[fd] = 0
+#else
+#define SETUP_CLOSE(fd)
+#define CHECK_CLOSE(fd)
+#define SET_CLOSE(fd)
+#define CLR_CLOSE(fd)
+#endif
+
 static void
 slapd_close( ber_socket_t s )
 {
@@ -1862,6 +1893,8 @@ slapd_daemon_init( const char *urls )
 	dtblsize = FD_SETSIZE;
 #endif /* ! HAVE_SYSCONF && ! HAVE_GETDTABLESIZE */
 
+	SETUP_CLOSE();
+
 	/* open a pipe (or something equivalent connected to itself).
 	 * we write a byte on this fd whenever we catch a signal. The main
 	 * loop will be select'ing on this socket, and will wake up when
@@ -2115,6 +2148,8 @@ slap_listener(
 		return 0;
 	}
 	tid = DAEMON_ID(sfd);
+	CHECK_CLOSE(sfd);
+	SET_CLOSE(sfd);
 
 #ifdef LDAP_DEBUG
 	ldap_pvt_thread_mutex_lock( &slap_daemon[tid].sd_mutex );
@@ -2141,6 +2176,9 @@ slap_listener(
 			Debug( LDAP_DEBUG_ANY,
 				"slapd(%ld): setsockopt(SO_KEEPALIVE) failed "
 				"errno=%d (%s)\n", (long) sfd, err, sock_errstr(err) );
+			CLR_CLOSE(sfd);
+			slapd_close(sfd);
+			return 0;
 		}
 #endif /* SO_KEEPALIVE */
 #ifdef TCP_NODELAY
@@ -2153,6 +2191,9 @@ slap_listener(
 			Debug( LDAP_DEBUG_ANY,
 				"slapd(%ld): setsockopt(TCP_NODELAY) failed "
 				"errno=%d (%s)\n", (long) sfd, err, sock_errstr(err) );
+			CLR_CLOSE(sfd);
+			slapd_close(sfd);
+			return 0;
 		}
 #endif /* TCP_NODELAY */
 	}
@@ -2241,6 +2282,7 @@ slap_listener(
 		} break;
 
 	default:
+		CLR_CLOSE(sfd);
 		slapd_close(sfd);
 		return 0;
 	}
@@ -2279,6 +2321,7 @@ slap_listener(
 					(long) sfd,
 					dnsname != NULL ? dnsname : SLAP_STRING_UNKNOWN,
 					peeraddr );
+				CLR_CLOSE(sfd);
 				slapd_close(sfd);
 				return 0;
 			}
@@ -2297,6 +2340,7 @@ slap_listener(
 
 	if( authid.bv_val ) ch_free(authid.bv_val);
 
+	CLR_CLOSE(sfd);
 	if( !c ) {
 		Debug( LDAP_DEBUG_ANY,
 			"daemon: connection_init(%ld, %s, %s) failed.\n",

Recompile daemon.c with DEBUG_CLOSE defined. It will assert if any other thread tries to close a socket while slapd is still processing the accept(). Run slapd under gdb so you can get a stack trace from the assert when it happens.

@quanah
Copy link

quanah commented Oct 28, 2019

The logging here doesn't show what authentication mechanisms were in use, but there is a bug in the Heimdal Kerberos libraries that can cause this to happen that has existed since 2009. The fix went into Heimdal master in 2018, but has not yet made its way into a release. In the meantime, slapd has been updated via ITS#9112 to handle EBADF situations differently. https://www.openldap.org/devel/gitweb.cgi?p=openldap.git;a=commit;h=4d7be1c161869daabb268bcfadbccf8fb1d2b9e1

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment