Merge pull request #74 from ao508/more-logging

More logging for datadog

src/main/java/org/mskcc/smile/service/impl/CmoLabelGeneratorServiceImpl.java

@@ -324,7 +324,7 @@ private String resolveNucleicAcidAbbreviation(String sampleTypeString,
                     return "d";
             }
         } catch (Exception e) {
-            LOG.warn("Could not resolve sample type acid from 'sampleType' - using default 'd'");
+            LOG.warn("Could not resolve nucleic acid from 'sampleType' - using default 'd'");
         }
         // if nucleic acid abbreviation is still unknown then attempt to resolve from
         // sample metadata --> cmo sample id fields --> naToExtract
@@ -385,8 +385,8 @@ public String resolveSampleTypeAbbreviation(String specimenTypeValue, String sam
                 }
             }
         } catch (Exception e) {
-            LOG.warn("Could not resolve specimen type acid from 'specimenType': "
-                    + specimenTypeValue);
+            LOG.warn("Could not resolve specimen type from 'specimenType': "
+                    + specimenTypeValue + ". Attempting from sample class.");
         }
 
         // if abbreviation is still not resolved then try to resolve from sample class
@@ -402,9 +402,10 @@ public String resolveSampleTypeAbbreviation(String specimenTypeValue, String sam
             // is initialized to default 'F'
         }
 
-        if (sampleTypeAbbreviation == "F") {
+        if (sampleTypeAbbreviation.equalsIgnoreCase("F")) {
             LOG.warn("Could not resolve sample type abbreviation from specimen type,"
-                     + " sample origin, or sample class - using default 'F' ");
+                     + " sample origin, or sample class - using default 'F': (" + specimenTypeValue
+                    + ", " + sampleOriginValue + ", " + cmoSampleClassValue + ")");
         }
         return sampleTypeAbbreviation;
     }
@@ -581,9 +582,9 @@ public String generateValidationReport(String originalJson, String filteredJson)
         // would be more helpful to have as a reference when debugging the error
         if (!filteredJsonMap.containsKey("status")) {
             allValid = Boolean.FALSE;
-            builder.append("Request JSON missing validation report ('status') post-validation:");
-            builder.append("\nOriginal JSON contents:\n")
-                    .append(originalJson).append("\nFiltered JSON contents:\n")
+            builder.append("[label-generator] Request JSON missing validation report ('status') ");
+            builder.append("post-validation: Original JSON contents: ")
+                    .append(originalJson).append(" Filtered JSON contents: ")
                     .append(filteredJson);
         } else {
             Map<String, Object> statusMap = (Map<String, Object>) filteredJsonMap.get("status");
@@ -593,7 +594,7 @@ public String generateValidationReport(String originalJson, String filteredJson)
             // if request validation report is not empty then log for ddog
             if (!validationReport.isEmpty()) {
                 allValid = Boolean.FALSE;
-                builder.append("Request-level status and validation report for request '")
+                builder.append("[label-generator] Request-level status and validation report for request '")
                         .append(requestId)
                         .append("': ")
                         .append(mapper.writeValueAsString(statusMap));
@@ -616,13 +617,13 @@ public String generateValidationReport(String originalJson, String filteredJson)
                             sampleMap.get("igoId"), sampleMap.get("primaryId")).toString();
                     if (!sampleValidationReport.isEmpty()) {
                         allValid = Boolean.FALSE;
-                        builder.append("\nValidation report for sample '")
+                        builder.append("\n[label-generator] Validation report for sample '")
                                 .append(sampleId)
                                 .append("': ")
                                 .append(mapper.writeValueAsString(sampleStatusMap));
                     }
                 } catch (NullPointerException e) {
-                    builder.append("\nNo known identifiers in current sample data: ")
+                    builder.append("\n[label-generator] No known identifiers in current sample data: ")
                             .append(mapper.writeValueAsString(sampleMap))
                             .append(", Validation report for unknown sample: ")
                             .append(mapper.writeValueAsString(sampleStatusMap));

src/main/java/org/mskcc/smile/service/impl/LabelGenMessageHandlingServiceImpl.java

@@ -145,7 +145,8 @@ public void run() {
                             }
                         } catch (Exception e) {
                             LOG.error("Error occurred during attempt to publish request "
-                                    + "to destination topic", e);
+                                    + "to destination topic: TOPIC=" + igoRequestDest
+                                    + ", JSON=" + requestJson, e);
                         }
                     }
                     if (interrupted && igoRequestQueue.isEmpty()) {
@@ -392,22 +393,25 @@ private String resolveAndUpdateCmoSampleLabel(String samplePrimaryId,
                 if (matchingSample.getCmoSampleName().equals(matchingSample.getInvestigatorSampleId())) {
                     return matchingSample.getCmoSampleName();
                 } else {
-                    LOG.error("Falling back on existing cmo sample name for sample.", e);
+                    LOG.error("IllegalStateException thrown. Falling back on existing CMO label for sample: "
+                            + samplePrimaryId, e);
                     return matchingSample.getCmoSampleName();
                 }
             } catch (NullPointerException e2) {
-                LOG.error("NPE caught during label generation check: ", e2);
-                LOG.error("Falling back on existing cmo sample name for sample.");
+                LOG.error("NPE caught during label generation check. Falling back on existing CMO label "
+                        + "name for sample: " + samplePrimaryId, e2);
                 return matchingSample.getCmoSampleName();
             }
             if (!updateRequired) {
-                LOG.info("No change detected for CMO sample label metadata - using "
-                        + "existing CMO label for matching IGO sample from database.");
+                LOG.info("No change detected for CMO sample label metadata. Falling back on "
+                        + "existing CMO label for matching IGO sample from database "
+                        + "for sample: " + samplePrimaryId);
                 return matchingSample.getCmoSampleName();
             }
         }
         LOG.info("Changes detected in CMO sample label metadata - "
-                    + "updating sample CMO label to newly generated label.");
+                    + "updating sample CMO label to newly generated label: "
+                + samplePrimaryId + ", new label: " + newCmoSampleLabel);
         return newCmoSampleLabel;
     }
 
@@ -479,7 +483,7 @@ public void initialize(Gateway gateway) throws Exception {
             initializeMessageHandlers();
             initialized = true;
         } else {
-            LOG.error("Messaging Handler Service has already been initialized, ignoring request.\n");
+            LOG.error("Messaging Handler Service has already been initialized, ignoring request.");
         }
     }
 

src/main/resources/application.properties.EXAMPLE

@@ -34,5 +34,3 @@ num.promoted_request_handler_threads=
 # publishing failures filepath
 smile.publishing_failures_filepath=
 
-# detailed consistency checking logger filepath
-cmo_label_generator.request_logger_filepath=