diff --git a/pipeline/pipeline.engines/src/main/java/fiftyone/pipeline/engines/services/DataUpdateServiceDefault.java b/pipeline/pipeline.engines/src/main/java/fiftyone/pipeline/engines/services/DataUpdateServiceDefault.java index 398bfd9b9..ba4631d33 100644 --- a/pipeline/pipeline.engines/src/main/java/fiftyone/pipeline/engines/services/DataUpdateServiceDefault.java +++ b/pipeline/pipeline.engines/src/main/java/fiftyone/pipeline/engines/services/DataUpdateServiceDefault.java @@ -67,6 +67,13 @@ */ public class DataUpdateServiceDefault implements DataUpdateService { + /** + * The log message of a failed check for a data update, with the error + * that says why attached. + */ + private static final String CHECK_FAILED = + "Error during check for data update"; + /** * The query parameter of a data update URL that holds the license keys, * as the 51Degrees URL formatter writes it. @@ -820,8 +827,8 @@ private AutoUpdateStatus downloadFile( loggedUrl, engineType); HttpURLConnection connection = httpClient.connect(new URI(url.trim()).toURL()); if (connection == null) { - logger.warn(connectFailure(loggedUrl, engineType, automatic, - "No response from the data update service")); + logCheckFailure("No response from data update service at '" + + loggedUrl + "' for engine '" + engineType + "'", null); return AutoUpdateStatus.AUTO_UPDATE_HTTPS_ERR; } try { @@ -842,11 +849,10 @@ private AutoUpdateStatus downloadFile( downloaded = downloadOkResponse( connection, dataFile, tempFile, automatic); } catch (Exception e) { - // An HTTP library's exception often names the - // URL it requested. - logger.warn(downloadFailure(loggedUrl, engineType, - automatic, LicenseKeyMask.maskIn( - e.getMessage(), licenseKeys)), + // A download cut short is the access error, as + // a failure to connect is. An HTTP library's + // exception often names the URL it requested. + logCheckFailure(accessFailure(loggedUrl, engineType), LicenseKeyMask.maskIn(e, licenseKeys)); return AutoUpdateStatus.AUTO_UPDATE_HTTPS_ERR; } @@ -859,8 +865,8 @@ private AutoUpdateStatus downloadFile( // Note: needed because TooManyRequests is not available // in some versions of the HttpStatusCode enum. case (429): - logger.warn(downloadFailure(loggedUrl, engineType, automatic, - "HTTP status code 429 (too many requests)")); + logCheckFailure("Too many requests to '" + loggedUrl + + "' for engine '" + engineType + "'", null); return AutoUpdateStatus.AUTO_UPDATE_ERR_429_TOO_MANY_ATTEMPTS; case HttpURLConnection.HTTP_NOT_MODIFIED: logger.info("No data newer than {} found at '{}' for Engine '{}'", @@ -868,12 +874,15 @@ private AutoUpdateStatus downloadFile( engineType); return AutoUpdateStatus.AUTO_UPDATE_NOT_NEEDED; case HttpURLConnection.HTTP_FORBIDDEN: - logger.warn(downloadFailure(loggedUrl, engineType, automatic, - "HTTP status code 403 (access denied)")); + logCheckFailure("Access denied to data update service " + + "at '" + loggedUrl + "' for engine '" + + engineType + "'", null); return AutoUpdateStatus.AUTO_UPDATE_ERR_403_FORBIDDEN; default: - logger.warn(downloadFailure(loggedUrl, engineType, automatic, - "HTTP status code " + connection.getResponseCode())); + logCheckFailure("HTTP status code '" + + connection.getResponseCode() + "' from data " + + "update service at '" + loggedUrl + + "' for engine '" + engineType + "'", null); return AutoUpdateStatus.AUTO_UPDATE_HTTPS_ERR; } } finally { @@ -881,8 +890,7 @@ private AutoUpdateStatus downloadFile( } } catch (Exception e) { // An HTTP library's exception often names the URL it requested. - logger.warn(connectFailure(loggedUrl, engineType, automatic, - LicenseKeyMask.maskIn(e.getMessage(), licenseKeys)), + logCheckFailure(accessFailure(loggedUrl, engineType), LicenseKeyMask.maskIn(e, licenseKeys)); return AutoUpdateStatus.AUTO_UPDATE_HTTPS_ERR; } @@ -911,31 +919,24 @@ private static String retryNote(boolean automatic) { } /** - * The warning for a failed connection. The URL and the detail are + * The message of the Errors table's row for a failure to connect to the + * data update service, or to download all of its response. The URL is * given with each license key already masked. */ - private static String connectFailure( - String loggedUrl, - String engineType, - boolean automatic, - String detail) { - return "An error occurred when connecting to " + loggedUrl + - " in order to check for data file updates for " + engineType + - "." + retryNote(automatic) + " Error detail: " + detail; + private static String accessFailure(String loggedUrl, String engineType) { + return "Error accessing data update service at '" + loggedUrl + + "' for engine '" + engineType + "'"; } /** - * The warning for a failed download. The URL and the detail are given - * with each license key already masked. + * Log an Error row of the Errors table as the specification asks, at + * Error, reading "Error during check for data update", with an error + * attached that carries the row's message and the cause when there is + * one. The message and the cause are given with each license key + * already masked. */ - private static String downloadFailure( - String loggedUrl, - String engineType, - boolean automatic, - String detail) { - return "An error occurred while downloading a data file update for " + - engineType + " from " + loggedUrl + "." + retryNote(automatic) + - " Error detail: " + detail; + private void logCheckFailure(String message, Throwable cause) { + logger.error(CHECK_FAILED, new IOException(message, cause)); } /** diff --git a/pipeline/pipeline.engines/src/test/java/fiftyone/pipeline/engines/services/DataUpdateServiceLoggingTests.java b/pipeline/pipeline.engines/src/test/java/fiftyone/pipeline/engines/services/DataUpdateServiceLoggingTests.java index dcd972ae1..c93f6369c 100644 --- a/pipeline/pipeline.engines/src/test/java/fiftyone/pipeline/engines/services/DataUpdateServiceLoggingTests.java +++ b/pipeline/pipeline.engines/src/test/java/fiftyone/pipeline/engines/services/DataUpdateServiceLoggingTests.java @@ -24,6 +24,7 @@ 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.ThrowableProxyUtil; import ch.qos.logback.core.read.ListAppender; import fiftyone.common.wrappers.io.FileWrapperFactoryDefault; @@ -41,6 +42,7 @@ import java.io.ByteArrayInputStream; import java.io.File; import java.io.IOException; +import java.io.InputStream; import java.net.HttpURLConnection; import java.net.URL; import java.util.ArrayList; @@ -50,7 +52,9 @@ import static org.junit.Assert.assertEquals; import static org.junit.Assert.assertFalse; import static org.junit.Assert.assertNotNull; +import static org.junit.Assert.assertNull; import static org.junit.Assert.assertTrue; +import static org.junit.Assert.fail; import static org.mockito.ArgumentMatchers.any; import static org.mockito.ArgumentMatchers.anyString; import static org.mockito.Mockito.doThrow; @@ -290,20 +294,18 @@ public void FileSystemWatcher_LogsCreatingFileSystemWatcher() { } @Test - public void ConnectFails_Manual_WarnsWithoutRetryText() throws Exception { + public void ConnectFails_Manual_LogsTheAccessError() throws Exception { when(httpClient.connect(any(URL.class))) .thenThrow(new IOException("refused")); newDataFile(false, false, false); dataUpdate.checkForUpdate(engine); - assertLogged(Level.WARN, "An error occurred when connecting to " + - UPDATE_URL + " in order to check for data file updates for " + - engineType + ". Error detail: refused"); + assertCheckFailed(accessFailure(UPDATE_URL), "refused"); } @Test - public void ConnectFails_Automatic_WarnsThatUpdateWillBeTriedAgain() + public void ConnectFails_Automatic_LogsTheAccessError() throws Exception { when(httpClient.connect(any(URL.class))) .thenThrow(new IOException("refused")); @@ -311,14 +313,11 @@ public void ConnectFails_Automatic_WarnsThatUpdateWillBeTriedAgain() dataUpdate.registerDataFile(file); - assertLogged(Level.WARN, "An error occurred when connecting to " + - UPDATE_URL + " in order to check for data file updates for " + - engineType + ". Update will be attempted again later. " + - "Error detail: refused"); + assertCheckFailed(accessFailure(UPDATE_URL), "refused"); } @Test - public void ConnectFails_AutoUpdateOff_DoesNotPromiseAnotherTry() + public void ConnectFails_AutoUpdateOff_LogsTheAccessError() throws Exception { when(httpClient.connect(any(URL.class))) .thenThrow(new IOException("refused")); @@ -326,37 +325,63 @@ public void ConnectFails_AutoUpdateOff_DoesNotPromiseAnotherTry() dataUpdate.registerDataFile(file); - assertLogged(Level.WARN, "An error occurred when connecting to " + - UPDATE_URL + " in order to check for data file updates for " + - engineType + ". Error detail: refused"); + assertCheckFailed(accessFailure(UPDATE_URL), "refused"); } - private void assertStatusWarned(int status, String detail) + /** + * A 200 response whose body ends before all of it has arrived is the + * first row of the Errors table, as a failure to connect is. + */ + @Test + public void DownloadCutShort_LogsTheAccessError() throws Exception { + when(connection.getResponseCode()) + .thenReturn(HttpURLConnection.HTTP_OK); + when(connection.getInputStream()).thenReturn(new InputStream() { + private int sent = 0; + + @Override + public int read() throws IOException { + if (sent < 10) { + sent++; + return 'x'; + } + throw new IOException("Premature EOF"); + } + }); + newDataFile(false, false, false); + + assertEquals(DataUpdateService.AutoUpdateStatus.AUTO_UPDATE_HTTPS_ERR, + dataUpdate.checkForUpdate(engine)); + + assertCheckFailed(accessFailure(UPDATE_URL), "Premature EOF"); + } + + private void assertStatusFailed(int status, String message) throws Exception { when(connection.getResponseCode()).thenReturn(status); newDataFile(true, false, false); dataUpdate.checkForUpdate(engine); - assertLogged(Level.WARN, "An error occurred while downloading a data " + - "file update for " + engineType + " from " + UPDATE_URL + ". " + - "Error detail: " + detail); - assertTrue(logged(Level.ERROR).isEmpty()); + assertCheckFailed(message, null); } @Test - public void TooManyRequests_WarnsAboutTheDownload() throws Exception { - assertStatusWarned(429, "HTTP status code 429 (too many requests)"); + public void TooManyRequests_LogsTheTableRow() throws Exception { + assertStatusFailed(429, "Too many requests to '" + UPDATE_URL + + "' for engine '" + engineType + "'"); } @Test - public void Forbidden_WarnsAboutTheDownload() throws Exception { - assertStatusWarned(403, "HTTP status code 403 (access denied)"); + public void Forbidden_LogsTheTableRow() throws Exception { + assertStatusFailed(403, "Access denied to data update service at '" + + UPDATE_URL + "' for engine '" + engineType + "'"); } @Test - public void OtherStatus_WarnsAboutTheDownload() throws Exception { - assertStatusWarned(500, "HTTP status code 500"); + public void OtherStatus_LogsTheTableRow() throws Exception { + assertStatusFailed(500, "HTTP status code '500' from data update " + + "service at '" + UPDATE_URL + "' for engine '" + engineType + "'"); } /** @@ -436,6 +461,46 @@ private AspectEngineDataFileDefault newKeyedDataFile(boolean inMemory) { return file; } + /** + * An Error row of the specification's Errors table, logged at Error as + * "Error during check for data update" with an error attached that + * carries the row's message, and a cause whose message holds the given + * text when there is one. A cause with a License Key masked out of it + * is a copy whose message starts with the original's class name. + */ + private void assertCheckFailed(String message, String causeMessage) { + List found = new ArrayList<>(); + for (ILoggingEvent event : appender.list) { + if (event.getLevel() == Level.ERROR && + "Error during check for data update".equals( + event.getFormattedMessage()) && + event.getThrowableProxy() != null) { + IThrowableProxy error = event.getThrowableProxy(); + found.add(error.getMessage()); + if (message.equals(error.getMessage())) { + IThrowableProxy cause = error.getCause(); + if (causeMessage == null) { + assertNull(cause); + } else { + assertNotNull(cause); + assertTrue("The cause was " + cause.getMessage(), + cause.getMessage().endsWith(causeMessage)); + } + assertTrue("A warning was logged as well: " + + logged(Level.WARN), logged(Level.WARN).isEmpty()); + return; + } + } + } + fail("Expected '" + message + "' attached to an Error entry, but " + + "the errors attached were " + found); + } + + private String accessFailure(String url) { + return "Error accessing data update service at '" + url + + "' for engine '" + engineType + "'"; + } + /** * Fails if any log entry, or any throwable logged with one, holds the * license key in full. @@ -498,9 +563,8 @@ public void LicenseKey_ConnectFails_MasksTheUrlAndTheException() dataUpdate.checkForUpdate(engine); - assertLogged(Level.WARN, "An error occurred when connecting to " + - MASKED_URL + " in order to check for data file updates for " + - engineType + ". Error detail: Connection refused: " + MASKED_URL); + assertCheckFailed(accessFailure(MASKED_URL), + "Connection refused: " + MASKED_URL); assertKeyOnlyMasked(); } @@ -515,9 +579,8 @@ public void LicenseKey_DownloadFails_MasksTheUrlAndTheException() dataUpdate.checkForUpdate(engine); - assertLogged(Level.WARN, "An error occurred while downloading a data " + - "file update for " + engineType + " from " + MASKED_URL + ". " + - "Error detail: Premature EOF from " + MASKED_URL); + assertCheckFailed(accessFailure(MASKED_URL), + "Premature EOF from " + MASKED_URL); assertKeyOnlyMasked(); } @@ -529,9 +592,8 @@ public void LicenseKey_Forbidden_LogsTheMaskedUrl() throws Exception { dataUpdate.checkForUpdate(engine); - assertLogged(Level.WARN, "An error occurred while downloading a data " + - "file update for " + engineType + " from " + MASKED_URL + ". " + - "Error detail: HTTP status code 403 (access denied)"); + assertCheckFailed("Access denied to data update service at '" + + MASKED_URL + "' for engine '" + engineType + "'", null); assertKeyOnlyMasked(); } @@ -542,10 +604,8 @@ public void LicenseKey_NoResponse_LogsTheMaskedUrl() throws Exception { dataUpdate.checkForUpdate(engine); - assertLogged(Level.WARN, "An error occurred when connecting to " + - MASKED_URL + " in order to check for data file updates for " + - engineType + ". Error detail: No response from the data update " + - "service"); + assertCheckFailed("No response from data update service at '" + + MASKED_URL + "' for engine '" + engineType + "'", null); assertKeyOnlyMasked(); } } diff --git a/pipeline/pipeline.engines/src/test/java/fiftyone/pipeline/engines/services/DataUpdateServiceTests.java b/pipeline/pipeline.engines/src/test/java/fiftyone/pipeline/engines/services/DataUpdateServiceTests.java index b10b06a8a..0d1796004 100644 --- a/pipeline/pipeline.engines/src/test/java/fiftyone/pipeline/engines/services/DataUpdateServiceTests.java +++ b/pipeline/pipeline.engines/src/test/java/fiftyone/pipeline/engines/services/DataUpdateServiceTests.java @@ -892,12 +892,13 @@ public void call(Object sender, DataUpdateService.DataUpdateCompleteArgs args) { // reconfigured to try again later. verify(futureFactory, atLeast(1)) .schedule(any(Runnable.class), anyLong()); - // We expect one warning to be logged so make sure it's - // ignored in cleanup and verify its presence. - ignoreWranings = 1; - assertEquals(1, logger.warningsLogged.size()); - assertTrue(logger.warningsLogged.get(0).contains(errorText)); - assertEquals(0, logger.errorsLogged.size()); + // The failed connection is the Errors table's access error, + // logged once at Error, so it is ignored in cleanup. + ignoreErrors = 1; + assertEquals(0, logger.warningsLogged.size()); + assertEquals(1, logger.errorsLogged.size()); + assertEquals("Error during check for data update", + logger.errorsLogged.get(0)); assertEquals(AUTO_UPDATE_HTTPS_ERR, completeEventArgs[0].getStatus()); } finally { @@ -1724,8 +1725,8 @@ public void call(Object sender, DataUpdateService.DataUpdateCompleteArgs args) { assertTrue("The 'checkForUpdateComplete' " + "event was never fired", completed); - // Ignore the warning that is logged due to the 429 - ignoreWranings = 1; + // Ignore the error that is logged due to the 429 + ignoreErrors = 1; // Check that the timer has been set to go off again. assertNotNull(file.getFuture()); // Check that the timer has been set to expire in 10 seconds.