Add more debug logs for reviewer suggestion that show up in trace

There are often support questions for the reviewer suggestion where a
user X wants to know why user Y was not suggested when Z was typed.
There are many reasons why Y may not be suggested, e.g. Y doesn't match
the query, Y can't see the change, Y is owner of the change, Y is
already a reviewer of the change, X can't see Y, a plugin drops Y etc.
By having detailed information from a trace such questions can be
answered much easier.

The reviewer suggestion already had a lot of debug logs, but some
important information was not logged yet:

- the account visibility setting (important to understand if user X can
  see user Y)
- the account index query (wasn't logged automatically since for
  performance reasons we read raw data here)
- skipping of change owner and existing reviewers
- suggestions of groups

Example trace:
[2018-08-10 13:09:39,928] [HTTP-75] TRACE com.google.gerrit.httpd.restapi.RestApiServlet : Received REST request: GET /a/changes/178/suggest_reviewers (parameters: [trace, q]) [CONTEXT forced=true TRACE_ID="1533899379928-2d0c7a5d" ]
[2018-08-10 13:09:39,929] [HTTP-75] TRACE com.google.gerrit.httpd.restapi.RestApiServlet : Calling user: admin [CONTEXT forced=true TRACE_ID="1533899379928-2d0c7a5d" ]
[2018-08-10 13:09:39,930] [HTTP-75] DEBUG com.google.gerrit.index.query.QueryProcessor : Query options: QueryOptions{config=IndexConfig{maxLimit=2147483647, maxPages=2147483647, maxTerms=1024, separateChangeSubIndexes=true}, start=0, limit=2147483647, fields=[project]} [CONTEXT forced=true TRACE_ID="1533899379928-2d0c7a5d" ]
[2018-08-10 13:09:39,935] [HTTP-75] DEBUG com.google.gerrit.index.query.QueryProcessor : changes index query[0]:
change:178
[CONTEXT forced=true TRACE_ID="1533899379928-2d0c7a5d" ]
[2018-08-10 13:09:39,946] [HTTP-75] DEBUG com.google.gerrit.index.query.QueryProcessor : Matches[0]:
[ChangeData{178}]
[CONTEXT forced=true TRACE_ID="1533899379928-2d0c7a5d" ]
[2018-08-10 13:09:39,970] [HTTP-75] DEBUG com.google.gerrit.server.restapi.change.SuggestReviewers : AccountVisibility: ALL [CONTEXT forced=true TRACE_ID="1533899379928-2d0c7a5d" ]
[2018-08-10 13:09:39,973] [HTTP-75] DEBUG com.google.gerrit.server.restapi.change.ReviewersUtil : Suggesting reviewers for change 178 to user admin. [CONTEXT forced=true TRACE_ID="1533899379928-2d0c7a5d" ]
[2018-08-10 13:09:39,973] [HTTP-75] DEBUG com.google.gerrit.server.restapi.change.ReviewersUtil : Query: adm [CONTEXT forced=true TRACE_ID="1533899379928-2d0c7a5d" ]
[2018-08-10 13:09:39,975] [HTTP-75] DEBUG com.google.gerrit.server.restapi.change.ReviewersUtil : accounts index query: (inactive:1 (name:adm OR username:adm)) [CONTEXT forced=true TRACE_ID="1533899379928-2d0c7a5d" ]
[2018-08-10 13:09:39,980] [HTTP-75] DEBUG com.google.gerrit.server.restapi.change.ReviewersUtil : Matches: [1000000] [CONTEXT forced=true TRACE_ID="1533899379928-2d0c7a5d" ]
[2018-08-10 13:09:39,980] [HTTP-75] DEBUG com.google.gerrit.server.restapi.change.ReviewersUtil : Candidate list: [1000000] [CONTEXT forced=true TRACE_ID="1533899379928-2d0c7a5d" ]
[2018-08-10 13:09:39,980] [HTTP-75] DEBUG com.google.gerrit.server.restapi.change.ReviewerRecommender : Candidates [1000000] [CONTEXT forced=true TRACE_ID="1533899379928-2d0c7a5d" ]
[2018-08-10 13:09:39,980] [HTTP-75] DEBUG com.google.gerrit.server.restapi.change.ReviewerRecommender : query: adm [CONTEXT forced=true TRACE_ID="1533899379928-2d0c7a5d" ]
[2018-08-10 13:09:39,980] [HTTP-75] DEBUG com.google.gerrit.server.restapi.change.ReviewerRecommender : base weight: 1.0 [CONTEXT forced=true TRACE_ID="1533899379928-2d0c7a5d" ]
[2018-08-10 13:09:39,993] [HTTP-75] DEBUG com.google.gerrit.index.query.QueryProcessor : Query options: QueryOptions{config=IndexConfig{maxLimit=2147483647, maxPages=2147483647, maxTerms=1024, separateChangeSubIndexes=true}, start=0, limit=26, fields=[project]} [CONTEXT forced=true TRACE_ID="1533899379928-2d0c7a5d" ]
[2018-08-10 13:09:39,994] [HTTP-75] DEBUG com.google.gerrit.index.query.QueryProcessor : changes index query[0]:
(project:foo (label:Code-Review OR label:Verified))
[CONTEXT forced=true TRACE_ID="1533899379928-2d0c7a5d" ]
[2018-08-10 13:09:39,994] [HTTP-75] DEBUG com.google.gerrit.index.query.QueryProcessor : Query options: QueryOptions{config=IndexConfig{maxLimit=2147483647, maxPages=2147483647, maxTerms=1024, separateChangeSubIndexes=true}, start=0, limit=26, fields=[project]} [CONTEXT forced=true TRACE_ID="1533899379928-2d0c7a5d" ]
[2018-08-10 13:09:39,994] [HTTP-75] DEBUG com.google.gerrit.index.query.QueryProcessor : changes index query[1]:
(project:foo owner:1000000)
[CONTEXT forced=true TRACE_ID="1533899379928-2d0c7a5d" ]
[2018-08-10 13:09:39,994] [HTTP-75] DEBUG com.google.gerrit.index.query.QueryProcessor : Query options: QueryOptions{config=IndexConfig{maxLimit=2147483647, maxPages=2147483647, maxTerms=1024, separateChangeSubIndexes=true}, start=0, limit=26, fields=[project]} [CONTEXT forced=true TRACE_ID="1533899379928-2d0c7a5d" ]
[2018-08-10 13:09:39,994] [HTTP-75] DEBUG com.google.gerrit.index.query.QueryProcessor : changes index query[2]:
(project:foo commentby:1000000)
[CONTEXT forced=true TRACE_ID="1533899379928-2d0c7a5d" ]
[2018-08-10 13:09:40,002] [HTTP-75] DEBUG com.google.gerrit.index.query.QueryProcessor : Matches[0]:
[ChangeData{179}, ChangeData{177}, ChangeData{178}, ChangeData{176}, ChangeData{174}, ChangeData{172}, ChangeData{141}, ChangeData{140}, ChangeData{139}, ChangeData{72}, ChangeData{41}, ChangeData{137}]
[CONTEXT forced=true TRACE_ID="1533899379928-2d0c7a5d" ]
[2018-08-10 13:09:40,004] [HTTP-75] DEBUG com.google.gerrit.index.query.QueryProcessor : Matches[1]:
[ChangeData{179}, ChangeData{177}, ChangeData{178}, ChangeData{176}, ChangeData{175}, ChangeData{174}, ChangeData{173}, ChangeData{172}, ChangeData{142}, ChangeData{141}, ChangeData{140}, ChangeData{139}, ChangeData{72}, ChangeData{41}, ChangeData{137}, ChangeData{39}, ChangeData{40}, ChangeData{6}, ChangeData{4}]
[CONTEXT forced=true TRACE_ID="1533899379928-2d0c7a5d" ]
[2018-08-10 13:09:40,007] [HTTP-75] DEBUG com.google.gerrit.index.query.QueryProcessor : Matches[2]:
[ChangeData{179}, ChangeData{177}, ChangeData{178}, ChangeData{176}, ChangeData{175}, ChangeData{174}, ChangeData{173}, ChangeData{172}, ChangeData{142}, ChangeData{141}, ChangeData{140}, ChangeData{139}, ChangeData{72}, ChangeData{41}, ChangeData{137}, ChangeData{39}, ChangeData{104}, ChangeData{40}, ChangeData{6}, ChangeData{4}]
[CONTEXT forced=true TRACE_ID="1533899379928-2d0c7a5d" ]
[2018-08-10 13:09:40,007] [HTTP-75] DEBUG com.google.gerrit.server.restapi.change.ReviewerRecommender : Base reviewer scores: {1000000=149.0} [CONTEXT forced=true TRACE_ID="1533899379928-2d0c7a5d" ]
[2018-08-10 13:09:40,008] [HTTP-75] DEBUG com.google.gerrit.server.restapi.change.ReviewerRecommender : Reviewer scores: {1000000=149.0} [CONTEXT forced=true TRACE_ID="1533899379928-2d0c7a5d" ]
[2018-08-10 13:09:40,008] [HTTP-75] DEBUG com.google.gerrit.server.restapi.change.ReviewerRecommender : Remove change owner 1000000 [CONTEXT forced=true TRACE_ID="1533899379928-2d0c7a5d" ]
[2018-08-10 13:09:40,012] [HTTP-75] DEBUG com.google.gerrit.server.restapi.change.ReviewerRecommender : Sorted suggestions: [] [CONTEXT forced=true TRACE_ID="1533899379928-2d0c7a5d" ]
[2018-08-10 13:09:40,012] [HTTP-75] DEBUG com.google.gerrit.server.restapi.change.ReviewersUtil : Sorted recommendations: [] [CONTEXT forced=true TRACE_ID="1533899379928-2d0c7a5d" ]
[2018-08-10 13:09:40,012] [HTTP-75] DEBUG com.google.gerrit.server.restapi.change.ReviewersUtil : Filtered recommendations: [] [CONTEXT forced=true TRACE_ID="1533899379928-2d0c7a5d" ]
[2018-08-10 13:09:40,017] [HTTP-75] DEBUG com.google.gerrit.server.restapi.change.ReviewersUtil : maxAllowedWithoutConfirmation: 10 [CONTEXT forced=true TRACE_ID="1533899379928-2d0c7a5d" ]
[2018-08-10 13:09:40,020] [HTTP-75] DEBUG com.google.gerrit.server.restapi.change.ReviewersUtil : Suggest group ca1fd42646e71d8081add52fbb0171a8504c97cd [CONTEXT forced=true TRACE_ID="1533899379928-2d0c7a5d" ]
[2018-08-10 13:09:40,020] [HTTP-75] DEBUG com.google.gerrit.server.restapi.change.ReviewersUtil : Suggested reviewers: [g/ca1fd42646e71d8081add52fbb0171a8504c97cd] [CONTEXT forced=true TRACE_ID="1533899379928-2d0c7a5d" ]
[2018-08-10 13:09:40,021] [HTTP-75] TRACE com.google.gerrit.httpd.restapi.RestApiServlet : REST call succeeded: 200 [CONTEXT forced=true TRACE_ID="1533899379928-2d0c7a5d" ]

Change-Id: I80ca648dbd2bb17b6b44f7177a0640406279b09a
Signed-off-by: Edwin Kempin <ekempin@google.com>

java/com/google/gerrit/server/restapi/change/ReviewerRecommender.java

@@ -107,8 +107,13 @@ public class ReviewerRecommender {
       ProjectState projectState,
       List<Account.Id> candidateList)
       throws OrmException, IOException, ConfigInvalidException {
+    logger.atFine().log("Candidates %s", candidateList);
+
     String query = suggestReviewers.getQuery();
+    logger.atFine().log("query: %s", query);
+
     double baseWeight = config.getInt("addReviewer", "baseWeight", 1);
+    logger.atFine().log("base weight: %s", baseWeight);
 
     Map<Account.Id, MutableDouble> reviewerScores;
     if (Strings.isNullOrEmpty(query)) {
@@ -116,6 +121,7 @@ public class ReviewerRecommender {
     } else {
       reviewerScores = baseRankingForCandidateList(candidateList, projectState, baseWeight);
     }
+    logger.atFine().log("Base reviewer scores: %s", reviewerScores);
 
     // Send the query along with a candidate list to all plugins and merge the
     // results. Plugins don't necessarily need to use the candidates list, they
@@ -163,6 +169,7 @@ public class ReviewerRecommender {
           }
         }
       }
+      logger.atFine().log("Reviewer scores: %s", reviewerScores);
     } catch (ExecutionException | InterruptedException e) {
       logger.atSevere().withCause(e).log("Exception while suggesting reviewers");
       return ImmutableList.of();
@@ -170,12 +177,20 @@ public class ReviewerRecommender {
 
     if (changeNotes != null) {
       // Remove change owner
-      reviewerScores.remove(changeNotes.getChange().getOwner());
+      if (reviewerScores.remove(changeNotes.getChange().getOwner()) != null) {
+        logger.atFine().log("Remove change owner %s", changeNotes.getChange().getOwner());
+      }
 
       // Remove existing reviewers
-      reviewerScores
-          .keySet()
-          .removeAll(approvalsUtil.getReviewers(dbProvider.get(), changeNotes).byState(REVIEWER));
+      approvalsUtil
+          .getReviewers(dbProvider.get(), changeNotes)
+          .byState(REVIEWER)
+          .forEach(
+              r -> {
+                if (reviewerScores.remove(r) != null) {
+                  logger.atFine().log("Remove existing reviewer %s", r);
+                }
+              });
     }
 
     // Sort results
@@ -185,6 +200,7 @@ public class ReviewerRecommender {
             .stream()
             .sorted(Collections.reverseOrder(Map.Entry.comparingByValue()));
     List<Account.Id> sortedSuggestions = sorted.map(Map.Entry::getKey).collect(toList());
+    logger.atFine().log("Sorted suggestions: %s", sortedSuggestions);
     return sortedSuggestions;
   }