ldap/servers/slapd/libglobs.c | 32 +++++
ldap/servers/slapd/proto-slap.h | 2
ldap/servers/slapd/result.c | 226 ++++++++++++++++++++++------------------
ldap/servers/slapd/slap.h | 2
4 files changed, 163 insertions(+), 99 deletions(-)
New commits:
commit 55ff5cf4cbbbd9bce392f5253031a8e5b4b14dc6
Author: Mark Reynolds <mreynolds(a)redhat.com>
Date: Tue Sep 17 18:32:13 2013 -0400
Ticket 47401 - report unindexed internal searches
Bug Description: Internal search operations that are unindexed are not logged. By
default plugins do not log their operations, even if access log
level
is set to record internal operations - unless the undocumented
config
attribute "nsslapd-logAccess: on" is set in each plugin
config entry.
Fix Description: Record the unindexed search in the error log, if access logging is
not
recording internal operations. Also, a new config attribute was
added
to cn=config:
nsslapd-plugin-logging: on|off
When set to on, it turns on logging for all plugin internal
operations.
https://fedorahosted.org/389/ticket/47401
Reviewed by: nhosoi(Thanks!)
diff --git a/ldap/servers/slapd/libglobs.c b/ldap/servers/slapd/libglobs.c
index 16799f5..047bd1c 100644
--- a/ldap/servers/slapd/libglobs.c
+++ b/ldap/servers/slapd/libglobs.c
@@ -258,6 +258,7 @@ slapi_onoff_t init_sasl_mapping_fallback;
slapi_onoff_t init_return_orig_type;
slapi_onoff_t init_enable_turbo_mode;
slapi_onoff_t init_connection_nocanon;
+slapi_onoff_t init_plugin_logging;
slapi_int_t init_connection_buffer;
slapi_int_t init_listen_backlog_size;
#ifdef MEMPOOL_EXPERIMENTAL
@@ -1059,6 +1060,10 @@ static struct config_get_and_set {
NULL, 0,
(void**)&global_slapdFrontendConfig.connection_nocanon,
CONFIG_ON_OFF, (ConfigGetFunc)config_get_connection_nocanon,
&init_connection_nocanon},
+ {CONFIG_PLUGIN_LOGGING, config_set_plugin_logging,
+ NULL, 0,
+ (void**)&global_slapdFrontendConfig.plugin_logging,
+ CONFIG_ON_OFF, (ConfigGetFunc)config_get_plugin_logging,
&init_plugin_logging},
{CONFIG_LISTEN_BACKLOG_SIZE, config_set_listen_backlog_size,
NULL, 0,
(void**)&global_slapdFrontendConfig.listen_backlog_size, CONFIG_INT,
@@ -1503,7 +1508,7 @@ FrontendConfig_init () {
init_enable_turbo_mode = cfg->enable_turbo_mode = LDAP_ON;
init_connection_buffer = cfg->connection_buffer = CONNECTION_BUFFER_ON;
init_connection_nocanon = cfg->connection_nocanon = LDAP_ON;
-
+ init_plugin_logging = cfg->plugin_logging = LDAP_OFF;
init_listen_backlog_size = cfg->listen_backlog_size = DAEMON_LISTEN_SIZE;
#ifdef MEMPOOL_EXPERIMENTAL
init_mempool_switch = cfg->mempool_switch = LDAP_ON;
@@ -6954,6 +6959,18 @@ config_get_connection_nocanon(void)
}
int
+config_get_plugin_logging(void)
+{
+ int retVal;
+ slapdFrontendConfig_t *slapdFrontendConfig = getFrontendConfig();
+ CFG_ONOFF_LOCK_READ(slapdFrontendConfig);
+ retVal = (int)slapdFrontendConfig->plugin_logging;
+ CFG_ONOFF_UNLOCK_READ(slapdFrontendConfig);
+
+ return retVal;
+}
+
+int
slapi_config_get_unhashed_pw_switch()
{
return config_get_unhashed_pw_switch();
@@ -6998,6 +7015,19 @@ config_set_connection_nocanon( const char *attrname, char *value,
}
int
+config_set_plugin_logging( const char *attrname, char *value,
+ char *errorbuf, int apply )
+{
+ int retVal = LDAP_SUCCESS;
+ slapdFrontendConfig_t *slapdFrontendConfig = getFrontendConfig();
+
+ retVal = config_set_onoff(attrname, value,
+ &(slapdFrontendConfig->plugin_logging),
+ errorbuf, apply);
+ return retVal;
+}
+
+int
config_get_connection_buffer(void)
{
int retVal;
diff --git a/ldap/servers/slapd/proto-slap.h b/ldap/servers/slapd/proto-slap.h
index 03cf8e5..f2f5319 100644
--- a/ldap/servers/slapd/proto-slap.h
+++ b/ldap/servers/slapd/proto-slap.h
@@ -569,7 +569,9 @@ int config_set_enable_turbo_mode(const char *attrname, char *value,
char *errorb
int config_get_connection_buffer();
int config_set_connection_buffer(const char *attrname, char *value, char *errorbuf, int
apply);
int config_get_connection_nocanon();
+int config_get_plugin_logging();
int config_set_connection_nocanon(const char *attrname, char *value, char *errorbuf, int
apply);
+int config_set_plugin_logging(const char *attrname, char *value, char *errorbuf, int
apply);
int config_get_listen_backlog_size(void);
PLHashNumber hashNocaseString(const void *key);
diff --git a/ldap/servers/slapd/result.c b/ldap/servers/slapd/result.c
index 9b6fb8b..f520e6b 100644
--- a/ldap/servers/slapd/result.c
+++ b/ldap/servers/slapd/result.c
@@ -568,8 +568,9 @@ send_ldap_result_ext(
log_and_return:
operation->o_status = SLAPI_OP_STATUS_RESULT_SENT; /* in case this has not yet been
set */
- if ( logit && operation_is_flag_set( operation,
- OP_FLAG_ACTION_LOG_ACCESS )) {
+ if ( logit && (operation_is_flag_set( operation, OP_FLAG_ACTION_LOG_ACCESS ) ||
+ (internal_op && config_get_plugin_logging() )))
+ {
log_result( pb, operation, err, tag, nentries );
}
@@ -1857,33 +1858,30 @@ notes2str( unsigned int notes, char *buf, size_t buflen )
#define ETIME_BUFSIZ 16 /* room for 99999999.999999 */
static void
-log_result( Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag,
- int nentries )
+log_result( Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries )
{
char *notes_str, notes_buf[ 256 ];
int internal_op;
CSN *operationcsn = NULL;
char csn_str[CSN_STRSIZE + 5];
- char etime[ETIME_BUFSIZ];
+ char etime[ETIME_BUFSIZ];
internal_op = operation_is_flag_set( op, OP_FLAG_INTERNAL );
- if ( (config_get_accesslog_level() & LDAP_DEBUG_TIMING) &&
- (op->o_interval != (PRIntervalTime) 0) ) {
- PRIntervalTime delta = PR_IntervalNow() - op->o_interval;
- PR_snprintf(etime, ETIME_BUFSIZ, "%f",
- (PRFloat64)delta/PR_TicksPerSecond());
- } else {
- PR_snprintf(etime, ETIME_BUFSIZ, "%ld", current_time() -
op->o_time);
- }
+ if ( (config_get_accesslog_level() & LDAP_DEBUG_TIMING) &&
+ (op->o_interval != (PRIntervalTime) 0) ) {
+ PRIntervalTime delta = PR_IntervalNow() - op->o_interval;
+ PR_snprintf(etime, ETIME_BUFSIZ, "%f",
(PRFloat64)delta/PR_TicksPerSecond());
+ } else {
+ PR_snprintf(etime, ETIME_BUFSIZ, "%ld", current_time() - op->o_time);
+ }
if ( 0 == pb->pb_operation_notes ) {
notes_str = "";
} else {
notes_str = notes_buf;
*notes_buf = ' ';
- notes2str( pb->pb_operation_notes, notes_buf + 1,
- sizeof( notes_buf ) - 1 );
+ notes2str( pb->pb_operation_notes, notes_buf + 1, sizeof( notes_buf ) - 1 );
}
csn_str[0] = '\0';
@@ -1897,92 +1895,124 @@ log_result( Slapi_PBlock *pb, Operation *op, int err, ber_tag_t
tag,
}
}
- if (op->o_tag == LDAP_REQ_BIND && err == LDAP_SASL_BIND_IN_PROGRESS)
{
- /*
- * Not actually an error.
- * Make that clear in the log.
- */
- if ( !internal_op )
- {
- slapi_log_access( LDAP_DEBUG_STATS,
- "conn=%" NSPRIu64 " op=%d RESULT err=%d"
- " tag=%" BERTAG_T " nentries=%d etime=%s%s%s"
- ", SASL bind in progress\n",
- (long long unsigned int)op->o_connid,
- op->o_opid,
- err, tag, nentries,
- etime,
- notes_str, csn_str );
- }
- else
- {
- slapi_log_access( LDAP_DEBUG_ARGS,
- "conn=%s op=%d RESULT err=%d"
- " tag=%" BERTAG_T " nentries=%d etime=%s%s%s"
- ", SASL bind in progress\n",
- LOG_INTERNAL_OP_CON_ID,
- LOG_INTERNAL_OP_OP_ID,
- err, tag, nentries,
- etime,
- notes_str, csn_str );
- }
- } else if (op->o_tag == LDAP_REQ_BIND && err == LDAP_SUCCESS) {
- char *dn = NULL;
-
- /*
- * For methods other than simple, the dn in the bind request
- * may be irrelevant. Log the actual authenticated dn.
- */
- slapi_pblock_get(pb, SLAPI_CONN_DN, &dn);
- if ( !internal_op )
- {
- slapi_log_access( LDAP_DEBUG_STATS,
- "conn=%" NSPRIu64 " op=%d RESULT err=%d"
- " tag=%" BERTAG_T " nentries=%d etime=%s%s%s"
- " dn=\"%s\"\n",
- (long long unsigned int)op->o_connid,
- op->o_opid,
- err, tag, nentries,
- etime,
- notes_str, csn_str, dn ? dn : "");
- }
- else
- {
- slapi_log_access( LDAP_DEBUG_ARGS,
- "conn=%s op=%d RESULT err=%d"
- " tag=%" BERTAG_T " nentries=%d etime=%s%s%s"
- " dn=\"%s\"\n",
- LOG_INTERNAL_OP_CON_ID,
- LOG_INTERNAL_OP_OP_ID,
- err, tag, nentries,
- etime,
- notes_str, csn_str, dn ? dn : "");
- }
- slapi_ch_free((void**)&dn);
- } else {
- if ( !internal_op )
- {
- slapi_log_access( LDAP_DEBUG_STATS,
- "conn=%" NSPRIu64 " op=%d RESULT err=%d"
- " tag=%" BERTAG_T " nentries=%d etime=%s%s%s\n",
- (long long unsigned int)op->o_connid,
- op->o_opid,
- err, tag, nentries,
- etime,
- notes_str, csn_str );
- }
- else
+ if (op->o_tag == LDAP_REQ_BIND && err == LDAP_SASL_BIND_IN_PROGRESS) {
+ /*
+ * Not actually an error.
+ * Make that clear in the log.
+ */
+ if ( !internal_op )
+ {
+ slapi_log_access( LDAP_DEBUG_STATS,
+ "conn=%" NSPRIu64 " op=%d RESULT err=%d"
+ " tag=%" BERTAG_T " nentries=%d etime=%s%s%s"
+ ", SASL bind in progress\n",
+ (long long unsigned int)op->o_connid,
+ op->o_opid,
+ err, tag, nentries,
+ etime,
+ notes_str, csn_str );
+ }
+ else
+ {
+ slapi_log_access( LDAP_DEBUG_ARGS,
+ "conn=%s op=%d RESULT err=%d"
+ " tag=%" BERTAG_T " nentries=%d etime=%s%s%s"
+ ", SASL bind in progress\n",
+ LOG_INTERNAL_OP_CON_ID,
+ LOG_INTERNAL_OP_OP_ID,
+ err, tag, nentries,
+ etime,
+ notes_str, csn_str );
+ }
+ } else if (op->o_tag == LDAP_REQ_BIND && err == LDAP_SUCCESS) {
+ char *dn = NULL;
+
+ /*
+ * For methods other than simple, the dn in the bind request
+ * may be irrelevant. Log the actual authenticated dn.
+ */
+ slapi_pblock_get(pb, SLAPI_CONN_DN, &dn);
+ if ( !internal_op )
+ {
+ slapi_log_access( LDAP_DEBUG_STATS,
+ "conn=%" NSPRIu64 " op=%d RESULT err=%d"
+ " tag=%" BERTAG_T " nentries=%d etime=%s%s%s"
+ " dn=\"%s\"\n",
+ (long long unsigned int)op->o_connid,
+ op->o_opid,
+ err, tag, nentries,
+ etime,
+ notes_str, csn_str, dn ? dn : "");
+ }
+ else
+ {
+ slapi_log_access( LDAP_DEBUG_ARGS,
+ "conn=%s op=%d RESULT err=%d"
+ " tag=%" BERTAG_T " nentries=%d etime=%s%s%s"
+ " dn=\"%s\"\n",
+ LOG_INTERNAL_OP_CON_ID,
+ LOG_INTERNAL_OP_OP_ID,
+ err, tag, nentries,
+ etime,
+ notes_str, csn_str, dn ? dn : "");
+ }
+ slapi_ch_free((void**)&dn);
+ } else {
+ if ( !internal_op )
+ {
+ slapi_log_access( LDAP_DEBUG_STATS,
+ "conn=%" NSPRIu64 " op=%d RESULT err=%d"
+ " tag=%" BERTAG_T " nentries=%d etime=%s%s%s\n",
+ (long long unsigned int)op->o_connid,
+ op->o_opid,
+ err, tag, nentries,
+ etime,
+ notes_str, csn_str );
+ }
+ else
+ {
+ int optype;
+ slapi_log_access( LDAP_DEBUG_ARGS,
+ "conn=%s op=%d RESULT err=%d"
+ " tag=%" BERTAG_T " nentries=%d etime=%s%s%s\n",
+ LOG_INTERNAL_OP_CON_ID,
+ LOG_INTERNAL_OP_OP_ID,
+ err, tag, nentries,
+ etime,
+ notes_str, csn_str );
+ /*
+ * If this is an unindexed search we should log it in the error log if
+ * we didn't log it in the access log.
+ */
+ slapi_pblock_get( pb, SLAPI_OPERATION_TYPE, &optype );
+ if(optype == SLAPI_OPERATION_SEARCH && /* search, */
+ strcmp(notes_str,"") && /* that's unindexed, */
+ !(config_get_accesslog_level() & LDAP_DEBUG_ARGS)) /* and not logged in access
log */
{
- slapi_log_access( LDAP_DEBUG_ARGS,
- "conn=%s op=%d RESULT err=%d"
- " tag=%" BERTAG_T " nentries=%d etime=%s%s%s\n",
- LOG_INTERNAL_OP_CON_ID,
- LOG_INTERNAL_OP_OP_ID,
- err, tag, nentries,
- etime,
- notes_str, csn_str );
+ struct slapdplugin *plugin = NULL;
+ struct slapi_componentid *cid = NULL;
+ char *filter_str;
+ char *plugin_dn;
+ char *base_dn;
+
+ slapi_pblock_get(pb, SLAPI_SEARCH_STRFILTER, &filter_str);
+ slapi_pblock_get(pb, SLAPI_TARGET_DN, &base_dn);
+ slapi_pblock_get (pb, SLAPI_PLUGIN_IDENTITY, &cid);
+ if (cid){
+ plugin=(struct slapdplugin *) cid->sci_plugin;
+ } else {
+ slapi_pblock_get (pb, SLAPI_PLUGIN, &plugin);
+ }
+ plugin_dn = plugin_get_dn(plugin);
+
+ slapi_log_error (SLAPI_LOG_FATAL, "Internal search" , "Unindexed
search: source (%s) "
+ "search base=\"%s\" filter=\"%s\" etime=%s nentries=%d
%s\n",
+ plugin_dn, base_dn, filter_str, etime, nentries, notes_str);
+
+ slapi_ch_free_string(&plugin_dn);
}
}
+ }
}
diff --git a/ldap/servers/slapd/slap.h b/ldap/servers/slapd/slap.h
index a98de47..6c88a56 100644
--- a/ldap/servers/slapd/slap.h
+++ b/ldap/servers/slapd/slap.h
@@ -2111,6 +2111,7 @@ typedef struct _slapdEntryPoints {
#define CONFIG_ENABLE_TURBO_MODE "nsslapd-enable-turbo-mode"
#define CONFIG_CONNECTION_BUFFER "nsslapd-connection-buffer"
#define CONFIG_CONNECTION_NOCANON "nsslapd-connection-nocanon"
+#define CONFIG_PLUGIN_LOGGING "nsslapd-plugin-logging"
#define CONFIG_LISTEN_BACKLOG_SIZE "nsslapd-listen-backlog-size"
/*
@@ -2364,6 +2365,7 @@ typedef struct _slapdFrontendConfig {
slapi_onoff_t enable_turbo_mode;
slapi_int_t connection_buffer; /* values are CONNECTION_BUFFER_* below */
slapi_onoff_t connection_nocanon; /* if "on" sets LDAP_OPT_X_SASL_NOCANON */
+ slapi_onoff_t plugin_logging; /* log all internal plugin operations */
} slapdFrontendConfig_t;
/* possible values for slapdFrontendConfig_t.schemareplace */