improvements to tx client logging functionality and terminology performance tracking

org.hl7.fhir.r5/src/main/java/org/hl7/fhir/r5/context/HTMLClientLogger.java

@@ -57,11 +57,11 @@ public class HTMLClientLogger extends BaseLogger implements ToolingClientLogger
 
   @Override
   public void logRequest(String method, String url, List<String> headers, byte[] body) {
+    if (DEBUG) {
+      System.out.println(" txlog req: " +method+" "+url+" "+present(body));
+    }
     if (file == null)
       return;
-    if (DEBUG) {
-      System.out.println("tx: " +method+" "+url+" "+present(body));
-    }
     String id = nextId();
     file.println("<hr/><a name=\"l"+id+"\"> </a>");
     file.println("<p>#"+id+"</p>");
@@ -81,11 +81,11 @@ public class HTMLClientLogger extends BaseLogger implements ToolingClientLogger
 
   @Override
   public void logResponse(String outcome, List<String> headers, byte[] body) {
+    if (DEBUG) {
+      System.out.println(" txlog resp: " +outcome+" "+present(body));
+    }
     if (file == null)
       return;
-    if (DEBUG) {
-      System.out.println("tx: " +outcome+" "+present(body));
-    }
     file.println("<pre>");
     file.println(outcome);
     for (String s : headers)  
@@ -106,8 +106,8 @@ public class HTMLClientLogger extends BaseLogger implements ToolingClientLogger
     }
     String cnt = new String(body);
     cnt = cnt.replace("\n", " ").replace("\r", "");
-    if (cnt.length() > 400) {
+    if (cnt.length() > 800) {
-      return cnt.substring(0, 398)+"...";
+      return cnt.substring(0, 798)+"...";
     } else {
       return cnt;
     }

org.hl7.fhir.r5/src/main/java/org/hl7/fhir/r5/context/TerminologyCache.java

@@ -285,6 +285,9 @@ public class TerminologyCache {
   }
 
   public ValidationResult getValidation(CacheToken cacheToken) {
+    if (cacheToken.key == null) {
+      return null;
+    }
     synchronized (lock) {
       NamedCache nc = getNamedCache(cacheToken);
       CacheEntry e = nc.map.get(cacheToken.key);
@@ -296,14 +299,16 @@ public class TerminologyCache {
   }
 
   public void cacheValidation(CacheToken cacheToken, ValidationResult res, boolean persistent) {
-    synchronized (lock) {      
+    if (cacheToken.key != null) {
-      NamedCache nc = getNamedCache(cacheToken);
+      synchronized (lock) {      
-      CacheEntry e = new CacheEntry();
+        NamedCache nc = getNamedCache(cacheToken);
-      e.request = cacheToken.request;
+        CacheEntry e = new CacheEntry();
-      e.persistent = persistent;
+        e.request = cacheToken.request;
-      e.v = res;
+        e.persistent = persistent;
-      store(cacheToken, persistent, nc, e);
+        e.v = res;
-    }    
+        store(cacheToken, persistent, nc, e);
+      }    
+    }
   }
 
   

org.hl7.fhir.r5/src/main/java/org/hl7/fhir/r5/utils/client/FHIRToolingClient.java

@@ -266,11 +266,15 @@ public class FHIRToolingClient {
         if (p.getValue() instanceof PrimitiveType)
           ps += p.getName() + "=" + Utilities.encodeUri(((PrimitiveType) p.getValue()).asStringValue()) + "&";
     ResourceRequest<T> result;
+    URI url = resourceAddress.resolveOperationURLFromClass(resourceClass, name, ps);
     if (complex) {
-      result = client.issuePostRequest(resourceAddress.resolveOperationURLFromClass(resourceClass, name, ps), ByteUtils.resourceToByteArray(params, false, isJson(getPreferredResourceFormat())), getPreferredResourceFormat(),
+      byte[] body = ByteUtils.resourceToByteArray(params, false, isJson(getPreferredResourceFormat()));
+      client.getLogger().logRequest("POST", url.toString(), null, body);
+      result = client.issuePostRequest(url, body, getPreferredResourceFormat(),
           "POST " + resourceClass.getName() + "/$" + name, TIMEOUT_OPERATION_LONG);
     } else {
-      result = client.issueGetResourceRequest(resourceAddress.resolveOperationURLFromClass(resourceClass, name, ps), getPreferredResourceFormat(), "GET " + resourceClass.getName() + "/$" + name, TIMEOUT_OPERATION_LONG);
+      client.getLogger().logRequest("GET", url.toString(), null, null);
+      result = client.issueGetResourceRequest(url, getPreferredResourceFormat(), "GET " + resourceClass.getName() + "/$" + name, TIMEOUT_OPERATION_LONG);
     }
     if (result.isUnsuccessfulRequest()) {
       throw new EFhirClientException("Server returned error code " + result.getHttpStatus(), (OperationOutcome) result.getPayload());

org.hl7.fhir.validation/src/main/java/org/hl7/fhir/validation/BaseValidator.java

@@ -734,7 +734,7 @@ public class BaseValidator {
           fr = ValueSetUtilities.generateImplicitValueSet(reference);
         } 
        
-        timeTracker.tx(t);
+        timeTracker.tx(t, "vs "+uri);
         return fr;
       }
     } else

org.hl7.fhir.validation/src/main/java/org/hl7/fhir/validation/TimeTracker.java

@@ -31,7 +31,9 @@ public class TimeTracker {
     overall = overall + (System.nanoTime() - start);
   }
   
-  public void tx(long start) {
+  public void tx(long start, String s) {
+    long ms = (System.nanoTime() - start) / 1000000;
+//    System.out.println("tx: "+ms+" "+s);
     txTime = txTime + (System.nanoTime() - start);
   }
   

org.hl7.fhir.validation/src/main/java/org/hl7/fhir/validation/instance/type/QuestionnaireValidator.java

@@ -524,7 +524,7 @@ public class QuestionnaireValidator extends BaseValidator {
 
         long t = System.nanoTime();
         ValidationResult res = context.validateCode(new ValidationOptions(stack.getWorkingLang()), c, vs);
-        timeTracker.tx(t);
+        timeTracker.tx(t, "vc "+c.getSystem()+"#"+c.getCode()+" '"+c.getDisplay()+"'");
         if (!res.isOk()) {
           txRule(errors, res.getTxLink(), IssueType.CODEINVALID, value.line(), value.col(), stack.getLiteralPath(), false, I18nConstants.QUESTIONNAIRE_QR_ITEM_BADOPTION, c.getSystem(), c.getCode());
         } else if (res.getSeverity() != null) {