From a8b9101a004bdc3b17da545a63f0b83af5da2e33 Mon Sep 17 00:00:00 2001 From: "Thierry bordaz (tbordaz)" Date: Fri, 17 May 2013 11:48:08 +0200 Subject: [PATCH] Ticket 47354 - Indexed search are logged with 'notes=U' in the access logs Bug Description: In the access log, the flag "notes=U" is present to warn the customer that the provided filter contains not indexed components. This flag is set independently of the fact that all entries of the database will be evaluated against the filter. So it can not be used to determine if all the entries have been scanned. Evaluated all entries is usually a performance hit for large database containing millions of entries. Fix Description: The fix consist to introduce a new flag 'notes=A' at the top level (ldbm_back_search) only when the candidate list is ALLID and all entries will be scanned. The fix also contains the update of logconv.pl to take into account this change. https://fedorahosted.org/389/ticket/47354 Reviewed by: ? Platforms tested: Fedora 17 Flag Day: no Doc impact: no --- ldap/admin/src/logconv.pl | 221 +++++++++++++++++++++++------ ldap/servers/slapd/back-ldbm/ldbm_search.c | 6 +- ldap/servers/slapd/result.c | 3 +- ldap/servers/slapd/slapi-plugin.h | 1 + 4 files changed, 187 insertions(+), 44 deletions(-) diff --git a/ldap/admin/src/logconv.pl b/ldap/admin/src/logconv.pl index efc5970..ee30abe 100755 --- a/ldap/admin/src/logconv.pl +++ b/ldap/admin/src/logconv.pl @@ -157,8 +157,10 @@ print "\nCommand: logconv.pl @ARGV\n\n"; $rootDNBindCount = 0; $anonymousBindCount = 0; -$unindexedSrchCount = 0; -$vlvNotesCount= 0; +$unindexedSrchCountNotesA = 0; +$unindexedSrchCountNotesU = 0; +$vlvNotesACount= 0; +$vlvNotesUCount= 0; $srchCount = 0; $fdTaken = 0; $fdReturned = 0; @@ -254,11 +256,16 @@ $UNBIND_CONN = "$dataLocation/unbindconn.logconv"; $UNBIND_OP = "$dataLocation/unbindop.logconv"; $EXT_CONN = "$dataLocation/extconn.logconv"; $EXT_OP = "$dataLocation/extop.logconv"; -$NOTES_ETIME = "$dataLocation/notesetime.logconv"; -$NOTES_CONN = "$dataLocation/notesconn.logconv"; -$NOTES_OP = "$dataLocation/notesop.logconv"; -$NOTES_TIME = "$dataLocation/notestime.logconv"; -$NOTES_NENTRIES = "$dataLocation/notesnentries.logconv"; +$NOTES_A_ETIME = "$dataLocation/notesAetime.logconv"; +$NOTES_A_CONN = "$dataLocation/notesAconn.logconv"; +$NOTES_A_OP = "$dataLocation/notesAop.logconv"; +$NOTES_A_TIME = "$dataLocation/notesAtime.logconv"; +$NOTES_A_NENTRIES = "$dataLocation/notesAnentries.logconv"; +$NOTES_U_ETIME = "$dataLocation/notesUetime.logconv"; +$NOTES_U_CONN = "$dataLocation/notesUconn.logconv"; +$NOTES_U_OP = "$dataLocation/notesUop.logconv"; +$NOTES_U_TIME = "$dataLocation/notesUtime.logconv"; +$NOTES_U_NENTRIES = "$dataLocation/notesUnentries.logconv"; $BADPWDCONN = "$dataLocation/badpwdconn.logconv"; $BADPWDOP = "$dataLocation/badpwdop.logconv"; $BADPWDIP = "$dataLocation/badpwdip.logconv"; @@ -641,20 +648,22 @@ print "Abandoned Requests: $abandonCount\n"; print "Smart Referrals Received: $referralCount\n"; print "\n"; print "VLV Operations: $vlvCount\n"; -print "VLV Unindexed Searches: $vlvNotesCount\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: $unindexedSrchCount\n"; +print "Unindexed Searches: $unindexedSrchCountNotesA\n"; +print "Unindexed Components: $unindexedSrchCountNotesU\n"; if ($verb eq "yes" || $usage =~ /u/){ - if ($unindexedSrchCount > 0){ + if ($unindexedSrchCountNotesA > 0){ %conn_hash = getHashFromFile($CONN_HASH); - @notesConn = getArrayFromFile($NOTES_CONN); - @notesOp = getArrayFromFile($NOTES_OP); - @notesEtime = getArrayFromFile($NOTES_ETIME); - @notesTime = getArrayFromFile($NOTES_TIME); - @notesNentries = getArrayFromFile($NOTES_NENTRIES); + @notesConn = getArrayFromFile($NOTES_A_CONN); + @notesOp = getArrayFromFile($NOTES_A_OP); + @notesEtime = getArrayFromFile($NOTES_A_ETIME); + @notesTime = getArrayFromFile($NOTES_A_TIME); + @notesNentries = getArrayFromFile($NOTES_A_NENTRIES); getInfoArraysFromFile($BASEINFO); @base_val = @fileArray1; @base_conn = @fileArray2; @@ -720,6 +729,78 @@ if ($verb eq "yes" || $usage =~ /u/){ undef @scope_conn; undef @scope_op; } + if ($unindexedSrchCountNotesU > 0){ + %conn_hash = getHashFromFile($CONN_HASH); + @notesConn = getArrayFromFile($NOTES_U_CONN); + @notesOp = getArrayFromFile($NOTES_U_OP); + @notesEtime = getArrayFromFile($NOTES_U_ETIME); + @notesTime = getArrayFromFile($NOTES_U_TIME); + @notesNentries = getArrayFromFile($NOTES_U_NENTRIES); + getInfoArraysFromFile($BASEINFO); + @base_val = @fileArray1; + @base_conn = @fileArray2; + @base_op = @fileArray3; + getInfoArraysFromFile($SCOPEINFO); + @scope_val = @fileArray1; + @scope_conn = @fileArray2; + @scope_op = @fileArray3; + getInfoArraysFromFile($FILTERINFO); + @filter_val = @fileArray1; + @filter_conn = @fileArray2; + @filter_op = @fileArray3; + + $notesCount = "1"; + for ($n = 0; $n <= $#notesEtime; $n++){ + @alreadyseenDN = (); + if($conn_hash{$notesConn[$n]} eq ""){ + $unindexedIp = "?"; + } else { + $unindexedIp = $conn_hash{$notesConn[$n]}; + } + print "\n Unindexed Components #".$notesCount."\n"; $notesCount++; + print " - Date/Time: $notesTime[$n]\n"; + print " - Connection Number: $notesConn[$n]\n"; + print " - Operation Number: $notesOp[$n]\n"; + print " - Etime: $notesEtime[$n]\n"; + print " - Nentries: $notesNentries[$n]\n"; + print " - IP Address: $unindexedIp\n"; + + for ($nnn = 0; $nnn < $baseCount; $nnn++){ + if ($notesConn[$n] eq $base_conn[$nnn] && $notesOp[$n] eq $base_op[$nnn]){ + print " - Search Base: $base_val[$nnn]\n"; + last; + } + } + for ($nnn = 0; $nnn < $scopeCount; $nnn++){ + if ($notesConn[$n] eq $scope_conn[$nnn] && $notesOp[$n] eq $scope_op[$nnn]){ + print " - Search Scope: $scope_val[$nnn]\n"; + last; + } + } + for ($nnn = 0; $nnn < $filterCount; $nnn++){ + if ($notesConn[$n] eq $filter_conn[$nnn] && $notesOp[$n] eq $filter_op[$nnn]){ + print " - Search Filter: $filter_val[$nnn]\n"; + last; + } + } + } + undef %conn_hash; + undef @notesConn; + undef @notesOp; + undef @notesEtime; + undef @notesTime; + undef @notesNentries; + undef @notesIp; + undef @filter_val; + undef @filter_conn; + undef @filter_op; + undef @base_val; + undef @base_conn; + undef @base_op; + undef @scope_val; + undef @scope_conn; + undef @scope_op; + } } # end of unindexed search report print "\n"; @@ -1276,10 +1357,14 @@ if ($usage =~ /j/i || $verb eq "yes"){ %conncount = getCounterHashFromFile($CONNCOUNT); print "\n----- Recommendations -----\n"; $recCount = "1"; - if ($unindexedSrchCount > 0){ + if ($unindexedSrchCountNotesA > 0){ print "\n $recCount. You have unindexed searches, this can be caused from a search on an unindexed attribute, or your returned results exceeded the allidsthreshold. Unindexed searches are not recommended. To refuse unindexed searches, switch \'nsslapd-require-index\' to \'on\' under your database entry (e.g. cn=UserRoot,cn=ldbm database,cn=plugins,cn=config).\n"; $recCount++; } + if ($unindexedSrchCountNotesU > 0){ + print "\n $recCount. You have unindexed components, this can be caused from a search on an unindexed attribute, or your returned results exceeded the allidsthreshold. Unindexed components are not recommended. To refuse unindexed searches, switch \'nsslapd-require-index\' to \'on\' under your database entry (e.g. cn=UserRoot,cn=ldbm database,cn=plugins,cn=config).\n"; + $recCount++; + } if ($conncount{"T1"} > 0){ print "\n $recCount. You have some connections that are are being closed by the idletimeout setting. You may want to increase the idletimeout if it is set low.\n"; $recCount++; @@ -1773,36 +1858,71 @@ sub parseLineNormal if (m/ RESULT err=/ && m/ notes=P/){ $pagedSearchCount++; } + if (m/ notes=A/){ + if ($_ =~ /conn= *([0-9]+)/i){ + $con = $1; + if ($_ =~ /op= *([0-9]+)/i){ $op = $1;} + } + for ($i=0; $i <= $vlvCount;$i++){ + if ($vlvconn[$i] eq $con && $vlvop[$i] eq $op){ $vlvNotesACount++; $isVlvNotes="1";} + } + if($isVlvNotes == 0){ + # We don't want to record vlv unindexed searches for our regular "bad" + # unindexed search stat, as VLV unindexed searches aren't that bad + $unindexedSrchCountNotesA++; + if($reportStats){ inc_stats('notesA',$s_stats,$m_stats); } + } + if ($usage =~ /u/ || $verb eq "yes"){ + if ($isVlvNnotes == 0 ){ + if ($_ =~ /etime= *([0-9.]+)/i ){ + writeFile($NOTES_A_ETIME, $1); + } + if ($_ =~ /conn= *([0-9]+)/i){ + writeFile($NOTES_A_CONN, $1); + } + if ($_ =~ /op= *([0-9]+)/i){ + writeFile($NOTES_A_OP, $1); + } + if ($_ =~ / *([0-9a-z:\/]+)/i){ + writeFile($NOTES_A_TIME, $1); + } + if ($_ =~ /nentries= *([0-9]+)/i ){ + writeFile($NOTES_A_NENTRIES, $1); + } + } + } + $isVlvNotes = 0; + } if (m/ notes=U/){ if ($_ =~ /conn= *([0-9]+)/i){ $con = $1; if ($_ =~ /op= *([0-9]+)/i){ $op = $1;} } for ($i=0; $i <= $vlvCount;$i++){ - if ($vlvconn[$i] eq $con && $vlvop[$i] eq $op){ $vlvNotesCount++; $isVlvNotes="1";} + if ($vlvconn[$i] eq $con && $vlvop[$i] eq $op){ $vlvNotesUCount++; $isVlvNotes="1";} } if($isVlvNotes == 0){ # We don't want to record vlv unindexed searches for our regular "bad" # unindexed search stat, as VLV unindexed searches aren't that bad - $unindexedSrchCount++; - if($reportStats){ inc_stats('notesu',$s_stats,$m_stats); } + $unindexedSrchCountNotesU++; + if($reportStats){ inc_stats('notesU',$s_stats,$m_stats); } } if ($usage =~ /u/ || $verb eq "yes"){ if ($isVlvNnotes == 0 ){ if ($_ =~ /etime= *([0-9.]+)/i ){ - writeFile($NOTES_ETIME, $1); + writeFile($NOTES_U_ETIME, $1); } if ($_ =~ /conn= *([0-9]+)/i){ - writeFile($NOTES_CONN, $1); + writeFile($NOTES_U_CONN, $1); } if ($_ =~ /op= *([0-9]+)/i){ - writeFile($NOTES_OP, $1); + writeFile($NOTES_U_OP, $1); } if ($_ =~ / *([0-9a-z:\/]+)/i){ - writeFile($NOTES_TIME, $1); + writeFile($NOTES_U_TIME, $1); } if ($_ =~ /nentries= *([0-9]+)/i ){ - writeFile($NOTES_NENTRIES, $1); + writeFile($NOTES_U_NENTRIES, $1); } } } @@ -2196,7 +2316,8 @@ reset_stats_block $stats->{'bind'}=0; $stats->{'anonbind'}=0; $stats->{'unbind'}=0; - $stats->{'notesu'}=0; + $stats->{'notesA'}=0; + $stats->{'notesU'}=0; $stats->{'etime'}=0; return; } @@ -2242,13 +2363,14 @@ print_stats_block $stats->{'bind'}, $stats->{'anonbind'}, $stats->{'unbind'}, - $stats->{'notesu'}, + $stats->{'notesA'}, + $stats->{'notesU'}, $stats->{'etime'}), "\n" ); } else { $stats->{'fh'}->print( "Time,time_t,Results,Search,Add,Mod,Modrdn,Moddn,Compare,Delete,Abandon,". - "Connections,SSL Conns,Bind,Anon Bind,Unbind,Unindexed,ElapsedTime\n" + "Connections,SSL Conns,Bind,Anon Bind,Unbind,Unindexed search,Unindexed component,ElapsedTime\n" ); } } @@ -2415,11 +2537,16 @@ openDataFiles open($UNBIND_OP, ">$UNBIND_OP") or do { openFailed($!, $UNBIND_OP) }; open($EXT_CONN, ">$EXT_CONN") or do { openFailed($!, $EXT_CONN) }; open($EXT_OP, ">$EXT_OP") or do { openFailed($!, $EXT_OP) }; - open($NOTES_ETIME, ">$NOTES_ETIME") or do { openFailed($!, $NOTES_ETIME) }; - open($NOTES_CONN, ">$NOTES_CONN") or do { openFailed($!, $NOTES_CONN) }; - open($NOTES_OP, ">$NOTES_OP") or do { openFailed($!, $NOTES_OP) }; - open($NOTES_TIME, ">$NOTES_TIME") or do { openFailed($!, $NOTES_TIME) }; - open($NOTES_NENTRIES, ">$NOTES_NENTRIES") or do { openFailed($!, $NOTES_NENTRIES) }; + open($NOTES_A_ETIME, ">$NOTES_A_ETIME") or do { openFailed($!, $NOTES_A_ETIME) }; + open($NOTES_A_CONN, ">$NOTES_A_CONN") or do { openFailed($!, $NOTES_A_CONN) }; + open($NOTES_A_OP, ">$NOTES_A_OP") or do { openFailed($!, $NOTES_A_OP) }; + open($NOTES_A_TIME, ">$NOTES_A_TIME") or do { openFailed($!, $NOTES_A_TIME) }; + open($NOTES_A_NENTRIES, ">$NOTES_A_NENTRIES") or do { openFailed($!, $NOTES_A_NENTRIES) }; + open($NOTES_U_ETIME, ">$NOTES_U_ETIME") or do { openFailed($!, $NOTES_U_ETIME) }; + open($NOTES_U_CONN, ">$NOTES_U_CONN") or do { openFailed($!, $NOTES_U_CONN) }; + open($NOTES_U_OP, ">$NOTES_U_OP") or do { openFailed($!, $NOTES_U_OP) }; + open($NOTES_U_TIME, ">$NOTES_U_TIME") or do { openFailed($!, $NOTES_U_TIME) }; + open($NOTES_U_NENTRIES, ">$NOTES_U_NENTRIES") or do { openFailed($!, $NOTES_U_NENTRIES) }; open($BADPWDCONN, ">$BADPWDCONN") or do { openFailed($!, $BADPWDCONN) }; open($BADPWDOP, ">$BADPWDOP") or do { openFailed($!, $BADPWDOP) }; open($BADPWDIP, ">$BADPWDIP") or do { openFailed($!, $NADPWDIP) }; @@ -2473,11 +2600,16 @@ closeDataFiles close $UNBIND_OP; close $EXT_CONN; close $EXT_OP; - close $NOTES_ETIME; - close $NOTES_CONN; - close $NOTES_OP; - close $NOTES_TIME; - close $NOTES_NENTRIES; + close $NOTES_A_ETIME; + close $NOTES_A_CONN; + close $NOTES_A_OP; + close $NOTES_A_TIME; + close $NOTES_A_NENTRIES; + close $NOTES_U_ETIME; + close $NOTES_U_CONN; + close $NOTES_U_OP; + close $NOTES_U_TIME; + close $NOTES_U_NENTRIES; close $BADPWDCONN; close $BADPWDOP; close $BADPWDIP; @@ -2531,11 +2663,16 @@ removeDataFiles unlink $UNBIND_OP; unlink $EXT_CONN; unlink $EXT_OP; - unlink $NOTES_ETIME; - unlink $NOTES_CONN; - unlink $NOTES_OP; - unlink $NOTES_TIME; - unlink $NOTES_NENTRIES; + unlink $NOTES_A_ETIME; + unlink $NOTES_A_CONN; + unlink $NOTES_A_OP; + unlink $NOTES_A_TIME; + unlink $NOTES_A_NENTRIES; + unlink $NOTES_U_ETIME; + unlink $NOTES_U_CONN; + unlink $NOTES_U_OP; + unlink $NOTES_U_TIME; + unlink $NOTES_U_NENTRIES; unlink $BADPWDCONN; unlink $BADPWDOP; unlink $BADPWDIP; diff --git a/ldap/servers/slapd/back-ldbm/ldbm_search.c b/ldap/servers/slapd/back-ldbm/ldbm_search.c index be4b63c..00cce2c 100644 --- a/ldap/servers/slapd/back-ldbm/ldbm_search.c +++ b/ldap/servers/slapd/back-ldbm/ldbm_search.c @@ -869,7 +869,7 @@ ldbm_back_search( Slapi_PBlock *pb ) * to record that fact. */ if ( NULL != candidates && ALLIDS( candidates )) { - unsigned int opnote = SLAPI_OP_NOTE_UNINDEXED; + unsigned int opnote; int ri = 0; int pr_idx = -1; @@ -892,6 +892,10 @@ ldbm_back_search( Slapi_PBlock *pb ) } } + slapi_pblock_get( pb, SLAPI_OPERATION_NOTES, &opnote ); + opnote |= SLAPI_OP_NOTE_FULL_UNINDEXED; /* the full filter leads to an unindexed search */ + opnote &= ~SLAPI_OP_NOTE_UNINDEXED; /* this note is useless because FULL_UNINDEXED includes UNINDEXED */ + slapi_pblock_set( pb, SLAPI_OPERATION_NOTES, NULL ); slapi_pblock_set( pb, SLAPI_OPERATION_NOTES, &opnote ); slapi_pblock_get( pb, SLAPI_PAGED_RESULTS_INDEX, &pr_idx ); pagedresults_set_unindexed( pb->pb_conn, pb->pb_op, pr_idx ); diff --git a/ldap/servers/slapd/result.c b/ldap/servers/slapd/result.c index e124d0b..8f64dd7 100644 --- a/ldap/servers/slapd/result.c +++ b/ldap/servers/slapd/result.c @@ -1617,7 +1617,8 @@ struct slapi_note_map { static struct slapi_note_map notemap[] = { { SLAPI_OP_NOTE_UNINDEXED, "U" }, - { SLAPI_OP_NOTE_SIMPLEPAGED, "P" } + { SLAPI_OP_NOTE_SIMPLEPAGED, "P" }, + { SLAPI_OP_NOTE_FULL_UNINDEXED, "A" } }; #define SLAPI_NOTEMAP_COUNT ( sizeof(notemap) / sizeof(struct slapi_note_map)) diff --git a/ldap/servers/slapd/slapi-plugin.h b/ldap/servers/slapd/slapi-plugin.h index ffcc928..2d618e9 100644 --- a/ldap/servers/slapd/slapi-plugin.h +++ b/ldap/servers/slapd/slapi-plugin.h @@ -6747,6 +6747,7 @@ typedef struct slapi_plugindesc { #define SLAPI_OPERATION_NOTES 57 #define SLAPI_OP_NOTE_UNINDEXED 0x01 #define SLAPI_OP_NOTE_SIMPLEPAGED 0x02 +#define SLAPI_OP_NOTE_FULL_UNINDEXED 0x04 /* Allows controls to be passed before operation object is created */ #define SLAPI_CONTROLS_ARG 58 -- 1.7.11.7