[GP-4316] Jira debug logging

changes/add_jira-debug-log.md

@@ -0,0 +1,2 @@
+Debug logging for jira issues
+

plugin-jira/src/main/java/ca/on/oicr/gsi/shesmu/jira/Issue.java

@@ -88,4 +88,16 @@ public void setKey(String key) {
   public void setSelf(String self) {
     this.self = self;
   }
+
+  public String toString() {
+    return new StringBuilder("Issue with fields = ")
+        .append(fields)
+        .append(", id = ")
+        .append(id)
+        .append(", key = ")
+        .append(key)
+        .append(", self = ")
+        .append(self)
+        .toString();
+  }
 }

plugin-jira/src/main/java/ca/on/oicr/gsi/shesmu/jira/IssueAction.java

@@ -3,6 +3,8 @@
 import ca.on.oicr.gsi.shesmu.jira.IssueVerb.Close;
 import ca.on.oicr.gsi.shesmu.jira.IssueVerb.Open;
 import ca.on.oicr.gsi.shesmu.plugin.AlgebraicValue;
+import ca.on.oicr.gsi.shesmu.plugin.Definer;
+import ca.on.oicr.gsi.shesmu.plugin.LogLevel;
 import ca.on.oicr.gsi.shesmu.plugin.action.Action;
 import ca.on.oicr.gsi.shesmu.plugin.action.ActionParameter;
 import ca.on.oicr.gsi.shesmu.plugin.action.ActionServices;
@@ -122,10 +124,16 @@ public ActionState perform(
     if (connection == null) {
       // 'connection' is a bit of a misnomer - it's the Definer supplied by the PluginManager.
       // It should never be null. Very bad things have happened if it's null
+      // We also can't log through the Definer if we have no Definer :(
       System.err.println("JIRA Connection Definer for " + issueUrl + " is null.");
       return ActionState.FAILED;
     }
     final var current = connection.get();
+    ((Definer<JiraConnection>) connection)
+        .log(
+            new StringBuilder("Performing jira updates with ").append(current).toString(),
+            LogLevel.DEBUG,
+            new TreeMap<>());
     requests.labels(current.url(), current.projectKey()).inc();
     try {
       final var issues =
@@ -141,6 +149,11 @@ public ActionState perform(
                   Issue.TYPE.name(),
                   Issue.UPDATED.name()));
       this.issues = issues.stream().map(Issue::getKey).collect(Collectors.toSet());
+      ((Definer<JiraConnection>) connection)
+          .log(
+              new StringBuilder("Got ").append(issues.isEmpty() ? "nothing" : issues).toString(),
+              LogLevel.DEBUG,
+              new TreeMap<>());
       final var missingLabels = new TreeSet<String>();
       final var result =
           verb.perform(
@@ -165,7 +178,7 @@ public ActionState perform(
       return result;
     } catch (final Exception e) {
       failure.labels(connection.get().url(), connection.get().projectKey()).inc();
-      e.printStackTrace();
+      ((Definer<JiraConnection>) connection).log(e.toString(), LogLevel.ERROR, new TreeMap<>());
       return ActionState.UNKNOWN;
     }
   }

plugin-jira/src/main/java/ca/on/oicr/gsi/shesmu/jira/IssueVerb.java

@@ -46,7 +46,28 @@ public ActionState perform(
         Consumer<Issue> bestMatch)
         throws URISyntaxException, IOException, InterruptedException {
       JiraConnection connection = definer.get();
+      Map<String, String> lokiLabels = new HashMap<>();
+      lokiLabels.put("verb", "close");
+      ((Definer<JiraConnection>) definer)
+          .log(
+              new StringBuilder("Trying to close ")
+                  .append(issues.isEmpty() ? "nothing" : issues)
+                  .append(" to one of ")
+                  .append(connection.closedStatuses().toList())
+                  .toString(),
+              LogLevel.DEBUG,
+              lokiLabels);
       for (final var issue : issues) {
+        lokiLabels.put("issue", issue.getKey());
+        ((Definer<JiraConnection>) definer)
+            .log(
+                new StringBuilder("Attempting to close ")
+                    .append(issue.getKey())
+                    .append(" whose status is ")
+                    .append(issue.extract(Issue.STATUS))
+                    .toString(),
+                LogLevel.DEBUG,
+                lokiLabels);
         if (issue
             .extract(Issue.STATUS)
             .map(s -> connection.closedStatuses().noneMatch(s.name()::equalsIgnoreCase))
@@ -59,9 +80,6 @@ public ActionState perform(
                 .append(issue.getKey())
                 .append("\nConnection: ")
                 .append(connection);
-            Map<String, String> lokiLabels = new HashMap<>();
-            lokiLabels.put("issue", issue.getKey());
-            lokiLabels.put("verb", "close");
             ((Definer<JiraConnection>) definer)
                 .log(errorBuilder.toString(), LogLevel.ERROR, lokiLabels);
             return ActionState.FAILED;
@@ -126,17 +144,46 @@ public ActionState perform(
         Consumer<Issue> bestMatch)
         throws URISyntaxException, IOException, InterruptedException {
       JiraConnection connection = definer.get();
+      Map<String, String> lokiLabels = new HashMap<>();
+      lokiLabels.put("verb", "open");
+      ((Definer<JiraConnection>) definer)
+          .log(
+              new StringBuilder("Trying to open ")
+                  .append(issues.isEmpty() ? "nothing" : issues)
+                  .append(" to something other than ")
+                  .append(connection.closedStatuses().toList())
+                  .toString(),
+              LogLevel.DEBUG,
+              new TreeMap<>());
       if (issues.stream()
           .anyMatch(
               issue ->
                   issue
                       .extract(Issue.STATUS)
                       .map(
                           status -> {
+                            lokiLabels.put("issue", issue.getKey());
+                            ((Definer<JiraConnection>) definer)
+                                .log(
+                                    new StringBuilder(issue.getKey())
+                                        .append(" is of status ")
+                                        .append(issue.extract(Issue.STATUS))
+                                        .toString(),
+                                    LogLevel.DEBUG,
+                                    lokiLabels);
                             final var isOpen =
                                 connection
                                     .closedStatuses()
                                     .noneMatch(status.name()::equalsIgnoreCase);
+                            ((Definer<JiraConnection>) definer)
+                                .log(
+                                    new StringBuilder("Is issue ")
+                                        .append(issue.getKey())
+                                        .append(" already open?: ")
+                                        .append(isOpen)
+                                        .toString(),
+                                    LogLevel.DEBUG,
+                                    lokiLabels);
                             if (isOpen) {
                               bestMatch.accept(issue);
                             }
@@ -147,11 +194,23 @@ public ActionState perform(
       }
 
       for (final var issue : issues) {
+        lokiLabels.put("issue", issue.getKey());
+        ((Definer<JiraConnection>) definer)
+            .log(
+                new StringBuilder("Attempting to open ")
+                    .append(issue.getKey())
+                    .append(" whose status is ")
+                    .append(issue.extract(Issue.STATUS))
+                    .toString(),
+                LogLevel.DEBUG,
+                lokiLabels);
         if (connection.transition(issue, Stream::noneMatch, comment)) {
           bestMatch.accept(issue);
           return ActionState.SUCCEEDED;
         }
       }
+      ((Definer<JiraConnection>) definer)
+          .log("No other attempts worked, creating an issue...", LogLevel.DEBUG, lokiLabels);
       bestMatch.accept(connection.createIssue(summary, description, assignee, labels, type));
 
       return ActionState.SUCCEEDED;

plugin-jira/src/main/java/ca/on/oicr/gsi/shesmu/jira/JiraConnection.java

@@ -194,6 +194,19 @@ Issue createIssue(
       throws URISyntaxException, IOException, InterruptedException {
     final var request = new Issue();
     final var project = new Project();
+    Map<String, String> lokiLabels = new HashMap<>();
+    lokiLabels.put("verb", "open");
+
+    StringBuilder logmsg =
+        new StringBuilder("Attempting to create a new issue in ")
+            .append(projectKey)
+            .append(" with ")
+            .append(summary)
+            .append(", ")
+            .append(description);
+    assignee.ifPresent(s -> logmsg.append(", ").append(s));
+    ((Definer<JiraConnection>) definer).log(logmsg.toString(), LogLevel.DEBUG, lokiLabels);
+
     project.setId(projectId);
     request.put(Issue.PROJECT, project);
     request.put(Issue.SUMMARY, summary);
@@ -214,6 +227,16 @@ Issue createIssue(
     issueType.setName(type);
     request.put(Issue.TYPE, issueType);
 
+    ((Definer<JiraConnection>) definer)
+        .log(
+            new StringBuilder("Sending request ")
+                .append(MAPPER.writeValueAsString(request))
+                .append(" to ")
+                .append(String.format("%s/rest/api/%s/issue", url, version.slug()))
+                .toString(),
+            LogLevel.DEBUG,
+            lokiLabels);
+
     IssueAction.issueCreates.labels(url, projectKey).inc();
     final var builder =
         HttpRequest.newBuilder(new URI(String.format("%s/rest/api/%s/issue", url, version.slug())));
@@ -225,6 +248,11 @@ Issue createIssue(
                 .POST(BodyPublishers.ofString(MAPPER.writeValueAsString(request)))
                 .build(),
             BodyHandlers.ofString());
+
+    ((Definer<JiraConnection>) definer)
+        .log(
+            new StringBuilder("Got result ").append(result).toString(), LogLevel.DEBUG, lokiLabels);
+
     if (result.statusCode() / 100 != 2) {
       throw new RuntimeException(
           String.format(
@@ -301,6 +329,11 @@ List<Issue> search(String jql, Set<String> fields)
     request.setFields(fields);
     request.setJql(jql);
 
+    ((Definer<JiraConnection>) definer)
+        .log(
+            new StringBuilder("Searching for ").append(request).toString(),
+            LogLevel.DEBUG,
+            new TreeMap<>());
     for (var page = 0; true; page++) {
       request.setStartAt(500 * page);
       final var builder =
@@ -318,6 +351,11 @@ List<Issue> search(String jql, Set<String> fields)
               .body()
               .get();
       buffer.addAll(results.getIssues());
+      ((Definer<JiraConnection>) definer)
+          .log(
+              new StringBuilder("Search returned ").append(results).toString(),
+              LogLevel.DEBUG,
+              new TreeMap<>());
       if (results.getIssues().isEmpty()) {
         break;
       }
@@ -381,6 +419,17 @@ boolean transition(
       Issue issue, BiFunction<Stream<String>, Predicate<String>, Boolean> matcher, String comment)
       throws URISyntaxException, IOException, InterruptedException {
     IssueAction.issueUpdates.labels(url, projectKey).inc();
+    Map<String, String> lokiLabels = new HashMap<>();
+    lokiLabels.put("issue", issue.getKey());
+    ((Definer<JiraConnection>) definer)
+        .log(
+            new StringBuilder("Attempting to transition issue ")
+                .append(issue.getKey())
+                .append(" with comment ")
+                .append(comment)
+                .toString(),
+            LogLevel.DEBUG,
+            lokiLabels);
     final var builder =
         HttpRequest.newBuilder(
             new URI(
@@ -395,8 +444,28 @@ boolean transition(
             .body()
             .get()
             .transitions();
+    ((Definer<JiraConnection>) definer)
+        .log(
+            new StringBuilder("Transitions available to ")
+                .append(issue.getKey())
+                .append(" are ")
+                .append(transitions)
+                .toString(),
+            LogLevel.DEBUG,
+            lokiLabels);
 
     for (final var transition : transitions) {
+      ((Definer<JiraConnection>) definer)
+          .log(
+              new StringBuilder("Attempting to apply transition ")
+                  .append(transition)
+                  .append(" to issue ")
+                  .append(issue.getKey())
+                  .append(" by matching against ")
+                  .append(closedStatuses())
+                  .toString(),
+              LogLevel.DEBUG,
+              lokiLabels);
       if (matcher.apply(closedStatuses(), transition.to().name()::equalsIgnoreCase)) {
         final var request = new TransitionRequest();
         /** "fields": { "assignee": { "name": "Will" }, "resolution": { "name": "Fixed" } } */
@@ -410,7 +479,18 @@ boolean transition(
           }
         }
         request.setTransition(transition);
-
+        ((Definer<JiraConnection>) definer)
+            .log(
+                new StringBuilder("Sending transition request ")
+                    .append(request)
+                    .append(" to ")
+                    .append(
+                        String.format(
+                            "%s/rest/api/%s/issue/%s/transitions",
+                            url, version.slug(), issue.getId()))
+                    .toString(),
+                LogLevel.DEBUG,
+                lokiLabels);
         final var requestBuilder =
             HttpRequest.newBuilder(
                 new URI(
@@ -426,6 +506,11 @@ boolean transition(
                     .POST(BodyPublishers.ofString(MAPPER.writeValueAsString(request)))
                     .build(),
                 BodyHandlers.ofString());
+        ((Definer<JiraConnection>) definer)
+            .log(
+                new StringBuilder("Got response ").append(transitionResult).toString(),
+                LogLevel.DEBUG,
+                lokiLabels);
         if (transitionResult.statusCode() / 100 != 2) {
           StringBuilder errorBuilder = new StringBuilder();
           errorBuilder
@@ -439,8 +524,6 @@ boolean transition(
               .append(MAPPER.writeValueAsString(request))
               .append(", received: ")
               .append(transitionResult.body());
-          Map<String, String> lokiLabels = new HashMap<>();
-          lokiLabels.put("issue", issue.getKey());
           ((Definer<JiraConnection>) definer)
               .log(errorBuilder.toString(), LogLevel.ERROR, lokiLabels);
           return false;
@@ -456,13 +539,29 @@ boolean transition(
         authenticationHeader.ifPresent(
             header -> commentRequestBuilder.header("Authorization", header));
 
+        ((Definer<JiraConnection>) definer)
+            .log(
+                new StringBuilder("Sending comment request ")
+                    .append(BodyPublishers.ofString(MAPPER.writeValueAsString(updateComment)))
+                    .append(" to ")
+                    .append(
+                        String.format(
+                            "%s/rest/api/%s/issue/%s/comment", url, version.slug(), issue.getId()))
+                    .toString(),
+                LogLevel.DEBUG,
+                lokiLabels);
         var commentResult =
             CLIENT.send(
                 commentRequestBuilder
                     .header("Content-Type", "application/json")
                     .POST(BodyPublishers.ofString(MAPPER.writeValueAsString(updateComment)))
                     .build(),
                 BodyHandlers.ofString());
+        ((Definer<JiraConnection>) definer)
+            .log(
+                new StringBuilder("Got response ").append(commentResult).toString(),
+                LogLevel.DEBUG,
+                lokiLabels);
         boolean isGood = commentResult.statusCode() / 100 == 2;
         if (!isGood) {
           StringBuilder errorBuilder = new StringBuilder();
@@ -471,10 +570,8 @@ boolean transition(
               .append(issue.getKey())
               .append(" using comment ")
               .append(comment)
-              .append("\nGot ")
+              .append(" and got ")
               .append(commentResult.body());
-          Map<String, String> lokiLabels = new HashMap<>();
-          lokiLabels.put("issue", issue.getKey());
           ((Definer<JiraConnection>) definer)
               .log(errorBuilder.toString(), LogLevel.ERROR, lokiLabels);
         }

plugin-jira/src/main/java/ca/on/oicr/gsi/shesmu/jira/SearchRequest.java

@@ -41,4 +41,16 @@ public void setMaxResults(int maxResults) {
   public void setStartAt(int startAt) {
     this.startAt = startAt;
   }
+
+  public String toString() {
+    return new StringBuilder("SearchRequest with fields = ")
+        .append(fields)
+        .append(", jql = ")
+        .append(jql)
+        .append(", maxResults = ")
+        .append(maxResults)
+        .append(", startAt = ")
+        .append(startAt)
+        .toString();
+  }
 }