rpms/389-ds-base
1
0
Fork 0
mirror of https://git.centos.org/rpms/389-ds-base.git synced 2025-02-24 08:42:57 +00:00
Code Issues Projects Releases Packages Wiki Activity Actions

import 389-ds-base-1.3.10.2-12.el7_9

Browse source
This commit is contained in:
CentOS Sources 2021-06-08 14:05:00 -04:00
parent ed98564350
commit d4e26e25fa
7 changed files with 2347 additions and 3 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

656
SOURCES/0020-Issue-51165-add-new-access-log-keywords-for-wtime-an.patch Normal file
View file

@ -0,0 +1,656 @@
From 5a0200975775f7bfbd51e1469e5560915800f791 Mon Sep 17 00:00:00 2001
From: Mark Reynolds <mreynolds@redhat.com>
Date: Tue, 23 Jun 2020 16:38:55 -0400
Subject: [PATCH] Issue 51165 - add new access log keywords for wtime and
optime
Description: In addition to the "etime" stat in the access we can also
add the time the operation spent in the work queue, and
how long the actual operation took. We now have "wtime"
and "optime" to track these stats in the access log.
Also updated logconf for notes=F (related to a different
ticket), and stats for wtime and optime.
relates: https://pagure.io/389-ds-base/issue/51165
Reviewed by: ?
---
ldap/admin/src/logconv.pl | 187 +++++++++++++++++++++++++++---
ldap/servers/slapd/add.c | 3 +
ldap/servers/slapd/bind.c | 4 +
ldap/servers/slapd/delete.c | 3 +
ldap/servers/slapd/modify.c | 3 +
ldap/servers/slapd/modrdn.c | 3 +
ldap/servers/slapd/operation.c | 24 ++++
ldap/servers/slapd/opshared.c | 3 +
ldap/servers/slapd/result.c | 50 ++++----
ldap/servers/slapd/slap.h | 13 ++-
ldap/servers/slapd/slapi-plugin.h | 26 ++++-
11 files changed, 270 insertions(+), 49 deletions(-)
diff --git a/ldap/admin/src/logconv.pl b/ldap/admin/src/logconv.pl
index e36386e11..250e9f9d4 100755
--- a/ldap/admin/src/logconv.pl
+++ b/ldap/admin/src/logconv.pl
@@ -3,7 +3,7 @@
#
# BEGIN COPYRIGHT BLOCK
# Copyright (C) 2001 Sun Microsystems, Inc. Used by permission.
-# Copyright (C) 2013 Red Hat, Inc.
+# Copyright (C) 2020 Red Hat, Inc.
# All rights reserved.
#
# License: GPL (version 3 or any later version).
@@ -55,7 +55,7 @@ my $reportStats = "";
my $dataLocation = "/tmp";
my $startTLSoid = "1.3.6.1.4.1.1466.20037";
my @statnames=qw(last last_str results srch add mod modrdn moddn cmp del abandon
- conns sslconns bind anonbind unbind notesA notesU etime);
+ conns sslconns bind anonbind unbind notesA notesU notesF etime);
my $s_stats;
my $m_stats;
my $verb = "no";
@@ -211,6 +211,7 @@ my $sslClientBindCount = 0;
my $sslClientFailedCount = 0;
my $objectclassTopCount= 0;
my $pagedSearchCount = 0;
+my $invalidFilterCount = 0;
my $bindCount = 0;
my $filterCount = 0;
my $baseCount = 0;
@@ -258,7 +259,7 @@ map {$conn{$_} = $_} @conncodes;
# hash db-backed hashes
my @hashnames = qw(attr rc src rsrc excount conn_hash ip_hash conncount nentries
filter base ds6xbadpwd saslmech saslconnop bindlist etime oid
- start_time_of_connection end_time_of_connection
+ start_time_of_connection end_time_of_connection notesf_conn_op
notesa_conn_op notesu_conn_op etime_conn_op nentries_conn_op
optype_conn_op time_conn_op srch_conn_op del_conn_op mod_conn_op
mdn_conn_op cmp_conn_op bind_conn_op unbind_conn_op ext_conn_op
@@ -926,7 +927,7 @@ if ($verb eq "yes" || $usage =~ /u/ || $usage =~ /U/){
}
while($op > 0){
# The bind op is not the same as the search op that triggered the notes=A.
- # We have adjust the key by decrementing the op count until we find the last bind op.
+ # We have to adjust the key by decrementing the op count until we find the last bind op.
$op--;
$binddn_key = "$srvRstCnt,$conn,$op";
if (exists($bind_conn_op->{$binddn_key}) && defined($bind_conn_op->{$binddn_key})) {
@@ -1049,9 +1050,60 @@ if ($verb eq "yes" || $usage =~ /u/ || $usage =~ /U/){
}
}
}
-} # end of unindexed search report
+ print "\n";
+}
+
+print "Invalid Attribute Filters: $invalidFilterCount\n";
+if ($invalidFilterCount > 0 && $verb eq "yes"){
+ my $conn_hash = $hashes->{conn_hash};
+ my $notesf_conn_op = $hashes->{notesf_conn_op};
+ my $time_conn_op = $hashes->{time_conn_op};
+ my $etime_conn_op = $hashes->{etime_conn_op};
+ my $nentries_conn_op = $hashes->{nentries_conn_op};
+ my $filter_conn_op = $hashes->{filter_conn_op};
+ my $bind_conn_op = $hashes->{bind_conn_op};
+ my $notesCount = 1;
+ my $unindexedIp;
+ my $binddn_key;
+ my %uniqFilt = (); # hash of unique filters
+ my %uniqFilter = (); # hash of unique filters bind dn
+ my %uniqBindDNs = (); # hash of unique bind dn's
+ my %uniqBindFilters = (); # hash of filters for a bind DN
+
+ while (my ($srcnt_conn_op, $count) = each %{$notesf_conn_op}) {
+ my ($srvRstCnt, $conn, $op) = split(",", $srcnt_conn_op);
+ my $attrIp = getIPfromConn($conn, $srvRstCnt);
+ print "\n Invalid Attribute Filter #".$notesCount." (notes=F)\n";
+ print " - Date/Time: $time_conn_op->{$srcnt_conn_op}\n";
+ print " - Connection Number: $conn\n";
+ print " - Operation Number: $op\n";
+ print " - Etime: $etime_conn_op->{$srcnt_conn_op}\n";
+ print " - Nentries: $nentries_conn_op->{$srcnt_conn_op}\n";
+ print " - IP Address: $attrIp\n";
+ if (exists($filter_conn_op->{$srcnt_conn_op}) && defined($filter_conn_op->{$srcnt_conn_op})) {
+ print " - Search Filter: $filter_conn_op->{$srcnt_conn_op}\n";
+ $uniqFilt{$filter_conn_op->{$srcnt_conn_op}}++;
+ }
+ while($op > 0){
+ # The bind op is not the same as the search op that triggered the notes=A.
+ # We have to adjust the key by decrementing the op count until we find the last bind op.
+ $op--;
+ $binddn_key = "$srvRstCnt,$conn,$op";
+ if (exists($bind_conn_op->{$binddn_key}) && defined($bind_conn_op->{$binddn_key})) {
+ print " - Bind DN: $bind_conn_op->{$binddn_key}\n";
+ $uniqBindDNs{$bind_conn_op->{$binddn_key}}++;
+ if( $uniqFilt{$filter_conn_op->{$srcnt_conn_op}} && defined($filter_conn_op->{$srcnt_conn_op})) {
+ $uniqBindFilters{$bind_conn_op->{$binddn_key}}{$filter_conn_op->{$srcnt_conn_op}}++;
+ $uniqFilter{$filter_conn_op->{$srcnt_conn_op}}{$bind_conn_op->{$binddn_key}}++;
+ }
+ last;
+ }
+ }
+ $notesCount++;
+ }
+ print "\n";
+}
-print "\n";
print "FDs Taken: $fdTaken\n";
print "FDs Returned: $fdReturned\n";
print "Highest FD Taken: $highestFdTaken\n\n";
@@ -1386,20 +1438,20 @@ if ($usage =~ /l/ || $verb eq "yes"){
}
}
-#########################################
-# #
-# Gather and Process the unique etimes #
-# #
-#########################################
+##############################################################
+# #
+# Gather and Process the unique etimes, wtimes, and optimes #
+# #
+##############################################################
my $first;
if ($usage =~ /t/i || $verb eq "yes"){
+ # Print the elapsed times (etime)
+
my $etime = $hashes->{etime};
my @ekeys = keys %{$etime};
- #
# print most often etimes
- #
- print "\n\n----- Top $sizeCount Most Frequent etimes -----\n\n";
+ print "\n\n----- Top $sizeCount Most Frequent etimes (elapsed times) -----\n\n";
my $eloop = 0;
my $retime = 0;
foreach my $et (sort { $etime->{$b} <=> $etime->{$a} } @ekeys) {
@@ -1411,16 +1463,84 @@ if ($usage =~ /t/i || $verb eq "yes"){
printf "%-8s %-12s\n", $etime->{ $et }, "etime=$et";
$eloop++;
}
- #
+ if ($eloop == 0) {
+ print "None";
+ }
# print longest etimes
- #
- print "\n\n----- Top $sizeCount Longest etimes -----\n\n";
+ print "\n\n----- Top $sizeCount Longest etimes (elapsed times) -----\n\n";
$eloop = 0;
foreach my $et (sort { $b <=> $a } @ekeys) {
if ($eloop == $sizeCount) { last; }
printf "%-12s %-10s\n","etime=$et",$etime->{ $et };
$eloop++;
}
+ if ($eloop == 0) {
+ print "None";
+ }
+
+ # Print the wait times (wtime)
+
+ my $wtime = $hashes->{wtime};
+ my @wkeys = keys %{$wtime};
+ # print most often wtimes
+ print "\n\n----- Top $sizeCount Most Frequent wtimes (wait times) -----\n\n";
+ $eloop = 0;
+ $retime = 0;
+ foreach my $et (sort { $wtime->{$b} <=> $wtime->{$a} } @wkeys) {
+ if ($eloop == $sizeCount) { last; }
+ if ($retime ne "2"){
+ $first = $et;
+ $retime = "2";
+ }
+ printf "%-8s %-12s\n", $wtime->{ $et }, "wtime=$et";
+ $eloop++;
+ }
+ if ($eloop == 0) {
+ print "None";
+ }
+ # print longest wtimes
+ print "\n\n----- Top $sizeCount Longest wtimes (wait times) -----\n\n";
+ $eloop = 0;
+ foreach my $et (sort { $b <=> $a } @wkeys) {
+ if ($eloop == $sizeCount) { last; }
+ printf "%-12s %-10s\n","wtime=$et",$wtime->{ $et };
+ $eloop++;
+ }
+ if ($eloop == 0) {
+ print "None";
+ }
+
+ # Print the operation times (optime)
+
+ my $optime = $hashes->{optime};
+ my @opkeys = keys %{$optime};
+ # print most often optimes
+ print "\n\n----- Top $sizeCount Most Frequent optimes (actual operation times) -----\n\n";
+ $eloop = 0;
+ $retime = 0;
+ foreach my $et (sort { $optime->{$b} <=> $optime->{$a} } @opkeys) {
+ if ($eloop == $sizeCount) { last; }
+ if ($retime ne "2"){
+ $first = $et;
+ $retime = "2";
+ }
+ printf "%-8s %-12s\n", $optime->{ $et }, "optime=$et";
+ $eloop++;
+ }
+ if ($eloop == 0) {
+ print "None";
+ }
+ # print longest optimes
+ print "\n\n----- Top $sizeCount Longest optimes (actual operation times) -----\n\n";
+ $eloop = 0;
+ foreach my $et (sort { $b <=> $a } @opkeys) {
+ if ($eloop == $sizeCount) { last; }
+ printf "%-12s %-10s\n","optime=$et",$optime->{ $et };
+ $eloop++;
+ }
+ if ($eloop == 0) {
+ print "None";
+ }
}
#######################################
@@ -2152,6 +2272,26 @@ sub parseLineNormal
if (m/ RESULT err=/ && m/ notes=[A-Z,]*P/){
$pagedSearchCount++;
}
+ if (m/ RESULT err=/ && m/ notes=[A-Z,]*F/){
+ $invalidFilterCount++;
+ $con = "";
+ if ($_ =~ /conn= *([0-9A-Z]+)/i){
+ $con = $1;
+ if ($_ =~ /op= *([0-9\-]+)/i){ $op = $1;}
+ }
+
+ if($reportStats){ inc_stats('notesF',$s_stats,$m_stats); }
+ if ($usage =~ /u/ || $usage =~ /U/ || $verb eq "yes"){
+ if($_ =~ /etime= *([0-9.]+)/i ){
+ if($1 >= $minEtime){
+ $hashes->{etime_conn_op}->{"$serverRestartCount,$con,$op"} = $1;
+ $hashes->{notesf_conn_op}->{"$serverRestartCount,$con,$op"}++;
+ if ($_ =~ / *([0-9a-z:\/]+)/i){ $hashes->{time_conn_op}->{"$serverRestartCount,$con,$op"} = $1; }
+ if ($_ =~ /nentries= *([0-9]+)/i ){ $hashes->{nentries_conn_op}->{"$serverRestartCount,$con,$op"} = $1; }
+ }
+ }
+ }
+ }
if (m/ notes=[A-Z,]*A/){
$con = "";
if ($_ =~ /conn= *([0-9A-Z]+)/i){
@@ -2435,6 +2575,16 @@ sub parseLineNormal
if ($usage =~ /t/i || $verb eq "yes"){ $hashes->{etime}->{$etime_val}++; }
if ($reportStats){ inc_stats_val('etime',$etime_val,$s_stats,$m_stats); }
}
+ if ($_ =~ /wtime= *([0-9.]+)/ ) {
+ my $wtime_val = $1;
+ if ($usage =~ /t/i || $verb eq "yes"){ $hashes->{wtime}->{$wtime_val}++; }
+ if ($reportStats){ inc_stats_val('wtime',$wtime_val,$s_stats,$m_stats); }
+ }
+ if ($_ =~ /optime= *([0-9.]+)/ ) {
+ my $optime_val = $1;
+ if ($usage =~ /t/i || $verb eq "yes"){ $hashes->{optime}->{$optime_val}++; }
+ if ($reportStats){ inc_stats_val('optime',$optime_val,$s_stats,$m_stats); }
+ }
if ($_ =~ / tag=101 / || $_ =~ / tag=111 / || $_ =~ / tag=100 / || $_ =~ / tag=115 /){
if ($_ =~ / nentries= *([0-9]+)/i ){
my $nents = $1;
@@ -2555,7 +2705,7 @@ sub parseLineNormal
}
}
}
- if (/ RESULT err=/ && / tag=97 nentries=0 etime=/ && $_ =~ /dn=\"(.*)\"/i){
+ if (/ RESULT err=/ && / tag=97 nentries=0 / && $_ =~ /dn=\"(.*)\"/i){
# Check if this is a sasl bind, if see we need to add the RESULT's dn as a bind dn
my $binddn = $1;
my ($conn, $op);
@@ -2678,6 +2828,7 @@ print_stats_block
$stats->{'unbind'},
$stats->{'notesA'},
$stats->{'notesU'},
+ $stats->{'notesF'},
$stats->{'etime'}),
"\n" );
} else {
diff --git a/ldap/servers/slapd/add.c b/ldap/servers/slapd/add.c
index 8f2fdeac8..3a8d83899 100644
--- a/ldap/servers/slapd/add.c
+++ b/ldap/servers/slapd/add.c
@@ -440,6 +440,9 @@ op_shared_add(Slapi_PBlock *pb)
internal_op = operation_is_flag_set(operation, OP_FLAG_INTERNAL);
pwpolicy = new_passwdPolicy(pb, slapi_entry_get_dn(e));
+ /* Set the time we actually started the operation */
+ slapi_operation_set_time_started(operation);
+
/* target spec is used to decide which plugins are applicable for the operation */
operation_set_target_spec(operation, slapi_entry_get_sdn(e));
diff --git a/ldap/servers/slapd/bind.c b/ldap/servers/slapd/bind.c
index b3fe27327..0b1540cc3 100644
--- a/ldap/servers/slapd/bind.c
+++ b/ldap/servers/slapd/bind.c
@@ -87,6 +87,10 @@ do_bind(Slapi_PBlock *pb)
send_ldap_result(pb, LDAP_OPERATIONS_ERROR, NULL, NULL, 0, NULL);
goto free_and_return;
}
+
+ /* Set the time we actually started the operation */
+ slapi_operation_set_time_started(pb_op);
+
ber = pb_op->o_ber;
/*
diff --git a/ldap/servers/slapd/delete.c b/ldap/servers/slapd/delete.c
index 49cdab138..8846a4dea 100644
--- a/ldap/servers/slapd/delete.c
+++ b/ldap/servers/slapd/delete.c
@@ -234,6 +234,9 @@ op_shared_delete(Slapi_PBlock *pb)
slapi_pblock_get(pb, SLAPI_OPERATION, &operation);
internal_op = operation_is_flag_set(operation, OP_FLAG_INTERNAL);
+ /* Set the time we actually started the operation */
+ slapi_operation_set_time_started(operation);
+
sdn = slapi_sdn_new_dn_byval(rawdn);
dn = slapi_sdn_get_dn(sdn);
slapi_pblock_set(pb, SLAPI_DELETE_TARGET_SDN, (void *)sdn);
diff --git a/ldap/servers/slapd/modify.c b/ldap/servers/slapd/modify.c
index f2f6d1783..a6894c305 100644
--- a/ldap/servers/slapd/modify.c
+++ b/ldap/servers/slapd/modify.c
@@ -634,6 +634,9 @@ op_shared_modify(Slapi_PBlock *pb, int pw_change, char *old_pw)
slapi_pblock_get(pb, SLAPI_SKIP_MODIFIED_ATTRS, &skip_modified_attrs);
slapi_pblock_get(pb, SLAPI_CONNECTION, &pb_conn);
+ /* Set the time we actually started the operation */
+ slapi_operation_set_time_started(operation);
+
if (sdn) {
passin_sdn = 1;
} else {
diff --git a/ldap/servers/slapd/modrdn.c b/ldap/servers/slapd/modrdn.c
index 9483aafb5..a48ab8859 100644
--- a/ldap/servers/slapd/modrdn.c
+++ b/ldap/servers/slapd/modrdn.c
@@ -415,6 +415,9 @@ op_shared_rename(Slapi_PBlock *pb, int passin_args)
internal_op = operation_is_flag_set(operation, OP_FLAG_INTERNAL);
slapi_pblock_get(pb, SLAPI_CONNECTION, &pb_conn);
+ /* Set the time we actually started the operation */
+ slapi_operation_set_time_started(operation);
+
/*
* If ownership has not been passed to this function, we replace the
* string input fields within the pblock with strdup'd copies. Why?
diff --git a/ldap/servers/slapd/operation.c b/ldap/servers/slapd/operation.c
index 8186fd33b..bc5c692fe 100644
--- a/ldap/servers/slapd/operation.c
+++ b/ldap/servers/slapd/operation.c
@@ -660,3 +660,27 @@ slapi_operation_time_expiry(Slapi_Operation *o, time_t timeout, struct timespec
{
slapi_timespec_expire_rel(timeout, &(o->o_hr_time_rel), expiry);
}
+
+/* Set the time the operation actually started */
+void
+slapi_operation_set_time_started(Slapi_Operation *o)
+{
+ clock_gettime(CLOCK_MONOTONIC, &(o->o_hr_time_started_rel));
+}
+
+/* The time diff of how long the operation took once it actually started */
+void
+slapi_operation_op_time_elapsed(Slapi_Operation *o, struct timespec *elapsed)
+{
+ struct timespec o_hr_time_now;
+ clock_gettime(CLOCK_MONOTONIC, &o_hr_time_now);
+
+ slapi_timespec_diff(&o_hr_time_now, &(o->o_hr_time_started_rel), elapsed);
+}
+
+/* The time diff the operation waited in the work queue */
+void
+slapi_operation_workq_time_elapsed(Slapi_Operation *o, struct timespec *elapsed)
+{
+ slapi_timespec_diff(&(o->o_hr_time_started_rel), &(o->o_hr_time_rel), elapsed);
+}
diff --git a/ldap/servers/slapd/opshared.c b/ldap/servers/slapd/opshared.c
index b9fc83516..2afb8e2fc 100644
--- a/ldap/servers/slapd/opshared.c
+++ b/ldap/servers/slapd/opshared.c
@@ -276,6 +276,9 @@ op_shared_search(Slapi_PBlock *pb, int send_result)
slapi_pblock_get(pb, SLAPI_SEARCH_TARGET_SDN, &sdn);
slapi_pblock_get(pb, SLAPI_OPERATION, &operation);
+ /* Set the time we actually started the operation */
+ slapi_operation_set_time_started(operation);
+
if (NULL == sdn) {
sdn = slapi_sdn_new_dn_byval(base);
slapi_pblock_set(pb, SLAPI_SEARCH_TARGET_SDN, sdn);
diff --git a/ldap/servers/slapd/result.c b/ldap/servers/slapd/result.c
index 61e7a70f9..807f58a2c 100644
--- a/ldap/servers/slapd/result.c
+++ b/ldap/servers/slapd/result.c
@@ -1912,21 +1912,31 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries
int internal_op;
CSN *operationcsn = NULL;
char csn_str[CSN_STRSIZE + 5];
- char etime[ETIME_BUFSIZ];
+ char etime[ETIME_BUFSIZ] = {0};
+ char wtime[ETIME_BUFSIZ] = {0};
+ char optime[ETIME_BUFSIZ] = {0};
int pr_idx = -1;
int pr_cookie = -1;
uint32_t operation_notes;
+ struct timespec o_hr_time_end;
slapi_pblock_get(pb, SLAPI_PAGED_RESULTS_INDEX, &pr_idx);
slapi_pblock_get(pb, SLAPI_PAGED_RESULTS_COOKIE, &pr_cookie);
-
internal_op = operation_is_flag_set(op, OP_FLAG_INTERNAL);
- struct timespec o_hr_time_end;
+ /* total elapsed time */
slapi_operation_time_elapsed(op, &o_hr_time_end);
+ snprintf(etime, ETIME_BUFSIZ, "%" PRId64 ".%.09" PRId64 "", (int64_t)o_hr_time_end.tv_sec, (int64_t)o_hr_time_end.tv_nsec);
+
+ /* wait time */
+ slapi_operation_workq_time_elapsed(op, &o_hr_time_end);
+ snprintf(wtime, ETIME_BUFSIZ, "%" PRId64 ".%.09" PRId64 "", (int64_t)o_hr_time_end.tv_sec, (int64_t)o_hr_time_end.tv_nsec);
+
+ /* op time */
+ slapi_operation_op_time_elapsed(op, &o_hr_time_end);
+ snprintf(optime, ETIME_BUFSIZ, "%" PRId64 ".%.09" PRId64 "", (int64_t)o_hr_time_end.tv_sec, (int64_t)o_hr_time_end.tv_nsec);
- snprintf(etime, ETIME_BUFSIZ, "%" PRId64 ".%.09" PRId64 "", (int64_t)o_hr_time_end.tv_sec, (int64_t)o_hr_time_end.tv_nsec);
slapi_pblock_get(pb, SLAPI_OPERATION_NOTES, &operation_notes);
@@ -1955,22 +1965,22 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries
if (!internal_op) {
slapi_log_access(LDAP_DEBUG_STATS,
"conn=%" PRIu64 " op=%d RESULT err=%d"
- " tag=%" BERTAG_T " nentries=%d etime=%s%s%s"
+ " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%s%s%s"
", SASL bind in progress\n",
op->o_connid,
op->o_opid,
err, tag, nentries,
- etime,
+ wtime, optime, 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"
+ " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%s%s%s"
", SASL bind in progress\n",
LOG_INTERNAL_OP_CON_ID,
LOG_INTERNAL_OP_OP_ID,
err, tag, nentries,
- etime,
+ wtime, optime, etime,
notes_str, csn_str);
}
} else if (op->o_tag == LDAP_REQ_BIND && err == LDAP_SUCCESS) {
@@ -1984,22 +1994,22 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries
if (!internal_op) {
slapi_log_access(LDAP_DEBUG_STATS,
"conn=%" PRIu64 " op=%d RESULT err=%d"
- " tag=%" BERTAG_T " nentries=%d etime=%s%s%s"
+ " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%s%s%s"
" dn=\"%s\"\n",
op->o_connid,
op->o_opid,
err, tag, nentries,
- etime,
+ wtime, optime, 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"
+ " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%s%s%s"
" dn=\"%s\"\n",
LOG_INTERNAL_OP_CON_ID,
LOG_INTERNAL_OP_OP_ID,
err, tag, nentries,
- etime,
+ wtime, optime, etime,
notes_str, csn_str, dn ? dn : "");
}
slapi_ch_free((void **)&dn);
@@ -2008,22 +2018,22 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries
if (!internal_op) {
slapi_log_access(LDAP_DEBUG_STATS,
"conn=%" PRIu64 " op=%d RESULT err=%d"
- " tag=%" BERTAG_T " nentries=%d etime=%s%s%s"
+ " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%s%s%s"
" pr_idx=%d pr_cookie=%d\n",
op->o_connid,
op->o_opid,
err, tag, nentries,
- etime,
+ wtime, optime, etime,
notes_str, csn_str, pr_idx, pr_cookie);
} else {
slapi_log_access(LDAP_DEBUG_ARGS,
"conn=%s op=%d RESULT err=%d"
- " tag=%" BERTAG_T " nentries=%d etime=%s%s%s"
+ " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%s%s%s"
" pr_idx=%d pr_cookie=%d \n",
LOG_INTERNAL_OP_CON_ID,
LOG_INTERNAL_OP_OP_ID,
err, tag, nentries,
- etime,
+ wtime, optime, etime,
notes_str, csn_str, pr_idx, pr_cookie);
}
} else if (!internal_op) {
@@ -2037,11 +2047,11 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries
}
slapi_log_access(LDAP_DEBUG_STATS,
"conn=%" PRIu64 " op=%d RESULT err=%d"
- " tag=%" BERTAG_T " nentries=%d etime=%s%s%s%s\n",
+ " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%s%s%s%s\n",
op->o_connid,
op->o_opid,
err, tag, nentries,
- etime,
+ wtime, optime, etime,
notes_str, csn_str, ext_str);
if (pbtxt) {
/* if !pbtxt ==> ext_str == "". Don't free ext_str. */
@@ -2051,11 +2061,11 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries
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",
+ " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%s%s%s\n",
LOG_INTERNAL_OP_CON_ID,
LOG_INTERNAL_OP_OP_ID,
err, tag, nentries,
- etime,
+ wtime, optime, etime,
notes_str, csn_str);
/*
* If this is an unindexed search we should log it in the error log if
diff --git a/ldap/servers/slapd/slap.h b/ldap/servers/slapd/slap.h
index 1d0a9cbeb..007c50b86 100644
--- a/ldap/servers/slapd/slap.h
+++ b/ldap/servers/slapd/slap.h
@@ -1522,16 +1522,17 @@ typedef struct slapi_operation_results
*/
typedef struct op
{
- BerElement *o_ber; /* ber of the request */
- ber_int_t o_msgid; /* msgid of the request */
- ber_tag_t o_tag; /* tag of the request */
+ BerElement *o_ber; /* ber of the request */
+ ber_int_t o_msgid; /* msgid of the request */
+ ber_tag_t o_tag; /* tag of the request */
struct timespec o_hr_time_rel; /* internal system time op initiated */
struct timespec o_hr_time_utc; /* utc system time op initiated */
- int o_isroot; /* requestor is manager */
+ struct timespec o_hr_time_started_rel; /* internal system time op started */
+ int o_isroot; /* requestor is manager */
Slapi_DN o_sdn; /* dn bound when op was initiated */
- char *o_authtype; /* auth method used to bind dn */
+ char *o_authtype; /* auth method used to bind dn */
int o_ssf; /* ssf for this operation (highest between SASL and TLS/SSL) */
- int o_opid; /* id of this operation */
+ int o_opid; /* id of this operation */
PRUint64 o_connid; /* id of conn initiating this op; for logging only */
void *o_handler_data;
result_handler o_result_handler;
diff --git a/ldap/servers/slapd/slapi-plugin.h b/ldap/servers/slapd/slapi-plugin.h
index a8b563dd1..9f7971ec1 100644
--- a/ldap/servers/slapd/slapi-plugin.h
+++ b/ldap/servers/slapd/slapi-plugin.h
@@ -8235,13 +8235,29 @@ void slapi_operation_time_elapsed(Slapi_Operation *o, struct timespec *elapsed);
*/
void slapi_operation_time_initiated(Slapi_Operation *o, struct timespec *initiated);
/**
- * Given an operation and a timeout, return a populate struct with the expiry
- * time of the operation suitable for checking with slapi_timespec_expire_check
+ * Given an operation, determine the time elapsed since the op
+ * was actually started.
*
- * \param Slapi_Operation o - the operation that is in progress
- * \param time_t timeout the seconds relative to operation initiation to expiry at.
- * \param struct timespec *expiry the timespec to popluate with the relative expiry.
+ * \param Slapi_Operation o - the operation which is inprogress
+ * \param struct timespec *elapsed - location where the time difference will be
+ * placed.
+ */
+void slapi_operation_op_time_elapsed(Slapi_Operation *o, struct timespec *elapsed);
+/**
+ * Given an operation, determine the time elapsed that the op spent
+ * in the work queue before actually being dispatched to a worker thread
+ *
+ * \param Slapi_Operation o - the operation which is inprogress
+ * \param struct timespec *elapsed - location where the time difference will be
+ * placed.
+ */
+void slapi_operation_workq_time_elapsed(Slapi_Operation *o, struct timespec *elapsed);
+/**
+ * Set the time the operation actually started
+ *
+ * \param Slapi_Operation o - the operation which is inprogress
*/
+void slapi_operation_set_time_started(Slapi_Operation *o);
#endif
/**
--
2.30.2

276
SOURCES/0021-Issue-51165-add-more-logconv-stats-for-the-new-acces.patch Normal file
View file

@ -0,0 +1,276 @@
From e8691d39f4fb0dc0a4ca12363430feb748984169 Mon Sep 17 00:00:00 2001
From: Mark Reynolds <mreynolds@redhat.com>
Date: Sun, 28 Jun 2020 15:46:59 -0400
Subject: [PATCH] Issue 51165 - add more logconv stats for the new access log
keywords
Description: Add "average" stats for wtime, optime, and etime
relates: https://pagure.io/389-ds-base/issue/51165
Reviewed by: firstyear(Thanks!)
---
ldap/admin/src/logconv.pl | 152 +++++++++++++++++++++-----------------
1 file changed, 86 insertions(+), 66 deletions(-)
diff --git a/ldap/admin/src/logconv.pl b/ldap/admin/src/logconv.pl
index 250e9f9d4..375283085 100755
--- a/ldap/admin/src/logconv.pl
+++ b/ldap/admin/src/logconv.pl
@@ -1,5 +1,4 @@
#!/usr/bin/env perl
-
#
# BEGIN COPYRIGHT BLOCK
# Copyright (C) 2001 Sun Microsystems, Inc. Used by permission.
@@ -249,6 +248,12 @@ my $deleteStat;
my $modrdnStat;
my $compareStat;
my $bindCountStat;
+my $totalEtime = 0.0;
+my $totalWtime = 0.0;
+my $totalOpTime = 0.0;
+my $etimeCount = 0;
+my $wtimeCount = 0;
+my $opTimeCount = 0;
my %cipher = ();
my @removefiles = ();
@@ -807,7 +812,7 @@ if ($totalTimeInNsecs == 0){
#
# Continue with standard report
#
-print "Restarts: $serverRestartCount\n";
+print "Restarts: $serverRestartCount\n";
if(%cipher){
print "Secure Protocol Versions:\n";
@@ -817,42 +822,42 @@ if(%cipher){
print "\n";
}
-print "Peak Concurrent Connections: $maxsimConnection\n";
-print "Total Operations: $allOps\n";
-print "Total Results: $allResults\n";
+print "Peak Concurrent Connections: $maxsimConnection\n";
+print "Total Operations: $allOps\n";
+print "Total Results: $allResults\n";
my ($perf, $tmp);
if ($allOps ne "0"){
- print sprintf "Overall Performance: %.1f%%\n\n" , ($perf = ($tmp = ($allResults / $allOps)*100) > 100 ? 100.0 : $tmp) ;
+ print sprintf "Overall Performance: %.1f%%\n\n" , ($perf = ($tmp = ($allResults / $allOps)*100) > 100 ? 100.0 : $tmp) ;
} else {
- print "Overall Performance: No Operations to evaluate\n\n";
+ print "Overall Performance: No Operations to evaluate\n\n";
}
format STDOUT =
-Total Connections: @<<<<<<<<<<<< @<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
- $connectionCount, $connStat,
- - LDAP Connections: @<<<<<<<<<<<< @<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
- ($connectionCount - $sslCount - $ldapiCount), $ldapConnStat
- - LDAPI Connections: @<<<<<<<<<<<< @<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
- $ldapiCount, $ldapiConnStat
- - LDAPS Connections: @<<<<<<<<<<<< @<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
- $sslCount, $sslConnStat
- - StartTLS Extended Ops: @<<<<<<<<<<<< @<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
- $startTLSCount, $tlsConnStat
-
-Searches: @<<<<<<<<<<<< @<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
- $srchCount, $searchStat,
-Modifications: @<<<<<<<<<<<< @<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
- $modCount, $modStat,
-Adds: @<<<<<<<<<<<< @<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
- $addCount, $addStat,
-Deletes: @<<<<<<<<<<<< @<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
- $delCount, $deleteStat,
-Mod RDNs: @<<<<<<<<<<<< @<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
- $modrdnCount, $modrdnStat,
-Compares: @<<<<<<<<<<<< @<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
- $cmpCount, $compareStat,
-Binds: @<<<<<<<<<<<< @<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
- $bindCount, $bindCountStat,
+Total Connections: @<<<<<<<<<<<< @<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
+ $connectionCount, $connStat,
+ - LDAP Connections: @<<<<<<<<<<<< @<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
+ ($connectionCount - $sslCount - $ldapiCount), $ldapConnStat
+ - LDAPI Connections: @<<<<<<<<<<<< @<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
+ $ldapiCount, $ldapiConnStat
+ - LDAPS Connections: @<<<<<<<<<<<< @<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
+ $sslCount, $sslConnStat
+ - StartTLS Extended Ops: @<<<<<<<<<<<< @<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
+ $startTLSCount, $tlsConnStat
+
+Searches: @<<<<<<<<<<<< @<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
+ $srchCount, $searchStat,
+Modifications: @<<<<<<<<<<<< @<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
+ $modCount, $modStat,
+Adds: @<<<<<<<<<<<< @<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
+ $addCount, $addStat,
+Deletes: @<<<<<<<<<<<< @<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
+ $delCount, $deleteStat,
+Mod RDNs: @<<<<<<<<<<<< @<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
+ $modrdnCount, $modrdnStat,
+Compares: @<<<<<<<<<<<< @<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
+ $cmpCount, $compareStat,
+Binds: @<<<<<<<<<<<< @<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
+ $bindCount, $bindCountStat,
.
write STDOUT;
@@ -863,23 +868,32 @@ sub dummy {
}
print "\n";
-print "Proxied Auth Operations: $proxiedAuthCount\n";
-print "Persistent Searches: $persistentSrchCount\n";
-print "Internal Operations: $internalOpCount\n";
-print "Entry Operations: $entryOpCount\n";
-print "Extended Operations: $extopCount\n";
-print "Abandoned Requests: $abandonCount\n";
-print "Smart Referrals Received: $referralCount\n";
+if ($wtimeCount ne "0") {
+ print sprintf "Average wtime (wait time): %.9f\n", $totalWtime / $wtimeCount;
+}
+if ($opTimeCount ne "0") {
+ print sprintf "Average optime (op time): %.9f\n", $totalOpTime / $opTimeCount;
+}
+print sprintf "Average etime (elapsed time): %.9f\n", $totalEtime / $etimeCount;
+
+print "\n";
+print "Proxied Auth Operations: $proxiedAuthCount\n";
+print "Persistent Searches: $persistentSrchCount\n";
+print "Internal Operations: $internalOpCount\n";
+print "Entry Operations: $entryOpCount\n";
+print "Extended Operations: $extopCount\n";
+print "Abandoned Requests: $abandonCount\n";
+print "Smart Referrals Received: $referralCount\n";
print "\n";
-print "VLV Operations: $vlvCount\n";
-print "VLV Unindexed Searches: $vlvNotesACount\n";
-print "VLV Unindexed Components: $vlvNotesUCount\n";
-print "SORT Operations: $vlvSortCount\n";
+print "VLV Operations: $vlvCount\n";
+print "VLV Unindexed Searches: $vlvNotesACount\n";
+print "VLV Unindexed Components: $vlvNotesUCount\n";
+print "SORT Operations: $vlvSortCount\n";
print "\n";
-print "Entire Search Base Queries: $objectclassTopCount\n";
-print "Paged Searches: $pagedSearchCount\n";
-print "Unindexed Searches: $unindexedSrchCountNotesA\n";
-print "Unindexed Components: $unindexedSrchCountNotesU\n";
+print "Entire Search Base Queries: $objectclassTopCount\n";
+print "Paged Searches: $pagedSearchCount\n";
+print "Unindexed Searches: $unindexedSrchCountNotesA\n";
+print "Unindexed Components: $unindexedSrchCountNotesU\n";
if ($verb eq "yes" || $usage =~ /u/ || $usage =~ /U/){
if ($unindexedSrchCountNotesA > 0){
@@ -1053,7 +1067,7 @@ if ($verb eq "yes" || $usage =~ /u/ || $usage =~ /U/){
print "\n";
}
-print "Invalid Attribute Filters: $invalidFilterCount\n";
+print "Invalid Attribute Filters: $invalidFilterCount\n";
if ($invalidFilterCount > 0 && $verb eq "yes"){
my $conn_hash = $hashes->{conn_hash};
my $notesf_conn_op = $hashes->{notesf_conn_op};
@@ -1104,10 +1118,10 @@ if ($invalidFilterCount > 0 && $verb eq "yes"){
print "\n";
}
-print "FDs Taken: $fdTaken\n";
-print "FDs Returned: $fdReturned\n";
-print "Highest FD Taken: $highestFdTaken\n\n";
-print "Broken Pipes: $brokenPipeCount\n";
+print "FDs Taken: $fdTaken\n";
+print "FDs Returned: $fdReturned\n";
+print "Highest FD Taken: $highestFdTaken\n\n";
+print "Broken Pipes: $brokenPipeCount\n";
if ($brokenPipeCount > 0){
my $rc = $hashes->{rc};
my @etext;
@@ -1121,7 +1135,7 @@ if ($brokenPipeCount > 0){
print "\n";
}
-print "Connections Reset By Peer: $connResetByPeerCount\n";
+print "Connections Reset By Peer: $connResetByPeerCount\n";
if ($connResetByPeerCount > 0){
my $src = $hashes->{src};
my @retext;
@@ -1135,7 +1149,7 @@ if ($connResetByPeerCount > 0){
print "\n";
}
-print "Resource Unavailable: $resourceUnavailCount\n";
+print "Resource Unavailable: $resourceUnavailCount\n";
if ($resourceUnavailCount > 0){
my $rsrc = $hashes->{rsrc};
my @rtext;
@@ -1147,27 +1161,27 @@ if ($resourceUnavailCount > 0){
}
print @rtext;
}
-print "Max BER Size Exceeded: $maxBerSizeCount\n";
+print "Max BER Size Exceeded: $maxBerSizeCount\n";
print "\n";
-print "Binds: $bindCount\n";
-print "Unbinds: $unbindCount\n";
-print "------------------------------";
+print "Binds: $bindCount\n";
+print "Unbinds: $unbindCount\n";
+print "-------------------------------";
print "-" x length $bindCount;
print "\n";
-print " - LDAP v2 Binds: $v2BindCount\n";
-print " - LDAP v3 Binds: $v3BindCount\n";
-print " - AUTOBINDs(LDAPI): $autobindCount\n";
-print " - SSL Client Binds: $sslClientBindCount\n";
-print " - Failed SSL Client Binds: $sslClientFailedCount\n";
-print " - SASL Binds: $saslBindCount\n";
+print " - LDAP v2 Binds: $v2BindCount\n";
+print " - LDAP v3 Binds: $v3BindCount\n";
+print " - AUTOBINDs(LDAPI): $autobindCount\n";
+print " - SSL Client Binds: $sslClientBindCount\n";
+print " - Failed SSL Client Binds: $sslClientFailedCount\n";
+print " - SASL Binds: $saslBindCount\n";
if ($saslBindCount > 0){
my $saslmech = $hashes->{saslmech};
foreach my $saslb ( sort {$saslmech->{$b} <=> $saslmech->{$a} } (keys %{$saslmech}) ){
printf " - %-4s: %s\n",$saslb, $saslmech->{$saslb};
}
}
-print " - Directory Manager Binds: $rootDNBindCount\n";
-print " - Anonymous Binds: $anonymousBindCount\n";
+print " - Directory Manager Binds: $rootDNBindCount\n";
+print " - Anonymous Binds: $anonymousBindCount\n";
##########################################################################
# Verbose Logging Section #
@@ -2572,16 +2586,22 @@ sub parseLineNormal
}
if ($_ =~ /etime= *([0-9.]+)/ ) {
my $etime_val = $1;
+ $totalEtime = $totalEtime + $1;
+ $etimeCount++;
if ($usage =~ /t/i || $verb eq "yes"){ $hashes->{etime}->{$etime_val}++; }
if ($reportStats){ inc_stats_val('etime',$etime_val,$s_stats,$m_stats); }
}
if ($_ =~ /wtime= *([0-9.]+)/ ) {
my $wtime_val = $1;
+ $totalWtime = $totalWtime + $1;
+ $wtimeCount++;
if ($usage =~ /t/i || $verb eq "yes"){ $hashes->{wtime}->{$wtime_val}++; }
if ($reportStats){ inc_stats_val('wtime',$wtime_val,$s_stats,$m_stats); }
}
if ($_ =~ /optime= *([0-9.]+)/ ) {
my $optime_val = $1;
+ $totalOpTime = $totalOpTime + $1;
+ $opTimeCount++;
if ($usage =~ /t/i || $verb eq "yes"){ $hashes->{optime}->{$optime_val}++; }
if ($reportStats){ inc_stats_val('optime',$optime_val,$s_stats,$m_stats); }
}
--
2.30.2

35
SOURCES/0022-Issue-51165-Set-the-operation-start-time-for-extende.patch Normal file
View file

@ -0,0 +1,35 @@
From 7ea2eafc8414d2bce6c57447d019276a124a0c77 Mon Sep 17 00:00:00 2001
From: Mark Reynolds <mreynolds@redhat.com>
Date: Mon, 17 Aug 2020 09:20:07 -0400
Subject: [PATCH] Issue 51165 - Set the operation start time for extended ops
Bug Description: Extended ops, likewhat is used in replication, were not
setting the operation start time. This caused invalid
values in the new access log keywords (wtime & optime)
Fix Description: Set the start start at the start of the extended op.
Fixes: https://pagure.io/389-ds-base/issue/51165
Reviewed by: mreynolds (one line commit rule)
---
ldap/servers/slapd/extendop.c | 3 +++
1 file changed, 3 insertions(+)
diff --git a/ldap/servers/slapd/extendop.c b/ldap/servers/slapd/extendop.c
index 98595bcaa..59a993ea8 100644
--- a/ldap/servers/slapd/extendop.c
+++ b/ldap/servers/slapd/extendop.c
@@ -221,6 +221,9 @@ do_extended(Slapi_PBlock *pb)
slapi_pblock_get(pb, SLAPI_OPERATION, &pb_op);
slapi_pblock_get(pb, SLAPI_CONNECTION, &pb_conn);
+ /* Set the time we actually started the operation */
+ slapi_operation_set_time_started(pb_op);
+
if (pb_conn == NULL || pb_op == NULL) {
send_ldap_result(pb, LDAP_OPERATIONS_ERROR, NULL, "param error", 0, NULL);
slapi_log_err(SLAPI_LOG_ERR, "do_extended",
--
2.30.2

35
SOURCES/0023-Issue-4706-negative-wtime-in-access-log-for-CMP-oper.patch Normal file
View file

@ -0,0 +1,35 @@
From b748757044ebe5a48119b5b8e31f23b423af736c Mon Sep 17 00:00:00 2001
From: Mark Reynolds <mreynolds@redhat.com>
Date: Mon, 29 Mar 2021 15:19:53 -0400
Subject: [PATCH] Issue 4706 - negative wtime in access log for CMP operations
Description: We forgot to set the start time for compare operations,
this led to invalid values in the access log for optime
and wtime.
relates: https://github.com/389ds/389-ds-base/issues/4706
Reviewed by: mreynolds (one line commit ruile)
---
ldap/servers/slapd/compare.c | 5 +++++
1 file changed, 5 insertions(+)
diff --git a/ldap/servers/slapd/compare.c b/ldap/servers/slapd/compare.c
index 88a6c3599..cb4a2c4c6 100644
--- a/ldap/servers/slapd/compare.c
+++ b/ldap/servers/slapd/compare.c
@@ -52,6 +52,11 @@ do_compare(Slapi_PBlock *pb)
slapi_pblock_get(pb, SLAPI_OPERATION, &pb_op);
slapi_pblock_get(pb, SLAPI_CONNECTION, &pb_conn);
+
+ /* Set the time we actually started the operation */
+ if (pb_op) {
+ slapi_operation_set_time_started(pb_op);
+ }
if (pb_op == NULL || pb_conn == NULL) {
slapi_log_err(SLAPI_LOG_ERR, "do_compare", "NULL param: pb_conn (0x%p) pb_op (0x%p)\n",
pb_conn, pb_op);
--
2.30.2

1254
SOURCES/0024-Issue-4609-CVE-info-disclosure-when-authenticating.patch Normal file
View file

File diff suppressed because it is too large Load diff

74
SOURCES/0025-Issue-4759-Fix-coverity-issue-4760.patch Normal file
View file

@ -0,0 +1,74 @@
From 8b236bc2c22ba907a9d8007889b7017122c26c2c Mon Sep 17 00:00:00 2001
From: tbordaz <tbordaz@redhat.com>
Date: Thu, 6 May 2021 18:50:06 +0200
Subject: [PATCH 1/2] Issue 4759 - Fix coverity issue (#4760)
Bug description:
with #4218 (wtime, optime in access log), hrtime is set in the
operation. But it is done before checking if the operation is
set. covscan fails
Fix description:
move the setting after verification that operation != NULL
relates: https://github.com/389ds/389-ds-base/issues/4759
Reviewed by: Simon Pichugin
Platforms tested: F34
---
ldap/servers/slapd/extendop.c | 6 +++---
ldap/servers/slapd/opshared.c | 6 +++---
2 files changed, 6 insertions(+), 6 deletions(-)
diff --git a/ldap/servers/slapd/extendop.c b/ldap/servers/slapd/extendop.c
index 59a993ea8..fbd41c6ee 100644
--- a/ldap/servers/slapd/extendop.c
+++ b/ldap/servers/slapd/extendop.c
@@ -221,9 +221,6 @@ do_extended(Slapi_PBlock *pb)
slapi_pblock_get(pb, SLAPI_OPERATION, &pb_op);
slapi_pblock_get(pb, SLAPI_CONNECTION, &pb_conn);
- /* Set the time we actually started the operation */
- slapi_operation_set_time_started(pb_op);
-
if (pb_conn == NULL || pb_op == NULL) {
send_ldap_result(pb, LDAP_OPERATIONS_ERROR, NULL, "param error", 0, NULL);
slapi_log_err(SLAPI_LOG_ERR, "do_extended",
@@ -231,6 +228,9 @@ do_extended(Slapi_PBlock *pb)
goto free_and_return;
}
+ /* Set the time we actually started the operation */
+ slapi_operation_set_time_started(pb_op);
+
/*
* Parse the extended request. It looks like this:
*
diff --git a/ldap/servers/slapd/opshared.c b/ldap/servers/slapd/opshared.c
index 2afb8e2fc..05b9a1553 100644
--- a/ldap/servers/slapd/opshared.c
+++ b/ldap/servers/slapd/opshared.c
@@ -276,9 +276,6 @@ op_shared_search(Slapi_PBlock *pb, int send_result)
slapi_pblock_get(pb, SLAPI_SEARCH_TARGET_SDN, &sdn);
slapi_pblock_get(pb, SLAPI_OPERATION, &operation);
- /* Set the time we actually started the operation */
- slapi_operation_set_time_started(operation);
-
if (NULL == sdn) {
sdn = slapi_sdn_new_dn_byval(base);
slapi_pblock_set(pb, SLAPI_SEARCH_TARGET_SDN, sdn);
@@ -309,6 +306,9 @@ op_shared_search(Slapi_PBlock *pb, int send_result)
rc = -1;
goto free_and_return_nolock;
}
+
+ /* Set the time we actually started the operation */
+ slapi_operation_set_time_started(operation);
internal_op = operation_is_flag_set(operation, OP_FLAG_INTERNAL);
flag_psearch = operation_is_flag_set(operation, OP_FLAG_PS);
--
2.30.2

20
SPECS/389-ds-base.spec
View file

@ -19,7 +19,7 @@
%global use_tcmalloc 0
%global variant base-asan
%else
%if %{_arch} != "s390x" && %{_arch} != "s390"
%if "%{_arch}" != "s390x" && "%{_arch}" != "s390"
%global use_tcmalloc 1
%else
%global use_tcmalloc 0
@ -39,7 +39,7 @@
Summary: 389 Directory Server (%{variant})
Name: 389-ds-base
Version: 1.3.10.2
Release: %{?relprefix}10%{?prerel}%{?dist}
Release: %{?relprefix}12%{?prerel}%{?dist}
License: GPLv3+
URL: https://www.port389.org/
Group: System Environment/Daemons
@ -165,6 +165,12 @@ Patch16: 0016-Issue-4521-DS-crash-in-deref-plugin-if-dereferenced-.patc
Patch17: 0017-Issue-4492-Changelog-cache-can-upload-updates-from-a.patch
Patch18: 0018-Issue-5442-Search-results-are-different-between-RHDS.patch
Patch19: 0019-Issue-4644-Large-updates-can-reset-the-CLcache-to-th.patch
Patch20: 0020-Issue-51165-add-new-access-log-keywords-for-wtime-an.patch
Patch21: 0021-Issue-51165-add-more-logconv-stats-for-the-new-acces.patch
Patch22: 0022-Issue-51165-Set-the-operation-start-time-for-extende.patch
Patch23: 0023-Issue-4706-negative-wtime-in-access-log-for-CMP-oper.patch
Patch24: 0024-Issue-4609-CVE-info-disclosure-when-authenticating.patch
Patch25: 0025-Issue-4759-Fix-coverity-issue-4760.patch
%description
@ -306,7 +312,7 @@ popd
sed -i -e 's|#{{PERL-EXEC}}|#!/usr/bin/perl|' $RPM_BUILD_ROOT%{_datadir}/%{pkgname}/script-templates/template-*.pl
# exclude 32-bit platforms from running tests
%if %{_arch} == "x86_64"
%if "%{_arch}" == "x86_64"
%check
# This checks the code, if it fails it prints why, then re-raises the fail to shortcircuit the rpm build.
if ! make DESTDIR="$RPM_BUILD_ROOT" check; then cat ./test-suite.log && false; fi
@ -519,6 +525,14 @@ fi
%{_sysconfdir}/%{pkgname}/dirsrvtests
%changelog
* Fri May 7 2021 Thierry Bordaz <tbordaz@redhat.com> - 1.3.10.2-12
- Bump version to 1.3.10.2-12
* Mon May 5 2021 Thierry Bordaz <tbordaz@redhat.com> - 1.3.10.2-11
- Bump version to 1.3.10.2-11
- Resolves: Bug 1953673 - Add new access log keywords for time spent in work queue and actual operation time
- Resolves: Bug 1931182 - information disclosure during the binding of a DN
* Thu Feb 25 2021 Mark Reynolds <mreynolds@redhat.com> - 1.3.10.2-10
- Bump version to 1.3.10.2-10
- Resolves: Bug 1909342 - DS crash in deref plugin while dereferencing an entry that exists but that is not returned by internal search