Close http response, temp file and improve logging

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

@@ -54,7 +54,9 @@ public void register(@Nonnull final RequestConfigurator callback) {
   }
 
   @Override
-  public ClientHttpRequest createRequest(final URI uri, final HttpMethod httpMethod) {
+  @Nonnull
+  public ClientHttpRequest createRequest(
+      @Nonnull final URI uri, @Nonnull final HttpMethod httpMethod) {
     return new ConfigFileResolvingRequest(this, uri, httpMethod);
   }
 

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

@@ -141,81 +141,88 @@ private ClientHttpResponse doFileRequest() throws IOException {
   }
 
   private ClientHttpResponse doHttpRequestWithRetry(final HttpHeaders headers) throws IOException {
-    AtomicInteger counter = new AtomicInteger();
+    final AtomicInteger counter = new AtomicInteger();
     do {
       logFetchingURIResource(headers);
       try {
-        ClientHttpResponse response = attemptToFetchResponse(headers, counter);
+        ClientHttpResponse response = attemptToFetchResponse(headers);
         if (response != null) {
           return response;
+        } else {
+          if (canRetry(counter)) {
+            sleepWithExceptionHandling();
+            LOGGER.debug("Retry fetching {}", this.getURI());
+          } else {
+            PrintException printException = new PrintException("Failed fetching " + getURI());
+            LOGGER.debug("Throwing exception since it cannot retry.", printException);
+            throw printException;
+          }
+        }
+      } catch (final IOException | RuntimeException e) {
+        boolean hasSlept = sleepIfPossible(e, counter);
+        if (!hasSlept) {
+          throw e;
         }
-      } catch (final IOException e) {
-        handleIOException(e, counter);
       }
     } while (true);
   }
 
   private void logFetchingURIResource(final HttpHeaders headers) {
     // Display headers, one by line <name>: <value>
     LOGGER.debug(
-        "Fetching URI resource {}, headers:\n{}",
+        "Fetching {}, using headers:\n{}",
         this.getURI(),
         headers.entrySet().stream()
             .map(entry -> entry.getKey() + "=" + String.join(", ", entry.getValue()))
             .collect(Collectors.joining("\n")));
   }
 
-  private ClientHttpResponse attemptToFetchResponse(
-      final HttpHeaders headers, final AtomicInteger counter) throws IOException {
+  private ClientHttpResponse attemptToFetchResponse(final HttpHeaders headers) throws IOException {
     ClientHttpRequest requestUsed =
         this.request != null ? this.request : createRequestFromWrapped(headers);
     LOGGER.debug("Executing http request: {}", requestUsed.getURI());
     ClientHttpResponse response = executeCallbacksAndRequest(requestUsed);
-    if (response.getRawStatusCode() < 500) {
-      LOGGER.debug(
-          "Fetching success URI resource {}, status code {}",
-          getURI(),
-          response.getRawStatusCode());
-      return response;
-    }
-    LOGGER.debug(
-        "Fetching failed URI resource {}, error code {}", getURI(), response.getRawStatusCode());
-    if (canRetry(counter)) {
-      sleepWithExceptionHandling();
-      LOGGER.debug("Retry fetching URI resource {}", this.getURI());
-    } else {
-      throw new PrintException(
-          String.format(
-              "Fetching failed URI resource %s, error code %s",
-              getURI(), response.getRawStatusCode()));
+    final int minStatusCodeError = HttpStatus.INTERNAL_SERVER_ERROR.value();
+    int rawStatusCode = minStatusCodeError;
+    try {
+      rawStatusCode = response.getRawStatusCode();
+      if (rawStatusCode < minStatusCodeError) {
+        LOGGER.debug("Successfully fetched {}, with status code {}", getURI(), rawStatusCode);
+        return response;
+      }
+      LOGGER.debug("Failed fetching {}, with error code {}", getURI(), rawStatusCode);
+      return null;
+    } finally {
+      if (rawStatusCode >= minStatusCodeError) {
+        response.close();
+      }
     }
-    return null;
   }
 
-  private void handleIOException(final IOException e, final AtomicInteger counter)
-      throws IOException {
-
+  private boolean sleepIfPossible(final Exception e, final AtomicInteger counter) {
     if (canRetry(counter)) {
       sleepWithExceptionHandling();
-      LOGGER.debug("Retry fetching URI resource {}", this.getURI());
+      LOGGER.debug("Retry fetching {} following exception", this.getURI(), e);
+      return true;
     } else {
-      LOGGER.debug("Fetching failed URI resource {}", getURI());
-      throw e;
+      LOGGER.debug("Has reached maximum number of retry for {}", getURI());
+      return false;
     }
   }
 
   private void sleepWithExceptionHandling() {
+    int sleepMs = configFileResolvingHttpRequestFactory.getHttpRequestFetchRetryIntervalMillis();
+    LOGGER.debug("Sleeping {} ms before retrying.", sleepMs);
     try {
-      TimeUnit.MILLISECONDS.sleep(
-          configFileResolvingHttpRequestFactory.getHttpRequestFetchRetryIntervalMillis());
+      TimeUnit.MILLISECONDS.sleep(sleepMs);
     } catch (InterruptedException e) {
       Thread.currentThread().interrupt();
       throw new PrintException("Interrupted while sleeping", e);
     }
   }
 
   private boolean canRetry(final AtomicInteger counter) {
-    return counter.incrementAndGet() < getHttpRequestMaxNumberFetchRetry();
+    return counter.incrementAndGet() <= getHttpRequestMaxNumberFetchRetry();
   }
 
   private int getHttpRequestMaxNumberFetchRetry() {

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

@@ -87,18 +87,22 @@ private CachedClientHttpResponse(final ClientHttpResponse originalResponse) thro
       this.headers = originalResponse.getHeaders();
       this.status = originalResponse.getRawStatusCode();
       this.statusText = originalResponse.getStatusText();
-      this.cachedFile =
+      this.cachedFile = createCachedFile(originalResponse.getBody());
+    }
+
+    private File createCachedFile(final InputStream originalBody) throws IOException {
+      File tempFile =
           File.createTempFile("cacheduri", null, HttpRequestFetcher.this.temporaryDirectory);
-      LOGGER.debug("Caching URI resource to {}", this.cachedFile);
-      try (OutputStream os = Files.newOutputStream(this.cachedFile.toPath())) {
-        InputStream body = originalResponse.getBody();
+      LOGGER.debug("Caching URI resource to {}", tempFile);
+      try (OutputStream os = Files.newOutputStream(tempFile.toPath())) {
         LOGGER.debug(
-            "Get from input stream {}, for response {}, body available: {}",
-            body.getClass(),
-            originalResponse.getClass(),
-            body.available());
-        IOUtils.copy(body, os);
+            "Get from input stream {}, body available: {}",
+            originalBody.getClass(),
+            originalBody.available());
+        IOUtils.copy(originalBody, os);
+        originalBody.close();
       }
+      return tempFile;
     }
 
     @Override

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

@@ -94,6 +94,7 @@ private static CloseableHttpClient createHttpClient(
 
   // allow extension only for testing
   @Override
+  @Nonnull
   public ConfigurableRequest createRequest(
       @Nonnull final URI uri, @Nonnull final HttpMethod httpMethod) {
     HttpRequestBase httpRequest = (HttpRequestBase) createHttpUriRequest(httpMethod, uri);
@@ -161,20 +162,24 @@ public HttpMethod getMethod() {
       return HttpMethod.valueOf(this.request.getMethod());
     }
 
+    @Nonnull
     @Override
     public String getMethodValue() {
       return this.request.getMethod();
     }
 
+    @Nonnull
     public URI getURI() {
       return this.request.getURI();
     }
 
+    @Nonnull
     @Override
     protected OutputStream getBodyInternal(@Nonnull final HttpHeaders headers) {
       return this.outputStream;
     }
 
+    @Nonnull
     @Override
     protected Response executeInternal(@Nonnull final HttpHeaders headers) throws IOException {
       CURRENT_CONFIGURATION.set(this.configuration);
@@ -207,7 +212,7 @@ protected Response executeInternal(@Nonnull final HttpHeaders headers) throws IO
     }
   }
 
-  static class Response extends AbstractClientHttpResponse {
+  public static class Response extends AbstractClientHttpResponse {
     private static final Logger LOGGER = LoggerFactory.getLogger(Response.class);
     private static final AtomicInteger ID_COUNTER = new AtomicInteger();
     private final HttpResponse response;
@@ -224,6 +229,7 @@ public int getRawStatusCode() {
       return this.response.getStatusLine().getStatusCode();
     }
 
+    @Nonnull
     @Override
     public String getStatusText() {
       return this.response.getStatusLine().getReasonPhrase();
@@ -247,6 +253,7 @@ public void close() {
       LOGGER.trace("Closed Http Response object: {}", this.id);
     }
 
+    @Nonnull
     @Override
     public synchronized InputStream getBody() throws IOException {
       if (this.inputStream == null) {
@@ -262,6 +269,7 @@ public synchronized InputStream getBody() throws IOException {
       return this.inputStream;
     }
 
+    @Nonnull
     @Override
     public HttpHeaders getHeaders() {
       final HttpHeaders translatedHeaders = new HttpHeaders();

core/src/main/java/org/mapfish/print/servlet/job/impl/ThreadPoolJobManager.java

@@ -452,10 +452,13 @@ private boolean updateRegistry() {
       final SubmittedPrintJob printJob = submittedJobs.next();
       if (!printJob.getReportFuture().isDone()
           && (isTimeoutExceeded(printJob) || isAbandoned(printJob))) {
-        LOGGER.info("Canceling job after timeout {}", printJob.getEntry().getReferenceId());
+        LOGGER.info(
+            "About to attempt timeout based automatic cancellation of job {}",
+            printJob.getEntry().getReferenceId());
         if (!printJob.getReportFuture().cancel(true)) {
           LOGGER.info(
-              "Could not cancel job after timeout {}", printJob.getEntry().getReferenceId());
+              "Automatic cancellation after timeout failed for job {}",
+              printJob.getEntry().getReferenceId());
         }
         // remove all canceled tasks from the work queue (otherwise the queue comparator
         // might stumble on non-PrintJob entries)

core/src/test/java/org/mapfish/print/TestHttpClientFactory.java

@@ -1,13 +1,12 @@
 package org.mapfish.print;
 
-import static org.junit.Assert.fail;
-
 import java.io.IOException;
 import java.io.OutputStream;
 import java.net.URI;
 import java.util.Map;
 import java.util.concurrent.ConcurrentHashMap;
 import java.util.function.Predicate;
+import javax.annotation.Nonnull;
 import org.apache.http.client.methods.HttpRequestBase;
 import org.mapfish.print.config.Configuration;
 import org.mapfish.print.http.ConfigurableRequest;
@@ -37,8 +36,9 @@ public void registerHandler(Predicate<URI> matcher, Handler handler) {
     handlers.put(matcher, handler);
   }
 
+  @Nonnull
   @Override
-  public ConfigurableRequest createRequest(URI uri, final HttpMethod httpMethod) {
+  public ConfigurableRequest createRequest(@Nonnull URI uri, @Nonnull final HttpMethod httpMethod) {
     for (Map.Entry<Predicate<URI>, Handler> entry : handlers.entrySet()) {
       if (entry.getKey().test(uri)) {
         try {
@@ -75,18 +75,6 @@ public MockClientHttpRequest error404(URI uri, HttpMethod httpMethod) {
       request.setResponse(response);
       return request;
     }
-
-    public MockClientHttpRequest failOnExecute(final URI uri, final HttpMethod httpMethod) {
-      MockClientHttpRequest request =
-          new MockClientHttpRequest(httpMethod, uri) {
-            @Override
-            protected ClientHttpResponse executeInternal() throws IOException {
-              fail("request should not be executed " + uri.toString());
-              throw new IOException();
-            }
-          };
-      return request;
-    }
   }
 
   private static class TestConfigurableRequest implements ConfigurableRequest {
@@ -106,11 +94,13 @@ public void setConfiguration(Configuration configuration) {
       // ignore
     }
 
+    @Nonnull
     @Override
     public ClientHttpResponse execute() throws IOException {
       return httpRequest.execute();
     }
 
+    @Nonnull
     @Override
     public OutputStream getBody() throws IOException {
       return httpRequest.getBody();
@@ -121,18 +111,21 @@ public HttpMethod getMethod() {
       return httpRequest.getMethod();
     }
 
+    @Nonnull
     @Override
     public String getMethodValue() {
       final HttpMethod method = httpRequest.getMethod();
       assert method != null;
       return method.name();
     }
 
+    @Nonnull
     @Override
     public URI getURI() {
       return httpRequest.getURI();
     }
 
+    @Nonnull
     @Override
     public HttpHeaders getHeaders() {
       return httpRequest.getHeaders();

core/src/test/java/org/mapfish/print/http/ConfigFileResolvingRequestTest.java

@@ -29,6 +29,7 @@ public void executeInternalShouldDoDataUriRequestWhenSchemeIsData() throws IOExc
 
     // Then
     assertEquals("OK", resp.getStatusText());
+    resp.close();
   }
 
   @Test
@@ -46,6 +47,7 @@ public void httpRequestWithRetryShouldSucceedAtSecondAttempt() throws IOExceptio
 
     // Then
     assertEquals(200, resp.getRawStatusCode());
+    resp.close();
   }
 
   @Test
@@ -66,6 +68,7 @@ public void httpRequestWithRetryShouldSucceedDespiteException() throws IOExcepti
 
     // Then
     assertEquals(200, resp.getRawStatusCode());
+    resp.close();
   }
 
   @Test
@@ -81,9 +84,10 @@ public void httpRequestWithRetryDoNotBlockWhenFailing() throws IOException {
     try {
       ClientHttpResponse resp = req.executeInternal(new HttpHeaders());
       fail("Should not have return the response " + resp);
+      resp.close();
     } catch (PrintException e) {
       // Then
-      assertEquals("Fetching failed URI resource http://ex.com, error code 500", e.getMessage());
+      assertEquals("Failed fetching http://ex.com", e.getMessage());
     }
   }