diff --git a/SOURCES/0020-Issue-51165-add-new-access-log-keywords-for-wtime-an.patch b/SOURCES/0020-Issue-51165-add-new-access-log-keywords-for-wtime-an.patch new file mode 100644 index 0000000..329c61e --- /dev/null +++ b/SOURCES/0020-Issue-51165-add-new-access-log-keywords-for-wtime-an.patch @@ -0,0 +1,656 @@ +From 5a0200975775f7bfbd51e1469e5560915800f791 Mon Sep 17 00:00:00 2001 +From: Mark Reynolds +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 + diff --git a/SOURCES/0021-Issue-51165-add-more-logconv-stats-for-the-new-acces.patch b/SOURCES/0021-Issue-51165-add-more-logconv-stats-for-the-new-acces.patch new file mode 100644 index 0000000..e431ae3 --- /dev/null +++ b/SOURCES/0021-Issue-51165-add-more-logconv-stats-for-the-new-acces.patch @@ -0,0 +1,276 @@ +From e8691d39f4fb0dc0a4ca12363430feb748984169 Mon Sep 17 00:00:00 2001 +From: Mark Reynolds +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 + diff --git a/SOURCES/0022-Issue-51165-Set-the-operation-start-time-for-extende.patch b/SOURCES/0022-Issue-51165-Set-the-operation-start-time-for-extende.patch new file mode 100644 index 0000000..7e11dfe --- /dev/null +++ b/SOURCES/0022-Issue-51165-Set-the-operation-start-time-for-extende.patch @@ -0,0 +1,35 @@ +From 7ea2eafc8414d2bce6c57447d019276a124a0c77 Mon Sep 17 00:00:00 2001 +From: Mark Reynolds +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 + diff --git a/SOURCES/0023-Issue-4706-negative-wtime-in-access-log-for-CMP-oper.patch b/SOURCES/0023-Issue-4706-negative-wtime-in-access-log-for-CMP-oper.patch new file mode 100644 index 0000000..53cbdaa --- /dev/null +++ b/SOURCES/0023-Issue-4706-negative-wtime-in-access-log-for-CMP-oper.patch @@ -0,0 +1,35 @@ +From b748757044ebe5a48119b5b8e31f23b423af736c Mon Sep 17 00:00:00 2001 +From: Mark Reynolds +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 + diff --git a/SOURCES/0024-Issue-4609-CVE-info-disclosure-when-authenticating.patch b/SOURCES/0024-Issue-4609-CVE-info-disclosure-when-authenticating.patch new file mode 100644 index 0000000..e952dbb --- /dev/null +++ b/SOURCES/0024-Issue-4609-CVE-info-disclosure-when-authenticating.patch @@ -0,0 +1,1254 @@ +From 5dafe01e0f52abb3679d1a53a229378331a73ca6 Mon Sep 17 00:00:00 2001 +From: Mark Reynolds +Date: Tue, 9 Feb 2021 14:02:59 -0500 +Subject: [PATCH] Issue 4609 - CVE - info disclosure when authenticating + +Description: If you bind as a user that does not exist. Error 49 is returned + instead of error 32. As error 32 discloses that the entry does + not exist. When you bind as an entry that does not have userpassword + set then error 48 (inappropriate auth) is returned, but this + discloses that the entry does indeed exist. Instead we should + always return error 49, even if the password is not set in the + entry. This way we do not disclose to an attacker if the Bind + DN exists or not. + +Relates: https://github.com/389ds/389-ds-base/issues/4609 + +Reviewed by: tbordaz(Thanks!) +--- + dirsrvtests/tests/suites/basic/basic_test.py | 1174 ------------------ + ldap/servers/slapd/back-ldbm/ldbm_bind.c | 4 +- + ldap/servers/slapd/dse.c | 7 +- + 3 files changed, 7 insertions(+), 1178 deletions(-) + delete mode 100644 dirsrvtests/tests/suites/basic/basic_test.py + +diff --git a/dirsrvtests/tests/suites/basic/basic_test.py b/dirsrvtests/tests/suites/basic/basic_test.py +deleted file mode 100644 +index cea4f6bfe..000000000 +--- a/dirsrvtests/tests/suites/basic/basic_test.py ++++ /dev/null +@@ -1,1174 +0,0 @@ +-# --- BEGIN COPYRIGHT BLOCK --- +-# Copyright (C) 2016 Red Hat, Inc. +-# All rights reserved. +-# +-# License: GPL (version 3 or any later version). +-# See LICENSE for details. +-# --- END COPYRIGHT BLOCK --- +-# +- +-""" +- :Requirement: Basic Directory Server Operations +-""" +- +-from subprocess import check_output, Popen +- +-import pytest +-from lib389.tasks import * +-from lib389.utils import * +-from lib389.topologies import topology_st +-from lib389.dbgen import dbgen +- +-from lib389._constants import DN_DM, PASSWORD, PW_DM +-from lib389.topologies import topology_st +- +-log = logging.getLogger(__name__) +- +-# Globals +-USER1_DN = 'uid=user1,' + DEFAULT_SUFFIX +-USER2_DN = 'uid=user2,' + DEFAULT_SUFFIX +-USER3_DN = 'uid=user3,' + DEFAULT_SUFFIX +-USER4_DN = 'uid=user4,' + DEFAULT_SUFFIX +- +-ROOTDSE_DEF_ATTR_LIST = ('namingContexts', +- 'supportedLDAPVersion', +- 'supportedControl', +- 'supportedExtension', +- 'supportedSASLMechanisms', +- 'vendorName', +- 'vendorVersion') +- +- +-@pytest.fixture(scope="module") +-def import_example_ldif(topology_st): +- """Import the Example LDIF for the tests in this suite""" +- +- log.info('Initializing the "basic" test suite') +- +- ldif = '%s/Example.ldif' % get_data_dir(topology_st.standalone.prefix) +- import_ldif = topology_st.standalone.get_ldif_dir() + "/Example.ldif" +- shutil.copyfile(ldif, import_ldif) +- topology_st.standalone.tasks.importLDIF(suffix=DEFAULT_SUFFIX, +- input_file=import_ldif, +- args={TASK_WAIT: True}) +- +- +-@pytest.fixture(params=ROOTDSE_DEF_ATTR_LIST) +-def rootdse_attr(topology_st, request): +- """Adds an attr from the list +- as the default attr to the rootDSE +- """ +- # Ensure the server is started and connected +- topology_st.standalone.start() +- +- RETURN_DEFAULT_OPATTR = "nsslapd-return-default-opattr" +- rootdse_attr_name = ensure_bytes(request.param) +- +- log.info(" Add the %s: %s to rootdse" % (RETURN_DEFAULT_OPATTR, +- rootdse_attr_name)) +- mod = [(ldap.MOD_ADD, RETURN_DEFAULT_OPATTR, rootdse_attr_name)] +- try: +- topology_st.standalone.modify_s("", mod) +- except ldap.LDAPError as e: +- log.fatal('Failed to add attr: error (%s)' % (e.message['desc'])) +- assert False +- +- def fin(): +- log.info(" Delete the %s: %s from rootdse" % (RETURN_DEFAULT_OPATTR, +- rootdse_attr_name)) +- mod = [(ldap.MOD_DELETE, RETURN_DEFAULT_OPATTR, rootdse_attr_name)] +- try: +- topology_st.standalone.modify_s("", mod) +- except ldap.LDAPError as e: +- log.fatal('Failed to delete attr: error (%s)' % (e.message['desc'])) +- assert False +- +- request.addfinalizer(fin) +- +- return rootdse_attr_name +- +- +-def test_basic_ops(topology_st, import_example_ldif): +- """Tests adds, mods, modrdns, and deletes operations +- +- :id: 33f97f55-60bf-46c7-b880-6c488517ae19 +- +- :setup: Standalone instance +- +- :steps: +- 1. Add 3 test users USER1, USER2 and USER3 to database +- 2. Modify (ADD, REPLACE and DELETE) description for USER1 in database +- 3. Rename USER1, USER2 and USER3 using Modrds +- 4. Delete test entries USER1, USER2 and USER3 +- +- :expectedresults: +- 1. Add operation should PASS. +- 2. Modify operations should PASS. +- 3. Rename operations should PASS. +- 4. Delete operations should PASS. +- """ +- log.info('Running test_basic_ops...') +- USER1_NEWDN = 'cn=user1' +- USER2_NEWDN = 'cn=user2' +- USER3_NEWDN = 'cn=user3' +- NEW_SUPERIOR = 'ou=people,' + DEFAULT_SUFFIX +- USER1_RDN_DN = 'cn=user1,' + DEFAULT_SUFFIX +- USER2_RDN_DN = 'cn=user2,' + DEFAULT_SUFFIX +- USER3_RDN_DN = 'cn=user3,' + NEW_SUPERIOR # New superior test +- +- # +- # Adds# +- try: +- topology_st.standalone.add_s(Entry((USER1_DN, +- {'objectclass': "top extensibleObject".split(), +- 'sn': '1', +- 'cn': 'user1', +- 'uid': 'user1', +- 'userpassword': 'password'}))) +- except ldap.LDAPError as e: +- log.error('Failed to add test user' + USER1_DN + ': error ' + e.message['desc']) +- assert False +- +- try: +- topology_st.standalone.add_s(Entry((USER2_DN, +- {'objectclass': "top extensibleObject".split(), +- 'sn': '2', +- 'cn': 'user2', +- 'uid': 'user2', +- 'userpassword': 'password'}))) +- except ldap.LDAPError as e: +- log.error('Failed to add test user' + USER2_DN + ': error ' + e.message['desc']) +- assert False +- +- try: +- topology_st.standalone.add_s(Entry((USER3_DN, +- {'objectclass': "top extensibleObject".split(), +- 'sn': '3', +- 'cn': 'user3', +- 'uid': 'user3', +- 'userpassword': 'password'}))) +- except ldap.LDAPError as e: +- log.error('Failed to add test user' + USER3_DN + ': error ' + e.message['desc']) +- assert False +- +- # +- # Mods +- # +- try: +- topology_st.standalone.modify_s(USER1_DN, [(ldap.MOD_ADD, 'description', +- b'New description')]) +- except ldap.LDAPError as e: +- log.error('Failed to add description: error ' + e.message['desc']) +- assert False +- +- try: +- topology_st.standalone.modify_s(USER1_DN, [(ldap.MOD_REPLACE, 'description', +- b'Modified description')]) +- except ldap.LDAPError as e: +- log.error('Failed to modify description: error ' + e.message['desc']) +- assert False +- +- try: +- topology_st.standalone.modify_s(USER1_DN, [(ldap.MOD_DELETE, 'description', +- None)]) +- except ldap.LDAPError as e: +- log.error('Failed to delete description: error ' + e.message['desc']) +- assert False +- +- # +- # Modrdns +- # +- try: +- topology_st.standalone.rename_s(USER1_DN, USER1_NEWDN, delold=1) +- except ldap.LDAPError as e: +- log.error('Failed to modrdn user1: error ' + e.message['desc']) +- assert False +- +- try: +- topology_st.standalone.rename_s(USER2_DN, USER2_NEWDN, delold=0) +- except ldap.LDAPError as e: +- log.error('Failed to modrdn user2: error ' + e.message['desc']) +- assert False # Modrdn - New superior +- +- try: +- topology_st.standalone.rename_s(USER3_DN, USER3_NEWDN, +- newsuperior=NEW_SUPERIOR, delold=1) +- except ldap.LDAPError as e: +- log.error('Failed to modrdn(new superior) user3: error ' + e.message['desc']) +- assert False +- # +- # Deletes +- # +- try: +- topology_st.standalone.delete_s(USER1_RDN_DN) +- except ldap.LDAPError as e: +- log.error('Failed to delete test entry1: ' + e.message['desc']) +- assert False +- +- try: +- topology_st.standalone.delete_s(USER2_RDN_DN) +- except ldap.LDAPError as e: +- log.error('Failed to delete test entry2: ' + e.message['desc']) +- assert False +- +- try: +- topology_st.standalone.delete_s(USER3_RDN_DN) +- except ldap.LDAPError as e: +- log.error('Failed to delete test entry3: ' + e.message['desc']) +- assert False +- log.info('test_basic_ops: PASSED') +- +- +-def test_basic_import_export(topology_st, import_example_ldif): +- """Test online and offline LDIF import & export +- +- :id: 3ceeea11-9235-4e20-b80e-7203b2c6e149 +- +- :setup: Standalone instance +- +- :steps: +- 1. Generate a test ldif (50k entries) +- 2. Import test ldif file using Online import. +- 3. Import test ldif file using Offline import (ldif2db). +- 4. Export test ldif file using Online export. +- 5. Export test ldif file using Offline export (db2ldif). +- 6. Cleanup - Import the Example LDIF for the other tests in this suite +- +- :expectedresults: +- 1. Test ldif file creation should PASS. +- 2. Online import should PASS. +- 3. Offline import should PASS. +- 4. Online export should PASS. +- 5. Offline export should PASS. +- 6. Cleanup should PASS. +- """ +- +- log.info('Running test_basic_import_export...') +- +- tmp_dir = '/tmp' +- +- # +- # Test online/offline LDIF imports +- # +- topology_st.standalone.start() +- +- # Generate a test ldif (50k entries) +- ldif_dir = topology_st.standalone.get_ldif_dir() +- import_ldif = ldif_dir + '/basic_import.ldif' +- dbgen(topology_st.standalone, 50000, import_ldif, DEFAULT_SUFFIX) +- +- # Online +- try: +- topology_st.standalone.tasks.importLDIF(suffix=DEFAULT_SUFFIX, +- input_file=import_ldif, +- args={TASK_WAIT: True}) +- except ValueError: +- log.fatal('test_basic_import_export: Online import failed') +- assert False +- +- # Offline +- topology_st.standalone.stop() +- if not topology_st.standalone.ldif2db(DEFAULT_BENAME, None, None, None, import_ldif): +- log.fatal('test_basic_import_export: Offline import failed') +- assert False +- topology_st.standalone.start() +- +- # +- # Test online and offline LDIF export +- # +- +- # Online export +- export_ldif = ldif_dir + '/export.ldif' +- exportTask = Tasks(topology_st.standalone) +- try: +- args = {TASK_WAIT: True} +- exportTask.exportLDIF(DEFAULT_SUFFIX, None, export_ldif, args) +- except ValueError: +- log.fatal('test_basic_import_export: Online export failed') +- assert False +- +- # Offline export +- topology_st.standalone.stop() +- if not topology_st.standalone.db2ldif(DEFAULT_BENAME, (DEFAULT_SUFFIX,), +- None, None, None, export_ldif): +- log.fatal('test_basic_import_export: Failed to run offline db2ldif') +- assert False +- +- topology_st.standalone.start() +- +- # +- # Cleanup - Import the Example LDIF for the other tests in this suite +- # +- ldif = '%s/Example.ldif' % get_data_dir(topology_st.standalone.prefix) +- import_ldif = topology_st.standalone.get_ldif_dir() + "/Example.ldif" +- shutil.copyfile(ldif, import_ldif) +- try: +- topology_st.standalone.tasks.importLDIF(suffix=DEFAULT_SUFFIX, +- input_file=import_ldif, +- args={TASK_WAIT: True}) +- except ValueError: +- log.fatal('test_basic_import_export: Online import failed') +- assert False +- +- log.info('test_basic_import_export: PASSED') +- +- +-def test_basic_backup(topology_st, import_example_ldif): +- """Tests online and offline backup and restore +- +- :id: 0e9d91f8-8748-40b6-ab03-fbd1998eb985 +- +- :setup: Standalone instance and import example.ldif +- +- :steps: +- 1. Test online backup using db2bak. +- 2. Test online restore using bak2db. +- 3. Test offline backup using db2bak. +- 4. Test offline restore using bak2db. +- +- :expectedresults: +- 1. Online backup should PASS. +- 2. Online restore should PASS. +- 3. Offline backup should PASS. +- 4. Offline restore should PASS. +- """ +- +- log.info('Running test_basic_backup...') +- +- backup_dir = topology_st.standalone.get_bak_dir() + '/backup_test' +- +- # Test online backup +- try: +- topology_st.standalone.tasks.db2bak(backup_dir=backup_dir, +- args={TASK_WAIT: True}) +- except ValueError: +- log.fatal('test_basic_backup: Online backup failed') +- assert False +- +- # Test online restore +- try: +- topology_st.standalone.tasks.bak2db(backup_dir=backup_dir, +- args={TASK_WAIT: True}) +- except ValueError: +- log.fatal('test_basic_backup: Online restore failed') +- assert False +- +- # Test offline backup +- topology_st.standalone.stop() +- if not topology_st.standalone.db2bak(backup_dir): +- log.fatal('test_basic_backup: Offline backup failed') +- assert False +- +- # Test offline restore +- if not topology_st.standalone.bak2db(backup_dir): +- log.fatal('test_basic_backup: Offline backup failed') +- assert False +- topology_st.standalone.start() +- +- log.info('test_basic_backup: PASSED') +- +- +-def test_basic_acl(topology_st, import_example_ldif): +- """Run some basic access control (ACL) tests +- +- :id: 4f4e705f-32f4-4065-b3a8-2b0c2525798b +- +- :setup: Standalone instance +- +- :steps: +- 1. Add two test users USER1_DN and USER2_DN. +- 2. Add an aci that denies USER1 from doing anything. +- 3. Set the default anonymous access for USER2. +- 4. Try searching entries using USER1. +- 5. Try searching entries using USER2. +- 6. Try searching entries using root dn. +- 7. Cleanup - delete test users and test ACI. +- +- :expectedresults: +- 1. Test Users should be added. +- 2. ACI should be added. +- 3. This operation should PASS. +- 4. USER1 should not be able to search anything. +- 5. USER2 should be able to search everything except password. +- 6. RootDN should be allowed to search everything. +- 7. Cleanup should PASS. +- """ +- +- """Run some basic access control(ACL) tests""" +- log.info('Running test_basic_acl...') +- +- DENY_ACI = ensure_bytes('(targetattr = "*")(version 3.0;acl "deny user";deny (all)(userdn = "ldap:///%s");)' % USER1_DN) +- +- # +- # Add two users +- # +- try: +- topology_st.standalone.add_s(Entry((USER1_DN, +- {'objectclass': "top extensibleObject".split(), +- 'sn': '1', +- 'cn': 'user 1', +- 'uid': 'user1', +- 'userpassword': PASSWORD}))) +- except ldap.LDAPError as e: +- log.fatal('test_basic_acl: Failed to add test user ' + USER1_DN + +- ': error ' + e.message['desc']) +- assert False +- +- try: +- topology_st.standalone.add_s(Entry((USER2_DN, +- {'objectclass': "top extensibleObject".split(), +- 'sn': '2', +- 'cn': 'user 2', +- 'uid': 'user2', +- 'userpassword': PASSWORD}))) +- except ldap.LDAPError as e: +- log.fatal('test_basic_acl: Failed to add test user ' + USER1_DN + +- ': error ' + e.message['desc']) +- assert False +- +- # +- # Add an aci that denies USER1 from doing anything, +- # and also set the default anonymous access +- # +- try: +- topology_st.standalone.modify_s(DEFAULT_SUFFIX, [(ldap.MOD_ADD, 'aci', DENY_ACI)]) +- except ldap.LDAPError as e: +- log.fatal('test_basic_acl: Failed to add DENY ACI: error ' + e.message['desc']) +- assert False +- +- # +- # Make sure USER1_DN can not search anything, but USER2_dn can... +- # +- try: +- topology_st.standalone.simple_bind_s(USER1_DN, PASSWORD) +- except ldap.LDAPError as e: +- log.fatal('test_basic_acl: Failed to bind as user1, error: ' + e.message['desc']) +- assert False +- +- try: +- entries = topology_st.standalone.search_s(DEFAULT_SUFFIX, +- ldap.SCOPE_SUBTREE, +- '(uid=*)') +- if entries: +- log.fatal('test_basic_acl: User1 was incorrectly able to search the suffix!') +- assert False +- except ldap.LDAPError as e: +- log.fatal('test_basic_acl: Search suffix failed(as user1): ' + e.message['desc']) +- assert False +- +- # Now try user2... Also check that userpassword is stripped out +- try: +- topology_st.standalone.simple_bind_s(USER2_DN, PASSWORD) +- except ldap.LDAPError as e: +- log.fatal('test_basic_acl: Failed to bind as user2, error: ' + e.message['desc']) +- assert False +- +- try: +- entries = topology_st.standalone.search_s(DEFAULT_SUFFIX, +- ldap.SCOPE_SUBTREE, +- '(uid=user1)') +- if not entries: +- log.fatal('test_basic_acl: User1 incorrectly not able to search the suffix') +- assert False +- if entries[0].hasAttr('userpassword'): +- # The default anonymous access aci should have stripped out userpassword +- log.fatal('test_basic_acl: User2 was incorrectly able to see userpassword') +- assert False +- except ldap.LDAPError as e: +- log.fatal('test_basic_acl: Search for user1 failed(as user2): ' + e.message['desc']) +- assert False +- +- # Make sure RootDN can also search (this also resets the bind dn to the +- # Root DN for future operations) +- try: +- topology_st.standalone.simple_bind_s(DN_DM, PW_DM) +- except ldap.LDAPError as e: +- log.fatal('test_basic_acl: Failed to bind as ROotDN, error: ' + e.message['desc']) +- assert False +- +- try: +- entries = topology_st.standalone.search_s(DEFAULT_SUFFIX, +- ldap.SCOPE_SUBTREE, +- '(uid=*)') +- if not entries: +- log.fatal('test_basic_acl: Root DN incorrectly not able to search the suffix') +- assert False +- except ldap.LDAPError as e: +- log.fatal('test_basic_acl: Search for user1 failed(as user2): ' + e.message['desc']) +- assert False +- +- # +- # Cleanup +- # +- try: +- topology_st.standalone.modify_s(DEFAULT_SUFFIX, [(ldap.MOD_DELETE, 'aci', DENY_ACI)]) +- except ldap.LDAPError as e: +- log.fatal('test_basic_acl: Failed to delete DENY ACI: error ' + e.message['desc']) +- assert False +- +- try: +- topology_st.standalone.delete_s(USER1_DN) +- except ldap.LDAPError as e: +- log.fatal('test_basic_acl: Failed to delete test entry1: ' + e.message['desc']) +- assert False +- +- try: +- topology_st.standalone.delete_s(USER2_DN) +- except ldap.LDAPError as e: +- log.fatal('test_basic_acl: Failed to delete test entry2: ' + e.message['desc']) +- assert False +- +- log.info('test_basic_acl: PASSED') +- +- +-def test_basic_searches(topology_st, import_example_ldif): +- """Tests basic search operations with filters. +- +- :id: 426a59ff-49b8-4a70-b377-0c0634a29b6f +- +- :setup: Standalone instance, add example.ldif to the database +- +- :steps: +- 1. Execute search command while using different filters. +- 2. Check number of entries returned by search filters. +- +- :expectedresults: +- 1. Search command should PASS. +- 2. Number of result entries returned should match number of the database entries according to the search filter. +- """ +- +- log.info('Running test_basic_searches...') +- +- filters = (('(uid=scarter)', 1), +- ('(uid=tmorris*)', 1), +- ('(uid=*hunt*)', 4), +- ('(uid=*cope)', 2), +- ('(mail=*)', 150), +- ('(roomnumber>=4000)', 35), +- ('(roomnumber<=4000)', 115), +- ('(&(roomnumber>=4000)(roomnumber<=4500))', 18), +- ('(!(l=sunnyvale))', 120), +- ('(&(uid=t*)(l=santa clara))', 7), +- ('(|(uid=k*)(uid=r*))', 18), +- ('(|(uid=t*)(l=sunnyvale))', 50), +- ('(&(!(uid=r*))(ou=people))', 139), +- ('(&(uid=m*)(l=sunnyvale)(ou=people)(mail=*example*)(roomNumber=*))', 3), +- ('(&(|(uid=m*)(l=santa clara))(roomNumber=22*))', 5), +- ('(&(|(uid=m*)(l=santa clara))(roomNumber=22*)(!(roomnumber=2254)))', 4),) +- +- for (search_filter, search_result) in filters: +- try: +- entries = topology_st.standalone.search_s(DEFAULT_SUFFIX, +- ldap.SCOPE_SUBTREE, +- search_filter) +- if len(entries) != search_result: +- log.fatal('test_basic_searches: An incorrect number of entries\ +- was returned from filter (%s): (%d) expected (%d)' % +- (search_filter, len(entries), search_result)) +- assert False +- except ldap.LDAPError as e: +- log.fatal('Search failed: ' + e.message['desc']) +- assert False +- +- log.info('test_basic_searches: PASSED') +- +- +-@pytest.fixture(scope="module") +-def add_test_entry(topology_st, request): +- # Add test entry +- topology_st.standalone.add_s(Entry((USER4_DN, +- {'objectclass': "top extensibleObject".split(), +- 'cn': 'user1', 'uid': 'user1'}))) +- +- +-search_params = [(['1.1'], 'cn', False), +- (['1.1', 'cn'], 'cn', True), +- (['+'], 'nsUniqueId', True), +- (['*'], 'cn', True), +- (['cn'], 'cn', True)] +-@pytest.mark.parametrize("attrs, attr, present", search_params) +-def test_search_req_attrs(topology_st, add_test_entry, attrs, attr, present): +- """Test requested attributes in search operations. +- :id: 426a59ff-49b8-4a70-b377-0c0634a29b6e +- :setup: Standalone instance +- :steps: +- 1. Test "1.1" does not return any attributes. +- 2. Test "1.1" is ignored if there are other requested attributes +- 3. Test "+" returns all operational attributes +- 4. Test "*" returns all attributes +- 5. Test requested attributes +- +- :expectedresults: +- 1. Success +- 2. Success +- 3. Success +- 4. Success +- 5. Success +- """ +- +- log.info("Testing attrs: {} attr: {} present: {}".format(attrs, attr, present)) +- entry = topology_st.standalone.search_s(USER4_DN, +- ldap.SCOPE_BASE, +- 'objectclass=top', +- attrs) +- if present: +- assert entry[0].hasAttr(attr) +- else: +- assert not entry[0].hasAttr(attr) +- +- +-def test_basic_referrals(topology_st, import_example_ldif): +- """Test LDAP server in referral mode. +- +- :id: c586aede-7ac3-4e8d-a1cf-bfa8b8d78cc2 +- +- :setup: Standalone instance +- +- :steps: +- 1. Set the referral and the backenidealyd state +- 2. Set backend state to referral mode. +- 3. Set server to not follow referral. +- 4. Search using referral. +- 5. Make sure server can restart in referral mode. +- 6. Cleanup - Delete referral. +- +- :expectedresults: +- 1. Set the referral, and the backend state should PASS. +- 2. Set backend state to referral mode should PASS. +- 3. Set server to not follow referral should PASS. +- 4. referral error(10) should occur. +- 5. Restart should PASS. +- 6. Cleanup should PASS. +- """ +- +- log.info('Running test_basic_referrals...') +- SUFFIX_CONFIG = 'cn="dc=example,dc=com",cn=mapping tree,cn=config' +- # +- # Set the referral, and the backend state +- # +- try: +- topology_st.standalone.modify_s(SUFFIX_CONFIG, +- [(ldap.MOD_REPLACE, +- 'nsslapd-referral', +- b'ldap://localhost.localdomain:389/o%3dnetscaperoot')]) +- except ldap.LDAPError as e: +- log.fatal('test_basic_referrals: Failed to set referral: error ' + e.message['desc']) +- assert False +- +- try: +- topology_st.standalone.modify_s(SUFFIX_CONFIG, [(ldap.MOD_REPLACE, +- 'nsslapd-state', b'Referral')]) +- except ldap.LDAPError as e: +- log.fatal('test_basic_referrals: Failed to set backend state: error ' +- + e.message['desc']) +- assert False +- +- # +- # Test that a referral error is returned +- # +- topology_st.standalone.set_option(ldap.OPT_REFERRALS, 0) # Do not follow referral +- try: +- topology_st.standalone.search_s(DEFAULT_SUFFIX, ldap.SCOPE_SUBTREE, 'objectclass=top') +- except ldap.REFERRAL: +- pass +- except ldap.LDAPError as e: +- log.fatal('test_basic_referrals: Search failed: ' + e.message['desc']) +- assert False +- +- # +- # Make sure server can restart in referral mode +- # +- topology_st.standalone.restart(timeout=10) +- +- # +- # Cleanup +- # +- try: +- topology_st.standalone.modify_s(SUFFIX_CONFIG, [(ldap.MOD_REPLACE, +- 'nsslapd-state', b'Backend')]) +- except ldap.LDAPError as e: +- log.fatal('test_basic_referrals: Failed to set backend state: error ' +- + e.message['desc']) +- assert False +- +- try: +- topology_st.standalone.modify_s(SUFFIX_CONFIG, [(ldap.MOD_DELETE, +- 'nsslapd-referral', None)]) +- except ldap.LDAPError as e: +- log.fatal('test_basic_referrals: Failed to delete referral: error ' +- + e.message['desc']) +- assert False +- topology_st.standalone.set_option(ldap.OPT_REFERRALS, 1) +- +- log.info('test_basic_referrals: PASSED') +- +- +-def test_basic_systemctl(topology_st, import_example_ldif): +- """Tests systemctl/lib389 can stop and start the server. +- +- :id: a92a7438-ecfa-4583-a89c-5fbfc0220b69 +- +- :setup: Standalone instance +- +- :steps: +- 1. Stop the server. +- 2. Start the server. +- 3. Stop the server, break the dse.ldif and dse.ldif.bak, so a start fails. +- 4. Verify that systemctl detects the failed start. +- 5. Fix the dse.ldif, and make sure the server starts up. +- 6. Verify systemctl correctly identifies the successful start. +- +- :expectedresults: +- 1. Server should be stopped. +- 2. Server should start +- 3. Stop should work but start after breaking dse.ldif should fail. +- 4. Systemctl should be able to detect the failed start. +- 5. Server should start. +- 6. Systemctl should be able to detect the successful start. +- """ +- +- log.info('Running test_basic_systemctl...') +- +- config_dir = topology_st.standalone.get_config_dir() +- +- # +- # Stop the server +- # +- log.info('Stopping the server...') +- topology_st.standalone.stop() +- log.info('Stopped the server.') +- +- # +- # Start the server +- # +- log.info('Starting the server...') +- topology_st.standalone.start() +- log.info('Started the server.') +- +- # +- # Stop the server, break the dse.ldif so a start fails, +- # and verify that systemctl detects the failed start +- # +- log.info('Stopping the server...') +- topology_st.standalone.stop() +- log.info('Stopped the server before breaking the dse.ldif.') +- +- shutil.copy(config_dir + '/dse.ldif', config_dir + '/dse.ldif.correct') +- open(config_dir + '/dse.ldif', 'w').close() +- # We need to kill the .bak file too, DS is just too smart! +- open(config_dir + '/dse.ldif.bak', 'w').close() +- +- log.info('Attempting to start the server with broken dse.ldif...') +- try: +- topology_st.standalone.start() +- except Exception as e: +- log.info('Server failed to start as expected: ' + str(e)) +- log.info('Check the status...') +- assert (not topology_st.standalone.status()) +- log.info('Server failed to start as expected') +- time.sleep(5) +- +- # +- # Fix the dse.ldif, and make sure the server starts up, +- # and systemctl correctly identifies the successful start +- # +- shutil.copy(config_dir + '/dse.ldif.correct', config_dir + '/dse.ldif') +- log.info('Starting the server with good dse.ldif...') +- topology_st.standalone.start() +- log.info('Check the status...') +- assert (topology_st.standalone.status()) +- log.info('Server started after fixing dse.ldif.') +- +- log.info('test_basic_systemctl: PASSED') +- +- +-def test_basic_ldapagent(topology_st, import_example_ldif): +- """Tests that the ldap agent starts +- +- :id: da1d1846-8fc4-4b8c-8e53-4c9c16eff1ba +- +- :setup: Standalone instance +- +- :steps: +- 1. Start SNMP ldap agent using command. +- 2. Cleanup - Kill SNMP agent process. +- +- :expectedresults: +- 1. SNMP agent should start. +- 2. SNMP agent process should be successfully killed. +- """ +- +- log.info('Running test_basic_ldapagent...') +- +- var_dir = topology_st.standalone.get_local_state_dir() +- +- config_file = os.path.join(topology_st.standalone.get_sysconf_dir(), 'dirsrv/config/agent.conf') +- +- agent_config_file = open(config_file, 'w') +- agent_config_file.write('agentx-master ' + var_dir + '/agentx/master\n') +- agent_config_file.write('agent-logdir ' + var_dir + '/log/dirsrv\n') +- agent_config_file.write('server slapd-' + topology_st.standalone.serverid + '\n') +- agent_config_file.close() +- +- # Remember, this is *forking* +- check_output([os.path.join(topology_st.standalone.get_sbin_dir(), 'ldap-agent'), config_file]) +- # First kill any previous agents .... +- pidpath = os.path.join(var_dir, 'run/ldap-agent.pid') +- pid = None +- with open(pidpath, 'r') as pf: +- pid = pf.readlines()[0].strip() +- if pid: +- log.debug('test_basic_ldapagent: Terminating agent %s', pid) +- check_output(['kill', pid]) +- +- log.info('test_basic_ldapagent: PASSED') +- +- +-def test_basic_dse(topology_st, import_example_ldif): +- """Tests that the dse.ldif is not wiped out after the process is killed (bug 910581) +- +- :id: 10f141da-9b22-443a-885c-87271dcd7a59 +- +- :setup: Standalone instance +- +- :steps: +- 1. Check out pid of ns-slapd process and Kill ns-slapd process. +- 2. Check the contents of dse.ldif file. +- 3. Start server. +- +- :expectedresults: +- 1. ns-slapd process should be killed. +- 2. dse.ldif should not be corrupted. +- 3. Server should start successfully. +- """ +- log.info('Running test_basic_dse...') +- +- dse_file = topology_st.standalone.confdir + '/dse.ldif' +- pid = check_output(['pidof', '-s', 'ns-slapd']).strip() +- check_output(['sudo', 'kill', '-9', ensure_str(pid)]) +- if os.path.getsize(dse_file) == 0: +- log.fatal('test_basic_dse: dse.ldif\'s content was incorrectly removed!') +- assert False +- +- topology_st.standalone.start(timeout=60) +- log.info('dse.ldif was not corrupted, and the server was restarted') +- +- log.info('test_basic_dse: PASSED') +- # Give the server time to startup, in some conditions this can be racey without systemd notification. Only affects this one test though... +- time.sleep(10) +- +- +-@pytest.mark.parametrize("rootdse_attr_name", ROOTDSE_DEF_ATTR_LIST) +-def test_def_rootdse_attr(topology_st, import_example_ldif, rootdse_attr_name): +- """Tests that operational attributes are not returned by default in rootDSE searches +- +- :id: 4fee33cc-4019-4c27-89e8-998e6c770dc0 +- +- :setup: Standalone instance +- +- :steps: +- 1. Make an ldapsearch for rootdse attribute +- 2. Check the returned entries. +- +- :expectedresults: +- 1. Search should not fail +- 2. Operational attributes should not be returned. +- """ +- +- topology_st.standalone.start() +- +- log.info(" Assert rootdse search hasn't %s attr" % rootdse_attr_name) +- try: +- entry = topology_st.standalone.search_s("", ldap.SCOPE_BASE)[0] +- assert not entry.hasAttr(rootdse_attr_name) +- +- except ldap.LDAPError as e: +- log.fatal('Search failed, error: ' + e.message['desc']) +- assert False +- +- +-def test_mod_def_rootdse_attr(topology_st, import_example_ldif, rootdse_attr): +- """Tests that operational attributes are returned by default in rootDSE searches after config modification +- +- :id: c7831e04-f458-4e23-83c7-b6f66109f639 +- +- :setup: Standalone instance and we are using rootdse_attr fixture which +-adds nsslapd-return-default-opattr attr with value of one operation attribute. +- +- :steps: +- 1. Make an ldapsearch for rootdse attribute +- 2. Check the returned entries. +- +- :expectedresults: +- 1. Search should not fail +- 2. Operational attributes should be returned after the config modification +- """ +- +- log.info(" Assert rootdse search has %s attr" % rootdse_attr) +- try: +- entry = topology_st.standalone.search_s("", ldap.SCOPE_BASE)[0] +- assert entry.hasAttr(rootdse_attr) +- +- except ldap.LDAPError as e: +- log.fatal('Search failed, error: ' + e.message['desc']) +- assert False +- +- +-@pytest.fixture(scope="module") +-def create_users(topology_st): +- """Add users to the default suffix +- """ +- +- users = UserAccounts(topology_st.standalone, DEFAULT_SUFFIX) +- user_names = ["Directory", "Server", "389", "lib389", "pytest"] +- +- log.info('Adding 5 test users') +- for name in user_names: +- user = users.create(properties={ +- 'uid': name, +- 'sn': name, +- 'cn': name, +- 'uidNumber': '1000', +- 'gidNumber': '1000', +- 'homeDirectory': '/home/%s' % name, +- 'mail': '%s@example.com' % name, +- 'userpassword': 'pass%s' % name, +- }) +- +- +-def test_basic_anonymous_search(topology_st, create_users): +- """Tests basic anonymous search operations +- +- :id: c7831e04-f458-4e50-83c7-b6f77109f639 +- :setup: Standalone instance +- Add 5 test users with different user names +- :steps: +- 1. Execute anonymous search with different filters +- :expectedresults: +- 1. Search should be successful +- """ +- +- filters = ["uid=Directory", "(|(uid=S*)(uid=3*))", "(&(uid=l*)(mail=l*))", "(&(!(uid=D*))(ou=People))"] +- log.info("Execute anonymous search with different filters") +- for filtr in filters: +- entries = topology_st.standalone.search_s(DEFAULT_SUFFIX, ldap.SCOPE_SUBTREE, filtr) +- assert len(entries) != 0 +- +- +-@pytest.mark.ds604 +-@pytest.mark.bz915801 +-def test_search_original_type(topology_st, create_users): +- """Test ldapsearch returning original attributes +- using nsslapd-search-return-original-type-switch +- +- :id: d7831d04-f558-4e50-93c7-b6f77109f640 +- :setup: Standalone instance +- Add some test entries +- :steps: +- 1. Set nsslapd-search-return-original-type-switch to ON +- 2. Check that ldapsearch *does* return unknown attributes +- 3. Turn off nsslapd-search-return-original-type-switch +- 4. Check that ldapsearch doesn't return any unknown attributes +- :expectedresults: +- 1. nsslapd-search-return-original-type-switch should be set to ON +- 2. ldapsearch should return unknown attributes +- 3. nsslapd-search-return-original-type-switch should be OFF +- 4. ldapsearch should not return any unknown attributes +- """ +- +- log.info("Set nsslapd-search-return-original-type-switch to ON") +- topology_st.standalone.config.set('nsslapd-search-return-original-type-switch', 'on') +- +- log.info("Check that ldapsearch *does* return unknown attributes") +- entries = topology_st.standalone.search_s(DEFAULT_SUFFIX, ldap.SCOPE_SUBTREE, 'uid=Directory', +- ['objectclass overflow', 'unknown']) +- assert "objectclass overflow" in entries[0].getAttrs() +- +- log.info("Set nsslapd-search-return-original-type-switch to Off") +- topology_st.standalone.config.set('nsslapd-search-return-original-type-switch', 'off') +- log.info("Check that ldapsearch *does not* return unknown attributes") +- entries = topology_st.standalone.search_s(DEFAULT_SUFFIX, ldap.SCOPE_SUBTREE, 'uid=Directory', +- ['objectclass overflow', 'unknown']) +- assert "objectclass overflow" not in entries[0].getAttrs() +- +- +-@pytest.mark.bz192901 +-def test_search_ou(topology_st): +- """Test that DS should not return an entry that does not match the filter +- +- :id: d7831d05-f117-4e89-93c7-b6f77109f640 +- :setup: Standalone instance +- :steps: +- 1. Create an OU entry without sub entries +- 2. Search from the OU with the filter that does not match the OU +- :expectedresults: +- 1. Creation of OU should be successful +- 2. Search should not return any results +- """ +- +- log.info("Create a test OU without sub entries") +- ou = OrganizationalUnits(topology_st.standalone, DEFAULT_SUFFIX) +- ou.create(properties={ +- 'ou': 'test_ou', +- }) +- +- search_base = ("ou=test_ou,%s" % DEFAULT_SUFFIX) +- log.info("Search from the OU with the filter that does not match the OU, it should not return anything") +- entries = topology_st.standalone.search_s(search_base, ldap.SCOPE_SUBTREE, 'uid=*', ['dn']) +- assert len(entries) == 0 +- +- +-@pytest.mark.bz1044135 +-@pytest.mark.ds47319 +-def test_connection_buffer_size(topology_st): +- """Test connection buffer size adjustable with different values(valid values and invalid) +- +- :id: e7831d05-f117-4ec9-1203-b6f77109f117 +- :setup: Standalone instance +- :steps: +- 1. Set nsslapd-connection-buffer to some valid values (2, 0 , 1) +- 2. Set nsslapd-connection-buffer to some invalid values (-1, a) +- :expectedresults: +- 1. This should pass +- 2. This should fail +- """ +- +- valid_values = ['2', '0', '1'] +- for value in valid_values: +- topology_st.standalone.config.replace('nsslapd-connection-buffer', value) +- +- invalid_values = ['-1', 'a'] +- for value in invalid_values: +- with pytest.raises(ldap.OPERATIONS_ERROR): +- topology_st.standalone.config.replace('nsslapd-connection-buffer', value) +- +-@pytest.mark.bz1637439 +-def test_critical_msg_on_empty_range_idl(topology_st): +- """Doing a range index lookup should not report a critical message even if IDL is empty +- +- :id: a07a2222-0551-44a6-b113-401d23799364 +- :setup: Standalone instance +- :steps: +- 1. Create an index for internationalISDNNumber. (attribute chosen because it is +- unlikely that previous tests used it) +- 2. telephoneNumber being indexed by default create 20 users without telephoneNumber +- 3. add a telephoneNumber value and delete it to trigger an empty index database +- 4. Do a search that triggers a range lookup on empty telephoneNumber +- 5. Check that the critical message is not logged in error logs +- :expectedresults: +- 1. This should pass +- 2. This should pass +- 3. This should pass +- 4. This should pass on normal build but could abort a debug build +- 4. This should pass +- """ +- indexedAttr = 'internationalISDNNumber' +- +- # Step 1 +- from lib389.index import Indexes +- +- indexes = Indexes(topology_st.standalone) +- indexes.create(properties={ +- 'cn': indexedAttr, +- 'nsSystemIndex': 'false', +- 'nsIndexType': 'eq' +- }) +- topology_st.standalone.restart() +- +- # Step 2 +- users = UserAccounts(topology_st.standalone, DEFAULT_SUFFIX) +- log.info('Adding 20 users without "%s"' % indexedAttr) +- for i in range(20): +- name = 'user_%d' % i +- last_user = users.create(properties={ +- 'uid': name, +- 'sn': name, +- 'cn': name, +- 'uidNumber': '1000', +- 'gidNumber': '1000', +- 'homeDirectory': '/home/%s' % name, +- 'mail': '%s@example.com' % name, +- 'userpassword': 'pass%s' % name, +- }) +- +- # Step 3 +- # required update to create the indexAttr (i.e. 'loginShell') database, and then make it empty +- topology_st.standalone.modify_s(last_user.dn, [(ldap.MOD_ADD, indexedAttr, b'1234')]) +- ent = topology_st.standalone.getEntry(last_user.dn, ldap.SCOPE_BASE,) +- assert ent +- assert ent.hasAttr(indexedAttr) +- topology_st.standalone.modify_s(last_user.dn, [(ldap.MOD_DELETE, indexedAttr, None)]) +- ent = topology_st.standalone.getEntry(last_user.dn, ldap.SCOPE_BASE,) +- assert ent +- assert not ent.hasAttr(indexedAttr) +- +- # Step 4 +- # The first component being not indexed the range on second is evaluated +- try: +- ents = topology_st.standalone.search_s(DEFAULT_SUFFIX, ldap.SCOPE_SUBTREE, '(&(sudoNotAfter=*)(%s>=111))' % indexedAttr) +- assert len(ents) == 0 +- except ldap.SERVER_DOWN: +- log.error('Likely testing against a debug version that asserted') +- pass +- +- # Step 5 +- assert not topology_st.standalone.searchErrorsLog('CRIT - list_candidates - NULL idl was recieved from filter_candidates_ext.') +- +-def audit_pattern_found(server, log_pattern): +- file_obj = open(server.ds_paths.audit_log, "r") +- +- found = None +- # Use a while true iteration because 'for line in file: hit a +- log.info('Audit log contains') +- while True: +- line = file_obj.readline() +- log.info(line) +- found = log_pattern.search(line) +- if ((line == '') or (found)): +- break +- +- return found +- +-@pytest.mark.ds50026 +-def test_ticketldbm_audit(topology_st): +- """When updating LDBM config attributes, those attributes/values are not listed +- in the audit log +- +- :id: 5bf75c47-a283-430e-a65c-3c5fd8dbadb8 +- :setup: Standalone Instance +- :steps: +- 1. Enable audit log +- 2. Update a set of config attrs in LDBM config +- 3. Disable audit log (to restore the default config) +- 4. Check that config attrs are listed in the audit log +- :expectedresults: +- 1. Should succeeds +- 2. Should succeeds +- 3. Should succeeds +- 4. Should succeeds +- """ +- inst = topology_st[0] +- +- inst.config.enable_log('audit') +- +- #inst.ds_paths.audit_log +- attrs = ['nsslapd-lookthroughlimit', 'nsslapd-pagedidlistscanlimit', 'nsslapd-idlistscanlimit', 'nsslapd-db-locks'] +- mods = [] +- for attr in attrs: +- mods.append((ldap.MOD_REPLACE, attr, b'10001')) +- inst.modify_s(DN_CONFIG_LDBM, mods) +- inst.config.enable_log('audit') +- +- for attr in attrs: +- log.info("Check %s is replaced in the audit log" % attr) +- regex = re.compile("^replace: %s" % attr) +- assert audit_pattern_found(inst, regex) +- +- +-if __name__ == '__main__': +- # Run isolated +- # -s for DEBUG mode +- CURRENT_FILE = os.path.realpath(__file__) +- pytest.main("-s %s" % CURRENT_FILE) +- +- +diff --git a/ldap/servers/slapd/back-ldbm/ldbm_bind.c b/ldap/servers/slapd/back-ldbm/ldbm_bind.c +index fa450ecd5..38d115a32 100644 +--- a/ldap/servers/slapd/back-ldbm/ldbm_bind.c ++++ b/ldap/servers/slapd/back-ldbm/ldbm_bind.c +@@ -76,8 +76,8 @@ ldbm_back_bind(Slapi_PBlock *pb) + case LDAP_AUTH_SIMPLE: { + Slapi_Value cv; + if (slapi_entry_attr_find(e->ep_entry, "userpassword", &attr) != 0) { +- slapi_send_ldap_result(pb, LDAP_INAPPROPRIATE_AUTH, NULL, +- NULL, 0, NULL); ++ slapi_pblock_set(pb, SLAPI_PB_RESULT_TEXT, "Entry does not have userpassword set"); ++ slapi_send_ldap_result(pb, LDAP_INVALID_CREDENTIALS, NULL, NULL, 0, NULL); + CACHE_RETURN(&inst->inst_cache, &e); + rc = SLAPI_BIND_FAIL; + goto bail; +diff --git a/ldap/servers/slapd/dse.c b/ldap/servers/slapd/dse.c +index b22c8e6b3..4337a0ed9 100644 +--- a/ldap/servers/slapd/dse.c ++++ b/ldap/servers/slapd/dse.c +@@ -1431,7 +1431,8 @@ dse_bind(Slapi_PBlock *pb) /* JCM There should only be one exit point from this + + ec = dse_get_entry_copy(pdse, sdn, DSE_USE_LOCK); + if (ec == NULL) { +- slapi_send_ldap_result(pb, LDAP_NO_SUCH_OBJECT, NULL, NULL, 0, NULL); ++ slapi_pblock_set(pb, SLAPI_PB_RESULT_TEXT, "Entry does not exist"); ++ slapi_send_ldap_result(pb, LDAP_INVALID_CREDENTIALS, NULL, NULL, 0, NULL); + return (SLAPI_BIND_FAIL); + } + +@@ -1439,7 +1440,8 @@ dse_bind(Slapi_PBlock *pb) /* JCM There should only be one exit point from this + case LDAP_AUTH_SIMPLE: { + Slapi_Value cv; + if (slapi_entry_attr_find(ec, "userpassword", &attr) != 0) { +- slapi_send_ldap_result(pb, LDAP_INAPPROPRIATE_AUTH, NULL, NULL, 0, NULL); ++ slapi_pblock_set(pb, SLAPI_PB_RESULT_TEXT, "Entry does not have userpassword set"); ++ slapi_send_ldap_result(pb, LDAP_INVALID_CREDENTIALS, NULL, NULL, 0, NULL); + slapi_entry_free(ec); + return SLAPI_BIND_FAIL; + } +@@ -1447,6 +1449,7 @@ dse_bind(Slapi_PBlock *pb) /* JCM There should only be one exit point from this + + slapi_value_init_berval(&cv, cred); + if (slapi_pw_find_sv(bvals, &cv) != 0) { ++ slapi_pblock_set(pb, SLAPI_PB_RESULT_TEXT, "Invalid credentials"); + slapi_send_ldap_result(pb, LDAP_INVALID_CREDENTIALS, NULL, NULL, 0, NULL); + slapi_entry_free(ec); + value_done(&cv); +-- +2.30.2 + diff --git a/SOURCES/0025-Issue-4759-Fix-coverity-issue-4760.patch b/SOURCES/0025-Issue-4759-Fix-coverity-issue-4760.patch new file mode 100644 index 0000000..b11d894 --- /dev/null +++ b/SOURCES/0025-Issue-4759-Fix-coverity-issue-4760.patch @@ -0,0 +1,74 @@ +From 8b236bc2c22ba907a9d8007889b7017122c26c2c Mon Sep 17 00:00:00 2001 +From: tbordaz +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 + diff --git a/SPECS/389-ds-base.spec b/SPECS/389-ds-base.spec index 70fb029..b55eb76 100644 --- a/SPECS/389-ds-base.spec +++ b/SPECS/389-ds-base.spec @@ -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 - 1.3.10.2-12 +- Bump version to 1.3.10.2-12 + +* Mon May 5 2021 Thierry Bordaz - 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 - 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