openldap-bugs February 2015

openldap-bugs@openldap.org

28 participants
71 discussions

(ITS#8055) High CPU usage with syncreply and wrong port
by adam＠cassar.id.au 09 Feb '15

09 Feb '15

Full_Name: Adam Version: 2.4.40 OS: Linux URL: ftp://ftp.openldap.org/incoming/ Submission from: (NULL) (115.70.231.55) Specifying a syncrepl provider with an unreachable port results in high CPU usage with slapd with slapd never terminating. Example configuration: syncrepl rid=1 provider=ldap://10.1.1.10:9292 type=refreshAndPersist interval=00:00:01:00 retry="60 +" searchbase="dc=howard,dc=chew" scope=sub schemachecking=on bindmethod=simple binddn="cn=admin,dc=howard,dc=chew" credentials=iwritecode

1 0

Re: (ITS#8054) Operation duration logging
by michael＠stroeder.com 09 Feb '15

09 Feb '15

hyc(a)symas.com wrote: > michael(a)stroeder.com wrote: >> ebackes(a)symas.com wrote: >>> Here is a patch to add duration logging for operations that appears in the >>> standard result messages of statslog. It's a reasonably small change with >>> negligible performance implications except under pathological benchmarking >>> conditions. It does change the quasi-machine-parsable statslog format, however, >>> so it might not be appropriate for general 2.4 release. Example line: >>> >>> 54d8298c conn=1000 op=1 SEARCH RESULT tag=101 err=0 duration=0.170ms nentries=1 >>> text= >> >> This is a very important feature. Highly appreciated! >> >> I'd love to see this in RE24. Yes, I know. No more features. :-( >> >> Would it be possible and make sense to have this configurable per database? > > No it would not make sense. There are ops like Abandon and Unbind which > have no associated database. Aren't Abandon and Unbind associated by authz-DN? Or how is this solved in slapo-accesslog? Ciao, Michael.

1 0

Re: (ITS#8054) Operation duration logging
by hyc＠symas.com 09 Feb '15

09 Feb '15

michael(a)stroeder.com wrote: > ebackes(a)symas.com wrote: >> Here is a patch to add duration logging for operations that appears in the >> standard result messages of statslog. It's a reasonably small change with >> negligible performance implications except under pathological benchmarking >> conditions. It does change the quasi-machine-parsable statslog format, however, >> so it might not be appropriate for general 2.4 release. Example line: >> >> 54d8298c conn=1000 op=1 SEARCH RESULT tag=101 err=0 duration=0.170ms nentries=1 >> text= > > This is a very important feature. Highly appreciated! > > I'd love to see this in RE24. Yes, I know. No more features. :-( > > Would it be possible and make sense to have this configurable per database? No it would not make sense. There are ops like Abandon and Unbind which have no associated database. Adding variation here is creating gratuitous complexity for no benefit. -- -- Howard Chu CTO, Symas Corp. http://www.symas.com Director, Highland Sun http://highlandsun.com/hyc/ Chief Architect, OpenLDAP http://www.openldap.org/project/

1 0

Re: (ITS#8054) Operation duration logging
by michael＠stroeder.com 09 Feb '15

09 Feb '15

ebackes(a)symas.com wrote: > Here is a patch to add duration logging for operations that appears in the > standard result messages of statslog. It's a reasonably small change with > negligible performance implications except under pathological benchmarking > conditions. It does change the quasi-machine-parsable statslog format, however, > so it might not be appropriate for general 2.4 release. Example line: > > 54d8298c conn=1000 op=1 SEARCH RESULT tag=101 err=0 duration=0.170ms nentries=1 > text= This is a very important feature. Highly appreciated! I'd love to see this in RE24. Yes, I know. No more features. :-( Would it be possible and make sense to have this configurable per database? Ciao, Michael.

1 0

Re: (ITS#8054) Operation duration logging
by ebackes＠symas.com 08 Feb '15

08 Feb '15

This is a multi-part message in MIME format. --Multipart=_Sun__8_Feb_2015_19_56_17_-0800_yxgp4/9WqjBC20PY Content-Type: text/plain; charset=US-ASCII Content-Transfer-Encoding: 7bit Here are the patches. -- Emily Backes Symas Corporation ebackes(a)symas.com --Multipart=_Sun__8_Feb_2015_19_56_17_-0800_yxgp4/9WqjBC20PY Content-Type: text/x-diff; name="master-operation-duration-logging.patch" Content-Disposition: attachment; filename="master-operation-duration-logging.patch" Content-Transfer-Encoding: 7bit >From 7582a21a4bc06271519e37cef11dcfb4348a34a2 Mon Sep 17 00:00:00 2001 From: Emily Backes <ebackes(a)symas.com> Date: Thu, 5 Feb 2015 18:52:19 -0800 Subject: [PATCH] operation duration logging --- include/ldap_log.h | 6 +++ servers/slapd/operation.c | 3 ++ servers/slapd/result.c | 98 +++++++++++++++++++++++++++++++++++++++++++++++ servers/slapd/slap.h | 19 +++++++++ 4 files changed, 126 insertions(+) diff --git a/include/ldap_log.h b/include/ldap_log.h index 9036060..289db00 100644 --- a/include/ldap_log.h +++ b/include/ldap_log.h @@ -192,6 +192,12 @@ extern void eb_syslog(int pri, const char *fmt, ...); #define Log5(level, severity, fmt, a1, a2, a3, a4, a5) \ LogExpand((level), (severity), (fmt) LogArg(a1) LogArg(a2) LogArg(a3) \ LogArg(a4) LogArg(a5)) +#define Log6(level, severity, fmt, a1, a2, a3, a4, a5, a6) \ + LogExpand((level), (severity), (fmt) LogArg(a1) LogArg(a2) LogArg(a3) \ + LogArg(a4) LogArg(a5) LogArg(a6)) +#define Log7(level, severity, fmt, a1, a2, a3, a4, a5, a6, a7) \ + LogExpand((level), (severity), (fmt) LogArg(a1) LogArg(a2) LogArg(a3) \ + LogArg(a4) LogArg(a5) LogArg(a6) LogArg(a7)) #define Debug(level, fmt, a1, a2, a3) \ LogExpand((level), ldap_syslog_level, (fmt) \ LogArg(a1) LogArg(a2) LogArg(a3)) diff --git a/servers/slapd/operation.c b/servers/slapd/operation.c index d16413f..1450718 100644 --- a/servers/slapd/operation.c +++ b/servers/slapd/operation.c @@ -204,6 +204,9 @@ slap_op_alloc( op->o_tag = tag; slap_op_time( &op->o_time, &op->o_tincr ); +#ifdef HAVE_GETTIMEOFDAY + (void) gettimeofday( &op->o_hr_time, NULL ); +#endif /* HAVE_GETTIMEOFDAY */ op->o_opid = id; #if defined( LDAP_SLAPI ) diff --git a/servers/slapd/result.c b/servers/slapd/result.c index 14bd6b7..20fc745 100644 --- a/servers/slapd/result.c +++ b/servers/slapd/result.c @@ -36,6 +36,19 @@ #include <ac/unistd.h> #include "slap.h" +#include "ldap_log.h" + +/* BSD seems to guarantee that this will be a macro, so... */ +#ifndef timersub +# define timersub(a,b,res) do { \ + (res)->tv_sec = (a)->tv_sec - (b)->tv_sec; \ + (res)->tv_usec = (a)->tv_usec - (b)->tv_usec; \ + if ((res)->tv_usec < 0) { \ + --(res)->tv_sec; \ + (res)->tv_usec += 1000000; \ + } \ + } while (0) +#endif const struct berval slap_dummy_bv = BER_BVNULL; @@ -819,10 +832,27 @@ send_ldap_disconnect( Operation *op, SlapReply *rs ) } if ( send_ldap_response( op, rs ) == SLAP_CB_CONTINUE ) { +#ifdef HAVE_GETTIMEOFDAY + struct timeval now; + struct timeval duration; + time_t msec; + + (void) gettimeofday( &now, NULL ); + timersub( &now, &op->o_hr_time, &duration ); + msec = duration.tv_usec / 1000 + duration.tv_sec * 1000; + + Statslog6( LDAP_DEBUG_STATS, + "%s DISCONNECT tag=%lu err=%d duration=%d.%03dms text=%s\n", + op->o_log_prefix, rs->sr_tag, rs->sr_err, + msec, + duration.tv_usec % 1000, + rs->sr_text ? rs->sr_text : "" ); +#else /* ! HAVE_GETTIMEOFDAY */ Statslog( LDAP_DEBUG_STATS, "%s DISCONNECT tag=%lu err=%d text=%s\n", op->o_log_prefix, rs->sr_tag, rs->sr_err, rs->sr_text ? rs->sr_text : "", 0 ); +#endif /* ! HAVE_GETTIMEOFDAY */ } } @@ -884,6 +914,37 @@ abandon: } if ( send_ldap_response( op, rs ) == SLAP_CB_CONTINUE ) { + +#ifdef HAVE_GETTIMEOFDAY + struct timeval now; + struct timeval duration; + time_t msec; + + (void) gettimeofday( &now, NULL ); + timersub( &now, &op->o_hr_time, &duration ); + msec = duration.tv_usec / 1000 + duration.tv_sec * 1000; + + if ( op->o_tag == LDAP_REQ_SEARCH ) { + Statslog7( LDAP_DEBUG_STATS, + "%s SEARCH RESULT tag=%lu err=%d duration=%d.%03dms nentries=%d text=%s\n", + op->o_log_prefix, + rs->sr_tag, + rs->sr_err, + msec, + duration.tv_usec % 1000, + rs->sr_nentries, + rs->sr_text ? rs->sr_text : ""); + } else { + Statslog6( LDAP_DEBUG_STATS, + "%s RESULT tag=%lu err=%d duration=%d.%03dms text=%s\n", + op->o_log_prefix, + rs->sr_tag, + rs->sr_err, + msec, + duration.tv_usec % 1000, + rs->sr_text ? rs->sr_text : ""); + } +#else /* ! HAVE_GETTIMEOFDAY */ if ( op->o_tag == LDAP_REQ_SEARCH ) { Statslog( LDAP_DEBUG_STATS, "%s SEARCH RESULT tag=%lu err=%d nentries=%d text=%s\n", @@ -895,6 +956,7 @@ abandon: op->o_log_prefix, rs->sr_tag, rs->sr_err, rs->sr_text ? rs->sr_text : "", 0 ); } +#endif /* ! HAVE_GETTIMEOFDAY */ } if( tmp != NULL ) ch_free(tmp); @@ -917,10 +979,27 @@ send_ldap_sasl( Operation *op, SlapReply *rs ) rs->sr_msgid = (rs->sr_tag != LBER_SEQUENCE) ? op->o_msgid : 0; if ( send_ldap_response( op, rs ) == SLAP_CB_CONTINUE ) { +#ifdef HAVE_GETTIMEOFDAY + struct timeval now; + struct timeval duration; + time_t msec; + + (void) gettimeofday( &now, NULL ); + timersub( &now, &op->o_hr_time, &duration ); + msec = duration.tv_usec / 1000 + duration.tv_sec * 1000; + + Statslog6( LDAP_DEBUG_STATS, + "%s RESULT tag=%lu err=%d duration=%d.%03dms text=%s\n", + op->o_log_prefix, rs->sr_tag, rs->sr_err, + msec, + duration.tv_usec % 1000, + rs->sr_text ? rs->sr_text : "" ); +#else /* ! HAVE_GETTIMEOFDAY */ Statslog( LDAP_DEBUG_STATS, "%s RESULT tag=%lu err=%d text=%s\n", op->o_log_prefix, rs->sr_tag, rs->sr_err, rs->sr_text ? rs->sr_text : "", 0 ); +#endif /* ! HAVE_GETTIMEOFDAY */ } } @@ -941,10 +1020,29 @@ slap_send_ldap_extended( Operation *op, SlapReply *rs ) rs->sr_msgid = (rs->sr_tag != LBER_SEQUENCE) ? op->o_msgid : 0; if ( send_ldap_response( op, rs ) == SLAP_CB_CONTINUE ) { +#ifdef HAVE_GETTIMEOFDAY + struct timeval now; + struct timeval duration; + time_t msec; + + (void) gettimeofday( &now, NULL ); + timersub( &now, &op->o_hr_time, &duration ); + msec = duration.tv_usec / 1000 + duration.tv_sec * 1000; + + Statslog6( LDAP_DEBUG_STATS, + "%s RESULT oid=%s err=%d duration=%d.%03dms text=%s\n", + op->o_log_prefix, + rs->sr_rspoid ? rs->sr_rspoid : "", + rs->sr_err, + msec, + duration.tv_usec % 1000, + rs->sr_text ? rs->sr_text : "" ); +#else /* ! HAVE_GETTIMEOFDAY */ Statslog( LDAP_DEBUG_STATS, "%s RESULT oid=%s err=%d text=%s\n", op->o_log_prefix, rs->sr_rspoid ? rs->sr_rspoid : "", rs->sr_err, rs->sr_text ? rs->sr_text : "", 0 ); +#endif /* ! HAVE_GETTIMEOFDAY */ } } diff --git a/servers/slapd/slap.h b/servers/slapd/slap.h index f89da27..17d09d9 100644 --- a/servers/slapd/slap.h +++ b/servers/slapd/slap.h @@ -2618,6 +2618,9 @@ struct Operation { #define o_log_prefix o_hdr->oh_log_prefix ber_tag_t o_tag; /* tag of the request */ +#ifdef HAVE_GETTIMEOFDAY + struct timeval o_hr_time; /* high-resolution time of op start*/ +#endif /* HAVE_GETTIMEOFDAY */ time_t o_time; /* time op was initiated */ int o_tincr; /* counter for multiple ops with same o_time */ @@ -2990,6 +2993,10 @@ struct Connection { #define Statslog( level, fmt, connid, opid, arg1, arg2, arg3 ) \ Log5( (level), ldap_syslog_level, (fmt), (connid), (opid), (arg1), (arg2), (arg3) ) +#define Statslog6( level, fmt, a1, a2, a3, a4, a5, a6 ) \ + Log6( (level), ldap_syslog_level, (fmt), (a1), (a2), (a3), (a4), (a5), (a6) ) +#define Statslog7( level, fmt, a1, a2, a3, a4, a5, a6, a7 ) \ + Log7( (level), ldap_syslog_level, (fmt), (a1), (a2), (a3), (a4), (a5), (a6), (a7) ) #define StatslogTest( level ) ((ldap_debug | ldap_syslog) & (level)) #else /* !LDAP_SYSLOG */ #define Statslog( level, fmt, connid, opid, arg1, arg2, arg3 ) \ @@ -2997,10 +3004,22 @@ struct Connection { if ( ldap_debug & (level) ) \ lutil_debug( ldap_debug, (level), (fmt), (connid), (opid), (arg1), (arg2), (arg3) );\ } while (0) +#define Statslog6( level, fmt, a1, a2, a3, a4, a5, a6 ) \ + do { \ + if ( ldap_debug & (level) ) \ + lutil_debug( ldap_debug, (level), (fmt), (a1), (a2), (a3), (a4), (a5), (a6) ); \ + } while (0) +#define Statslog7( level, fmt, a1, a2, a3, a4, a5, a6, a7 ) \ + do { \ + if ( ldap_debug & (level) ) \ + lutil_debug( ldap_debug, (level), (fmt), (a1), (a2), (a3), (a4), (a5), (a6), (a7) ); \ + } while (0) #define StatslogTest( level ) (ldap_debug & (level)) #endif /* !LDAP_SYSLOG */ #else /* !LDAP_DEBUG */ #define Statslog( level, fmt, connid, opid, arg1, arg2, arg3 ) ((void) 0) +#define Statslog6( level, fmt, a1, a2, a3, a4, a5, a6 ) ((void) 0) +#define Statslog7( level, fmt, a1, a2, a3, a4, a5, a6, a7 ) ((void) 0) #define StatslogTest( level ) (0) #endif /* !LDAP_DEBUG */ -- 2.1.4 --Multipart=_Sun__8_Feb_2015_19_56_17_-0800_yxgp4/9WqjBC20PY Content-Type: text/x-diff; name="RE24-operation-duration-logging.patch" Content-Disposition: attachment; filename="RE24-operation-duration-logging.patch" Content-Transfer-Encoding: 7bit >From bfabab23da6d0914f222a22f1cd0e28c48b4db90 Mon Sep 17 00:00:00 2001 From: Emily Backes <ebackes(a)symas.com> Date: Thu, 5 Feb 2015 18:52:19 -0800 Subject: [PATCH] operation duration logging --- include/ldap_log.h | 14 +++++++ servers/slapd/operation.c | 3 ++ servers/slapd/result.c | 98 +++++++++++++++++++++++++++++++++++++++++++++++ servers/slapd/slap.h | 19 +++++++++ 4 files changed, 134 insertions(+) diff --git a/include/ldap_log.h b/include/ldap_log.h index 94a73bd..50c7f4b 100644 --- a/include/ldap_log.h +++ b/include/ldap_log.h @@ -190,6 +190,20 @@ extern void eb_syslog(int pri, const char *fmt, ...); if ( ldap_syslog & (level) ) \ syslog( LDAP_LEVEL_MASK((severity)), (fmt), (arg1), (arg2), (arg3), (arg4), (arg5) ); \ } while ( 0 ) +#define Log6( level, severity, fmt, arg1, arg2, arg3, arg4, arg5, arg6 ) \ + do { \ + if ( ldap_debug & (level) ) \ + lutil_debug( ldap_debug, (level), (fmt), (arg1), (arg2), (arg3), (arg4), (arg5), (arg6) ); \ + if ( ldap_syslog & (level) ) \ + syslog( LDAP_LEVEL_MASK((severity)), (fmt), (arg1), (arg2), (arg3), (arg4), (arg5), (arg6) ); \ + } while ( 0 ) +#define Log7( level, severity, fmt, arg1, arg2, arg3, arg4, arg5, arg6, arg7 ) \ + do { \ + if ( ldap_debug & (level) ) \ + lutil_debug( ldap_debug, (level), (fmt), (arg1), (arg2), (arg3), (arg4), (arg5), (arg6), (arg7) ); \ + if ( ldap_syslog & (level) ) \ + syslog( LDAP_LEVEL_MASK((severity)), (fmt), (arg1), (arg2), (arg3), (arg4), (arg5), (arg6), (arg7) ); \ + } while ( 0 ) #define Debug( level, fmt, arg1, arg2, arg3 ) \ Log3( (level), ldap_syslog_level, (fmt), (arg1), (arg2), (arg3) ) #define LogTest(level) ( ( ldap_debug | ldap_syslog ) & (level) ) diff --git a/servers/slapd/operation.c b/servers/slapd/operation.c index cc09a22..1c712e0 100644 --- a/servers/slapd/operation.c +++ b/servers/slapd/operation.c @@ -204,6 +204,9 @@ slap_op_alloc( op->o_tag = tag; slap_op_time( &op->o_time, &op->o_tincr ); +#ifdef HAVE_GETTIMEOFDAY + (void) gettimeofday( &op->o_hr_time, NULL ); +#endif /* HAVE_GETTIMEOFDAY */ op->o_opid = id; #if defined( LDAP_SLAPI ) diff --git a/servers/slapd/result.c b/servers/slapd/result.c index 35cddc7..2bd910e 100644 --- a/servers/slapd/result.c +++ b/servers/slapd/result.c @@ -36,6 +36,19 @@ #include <ac/unistd.h> #include "slap.h" +#include "ldap_log.h" + +/* BSD seems to guarantee that this will be a macro, so... */ +#ifndef timersub +# define timersub(a,b,res) do { \ + (res)->tv_sec = (a)->tv_sec - (b)->tv_sec; \ + (res)->tv_usec = (a)->tv_usec - (b)->tv_usec; \ + if ((res)->tv_usec < 0) { \ + --(res)->tv_sec; \ + (res)->tv_usec += 1000000; \ + } \ + } while (0) +#endif const struct berval slap_dummy_bv = BER_BVNULL; @@ -794,10 +807,27 @@ send_ldap_disconnect( Operation *op, SlapReply *rs ) } if ( send_ldap_response( op, rs ) == SLAP_CB_CONTINUE ) { +#ifdef HAVE_GETTIMEOFDAY + struct timeval now; + struct timeval duration; + time_t msec; + + (void) gettimeofday( &now, NULL ); + timersub( &now, &op->o_hr_time, &duration ); + msec = duration.tv_usec / 1000 + duration.tv_sec * 1000; + + Statslog6( LDAP_DEBUG_STATS, + "%s DISCONNECT tag=%lu err=%d duration=%d.%03dms text=%s\n", + op->o_log_prefix, rs->sr_tag, rs->sr_err, + msec, + duration.tv_usec % 1000, + rs->sr_text ? rs->sr_text : "" ); +#else /* ! HAVE_GETTIMEOFDAY */ Statslog( LDAP_DEBUG_STATS, "%s DISCONNECT tag=%lu err=%d text=%s\n", op->o_log_prefix, rs->sr_tag, rs->sr_err, rs->sr_text ? rs->sr_text : "", 0 ); +#endif /* ! HAVE_GETTIMEOFDAY */ } } @@ -859,6 +889,37 @@ abandon: } if ( send_ldap_response( op, rs ) == SLAP_CB_CONTINUE ) { + +#ifdef HAVE_GETTIMEOFDAY + struct timeval now; + struct timeval duration; + time_t msec; + + (void) gettimeofday( &now, NULL ); + timersub( &now, &op->o_hr_time, &duration ); + msec = duration.tv_usec / 1000 + duration.tv_sec * 1000; + + if ( op->o_tag == LDAP_REQ_SEARCH ) { + Statslog7( LDAP_DEBUG_STATS, + "%s SEARCH RESULT tag=%lu err=%d duration=%d.%03dms nentries=%d text=%s\n", + op->o_log_prefix, + rs->sr_tag, + rs->sr_err, + msec, + duration.tv_usec % 1000, + rs->sr_nentries, + rs->sr_text ? rs->sr_text : ""); + } else { + Statslog6( LDAP_DEBUG_STATS, + "%s RESULT tag=%lu err=%d duration=%d.%03dms text=%s\n", + op->o_log_prefix, + rs->sr_tag, + rs->sr_err, + msec, + duration.tv_usec % 1000, + rs->sr_text ? rs->sr_text : ""); + } +#else /* ! HAVE_GETTIMEOFDAY */ if ( op->o_tag == LDAP_REQ_SEARCH ) { Statslog( LDAP_DEBUG_STATS, "%s SEARCH RESULT tag=%lu err=%d nentries=%d text=%s\n", @@ -870,6 +931,7 @@ abandon: op->o_log_prefix, rs->sr_tag, rs->sr_err, rs->sr_text ? rs->sr_text : "", 0 ); } +#endif /* ! HAVE_GETTIMEOFDAY */ } if( tmp != NULL ) ch_free(tmp); @@ -892,10 +954,27 @@ send_ldap_sasl( Operation *op, SlapReply *rs ) rs->sr_msgid = (rs->sr_tag != LBER_SEQUENCE) ? op->o_msgid : 0; if ( send_ldap_response( op, rs ) == SLAP_CB_CONTINUE ) { +#ifdef HAVE_GETTIMEOFDAY + struct timeval now; + struct timeval duration; + time_t msec; + + (void) gettimeofday( &now, NULL ); + timersub( &now, &op->o_hr_time, &duration ); + msec = duration.tv_usec / 1000 + duration.tv_sec * 1000; + + Statslog6( LDAP_DEBUG_STATS, + "%s RESULT tag=%lu err=%d duration=%d.%03dms text=%s\n", + op->o_log_prefix, rs->sr_tag, rs->sr_err, + msec, + duration.tv_usec % 1000, + rs->sr_text ? rs->sr_text : "" ); +#else /* ! HAVE_GETTIMEOFDAY */ Statslog( LDAP_DEBUG_STATS, "%s RESULT tag=%lu err=%d text=%s\n", op->o_log_prefix, rs->sr_tag, rs->sr_err, rs->sr_text ? rs->sr_text : "", 0 ); +#endif /* ! HAVE_GETTIMEOFDAY */ } } @@ -916,10 +995,29 @@ slap_send_ldap_extended( Operation *op, SlapReply *rs ) rs->sr_msgid = (rs->sr_tag != LBER_SEQUENCE) ? op->o_msgid : 0; if ( send_ldap_response( op, rs ) == SLAP_CB_CONTINUE ) { +#ifdef HAVE_GETTIMEOFDAY + struct timeval now; + struct timeval duration; + time_t msec; + + (void) gettimeofday( &now, NULL ); + timersub( &now, &op->o_hr_time, &duration ); + msec = duration.tv_usec / 1000 + duration.tv_sec * 1000; + + Statslog6( LDAP_DEBUG_STATS, + "%s RESULT oid=%s err=%d duration=%d.%03dms text=%s\n", + op->o_log_prefix, + rs->sr_rspoid ? rs->sr_rspoid : "", + rs->sr_err, + msec, + duration.tv_usec % 1000, + rs->sr_text ? rs->sr_text : "" ); +#else /* ! HAVE_GETTIMEOFDAY */ Statslog( LDAP_DEBUG_STATS, "%s RESULT oid=%s err=%d text=%s\n", op->o_log_prefix, rs->sr_rspoid ? rs->sr_rspoid : "", rs->sr_err, rs->sr_text ? rs->sr_text : "", 0 ); +#endif /* ! HAVE_GETTIMEOFDAY */ } } diff --git a/servers/slapd/slap.h b/servers/slapd/slap.h index 60db371..d22f1bf 100644 --- a/servers/slapd/slap.h +++ b/servers/slapd/slap.h @@ -2598,6 +2598,9 @@ struct Operation { #define o_log_prefix o_hdr->oh_log_prefix ber_tag_t o_tag; /* tag of the request */ +#ifdef HAVE_GETTIMEOFDAY + struct timeval o_hr_time; /* high-resolution time of op start*/ +#endif /* HAVE_GETTIMEOFDAY */ time_t o_time; /* time op was initiated */ int o_tincr; /* counter for multiple ops with same o_time */ @@ -2969,6 +2972,10 @@ struct Connection { #define Statslog( level, fmt, connid, opid, arg1, arg2, arg3 ) \ Log5( (level), ldap_syslog_level, (fmt), (connid), (opid), (arg1), (arg2), (arg3) ) +#define Statslog6( level, fmt, a1, a2, a3, a4, a5, a6 ) \ + Log6( (level), ldap_syslog_level, (fmt), (a1), (a2), (a3), (a4), (a5), (a6) ) +#define Statslog7( level, fmt, a1, a2, a3, a4, a5, a6, a7 ) \ + Log7( (level), ldap_syslog_level, (fmt), (a1), (a2), (a3), (a4), (a5), (a6), (a7) ) #define StatslogTest( level ) ((ldap_debug | ldap_syslog) & (level)) #else /* !LDAP_SYSLOG */ #define Statslog( level, fmt, connid, opid, arg1, arg2, arg3 ) \ @@ -2976,10 +2983,22 @@ struct Connection { if ( ldap_debug & (level) ) \ lutil_debug( ldap_debug, (level), (fmt), (connid), (opid), (arg1), (arg2), (arg3) );\ } while (0) +#define Statslog6( level, fmt, a1, a2, a3, a4, a5, a6 ) \ + do { \ + if ( ldap_debug & (level) ) \ + lutil_debug( ldap_debug, (level), (fmt), (a1), (a2), (a3), (a4), (a5), (a6) ); \ + } while (0) +#define Statslog7( level, fmt, a1, a2, a3, a4, a5, a6, a7 ) \ + do { \ + if ( ldap_debug & (level) ) \ + lutil_debug( ldap_debug, (level), (fmt), (a1), (a2), (a3), (a4), (a5), (a6), (a7) ); \ + } while (0) #define StatslogTest( level ) (ldap_debug & (level)) #endif /* !LDAP_SYSLOG */ #else /* !LDAP_DEBUG */ #define Statslog( level, fmt, connid, opid, arg1, arg2, arg3 ) ((void) 0) +#define Statslog6( level, fmt, a1, a2, a3, a4, a5, a6 ) ((void) 0) +#define Statslog7( level, fmt, a1, a2, a3, a4, a5, a6, a7 ) ((void) 0) #define StatslogTest( level ) (0) #endif /* !LDAP_DEBUG */ -- 2.1.4 --Multipart=_Sun__8_Feb_2015_19_56_17_-0800_yxgp4/9WqjBC20PY--

1 0

(ITS#8054) Operation duration logging
by ebackes＠symas.com 08 Feb '15

08 Feb '15

Full_Name: Emily Backes Version: master, 2.4 OS: URL: Submission from: (NULL) (50.113.67.84) Here is a patch to add duration logging for operations that appears in the standard result messages of statslog. It's a reasonably small change with negligible performance implications except under pathological benchmarking conditions. It does change the quasi-machine-parsable statslog format, however, so it might not be appropriate for general 2.4 release. Example line: 54d8298c conn=1000 op=1 SEARCH RESULT tag=101 err=0 duration=0.170ms nentries=1 text= As written, it uses a separate field in struct Operation and is entirely independent of the o_tincr functionality. Merging those has further portability problems, and is out of the scope of this feature. As a result, the overhead is two additional gettimeofday() calls per operation. The change is wrapped in #ifdef HAVE_GETTIMEOFDAY, so architectures lacking that will see no change. I have patches versus both the master branch (which likely covers 2.5), and OPENLDAP_REL_ENG_2_4. They'll be attached momentarily, outside jitterbug's web interface. %ThThese modifications are the sole work of myself (Emily Backes) on behalf of Symas Corporation based on existing log features of OpenLDAP. Therefore, these modifications are: Copyright 2014-2015 Symas Corporation Redistribution and use in source and binary forms, with or without modification, are permitted only as authorized by the OpenLDAP Public License.

1 0

Re: (ITS#8046) query caused slapd to stop
by ryan＠nardis.ca 06 Feb '15

06 Feb '15

This follow-up is just to add some missing details to the log, since this is getting some traffic now. A query that reproduces the crash is: ldapsearch -E 'mv=(cn={*)(sn=*)' It was introduced by "ITS#7942 plug leak in controls": commit 9d991339 on master, ffd0f03b on RE24. vrFilter_free was broken for a long time, but was never called until the leak was fixed in that ITS. hope that helps, Ryan

1 0

Re: (ITS#8053) Error with replication " invalid format (line 5) entry: "olcDatabase={1}hdb, cn=config"
by Howard Chu 05 Feb '15

05 Feb '15

The OpenLDAP-ITS address is for reporting bugs in OpenLDAP software. Nothing in your report is indicative of a bug in OpenLDAP. If you have questions about use of OpenLDAP Software which are not answered in the documentation, FAQ, and archives, use the OpenLDAP-technical list (subscription required; instructions here <http://www.openldap.org/lists/mm/listinfo/openldap-technical>). This issue report will be closed. p.

1 0

(ITS#8053) Error with replication " invalid format (line 5) entry: "olcDatabase={1}hdb, cn=config"
by dennishilla＠web.de 05 Feb '15

05 Feb '15

Full_Name: Dennis Version: 2.4.31 OS: Ubuntu 14.04 URL: Submission from: (NULL) (131.159.10.148) Hi guys, we just set up a Ubuntu Server with OpenLDAP running. We also have a second server, running Ubuntu as well. Now i tried to set up the replication using this guide: https://help.ubuntu.com/lts/serverguide/openldap-server.html#openldap-serve… Problem is, when i want to add the provider file using sudo ldapadd -Q -Y EXTERNAL -H ldapi:/// -f provider_sync.ldif i get a error-message: ldapadd: invalid format (line 5) entry: "olcDatabase={1}hdb,cn=config" Does anyone know where this problem comes from?

1 0

Re: (ITS#8052) OpenLDAP not compiling on Ubuntu
by jfha73＠gmail.com 04 Feb '15

04 Feb '15

On 2/4/2015 1:09 PM, Michael Ströder wrote: > jfha73(a)gmail.com wrote: >> Because it is for libraries for PHP master (7) and I was told that PHP 7 >> is not yet supporting 2.4.x > I don't know "PHP master (7)" means. > But php-ldap is linked to OpenLDAP 2.4 libs on my systems since years. > > BTW: The ITS is not for usage questions. Please follow-up on > openldap-technical mailing list. > > Ciao, Michael. > According to PHP's wiki page it's not, they are using version 2.3.42, but I'll check with them to see if they can update their software to work with version 2.4.x Thanks, you can close this Bug. Jorge_.

1 0

2024

2023

2022

2021

2020

2019

2018

2017

2016

2015

2014

2013

2012

2011

2010

2009

2008

2007

2006

openldap-bugs February 2015