first try at logging improvements

include/lber.h

@@ -23,6 +23,9 @@
 #ifndef _LBER_H
 #define _LBER_H
 
+#include <stdio.h>
+#include <ac/stdarg.h>
+
 #include <lber_types.h>
 
 LDAP_BEGIN_DECL
@@ -103,6 +106,9 @@ LDAP_BEGIN_DECL
 
 /* get/set Memory Debug options */
 #define LBER_OPT_MEMORY_INUSE		0x8005	/* for memory debugging */
+#define LBER_OPT_LOG_PROC           0x8006  /* for external logging function */
+
+typedef void (*BER_LOG_FN) LDAP_P((FILE *file, char *subsys, int level, const char *fmt, va_list vl));
 
 typedef int* (*BER_ERRNO_FN) LDAP_P(( void ));
 
@@ -219,6 +225,9 @@ LBER_F( void )
 ber_sos_dump LDAP_P((
 	Seqorset *sos ));
 
+LBER_F( int )
+ber_pvt_log_output LDAP_P((
+	char *subsystem, int level, const char *fmt, ... ));
 
 /*
  * in decode.c:

include/ldap_log.h

@@ -23,10 +23,54 @@
 #ifndef _LDAP_LOG_H
 #define _LDAP_LOG_H
 
+#include <stdio.h>
 #include <ldap_cdefs.h>
 
 LDAP_BEGIN_DECL
 
+/*
+ * While it's not important that the subsystem number are
+ * contiguous, it is important that the NUM_SUBSYS accurately
+ * reflect the number of subsystems and MAX_SUBSYS reflect
+ * the largest subsystem number.
+ */
+#define NUM_SUBSYS 12
+#define MAX_SUBSYS 11
+
+#define LDAP_SUBSYS_GLOBAL      0
+#define LDAP_SUBSYS_OPERATION   1
+#define LDAP_SUBSYS_TRANSPORT   2
+#define LDAP_SUBSYS_CONNECTION  3
+#define LDAP_SUBSYS_FILTER      4
+#define LDAP_SUBSYS_BACKEND     5
+#define LDAP_SUBSYS_BER         6
+#define LDAP_SUBSYS_CONFIG      7
+#define LDAP_SUBSYS_ACL         8
+#define LDAP_SUBSYS_CACHE       9
+#define LDAP_SUBSYS_INDEX      10
+#define LDAP_SUBSYS_LDIF       11
+
+/*
+ * debug reporting levels.
+ *
+ * They start with the syslog levels, and
+ * go down in importance.  The normal
+ * debugging levels begin with LDAP_LEVEL_ENTRY
+ *
+ */
+#define LDAP_LEVEL_EMERG       0
+#define LDAP_LEVEL_ALERT       1
+#define LDAP_LEVEL_CRIT        2
+#define LDAP_LEVEL_ERR         3
+#define LDAP_LEVEL_WARNING     4
+#define LDAP_LEVEL_NOTICE      5
+#define LDAP_LEVEL_INFO        6
+#define LDAP_LEVEL_ENTRY       7  /* log function entry points */
+#define LDAP_LEVEL_ARGS        8  /* log function call parameters */
+#define LDAP_LEVEL_RESULTS     9  /* Log function results */
+#define LDAP_LEVEL_DETAIL1    10  /* log level 1 function operational details */
+#define LDAP_LEVEL_DETAIL2    11  /* Log level 2 function operational details */
+
 #define LDAP_DEBUG_TRACE	0x0001
 #define LDAP_DEBUG_PACKETS	0x0002
 #define LDAP_DEBUG_ARGS		0x0004
@@ -39,6 +83,8 @@ LDAP_BEGIN_DECL
 #define LDAP_DEBUG_STATS2	0x0200
 #define LDAP_DEBUG_SHELL	0x0400
 #define LDAP_DEBUG_PARSE	0x0800
+#define LDAP_DEBUG_CACHE    0x1000
+#define LDAP_DEBUG_INDEX    0x2000
 
 #define LDAP_DEBUG_DEPRECATED	0x1000
 #define LDAP_DEBUG_NONE		0x8000
@@ -78,6 +124,17 @@ extern int	ldap_syslog_level;
 #define Debug( level, fmt, arg1, arg2, arg3 )
 #endif /* LDAP_DEBUG */
 
+
+#define LDAP_LOG(a) lutil_log a
+
+LDAP_LUTIL_F(void) lutil_log_initialize(int argc, char **argv);
+LDAP_LUTIL_F(void) lutil_set_debug_level LDAP_P(( char *subsys, int level ));
+LDAP_LUTIL_F(void) lutil_log LDAP_P(( char *subsys, int level, const char *fmt, ... ));
+/*LDAP_LUTIL_F(void) lutil_log_int LDAP_P(( FILE* file, char *subsys, int level, const char *fmt, va_list vl ));*/
+
+LDAP_LUTIL_F(int) lutil_debug_file LDAP_P(( FILE *file ));
+
+
 LDAP_LUTIL_F(void) lutil_debug LDAP_P((
 	int debug, int level,
 	const char* fmt, ... )) LDAP_GCCATTR((format(printf, 3, 4)));

libraries/liblber/bprint.c

@@ -14,6 +14,8 @@
 
 #include "lber-int.h"
 
+BER_LOG_FN ber_int_log_proc = NULL;
+
 /*
  * We don't just set ber_pvt_err_file to stderr here, because in NT,
  * stderr is a symbol imported from a DLL. As such, the compiler
@@ -65,6 +67,34 @@ BER_LOG_PRINT_FN ber_pvt_log_print = ber_error_print;
  * lber log 
  */
 
+int ber_pvt_log_output( char *subsystem, int level, const char *fmt, ... )
+{
+	char buf[ 1024 ];
+	va_list vl;
+	va_start( vl, fmt );
+
+	if ( ber_int_log_proc != NULL )
+	{
+		ber_int_log_proc( ber_pvt_err_file, subsystem, level, fmt, vl );
+	}
+	else
+	{
+#ifdef HAVE_VSNPRINTF
+		buf[sizeof(buf) - 1] = '\0';
+		vsnprintf( buf, sizeof(buf)-1, fmt, vl );
+#elif HAVE_VSPRINTF
+		vsprintf( buf, fmt, vl ); /* hope it's not too long */
+#else
+	/* use doprnt() */
+#error "vsprintf() required."
+#endif
+		(*ber_pvt_log_print)( buf );
+	}
+	va_end(vl);
+
+	return 1;
+}
+	
 static int ber_log_check( int errlvl, int loglvl )
 {
 	return errlvl & loglvl ? 1 : 0;

libraries/liblber/decode.c

@@ -494,6 +494,8 @@ ber_scanf ( BerElement *ber,
 
 	fmt_reset = fmt;
 
+	LDAP_LOG( "LIBLBER", LDAP_LEVEL_ENTRY, "ber_scanf fmt (%s) ber:\n", fmt );
+
 	ber_log_printf( LDAP_DEBUG_TRACE, ber->ber_debug,
 		"ber_scanf fmt (%s) ber:\n", fmt );
 	ber_log_dump( LDAP_DEBUG_BER, ber->ber_debug, ber, 1 );

libraries/liblber/lber-int.h

@@ -33,6 +33,8 @@ struct lber_options {
 	long		lbo_meminuse;
 };
 
+#define LDAP_LOG ber_pvt_log_output
+
 #define LBER_UNINITIALIZED		0x0
 #define LBER_INITIALIZED		0x1
 #define LBER_VALID_BERELEMENT	0x2

libraries/liblber/options.c

@@ -11,6 +11,7 @@
 #include "lber-int.h"
 
 extern void * ber_pvt_err_file;	/* bprint.c */
+extern BER_LOG_FN ber_int_log_proc;
 
 struct lber_options ber_int_options = {
 	LBER_UNINITIALIZED, 0, 0 };
@@ -50,6 +51,9 @@ ber_get_option(
 #else
 			return LBER_OPT_ERROR;
 #endif
+		} else if(option == LBER_OPT_LOG_PRINT_FILE) {
+			*((FILE**)outvalue) = (FILE*)ber_pvt_err_file;
+			return LBER_OPT_SUCCESS;
 		}
 
 		ber_errno = LBER_ERROR_PARAM;
@@ -166,6 +170,8 @@ ber_set_option(
 #else
 			return LBER_OPT_ERROR;
 #endif
+		} else if(option == LBER_OPT_LOG_PROC) {
+			ber_int_log_proc = (BER_LOG_FN)invalue;
 		}
 
 		ber_errno = LBER_ERROR_PARAM;

libraries/liblutil/debug.c

@@ -26,6 +26,7 @@
 
 #include <ac/stdarg.h>
 #include <ac/string.h>
+#include <ac/time.h>
 
 #include "ldap_log.h"
 #include "ldap_defaults.h"
@@ -33,6 +34,60 @@
 
 static FILE *log_file;
 
+struct M2S
+{
+	char *mnemonic;
+	int  subsys;
+};
+
+struct DEBUGLEVEL
+{
+	char *subsystem;
+	int  level;
+};
+
+static struct DEBUGLEVEL **levelArray;
+static long   numLevels = 0;
+
+int global_level = 0;
+
+static void addSubsys( const char *subsys, int level )
+{
+	int i, j;
+	for( i = 0; i < numLevels; i++ )
+	{
+		if ( levelArray[i] == NULL )
+		{
+			levelArray[i] = (struct DEBUGLEVEL*)ber_memalloc( sizeof( struct DEBUGLEVEL ) );
+			levelArray[i]->subsystem = (char*)ber_memalloc( strlen( subsys ) + 1 );
+			strcpy ( levelArray[i]->subsystem, subsys );
+			levelArray[i]->level = level;
+			return;
+		}
+		if( !strcasecmp( subsys, levelArray[i]->subsystem ) )
+		{
+			levelArray[i]->level = level;
+			return;
+		}
+	}
+	levelArray = (struct DEBUGLEVEL**)ber_memrealloc( levelArray, sizeof( struct DEBUGLEVEL* ) * (numLevels + 10) );
+	for( j = numLevels; j < (numLevels + 10); j++ )
+	{
+		levelArray[j] = NULL;
+	}
+	numLevels += 10;
+	levelArray[i] = (struct DEBUGLEVEL*)ber_memalloc( sizeof( struct DEBUGLEVEL ) );
+	levelArray[i]->subsystem = (char*)ber_memalloc( strlen( subsys ) + 1 );
+	strcpy( levelArray[i]->subsystem, subsys );
+	levelArray[i]->level = level;
+	return;
+}
+
+void lutil_set_debug_level( char* subsys, int level )
+{
+	addSubsys( subsys, level );
+}
+
 int lutil_debug_file( FILE *file )
 {
 	log_file = file;
@@ -41,6 +96,154 @@ int lutil_debug_file( FILE *file )
 	return 0;
 }
 
+void lutil_log_int(FILE* file, char *subsys, int level, const char *fmt, va_list vl )
+{
+	char buffer[4096];
+	time_t now;
+	struct tm *today;
+	int i;
+
+        /*
+         * Look for the subsystem in the level array.  When we find it, break out of the
+         * loop.
+         */
+	for( i = 0; i < numLevels; i++ )
+	{
+		if ( ! strcasecmp( levelArray[i]->subsystem, subsys ) ) break;
+	}
+
+        /*
+         * If we didn't find the subsystem, or the set level is less than
+         * the requested output level, don't output it.
+         */
+	if ( (level > global_level) && 
+             ((i > numLevels ) || ( level > levelArray[i]->level )) )
+		return;
+
+#if 0
+#ifdef HAVE_WINSOCK
+	if( log_file == NULL ) {
+		log_file = fopen( LDAP_RUNDIR LDAP_DIRSEP "openldap.log", "w" );
+
+		if ( log_file == NULL )
+			log_file = fopen( "openldap.log", "w" );
+
+		if ( log_file == NULL )
+			return;
+
+		ber_set_option( NULL, LBER_OPT_LOG_PRINT_FILE, log_file );
+	}
+#endif
+#endif
+
+        /*
+         * Stick the time in the buffer to output.  Kurt doesn't like
+         * doing this here, but NT can't pipe to a timestamp program
+         * like Unix can, and I don't think it costs much.
+         */
+	time( &now );
+	today = localtime( &now );
+	sprintf( buffer, "%4d%02d%02d:%02d:%02d:%02d ",
+		today->tm_year + 1900, today->tm_mon + 1,
+		today->tm_mday, today->tm_hour,
+		today->tm_min, today->tm_sec );
+
+        /*
+         * format the output data.
+         */
+#ifdef HAVE_VSNPRINTF
+	vsnprintf( &buffer[18], sizeof(buffer)-18, fmt, vl );
+#else
+	vsprintf( &buffer[18], fmt, vl );
+#endif
+	buffer[sizeof(buffer)-1] = '\0';
+
+        /*
+         * If the user set up a file using 
+         * ber_set_option( NULL, LBER_OPT_LOG_PRINT_FILE, file), use
+         * it.  Otherwise, just output to stderr.
+         */
+	if( file != NULL ) {
+		fputs( buffer, file );
+		fflush( file );
+	}
+        else
+        {
+            fputs( buffer, stderr );
+        }
+
+/*
+ * Kurt or someone needs to decide what to do about this.  This
+ * code will log to syslog if the level is less than a normal
+ * debug level (meaning a warning or error of some kind).  However,
+ * having the code here means that ldap_syslog has to be defined.
+ */
+#if 0
+#ifdef LDAP_SYSLOG
+	if ( level < LDAP_LEVEL_ENTRY && level >= ldap_syslog )
+	{
+		syslog( level, buffer );
+	}
+#endif
+#endif
+}
+
+/*
+ * The primary logging routine.  Takes the subsystem being logged from, the
+ * level of the log output and the format and data.  Send this on to the
+ * internal routine with the print file, if any.
+ */
+void lutil_log( char *subsys, int level, const char *fmt, ... )
+{
+	FILE* outfile = NULL;
+	va_list vl;
+	va_start( vl, fmt );
+	ber_get_option( NULL, LBER_OPT_LOG_PRINT_FILE, &outfile );
+	lutil_log_int( outfile, subsys, level, fmt, vl );
+	va_end( vl );
+}
+
+void lutil_log_initialize(int argc, char **argv)
+{
+    int i;
+    /*
+     * Start by setting the hook for the libraries to use this logging
+     * routine.
+     */
+    ber_set_option( NULL, LBER_OPT_LOG_PROC, (void*)lutil_log_int );
+
+    if ( argc == 0 ) return;
+    /*
+     * Now go through the command line options to set the debugging
+     * levels
+     */
+    for( i = 0; i < argc; i++ )
+    {
+        char *next = argv[i];
+        if ( i < argc-1 && next[0] == '-' && next[1] == 'd' )
+        {
+            char subsys[64];
+            int level;
+            char *optarg = argv[i+1];
+            char *index = strchr( optarg, '=' );
+            if ( index != NULL )
+            {
+                *index = 0;
+                strcpy ( subsys, optarg );
+                level = atoi( index+1 );
+                lutil_set_debug_level( subsys, level );
+                printf( "setting debug level of %s to %d\n", subsys, level );
+                *index = '=';
+            }
+            else
+            {
+                global_level = atoi( optarg );
+                printf( "setting global level to %d\n", global_level );
+            }
+        }
+    }
+}
+
 void (lutil_debug)( int debug, int level, const char *fmt, ... )
 {
 	char buffer[4096];