Merge pull request #3446 from mapfish/metrics-requests

Add new metrics

core/src/main/java/org/mapfish/print/cli/Main.java

@@ -3,7 +3,7 @@
 import ch.qos.logback.classic.LoggerContext;
 import ch.qos.logback.classic.joran.JoranConfigurator;
 import ch.qos.logback.core.joran.spi.JoranException;
-import ch.qos.logback.core.util.StatusPrinter;
+import ch.qos.logback.core.util.StatusPrinter2;
 import com.google.common.annotations.VisibleForTesting;
 import com.sampullara.cli.Args;
 import java.io.File;
@@ -58,7 +58,6 @@ private Main() {
    * Main method.
    *
    * @param args the cli arguments
-   * @throws Exception
    */
   public static void main(final String[] args) throws Exception {
     runMain(args);
@@ -69,7 +68,6 @@ public static void main(final String[] args) throws Exception {
    * Runs the print.
    *
    * @param args the cli arguments
-   * @throws Exception
    */
   @VisibleForTesting
   public static void runMain(final String[] args) throws Exception {
@@ -133,17 +131,20 @@ private static void configureLogs(final String verbose) {
       case LOGLEVEL_INFO:
         logfile = classLoader.getResource("shell-info-log.xml");
         break;
-      case LOGLEVEL_DEFAULT:
-        logfile = classLoader.getResource("shell-default-log.xml");
-        break;
       case LOGLEVEL_VERBOSE:
         logfile = classLoader.getResource("shell-verbose-log.xml");
         break;
+      case LOGLEVEL_DEFAULT:
       default:
         logfile = classLoader.getResource("shell-default-log.xml");
         break;
     }
 
+    LoggerContext loggerContext = getLoggerContext(logfile);
+    new StatusPrinter2().printInCaseOfErrorsOrWarnings(loggerContext);
+  }
+
+  private static LoggerContext getLoggerContext(final URL logfile) {
     LoggerContext loggerContext = (LoggerContext) LoggerFactory.getILoggerFactory();
 
     try {
@@ -156,15 +157,15 @@ private static void configureLogs(final String verbose) {
     } catch (JoranException je) {
       // StatusPrinter will handle this
     }
-    StatusPrinter.printInCaseOfErrorsOrWarnings(loggerContext);
+    return loggerContext;
   }
 
   /**
-   * Instead of calling system.exit an exception will be thrown. This is useful for testing so a
-   * test won't shutdown jvm.
+   * Instead of calling System.exit() an exception will be thrown. This is useful for testing so a
+   * test won't shut down the jvm.
    *
-   * @param exceptionOnFailure if true then an exception will be thrown instead of system.exit being
-   *     called.
+   * @param exceptionOnFailure if true then an exception will be thrown instead of System.exit()
+   *     being called.
    */
   @VisibleForTesting
   static void setExceptionOnFailure(final boolean exceptionOnFailure) {
@@ -197,7 +198,7 @@ private void run(final CliDefinition cli) throws Exception {
         if (LOGGER.isDebugEnabled()) {
           LOGGER.debug("Request Data: \n{}", jsonSpec.getInternalObj().toString(2));
         }
-        this.mapPrinter.print(new HashMap<String, String>(), jsonSpec, outFile);
+        this.mapPrinter.print(new HashMap<>(), jsonSpec, outFile);
       }
     }
   }

core/src/main/java/org/mapfish/print/http/HttpRequestFetcher.java

@@ -189,7 +189,10 @@ public OutputStream getBody() {
     @Nonnull
     public ClientHttpResponse execute() {
       assert this.future != null;
-      Timer timerWait = HttpRequestFetcher.this.registry.timer(buildMetricName(".waitDownloader"));
+      Timer timerWait =
+          HttpRequestFetcher.this.registry.timer(
+              MetricRegistry.name(
+                  HttpRequestFetcher.class.getSimpleName(), "TimeWaitingDownloader"));
       try (Timer.Context ignored = timerWait.time()) {
         this.future.join();
       }
@@ -204,25 +207,25 @@ public ClientHttpResponse execute() {
       return result;
     }
 
-    private String buildMetricName(final String suffix) {
-      return HttpRequestFetcher.class.getName() + suffix;
-    }
-
     @Override
     public Void call() throws Exception {
       return context.mdcContextEx(
           () -> {
             final String baseMetricName =
-                buildMetricName(".read." + StatsUtils.quotePart(getURI().getHost()));
+                MetricRegistry.name(
+                    HttpRequestFetcher.class.getSimpleName(),
+                    "read",
+                    StatsUtils.quotePart(getURI().getHost()));
             Timer timerDownload = HttpRequestFetcher.this.registry.timer(baseMetricName);
             try (Timer.Context ignored = timerDownload.time()) {
               try {
                 context.stopIfCanceled();
                 this.response = new CachedClientHttpResponse(this.originalRequest.execute());
               } catch (IOException | RuntimeException e) {
                 LOGGER.error("Request failed {}", this.originalRequest.getURI(), e);
+                String errorCounter = MetricRegistry.name(baseMetricName, "error");
+                HttpRequestFetcher.this.registry.counter(errorCounter).inc();
                 this.response = new ErrorResponseClientHttpResponse(e);
-                HttpRequestFetcher.this.registry.counter(baseMetricName + ".error").inc();
               }
             }
             return null;

core/src/main/java/org/mapfish/print/map/image/AbstractSingleImageLayer.java

@@ -67,7 +67,7 @@ protected AbstractSingleImageLayer(
       final ExecutorService executorService,
       final StyleSupplier<GridCoverage2D> styleSupplier,
       final AbstractLayerParams params,
-      final MetricRegistry registry,
+      @Nonnull final MetricRegistry registry,
       final Configuration configuration) {
     super(executorService, params);
     this.styleSupplier = styleSupplier;
@@ -168,14 +168,15 @@ protected BufferedImage fetchImage(
 
         return fetchImageFromHttpResponse(request, httpResponse, transformer, baseMetricName);
       } catch (RuntimeException e) {
-        this.registry.counter(baseMetricName + ".error").inc();
+        this.registry.counter(MetricRegistry.name(baseMetricName, "error")).inc();
         throw e;
       }
     }
   }
 
   private String getBaseMetricName(@Nonnull final ClientHttpRequest request) {
-    return getClass().getName() + ".read." + StatsUtils.quotePart(request.getURI().getHost());
+    return MetricRegistry.name(
+        getClass().getSimpleName(), "read", StatsUtils.quotePart(request.getURI().getHost()));
   }
 
   private static String getInvalidResponseBody(
@@ -215,7 +216,7 @@ private boolean isResponseStatusCodeValid(
       if (stringBody != null) {
         message += "\nContent:\n" + stringBody;
       }
-      this.registry.counter(baseMetricName + ".error").inc();
+      this.registry.counter(MetricRegistry.name(baseMetricName, "error")).inc();
       if (getFailOnError()) {
         throw new RuntimeException(message);
       } else {
@@ -237,7 +238,7 @@ private boolean isResponseBodyValid(
           request.getURI(),
           contentType.get(0),
           responseBody);
-      this.registry.counter(baseMetricName + ".error").inc();
+      this.registry.counter(MetricRegistry.name(baseMetricName, "error")).inc();
       if (getFailOnError()) {
         throw new RuntimeException("Wrong content-type : " + contentType.get(0));
       } else {
@@ -256,7 +257,7 @@ private BufferedImage fetchImageFromHttpResponse(
     final BufferedImage image = ImageIO.read(httpResponse.getBody());
     if (image == null) {
       LOGGER.warn("Cannot read image from {}", request.getURI());
-      this.registry.counter(baseMetricName + ".error").inc();
+      this.registry.counter(MetricRegistry.name(baseMetricName, "error")).inc();
       if (getFailOnError()) {
         throw new RuntimeException("Cannot read image from " + request.getURI());
       }

core/src/main/java/org/mapfish/print/map/image/wms/WmsLayer.java

@@ -35,7 +35,7 @@ public final class WmsLayer extends AbstractSingleImageLayer {
    * @param registry the metrics registry.
    * @param configuration the configuration.
    */
-  protected WmsLayer(
+  WmsLayer(
       @Nonnull final ExecutorService executorService,
       @Nonnull final StyleSupplier<GridCoverage2D> styleSupplier,
       @Nonnull final WmsLayerParam params,

core/src/main/java/org/mapfish/print/metrics/HealthCheckingRegistry.java

@@ -4,10 +4,12 @@
 import org.springframework.beans.factory.annotation.Autowired;
 
 public class HealthCheckingRegistry extends com.codahale.metrics.health.HealthCheckRegistry {
-  @Autowired private ApplicationStatus applicationStatus;
+  @Autowired private JobQueueHealthCheck jobQueueHealthCheck;
+  @Autowired private UnhealthyCountersHealthCheck unhealthyCountersHealthCheck;
 
   @PostConstruct
   public void registerHealthCheck() {
-    register("application", applicationStatus);
+    register("jobQueueStatus", jobQueueHealthCheck);
+    register("unhealthyCountersStatus", unhealthyCountersHealthCheck);
   }
 }

core/src/main/java/org/mapfish/print/metrics/ApplicationStatus.java → core/src/main/java/org/mapfish/print/metrics/JobQueueHealthCheck.java

@@ -9,7 +9,7 @@
 import org.springframework.beans.factory.annotation.Autowired;
 import org.springframework.beans.factory.annotation.Value;
 
-class ApplicationStatus extends HealthCheck {
+public class JobQueueHealthCheck extends HealthCheck {
   @Value("${healthStatus.expectedMaxTime.sinceLastPrint.InSeconds}")
   private int secondsInFloatingWindow;
 
@@ -34,7 +34,7 @@ protected Result check() throws Exception {
     String health = ". Number of print jobs waiting is " + waitingJobsCount;
 
     if (jobManager.getLastExecutedJobTimestamp() == null) {
-      return Result.unhealthy("No print job was ever processed by this server" + health);
+      return Result.unhealthy("This server never processed a print job" + health);
     } else if (hasThisServerPrintedRecently()) {
       // WIP (See issue https://github.com/mapfish/mapfish-print/issues/3393)
       if (waitingJobsCount > maxNbrPrintJobQueued) {

core/src/main/java/org/mapfish/print/metrics/UnhealthyCountersHealthCheck.java

@@ -0,0 +1,49 @@
+package org.mapfish.print.metrics;
+
+import com.codahale.metrics.Counter;
+import com.codahale.metrics.MetricRegistry;
+import com.codahale.metrics.health.HealthCheck;
+import java.util.HashSet;
+import java.util.Set;
+import org.springframework.beans.factory.annotation.Autowired;
+
+public class UnhealthyCountersHealthCheck extends HealthCheck {
+  @Autowired private MetricRegistry metricRegistry;
+
+  private final Set<String> unhealthyCounters = new HashSet<>();
+
+  /**
+   * When a Result is returned it can be healthy or unhealthy. In both cases it is associated to a
+   * Http 200 status. When an exception is thrown it means the server is no longer working at all,
+   * it is associated to a Http 500 status.
+   */
+  @Override
+  protected HealthCheck.Result check() throws Exception {
+    StringBuilder messageBuilder = new StringBuilder();
+    boolean first = true;
+    for (String unhealthyCounter : this.unhealthyCounters) {
+      if (metricRegistry.getNames().contains(unhealthyCounter)) {
+        Counter counter = metricRegistry.counter(unhealthyCounter);
+        if (counter.getCount() != 0) {
+          if (first) {
+            first = false;
+          } else {
+            messageBuilder.append("\n");
+          }
+          messageBuilder.append(unhealthyCounter);
+          messageBuilder.append(" = ");
+          messageBuilder.append(counter.getCount());
+        }
+      }
+    }
+    if (first) {
+      return Result.healthy("No unhealthy counter found.");
+    }
+    return Result.unhealthy(messageBuilder.toString());
+  }
+
+  /** To record a counter which might make the server unhealthy if its count is not zero. */
+  public void recordUnhealthyCounter(final String counterName) {
+    unhealthyCounters.add(counterName);
+  }
+}

core/src/main/java/org/mapfish/print/processor/ProcessorGraphNode.java

@@ -120,7 +120,7 @@ public BiMap<String, String> getInputMapper() {
    */
   public void toString(final StringBuilder builder, final int indent, final String parent) {
     this.processor.toString(builder, indent, parent);
-    for (ProcessorGraphNode dependency : this.dependencies) {
+    for (ProcessorGraphNode<?, ?> dependency : this.dependencies) {
       dependency.toString(builder, indent + 1, this.processor.toString());
     }
   }
@@ -182,8 +182,10 @@ protected Values compute() {
 
     private void executeProcess(final Processor<In, Out> process, final Values values) {
       final String timerName =
-          String.format(
-              "%s.compute.%s", ProcessorGraphNode.class.getName(), process.getClass().getName());
+          MetricRegistry.name(
+              ProcessorGraphNode.class.getSimpleName(),
+              "compute",
+              process.getClass().getSimpleName());
       final Timer.Context timerContext = this.node.metricRegistry.timer(timerName).time();
       try {
         final In inputParameter = ProcessorUtils.populateInputParameter(process, values);
@@ -219,7 +221,7 @@ private RuntimeException handleException(
       LOGGER.info("Error while executing process: {}", process, cause);
       // the processor is already canceled, so we don't care if something fails
       this.execContext.getContext().stopIfCanceled();
-      this.node.metricRegistry.counter(timerName + ".error").inc();
+      this.node.metricRegistry.counter(MetricRegistry.name(timerName, "error")).inc();
       return Objects.requireNonNullElseGet(
           runtimeCause, () -> new PrintException("Failed to execute process:" + process, cause));
     }

core/src/main/java/org/mapfish/print/processor/jasper/JasperReportBuilder.java

@@ -50,7 +50,7 @@ public final class JasperReportBuilder extends AbstractProcessor<JasperReportBui
   @Autowired private WorkingDirectories workingDirectories;
 
   /** Constructor. */
-  protected JasperReportBuilder() {
+  private JasperReportBuilder() {
     super(Void.class);
   }
 
@@ -95,18 +95,20 @@ private void doCompileAndMoveReport(final File buildFile, final File jasperFile)
       throws JRException, IOException {
     final File tmpBuildFile =
         File.createTempFile("temp_", JASPER_REPORT_COMPILED_FILE_EXT, buildFile.getParentFile());
-    final String timerName = getClass().getName() + ".compile." + jasperFile;
-    Timer.Context compileTimerContext = this.metricRegistry.timer(timerName).time();
-    try {
-      JasperCompileManager.compileReportToFile(
-          jasperFile.getAbsolutePath(), tmpBuildFile.getAbsolutePath());
-    } catch (JRValidationException e) {
-      LOGGER.error("The report '{}' isn't valid.", jasperFile.getAbsolutePath());
-      throw e;
-    } finally {
-      final long compileTime =
-          TimeUnit.MILLISECONDS.convert(compileTimerContext.stop(), TimeUnit.NANOSECONDS);
-      LOGGER.info("Report '{}' built in {}ms.", jasperFile.getAbsolutePath(), compileTime);
+    final String timerName =
+        MetricRegistry.name(getClass().getSimpleName(), "compile", String.valueOf(jasperFile));
+    try (Timer.Context compileTimerContext = this.metricRegistry.timer(timerName).time()) {
+      try {
+        JasperCompileManager.compileReportToFile(
+            jasperFile.getAbsolutePath(), tmpBuildFile.getAbsolutePath());
+      } catch (JRValidationException e) {
+        LOGGER.error("The report '{}' isn't valid.", jasperFile.getAbsolutePath());
+        throw e;
+      } finally {
+        final long compileTime =
+            TimeUnit.MILLISECONDS.convert(compileTimerContext.stop(), TimeUnit.NANOSECONDS);
+        LOGGER.info("Report '{}' built in {}ms.", jasperFile.getAbsolutePath(), compileTime);
+      }
     }
     move(tmpBuildFile.toPath(), buildFile.toPath(), StandardCopyOption.ATOMIC_MOVE);
   }

core/src/main/java/org/mapfish/print/processor/map/CreateMapProcessor.java

@@ -107,7 +107,7 @@ public final class CreateMapProcessor
   private ForkJoinPool requestForkJoinPool;
 
   /** Constructor. */
-  protected CreateMapProcessor() {
+  private CreateMapProcessor() {
     super(Output.class);
   }
 
@@ -389,7 +389,7 @@ private List<URI> createLayerGraphics(
     final AreaOfInterest areaOfInterest = addAreaOfInterestLayer(mapValues, layers);
     final String mapKey = UUID.randomUUID().toString();
     final List<URI> graphics = new ArrayList<>(layers.size());
-    String timerName = getClass().getName() + ".buildLayers";
+    final String timerName = MetricRegistry.name(getClass().getSimpleName(), "buildLayers");
     try (Timer.Context ignored = this.metricRegistry.timer(timerName).time()) {
       int fileNumber = 0;
       for (LayerGroup layerGroup : LayerGroup.buildGroups(layers, pdfA)) {