config.h.in | 3
configure | 2
configure.ac | 2
ldap/admin/src/logconv.pl | 84 ++++++++------
ldap/schema/01core389.ldif | 1
ldap/servers/slapd/libglobs.c | 30 +++++
ldap/servers/slapd/log.c | 225 +++++++++++++++++++++-------------------
ldap/servers/slapd/proto-slap.h | 8 +
ldap/servers/slapd/slap.h | 7 +
ldap/servers/slapd/time.c | 104 ++++++++++++++++++
10 files changed, 321 insertions(+), 145 deletions(-)
New commits:
commit dbf16991bc8add44dff1ff39d6a2392414913c22
Author: William Brown <firstyear(a)redhat.com>
Date: Fri Feb 5 15:21:37 2016 +1000
Ticket 47982 - improve timestamp resolution in logs
Bug Description: An rfe was proposed to increase the resolution of timestamps
in logs to allow better automated machine sorting and time analysis of events.
Fix Description: This patch enables a configuration option
nsslapd-logging-hr-timestamps-enabled, default to on that provides nanosecond
accurate timestamps in logs.
This is only avaliable on platforms that support clock_gettime.
This patch removes the str buffer as it actually slowed down logging performance.
This enables support in logconv.pl for HR timestamps.
https://fedorahosted.org/389/ticket/47982
Author: wibrown
Review by: nhosoi (Thanks!)
diff --git a/config.h.in b/config.h.in
index 041a18f..ea9369b 100644
--- a/config.h.in
+++ b/config.h.in
@@ -78,6 +78,9 @@
/* Define to 1 if your system has a working `chown' function. */
#undef HAVE_CHOWN
+/* Define to 1 if you have the `clock_gettime' function. */
+#undef HAVE_CLOCK_GETTIME
+
/* Define to 1 if you have the declaration of `strerror_r', and to 0 if you
don't. */
#undef HAVE_DECL_STRERROR_R
diff --git a/configure b/configure
index 142d91a..6a03247 100755
--- a/configure
+++ b/configure
@@ -17666,7 +17666,7 @@ fi
done
-for ac_func in setrlimit endpwent ftruncate getcwd gethostbyname inet_ntoa localtime_r
memmove memset mkdir munmap putenv rmdir socket strcasecmp strchr strcspn strdup strerror
strncasecmp strpbrk strrchr strstr strtol tzset
+for ac_func in clock_gettime endpwent ftruncate getcwd gethostbyname inet_ntoa
localtime_r memmove memset mkdir munmap putenv rmdir setrlimit socket strcasecmp strchr
strcspn strdup strerror strncasecmp strpbrk strrchr strstr strtol tzset
do :
as_ac_var=`$as_echo "ac_cv_func_$ac_func" | $as_tr_sh`
ac_fn_c_check_func "$LINENO" "$ac_func" "$as_ac_var"
diff --git a/configure.ac b/configure.ac
index b80a077..c520022 100644
--- a/configure.ac
+++ b/configure.ac
@@ -63,7 +63,7 @@ AC_FUNC_STAT
AC_FUNC_STRERROR_R
AC_FUNC_STRFTIME
AC_FUNC_VPRINTF
-AC_CHECK_FUNCS([setrlimit endpwent ftruncate getcwd gethostbyname inet_ntoa localtime_r
memmove memset mkdir munmap putenv rmdir socket strcasecmp strchr strcspn strdup strerror
strncasecmp strpbrk strrchr strstr strtol tzset])
+AC_CHECK_FUNCS([clock_gettime endpwent ftruncate getcwd gethostbyname inet_ntoa
localtime_r memmove memset mkdir munmap putenv rmdir setrlimit socket strcasecmp strchr
strcspn strdup strerror strncasecmp strpbrk strrchr strstr strtol tzset])
AC_MSG_CHECKING(for --enable-debug)
AC_ARG_ENABLE(debug, AS_HELP_STRING([--enable-debug], [Enable debug features (default:
no)]),
diff --git a/ldap/admin/src/logconv.pl b/ldap/admin/src/logconv.pl
index 22d1a88..131a8c0 100755
--- a/ldap/admin/src/logconv.pl
+++ b/ldap/admin/src/logconv.pl
@@ -25,6 +25,7 @@ use sigtrap qw(die normal-signals);
use Archive::Tar;
use IO::Uncompress::AnyUncompress qw($AnyUncompressError);
use Scalar::Util qw(looks_like_number);
+use DB;
Getopt::Long::Configure ("bundling");
Getopt::Long::Configure ("permute");
@@ -45,10 +46,10 @@ my $logversion = "8.1";
my $sizeCount = "20";
my $startFlag = 0;
my $startTime = 0;
-my $startTimeInSecs = 0;
+my $startTimeInNsecs = 0;
my $endFlag = 0;
my $endTime = 0;
-my $endTimeInSecs = 0;
+my $endTimeInNsecs = 0;
my $minEtime = 0;
my $reportStats = "";
my $dataLocation = "/tmp";
@@ -361,8 +362,8 @@ my %monthname = (
#
if ($startTime and $endTime){
# Make sure the end time is not earlier than the start time
- my $testStart = convertTimeToSeconds($startTime);
- my $testEnd = convertTimeToSeconds($endTime);
+ my $testStart = convertTimeToNanoseconds($startTime);
+ my $testEnd = convertTimeToNanoseconds($endTime);
if ($testStart > $testEnd){
print "Start time ($startTime) is greater than end time ($endTime)!\n";
exit 1;
@@ -471,7 +472,7 @@ sub doUncompress {
return $TARFH;
}
-sub convertTimeToSeconds {
+sub convertTimeToNanoseconds {
my $log_line = shift;
my $logDate;
@@ -506,11 +507,11 @@ sub convertTimeToSeconds {
my $logTime;
my @timeComps;
- my ($timeHour, $timeMinute, $timeSecond, $timeTotal);
+ my ($timeHour, $timeMinute, $timeSecond, $timeNanosecond, $timeTotal);
$timeTotal = 0;
- if ($log_line =~ / *(:[0-9:]+)/i ){
+ if ($log_line =~ / *(:[0-9:\.]+)/i ){
$logTime = $1;
- @timeComps = split /:/, $logTime;
+ @timeComps = split /:|\./, $logTime;
if ($#timeComps < 3) {
print "The time string ($log_line) is invalid, exiting...\n";
exit(1);
@@ -527,20 +528,26 @@ sub convertTimeToSeconds {
print "The time string ($log_line) has invalid second ($timeComps[3]),
exiting...\n";
exit(1);
}
+ if ($#timeComps < 4 || !looks_like_number($timeComps[4]) || length $timeComps[4] !=
9){
+ # This isn't an error for nano seconds, we just assume old log format and set nsec
to 0
+ $timeNanosecond = 0;
+ } else {
+ $timeNanosecond = $timeComps[4];
+ }
$timeHour = $timeComps[1] * 3600;
$timeMinute = $timeComps[2] * 60;
$timeSecond = $timeComps[3];
$timeTotal = $timeHour + $timeMinute + $timeSecond;
}
- return $timeTotal + $dateTotal;
+ return (($timeTotal + $dateTotal) * 1000000000) + $timeNanosecond;
}
if($startTime){
- $startTimeInSecs = convertTimeToSeconds($startTime);
+ $startTimeInNsecs = convertTimeToNanoseconds($startTime);
}
if($endTime){
- $endTimeInSecs = convertTimeToSeconds($endTime);
+ $endTimeInNsecs = convertTimeToNanoseconds($endTime);
}
$Archive::Tar::WARN = 0; # so new will shut up when reading a regular file
@@ -672,58 +679,61 @@ $allOps = $srchCount + $modCount + $addCount + $cmpCount + $delCount
+ $modrdnCo
my $start;
if($startTime){
- if ($start =~ / *([0-9a-z:\/]+)/i){$start=$1;}
+ if ($start =~ / *([0-9a-z:\/\.]+)/i){$start=$1;}
}
my $end;
if($endTime){
- if ($end =~ / *([0-9a-z:\/]+)/i){$end =$1;}
+ if ($end =~ / *([0-9a-z:\/\.]+)/i){$end =$1;}
}
#
# Get the start time in seconds
#
my $logStart = $start;
-my $startTotal = convertTimeToSeconds($logStart);
+my $startTotal = convertTimeToNanoseconds($logStart);
#
# Get the end time in seconds
#
my $logEnd = $end;
-my $endTotal = convertTimeToSeconds($logEnd);
+my $endTotal = convertTimeToNanoseconds($logEnd);
#
# Tally the numbers
#
-my $totalTimeInSecs = $endTotal - $startTotal;
-my $remainingTimeInSecs = $totalTimeInSecs;
+my $totalTimeInNsecs = $endTotal - $startTotal;
+my $remainingTimeInNsecs = $totalTimeInNsecs;
+
+my $totalTimeInSecs = $totalTimeInNsecs / 1000000000;
+my $remainingTimeInSecs = $remainingTimeInNsecs / 1000000000;
#
# Calculate the elapsed time
#
# days
-while(($remainingTimeInSecs - 86400) > 0){
+while(($remainingTimeInNsecs - (86400 * 1000000000)) > 0){
$elapsedDays++;
- $remainingTimeInSecs = $remainingTimeInSecs - 86400;
+ $remainingTimeInNsecs = $remainingTimeInNsecs - (86400 * 1000000000);
}
# hours
my $elapsedHours = 0;
-while(($remainingTimeInSecs - 3600) > 0){
+while(($remainingTimeInNsecs - (3600 * 1000000000 )) > 0){
$elapsedHours++;
- $remainingTimeInSecs = $remainingTimeInSecs - 3600;
+ $remainingTimeInNsecs = $remainingTimeInNsecs - (3600 * 1000000000);
}
# minutes
my $elapsedMinutes = 0;
-while($remainingTimeInSecs - 60 > 0){
+while($remainingTimeInNsecs - (60 * 1000000000) > 0){
$elapsedMinutes++;
- $remainingTimeInSecs = $remainingTimeInSecs - 60;
+ $remainingTimeInNsecs = $remainingTimeInNsecs - (60 * 1000000000);
}
# seconds
-my $elapsedSeconds = $remainingTimeInSecs;
+my $elapsedSeconds = $remainingTimeInNsecs / 1000000000;
#####################################
# #
@@ -784,7 +794,7 @@ if ($allOps ne "0"){
print "Overall Performance: No Operations to evaluate\n\n";
}
-if ($totalTimeInSecs == 0){
+if ($totalTimeInNsecs == 0){
$searchStat = sprintf "(%.2f/sec) (%.2f/min)\n","0",
"0";
$modStat = sprintf "(%.2f/sec) (%.2f/min)\n","0", "0";
$addStat = sprintf "(%.2f/sec) (%.2f/min)\n","0", "0";
@@ -1697,15 +1707,15 @@ parseLineBind {
if($firstFile == 1 && $_ =~ /^\[/){
$start = $_;
- if ($start =~ / *([0-9a-z:\/]+)/i){$start=$1;}
+ if ($start =~ / *([0-9a-z:\/\.]+)/i){$start=$1;}
$firstFile = 0;
}
- if ($endFlag != 1 && $_ =~ /^\[/ && $_ =~ / *([0-9a-z:\/]+)/i){
+ if ($endFlag != 1 && $_ =~ /^\[/ && $_ =~ / *([0-9a-z:\/\.]+)/i){
$end =$1;
}
if ($startTime && !$startFlag) {
- my $currentTimeInSecs = convertTimeToSeconds($_);
- if ($currentTimeInSecs >= $startTimeInSecs) {
+ my $currentTimeInNsecs = convertTimeToNanoseconds($_);
+ if ($currentTimeInNsecs >= $startTimeInNsecs) {
$startFlag = 1;
($start) = $startTime =~ /\D*(\S*)/;
} else {
@@ -1713,8 +1723,8 @@ parseLineBind {
}
}
if ($endTime && !$endFlag) {
- my $currentTimeInSecs = convertTimeToSeconds($_);
- if ($currentTimeInSecs > $endTimeInSecs) {
+ my $currentTimeInNsecs = convertTimeToNanoseconds($_);
+ if ($currentTimeInNsecs > $endTimeInNsecs) {
$endFlag = 1;
($end) = $endTime =~ /\D*(\S*)/;
}
@@ -1867,15 +1877,15 @@ sub parseLineNormal
if($firstFile == 1 && $_ =~ /^\[/){
# if we are using startTime & endTime, this will get overwritten, which is ok
$start = $_;
- if ($start =~ / *([0-9a-z:\/]+)/i){$start=$1;}
+ if ($start =~ / *([0-9a-z:\/\.]+)/i){$start=$1;}
$firstFile = 0;
}
- if ($endFlag != 1 && $_ =~ /^\[/ && $_ =~ / *([0-9a-z:\/]+)/i){
+ if ($endFlag != 1 && $_ =~ /^\[/ && $_ =~ / *([0-9a-z:\/\.]+)/i){
$end =$1;
}
if ($startTime && !$startFlag) {
- my $currentTimeInSecs = convertTimeToSeconds($_);
- if ($currentTimeInSecs >= $startTimeInSecs) {
+ my $currentTimeInNsecs = convertTimeToNanoseconds($_);
+ if ($currentTimeInNsecs >= $startTimeInNsecs) {
$startFlag = 1;
($start) = $startTime =~ /\D*(\S*)/;
} else {
@@ -1883,8 +1893,8 @@ sub parseLineNormal
}
}
if ($endTime && !$endFlag) {
- my $currentTimeInSecs = convertTimeToSeconds($_);
- if ($currentTimeInSecs > $endTimeInSecs) {
+ my $currentTimeInNsecs = convertTimeToNanoseconds($_);
+ if ($currentTimeInNsecs > $endTimeInNsecs) {
$endFlag = 1;
($end) = $endTime =~ /\D*(\S*)/;
}
diff --git a/ldap/schema/01core389.ldif b/ldap/schema/01core389.ldif
index 0b14c06..5628e99 100644
--- a/ldap/schema/01core389.ldif
+++ b/ldap/schema/01core389.ldif
@@ -292,6 +292,7 @@ attributeTypes: ( 2.16.840.1.113730.3.1.2326 NAME
'nsslapd-auditfaillog-logging-
attributeTypes: ( 2.16.840.1.113730.3.1.2327 NAME 'nsslapd-auditfaillog' DESC
'Netscape defined attribute type' SYNTAX 1.3.6.1.4.1.1466.115.121.1.15
SINGLE-VALUE X-ORIGIN 'Netscape Directory Server' )
attributeTypes: ( 2.16.840.1.113730.3.1.2328 NAME 'nsslapd-auditfaillog-list'
DESC 'Netscape defined attribute type' SYNTAX 1.3.6.1.4.1.1466.115.121.1.15
X-ORIGIN 'Netscape Directory Server' )
attributeTypes: ( 2.16.840.1.113730.3.1.2330 NAME 'nsslapd-logging-backend' DESC
'Netscape defined attribute type' SYNTAX 1.3.6.1.4.1.1466.115.121.1.15 X-ORIGIN
'Netscape Directory Server' )
+attributeTypes: ( 2.16.840.1.113730.3.1.2331 NAME
'nsslapd-logging-hr-timestamps-enabled' DESC 'Netscape defined attribute
type' SYNTAX 1.3.6.1.4.1.1466.115.121.1.15 X-ORIGIN 'Netscape Directory
Server' )
#
# objectclasses
#
diff --git a/ldap/servers/slapd/libglobs.c b/ldap/servers/slapd/libglobs.c
index 51fd2b4..33f2f92 100644
--- a/ldap/servers/slapd/libglobs.c
+++ b/ldap/servers/slapd/libglobs.c
@@ -183,6 +183,7 @@ slapi_onoff_t init_auditlog_logging_enabled;
slapi_onoff_t init_auditlog_logging_hide_unhashed_pw;
slapi_onoff_t init_auditfaillog_logging_enabled;
slapi_onoff_t init_auditfaillog_logging_hide_unhashed_pw;
+slapi_onoff_t init_logging_hr_timestamps;
slapi_onoff_t init_csnlogging;
slapi_onoff_t init_pw_unlock;
slapi_onoff_t init_pw_must_change;
@@ -1190,6 +1191,12 @@ static struct config_get_and_set {
CONFIG_STRING_OR_EMPTY, NULL, NULL/* deletion is not allowed */},
/* End audit fail log configuration */
/* warning: initialization makes pointer from integer without a cast [enabled by
default]. Why do we get this? */
+#ifdef HAVE_CLOCK_GETTIME
+ {CONFIG_LOGGING_HR_TIMESTAMPS, config_set_logging_hr_timestamps,
+ NULL, 0,
+ (void**)&global_slapdFrontendConfig.logging_hr_timestamps,
+ CONFIG_ON_OFF, NULL, &init_logging_hr_timestamps},
+#endif
{CONFIG_LOGGING_BACKEND, NULL,
log_set_backend, 0,
(void**)&global_slapdFrontendConfig.logging_backend,
@@ -1619,6 +1626,11 @@ FrontendConfig_init () {
init_auditfaillog_logging_hide_unhashed_pw =
cfg->auditfaillog_logging_hide_unhashed_pw = LDAP_ON;
+#ifdef HAVE_CLOCK_GETTIME
+ init_logging_hr_timestamps =
+ cfg->logging_hr_timestamps = LDAP_ON;
+#endif
+
init_entryusn_global = cfg->entryusn_global = LDAP_OFF;
cfg->entryusn_import_init = slapi_ch_strdup(ENTRYUSN_IMPORT_INIT);
cfg->allowed_to_delete_attrs = slapi_ch_strdup("passwordadmindn
nsslapd-listenhost nsslapd-securelistenhost nsslapd-defaultnamingcontext");
@@ -1765,6 +1777,24 @@ config_set_auditfaillog_unhashed_pw(const char *attrname, char
*value, char *err
return retVal;
}
+#ifdef HAVE_CLOCK_GETTIME
+int
+config_set_logging_hr_timestamps(const char *attrname, char *value, char *errorbuf, int
apply)
+{
+ slapdFrontendConfig_t *slapdFrontendConfig = getFrontendConfig();
+ int retVal = LDAP_SUCCESS;
+
+ retVal = config_set_onoff ( attrname, value,
&(slapdFrontendConfig->logging_hr_timestamps),
+ errorbuf, apply);
+ if(strcasecmp(value,"on") == 0){
+ log_enable_hr_timestamps();
+ } else {
+ log_disable_hr_timestamps();
+ }
+ return retVal;
+}
+#endif
+
/*
* Utility function called by many of the config_set_XXX() functions.
* Returns a non-zero value if 'value' is NULL and zero if not.
diff --git a/ldap/servers/slapd/log.c b/ldap/servers/slapd/log.c
index 8b22297..80ff53e 100644
--- a/ldap/servers/slapd/log.c
+++ b/ldap/servers/slapd/log.c
@@ -36,9 +36,7 @@ PRUintn logbuf_tsdindex;
struct logbufinfo *logbuf_accum;
static struct logging_opts loginfo;
static int detached=0;
-
-/* used to lock the timestamp info used by vslapd_log_access */
-static PRLock *ts_time_lock = NULL;
+static int logging_hr_timestamps_enabled = 1;
/*
* Note: the order of the values in the slapi_log_map array must exactly
@@ -188,10 +186,6 @@ void g_log_init(int log_enabled)
{
slapdFrontendConfig_t *slapdFrontendConfig = getFrontendConfig();
- ts_time_lock = PR_NewLock();
- if (! ts_time_lock)
- exit(-1);
-
/* ACCESS LOG */
loginfo.log_access_state = 0;
loginfo.log_access_mode = SLAPD_DEFAULT_FILE_MODE;
@@ -1812,6 +1806,24 @@ log_set_expirationtimeunit(const char *attrname, char *expunit, int
logtype, cha
return rv;
}
+/*
+ * Enables HR timestamps in logs.
+ */
+void
+log_enable_hr_timestamps()
+{
+ logging_hr_timestamps_enabled = 1;
+}
+
+/*
+ * Disables HR timestamps in logs.
+ */
+void
+log_disable_hr_timestamps()
+{
+ logging_hr_timestamps_enabled = 0;
+}
+
/******************************************************************************
* Write title line in log file
*****************************************************************************/
@@ -2172,41 +2184,46 @@ slapd_log_error_proc_internal(
static void
vslapd_log_emergency_error(LOGFD fp, const char *msg, int locked)
{
- time_t tnl;
- long tz;
- struct tm *tmsp, tms;
char tbuf[ TBUFSIZE ];
char buffer[SLAPI_LOG_BUFSIZ];
- char sign;
- int size;
-
- tnl = current_time();
- (void)localtime_r( &tnl, &tms );
- tmsp = &tms;
-#ifdef BSD_TIME
- tz = tmsp->tm_gmtoff;
-#else /* BSD_TIME */
- tz = - timezone;
- if ( tmsp->tm_isdst ) {
- tz += 3600;
- }
-#endif /* BSD_TIME */
- sign = ( tz >= 0 ? '+' : '-' );
- if ( tz < 0 ) {
- tz = -tz;
+ int size = TBUFSIZE;
+
+#ifdef HAVE_CLOCK_GETTIME
+ if (logging_hr_timestamps_enabled == 1) {
+ struct timespec tsnow;
+ if (clock_gettime(CLOCK_REALTIME, &tsnow) != 0) {
+ syslog(LOG_CRIT, "CRITICAL: vslapd_log_emergency_error, Unable to
determine system time for message :: %s", msg);
+ return;
+ }
+ if (format_localTime_hr_log(tsnow.tv_sec, tsnow.tv_nsec, sizeof(tbuf), tbuf,
&size) != 0) {
+ syslog(LOG_CRIT, "CRITICAL: vslapd_log_emergency_error, Unable to format
system time for message :: %s", msg);
+ return;
+ }
+ } else {
+#endif
+ time_t tnl;
+ tnl = current_time();
+ if (format_localTime_log(tnl, sizeof(tbuf), tbuf, &size) != 0) {
+ syslog(LOG_CRIT, "CRITICAL: vslapd_log_emergency_error, Unable to format
system time for message :: %s", msg);
+ return;
+ }
+#ifdef HAVE_CLOCK_GETTIME
}
- (void)strftime( tbuf, (size_t)TBUFSIZE, "%d/%b/%Y:%H:%M:%S", tmsp);
- sprintf( buffer, "[%s %c%02d%02d] - %s", tbuf, sign, (int)( tz / 3600 ),
(int)( tz % 3600 ), msg);
+#endif
+
+ PR_snprintf( buffer, sizeof(buffer), "%s - %s", tbuf, msg);
size = strlen(buffer);
- if(!locked)
+ if(!locked) {
LOG_ERROR_LOCK_WRITE();
+ }
slapi_write_buffer((fp), (buffer), (size));
PR_Sync(fp);
- if(!locked)
+ if(!locked) {
LOG_ERROR_UNLOCK_WRITE();
+ }
}
static int
@@ -2217,37 +2234,43 @@ vslapd_log_error(
va_list ap,
int locked )
{
- time_t tnl;
- long tz;
- struct tm *tmsp, tms;
- char tbuf[ TBUFSIZE ];
- char sign;
char buffer[SLAPI_LOG_BUFSIZ];
- int blen;
+ int blen = TBUFSIZE;
char *vbuf;
int header_len = 0;
int err = 0;
- tnl = current_time();
- (void)localtime_r( &tnl, &tms );
- tmsp = &tms;
-#ifdef BSD_TIME
- tz = tmsp->tm_gmtoff;
-#else /* BSD_TIME */
- tz = - timezone;
- if ( tmsp->tm_isdst ) {
- tz += 3600;
+ if ((vbuf = PR_vsmprintf(fmt, ap)) == NULL) {
+ log__error_emergency("CRITICAL: vslapd_log_error, Unable to format
message", 1 , locked);
+ return -1;
}
-#endif /* BSD_TIME */
- sign = ( tz >= 0 ? '+' : '-' );
- if ( tz < 0 ) {
- tz = -tz;
+
+#ifdef HAVE_CLOCK_GETTIME
+ if (logging_hr_timestamps_enabled == 1) {
+ struct timespec tsnow;
+ if (clock_gettime(CLOCK_REALTIME, &tsnow) != 0) {
+ PR_snprintf(buffer, sizeof(buffer), "CRITICAL: vslapd_log_error, Unable
to determine system time for message :: %s", vbuf);
+ log__error_emergency(buffer, 1 ,locked);
+ return -1;
+ }
+ if (format_localTime_hr_log(tsnow.tv_sec, tsnow.tv_nsec, sizeof(buffer), buffer,
&blen) != 0) {
+ /* MSG may be truncated */
+ PR_snprintf(buffer, sizeof(buffer), "CRITICAL: vslapd_log_error, Unable
to format system time for message :: %s", vbuf);
+ log__error_emergency(buffer, 1 ,locked);
+ return -1;
+ }
+ } else {
+#endif
+ time_t tnl;
+ tnl = current_time();
+ if (format_localTime_log(tnl, sizeof(buffer), buffer, &blen) != 0) {
+ PR_snprintf(buffer, sizeof(buffer), "CRITICAL: vslapd_log_error, Unable
to format system time for message :: %s", vbuf);
+ log__error_emergency(buffer, 1 ,locked);
+ return -1;
+ }
+#ifdef HAVE_CLOCK_GETTIME
}
- (void)strftime( tbuf, (size_t)TBUFSIZE, "%d/%b/%Y:%H:%M:%S", tmsp);
- sprintf( buffer, "[%s %c%02d%02d]%s%s - ", tbuf, sign,
- (int)( tz / 3600 ), (int)( tz % 3600 ),
- subsystem ? " " : "",
- subsystem ? subsystem : "");
+#endif
/* Bug 561525: to be able to remove timestamp to not over pollute syslog, we may
need
to skip the timestamp part of the message.
@@ -2261,12 +2284,11 @@ vslapd_log_error(
+ size of ]
*/
- header_len = strlen(tbuf) + 8;
+ /* Due to the change to use format_localTime_log, this is now blen */
+ header_len = blen;
- if ((vbuf = PR_vsmprintf(fmt, ap)) == NULL) {
- return -1;
- }
- blen = strlen(buffer);
+ /* blen = strlen(buffer); */
+ /* This truncates again .... But we have the nice smprintf above! */
PR_snprintf (buffer+blen, sizeof(buffer)-blen, "%s", vbuf);
buffer[sizeof(buffer)-1] = '\0';
@@ -2387,61 +2409,52 @@ slapi_is_loglevel_set ( const int loglevel )
******************************************************************************/
static int vslapd_log_access(char *fmt, va_list ap)
{
- time_t tnl;
- long tz;
- struct tm *tmsp, tms;
- char tbuf[ TBUFSIZE ];
- char sign;
char buffer[SLAPI_LOG_BUFSIZ];
char vbuf[SLAPI_LOG_BUFSIZ];
- int blen;
+ int blen = TBUFSIZE;
int vlen;
- /* info needed to keep us from calling localtime/strftime so often: */
- static time_t old_time = 0;
- static char old_tbuf[SLAPI_LOG_BUFSIZ];
- static int old_blen = 0;
-
- tnl = current_time();
-
- /* check if we can use the old strftime buffer */
- PR_Lock(ts_time_lock);
- if (tnl == old_time) {
- strcpy(buffer, old_tbuf);
- blen = old_blen;
- PR_Unlock(ts_time_lock);
- } else {
- /* nope... painstakingly create the new strftime buffer */
- (void)localtime_r( &tnl, &tms );
- tmsp = &tms;
-
-#ifdef BSD_TIME
- tz = tmsp->tm_gmtoff;
-#else /* BSD_TIME */
- tz = - timezone;
- if ( tmsp->tm_isdst ) {
- tz += 3600;
- }
-#endif /* BSD_TIME */
- sign = ( tz >= 0 ? '+' : '-' );
- if ( tz < 0 ) {
- tz = -tz;
- }
- (void)strftime( tbuf, (size_t)TBUFSIZE, "%d/%b/%Y:%H:%M:%S", tmsp);
- sprintf( buffer, "[%s %c%02d%02d] ", tbuf, sign,
- (int)( tz / 3600 ), (int)( tz % 3600));
- old_time = tnl;
- strcpy(old_tbuf, buffer);
- blen = strlen(buffer);
- old_blen = blen;
- PR_Unlock(ts_time_lock);
- }
+ time_t tnl;
+ /* We do this sooner, because that we we can use the message in other calls */
vlen = PR_vsnprintf(vbuf, SLAPI_LOG_BUFSIZ, fmt, ap);
if (! vlen) {
+ log__error_emergency("CRITICAL: vslapd_log_access, Unable to format
message", 1 ,0);
return -1;
}
-
+
+#ifdef HAVE_CLOCK_GETTIME
+ if (logging_hr_timestamps_enabled == 1) {
+ struct timespec tsnow;
+ if (clock_gettime(CLOCK_REALTIME, &tsnow) != 0) {
+ /* Make an error */
+ PR_snprintf(buffer, sizeof(buffer), "CRITICAL: vslapd_log_access, Unable
to determine system time for message :: %s", vbuf);
+ log__error_emergency(buffer, 1 ,0);
+ return -1;
+ }
+ tnl = tsnow.tv_sec;
+ if (format_localTime_hr_log(tsnow.tv_sec, tsnow.tv_nsec, sizeof(buffer), buffer,
&blen) != 0) {
+ /* MSG may be truncated */
+ PR_snprintf(buffer, sizeof(buffer), "CRITICAL: vslapd_log_access, Unable
to format system time for message :: %s", vbuf);
+ log__error_emergency(buffer, 1 ,0);
+ return -1;
+ }
+ } else {
+#endif
+ tnl = current_time();
+ if (format_localTime_log(tnl, sizeof(buffer), buffer, &blen) != 0) {
+ /* MSG may be truncated */
+ PR_snprintf(buffer, sizeof(buffer), "CRITICAL: vslapd_log_access, Unable
to format system time for message :: %s", vbuf);
+ log__error_emergency(buffer, 1 ,0);
+ return -1;
+ }
+#ifdef HAVE_CLOCK_GETTIME
+ }
+#endif
+
if (SLAPI_LOG_BUFSIZ - blen < vlen) {
+ /* We won't be able to fit the message in! Uh-oh! */
+ /* Should we actually just do the snprintf, and warn that message was trunced?
*/
+ log__error_emergency("Insufficent buffer capacity to fit timestamp and
message!", 1 ,0);
return -1;
}
diff --git a/ldap/servers/slapd/proto-slap.h b/ldap/servers/slapd/proto-slap.h
index 8a0bdd3..ff5a7fd 100644
--- a/ldap/servers/slapd/proto-slap.h
+++ b/ldap/servers/slapd/proto-slap.h
@@ -401,6 +401,12 @@ int config_set_maxsimplepaged_per_conn( const char *attrname, char
*value, char
int log_set_backend(const char *attrname, char *value, int logtype, char *errorbuf, int
apply);
+#ifdef HAVE_CLOCK_GETTIME
+int config_set_logging_hr_timestamps(const char *attrname, char *value, char *errorbuf,
int apply);
+void log_enable_hr_timestamps();
+void log_disable_hr_timestamps();
+#endif
+
int config_get_SSLclientAuth();
int config_get_ssl_check_hostname();
char *config_get_SSL3ciphers();
@@ -1151,6 +1157,8 @@ void free_timestring(char *timestr);
time_t current_time();
time_t poll_current_time();
char* format_localTime (time_t from);
+int format_localTime_log(time_t t, int initsize, char *buf, int *bufsize);
+int format_localTime_hr_log(time_t t, long nsec, int initsize, char *buf, int *bufsize);
time_t parse_localTime (char* from);
#ifndef HAVE_TIME_R
diff --git a/ldap/servers/slapd/slap.h b/ldap/servers/slapd/slap.h
index 5bb9252..4d392b0 100644
--- a/ldap/servers/slapd/slap.h
+++ b/ldap/servers/slapd/slap.h
@@ -2124,6 +2124,10 @@ typedef struct _slapdEntryPoints {
#define CONFIG_MAXSIMPLEPAGED_PER_CONN_ATTRIBUTE
"nsslapd-maxsimplepaged-per-conn"
#define CONFIG_LOGGING_BACKEND "nsslapd-logging-backend"
+#ifdef HAVE_CLOCK_GETTIME
+#define CONFIG_LOGGING_HR_TIMESTAMPS "nsslapd-logging-hr-timestamps-enabled"
+#endif
+
/* getenv alternative */
#define CONFIG_MALLOC_MXFAST "nsslapd-malloc-mxfast"
#define CONFIG_MALLOC_TRIM_THRESHOLD "nsslapd-malloc-trim-threshold"
@@ -2319,6 +2323,9 @@ typedef struct _slapdFrontendConfig {
slapi_onoff_t auditfaillog_logging_hide_unhashed_pw;
char *logging_backend;
+#ifdef HAVE_CLOCK_GETTIME
+ slapi_onoff_t logging_hr_timestamps;
+#endif
slapi_onoff_t return_exact_case; /* Return attribute names with the same case
as they appear in at.conf */
diff --git a/ldap/servers/slapd/time.c b/ldap/servers/slapd/time.c
index 15d8fcf..d98b94b 100644
--- a/ldap/servers/slapd/time.c
+++ b/ldap/servers/slapd/time.c
@@ -166,6 +166,110 @@ time_plus_sec (time_t l, long r)
return mktime_r (&t);
}
+
+/*
+ * format_localTime_log will take a time value, and prepare it for
+ * log printing.
+ *
+ * \param time_t t - the time to convert
+ * \param int initsize - the initial buffer size
+ * \param char *buf - The destitation string
+ * \param int *bufsize - The size of the resulting buffer
+ *
+ * \return int success - 0 on correct format, >= 1 on error.
+ */
+int
+format_localTime_log(time_t t, int initsize, char *buf, int *bufsize)
+{
+
+ long tz;
+ struct tm *tmsp, tms;
+ char tbuf[ *bufsize ];
+ char sign;
+ /* make sure our buffer will be big enough. Need at least 29 */
+ if (*bufsize < 29) {
+ return 1;
+ }
+ /* nope... painstakingly create the new strftime buffer */
+ (void)localtime_r( &t, &tms );
+ tmsp = &tms;
+
+#ifdef BSD_TIME
+ tz = tmsp->tm_gmtoff;
+#else /* BSD_TIME */
+ tz = - timezone;
+ if ( tmsp->tm_isdst ) {
+ tz += 3600;
+ }
+#endif /* BSD_TIME */
+ sign = ( tz >= 0 ? '+' : '-' );
+ if ( tz < 0 ) {
+ tz = -tz;
+ }
+ if (strftime( tbuf, (size_t)*bufsize, "%d/%b/%Y:%H:%M:%S", tmsp) == 0) {
+ return 1;
+ }
+ if (PR_snprintf( buf, *bufsize, "[%s %c%02d%02d] ", tbuf, sign,
+ (int)( tz / 3600 ), (int)( tz % 3600)) == -1) {
+ return 1;
+ }
+ *bufsize = strlen(buf);
+ return 0;
+}
+
+#ifdef HAVE_CLOCK_GETTIME
+/*
+ * format_localTime_hr_log will take a time value, and prepare it for
+ * log printing.
+ *
+ * \param time_t t - the time to convert
+ * \param long nsec - the nanoseconds elapsed in the current second.
+ * \param int initsize - the initial buffer size
+ * \param char *buf - The destitation string
+ * \param int *bufsize - The size of the resulting buffer
+ *
+ * \return int success - 0 on correct format, >= 1 on error.
+ */
+int
+format_localTime_hr_log(time_t t, long nsec, int initsize, char *buf, int *bufsize)
+{
+
+ long tz;
+ struct tm *tmsp, tms;
+ char tbuf[ *bufsize ];
+ char sign;
+ /* make sure our buffer will be big enough. Need at least 39 */
+ if (*bufsize < 39) {
+ /* Should this set the buffer to be something? */
+ return 1;
+ }
+ (void)localtime_r( &t, &tms );
+ tmsp = &tms;
+
+#ifdef BSD_TIME
+ tz = tmsp->tm_gmtoff;
+#else /* BSD_TIME */
+ tz = - timezone;
+ if ( tmsp->tm_isdst ) {
+ tz += 3600;
+ }
+#endif /* BSD_TIME */
+ sign = ( tz >= 0 ? '+' : '-' );
+ if ( tz < 0 ) {
+ tz = -tz;
+ }
+ if (strftime( tbuf, (size_t)*bufsize, "%d/%b/%Y:%H:%M:%S", tmsp) == 0) {
+ return 1;
+ }
+ if (PR_snprintf( buf, *bufsize, "[%s.%09ld %c%02d%02d] ", tbuf, nsec,
sign,
+ (int)( tz / 3600 ), (int)( tz % 3600)) == -1) {
+ return 1;
+ }
+ *bufsize = strlen(buf);
+ return 0;
+}
+#endif /* HAVE_CLOCK_GETTIME */
+
char*
format_localTime (time_t from)
/* return a newly-allocated string containing the given time, expressed