Lnk 2116 logging improvements

api/src/main/java/com/lantanagroup/link/api/ReportGenerator.java

@@ -20,9 +20,11 @@
 import org.hl7.fhir.r4.model.MeasureReport;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
+import org.slf4j.MDC;
 
 import java.text.ParseException;
 import java.util.List;
+import java.util.Map;
 import java.util.concurrent.ExecutionException;
 import java.util.concurrent.ForkJoinPool;
 import java.util.concurrent.atomic.AtomicInteger;
@@ -66,8 +68,12 @@ public void generate(QueryPhase queryPhase) throws ExecutionException, Interrupt
     AtomicInteger progress = new AtomicInteger(0);
     List<PatientOfInterestModel> pois = measureContext.getPatientsOfInterest(queryPhase);
 
+    var contextMapCopy = MDC.getCopyOfContextMap();
+
+    forkJoinPool.submit(() -> pois.parallelStream().forEach(patient -> {
+
+                MDC.setContextMap(contextMapCopy);
 
-      forkJoinPool.submit(() -> pois.parallelStream().forEach(patient -> {
                 if (StringUtils.isEmpty(patient.getId())) {
                   logger.error("Patient {} has no ID; cannot generate measure report", patient);
                   return;

api/src/main/java/com/lantanagroup/link/api/controller/ReportController.java

@@ -35,6 +35,7 @@
 import org.hl7.fhir.r4.model.MeasureReport;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
+import org.slf4j.MDC;
 import org.springframework.beans.factory.annotation.Autowired;
 import org.springframework.context.ApplicationContext;
 import org.springframework.http.HttpStatus;
@@ -397,6 +398,8 @@ private Report generateResponse(TenantService tenantService, LinkCredentials use
       report.setDeviceInfo(FhirHelper.getDevice(this.config, tenantService, validator));
       report.setQueryPlan(new YAMLMapper().writeValueAsString(queryPlan));
 
+      MDC.put("reportId", report.getId());
+
       // Preserve the version of the already-existing report
       if (existingReport != null) {
         report.setVersion(existingReport.getVersion());
@@ -408,31 +411,31 @@ private Report generateResponse(TenantService tenantService, LinkCredentials use
 
       // Scoop the data for the patients and store it
       if (config.isSkipQuery() || skipQuery) {
-        logger.info("Skipping initial query and store");
+        logger.info("Skipping initial query and store", report.getId());
         for (PatientOfInterestModel patient : reportContext.getPatientsOfInterest()) {
           if (patient.getReference() != null) {
             patient.setId(patient.getReference().replaceAll("^Patient/", ""));
           }
         }
       } else {
-        logger.info("Beginning initial query and store");
+        logger.info("Beginning initial query and store", report.getId());
         tenantService.beginReport(masterIdentifierValue);
         this.queryFhir(tenantService, criteria, reportContext, QueryPhase.INITIAL);
       }
 
       this.eventService.triggerEvent(tenantService, EventTypes.AfterPatientDataQuery, criteria, reportContext);
 
-      logger.info("Beginning initial measure evaluation");
+      logger.info("Beginning initial measure evaluation", report.getId());
       this.evaluateMeasures(tenantService, criteria, reportContext, report, QueryPhase.INITIAL, false);
 
       if (config.isSkipQuery() || skipQuery || CollectionUtils.isEmpty(reportContext.getQueryPlan().getSupplemental())) {
-        logger.info("Skipping supplemental query and store");
-        logger.info("Beginning aggregation");
+        logger.info("Skipping supplemental query and store", report.getId());
+        logger.info("Beginning aggregation", report.getId());
         this.evaluateMeasures(tenantService, criteria, reportContext, report, QueryPhase.SUPPLEMENTAL, true);
       } else {
-        logger.info("Beginning supplemental query and store");
+        logger.info("Beginning supplemental query and store", report.getId());
         this.queryFhir(tenantService, criteria, reportContext, QueryPhase.SUPPLEMENTAL);
-        logger.info("Beginning supplemental measure evaluation and aggregation");
+        logger.info("Beginning supplemental measure evaluation and aggregation", report.getId());
         this.evaluateMeasures(tenantService, criteria, reportContext, report, QueryPhase.SUPPLEMENTAL, false);
       }
 
@@ -460,6 +463,8 @@ private Report generateResponse(TenantService tenantService, LinkCredentials use
     logger.info("Statistics for report {} are:\n{}", report.getId(), this.stopwatchManager.getStatistics());
     this.stopwatchManager.reset();
 
+    MDC.clear();
+
     return report;
   }
 

api/src/main/resources/logback.xml

@@ -5,6 +5,6 @@
     <property name="LOGBACK_ROLLINGPOLICY_MAX_HISTORY" value="0"/>
     <include resource="org/springframework/boot/logging/logback/base.xml"/>
 
-    <logger name="com.lantanagroup.link" level="DEBUG"/>
+    <logger name="com.lantanagroup.link" level="INFO" />
     <logger name="org.springframework.web" level="DEBUG"/>
 </configuration>

core/src/main/java/com/lantanagroup/link/appender/MdcDbAppender.java

@@ -0,0 +1,20 @@
+package com.lantanagroup.link.appender;
+
+import ch.qos.logback.classic.db.DBAppender;
+import ch.qos.logback.classic.spi.ILoggingEvent;
+import com.lantanagroup.link.events.MdcLoggingEvent;
+
+import java.sql.Connection;
+import java.sql.PreparedStatement;
+
+public class MdcDbAppender extends DBAppender {
+
+  @Override
+  protected void subAppend(ILoggingEvent event, Connection connection, PreparedStatement insertStatement)
+          throws Throwable {
+    // use a special event with custom formatted message
+    MdcLoggingEvent customEvent = new MdcLoggingEvent(event);
+    super.subAppend(customEvent, connection, insertStatement);
+  }
+
+}

core/src/main/java/com/lantanagroup/link/db/SharedService.java

@@ -1,14 +1,19 @@
 package com.lantanagroup.link.db;
 
 import ch.qos.logback.classic.LoggerContext;
+import ch.qos.logback.classic.PatternLayout;
 import ch.qos.logback.classic.db.DBAppender;
+import ch.qos.logback.classic.encoder.PatternLayoutEncoder;
+import ch.qos.logback.classic.spi.ILoggingEvent;
 import ch.qos.logback.core.db.DataSourceConnectionSource;
+import ch.qos.logback.core.encoder.LayoutWrappingEncoder;
 import com.fasterxml.jackson.core.JsonProcessingException;
 import com.fasterxml.jackson.databind.DeserializationFeature;
 import com.fasterxml.jackson.databind.JsonMappingException;
 import com.fasterxml.jackson.databind.ObjectMapper;
 import com.lantanagroup.link.FhirContextProvider;
 import com.lantanagroup.link.Helper;
+import com.lantanagroup.link.appender.MdcDbAppender;
 import com.lantanagroup.link.auth.LinkCredentials;
 import com.lantanagroup.link.config.api.ApiConfig;
 import com.lantanagroup.link.config.api.MeasureDefConfig;
@@ -99,7 +104,20 @@ private void initDatabaseLogging() {
     source.setContext(logCtx);
     source.start();
 
-    DBAppender appender = new DBAppender();
+//    ReportLoggingLayout layout = new ReportLoggingLayout();
+//    layout.setContext(logCtx);
+//    layout.setPrefix("ReportGeneration");
+//    layout.setPrintThreadName(true);
+//    layout.start();
+
+    //LayoutWrappingEncoder encoder = new LayoutWrappingEncoder();
+//    PatternLayoutEncoder encoder = new PatternLayoutEncoder();
+//    encoder.setContext(logCtx);
+//    //encoder.setLayout(layout);
+//    encoder.setPattern("%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %reportId - %message%n");
+//    encoder.start();
+
+    DBAppender appender = new MdcDbAppender();
     appender.setContext(logCtx);
     appender.setConnectionSource(source);
     appender.setName("link-db");

core/src/main/java/com/lantanagroup/link/events/MdcLoggingEvent.java

@@ -0,0 +1,137 @@
+package com.lantanagroup.link.events;
+
+
+import ch.qos.logback.classic.Level;
+import ch.qos.logback.classic.spi.ILoggingEvent;
+import ch.qos.logback.classic.spi.IThrowableProxy;
+import ch.qos.logback.classic.spi.LoggerContextVO;
+import org.slf4j.Marker;
+import org.slf4j.event.KeyValuePair;
+
+import java.util.Arrays;
+import java.util.List;
+import java.util.Map;
+
+public class MdcLoggingEvent implements ILoggingEvent {
+
+  private ILoggingEvent mOrigEvent;
+
+  public MdcLoggingEvent(ILoggingEvent origEvent) {
+    mOrigEvent = origEvent;
+  }
+
+  @Override
+  public String getThreadName() {
+    return mOrigEvent.getThreadName();
+  }
+
+  @Override
+  public Level getLevel() {
+    return mOrigEvent.getLevel();
+  }
+
+  @Override
+  public String getMessage() {
+    return mOrigEvent.getMessage();
+  }
+
+  @Override
+  public Object[] getArgumentArray() {
+    var argList = mOrigEvent.getArgumentArray().clone();
+    Map<String, String> mpm = mOrigEvent.getMDCPropertyMap();
+
+    try {
+      if (mpm.containsKey("reportId")) {
+        var reportId = mpm.get("reportId");
+        argList[0] = reportId;
+        return argList;
+      }
+    } catch (Exception e) {
+        return mOrigEvent.getArgumentArray();
+    }
+    return mOrigEvent.getArgumentArray();
+  }
+
+  @Override
+  public String getFormattedMessage() {
+    Map<String, String> mpm = mOrigEvent.getMDCPropertyMap();
+
+    if (mpm.containsKey("reportId")) {
+      var reportId = mpm.get("reportId");
+      return String.format("[%s] ", reportId) + mOrigEvent.getFormattedMessage();
+    }
+
+    return mOrigEvent.getFormattedMessage();
+  }
+
+  @Override
+  public String getLoggerName() {
+    return mOrigEvent.getLoggerName();
+  }
+
+  @Override
+  public LoggerContextVO getLoggerContextVO() {
+    return mOrigEvent.getLoggerContextVO();
+  }
+
+  @Override
+  public IThrowableProxy getThrowableProxy() {
+    return mOrigEvent.getThrowableProxy();
+  }
+
+  @Override
+  public StackTraceElement[] getCallerData() {
+    return mOrigEvent.getCallerData();
+  }
+
+  @Override
+  public boolean hasCallerData() {
+    return mOrigEvent.hasCallerData();
+  }
+
+  @Override
+  public Marker getMarker() {
+    return mOrigEvent.getMarker();
+  }
+
+  @Override
+  public List<Marker> getMarkerList() {
+    return null;
+  }
+
+  @Override
+  public Map<String, String> getMDCPropertyMap() {
+    return mOrigEvent.getMDCPropertyMap();
+  }
+
+  @Override
+  public Map<String, String> getMdc() {
+    return mOrigEvent.getMdc();
+  }
+
+  @Override
+  public long getTimeStamp() {
+    return mOrigEvent.getTimeStamp();
+  }
+
+  @Override
+  public int getNanoseconds() {
+    return 0;
+  }
+
+  @Override
+  public long getSequenceNumber() {
+    return 0;
+  }
+
+  @Override
+  public List<KeyValuePair> getKeyValuePairs() {
+    return null;
+  }
+
+  @Override
+  public void prepareForDeferredProcessing() {
+    mOrigEvent.prepareForDeferredProcessing();
+  }
+
+}