Full_Name: Dagobert Michelsen Version: 2.2.23 OS: Solaris 9 4/04 URL: Submission from: (NULL) (62.214.9.52) The slapd process terminates unexpectedly after a random number of requests. Before 2.2.23 we used 2.2.17 and were forced to upgrade because of ITS#3400 (loop in slapd_daemon_task() (daemon.c) after repeated EBADF returns from select()) The modification in ITS#3400 seem to change the behaviour from spinning to terminating which I assume is the change we are seeing here. However the cause of the termination is still unclear. The problem was reproduced on a SunFire V440 with 4 CPUs. We were unable to reproduce the problem on server with 1 CPU, so it might be a threading/sync issue. Additionally we are seeing the problem only with the instance using the Perl backend, not with BDB. We use a modified back-perl which instantiates a new Perl object with each connection but I cannot see any evidence that the termination is due to our backend-modifications. Additional information: We were forced to modify the mutex shielding in servers/slapd/back-perl/search.c because the current implementation hangs (no spinning) when a long search result is sent back to a client and another search request is going to be processed. If necessary you can see the patch containing the full modifications under http://www.familie-michelsen.de/openldap-2.2.23-back-perl-multiconn.patch I have the complete truss-output and full debug output from slapd. Some of the slapd debug output results from our modified perl backend which can be safely ignored. Here are the last 500 lines of the truss-output: /4: llseek(34, 0, SEEK_CUR) Err#29 ESPIPE /4: close(34) = 0 /4: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7DFFEFC0) = 0 /4: sigprocmask(SIG_SETMASK, 0x7DFFEFAC, 0x00000000) = 0 /4: sigaction(SIGPIPE, 0x7DFFEED0, 0x7DFFEFF0) = 0 /4: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7DFFEF58) = 0 /4: sigprocmask(SIG_SETMASK, 0x7DFFEF44, 0x00000000) = 0 /4: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7DFFF088) = 0 /4: sigprocmask(SIG_SETMASK, 0x7DFFF074, 0x00000000) = 0 /4: sigaction(SIGPIPE, 0x7DFFEF98, 0x7DFFF0B8) = 0 /4: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7DFFF020) = 0 /4: sigprocmask(SIG_SETMASK, 0x7DFFF00C, 0x00000000) = 0 /4: write(35, "150301\0 98F6 gA2 #B1 L".., 37) = 37 /4: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7DFFF020) = 0 /4: sigprocmask(SIG_SETMASK, 0x7DFFF00C, 0x00000000) = 0 /4: sigaction(SIGPIPE, 0x7DFFEF30, 0x7DFFF050) = 0 /4: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7DFFEFB8) = 0 /4: sigprocmask(SIG_SETMASK, 0x7DFFEFA4, 0x00000000) = 0 /4: dup(35) = 7 /4: close(35) = 0 /4: fcntl(7, F_DUP2FD, 0x00000023) = 35 /4: close(7) = 0 /4: llseek(35, 0, SEEK_CUR) Err#29 ESPIPE /4: close(35) = 0 /4: write(2, " d a e m o n : r e m o".., 20) = 20 /4: write(2, " c o n n =", 5) = 5 /4: write(2, " 1 6 8 1", 4) = 4 /4: write(2, " f d =", 4) = 4 /4: write(2, " 3 3", 2) = 2 /4: write(2, " c l o s e d\n", 8) = 8 /4: fstat(4, 0x7DFFF8E8) = 0 /4: time() = 1109235879 /4: getpid() = 17244 [17235] /4: putmsg(4, 0x7DFFEFA0, 0x7DFFEF94, 0) = 0 /4: open("/var/run/syslog_door", O_RDONLY) = 7 /4: door_info(7, 0x7DFFEED8) = 0 /4: getpid() = 17244 [17235] /4: door_call(7, 0x7DFFEEC0) = 0 /4: close(7) = 0 /4: write(33, "150301\0 AC D7FFFB8C04".., 37) = 37 /4: write(2, " t l s _ w r i t e : w".., 31) = 31 /4: write(2, " 0 0 0 0 : 1 5 ".., 79) = 79 /4: write(2, " 0 0 1 0 : 8 2 ".., 79) = 79 /4: write(2, " 0 0 2 0 : 8 c ".., 79) = 79 /4: write(2, " T L S t r a c e : S".., 49) = 49 /4: shutdown(33, 2, 1) Err#134 ENOTCONN /4: close(33) = 0 /2: lwp_park(0x00000000, 0) = 0 /4: lwp_unpark(2, 1) = 0 /2: write(2, " c o n n e c t i o n _ c".., 55) = 55 /4: yield() = 0 /2: write(6, " 0", 1) = 1 /2: write(6, " 0", 1) = 1 /2: write(2, " c o n n e c t i o n _ c".., 34) = 34 /2: write(2, " O p e n L D A P R e m".., 60) = 60 /2: write(2, " R e m a p C o n n e c t".., 30) = 30 /2: write(2, "\n", 1) = 1 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE350) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE33C, 0x00000000) = 0 /2: sigaction(SIGPIPE, 0x7EFFE260, 0x7EFFE380) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE2E8) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE2D4, 0x00000000) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE418) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE404, 0x00000000) = 0 /2: sigaction(SIGPIPE, 0x7EFFE328, 0x7EFFE448) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE3B0) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE39C, 0x00000000) = 0 /2: write(13, "150301\0 AED0BB97E80EB5".., 37) = 37 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE3B0) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE39C, 0x00000000) = 0 /2: sigaction(SIGPIPE, 0x7EFFE2C0, 0x7EFFE3E0) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE348) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE334, 0x00000000) = 0 /2: dup(13) = 7 /2: close(13) = 0 /2: fcntl(7, F_DUP2FD, 0x0000000D) = 13 /2: close(7) = 0 /2: llseek(13, 0, SEEK_CUR) Err#29 ESPIPE /2: close(13) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE350) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE33C, 0x00000000) = 0 /2: sigaction(SIGPIPE, 0x7EFFE260, 0x7EFFE380) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE2E8) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE2D4, 0x00000000) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE418) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE404, 0x00000000) = 0 /2: sigaction(SIGPIPE, 0x7EFFE328, 0x7EFFE448) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE3B0) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE39C, 0x00000000) = 0 /2: write(12, "150301\0 '1F dE7DC m Q".., 37) = 37 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE3B0) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE39C, 0x00000000) = 0 /2: sigaction(SIGPIPE, 0x7EFFE2C0, 0x7EFFE3E0) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE348) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE334, 0x00000000) = 0 /2: dup(12) = 7 /2: close(12) = 0 /2: fcntl(7, F_DUP2FD, 0x0000000C) = 12 /2: close(7) = 0 /2: llseek(12, 0, SEEK_CUR) Err#29 ESPIPE /2: close(12) = 0 /2: write(2, " d a e m o n : r e m o".., 20) = 20 /2: write(2, " c o n n =", 5) = 5 /2: write(2, " 1 6 8 5", 4) = 4 /2: write(2, " f d =", 4) = 4 /2: write(2, " 1 5", 2) = 2 /2: write(2, " c l o s e d\n", 8) = 8 /2: fstat(4, 0x7EFFEC78) = 0 /2: time() = 1109235879 /2: getpid() = 17244 [17235] /2: putmsg(4, 0x7EFFE330, 0x7EFFE324, 0) = 0 /2: open("/var/run/syslog_door", O_RDONLY) = 7 /2: door_info(7, 0x7EFFE268) = 0 /2: getpid() = 17244 [17235] /2: door_call(7, 0x7EFFE250) = 0 /2: close(7) = 0 /2: write(15, "150301\0 { o : e E\b\b".., 37) = 37 /2: write(2, " t l s _ w r i t e : w".., 31) = 31 /2: write(2, " 0 0 0 0 : 1 5 ".., 79) = 79 /2: write(2, " 0 0 1 0 : b f ".., 79) = 79 /2: write(2, " 0 0 2 0 : 3 e ".., 79) = 79 /2: write(2, " T L S t r a c e : S".., 49) = 49 /2: shutdown(15, 2, 1) = 0 /2: close(15) = 0 /2: write(2, " c o n n e c t i o n _ c".., 55) = 55 /2: write(6, " 0", 1) = 1 /2: write(6, " 0", 1) = 1 /2: write(2, " c o n n e c t i o n _ c".., 34) = 34 /2: write(2, " O p e n L D A P R e m".., 60) = 60 /2: write(2, " R e m a p C o n n e c t".., 30) = 30 /2: write(2, "\n", 1) = 1 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE350) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE33C, 0x00000000) = 0 /2: sigaction(SIGPIPE, 0x7EFFE260, 0x7EFFE380) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE2E8) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE2D4, 0x00000000) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE418) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE404, 0x00000000) = 0 /2: sigaction(SIGPIPE, 0x7EFFE328, 0x7EFFE448) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE3B0) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE39C, 0x00000000) = 0 /2: write(18, "150301\0 |D78E :92 :E5".., 37) = 37 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE3B0) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE39C, 0x00000000) = 0 /2: sigaction(SIGPIPE, 0x7EFFE2C0, 0x7EFFE3E0) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE348) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE334, 0x00000000) = 0 /2: dup(18) = 7 /2: close(18) = 0 /2: fcntl(7, F_DUP2FD, 0x00000012) = 18 /2: close(7) = 0 /2: llseek(18, 0, SEEK_CUR) Err#29 ESPIPE /2: close(18) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE350) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE33C, 0x00000000) = 0 /2: sigaction(SIGPIPE, 0x7EFFE260, 0x7EFFE380) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE2E8) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE2D4, 0x00000000) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE418) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE404, 0x00000000) = 0 /2: sigaction(SIGPIPE, 0x7EFFE328, 0x7EFFE448) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE3B0) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE39C, 0x00000000) = 0 /2: write(14, "150301\0 0114 1\b A @A2".., 37) = 37 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE3B0) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE39C, 0x00000000) = 0 /2: sigaction(SIGPIPE, 0x7EFFE2C0, 0x7EFFE3E0) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE348) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE334, 0x00000000) = 0 /2: dup(14) = 7 /2: close(14) = 0 /2: fcntl(7, F_DUP2FD, 0x0000000E) = 14 /2: close(7) = 0 /2: llseek(14, 0, SEEK_CUR) Err#29 ESPIPE /2: close(14) = 0 /2: write(2, " d a e m o n : r e m o".., 20) = 20 /2: write(2, " c o n n =", 5) = 5 /2: write(2, " 1 6 8 6", 4) = 4 /2: write(2, " f d =", 4) = 4 /2: write(2, " 1 6", 2) = 2 /2: write(2, " c l o s e d\n", 8) = 8 /2: fstat(4, 0x7EFFEC78) = 0 /2: time() = 1109235879 /2: getpid() = 17244 [17235] /2: putmsg(4, 0x7EFFE330, 0x7EFFE324, 0) = 0 /2: open("/var/run/syslog_door", O_RDONLY) = 7 /2: door_info(7, 0x7EFFE268) = 0 /2: getpid() = 17244 [17235] /2: door_call(7, 0x7EFFE250) = 0 /2: close(7) = 0 /2: write(16, "150301\0 C5C1 }93A7 MAA".., 37) = 37 /2: write(2, " t l s _ w r i t e : w".., 31) = 31 /2: write(2, " 0 0 0 0 : 1 5 ".., 79) = 79 /2: write(2, " 0 0 1 0 : 2 1 ".., 79) = 79 /2: write(2, " 0 0 2 0 : c e ".., 79) = 79 /2: write(2, " T L S t r a c e : S".., 49) = 49 /2: shutdown(16, 2, 1) = 0 /2: close(16) = 0 /2: write(2, " c o n n e c t i o n _ c".., 55) = 55 /2: write(6, " 0", 1) = 1 /2: write(6, " 0", 1) = 1 /2: write(2, " c o n n e c t i o n _ c".., 34) = 34 /2: write(2, " O p e n L D A P R e m".., 60) = 60 /2: write(2, " R e m a p C o n n e c t".., 30) = 30 /2: write(2, "\n", 1) = 1 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE350) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE33C, 0x00000000) = 0 /2: sigaction(SIGPIPE, 0x7EFFE260, 0x7EFFE380) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE2E8) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE2D4, 0x00000000) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE418) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE404, 0x00000000) = 0 /2: sigaction(SIGPIPE, 0x7EFFE328, 0x7EFFE448) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE3B0) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE39C, 0x00000000) = 0 /2: write(20, "150301\0 2 SA69DCBB9 }".., 37) = 37 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE3B0) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE39C, 0x00000000) = 0 /2: sigaction(SIGPIPE, 0x7EFFE2C0, 0x7EFFE3E0) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE348) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE334, 0x00000000) = 0 /2: dup(20) = 7 /2: close(20) = 0 /2: fcntl(7, F_DUP2FD, 0x00000014) = 20 /2: close(7) = 0 /2: llseek(20, 0, SEEK_CUR) Err#29 ESPIPE /2: close(20) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE350) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE33C, 0x00000000) = 0 /2: sigaction(SIGPIPE, 0x7EFFE260, 0x7EFFE380) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE2E8) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE2D4, 0x00000000) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE418) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE404, 0x00000000) = 0 /2: sigaction(SIGPIPE, 0x7EFFE328, 0x7EFFE448) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE3B0) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE39C, 0x00000000) = 0 /2: write(19, "150301\0 B2ADE0E9 /05 %".., 37) = 37 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE3B0) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE39C, 0x00000000) = 0 /2: sigaction(SIGPIPE, 0x7EFFE2C0, 0x7EFFE3E0) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE348) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE334, 0x00000000) = 0 /2: dup(19) = 7 /2: close(19) = 0 /2: fcntl(7, F_DUP2FD, 0x00000013) = 19 /2: close(7) = 0 /2: llseek(19, 0, SEEK_CUR) Err#29 ESPIPE /2: close(19) = 0 /2: write(2, " d a e m o n : r e m o".., 20) = 20 /2: write(2, " c o n n =", 5) = 5 /2: write(2, " 1 6 8 7", 4) = 4 /2: write(2, " f d =", 4) = 4 /2: write(2, " 2 1", 2) = 2 /2: write(2, " c l o s e d\n", 8) = 8 /2: fstat(4, 0x7EFFEC78) = 0 /2: time() = 1109235879 /2: getpid() = 17244 [17235] /2: putmsg(4, 0x7EFFE330, 0x7EFFE324, 0) = 0 /2: open("/var/run/syslog_door", O_RDONLY) = 7 /2: door_info(7, 0x7EFFE268) = 0 /2: getpid() = 17244 [17235] /2: door_call(7, 0x7EFFE250) = 0 /2: close(7) = 0 /2: shutdown(21, 2, 1) Err#9 EBADF /2: close(21) Err#9 EBADF /2: write(2, " c o n n e c t i o n _ c".., 55) = 55 /2: write(6, " 0", 1) = 1 /2: write(6, " 0", 1) = 1 /2: write(2, " c o n n e c t i o n _ c".., 34) = 34 /2: write(2, " O p e n L D A P R e m".., 60) = 60 /2: write(2, " R e m a p C o n n e c t".., 30) = 30 /2: write(2, "\n", 1) = 1 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE350) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE33C, 0x00000000) = 0 /2: sigaction(SIGPIPE, 0x7EFFE260, 0x7EFFE380) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE2E8) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE2D4, 0x00000000) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE418) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE404, 0x00000000) = 0 /2: sigaction(SIGPIPE, 0x7EFFE328, 0x7EFFE448) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE3B0) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE39C, 0x00000000) = 0 /2: write(23, "150301\0 A6 > :FB g9EAB".., 37) = 37 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE3B0) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE39C, 0x00000000) = 0 /2: sigaction(SIGPIPE, 0x7EFFE2C0, 0x7EFFE3E0) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE348) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE334, 0x00000000) = 0 /2: dup(23) = 7 /2: close(23) = 0 /2: fcntl(7, F_DUP2FD, 0x00000017) = 23 /2: close(7) = 0 /2: llseek(23, 0, SEEK_CUR) Err#29 ESPIPE /2: close(23) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE350) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE33C, 0x00000000) = 0 /2: sigaction(SIGPIPE, 0x7EFFE260, 0x7EFFE380) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE2E8) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE2D4, 0x00000000) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE418) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE404, 0x00000000) = 0 /2: sigaction(SIGPIPE, 0x7EFFE328, 0x7EFFE448) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE3B0) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE39C, 0x00000000) = 0 /2: write(22, "150301\0 84CB N c I B1".., 37) = 37 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE3B0) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE39C, 0x00000000) = 0 /2: sigaction(SIGPIPE, 0x7EFFE2C0, 0x7EFFE3E0) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE348) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE334, 0x00000000) = 0 /2: dup(22) = 7 /2: close(22) = 0 /2: fcntl(7, F_DUP2FD, 0x00000016) = 22 /2: close(7) = 0 /2: llseek(22, 0, SEEK_CUR) Err#29 ESPIPE /2: close(22) = 0 /2: write(2, " d a e m o n : r e m o".., 20) = 20 /2: write(2, " c o n n =", 5) = 5 /2: write(2, " 1 5 1 3", 4) = 4 /2: write(2, " f d =", 4) = 4 /2: write(2, " 2 3", 2) = 2 /2: write(2, " c l o s e d\n", 8) = 8 /2: fstat(4, 0x7EFFEC78) = 0 /2: time() = 1109235879 /2: getpid() = 17244 [17235] /2: putmsg(4, 0x7EFFE330, 0x7EFFE324, 0) = 0 /2: open("/var/run/syslog_door", O_RDONLY) = 7 /2: door_info(7, 0x7EFFE268) = 0 /2: getpid() = 17244 [17235] /2: door_call(7, 0x7EFFE250) = 0 /2: close(7) = 0 /2: shutdown(23, 2, 1) Err#9 EBADF /2: close(23) Err#9 EBADF /2: write(2, " c o n n e c t i o n _ c".., 55) = 55 /2: write(6, " 0", 1) = 1 /2: write(6, " 0", 1) = 1 /2: write(2, " c o n n e c t i o n _ c".., 34) = 34 /2: write(2, " O p e n L D A P R e m".., 60) = 60 /2: write(2, " R e m a p C o n n e c t".., 30) = 30 /2: write(2, "\n", 1) = 1 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE350) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE33C, 0x00000000) = 0 /2: sigaction(SIGPIPE, 0x7EFFE260, 0x7EFFE380) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE2E8) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE2D4, 0x00000000) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE418) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE404, 0x00000000) = 0 /2: sigaction(SIGPIPE, 0x7EFFE328, 0x7EFFE448) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE3B0) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE39C, 0x00000000) = 0 /2: write(27, "150301\0 90 N9B8D c .F2".., 37) = 37 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE3B0) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE39C, 0x00000000) = 0 /2: sigaction(SIGPIPE, 0x7EFFE2C0, 0x7EFFE3E0) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE348) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE334, 0x00000000) = 0 /2: dup(27) = 7 /2: close(27) = 0 /2: fcntl(7, F_DUP2FD, 0x0000001B) = 27 /2: close(7) = 0 /2: llseek(27, 0, SEEK_CUR) Err#29 ESPIPE /2: close(27) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE350) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE33C, 0x00000000) = 0 /2: sigaction(SIGPIPE, 0x7EFFE260, 0x7EFFE380) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE2E8) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE2D4, 0x00000000) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE418) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE404, 0x00000000) = 0 /2: sigaction(SIGPIPE, 0x7EFFE328, 0x7EFFE448) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE3B0) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE39C, 0x00000000) = 0 /2: write(25, "150301\0 588 798 " qC2".., 37) = 37 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE3B0) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE39C, 0x00000000) = 0 /2: sigaction(SIGPIPE, 0x7EFFE2C0, 0x7EFFE3E0) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFE348) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFE334, 0x00000000) = 0 /2: dup(25) = 7 /2: close(25) = 0 /2: fcntl(7, F_DUP2FD, 0x00000019) = 25 /2: close(7) = 0 /2: llseek(25, 0, SEEK_CUR) Err#29 ESPIPE /2: close(25) = 0 /2: write(2, " d a e m o n : r e m o".., 20) = 20 /2: write(2, " c o n n =", 5) = 5 /2: write(2, " 1 6 8 4", 4) = 4 /2: write(2, " f d =", 4) = 4 /2: write(2, " 2 4", 2) = 2 /2: write(2, " c l o s e d\n", 8) = 8 /2: fstat(4, 0x7EFFEC78) = 0 /2: time() = 1109235879 /2: getpid() = 17244 [17235] /2: putmsg(4, 0x7EFFE330, 0x7EFFE324, 0) = 0 /2: open("/var/run/syslog_door", O_RDONLY) = 7 /2: door_info(7, 0x7EFFE268) = 0 /2: getpid() = 17244 [17235] /2: door_call(7, 0x7EFFE250) = 0 /2: close(7) = 0 /2: write(24, "150301\0 M LE18E97C5D6".., 37) = 37 /2: write(2, " t l s _ w r i t e : w".., 31) = 31 /2: write(2, " 0 0 0 0 : 1 5 ".., 79) = 79 /2: write(2, " 0 0 1 0 : 3 8 ".., 79) = 79 /2: write(2, " 0 0 2 0 : c 5 ".., 79) = 79 /2: write(2, " T L S t r a c e : S".., 49) = 49 /2: shutdown(24, 2, 1) = 0 /2: close(24) = 0 /2: write(2, " s l a p d s h u t d o".., 51) = 51 /2: fstat(4, 0x7EFFEDF0) = 0 /2: time() = 1109235879 /2: getpid() = 17244 [17235] /2: putmsg(4, 0x7EFFE4A8, 0x7EFFE49C, 0) = 0 /2: open("/var/run/syslog_door", O_RDONLY) = 7 /2: door_info(7, 0x7EFFE3E0) = 0 /2: getpid() = 17244 [17235] /2: door_call(7, 0x7EFFE3C8) = 0 /2: close(7) = 0 /2: lwp_unpark(8, 1) = 0 /2: yield() = 0 /2: lwp_unpark(5, 1) = 0 /5: lwp_park(0x00000000, 0) = 0 /2: yield() = 0 /5: lwp_unpark(7, 1) = 0 /2: lwp_unpark(9, 1) = 0 /5: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7D7FFCA0) = 0 /2: yield() = 0 /5: sigprocmask(SIG_SETMASK, 0x7D7FFC8C, 0x00000000) = 0 /3: lwp_park(0x00000000, 0) = 0 /3: lwp_unpark(4, 1) = 0 /3: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7E7FFCA0) = 0 /3: sigprocmask(SIG_SETMASK, 0x7E7FFC8C, 0x00000000) = 0 /3: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x00000000) = 0 /3: lwp_exit() /2: lwp_unpark(3, 1) = 0 /5: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x00000000) = 0 /2: yield() = 0 /5: lwp_exit() /2: lwp_unpark(6, 1) = 0 /9: lwp_park(0x00000000, 0) = 0 /6: lwp_park(0x00000000, 0) = 0 /9: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7B7FFCA0) = 0 /6: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7CFFFCA0) = 0 /9: sigprocmask(SIG_SETMASK, 0x7B7FFC8C, 0x00000000) = 0 /7: lwp_park(0x00000000, 0) = 0 /4: lwp_park(0x00000000, 0) = 0 /7: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7C7FFCA0) = 0 /4: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7DFFFCA0) = 0 /9: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x00000000) = 0 /4: sigprocmask(SIG_SETMASK, 0x7DFFFC8C, 0x00000000) = 0 /9: lwp_exit() /4: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x00000000) = 0 /4: lwp_exit() /7: sigprocmask(SIG_SETMASK, 0x7C7FFC8C, 0x00000000) = 0 /7: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x00000000) = 0 /6: sigprocmask(SIG_SETMASK, 0x7CFFFC8C, 0x00000000) = 0 /2: yield() = 0 /8: lwp_park(0x00000000, 0) = 0 /6: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x00000000) = 0 /7: lwp_exit() /8: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7BFFFCA0) = 0 /6: lwp_exit() /8: sigprocmask(SIG_SETMASK, 0x7BFFFC8C, 0x00000000) = 0 /8: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x00000000) = 0 /8: lwp_exit() /2: yield() = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x7EFFFF20) = 0 /2: sigprocmask(SIG_SETMASK, 0x7EFFFF0C, 0x00000000) = 0 /2: sigprocmask(SIG_SETMASK, 0x7F66A074, 0x00000000) = 0 /2: lwp_exit() lwp_wait(2, 0xFFBFF6F4) = 0 write(2, " s l a p d s h u t d o".., 26) = 26 write(2, " O p e n L D A P B a c".., 57) = 57 write(2, " R e m a p B a c k e n d".., 27) = 27 write(2, "\n", 1) = 1 llseek(17, 0xFFFFFFFFFFFFF1F9, SEEK_CUR) = 4601 close(17) = 0 write(2, " s l a p d s h u t d o".., 42) = 42 yield() = 0 write(2, " s l a p d s t o p p e".., 15) = 15 fstat(4, 0xFFBFF588) = 0 time() = 1109235879 getpid() = 17244 [17235] putmsg(4, 0xFFBFEC40, 0xFFBFEC34, 0) = 0 open("/var/run/syslog_door", O_RDONLY) = 7 door_info(7, 0xFFBFEB78) = 0 getpid() = 17244 [17235] door_call(7, 0xFFBFEB60) = 0 close(7) = 0 fstat(4, 0xFFBFF758) = 0 close(4) = 0 shutdown(6, 2, 1) Err#95 ENOTSOCK close(6) = 0 shutdown(5, 2, 1) Err#95 ENOTSOCK close(5) = 0 getpid() = 17244 [17235] unlink("/ha/ldap-test/var/run/slapd-remapper.pid") = 0 unlink("/ha/ldap-test/var/run/slapd-remapper.args") = 0 lwp_mutex_lock(0x7F668A00) = 0 _exit(0) Here are the last 500 lines of Debug-output from slapd: tls_read: want=32, got=32 0000: 8b 5e e3 de dd 35 2c 4f 6f ed 2b a0 82 36 c4 60 .^...5,Oo.+..6.` 0010: 1a bc 6f 94 c2 da f9 e6 29 08 c8 83 1d da 46 62 ..o.....).....Fb ldap_read: want=8, got=7 0000: 30 05 02 01 03 42 00 0....B. ber_get_next: tag 0x30 len 5 contents: ber_dump: buf=0x0080d318 ptr=0x0080d318 end=0x0080d31d len=5 0000: 02 01 03 42 00 ...B. do_unbind conn=1683 op=2 UNBIND ber_get_next tls_read: want=5, got=5 0000: 15 03 01 00 20 .... tls_read: want=32, got=32 0000: e8 e8 0c b5 d6 69 da 94 7d b3 e1 4e 27 e9 36 52 .....i..}..N'.6R 0010: a9 3b 62 82 73 2e 7c 22 1c b8 2e 63 e7 ba 2f f0 .;b.s.|"...c../. TLS trace: SSL3 alert read:warning:close notify back-perl: === Unbind === ldap_read: want=8, got=0 ber_get_next on fd 19 failed errno=0 (Error 0) connection_read(19): input error=-2 id=1683, closing. connection_closing: readying conn=1683 sd=19 for close connection_close: deferring conn=1683 sd=19 daemon: read activity on 24 connection_get(24) connection_get(24): got connid=1684 Perl UNBIND returned 0x0000 connection_read(24): checking for input on id=1684 ber_get_next tls_read: want=5, got=5 0000: 17 03 01 00 20 .... tls_read: want=32, got=32 0000: ae a8 0e 3e fe 2d a6 22 72 dc b9 8d 15 1b 54 64 ...>.-."r.....Td 0010: 07 22 ca e3 83 cb 82 6a 19 cc 6b 39 d4 a8 d2 ae .".....j..k9.... connection_resched: reaquiring locks conn=1683 sd=19 tls_read: want=5, got=5 0000: 17 03 01 00 60 ....` tls_read: want=96, got=96 0000: 5a a6 b4 1e 03 a6 b1 1d 03 f5 cc d1 92 19 f4 b1 Z............... 0010: 2b 47 5a a3 e2 bc a6 02 77 dd ba ea b0 d6 79 9a +GZ.....w.....y. 0020: 8d 49 c5 64 dd dd e9 82 74 a0 3b 00 c1 80 29 df .I.d....t.;...). 0030: f2 60 ce ad d7 d0 0c 84 f2 01 71 0c 2f 16 70 ce .`........q./.p. 0040: aa 83 9e fe a4 dc a5 e3 de f1 3f b6 bf 15 40 c9 ..........?...@. 0050: 45 6e 19 fc e7 7d c3 47 67 98 f7 45 2e 62 e7 3b En...}.Gg..E.b.; ldap_read: want=8, got=8 0000: 30 3d 02 01 01 60 38 02 0=...`8. ldap_read: want=55, got=55 0000: 01 03 04 28 63 6e 3d 70 72 6f 78 79 61 67 65 6e ...(cn=proxyagen 0010: 74 2c 6f 75 3d 70 72 6f 66 69 6c 65 2c 64 63 3d t,ou=profile,dc= 0020: 67 65 62 65 63 6f 2c 64 63 3d 64 65 80 09 70 72 gebeco,dc=de..pr 0030: 6f 78 79 31 32 33 34 oxy1234 ber_get_next: tag 0x30 len 61 contents: ber_dump: buf=0x00ad1a98 ptr=0x00ad1a98 end=0x00ad1ad5 len=61 0000: 02 01 01 60 38 02 01 03 04 28 63 6e 3d 70 72 6f ...`8....(cn=pro 0010: 78 79 61 67 65 6e 74 2c 6f 75 3d 70 72 6f 66 69 xyagent,ou=profi 0020: 6c 65 2c 64 63 3d 67 65 62 65 63 6f 2c 64 63 3d le,dc=gebeco,dc= 0030: 64 65 80 09 70 72 6f 78 79 31 32 33 34 de..proxy1234 ber_get_next do_bind tls_read: want=5 error=Resource temporarily unavailable ldap_read: want=8 error=Resource temporarily unavailable ber_get_next on fd 24 failed errno=11 (Resource temporarily unavailable) ber_scanf fmt ({imt) ber: daemon: select: listen=7 active_threads=0 tvp=NULL daemon: select: listen=8 active_threads=0 tvp=NULL daemon: activity on 5 descriptors ber_dump: buf=0x00ad1a98 ptr=0x00ad1a9b end=0x00ad1ad5 len=58 connection_resched: attempting closing conn=1683 sd=19 connection_close: conn=1683 sd=19 OpenLDAP RemapConnection Autoload: RemapConnection::DESTROY RemapConnection=HASH(0x60c1f0) daemon: select: listen=7 active_threads=0 tvp=NULL 0000: 60 38 02 01 03 04 28 63 6e 3d 70 72 6f 78 79 61 `8....(cn=proxya 0010: 67 65 6e 74 2c 6f 75 3d 70 72 6f 66 69 6c 65 2c gent,ou=profile, 0020: 64 63 3d 67 65 62 65 63 6f 2c 64 63 3d 64 65 80 dc=gebeco,dc=de. 0030: 09 70 72 6f 78 79 31 32 33 34 .proxy1234 ber_scanf fmt (m}) ber: ber_dump: buf=0x00ad1a98 ptr=0x00ad1aca end=0x00ad1ad5 len=11 daemon: select: listen=8 active_threads=0 tvp=NULL 0000: 00 09 70 72 6f 78 79 31 32 33 34 ..proxy1234 >>> dnPrettyNormal: <cn=proxyagent,ou=profile,dc=gebeco,dc=de> => ldap_bv2dn(cn=proxyagent,ou=profile,dc=gebeco,dc=de,0) ldap_err2string daemon: activity on 4 descriptors <= ldap_bv2dn(cn=proxyagent,ou=profile,dc=gebeco,dc=de)=0 Success => ldap_dn2bv(272) slapd(21): setsockopt(SO_KEEPALIVE) failed errno=9 (Bad file number) ldap_err2string <= ldap_dn2bv(cn=proxyagent,ou=profile,dc=gebeco,dc=de)=0 Success => ldap_dn2bv(272) ldap_err2string <= ldap_dn2bv(cn=proxyagent,ou=profile,dc=gebeco,dc=de)=0 Success <<< dnPrettyNormal: <cn=proxyagent,ou=profile,dc=gebeco,dc=de>, <cn=proxyagent,ou=profile,dc=gebeco,dc=de> slapd(21): setsockopt(TCP_NODELAY) failed errno=9 (Bad file number) do_bind: version=3 dn="cn=proxyagent,ou=profile,dc=gebeco,dc=de" method=128 conn=1684 op=0 BIND dn="cn=proxyagent,ou=profile,dc=gebeco,dc=de" method=128 daemon: new connection on 21 daemon: removing 19 conn=1683 fd=19 closed Calling object with connid 24 back-perl: === Bind === back-perl: Bind DN: cn=proxyagent,ou=profile,dc=gebeco,dc=de back-perl: Password: proxy1234 tls_write: want=37, written=37 0000: 15 03 01 00 20 ae 33 c8 59 a3 62 89 ab 9a 8f 47 .... .3.Y.b....G 0010: 6d 0f f2 8d be b8 27 ce 39 23 f2 3e ac 89 4c d9 m.....'.9#.>..L. 0020: 42 5d 55 7f 26 B]U.& TLS trace: SSL3 alert write:warning:close notify connection_init(21, IP=10.144.42.19:58426): set nonblocking failed Perl BIND returned 0x0000 RemapBackend connection_init called with RemapBackend=HASH(0x14865c),21 back-perl: === New === back-perl: Posix Var 1024 and 1024 back-perl: INC: /ha/ldap-test/opt/lib/perl5/5.8.3/sun4-solaris:/ha/ldap-test/opt/lib/perl5/5.8.3:/ha/ldap-test/opt/lib/perl5/site_perl/5.8.3/sun4-solaris:/ha/ldap-test/opt/lib/perl5/site_perl/5.8.3:/ha/ldap-test/opt/lib/perl5/site_perl:.:/ha/ldap-test/ha/ldap-test/opt/etc/openldap back-perl: Options: managerPW,test123,managerDN,cn=Manager,dc=gebeco,dc=de,httpserver,(undef),masterLDAP,ldaps://ldap-test.gebeco.de:637 conn=1684 op=0 BIND dn="cn=proxyagent,ou=profile,dc=gebeco,dc=de" mech=SIMPLE ssf=0 do_bind: v3 bind: "cn=proxyagent,ou=profile,dc=gebeco,dc=de" to "cn=proxyagent,ou=profile,dc=gebeco,dc=de" send_ldap_result: conn=1684 op=0 p=3 send_ldap_result: err=0 matched="" text="" send_ldap_response: msgid=1 tag=97 err=0 ber_flush: 14 bytes to sd 24 0000: 30 0c 02 01 01 61 07 0a 01 00 04 00 04 00 0....a........ tls_write: want=90, written=90 0000: 17 03 01 00 20 ac ed 9c c8 45 f7 74 94 82 3b 3e .... ....E.t..;> 0010: b7 5d ab fb 9d 71 8d 62 b0 cf 78 66 6a 1b c5 df .]...q.b..xfj... 0020: 2c d4 18 06 d7 17 03 01 00 30 c7 cb ca 34 fc 9e ,........0...4.. 0030: 0d e5 24 09 0e f5 5d e6 b9 8b 78 66 5c 1c 57 0c ..$...]...xf\.W. 0040: ec 62 66 6b 3f fe 03 3e 85 53 65 14 16 6c f3 8e .bfk?..>.Se..l.. 0050: b3 87 22 c8 29 a9 8e d8 e1 a6 ..".)..... ldap_write: want=14, written=14 0000: 30 0c 02 01 01 61 07 0a 01 00 04 00 04 00 0....a........ conn=1684 op=0 RESULT tag=97 err=0 text= conn=1687 fd=21 ACCEPT from IP=10.144.42.19:58426 (IP=10.144.42.19:636) daemon: added 21r daemon: activity on: 15r 16r 33r daemon: read activity on 15 connection_get(15) connection_get(15): got connid=1685 connection_read(15): checking for input on id=1685 ber_get_next tls_read: want=5, got=5 0000: 17 03 01 00 20 .... tls_read: want=32, got=32 0000: ae 62 7b c5 f0 d8 19 9a 50 23 37 91 47 48 71 44 .b{.....P#7.GHqD 0010: 8a 49 97 17 64 58 58 02 f8 f7 f0 0a 21 37 7f 1d .I..dXX.....!7.. tls_read: want=5, got=5 0000: 17 03 01 00 60 ....` tls_read: want=96, got=96 0000: 28 c9 00 3c 88 af 7b 89 ba e4 bc e5 a4 80 92 67 (..<..{........g 0010: 91 99 33 2c b6 3c ec 1a 40 7e 89 11 03 5c 28 6b ..3,.<..@~...\(k 0020: 8d b7 8e a3 a8 70 74 3b f3 6f 4b aa 04 e7 ca 55 .....pt;.oK....U 0030: 9f bc b1 e3 6d b5 0e 65 89 c9 e0 20 62 f5 d4 08 ....m..e... b... 0040: 14 86 99 12 8a 42 29 21 ca 32 42 3e a9 5e 1d 51 .....B)!.2B>.^.Q 0050: 01 a4 b1 ff b0 1b 97 52 e2 53 96 51 ef a7 a9 8d .......R.S.Q.... ldap_read: want=8, got=8 0000: 30 3d 02 01 01 60 38 02 0=...`8. ldap_read: want=55, got=55 0000: 01 03 04 28 63 6e 3d 70 72 6f 78 79 61 67 65 6e ...(cn=proxyagen 0010: 74 2c 6f 75 3d 70 72 6f 66 69 6c 65 2c 64 63 3d t,ou=profile,dc= 0020: 67 65 62 65 63 6f 2c 64 63 3d 64 65 80 09 70 72 gebeco,dc=de..pr 0030: 6f 78 79 31 32 33 34 oxy1234 ber_get_next: tag 0x30 len 61 contents: ber_dump: buf=0x00953708 ptr=0x00953708 end=0x00953745 len=61 0000: 02 01 01 60 38 02 01 03 04 28 63 6e 3d 70 72 6f ...`8....(cn=pro 0010: 78 79 61 67 65 6e 74 2c 6f 75 3d 70 72 6f 66 69 xyagent,ou=profi 0020: 6c 65 2c 64 63 3d 67 65 62 65 63 6f 2c 64 63 3d le,dc=gebeco,dc= 0030: 64 65 80 09 70 72 6f 78 79 31 32 33 34 de..proxy1234 ber_get_next do_bind tls_read: want=5 error=Resource temporarily unavailable ldap_read: want=8 error=Resource temporarily unavailable ber_get_next on fd 15 failed errno=11 (Resource temporarily unavailable) daemon: read activity on 16 connection_get(16) connection_get(16): got connid=1686 ber_scanf fmt ({imt) ber: ber_dump: buf=0x00953708 ptr=0x0095370b end=0x00953745 len=58 0000: 60 38 02 01 03 04 28 63 6e 3d 70 72 6f 78 79 61 `8....(cn=proxya 0010: 67 65 6e 74 2c 6f 75 3d 70 72 6f 66 69 6c 65 2c gent,ou=profile, 0020: 64 63 3d 67 65 62 65 63 6f 2c 64 63 3d 64 65 80 dc=gebeco,dc=de. 0030: 09 70 72 6f 78 79 31 32 33 34 .proxy1234 ber_scanf fmt (m}) ber: ber_dump: buf=0x00953708 ptr=0x0095373a end=0x00953745 len=11 0000: 00 09 70 72 6f 78 79 31 32 33 34 ..proxy1234 >>> dnPrettyNormal: <cn=proxyagent,ou=profile,dc=gebeco,dc=de> => ldap_bv2dn(cn=proxyagent,ou=profile,dc=gebeco,dc=de,0) ldap_err2string <= ldap_bv2dn(cn=proxyagent,ou=profile,dc=gebeco,dc=de)=0 Success => ldap_dn2bv(272) ldap_err2string <= ldap_dn2bv(cn=proxyagent,ou=profile,dc=gebeco,dc=de)=0 Success => ldap_dn2bv(272) ldap_err2string <= ldap_dn2bv(cn=proxyagent,ou=profile,dc=gebeco,dc=de)=0 Success <<< dnPrettyNormal: <cn=proxyagent,ou=profile,dc=gebeco,dc=de>, <cn=proxyagent,ou=profile,dc=gebeco,dc=de> do_bind: version=3 dn="cn=proxyagent,ou=profile,dc=gebeco,dc=de" method=128 conn=1685 op=0 BIND dn="cn=proxyagent,ou=profile,dc=gebeco,dc=de" method=128 connection_read(16): checking for input on id=1686 TLS trace: SSL_accept:before/accept initialization tls_read: want=11, got=11 0000: 80 92 01 03 01 00 69 00 00 00 20 ......i... tls_read: want=137, got=137 0000: 00 00 39 00 00 38 00 00 35 00 00 16 00 00 13 00 ..9..8..5....... 0010: 00 0a 07 00 c0 00 00 33 00 00 32 00 00 2f 00 00 .......3..2../.. 0020: 07 05 00 80 03 00 80 00 00 66 00 00 05 00 00 04 .........f...... 0030: 01 00 80 08 00 80 00 00 63 00 00 62 00 00 61 00 ........c..b..a. 0040: 00 15 00 00 12 00 00 09 06 00 40 00 00 65 00 00 ..........@..e.. 0050: 64 00 00 60 00 00 14 00 00 11 00 00 08 00 00 06 d..`............ 0060: 04 00 80 00 00 03 02 00 80 ab 50 35 af e5 fb a5 ..........P5.... 0070: 8c e9 39 a7 c8 3f f7 14 3d 27 1b 13 a1 af 1f e5 ..9..?..='...... 0080: 8f 23 4d 64 63 17 d3 4d a2 .#Mdc..M. Calling object with connid 15 back-perl: === Bind === back-perl: Bind DN: cn=proxyagent,ou=profile,dc=gebeco,dc=de back-perl: Password: proxy1234 TLS trace: SSL_accept:SSLv3 read client hello A TLS trace: SSL_accept:SSLv3 write server hello A TLS trace: SSL_accept:SSLv3 write certificate A TLS trace: SSL_accept:SSLv3 write server done A tls_write: want=1852, written=1852 0000: 16 03 01 00 4a 02 00 00 46 03 01 42 1d 98 a7 19 ....J...F..B.... 0010: 51 f8 b9 db dc 6e 82 68 1f 66 6f 26 89 b5 67 98 Q....n.h.fo&..g. 0020: 42 ff 5b 8b 2b 5f cf b5 3f ff 6b 20 93 ae e7 0a B.[.+_..?.k .... 0030: 9a 0f e4 70 02 a7 56 d5 db dd 88 f3 64 2d 4c ac ...p..V.....d-L. 0040: 20 07 f9 1e a6 cd 78 31 9c 97 b4 49 00 35 00 16 .....x1...I.5.. 0050: 03 01 06 df 0b 00 06 db 00 06 d8 00 03 6c 30 82 .............l0. 0060: 03 68 30 82 02 d1 a0 03 02 01 02 02 01 05 30 0d .h0...........0. 0070: 06 09 2a 86 48 86 f7 0d 01 01 04 05 00 30 81 83 ..*.H........0.. 0080: 31 0b 30 09 06 03 55 04 06 13 02 44 45 31 1b 30 1.0...U....DE1.0 0090: 19 06 03 55 04 08 13 12 53 63 68 6c 65 73 77 69 ...U....Schleswi 00a0: 67 2d 48 6f 6c 73 74 65 69 6e 31 0d 30 0b 06 03 g-Holstein1.0... 00b0: 55 04 07 13 04 4b 69 65 6c 31 0f 30 0d 06 03 55 U....Kiel1.0...U 00c0: 04 0a 13 06 47 65 42 65 43 6f 31 1a 30 18 06 03 ....GeBeCo1.0... 00d0: 55 04 03 13 11 74 6f 65 6c 70 65 6c 2e 67 65 62 U....toelpel.geb 00e0: 65 63 6f 2e 64 65 31 1b 30 19 06 09 2a 86 48 86 eco.de1.0...*.H. 00f0: f7 0d 01 09 01 16 0c 74 73 40 67 65 62 65 63 6f .......ts@gebeco 0100: 2e 64 65 30 1e 17 0d 30 34 31 30 31 35 31 32 34 .de0...041015124 0110: 38 34 38 5a 17 0d 30 35 31 30 31 35 31 32 34 38 848Z..0510151248 0120: 34 38 5a 30 5d 31 0b 30 09 06 03 55 04 06 13 02 48Z0]1.0...U.... 0130: 44 45 31 10 30 0e 06 03 55 04 08 13 07 47 65 72 DE1.0...U....Ger 0140: 6d 61 6e 79 31 0d 30 0b 06 03 55 04 07 13 04 4b many1.0...U....K 0150: 69 65 6c 31 0f 30 0d 06 03 55 04 0a 13 06 47 65 iel1.0...U....Ge 0160: 62 65 63 6f 31 1c 30 1a 06 03 55 04 03 13 13 6c beco1.0...U....l 0170: 64 61 70 2d 74 65 73 74 2e 67 65 62 65 63 6f 2e dap-test.gebeco. 0180: 64 65 30 81 9f 30 0d 06 09 2a 86 48 86 f7 0d 01 de0..0...*.H.... 0190: 01 01 05 00 03 81 8d 00 30 81 89 02 81 81 00 af ........0....... 01a0: 1b 52 72 aa 04 b5 ea 9c 90 15 bf e7 eb d1 63 a3 .Rr...........c. 01b0: 2f 22 36 34 b4 a9 72 2a 2f d2 4b 52 7c ed b8 7b /"64..r*/.KR|..{ 01c0: 71 df f9 52 0c ae db b7 1a 33 51 f9 31 e6 6c 66 q..R.....3Q.1.lf 01d0: f9 43 71 3a a4 67 38 55 75 b9 88 2a 68 75 c9 e2 .Cq:.g8Uu..*hu.. 01e0: 5f b6 28 2f 0f 48 66 51 39 59 6f 89 3e 91 ff 65 _.(/.HfQ9Yo.>..e 01f0: bf 24 28 9b 75 ab 8f ef b1 be f8 ff 4a 6a 92 90 .$(.u.......Jj.. 0200: e5 e3 b1 83 16 98 57 1f cf d0 c1 44 98 55 d8 73 ......W....D.U.s 0210: 69 3c 74 a7 76 47 19 c8 b6 1e 9f 92 5f 6c 9b 02 i<t.vG......_l.. 0220: 03 01 00 01 a3 82 01 0f 30 82 01 0b 30 09 06 03 ........0...0... 0230: 55 1d 13 04 02 30 00 30 2c 06 09 60 86 48 01 86 U....0.0,..`.H.. 0240: f8 42 01 0d 04 1f 16 1d 4f 70 65 6e 53 53 4c 20 .B......OpenSSL 0250: 47 65 6e 65 72 61 74 65 64 20 43 65 72 74 69 66 Generated Certif 0260: 69 63 61 74 65 30 1d 06 03 55 1d 0e 04 16 04 14 icate0...U...... 0270: eb 08 98 ed 0e 15 68 3e 69 2d 40 f5 c3 d3 ab 64 ......h>i-@....d 0280: 13 a2 5a 34 30 81 b0 06 03 55 1d 23 04 81 a8 30 ..Z40....U.#...0 0290: 81 a5 80 14 cf de 16 ac 47 55 22 e4 72 56 98 42 ........GU".rV.B 02a0: 0e c4 56 f4 a9 09 5b 1a a1 81 89 a4 81 86 30 81 ..V...[.......0. 02b0: 83 31 0b 30 09 06 03 55 04 06 13 02 44 45 31 1b .1.0...U....DE1. 02c0: 30 19 06 03 55 04 08 13 12 53 63 68 6c 65 73 77 0...U....Schlesw 02d0: 69 67 2d 48 6f 6c 73 74 65 69 6e 31 0d 30 0b 06 ig-Holstein1.0.. 02e0: 03 55 04 07 13 04 4b 69 65 6c 31 0f 30 0d 06 03 .U....Kiel1.0... 02f0: 55 04 0a 13 06 47 65 42 65 43 6f 31 1a 30 18 06 U....GeBeCo1.0.. 0300: 03 55 04 03 13 11 74 6f 65 6c 70 65 6c 2e 67 65 .U....toelpel.ge 0310: 62 65 63 6f 2e 64 65 31 1b 30 19 06 09 2a 86 48 beco.de1.0...*.H 0320: 86 f7 0d 01 09 01 16 0c 74 73 40 67 65 62 65 63 ........ts@gebec 0330: 6f 2e 64 65 82 01 00 30 0d 06 09 2a 86 48 86 f7 o.de...0...*.H.. 0340: 0d 01 01 04 05 00 03 81 81 00 c6 1d 3e d0 81 b5 ............>... 0350: cf 00 2c 5a 62 ff 4b 8f 6e cb 85 8a 99 41 09 fc ..,Zb.K.n....A.. 0360: d6 f8 ec 34 76 98 8e e2 92 d1 16 d1 d6 e4 9c 27 ...4v..........' 0370: 35 ea 04 80 cd f7 b3 e7 b8 4f 4d a4 e9 e6 4f 35 5........OM...O5 0380: 33 4d a6 84 f5 f3 80 2f b5 33 5a e9 80 5d 7d f2 3M...../.3Z..]}. 0390: 2e f4 e2 ea b4 53 2a 11 28 9e 78 a5 bb 15 59 9e .....S*.(.x...Y. 03a0: 4e df d4 f6 50 79 42 87 1f 73 14 ca 53 7c 96 c3 N...PyB..s..S|.. 03b0: 41 d2 40 02 17 39 6b ba 5c 31 b1 50 81 b9 7f b8 A.@..9k.\1.P.... 03c0: 3c 46 4d 1b c9 07 5e 3a 78 64 00 03 66 30 82 03 <FM...^:xd..f0.. 03d0: 62 30 82 02 cb a0 03 02 01 02 02 01 00 30 0d 06 b0...........0.. 03e0: 09 2a 86 48 86 f7 0d 01 01 04 05 00 30 81 83 31 .*.H........0..1 03f0: 0b 30 09 06 03 55 04 06 13 02 44 45 31 1b 30 19 .0...U....DE1.0. 0400: 06 03 55 04 08 13 12 53 63 68 6c 65 73 77 69 67 ..U....Schleswig 0410: 2d 48 6f 6c 73 74 65 69 6e 31 0d 30 0b 06 03 55 -Holstein1.0...U 0420: 04 07 13 04 4b 69 65 6c 31 0f 30 0d 06 03 55 04 ....Kiel1.0...U. 0430: 0a 13 06 47 65 42 65 43 6f 31 1a 30 18 06 03 55 ...GeBeCo1.0...U 0440: 04 03 13 11 74 6f 65 6c 70 65 6c 2e 67 65 62 65 ....toelpel.gebe 0450: 63 6f 2e 64 65 31 1b 30 19 06 09 2a 86 48 86 f7 co.de1.0...*.H.. 0460: 0d 01 09 01 16 0c 74 73 40 67 65 62 65 63 6f 2e ......ts@gebeco. 0470: 64 65 30 1e 17 0d 30 34 30 38 31 38 31 34 31 30 de0...0408181410 0480: 33 32 5a 17 0d 30 35 30 38 31 38 31 34 31 30 33 32Z..05081814103 0490: 32 5a 30 81 83 31 0b 30 09 06 03 55 04 06 13 02 2Z0..1.0...U.... 04a0: 44 45 31 1b 30 19 06 03 55 04 08 13 12 53 63 68 DE1.0...U....Sch 04b0: 6c 65 73 77 69 67 2d 48 6f 6c 73 74 65 69 6e 31 leswig-Holstein1 04c0: 0d 30 0b 06 03 55 04 07 13 04 4b 69 65 6c 31 0f .0...U....Kiel1. 04d0: 30 0d 06 03 55 04 0a 13 06 47 65 42 65 43 6f 31 0...U....GeBeCo1 04e0: 1a 30 18 06 03 55 04 03 13 11 74 6f 65 6c 70 65 .0...U....toelpe 04f0: 6c 2e 67 65 62 65 63 6f 2e 64 65 31 1b 30 19 06 l.gebeco.de1.0.. 0500: 09 2a 86 48 86 f7 0d 01 09 01 16 0c 74 73 40 67 .*.H........ts@g 0510: 65 62 65 63 6f 2e 64 65 30 81 9f 30 0d 06 09 2a ebeco.de0..0...* 0520: 86 48 86 f7 0d 01 01 01 05 00 03 81 8d 00 30 81 .H............0. 0530: 89 02 81 81 00 c7 21 aa 8d 4b 37 08 96 1e 73 ee ......!..K7...s. 0540: 24 3c 1f 3f ca be 95 54 94 2e 3e cc d1 e1 df 13 $<.?...T..>..... 0550: da 1d 40 21 60 f5 9c 69 6b dc 1f 92 dd 2f c0 cb ..@!`..ik..../.. 0560: 01 92 97 18 b9 d1 1c b2 a9 aa a5 f6 bc 57 35 f3 .............W5. 0570: 03 08 21 79 89 f4 ab 7a 77 d8 be 51 c0 43 73 4c ..!y...zw..Q.CsL 0580: 5c d3 08 32 37 7e 43 12 a6 f8 a9 8d 41 7b 61 44 \..27~C.....A{aD 0590: ec 57 55 d5 bb 3e 8f 98 91 be 82 1c 4a 16 b9 61 .WU..>......J..a 05a0: 4f 39 42 1e 44 6f b6 c3 37 00 c8 5e 69 dc 6c fa O9B.Do..7..^i.l. 05b0: b4 74 be 57 af 02 03 01 00 01 a3 81 e3 30 81 e0 .t.W.........0.. 05c0: 30 1d 06 03 55 1d 0e 04 16 04 14 cf de 16 ac 47 0...U..........G 05d0: 55 22 e4 72 56 98 42 0e c4 56 f4 a9 09 5b 1a 30 U".rV.B..V...[.0 05e0: 81 b0 06 03 55 1d 23 04 81 a8 30 81 a5 80 14 cf ....U.#...0..... 05f0: de 16 ac 47 55 22 e4 72 56 98 42 0e c4 56 f4 a9 ...GU".rV.B..V.. 0600: 09 5b 1a a1 81 89 a4 81 86 30 81 83 31 0b 30 09 .[.......0..1.0. 0610: 06 03 55 04 06 13 02 44 45 31 1b 30 19 06 03 55 ..U....DE1.0...U 0620: 04 08 13 12 53 63 68 6c 65 73 77 69 67 2d 48 6f ....Schleswig-Ho 0630: 6c 73 74 65 69 6e 31 0d 30 0b 06 03 55 04 07 13 lstein1.0...U... 0640: 04 4b 69 65 6c 31 0f 30 0d 06 03 55 04 0a 13 06 .Kiel1.0...U.... 0650: 47 65 42 65 43 6f 31 1a 30 18 06 03 55 04 03 13 GeBeCo1.0...U... 0660: 11 74 6f 65 6c 70 65 6c 2e 67 65 62 65 63 6f 2e .toelpel.gebeco. 0670: 64 65 31 1b 30 19 06 09 2a 86 48 86 f7 0d 01 09 de1.0...*.H..... 0680: 01 16 0c 74 73 40 67 65 62 65 63 6f 2e 64 65 82 ...ts@gebeco.de. 0690: 01 00 30 0c 06 03 55 1d 13 04 05 30 03 01 01 ff ..0...U....0.... 06a0: 30 0d 06 09 2a 86 48 86 f7 0d 01 01 04 05 00 03 0...*.H......... 06b0: 81 81 00 a2 86 4e 22 ab 5d 0a ed a9 a1 84 e9 fc .....N".]....... 06c0: 0c a5 72 22 a2 89 7a d6 f1 14 97 1a 37 f5 83 45 ..r"..z.....7..E 06d0: c4 07 d0 fb d3 47 54 b3 ee e5 20 29 e3 7e a5 aa .....GT... ).~.. 06e0: 19 62 c8 0d be 4c 2d e6 d2 e1 24 4b a4 61 f7 5d .b...L-...$K.a.] 06f0: cc c1 82 5a 65 f7 b4 da b4 3c eb 14 7d 68 bb 01 ...Ze....<..}h.. 0700: 2b ee f6 34 75 53 2b f5 e0 92 d4 a2 27 c3 b8 bc +..4uS+.....'... 0710: a0 81 51 56 9d 9b 60 c2 25 79 52 09 19 cc 33 6d ..QV..`.%yR...3m 0720: 50 cf ae 85 86 70 db 52 40 27 39 c8 6b 36 9a 15 P....p.R@'9.k6.. 0730: 93 68 24 16 03 01 00 04 0e 00 00 00 .h$......... TLS trace: SSL_accept:SSLv3 flush data Perl BIND returned 0x0000 tls_read: want=5, got=5 0000: 16 03 01 00 86 ..... tls_read: want=134, got=134 0000: 10 00 00 82 00 80 4d 03 c9 be 57 7a 02 6a 14 46 ......M...Wz.j.F 0010: 03 17 31 ea 6b 06 1f 2f 0d 16 c7 07 90 21 33 69 ..1.k../.....!3i 0020: 37 43 bb 76 c6 06 78 45 73 9d de ce ec ea 00 81 7C.v..xEs....... 0030: 20 ec 9a 36 f8 3b 59 af a2 78 5c a1 e8 fa 08 57 ..6.;Y..x\....W 0040: 50 a6 97 db 21 04 3a 4a 09 c1 b8 c2 21 40 2a 03 P...!.:J....!@*. 0050: 56 e4 1f 17 39 33 3b 3c 2a 5f 99 d3 3d 19 3d 0b V...93;<*_..=.=. 0060: 5a 89 a3 09 e2 36 04 76 85 b1 d7 9f 35 d6 41 95 Z....6.v....5.A. 0070: 67 7e c5 ed 44 95 38 92 ff b3 2e 74 17 ce d2 d3 g~..D.8....t.... 0080: 0f 0d 26 e2 a9 cf ..&... conn=1685 op=0 BIND dn="cn=proxyagent,ou=profile,dc=gebeco,dc=de" mech=SIMPLE ssf=0 do_bind: v3 bind: "cn=proxyagent,ou=profile,dc=gebeco,dc=de" to "cn=proxyagent,ou=profile,dc=gebeco,dc=de" send_ldap_result: conn=1685 op=0 p=3 send_ldap_result: err=0 matched="" text="" send_ldap_response: msgid=1 tag=97 err=0 ber_flush: 14 bytes to sd 15 0000: 30 0c 02 01 01 61 07 0a 01 00 04 00 04 00 0....a........ tls_write: want=90, written=90 0000: 17 03 01 00 20 9e bd fe d4 e1 61 7e 81 b9 06 6d .... .....a~...m 0010: c3 d9 e7 95 a5 58 f5 e2 77 75 a7 37 91 af 87 39 .....X..wu.7...9 0020: d0 91 39 fe 0a 17 03 01 00 30 cf 99 77 34 a7 c2 ..9......0..w4.. 0030: 59 df 81 69 61 b1 ad 34 ea dc f2 57 ca f5 96 6b Y..ia..4...W...k 0040: 78 65 20 be 86 60 74 27 7f 75 7f db b0 33 83 17 xe ..`t'.u...3.. 0050: 1f 59 a6 57 cc e4 4c ba fb 88 .Y.W..L... ldap_write: want=14, written=14 0000: 30 0c 02 01 01 61 07 0a 01 00 04 00 04 00 0....a........ conn=1685 op=0 RESULT tag=97 err=0 text= TLS trace: SSL_accept:SSLv3 read client key exchange A tls_read: want=5, got=5 0000: 14 03 01 00 01 ..... tls_read: want=1, got=1 0000: 01 . tls_read: want=5, got=5 0000: 16 03 01 00 30 ....0 tls_read: want=48, got=48 0000: 1c a6 75 0f 20 a8 7b 81 80 b0 46 75 ee 35 b9 89 ..u. .{...Fu.5.. 0010: 58 4e 6f 06 5c 87 c4 7c 5a d0 04 21 1c 0f 0c 86 XNo.\..|Z..!.... 0020: 63 47 cb 86 1a ae e5 24 29 bf 20 a3 28 69 bf e3 cG.....$). .(i.. TLS trace: SSL_accept:SSLv3 read finished A TLS trace: SSL_accept:SSLv3 write change cipher spec A TLS trace: SSL_accept:SSLv3 write finished A tls_write: want=59, written=59 0000: 14 03 01 00 01 01 16 03 01 00 30 af 96 d4 0f 92 ..........0..... 0010: a2 aa 6c e0 ab ea 7a cc 8f 06 a9 d1 69 e0 31 47 ..l...z.....i.1G 0020: 31 c6 bd 28 f2 e0 0f 95 2c 6e cb 85 11 7d 71 32 1..(....,n...}q2 0030: 12 d9 23 34 43 7f 82 32 7b ae 4d ..#4C..2{.M TLS trace: SSL_accept:SSLv3 flush data connection_read(16): unable to get TLS client DN, error=49 id=1686 daemon: read activity on 33 connection_get(33) connection_get(33): got connid=1681 connection_read(33): checking for input on id=1681 ber_get_next tls_read: want=5, got=5 0000: 17 03 01 00 20 .... tls_read: want=32, got=32 0000: 71 97 9d 90 d5 7b a5 e9 8c 8e fa 4f 37 7b 88 42 q....{.....O7{.B 0010: e3 5c c7 93 73 07 d1 5a b2 0d c7 e7 46 42 fc bc .\..s..Z....FB.. tls_read: want=5, got=5 0000: 17 03 01 00 20 .... tls_read: want=32, got=32 0000: c1 99 87 8a 63 43 ef f8 45 13 73 ed cc f3 9b 7c ....cC..E.s....| 0010: 8d d4 39 33 20 8a b5 bf 0c 61 9f e9 f9 a9 d3 0c ..93 ....a...... ldap_read: want=8, got=7 0000: 30 05 02 01 03 42 00 0....B. ber_get_next: tag 0x30 len 5 contents: ber_dump: buf=0x00e66858 ptr=0x00e66858 end=0x00e6685d len=5 0000: 02 01 03 42 00 ...B. ber_get_next do_unbind conn=1681 op=2 UNBIND tls_read: want=5, got=5 0000: 15 03 01 00 20 .... tls_read: want=32, got=32 0000: a4 0b e3 b8 91 f5 ae cf 01 2d 50 19 24 be 18 c6 .........-P.$... 0010: e2 01 d5 37 94 cb f8 fc c0 40 1d 02 fd a9 2a 92 ...7.....@....*. TLS trace: SSL3 alert read:warning:close notify ldap_read: want=8, got=0 ber_get_next on fd 33 failed errno=0 (Error 0) connection_read(33): input error=-2 id=1681, closing. connection_closing: readying conn=1681 sd=33 for close back-perl: === Unbind === connection_close: deferring conn=1681 sd=33 daemon: select: listen=7 active_threads=0 tvp=NULL daemon: select: listen=8 active_threads=0 tvp=NULL daemon: select: listen=7 active_threads=0 tvp=NULL daemon: select: listen=8 active_threads=0 tvp=NULL daemon: select: listen=7 active_threads=0 tvp=NULL daemon: select: listen=8 active_threads=0 tvp=NULL Perl UNBIND returned 0x0000 daemon: select: listen=7 active_threads=0 tvp=NULL daemon: select: listen=8 active_threads=0 tvp=NULL daemon: select: listen=7 active_threads=0 tvp=NULL daemon: select: listen=8 active_threads=0 tvp=NULL daemon: select failed (89): Operation not applicable daemon: abnormal condition, shutdown initiated. daemon: closing 7 connection_resched: attempting closing conn=1681 sd=33 connection_close: conn=1681 sd=33 daemon: closing 8 OpenLDAP RemapConnection Autoload: RemapConnection::DESTROY RemapConnection=HASH(0xac10c4) daemon: removing 33 conn=1681 fd=33 closed tls_write: want=37, written=37 0000: 15 03 01 00 20 ac 20 d7 ff fb 8c 04 fa 67 40 6b .... . ......g@k 0010: 82 d5 cd dd d9 68 99 69 43 bb fd 48 3a e8 f4 ff .....h.iC..H:... 0020: 8c b8 79 6e a9 ..yn. TLS trace: SSL3 alert write:warning:close notify connection_closing: readying conn=1685 sd=15 for close connection_close: conn=1685 sd=15 OpenLDAP RemapConnection Autoload: RemapConnection::DESTROY RemapConnection=HASH(0x92686c) daemon: removing 15 conn=1685 fd=15 closed tls_write: want=37, written=37 0000: 15 03 01 00 20 7b 6f 3a 65 45 08 08 12 5c cc da .... {o:eE...\.. 0010: bf 29 7a 27 32 76 0c 5b 70 24 dc 99 47 e6 e4 53 .)z'2v.[p$..G..S 0020: 3e fd bc dc 5e >...^ TLS trace: SSL3 alert write:warning:close notify connection_closing: readying conn=1686 sd=16 for close connection_close: conn=1686 sd=16 OpenLDAP RemapConnection Autoload: RemapConnection::DESTROY RemapConnection=HASH(0x922990) daemon: removing 16 conn=1686 fd=16 closed tls_write: want=37, written=37 0000: 15 03 01 00 20 c5 c1 7d 93 a7 4d aa 50 4e 1b b4 .... ..}..M.PN.. 0010: 21 cd ed 5c c4 05 40 22 75 2f 59 6c 5c 84 b5 54 !..\..@"u/Yl\..T 0020: ce 10 86 9d bd ..... TLS trace: SSL3 alert write:warning:close notify connection_closing: readying conn=1687 sd=21 for close connection_close: conn=1687 sd=21 OpenLDAP RemapConnection Autoload: RemapConnection::DESTROY RemapConnection=HASH(0xac10b8) daemon: removing 21 conn=1687 fd=21 closed connection_closing: readying conn=1513 sd=23 for close connection_close: conn=1513 sd=23 OpenLDAP RemapConnection Autoload: RemapConnection::DESTROY RemapConnection=HASH(0x978ba4) daemon: removing 23 conn=1513 fd=23 closed connection_closing: readying conn=1684 sd=24 for close connection_close: conn=1684 sd=24 OpenLDAP RemapConnection Autoload: RemapConnection::DESTROY RemapConnection=HASH(0x91dae0) daemon: removing 24 conn=1684 fd=24 closed tls_write: want=37, written=37 0000: 15 03 01 00 20 4d 4c e1 8e 97 c5 d6 ad ee 55 c0 .... ML.......U. 0010: 38 b9 39 b2 c8 99 3e 15 b9 de 9d 0c c9 21 3a b7 8.9...>......!:. 0020: c5 a6 20 9f eb .. .. TLS trace: SSL3 alert write:warning:close notify slapd shutdown: waiting for 0 threads to terminate slapd shutdown: initiated OpenLDAP Backend Adaptor Autoload: RemapBackend::DESTROY RemapBackend=HASH(0x14865c) slapd shutdown: freeing system resources. slapd stopped. The full logs are available on request. Any help is appreciated. Best regards -- Dagobert Michelsen
Hi, further investigation lead me to the assumption that this might be a duplicate of ITS#3206 (slapd crashing with daemon: select failed (89)) ITS#3206 seems to be closed because of missing configuration details. Therefore I included our slapd.conf: loglevel 256 ucdata-path /ha/ldap-test/opt/share/openldap/ucdata include /ha/ldap-test/opt/etc/openldap/schema/core.schema include /ha/ldap-test/opt/etc/openldap/schema/cosine.schema include /ha/ldap-test/opt/etc/openldap/schema/inetorgperson.schema include /ha/ldap-test/opt/etc/openldap/schema/nis.schema include /ha/ldap-test/opt/etc/openldap/schema/solaris.schema include /ha/ldap-test/opt/etc/openldap/schema/automount.schema include /ha/ldap-test/opt/etc/openldap/schema/samba.schema include /ha/ldap-test/opt/etc/openldap/schema/DUAConfigProfile.schema include /ha/ldap-test/opt/etc/openldap/schema/communigate.schema include /ha/ldap-test/opt/etc/openldap/schema/password-expiry.schema pidfile /ha/ldap-test/var/run/slapd-remapper.pid argsfile /ha/ldap-test/var/run/slapd-remapper.args # Load dynamic backend modules: modulepath /ha/ldap-test/opt/libexec/openldap moduleload back_perl.la # moduleload back_bdb.la # moduleload back_ldap.la # moduleload back_ldbm.la # moduleload back_passwd.la # moduleload back_shell.la # This is needed for the Linux Automounter allow bind_v2 bind_anon_dn password-hash {CLEARTEXT} access to attrs=userPassword by dn="cn=proxyagent,ou=profile,dc=gebeco,dc=de" read by dn="cn=CommuniGate,dc=gebeco,dc=de" write by dn="cn=Manager,dc=gebeco,dc=de" write by anonymous auth by self write by * none access to * by dn="cn=CommuniGate,dc=gebeco,dc=de" write by * read TLSCipherSuite HIGH:MEDIUM:+SSLv2 TLSCertificateFile /ha/ldap-test/opt/etc/openldap/ldapcert.pem TLSCertificateKeyFile /ha/ldap-test/opt/etc/openldap/ldapkey.pem TLSCACertificateFile /ha/ldap-test/opt/etc/openldap/demoCA/cacert.pem defaultsearchbase "dc=gebeco,dc=de" ####################################################################### # Perl Backend Specification ####################################################################### database perl suffix "dc=gebeco,dc=de" perlModulePath /ha/ldap-test/opt/etc/openldap perlModule RemapBackend managerPW secret managerDN cn=Manager,dc=gebeco,dc=de masterLDAP ldaps://ldap-test.gebeco.de:637 Best regards -- Dagobert Michelsen -- Dagobert Michelsen (Leiter IT) Baltic Online Computer GmbH Alter Markt 1-2, 24103 Kiel, +49 431 54003-0 (Fon) -99 (Fax) Flughafenstr. 52c, 22335 Hamburg, +49 40 53299-395 (Fon) -100 (Fax) Big Servers, Fat Pipes, Massive Storage, Objects Everywhere
dam@baltic-online.de wrote: >Full_Name: Dagobert Michelsen >Version: 2.2.23 >OS: Solaris 9 4/04 >URL: >Submission from: (NULL) (62.214.9.52) > > >The slapd process terminates unexpectedly after a random number of requests. >Before 2.2.23 we used 2.2.17 and were forced to upgrade because of ITS#3400 >(loop in >slapd_daemon_task() (daemon.c) after repeated EBADF returns from select()) The >modification in ITS#3400 seem to change the behaviour from spinning to >terminating >which I assume is the change we are seeing here. However the cause of the >termination >is still unclear. > >The problem was reproduced on a SunFire V440 with 4 CPUs. We were unable to >reproduce the problem on server with 1 CPU, so it might be a threading/sync >issue. > > That's definitely a possibility. We've seen threading issues on Solaris 8 that were fixed by switching to use the new threads library (which is the default library on Solaris 9) but I'm not aware of any issues with the Solaris 9 threads library. Perhaps you found one. >Additionally we are seeing the problem only with the instance using the >Perl backend, not with BDB. We use a modified back-perl which instantiates >a new Perl object with each connection but I cannot see any evidence that the >termination is due to our backend-modifications. > > If your usage pattern for back-bdb and back-perl are the same, but the problem does not occur with back-bdb, that certainly points at your back-perl code. The truss output you sent begins too late, after the slapd shutdown sequence has already begun. It might help to see a little more of that so we can see what happens leading up to the first failed select call. -- -- Howard Chu Chief Architect, Symas Corp. Director, Highland Sun http://www.symas.com http://highlandsun.com/hyc Symas: Premier OpenSource Development and Support
Hello, Von Howard Chu <hyc@symas.com> (Fri, 04 Mar 2005 09:55:33 -0800): > dam@baltic-online.de wrote: > >The problem was reproduced on a SunFire V440 with 4 CPUs. We were unable to > >reproduce the problem on server with 1 CPU, so it might be a threading/sync > >issue. > > > That's definitely a possibility. We've seen threading issues on Solaris 8 that were fixed by switching to use the new threads library (which is the default library on Solaris 9) but I'm not aware of any issues with the Solaris 9 threads library. Perhaps you found one. > > >Additionally we are seeing the problem only with the instance using the > >Perl backend, not with BDB. We use a modified back-perl which instantiates > >a new Perl object with each connection but I cannot see any evidence that the > >termination is due to our backend-modifications. > > > > > If your usage pattern for back-bdb and back-perl are the same, but the problem does not occur with back-bdb, that certainly points at your back-perl code. Not necessarily. The BDB backend does not open new connections, our Perl code opens two outgoing connections for each incoming connection, so the io system is stressed more than using only bdb. > The truss output you sent begins too late, after the slapd shutdown sequence has already begun. It might help to see a little more of that so we can see what happens leading up to the first failed select call. I uploaded the last 500k lines of truss output to http://www.familie-michelsen.de/its3567/ldap-remapper-500000.trusslog.bz2 If you need anything else just write. Best regards -- Dagobert Michelsen -- Dagobert Michelsen (Leiter IT) Baltic Online Computer GmbH Alter Markt 1-2, 24103 Kiel, +49 431 54003-0 (Fon) -99 (Fax) Flughafenstr. 52c, 22335 Hamburg, +49 40 53299-395 (Fon) -100 (Fax) Big Servers, Fat Pipes, Massive Storage, Objects Everywhere
Dagobert Michelsen wrote: >Hello, > >Von Howard Chu <hyc@symas.com> (Fri, 04 Mar 2005 09:55:33 -0800): > > >>The truss output you sent begins too late, after the slapd shutdown sequence has already begun. It might help to see a little more of that so we can see what happens leading up to the first failed select call. >> >> > >I uploaded the last 500k lines of truss output to > http://www.familie-michelsen.de/its3567/ldap-remapper-500000.trusslog.bz2 >If you need anything else just write. > > > Your log shows that poll() fails with ENOSYS, which is not a documented failure code for this system call. It looks like Solaris itself has failed here, and you should probably contact Sun for a solution. -- -- Howard Chu Chief Architect, Symas Corp. Director, Highland Sun http://www.symas.com http://highlandsun.com/hyc Symas: Premier OpenSource Development and Support
Hi, Von Howard Chu <hyc@symas.com> (Mon, 07 Mar 2005 02:25:10 -0800): > Dagobert Michelsen wrote: > >I uploaded the last 500k lines of truss output to > > http://www.familie-michelsen.de/its3567/ldap-remapper-500000.trusslog.bz2 > >If you need anything else just write. > > > Your log shows that poll() fails with ENOSYS, which is not a documented failure code for this system call. It looks like Solaris itself has failed here, and you should probably contact Sun for a solution. I just opened a call at Sun about the issue. I will keep you informed about the progress. Best regards -- Dagobert -- Dagobert Michelsen (Leiter IT) Baltic Online Computer GmbH Alter Markt 1-2, 24103 Kiel, +49 431 54003-0 (Fon) -99 (Fax) Flughafenstr. 52c, 22335 Hamburg, +49 40 53299-395 (Fon) -100 (Fax) Big Servers, Fat Pipes, Massive Storage, Objects Everywhere
Howard, Dagobert, > Your log shows that poll() fails with ENOSYS, which is not a documented > failure code for this system call. It looks like Solaris itself has > failed here, and you should probably contact Sun for a solution. Maybe this is a Sun bug but as we went through here at Sendamil and reported in ITS 3400, the ENOSYS could mean "I don't like a return value I got from poll()" where poll() is use to implement select on Solaris. Dagobert - I suggest you repro the problem and get three pieces of doc: 1) truss with options: truss -d -l -f -vpoll -u:: -ua.out:: -o <output_file_name> -p <pid> This will show the select call getting mapped to poll() like the following. In ITS 3400, we saw that the pollset as built from the select() call had a bit set for an FD that Solaris thinks is closed. (My suspicsion is slapd lost track of FDs somehow and left one set for an FD that it had closed.) E.g., 14073/2@2: 22.1298 -> libc:select_large_fdset(0x10, 0xfe3ffb74, 0xfe3ff774, 0x0) 14073/2@2: 22.1303 -> libc_psr:memset(0xfe3fd188, 0x0, 0x2000,0x0) 14073/2@2: 22.1309 <- libc_psr:memset() = 0xfe3fd188 14073/2@2: 22.1314 -> libc_psr:memset(0xfe3fcf80, 0x0, 0x200, 0xfffffff8) 14073/2@2: 22.1319 <- libc_psr:memset() = 0xfe3fcf80 14073/2@2: 22.1325 -> libc:_poll(0xfe3fcf80, 0x7, 0xffffffff, 0xfffffff8) 14073/2: 22.1330 poll(0xFE3FCF80, 7, -1) = 1 14073/2: fd=5 ev=POLLRDNORM rev=0 14073/2: fd=7 ev=POLLRDNORM rev=0 14073/2: fd=8 ev=POLLRDNORM rev=0 14073/2: fd=9 ev=POLLRDNORM rev=0 14073/2: fd=10 ev=POLLRDNORM rev=0 14073/2: fd=11 ev=POLLRDNORM rev=0 14073/2: fd=15 ev=POLLRDNORM rev=POLLRDNORM 14073/2@2: 22.1337 <- libc:_poll() = 1 14073/2@2: 22.1341 <- libc:select_large_fdset() = 1 Stop this truss as soon as it looks like it's spinning so there's not too much data. 2) To see that possibility, run slapd (same time as you got the truss) with the debug level 8, which should trace slapd connection activity ala (this exampel is from OpenLDAP 2.1 but it should be roughly the same): Mar 7 14:12:18 qa-karn slapd[14073]: [ID 100111 local4.debug] slapd starting Mar 7 14:12:18 qa-karn slapd[14073]: [ID 732783 local4.debug] daemon: added 7r Mar 7 14:12:18 qa-karn slapd[14073]: [ID 732783 local4.debug] daemon: added 8r Mar 7 14:12:18 qa-karn slapd[14073]: [ID 732783 local4.debug] daemon: added 9r Mar 7 14:12:18 qa-karn slapd[14073]: [ID 732783 local4.debug] daemon: added 10r Mar 7 14:12:18 qa-karn slapd[14073]: [ID 732783 local4.debug] daemon: added 11r Mar 7 14:12:18 qa-karn slapd[14073]: [ID 538834 local4.debug] daemon: select: listen=7 active_threads=0 tvp=NULL Mar 7 14:12:18 qa-karn slapd[14073]: [ID 538834 local4.debug] daemon: select: listen=8 active_threads=0 tvp=NULL Mar 7 14:12:18 qa-karn slapd[14073]: [ID 538834 local4.debug] daemon: select: listen=9 active_threads=0 tvp=NULL Mar 7 14:12:18 qa-karn slapd[14073]: [ID 538834 local4.debug] daemon: select: listen=10 active_threads=0 tvp=NULL Mar 7 14:12:18 qa-karn slapd[14073]: [ID 538834 local4.debug] daemon: select: listen=11 active_threads=0 tvp=NULL Mar 7 14:13:18 qa-karn slapd[14073]: [ID 454241 local4.debug] daemon: activity on 1 descriptors Mar 7 14:13:19 qa-karn slapd[14073]: [ID 923062 local4.debug] daemon: new connection on 15 Mar 7 14:13:21 qa-karn slapd[14073]: [ID 732783 local4.debug] daemon: added 15r Mar 7 14:13:22 qa-karn slapd[14073]: [ID 802679 local4.debug] daemon: activity on: Mar 7 14:13:23 qa-karn slapd[14073]: [ID 100000 local4.debug] Mar 7 14:13:23 qa-karn slapd[14073]: [ID 538834 local4.debug] daemon: select: listen=7 active_threads=0 tvp=NULL Mar 7 14:13:24 qa-karn slapd[14073]: [ID 538834 local4.debug] daemon: select: listen=8 active_threads=0 tvp=NULL Mar 7 14:13:25 qa-karn slapd[14073]: [ID 538834 local4.debug] daemon: select: listen=9 active_threads=0 tvp=NULL Mar 7 14:13:26 qa-karn slapd[14073]: [ID 538834 local4.debug] daemon: select: listen=10 active_threads=0 tvp=NULL Mar 7 14:13:26 qa-karn slapd[14073]: [ID 538834 local4.debug] daemon: select: listen=11 active_threads=0 tvp=NULL Mar 7 14:13:27 qa-karn slapd[14073]: [ID 454241 local4.debug] daemon: activity on 1 descriptors Mar 7 14:13:28 qa-karn slapd[14073]: [ID 802679 local4.debug] daemon: activity on: 15r 3) When it spins, take a core dump of slapd with the gcore command. If you can reproduce this easily, this doc may help see if it's the same sort of "descriptor is set when it's not supposed to be" issue that I saw and reported in ITS 3400. I'll help Howard look at the doc if you can collect it (and if he wants/needs my help). Chris
The select and poll manpages document EBADF as the errno value for invalid descriptors. This return of ENOSYS is something different. There will be no spin in slapd because that loop only happens for EBADF. As soon as this ENOSYS error occurs a single time, slapd will shut itself down because the process is definitely in an unstable state. cmarkle@sendmail.com wrote: >Howard, Dagobert, > >>Your log shows that poll() fails with ENOSYS, which is not a documented >>failure code for this system call. It looks like Solaris itself has >>failed here, and you should probably contact Sun for a solution. >> >> >Maybe this is a Sun bug but as we went through here at Sendamil and >reported in ITS 3400, the ENOSYS could mean "I don't like a return value >I got from poll()" where poll() is use to implement select on Solaris. >Dagobert - I suggest you repro the problem and get three pieces of doc: > > -- -- Howard Chu Chief Architect, Symas Corp. Director, Highland Sun http://www.symas.com http://highlandsun.com/hyc Symas: Premier OpenSource Development and Support
Hello, Von Chris Markle <cmarkle@sendmail.com> (Mon, 07 Mar 2005 22:10:44 -0800): > Howard, Dagobert, > >Your log shows that poll() fails with ENOSYS, which is not a documented > >failure code for this system call. It looks like Solaris itself has > >failed here, and you should probably contact Sun for a solution. > > Maybe this is a Sun bug but as we went through here at Sendamil and reported in ITS 3400, the ENOSYS could mean "I don't like a return value I got from poll()" where poll() is use to implement select on Solaris. Dagobert - I suggest you repro the problem and get three pieces of doc: > > 1) truss with options: > > truss -d -l -f -vpoll -u:: -ua.out:: -o <output_file_name> -p <pid> > > This will show the select call getting mapped to poll() like the following. In ITS 3400, we saw that the pollset as built from the select() call had a bit set for an FD that Solaris thinks is closed. (My suspicsion is slapd lost track of FDs somehow and left one set for an FD that it had closed.) I used truss -d -l -f -vpoll -u\!back_perl-2.2 -ua.out:: -o ldap-remapper-2005-03-08.truss -p 5988 because the backend messages cluttered up the log. The output can be found at http://www.familie-michelsen.de/its3567/ldap-remapper-2005-03-08.truss.bz2 [3.3M] > 2) To see that possibility, run slapd (same time as you got the truss) with the debug level 8, which should trace slapd connection activity ala (this exampel is from OpenLDAP 2.1 but it should be roughly the same): The result can be found at http://www.familie-michelsen.de/its3567/ldap-remapper-2005-03-08.debug8.bz2 > 3) When it spins, take a core dump of slapd with the gcore command. I don't think that it will spin as I used 2.2.23 where slapd terminates after this kind of failure. > I'll help Howard look at the doc if you can collect it (and if he wants/needs my help). I really appreciate your commitment. Best regards -- Dagobert -- Dagobert Michelsen (Leiter IT) Baltic Online Computer GmbH Alter Markt 1-2, 24103 Kiel, +49 431 54003-0 (Fon) -99 (Fax) Flughafenstr. 52c, 22335 Hamburg, +49 40 53299-395 (Fon) -100 (Fax) Big Servers, Fat Pipes, Massive Storage, Objects Everywhere
Howard, > The select and poll manpages document EBADF as the errno value for > invalid descriptors. This return of ENOSYS is something different. There > will be no spin in slapd because that loop only happens for EBADF. As > soon as this ENOSYS error occurs a single time, slapd will shut itself > down because the process is definitely in an unstable state. You're right... I was thinking about old pre-ITS 3400 slapd behavior. So forget the core dump, but I think it would be interested for Dagobert to get a richer truss with corresponding OpenLDAP connection debug logging... Chris
Dagobert, >>truss -d -l -f -vpoll -u:: -ua.out:: -o <output_file_name> -p <pid> >>This will show the select call getting mapped to poll()... > > I used > truss -d -l -f -vpoll -u\!back_perl-2.2 -ua.out:: > -o ldap-remapper-2005-03-08.truss -p 5988 > because the backend messages cluttered up the log. If OpenLDAP 2.2 still uses select on Solaris then we'll want to see how select gets mapped to poll() and hence will need the -u:: parm to truss. You'll want to see calls to select_large_fdsets or something like that. Maybe you can take out -ua.out:: if you're getting too much output. Chris
Dagobert Michelsen wrote: >Hello, > > >>This will show the select call getting mapped to poll() like the following. In ITS 3400, we saw that the pollset as built from the select() call had a bit set for an FD that Solaris thinks is closed. (My suspicsion is slapd lost track of FDs somehow and left one set for an FD that it had closed.) >> >> Looks like Chris was close. > >I used > truss -d -l -f -vpoll -u\!back_perl-2.2 -ua.out:: -o ldap-remapper-2005-03-08.truss -p 5988 >because the backend messages cluttered up the log. The output can be found at > http://www.familie-michelsen.de/its3567/ldap-remapper-2005-03-08.truss.bz2 [3.3M] > > Here is an excerpt from the truss showing the failure: 5988/2: 203.2408 poll(0x7EFFEED8, 7, -1) Err#89 ENOSYS 5988/2: fd=5 ev=POLLRDNORM rev=0 5988/2: fd=7 ev=POLLRDNORM rev=0 5988/2: fd=8 ev=POLLRDNORM rev=0 5988/2: fd=14 ev=POLLRDNORM rev=0 5988/2: fd=16 ev=POLLRDNORM rev=POLLIN 5988/2: fd=19 ev=POLLRDNORM rev=0 5988/2: fd=22 ev=POLLRDNORM rev=0 5988/4: 203.2409 close(14) = 0 5988/2: 203.2411 write(2, " d a e m o n : s e l e".., 53) = 53 Here's what happened earlier on; the crucial part is to notice the thread IDs and watch what happened to descriptor #14: 5988/2: 202.9282 time() = 1110276036 5988/3@3: 202.9284 -> sl_calloc(0x1, 0x18, 0x6c0250, 0x95dac) 5988/2: 202.9285 write(2, " d a e m o n : s e l e".., 51) = 51 5988/3@3: 202.9286 -> sl_malloc(0x18, 0x6c0250, 0x0, 0x0) 5988/2: 202.9287 write(2, " d a e m o n : s e l e".., 51) = 51 5988/3@3: 202.9289 <- sl_malloc() = 0x6d584c 5988/2: 202.9290 poll(0x7EFFEED8, 7, -1) = 3 5988/2: fd=5 ev=POLLRDNORM rev=0 5988/2: fd=7 ev=POLLRDNORM rev=0 5988/2: fd=8 ev=POLLRDNORM rev=POLLRDNORM 5988/2: fd=16 ev=POLLRDNORM rev=0 5988/2: fd=19 ev=POLLRDNORM rev=POLLRDNORM 5988/2: fd=22 ev=POLLRDNORM rev=0 5988/2: fd=27 ev=POLLRDNORM rev=POLLRDNORM 5988/3@3: 202.9291 <- sl_calloc() = 0x6d584c 5988/2: 202.9293 write(2, " d a e m o n : a c t i".., 34) = 34 5988/3@3: 202.9295 -> slap_sl_free(0x6d584c, 0x6c0250, 0x96134, 0x0) 5988/5: 202.9247 close(14) = 0 5988/3@3: 202.9298 <- slap_sl_free() = 0x6d584c 5988/2: 202.9303 accept(8, 0x7EFFFD30, 0x7EFFF914, 1) = 14 5988/3@3: 202.9303 -> slap_sl_free(0x6d582c, 0x6c0250, 0x96134, 0x0) 5988/3@3: 202.9306 <- slap_sl_free() = 0x6d582c 5988/5: 202.9309 fcntl(28, F_DUP2FD, 0x0000000E) = 14 5988/2: 202.9310 setsockopt(14, SOL_SOCKET, SO_KEEPALIVE, 0x7EFFF0E8, 4, 1) = 0 5988/3@3: 202.9311 -> ad_inlist(0x809e88, 0x6d565c, 0xcec00, 0xce800) 5988/2: 202.9316 setsockopt(14, tcp, TCP_NODELAY, 0x7EFFF0E8, 4, 1) = 0 5988/2: 202.9318 write(2, " d a e m o n : n e w ".., 29) = 29 5988/2@2: 202.9320 -> connection_init(0xe, 0xf8628, 0xcbe28, 0x7efff0f0) 5988/5: 202.9310 close(28) = 0 5988/3@3: 202.9324 <- ad_inlist() = 1 5988/5: 202.9324 llseek(14, 0, SEEK_CUR) Err#29 ESPIPE 5988/3@3: 202.9327 -> access_allowed(0x82be78, 0xbcdd00, 0x809e88, 0xbce518) 5988/5: 202.9329 close(14) = 0 At time 202.9303 the slapd listener thread (#2) accepted an incoming connection, and that was assigned to fd 14. At time 202.9309 thread #5 explicitly dup'd descriptor 28 onto #14. Thread #5 is your perl code (which you can verify by noting the message logged at 202.9019). There are interleaved operations on descriptor 14 between thread 2 and 5 after that point. Ultimately fd 14 is closed by the perl code. As I suspected at the outset, the problem is in your back-perl code, not in slapd. slapd cannot be expected to defend itself from user code closing its file descriptors arbitrarily, and signalling the problem by terminating as it does is the safest thing it can do. This ITS will be closed. -- -- Howard Chu Chief Architect, Symas Corp. Director, Highland Sun http://www.symas.com http://highlandsun.com/hyc Symas: Premier OpenSource Development and Support
changed notes changed state Open to Feedback
Hello Howard, Am 08.03.2005 um 20:05 schrieb Howard Chu: > Dagobert Michelsen wrote: >> I used >> truss -d -l -f -vpoll -u\!back_perl-2.2 -ua.out:: -o >> ldap-remapper-2005-03-08.truss -p 5988 >> because the backend messages cluttered up the log. The output can be >> found at >> >> http://www.familie-michelsen.de/its3567/ldap-remapper-2005-03 >> -08.truss.bz2 [3.3M] >> > Here is an excerpt from the truss showing the failure: > 5988/2: 203.2408 poll(0x7EFFEED8, 7, -1) > Err#89 ENOSYS > 5988/2: fd=5 ev=POLLRDNORM rev=0 > 5988/2: fd=7 ev=POLLRDNORM rev=0 > 5988/2: fd=8 ev=POLLRDNORM rev=0 > 5988/2: fd=14 ev=POLLRDNORM rev=0 > 5988/2: fd=16 ev=POLLRDNORM rev=POLLIN > 5988/2: fd=19 ev=POLLRDNORM rev=0 > 5988/2: fd=22 ev=POLLRDNORM rev=0 > 5988/4: 203.2409 close(14) = 0 > 5988/2: 203.2411 write(2, " d a e m o n : s e l e".., 53) > = 53 > > Here's what happened earlier on; the crucial part is to notice the > thread IDs and watch what happened to descriptor #14: > 5988/2: 202.9282 time() = 1110276036 > 5988/3@3: 202.9284 -> sl_calloc(0x1, 0x18, 0x6c0250, 0x95dac) > 5988/2: 202.9285 write(2, " d a e m o n : s e l e".., 51) > = 51 > 5988/3@3: 202.9286 -> sl_malloc(0x18, 0x6c0250, 0x0, 0x0) > 5988/2: 202.9287 write(2, " d a e m o n : s e l e".., 51) > = 51 > 5988/3@3: 202.9289 <- sl_malloc() = 0x6d584c > 5988/2: 202.9290 poll(0x7EFFEED8, 7, -1) = 3 > 5988/2: fd=5 ev=POLLRDNORM rev=0 > 5988/2: fd=7 ev=POLLRDNORM rev=0 > 5988/2: fd=8 ev=POLLRDNORM rev=POLLRDNORM > 5988/2: fd=16 ev=POLLRDNORM rev=0 > 5988/2: fd=19 ev=POLLRDNORM rev=POLLRDNORM > 5988/2: fd=22 ev=POLLRDNORM rev=0 > 5988/2: fd=27 ev=POLLRDNORM rev=POLLRDNORM > 5988/3@3: 202.9291 <- sl_calloc() = 0x6d584c > 5988/2: 202.9293 write(2, " d a e m o n : a c t i".., 34) > = 34 > 5988/3@3: 202.9295 -> slap_sl_free(0x6d584c, 0x6c0250, > 0x96134, 0x0) > 5988/5: 202.9247 close(14) = 0 > 5988/3@3: 202.9298 <- slap_sl_free() = 0x6d584c > 5988/2: 202.9303 accept(8, 0x7EFFFD30, 0x7EFFF914, 1) > = 14 > 5988/3@3: 202.9303 -> slap_sl_free(0x6d582c, 0x6c0250, > 0x96134, 0x0) > 5988/3@3: 202.9306 <- slap_sl_free() = 0x6d582c > 5988/5: 202.9309 fcntl(28, F_DUP2FD, 0x0000000E) > = 14 > 5988/2: 202.9310 setsockopt(14, SOL_SOCKET, SO_KEEPALIVE, > 0x7EFFF0E8, 4, 1) = 0 > 5988/3@3: 202.9311 -> ad_inlist(0x809e88, 0x6d565c, 0xcec00, > 0xce800) > 5988/2: 202.9316 setsockopt(14, tcp, TCP_NODELAY, > 0x7EFFF0E8, 4, 1) = 0 > 5988/2: 202.9318 write(2, " d a e m o n : n e w ".., 29) > = 29 > 5988/2@2: 202.9320 -> connection_init(0xe, 0xf8628, 0xcbe28, > 0x7efff0f0) > 5988/5: 202.9310 close(28) = 0 > 5988/3@3: 202.9324 <- ad_inlist() = 1 > 5988/5: 202.9324 llseek(14, 0, SEEK_CUR) > Err#29 ESPIPE > 5988/3@3: 202.9327 -> access_allowed(0x82be78, 0xbcdd00, > 0x809e88, 0xbce518) > 5988/5: 202.9329 close(14) = 0 > > At time 202.9303 the slapd listener thread (#2) accepted an incoming > connection, and that was assigned to fd 14. At time 202.9309 thread #5 > explicitly dup'd descriptor 28 onto #14. Thread #5 is your perl code > (which you can verify by noting the message logged at 202.9019). There > are interleaved operations on descriptor 14 between thread 2 and 5 > after that point. Ultimately fd 14 is closed by the perl code. > > As I suspected at the outset, the problem is in your back-perl code, > not in slapd. slapd cannot be expected to defend itself from user code > closing its file descriptors arbitrarily, and signalling the problem > by terminating as it does is the safest thing it can do. This ITS will > be closed. First thanks for the in-depth analysis. However, for me it looks like fd #14 is opened straight before the select you mentioned and closed without errors right after the poll: 5988/4: 203.2398 putmsg(4, 0x7DFFEFB0, 0x7DFFEFA4, 0) = 0 5988/3@3: 203.2400 <- access_allowed() = 1 5988/4: 203.2401 open("/var/run/syslog_door", O_RDONLY) = 14 <--- 5988/2: 203.2346 time() = 1110276036 5988/4: 203.2404 door_info(14, 0x7DFFEEE8) = 0 5988/2: 203.2406 write(2, " d a e m o n : s e l e".., 51) = 51 5988/4: 203.2406 getpid() = 5988 [5979] 5988/2: 203.2407 write(2, " d a e m o n : s e l e".., 51) = 51 5988/4: 203.2408 door_call(14, 0x7DFFEED0) = 0 5988/2: 203.2408 poll(0x7EFFEED8, 7, -1) Err#89 ENOSYS 5988/2: fd=5 ev=POLLRDNORM rev=0 5988/2: fd=7 ev=POLLRDNORM rev=0 5988/2: fd=8 ev=POLLRDNORM rev=0 5988/2: fd=14 ev=POLLRDNORM rev=0 5988/2: fd=16 ev=POLLRDNORM rev=POLLIN 5988/2: fd=19 ev=POLLRDNORM rev=0 5988/2: fd=22 ev=POLLRDNORM rev=0 5988/4: 203.2409 close(14) = 0 5988/2: 203.2411 write(2, " d a e m o n : s e l e".., 53) = 53 However there is one more thing I don't understand: if my Perl code runs in thread #5 and the fd is duped onto fd #14 in this thread, why should openldap bother about issueing select on it? Additionally, the perl code never closes a fd explicitly, only perl filehandles and Net::LDAP are used. Best regards -- Dagobert
Dagobert Michelsen wrote: > > First thanks for the in-depth analysis. However, for me it looks like > fd #14 is opened straight before the select you mentioned and closed > without errors right after the poll: > > > > However there is one more thing I don't understand: if my Perl code > runs in thread #5 and the fd is duped onto fd #14 in this thread, why > should openldap bother about issueing select on it? Additionally, the > perl code never closes a fd explicitly, only perl filehandles and > Net::LDAP are used. > You are completely missing the point. The point is that the slapd listener issued an accept() call which returned fd#14, so slapd expects fd#14 to be an incoming LDAP session socket. Your code causes fd#14 to be closed and replaced with some other thing, which in particular probably does not support being select'd or poll'd. slapd performs the select because the listener thread has no knowledge that your code has closed the LDAP socket and replaced it with something else, it still thinks there is an incoming LDAP session on that descriptor. Regardless of the fact that fd#14 is open at the time of the next select()/poll() it is no longer a socket descriptor, and so the call fails with ENOSYS. If your code doesn't explicitly close fd's then the underlying perl runtime and/or Net::LDAP modules are broken. The nature of the error is outside the scope of this OpenLDAP Issue Tracking System, but I'll make one further observation - it is poor programming practice to close an fd and then explicitly dup another fd onto it. Since the dup operation always atomically closes any previous file on the target descriptor, it is best to just perform the dup without calling close. Any decent Unix programmer knows this, as doing it with an explicit close in advance introduces a race condition, as your truss so clearly demonstrates. Whatever code is issuing the dup request is broken. -- -- Howard Chu Chief Architect, Symas Corp. Director, Highland Sun http://www.symas.com http://highlandsun.com/hyc Symas: Premier OpenSource Development and Support
changed state Feedback to Closed
Hello, Von Howard Chu <hyc@symas.com> (Mon, 07 Mar 2005 02:25:10 -0800): > Your log shows that poll() fails with ENOSYS, which is not a documented failure code for this system call. It looks like Solaris itself has failed here, and you should probably contact Sun for a solution. I opened a case at Sun under the Case-ID 37336457 and finally got an answer: If select is applied to a door (a special file in the filesystem allowing an immediate context switch to lower latency, in this case /var/run/syslog_door) a generic function is called in the doorfs processing the call where ENOSYS is returned, because poll is not supported on this filesystem type. Finally this is returned as errno from select. The mechanism is documented in select(3c): The select() function supports regular files, terminal and pseudo-terminal devices, STREAMS-based files, FIFOs and pipes. The behavior of select() on file descriptors that refer to other types of file is unspecified. In this case "other file types" is a door and unspecified is ENOSYS. Hope this helps the next time this returncode is encountered. Best regards -- Dagobert Michelsen -- Dagobert Michelsen (Leiter IT) Baltic Online Computer GmbH Alter Markt 1-2, 24103 Kiel, +49 431 54003-0 (Fon) -99 (Fax) Flughafenstr. 52c, 22335 Hamburg, +49 40 53299-395 (Fon) -100 (Fax)
Hi, the race condition in the Perl interpreter is further tracked at https://rt.perl.org/rt3/Ticket/Display.html?id=34914 Best regards -- Dagobert Michelsen -- Dagobert Michelsen (Leiter IT) Baltic Online Computer GmbH Alter Markt 1-2, 24103 Kiel, +49 431 54003-0 (Fon) -99 (Fax) Flughafenstr. 52c, 22335 Hamburg, +49 40 53299-395 (Fon) -100 (Fax)
moved from Incoming to Archive.Incoming
not an OpenLDAP bug