diff --git a/device-detection/device-detection/src/test/java/fiftyone/devicedetection/DeviceDetectionOnPremisePipelineBuilderTest.java b/device-detection/device-detection/src/test/java/fiftyone/devicedetection/DeviceDetectionOnPremisePipelineBuilderTest.java index 21b9e5bd4..aed639665 100644 --- a/device-detection/device-detection/src/test/java/fiftyone/devicedetection/DeviceDetectionOnPremisePipelineBuilderTest.java +++ b/device-detection/device-detection/src/test/java/fiftyone/devicedetection/DeviceDetectionOnPremisePipelineBuilderTest.java @@ -64,6 +64,7 @@ public void setup() throws Exception { when(loggerFactory.getLogger(anyString())).thenReturn(logger); builder = new DeviceDetectionPipelineBuilder(loggerFactory) .useOnPremise(datafile.getAbsolutePath(), false) + .setAutoUpdate(false) .setShareUsage(false); } @@ -122,6 +123,7 @@ public void setEngineData_PropertyPropagatedToDataFileConfiguration() throws Exc try (Pipeline pipeline = new DeviceDetectionPipelineBuilder(loggerFactory) .useOnPremise(new byte[]{}, Enums.DeviceDetectionAlgorithm.Hash) .setEngineData(data) + .setAutoUpdate(false) .setShareUsage(false) .build()) { DataFileConfiguration dataFileConfiguration = getDataFileConfiguration(pipeline); @@ -144,6 +146,7 @@ public void setEngineData_FilenameIsSet_PropertyNotPropagated() throws Exception public void setShareUsage_False_SharedFlowElementNotAdded() throws Exception { try (Pipeline pipeline = new DeviceDetectionPipelineBuilder(loggerFactory) .useOnPremise(datafile.getAbsolutePath(), false) + .setAutoUpdate(false) .setShareUsage(false) .build()) { List flowElements = pipeline.getFlowElements(); @@ -156,6 +159,7 @@ public void setShareUsage_False_SharedFlowElementNotAdded() throws Exception { public void setShareUsage_True_SharedFlowElementAdded() throws Exception { try (Pipeline pipeline = new DeviceDetectionPipelineBuilder(loggerFactory) .useOnPremise(datafile.getAbsolutePath(), false) + .setAutoUpdate(false) .setShareUsage(true) .build()) { List flowElements = pipeline.getFlowElements(); @@ -168,6 +172,7 @@ public void setShareUsage_True_SharedFlowElementAdded() throws Exception { public void setAutoUpdate_PropertyPropagatedToDataFileConfiguration() throws Exception { try (Pipeline pipeline = builder .setAutoUpdate(true) + .setDataUpdateLicenseKey("licence_key") .build()) { DataFileConfiguration dataFileConfiguration = getDataFileConfiguration(pipeline); assertTrue(dataFileConfiguration.getAutomaticUpdatesEnabled()); @@ -189,6 +194,7 @@ public void setDataUpdateService_RegisterDataFileTriggered() throws Exception { DataUpdateServiceDefault dataUpdateServiceDefault = mock(DataUpdateServiceDefault.class); try (Pipeline ignored = builder .setAutoUpdate(true) + .setDataUpdateLicenseKey("licence_key") .setDataUpdateService(dataUpdateServiceDefault) .build()) { verify(dataUpdateServiceDefault).registerDataFile(any()); @@ -199,6 +205,8 @@ public void setDataUpdateService_RegisterDataFileTriggered() throws Exception { public void setDataUpdateOnStartup_PropertyPropagatedToDataFileConfiguration() throws Exception { try (Pipeline pipeline = builder .setDataUpdateOnStartup(true) + .setDataUpdateLicenseKey("licence_key") + .setDataUpdateService(mock(DataUpdateServiceDefault.class)) .build()) { DataFileConfiguration dataFileConfiguration = getDataFileConfiguration(pipeline); assertTrue(dataFileConfiguration.getUpdateOnStartup()); diff --git a/ip-intelligence/ip-intelligence/src/test/java/fiftyone/ipintelligence/IPIntelligenceOnPremisePipelineBuilderTest.java b/ip-intelligence/ip-intelligence/src/test/java/fiftyone/ipintelligence/IPIntelligenceOnPremisePipelineBuilderTest.java index d220eb776..9e37ada63 100644 --- a/ip-intelligence/ip-intelligence/src/test/java/fiftyone/ipintelligence/IPIntelligenceOnPremisePipelineBuilderTest.java +++ b/ip-intelligence/ip-intelligence/src/test/java/fiftyone/ipintelligence/IPIntelligenceOnPremisePipelineBuilderTest.java @@ -65,6 +65,7 @@ public void setup() throws Exception { when(loggerFactory.getLogger(anyString())).thenReturn(logger); builder = new IPIntelligencePipelineBuilder(loggerFactory) .useOnPremise(datafile.getAbsolutePath(), false) + .setAutoUpdate(false) .setShareUsage(false); } @@ -121,6 +122,7 @@ public void setFilename_OtherExtension_ExceptionThrown() { public void setShareUsage_False_SharedFlowElementNotAdded() throws Exception { try (Pipeline pipeline = new IPIntelligencePipelineBuilder(loggerFactory) .useOnPremise(datafile.getAbsolutePath(), false) + .setAutoUpdate(false) .setShareUsage(false) .build()) { List flowElements = pipeline.getFlowElements(); @@ -133,6 +135,7 @@ public void setShareUsage_False_SharedFlowElementNotAdded() throws Exception { public void setShareUsage_True_SharedFlowElementAdded() throws Exception { try (Pipeline pipeline = new IPIntelligencePipelineBuilder(loggerFactory) .useOnPremise(datafile.getAbsolutePath(), false) + .setAutoUpdate(false) .setShareUsage(true) .build()) { List flowElements = pipeline.getFlowElements(); @@ -145,6 +148,7 @@ public void setShareUsage_True_SharedFlowElementAdded() throws Exception { public void setAutoUpdate_PropertyPropagatedToDataFileConfiguration() throws Exception { try (Pipeline pipeline = builder .setAutoUpdate(true) + .setDataUpdateLicenseKey("licence_key") .build()) { DataFileConfiguration dataFileConfiguration = getDataFileConfiguration(pipeline); assertTrue(dataFileConfiguration.getAutomaticUpdatesEnabled()); @@ -166,6 +170,7 @@ public void setDataUpdateService_RegisterDataFileTriggered() throws Exception { DataUpdateServiceDefault dataUpdateServiceDefault = mock(DataUpdateServiceDefault.class); try (Pipeline ignored = builder .setAutoUpdate(true) + .setDataUpdateLicenseKey("licence_key") .setDataUpdateService(dataUpdateServiceDefault) .build()) { verify(dataUpdateServiceDefault).registerDataFile(any()); @@ -176,6 +181,8 @@ public void setDataUpdateService_RegisterDataFileTriggered() throws Exception { public void setDataUpdateOnStartup_PropertyPropagatedToDataFileConfiguration() throws Exception { try (Pipeline pipeline = builder .setDataUpdateOnStartup(true) + .setDataUpdateLicenseKey("licence_key") + .setDataUpdateService(mock(DataUpdateServiceDefault.class)) .build()) { DataFileConfiguration dataFileConfiguration = getDataFileConfiguration(pipeline); assertTrue(dataFileConfiguration.getUpdateOnStartup()); diff --git a/pipeline/pipeline.engines.fiftyone/src/main/java/fiftyone/pipeline/engines/fiftyone/flowelements/FiftyOneOnPremiseAspectEngineBuilderBase.java b/pipeline/pipeline.engines.fiftyone/src/main/java/fiftyone/pipeline/engines/fiftyone/flowelements/FiftyOneOnPremiseAspectEngineBuilderBase.java index bcd634359..b6ea858ec 100644 --- a/pipeline/pipeline.engines.fiftyone/src/main/java/fiftyone/pipeline/engines/fiftyone/flowelements/FiftyOneOnPremiseAspectEngineBuilderBase.java +++ b/pipeline/pipeline.engines.fiftyone/src/main/java/fiftyone/pipeline/engines/fiftyone/flowelements/FiftyOneOnPremiseAspectEngineBuilderBase.java @@ -22,6 +22,7 @@ package fiftyone.pipeline.engines.fiftyone.flowelements; +import fiftyone.pipeline.engines.configuration.DataFileConfiguration; import fiftyone.pipeline.engines.data.AspectEngineDataFile; import fiftyone.pipeline.engines.fiftyone.data.FiftyOneDataFile; import fiftyone.pipeline.engines.fiftyone.data.FiftyOneDataFileDefault; @@ -80,6 +81,17 @@ public FiftyOneOnPremiseAspectEngineBuilderBase( setDataUpdateUrlFormatter(new FiftyOneUrlFormatter()); } + /** + * The Distributor serves nothing without a license key, so a key is + * required while the data update URL is the Distributor's. + * @param dataFileConfig the data file configuration to check + * @return true if the data update URL is the Distributor's + */ + @Override + protected boolean isLicenseKeyRequired(DataFileConfiguration dataFileConfig) { + return DATA_UPDATE_URL.equals(dataFileConfig.getDataUpdateUrl()); + } + /** * Create a new empty data file instance to be populated with the details of * the data file to be used. diff --git a/pipeline/pipeline.engines.fiftyone/src/test/java/fiftyone/pipeline/engines/fiftyone/flowelements/FiftyOneDegreesOnPremiseAspectEngineBuilderBaseTests.java b/pipeline/pipeline.engines.fiftyone/src/test/java/fiftyone/pipeline/engines/fiftyone/flowelements/FiftyOneDegreesOnPremiseAspectEngineBuilderBaseTests.java index c1ff832dc..bb7231527 100644 --- a/pipeline/pipeline.engines.fiftyone/src/test/java/fiftyone/pipeline/engines/fiftyone/flowelements/FiftyOneDegreesOnPremiseAspectEngineBuilderBaseTests.java +++ b/pipeline/pipeline.engines.fiftyone/src/test/java/fiftyone/pipeline/engines/fiftyone/flowelements/FiftyOneDegreesOnPremiseAspectEngineBuilderBaseTests.java @@ -22,12 +22,15 @@ package fiftyone.pipeline.engines.fiftyone.flowelements; +import fiftyone.pipeline.core.exceptions.PipelineConfigurationException; import fiftyone.pipeline.engines.Constants; import fiftyone.pipeline.engines.data.AspectData; import fiftyone.pipeline.engines.data.AspectEngineDataFile; +import fiftyone.pipeline.engines.data.AspectEngineDataFileDefault; import fiftyone.pipeline.engines.data.AspectPropertyMetaData; import fiftyone.pipeline.engines.fiftyone.data.FiftyOneDataFile; import fiftyone.pipeline.engines.services.DataUpdateService; +import org.mockito.ArgumentCaptor; import org.junit.jupiter.api.BeforeEach; import org.junit.jupiter.api.Test; import org.mockito.invocation.InvocationOnMock; @@ -38,7 +41,10 @@ import java.util.List; import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertFalse; import static org.junit.jupiter.api.Assertions.assertNotNull; +import static org.junit.jupiter.api.Assertions.assertThrows; +import static org.junit.jupiter.api.Assertions.assertTrue; import static org.mockito.ArgumentMatchers.any; import static org.mockito.Mockito.*; @@ -118,6 +124,7 @@ public void DataFile_SetEngine() throws Exception { ImplementedBuilder builder = new ImplementedBuilder( LoggerFactory.getILoggerFactory(), updateService); + builder.setAutoUpdate(false); builder.build("", false); assertNotNull(engine.getDataFileMetaData()); @@ -145,4 +152,124 @@ public void DataFile_UrlFormatter() throws Exception { "https://distributor.51degrees.com/api/v2/download?LicenseKeys="+licenseKey+"&Download=True&Type="+downloadType, engine.getDataFileMetaData().getFormattedUrl()); } + + private ImplementedBuilder newBuilder() { + return new ImplementedBuilder( + LoggerFactory.getILoggerFactory(), + updateService); + } + + /** + * The data file is registered with the update service when update on + * start-up is on, even though auto update is off. + */ + @Test + public void UpdateOnStartup_AutoUpdateOff_DataFileRegistered() + throws Exception { + ImplementedBuilder builder = newBuilder() + .setAutoUpdate(false) + .setDataUpdateOnStartup(true) + .setDataUpdateLicenseKey(licenseKey); + + builder.build("", false); + + verify(updateService, times(1)).registerDataFile(any()); + } + + /** + * The engine does not exist when the data file is registered, so the + * data file carries the engine's type name for the update service's log. + */ + @Test + public void UpdateOnStartup_DataFileCarriesTheEngineTypeName() + throws Exception { + ImplementedBuilder builder = newBuilder() + .setAutoUpdate(false) + .setDataUpdateOnStartup(true) + .setDataUpdateLicenseKey(licenseKey); + + builder.build("", false); + + ArgumentCaptor registered = + ArgumentCaptor.forClass(AspectEngineDataFile.class); + verify(updateService).registerDataFile(registered.capture()); + assertEquals("Implemented", + ((AspectEngineDataFileDefault) registered.getValue()) + .getEngineTypeName()); + } + + @Test + public void AutoUpdateAndUpdateOnStartupOff_DataFileNotRegistered() + throws Exception { + ImplementedBuilder builder = newBuilder() + .setAutoUpdate(false) + .setDataUpdateOnStartup(false); + + builder.build("", false); + + verify(updateService, never()).registerDataFile(any()); + } + + /** + * The default update URL is the Distributor's, which serves nothing + * without a license key. + */ + @Test + public void AutoUpdate_DefaultUrlNoLicenseKey_BuildRefused() { + ImplementedBuilder builder = newBuilder().setAutoUpdate(true); + + PipelineConfigurationException e = assertThrows( + PipelineConfigurationException.class, + () -> builder.build("", false)); + + assertTrue(e.getMessage().contains("setAutoUpdate(false)")); + assertFalse(e.getMessage().contains("setDataUpdateOnStartup(false)")); + verify(updateService, never()).registerDataFile(any()); + } + + @Test + public void UpdateOnStartup_DefaultUrlNoLicenseKey_BuildRefused() { + ImplementedBuilder builder = newBuilder() + .setAutoUpdate(false) + .setDataUpdateOnStartup(true); + + PipelineConfigurationException e = assertThrows( + PipelineConfigurationException.class, + () -> builder.build("", false)); + + assertTrue(e.getMessage().contains("setDataUpdateOnStartup(false)")); + assertFalse(e.getMessage().contains("setAutoUpdate(false)")); + } + + @Test + public void AutoUpdate_LicenseKeySet_BuildAllowed() throws Exception { + ImplementedBuilder builder = newBuilder() + .setAutoUpdate(true) + .setDataUpdateLicenseKey(licenseKey); + + builder.build("", false); + + verify(updateService, times(1)).registerDataFile(any()); + } + + @Test + public void AutoUpdate_OtherUrlNoLicenseKey_BuildAllowed() + throws Exception { + ImplementedBuilder builder = newBuilder() + .setAutoUpdate(true) + .setDataUpdateUrl("https://example.com/data.file"); + + builder.build("", false); + + verify(updateService, times(1)).registerDataFile(any()); + } + + @Test + public void AutoUpdateOff_NoLicenseKey_BuildAllowed() throws Exception { + ImplementedBuilder builder = newBuilder().setAutoUpdate(false); + + builder.build("", false); + + verify(updateService, never()).registerDataFile(any()); + } } diff --git a/pipeline/pipeline.engines/src/main/java/fiftyone/pipeline/engines/data/AspectEngineDataFileDefault.java b/pipeline/pipeline.engines/src/main/java/fiftyone/pipeline/engines/data/AspectEngineDataFileDefault.java index 100d23207..55ecaa049 100644 --- a/pipeline/pipeline.engines/src/main/java/fiftyone/pipeline/engines/data/AspectEngineDataFileDefault.java +++ b/pipeline/pipeline.engines/src/main/java/fiftyone/pipeline/engines/data/AspectEngineDataFileDefault.java @@ -41,6 +41,7 @@ public class AspectEngineDataFileDefault implements AspectEngineDataFile { private DataFileConfiguration configuration; private DataUpdateService dataUpdateService = null; private String tempDataDirPath; + private String engineTypeName; @Override public String getIdentifier() { @@ -87,6 +88,23 @@ public void setTempDataFilePath(String path) { this.tempDataFilePath = path; } + /** + * The type name of the engine this data file is for, which the update + * service logs until the engine is set. + * @return the engine type name, or null if it is not known + */ + public String getEngineTypeName() { + return engineTypeName; + } + + /** + * Set the type name of the engine this data file is for. + * @param engineTypeName the engine type name + */ + public void setEngineTypeName(String engineTypeName) { + this.engineTypeName = engineTypeName; + } + @Override public String getTempDataDirPath() { if (tempDataDirPath == null && diff --git a/pipeline/pipeline.engines/src/main/java/fiftyone/pipeline/engines/flowelements/OnPremiseAspectEngineBuilderBase.java b/pipeline/pipeline.engines/src/main/java/fiftyone/pipeline/engines/flowelements/OnPremiseAspectEngineBuilderBase.java index 37c9dc7c9..a0995b9fb 100644 --- a/pipeline/pipeline.engines/src/main/java/fiftyone/pipeline/engines/flowelements/OnPremiseAspectEngineBuilderBase.java +++ b/pipeline/pipeline.engines/src/main/java/fiftyone/pipeline/engines/flowelements/OnPremiseAspectEngineBuilderBase.java @@ -23,6 +23,7 @@ package fiftyone.pipeline.engines.flowelements; import fiftyone.pipeline.annotations.DefaultValue; +import fiftyone.pipeline.core.exceptions.PipelineConfigurationException; import fiftyone.pipeline.engines.Constants; import fiftyone.pipeline.engines.configuration.DataFileConfiguration; import fiftyone.pipeline.engines.data.AspectEngineDataFile; @@ -181,28 +182,95 @@ protected void preCreateEngine() { // Any files that have the 'update on startup' flag set // will be updated now. // Create the auto-update configuration and register it. + for (DataFileConfiguration dataFileConfig : dataFileConfigs) { + checkUpdateConfiguration(dataFileConfig); + } for (DataFileConfiguration dataFileConfig : dataFileConfigs) { AspectEngineDataFile dataFile = newAspectEngineDataFile(); dataFile.setIdentifier(dataFileConfig.getIdentifier()); dataFile.setConfiguration(dataFileConfig); dataFile.setTempDataDirPath(tempDir); + if (dataFile instanceof AspectEngineDataFileDefault) { + // By convention an engine is named for its builder. + String builderName = getClass().getSimpleName(); + ((AspectEngineDataFileDefault) dataFile).setEngineTypeName( + builderName.endsWith("Builder") ? + builderName.substring( + 0, builderName.length() - "Builder".length()) : + builderName); + } - if (dataFileConfig.getAutomaticUpdatesEnabled()) { - if (dataUpdateService == null) { - throw new RuntimeException( - "Auto update enabled by data update service does not exist. " + - "This can be corrected by passing an DataUpdateService " + - "instance to the engine builder constructor. " + - "If building from configuration, this can be corrected " + - "by adding an DataUpdateService instance to the " + - "the pipeline builder via addService() method."); - } + if (dataFileConfig.getAutomaticUpdatesEnabled() || + dataFileConfig.getUpdateOnStartup()) { dataUpdateService.registerDataFile(dataFile); } dataFiles.add(dataFile); } } + /** + * Refuse a data file configuration that needs a data update service or + * a license key it does not have. Every data file is checked before any + * is registered, so a refused build leaves nothing registered. + */ + private void checkUpdateConfiguration(DataFileConfiguration dataFileConfig) { + boolean autoUpdate = dataFileConfig.getAutomaticUpdatesEnabled(); + boolean updateOnStartup = dataFileConfig.getUpdateOnStartup(); + if (autoUpdate == false && updateOnStartup == false) { + return; + } + String features = (autoUpdate ? "auto update" : "") + + (autoUpdate && updateOnStartup ? " and " : "") + + (updateOnStartup ? "update on startup" : ""); + if (dataUpdateService == null) { + throw new RuntimeException( + "The data update service does not exist but is " + + "needed for " + features + ". " + + "This can be corrected by passing a DataUpdateService " + + "instance to the engine builder constructor. " + + "If building from configuration, this can be corrected " + + "by adding a DataUpdateService instance to the " + + "pipeline builder via addService() method."); + } + if (isLicenseKeyRequired(dataFileConfig) && + hasLicenseKey(dataFileConfig) == false) { + throw new PipelineConfigurationException( + "No license key is set, and the data update URL " + + "serves nothing without one, so the engine cannot " + + "be built with " + features + " on. Set a license " + + "key with setDataUpdateLicenseKey, or turn off " + + (autoUpdate ? "auto update with setAutoUpdate(false)" : "") + + (autoUpdate && updateOnStartup ? " and " : "") + + (updateOnStartup ? + "update on startup with setDataUpdateOnStartup(false)" : "") + + "."); + } + } + + /** + * Whether the data update URL in the configuration serves nothing + * without a license key. Engines whose update source needs a key + * override this, and the engine then refuses to build with a data update + * option on and no key set. + * @param dataFileConfig the data file configuration to check + * @return true if the update source needs a license key + */ + protected boolean isLicenseKeyRequired(DataFileConfiguration dataFileConfig) { + return false; + } + + private static boolean hasLicenseKey(DataFileConfiguration dataFileConfig) { + List keys = dataFileConfig.getDataUpdateLicenseKeys(); + if (keys != null) { + for (String key : keys) { + if (key != null && key.isEmpty() == false) { + return true; + } + } + } + return false; + } + @SuppressWarnings("unchecked") @Override protected void configureEngine(TEngine engine) throws Exception { 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 a2c4af853..b21f1a317 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 @@ -47,6 +47,7 @@ import java.net.URI; import java.net.URLDecoder; import java.nio.file.*; +import java.time.Instant; import java.security.DigestInputStream; import java.security.MessageDigest; import java.security.NoSuchAlgorithmException; @@ -217,10 +218,14 @@ private AutoUpdateStatus checkForUpdate(Object state, boolean manualUpdate) { null; boolean newDataAvailable = false; if (dataFile != null) { - // Only check the file system if the file system watcher - // is not enabled and the engine is using a temporary file. + logger.info("Checking for update"); logger.debug("CheckForUpdate {}", dataFile.getDataFilePath()); - if (dataFile.getConfiguration().getFileSystemWatcherEnabled() == false && + // Compare the data file with the temporary file the engine uses. + // A programmatic update always does, whether or not Automatic + // Update from File is enabled. The timer does only when no file + // system watcher exists to notice a new file. + if ((manualUpdate || + dataFile.getConfiguration().getWatchKey() == null) && dataFile.getDataFilePath() != null && dataFile.getDataFilePath().isEmpty() == false && dataFile.getTempDataFilePath() != null && @@ -241,7 +246,11 @@ private AutoUpdateStatus checkForUpdate(Object state, boolean manualUpdate) { if (newDataAvailable == false && dataFile.getConfiguration().getDataUpdateUrl() != null && dataFile.getConfiguration().getDataUpdateUrl().isEmpty() == false) { - result = checkForUpdateFromUrl(dataFile); + // A failed update is tried again only when the timer is on. + result = checkForUpdateFromUrl( + dataFile, + manualUpdate == false && + dataFile.getAutomaticUpdatesEnabled()); newDataAvailable = result == AutoUpdateStatus.AUTO_UPDATE_IN_PROGRESS || result == AutoUpdateStatus.AUTO_UPDATE_SUCCESS; @@ -335,15 +344,18 @@ private AutoUpdateStatus updatedFileAvailable(AspectEngineDataFile dataFile) { return AutoUpdateStatus.AUTO_UPDATE_SUCCESS; } + logger.info("Attempting to refresh Engine '{}' with new data", + getEngineType(dataFile)); // Try to update the file multiple times to ensure the file is not locked. int tries = 0; + Exception lastFailure = null; while (tries < 10) { try { dataFile.getEngine().refreshData(dataFile.getIdentifier()); return AUTO_UPDATE_SUCCESS; } catch (Exception ex) { - logger.warn("File Update: Error applying a data update to engine '{}'", - dataFile.getEngine().getClass().getSimpleName(), ex); + lastFailure = ex; + logger.debug("Refresh attempt {} failed", tries + 1, ex); try { Thread.sleep(200); } catch (InterruptedException ignored) { @@ -351,6 +363,7 @@ private AutoUpdateStatus updatedFileAvailable(AspectEngineDataFile dataFile) { } tries++; } + logRefreshFailure(dataFile, lastFailure, tries); return AUTO_UPDATE_REFRESH_FAILED; } @@ -446,22 +459,19 @@ public AutoUpdateStatus updateFromMemory(AspectEngineDataFile dataFile, byte[] d .writeBytes(data); } catch (Exception ex) { logger.error("An error occurred when writing to " + - "'" + dataFile.getDataFilePath() + - "'. The engine will be updated to use the new data " + - "but the file on disk will still contain old data.", - ex); + dataFile.getDataFilePath() + + ". Error detail: " + ex.getMessage(), ex); } } try { // Refresh the engine using the new data. + logger.info("Attempting to refresh Engine '{}' with new data", + getEngineType(dataFile)); dataFile.getEngine().refreshData(dataFile.getIdentifier(), data); result = AUTO_UPDATE_SUCCESS; } catch (Exception ex) { - logger.error("An error occurred when applying a " + - "data update to engine '" + dataFile.getEngine().getClass().getSimpleName() + - "'.", - ex); + logRefreshFailure(dataFile, ex, null); result = AutoUpdateStatus.AUTO_UPDATE_REFRESH_FAILED; } @@ -482,6 +492,7 @@ public void registerDataFile(final AspectEngineDataFile dataFile) { // We also want to do this synchronously so that execution // will block until the engine is ready. if (dataFile.getConfiguration().getUpdateOnStartup() && isFalse(alreadyRegistered)) { + logger.info("Updating on start-up"); logger.debug("Checking for Update on Startup {}", dataFile.getDataFilePath()); AutoUpdateStatus status = checkForUpdate(dataFile, false); if (ObjectUtils.notEqual(status, AUTO_UPDATE_SUCCESS) && @@ -537,11 +548,15 @@ public void run() { } } - // If file system watcher is enabled then set it up. - if (aspectDataFile.getConfiguration().getFileSystemWatcherEnabled() && + // If file system watcher is enabled then set it up. The + // automatic update switch governs the watcher as well as the + // polling timer. + if (aspectDataFile.getAutomaticUpdatesEnabled() && + aspectDataFile.getConfiguration().getFileSystemWatcherEnabled() && aspectDataFile.getConfiguration().getWatchKey() == null && aspectDataFile.getDataFilePath() != null && aspectDataFile.getDataFilePath().isEmpty() == false) { + logger.info("Creating file system watcher"); logger.debug("Initialising watch service"); final Path aspectDataFilePath = Paths.get(aspectDataFile.getDataFilePath()).toAbsolutePath(); @@ -714,15 +729,18 @@ private static List licenseKeysToMask( * If the data currently used by the engine is the newest available then * nothing will be downloaded. * - * @param dataFile the data file to use - * @param tempFile the temp file to write the data to + * @param dataFile the data file to use + * @param tempFile the temp file to write the data to + * @param automatic true if the update will be tried again if it fails * @return the {@link AutoUpdateStatus} value indicating the result */ private AutoUpdateStatus downloadFile( AspectEngineDataFile dataFile, - FileWrapper tempFile) { + FileWrapper tempFile, + boolean automatic) { String url = dataFile.getFormattedUrl(); + String engineType = getEngineType(dataFile); // The URL carries the license keys, so every message names it with // each key masked. List licenseKeys = licenseKeysToMask(dataFile, url); @@ -730,20 +748,20 @@ private AutoUpdateStatus downloadFile( logger.debug("downloadFile from {}", loggedUrl); try { + logger.info("Checking for update from '{}' for Engine '{}'", + loggedUrl, engineType); HttpURLConnection connection = httpClient.connect(new URI(url.trim()).toURL()); if (connection == null) { - logger.error("No response from data update service at '{}' for engine '{}'", - loggedUrl, Objects.nonNull(dataFile.getEngine()) ? - dataFile.getEngine().getClass().getSimpleName() : "No Engine"); + logger.warn(connectFailure(loggedUrl, engineType, automatic, + "No response from the data update service")); return AutoUpdateStatus.AUTO_UPDATE_HTTPS_ERR; } try { // Set last-modified header to ensure that a file will only // be downloaded if it is newer than the data we already have. + long ifModifiedSince = 0; if (dataFile.getConfiguration().getVerifyModifiedSince() == true) { - long ifModifiedSince = dataFile - .getDataPublishedDateTime() - .getTime(); + ifModifiedSince = getIfModifiedSince(dataFile); connection.setIfModifiedSince(ifModifiedSince); } @@ -751,26 +769,43 @@ private AutoUpdateStatus downloadFile( switch (connection.getResponseCode()) { case (HttpURLConnection.HTTP_OK): - return downloadOkResponse(connection, dataFile, tempFile); + AutoUpdateStatus downloaded; + try { + 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)), + LicenseKeyMask.maskIn(e, licenseKeys)); + return AutoUpdateStatus.AUTO_UPDATE_HTTPS_ERR; + } + if (downloaded == AutoUpdateStatus.AUTO_UPDATE_IN_PROGRESS) { + logger.info("Downloaded new data from '{}' for Engine '{}'", + loggedUrl, engineType); + } + return downloaded; // Note: needed because TooManyRequests is not available // in some versions of the HttpStatusCode enum. case (429): - logger.error("Too many requests to '{}' for {}", - loggedUrl, getIdForLogging(dataFile)); + logger.warn(downloadFailure(loggedUrl, engineType, automatic, + "HTTP status code 429 (too many requests)")); return AutoUpdateStatus.AUTO_UPDATE_ERR_429_TOO_MANY_ATTEMPTS; case HttpURLConnection.HTTP_NOT_MODIFIED: - logger.debug("No data update available from '{}' for {}", - loggedUrl, getIdForLogging(dataFile)); + logger.info("No data newer than {} found at '{}' for Engine '{}'", + Instant.ofEpochMilli(ifModifiedSince), loggedUrl, + engineType); return AutoUpdateStatus.AUTO_UPDATE_NOT_NEEDED; case HttpURLConnection.HTTP_FORBIDDEN: - logger.error("Access denied to data update service at '{}' for {}", - loggedUrl, getIdForLogging(dataFile)); + logger.warn(downloadFailure(loggedUrl, engineType, automatic, + "HTTP status code 403 (access denied)")); return AutoUpdateStatus.AUTO_UPDATE_ERR_403_FORBIDDEN; default: - logger.error("HTTP status code '{}' from data update service at '{}' for {}", - connection.getResponseCode(), loggedUrl, - getIdForLogging(dataFile)); + logger.warn(downloadFailure(loggedUrl, engineType, automatic, + "HTTP status code " + connection.getResponseCode())); return AutoUpdateStatus.AUTO_UPDATE_HTTPS_ERR; } } finally { @@ -778,12 +813,90 @@ private AutoUpdateStatus downloadFile( } } catch (Exception e) { // An HTTP library's exception often names the URL it requested. - logger.error("Error while processing data file download", + logger.warn(connectFailure(loggedUrl, engineType, automatic, + LicenseKeyMask.maskIn(e.getMessage(), licenseKeys)), LicenseKeyMask.maskIn(e, licenseKeys)); return AutoUpdateStatus.AUTO_UPDATE_HTTPS_ERR; } } + /** + * Get the time to send as If-Modified-Since. This is the publication date + * of the data file, or the last modified time of the data file on disk + * where the data file has no publication date. + */ + private long getIfModifiedSince(AspectEngineDataFile dataFile) { + Date published = dataFile.getDataPublishedDateTime(); + long publishedMillis = published == null ? 0 : published.getTime(); + if (publishedMillis > 0) { + return publishedMillis; + } + String path = dataFile.getDataFilePath(); + if (path != null && path.isEmpty() == false) { + return fileWrapperFactory.getLastModified(path); + } + return publishedMillis; + } + + private static String retryNote(boolean automatic) { + return automatic ? " Update will be attempted again later." : ""; + } + + /** + * The warning for a failed connection. The URL and the detail are + * 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; + } + + /** + * The warning for a failed download. The URL and the detail 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; + } + + /** + * Log the Errors table's message for a refresh that failed, with the + * number of tries for a refresh from the file and without it for one + * from data held in memory. The exception is passed to the logger, so + * its detail is kept beside the message. + */ + private void logRefreshFailure( + AspectEngineDataFile dataFile, + Exception ex, + Integer tries) { + logger.error("An error occurred when applying a data update to " + + "engine '" + getEngineType(dataFile) + "'" + + (tries == null ? "." : " after " + tries + " tries."), ex); + } + + private String getEngineType(AspectEngineDataFile dataFile) { + if (dataFile.getEngine() != null) { + return dataFile.getEngine().getClass().getSimpleName(); + } + // The engine is built after update on start-up has run. + if (dataFile instanceof AspectEngineDataFileDefault && + ((AspectEngineDataFileDefault) dataFile).getEngineTypeName() != null) { + return ((AspectEngineDataFileDefault) dataFile).getEngineTypeName(); + } + return "No Engine"; + } + /** * Persist the body of a 200 OK download to {@code tempFile}. *

@@ -792,11 +905,16 @@ private AutoUpdateStatus downloadFile( * {@link GZIPInputStream}, so the JDK's concatenated-gzip-member * decoder behaves correctly on top of {@link HttpURLConnection} on * every JDK from 7 upwards. See that method for the gory details. + *

+ * A failure reading the download is thrown, for the caller to report. + * A failure writing {@code tempFile} is logged here as the + * specification's write error. */ private AutoUpdateStatus downloadOkResponse( HttpURLConnection connection, AspectEngineDataFile dataFile, - FileWrapper tempFile) throws IOException { + FileWrapper tempFile, + boolean automatic) throws IOException { logger.debug("HTTP Status is OK"); boolean verifyMd5 = dataFile.getConfiguration().getVerifyMd5(); boolean decompress = dataFile.getConfiguration().getDecompressContent(); @@ -817,9 +935,25 @@ private AutoUpdateStatus downloadOkResponse( src = new GZIPInputStream(src); } - writeBodyTo(tempFile, src); + ReadFailureRecorder body = new ReadFailureRecorder(src); + try { + writeBodyTo(tempFile, body); + } catch (IOException e) { + if (body.readFailed) { + // The download failed, which the caller reports. + throw e; + } + logger.error("An error occurred when writing to " + + tempFile.getPath() + ". Error detail: " + e.getMessage(), e); + return AutoUpdateStatus.AUTO_UPDATE_ERR_READING_STREAM; + } if (verifyMd5 && !md5Matches(md, connection)) { + logger.warn("An error occurred during the integrity check of new " + + "data file for " + getEngineType(dataFile) + "." + + retryNote(automatic) + + " Error detail: the MD5 hash of the download does not " + + "match the Content-MD5 header"); return AutoUpdateStatus.AUTO_UPDATE_ERR_MD5_VALIDATION_FAILED; } return AutoUpdateStatus.AUTO_UPDATE_IN_PROGRESS; @@ -857,6 +991,38 @@ public int available() throws IOException { return new BufferedInputStream(lying); } + /** + * Records whether a read of the download failed, so that a failure to + * write the temporary file can be told from a failure to download. + */ + private static final class ReadFailureRecorder extends FilterInputStream { + private boolean readFailed; + + ReadFailureRecorder(InputStream in) { + super(in); + } + + @Override + public int read() throws IOException { + try { + return super.read(); + } catch (IOException e) { + readFailed = true; + throw e; + } + } + + @Override + public int read(byte[] b, int off, int len) throws IOException { + try { + return super.read(b, off, len); + } catch (IOException e) { + readFailed = true; + throw e; + } + } + } + private void writeBodyTo(FileWrapper tempFile, InputStream body) throws IOException { if (tempFile.getPath() != null) { logger.debug("Copying download stream"); @@ -890,20 +1056,17 @@ public void close() { } } - private String getIdForLogging(AspectEngineDataFile dataFile) { - return dataFile.getEngine() == null ? - "data file '" + dataFile.getIdentifier() + "'" : - "engine '" + dataFile.getEngine().getClass().getSimpleName() + "'"; - } - - private AutoUpdateStatus checkForUpdateFromUrl(AspectEngineDataFile dataFile) { + private AutoUpdateStatus checkForUpdateFromUrl( + AspectEngineDataFile dataFile, + boolean automatic) { if (dataFile.getDataFilePath() == null || dataFile.getDataFilePath().isEmpty()) { // There is no data file path specified so perform the // update entirely in memory. try { FileWrapper uncompressedData = new FileWrapperMemory(); - AutoUpdateStatus memoryDownloadResult = downloadFile(dataFile, uncompressedData); + AutoUpdateStatus memoryDownloadResult = + downloadFile(dataFile, uncompressedData, automatic); if (memoryDownloadResult != AutoUpdateStatus.AUTO_UPDATE_IN_PROGRESS) { return memoryDownloadResult; } @@ -911,6 +1074,8 @@ private AutoUpdateStatus checkForUpdateFromUrl(AspectEngineDataFile dataFile) { if (dataFile.getEngine() != null) { // Tell the engine to refresh itself with // the new data. + logger.info("Attempting to refresh Engine '{}' with new data", + getEngineType(dataFile)); dataFile.getEngine().refreshData(dataFile.getIdentifier(), reader.toByteArray()); } else { @@ -922,21 +1087,26 @@ private AutoUpdateStatus checkForUpdateFromUrl(AspectEngineDataFile dataFile) { // The engine, or the configuration, now holds the new data. return AUTO_UPDATE_SUCCESS; } catch (Exception ex) { - logger.error("An error occurred when applying a data update to engine '{}'" , - Objects.nonNull(dataFile.getEngine())? - dataFile.getEngine().getClass().getName(): "no engine",ex); + logRefreshFailure(dataFile, ex, null); return AutoUpdateStatus.AUTO_UPDATE_REFRESH_FAILED; } } - + if (dataFile.getTempDataDirPath() == null || + dataFile.getTempDataDirPath().isEmpty()) { + logger.error("The data file '" + dataFile.getIdentifier() + + "' is checking for updates but does not have a temporary " + + "file path configured."); + return AutoUpdateStatus.AUTO_UPDATE_REFRESH_FAILED; + } Path uncompressedTempFile = Paths.get( dataFile.getTempDataDirPath(), dataFile.getIdentifier() + "-" + randomUUID() + ".tmp"); FileWrapper uncompressedData = fileWrapperFactory.build(uncompressedTempFile.toString()); try { // Check if there is an update and download it if there is - AutoUpdateStatus result = downloadFile(dataFile, uncompressedData); + AutoUpdateStatus result = + downloadFile(dataFile, uncompressedData, automatic); if (result == AutoUpdateStatus.AUTO_UPDATE_IN_PROGRESS) { WatchKey watchKey = dataFile.getConfiguration().getWatchKey(); @@ -962,12 +1132,9 @@ private AutoUpdateStatus checkForUpdateFromUrl(AspectEngineDataFile dataFile) { logger.debug("Reading file {}", d.read()); } } catch (Exception ex) { - logger.error("An error occurred when moving a data file to replace " + - "the existing one at {} for engine '{}'.", - dataFile.getDataFilePath(), - Objects.nonNull(dataFile.getEngine()) ? - dataFile.getEngine().getClass().getSimpleName() : "No engine defined", - ex); + logger.error("An error occurred when copying a data file to " + + "replace the existing one at '{}'.", + dataFile.getDataFilePath(), ex); result = AutoUpdateStatus.AUTO_UPDATE_NEW_FILE_CANT_RENAME; } // Make sure to enable the file watcher again if needed. diff --git a/pipeline/pipeline.engines/src/test/java/fiftyone/pipeline/engines/flowelements/OnPremiseAspectEngineBuilderBaseTest.java b/pipeline/pipeline.engines/src/test/java/fiftyone/pipeline/engines/flowelements/OnPremiseAspectEngineBuilderBaseTest.java index 68d84213d..196e6b9d3 100644 --- a/pipeline/pipeline.engines/src/test/java/fiftyone/pipeline/engines/flowelements/OnPremiseAspectEngineBuilderBaseTest.java +++ b/pipeline/pipeline.engines/src/test/java/fiftyone/pipeline/engines/flowelements/OnPremiseAspectEngineBuilderBaseTest.java @@ -22,7 +22,11 @@ package fiftyone.pipeline.engines.flowelements; +import fiftyone.pipeline.core.exceptions.PipelineConfigurationException; import fiftyone.pipeline.engines.Constants; +import fiftyone.pipeline.engines.configuration.DataFileConfiguration; +import fiftyone.pipeline.engines.configuration.DataFileConfigurationDefault; +import fiftyone.pipeline.engines.services.DataUpdateService; import org.junit.After; import org.junit.Assume; import org.junit.Before; @@ -35,11 +39,17 @@ import java.nio.file.Path; import java.nio.file.Paths; import java.nio.file.attribute.PosixFilePermission; +import java.util.Collections; import java.util.List; import java.util.Set; import static org.junit.Assert.assertFalse; +import static org.junit.Assert.assertThrows; import static org.junit.Assert.assertTrue; +import static org.mockito.ArgumentMatchers.any; +import static org.mockito.Mockito.mock; +import static org.mockito.Mockito.never; +import static org.mockito.Mockito.verify; @SuppressWarnings("rawtypes") public class OnPremiseAspectEngineBuilderBaseTest { @@ -131,4 +141,52 @@ public void CreateTemporaryFolder_VerifyPermissions() { assertTrue(tempDir.canWrite()); assertTrue(tempDir.canExecute()); } + + /** + * Every data file's license key is checked before any data file is + * registered, so a build refused for a later data file leaves nothing + * registered with the data update service. + */ + @Test + public void LaterDataFileHasNoLicenseKey_NothingRegistered() { + DataUpdateService updateService = mock(DataUpdateService.class); + OnPremiseAspectEngineBuilderBase builder = + new OnPremiseAspectEngineBuilderBase(null, updateService) { + @Override + public OnPremiseAspectEngineBuilderBase setPerformanceProfile( + Constants.PerformanceProfiles profile) { + return this; + } + + @Override + protected AspectEngine newEngine(List properties) { + return null; + } + + @Override + protected boolean isLicenseKeyRequired( + DataFileConfiguration dataFileConfig) { + return true; + } + }; + builder.addDataFile(autoUpdateConfiguration("First", "SOMELICENSEKEY")); + builder.addDataFile(autoUpdateConfiguration("Second", null)); + + assertThrows(PipelineConfigurationException.class, builder::buildEngine); + + verify(updateService, never()).registerDataFile(any()); + } + + private static DataFileConfiguration autoUpdateConfiguration( + String identifier, + String licenseKey) { + DataFileConfigurationDefault config = new DataFileConfigurationDefault(); + config.setIdentifier(identifier); + config.setAutomaticUpdatesEnabled(true); + if (licenseKey != null) { + config.setDataUpdateLicenseKeys( + Collections.singletonList(licenseKey)); + } + return config; + } } \ No newline at end of file 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 new file mode 100644 index 000000000..4ec40a1b0 --- /dev/null +++ b/pipeline/pipeline.engines/src/test/java/fiftyone/pipeline/engines/services/DataUpdateServiceLoggingTests.java @@ -0,0 +1,550 @@ +/* ********************************************************************* + * This Original Work is copyright of 51 Degrees Mobile Experts Limited. + * Copyright 2026 51 Degrees Mobile Experts Limited, Davidson House, + * Forbury Square, Reading, Berkshire, United Kingdom RG1 3EU. + * + * This Original Work is licensed under the European Union Public Licence + * (EUPL) v.1.2 and is subject to its terms as set out below. + * + * If a copy of the EUPL was not distributed with this file, You can obtain + * one at https://opensource.org/licenses/EUPL-1.2. + * + * The 'Compatible Licences' set out in the Appendix to the EUPL (as may be + * amended by the European Commission) shall be deemed incompatible for + * the purposes of the Work and the provisions of the compatibility + * clause in Article 5 of the EUPL shall not apply. + * + * If using the Work as, or as part of, a network application, by + * including the attribution notice(s) required under Article 5 of the EUPL + * in the end user terms of the application under an appropriate heading, + * such notice(s) shall fulfill the requirements of that article. + * ********************************************************************* */ + +package fiftyone.pipeline.engines.services; + +import ch.qos.logback.classic.Level; +import ch.qos.logback.classic.spi.ILoggingEvent; +import ch.qos.logback.classic.spi.ThrowableProxyUtil; +import ch.qos.logback.core.read.ListAppender; +import fiftyone.common.wrappers.io.FileWrapperFactoryDefault; +import fiftyone.pipeline.engines.configuration.DataFileConfiguration; +import fiftyone.pipeline.engines.configuration.DataFileConfigurationDefault; +import fiftyone.pipeline.engines.data.AspectData; +import fiftyone.pipeline.engines.data.AspectEngineDataFileDefault; +import fiftyone.pipeline.engines.data.AspectPropertyMetaData; +import fiftyone.pipeline.engines.flowelements.OnPremiseAspectEngine; +import org.junit.After; +import org.junit.Before; +import org.junit.Test; +import org.slf4j.LoggerFactory; + +import java.io.ByteArrayInputStream; +import java.io.File; +import java.io.IOException; +import java.net.HttpURLConnection; +import java.net.URL; +import java.util.ArrayList; +import java.util.Collections; +import java.util.List; + +import static org.junit.Assert.assertEquals; +import static org.junit.Assert.assertFalse; +import static org.junit.Assert.assertNotNull; +import static org.junit.Assert.assertTrue; +import static org.mockito.ArgumentMatchers.any; +import static org.mockito.ArgumentMatchers.anyString; +import static org.mockito.Mockito.doThrow; +import static org.mockito.Mockito.mock; +import static org.mockito.Mockito.verify; +import static org.mockito.Mockito.when; + +/** + * The messages and levels in the Logging section of the data update + * specification, and the If-Modified-Since time the update URL is sent. + * @see Specification + */ +@SuppressWarnings("unchecked") +public class DataUpdateServiceLoggingTests { + + private static final String UPDATE_URL = "http://test.com"; + // 13 September 2020, 12:26:40 UTC. + private static final long FILE_MODIFIED_MILLIS = 1600000000000L; + // A license key of the length and characters the Distributor issues. + private static final String LICENSE_KEY = "QF8ZR2KD7NMB4XWT9HJC3LPA"; + private static final String MASKED_KEY = "********************3LPA"; + private static final String KEYED_URL = UPDATE_URL + "?LicenseKeys=" + + LICENSE_KEY + "&Download=True&Type=HashV41"; + private static final String MASKED_URL = UPDATE_URL + "?LicenseKeys=" + + MASKED_KEY + "&Download=True&Type=HashV41"; + + private ch.qos.logback.classic.Logger logger; + private ListAppender appender; + private HttpClient httpClient; + private HttpURLConnection connection; + private DataUpdateServiceDefault dataUpdate; + private OnPremiseAspectEngine engine; + private String engineType; + private File dataFile; + + @Before + public void init() throws IOException { + logger = (ch.qos.logback.classic.Logger) LoggerFactory.getLogger( + "DataUpdateServiceLoggingTests"); + logger.setLevel(Level.INFO); + appender = new ListAppender<>(); + appender.start(); + logger.addAppender(appender); + + connection = mock(HttpURLConnection.class); + httpClient = mock(HttpClient.class); + when(httpClient.connect(any(URL.class))).thenReturn(connection); + // The futures are real but their first run is a day away. + dataUpdate = new DataUpdateServiceDefault( + logger, httpClient, new FileWrapperFactoryDefault(), null); + + engine = mock(OnPremiseAspectEngine.class); + engineType = engine.getClass().getSimpleName(); + dataFile = File.createTempFile("logging-test", ".tmp"); + assertTrue(dataFile.setLastModified(FILE_MODIFIED_MILLIS)); + } + + @After + public void cleanup() { + dataUpdate.close(); + logger.detachAppender(appender); + dataFile.delete(); + } + + private AspectEngineDataFileDefault newDataFile( + boolean inMemory, + boolean autoUpdate, + boolean updateOnStartup) { + DataFileConfigurationDefault config = new DataFileConfigurationDefault(); + config.setAutomaticUpdatesEnabled(autoUpdate); + config.setUpdateOnStartup(updateOnStartup); + config.setFileSystemWatcherEnabled(false); + config.setDataUpdateUrl(UPDATE_URL); + config.setVerifyMd5(false); + config.setDecompressContent(false); + config.setPollingIntervalSeconds(86400); + config.setMaxRandomisationSeconds(0); + if (inMemory == false) { + config.setDataFilePath(dataFile.getAbsolutePath()); + } + AspectEngineDataFileDefault file = new AspectEngineDataFileDefault(); + file.setIdentifier("default"); + file.setEngine(engine); + file.setConfiguration(config); + file.setTempDataDirPath(System.getProperty("java.io.tmpdir")); + when(engine.getDataFileMetaData()).thenReturn(file); + return file; + } + + private List logged(Level level) { + List messages = new ArrayList<>(); + for (ILoggingEvent event : appender.list) { + if (event.getLevel() == level) { + messages.add(event.getFormattedMessage()); + } + } + return messages; + } + + private void assertLogged(Level level, String message) { + List messages = logged(level); + assertTrue( + "Expected '" + message + "' at " + level + " but got " + messages, + messages.contains(message)); + } + + @Test + public void IfModifiedSince_NoPublishedDate_UsesFileLastModified() + throws Exception { + when(connection.getResponseCode()) + .thenReturn(HttpURLConnection.HTTP_NOT_MODIFIED); + AspectEngineDataFileDefault file = newDataFile(false, false, false); + file.getConfiguration().setVerifyModifiedSince(true); + + dataUpdate.checkForUpdate(engine); + + verify(connection).setIfModifiedSince(FILE_MODIFIED_MILLIS); + } + + @Test + public void IfModifiedSince_PublishedDate_UsedInsteadOfFileLastModified() + throws Exception { + when(connection.getResponseCode()) + .thenReturn(HttpURLConnection.HTTP_NOT_MODIFIED); + AspectEngineDataFileDefault file = newDataFile(false, false, false); + file.getConfiguration().setVerifyModifiedSince(true); + file.setDataPublishedDateTime(new java.util.Date(1500000000000L)); + + dataUpdate.checkForUpdate(engine); + + verify(connection).setIfModifiedSince(1500000000000L); + } + + @Test + public void Check_NotModified_LogsTheSpecifiedMessages() throws Exception { + when(connection.getResponseCode()) + .thenReturn(HttpURLConnection.HTTP_NOT_MODIFIED); + AspectEngineDataFileDefault file = newDataFile(false, false, false); + file.getConfiguration().setVerifyModifiedSince(true); + + dataUpdate.checkForUpdate(engine); + + assertLogged(Level.INFO, "Checking for update"); + assertLogged(Level.INFO, "Checking for update from '" + UPDATE_URL + + "' for Engine '" + engineType + "'"); + assertLogged(Level.INFO, "No data newer than 2020-09-13T12:26:40Z " + + "found at '" + UPDATE_URL + "' for Engine '" + engineType + "'"); + } + + @Test + public void Check_Downloaded_LogsDownloadAndRefresh() throws Exception { + when(connection.getResponseCode()) + .thenReturn(HttpURLConnection.HTTP_OK); + when(connection.getInputStream()) + .thenReturn(new ByteArrayInputStream(new byte[]{1, 2, 3})); + newDataFile(true, false, false); + + dataUpdate.checkForUpdate(engine); + + assertLogged(Level.INFO, "Downloaded new data from '" + UPDATE_URL + + "' for Engine '" + engineType + "'"); + assertLogged(Level.INFO, "Attempting to refresh Engine '" + + engineType + "' with new data"); + } + + @Test + public void UpdateFromMemory_LogsRefresh() { + AspectEngineDataFileDefault file = newDataFile(true, false, false); + + dataUpdate.updateFromMemory(file, new byte[]{1, 2, 3}); + + assertLogged(Level.INFO, "Attempting to refresh Engine '" + + engineType + "' with new data"); + } + + @Test + public void UpdateFromMemory_RefreshFails_LogsTheTableMessage() + throws Exception { + AspectEngineDataFileDefault file = newDataFile(true, false, false); + doThrow(new RuntimeException("no room")) + .when(engine).refreshData(anyString(), any(byte[].class)); + + dataUpdate.updateFromMemory(file, new byte[]{1, 2, 3}); + + assertLogged(Level.ERROR, "An error occurred when applying a data " + + "update to engine '" + engineType + "'."); + } + + @Test + public void UpdateOnStartup_LogsUpdatingOnStartUp() throws Exception { + when(connection.getResponseCode()) + .thenReturn(HttpURLConnection.HTTP_NOT_MODIFIED); + AspectEngineDataFileDefault file = newDataFile(false, false, true); + + dataUpdate.registerDataFile(file); + + assertLogged(Level.INFO, "Updating on start-up"); + } + + @Test + public void UpdateOnStartup_EngineNotBuiltYet_LogsTheEngineTypeName() + throws Exception { + when(connection.getResponseCode()) + .thenReturn(HttpURLConnection.HTTP_NOT_MODIFIED); + AspectEngineDataFileDefault file = newDataFile(false, false, true); + file.setEngine(null); + file.setEngineTypeName("ExampleEngine"); + + dataUpdate.registerDataFile(file); + + assertLogged(Level.INFO, "Checking for update from '" + UPDATE_URL + + "' for Engine 'ExampleEngine'"); + } + + @Test + public void UpdateOnStartup_AutoUpdateOff_StartsNoTimer() throws Exception { + when(connection.getResponseCode()) + .thenReturn(HttpURLConnection.HTTP_NOT_MODIFIED); + AspectEngineDataFileDefault file = newDataFile(false, false, true); + + dataUpdate.registerDataFile(file); + + assertEquals(null, file.getFuture()); + } + + @Test + public void FileSystemWatcher_LogsCreatingFileSystemWatcher() { + AspectEngineDataFileDefault file = newDataFile(false, true, false); + file.getConfiguration().setFileSystemWatcherEnabled(true); + + dataUpdate.registerDataFile(file); + + assertLogged(Level.INFO, "Creating file system watcher"); + assertNotNull(file.getConfiguration().getWatchKey()); + } + + @Test + public void ConnectFails_Manual_WarnsWithoutRetryText() 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"); + } + + @Test + public void ConnectFails_Automatic_WarnsThatUpdateWillBeTriedAgain() + throws Exception { + when(httpClient.connect(any(URL.class))) + .thenThrow(new IOException("refused")); + AspectEngineDataFileDefault file = newDataFile(false, true, true); + + 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"); + } + + @Test + public void ConnectFails_AutoUpdateOff_DoesNotPromiseAnotherTry() + throws Exception { + when(httpClient.connect(any(URL.class))) + .thenThrow(new IOException("refused")); + AspectEngineDataFileDefault file = newDataFile(false, false, true); + + 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"); + } + + private void assertStatusWarned(int status, String detail) + 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()); + } + + @Test + public void TooManyRequests_WarnsAboutTheDownload() throws Exception { + assertStatusWarned(429, "HTTP status code 429 (too many requests)"); + } + + @Test + public void Forbidden_WarnsAboutTheDownload() throws Exception { + assertStatusWarned(403, "HTTP status code 403 (access denied)"); + } + + @Test + public void OtherStatus_WarnsAboutTheDownload() throws Exception { + assertStatusWarned(500, "HTTP status code 500"); + } + + /** + * The download is written to a temporary file in a folder that does not + * exist, so the write fails while the download itself succeeds. + */ + @Test + public void TemporaryFileCannotBeWritten_LogsTheWriteError() + throws Exception { + when(connection.getResponseCode()) + .thenReturn(HttpURLConnection.HTTP_OK); + when(connection.getInputStream()) + .thenReturn(new ByteArrayInputStream(new byte[]{1, 2, 3})); + AspectEngineDataFileDefault file = newDataFile(false, false, false); + String missingDirectory = new File( + System.getProperty("java.io.tmpdir"), + "no-such-directory-" + System.nanoTime()).getAbsolutePath(); + file.setTempDataDirPath(missingDirectory); + // The engine's copy is the data file itself, so the file on disk is + // not newer and the update is downloaded. + file.setTempDataFilePath(dataFile.getAbsolutePath()); + + dataUpdate.checkForUpdate(engine); + + verify(connection).getInputStream(); + boolean found = false; + for (String message : logged(Level.ERROR)) { + found |= message.startsWith("An error occurred when writing to " + + missingDirectory) && message.contains(". Error detail: "); + } + assertTrue("No write error in " + logged(Level.ERROR) + + ", and the warnings are " + logged(Level.WARN), found); + assertTrue(logged(Level.WARN).isEmpty()); + } + + @Test + public void Md5DoesNotMatch_WarnsAboutIntegrityCheck() throws Exception { + when(connection.getResponseCode()) + .thenReturn(HttpURLConnection.HTTP_OK); + when(connection.getInputStream()) + .thenReturn(new ByteArrayInputStream(new byte[]{1, 2, 3})); + when(connection.getHeaderField("Content-MD5")).thenReturn("0"); + AspectEngineDataFileDefault file = newDataFile(true, false, false); + file.getConfiguration().setVerifyMd5(true); + + dataUpdate.checkForUpdate(engine); + + assertLogged(Level.WARN, "An error occurred during the integrity " + + "check of new data file for " + engineType + ". Error detail: " + + "the MD5 hash of the download does not match the Content-MD5 " + + "header"); + } + + @Test + public void NoTemporaryFilePath_LogsError() { + AspectEngineDataFileDefault file = newDataFile(false, false, false); + file.setTempDataDirPath(null); + when(engine.getTempDataDirPath()).thenReturn(null); + + dataUpdate.checkForUpdate(engine); + + assertLogged(Level.ERROR, "The data file 'default' is checking for " + + "updates but does not have a temporary file path configured."); + } + + /** + * A data file whose formatted URL carries a license key, as the + * Distributor's URL does, with every level logged. + */ + private AspectEngineDataFileDefault newKeyedDataFile(boolean inMemory) { + logger.setLevel(Level.DEBUG); + AspectEngineDataFileDefault file = newDataFile(inMemory, false, false); + DataFileConfiguration config = file.getConfiguration(); + config.setDataUpdateLicenseKeys( + Collections.singletonList(LICENSE_KEY)); + config.setUrlFormatter(dataFile -> KEYED_URL); + return file; + } + + /** + * Fails if any log entry, or any throwable logged with one, holds the + * license key in full. + */ + private void assertKeyOnlyMasked() { + assertFalse(appender.list.isEmpty()); + for (ILoggingEvent event : appender.list) { + String text = event.getFormattedMessage(); + if (event.getThrowableProxy() != null) { + text += "\n" + + ThrowableProxyUtil.asString(event.getThrowableProxy()); + } + assertFalse( + "The license key is in full in: " + text, + text.contains(LICENSE_KEY)); + } + } + + @Test + public void LicenseKey_NotModified_LogsTheMaskedUrl() throws Exception { + when(connection.getResponseCode()) + .thenReturn(HttpURLConnection.HTTP_NOT_MODIFIED); + AspectEngineDataFileDefault file = newKeyedDataFile(false); + file.getConfiguration().setVerifyModifiedSince(true); + + dataUpdate.checkForUpdate(engine); + + assertLogged(Level.INFO, "Checking for update from '" + MASKED_URL + + "' for Engine '" + engineType + "'"); + assertLogged(Level.INFO, "No data newer than 2020-09-13T12:26:40Z " + + "found at '" + MASKED_URL + "' for Engine '" + engineType + "'"); + assertKeyOnlyMasked(); + } + + @Test + public void LicenseKey_Downloaded_LogsTheMaskedUrl() throws Exception { + when(connection.getResponseCode()) + .thenReturn(HttpURLConnection.HTTP_OK); + when(connection.getInputStream()) + .thenReturn(new ByteArrayInputStream(new byte[]{1, 2, 3})); + newKeyedDataFile(true); + + dataUpdate.checkForUpdate(engine); + + assertLogged(Level.INFO, "Downloaded new data from '" + MASKED_URL + + "' for Engine '" + engineType + "'"); + assertKeyOnlyMasked(); + } + + /** + * An HTTP library's exception often names the URL it requested, so the + * error detail and the logged exception are masked too. + */ + @Test + public void LicenseKey_ConnectFails_MasksTheUrlAndTheException() + throws Exception { + when(httpClient.connect(any(URL.class))) + .thenThrow(new IOException("Connection refused: " + KEYED_URL)); + newKeyedDataFile(false); + + 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); + assertKeyOnlyMasked(); + } + + @Test + public void LicenseKey_DownloadFails_MasksTheUrlAndTheException() + throws Exception { + when(connection.getResponseCode()) + .thenReturn(HttpURLConnection.HTTP_OK); + when(connection.getInputStream()) + .thenThrow(new IOException("Premature EOF from " + KEYED_URL)); + newKeyedDataFile(true); + + 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); + assertKeyOnlyMasked(); + } + + @Test + public void LicenseKey_Forbidden_LogsTheMaskedUrl() throws Exception { + when(connection.getResponseCode()) + .thenReturn(HttpURLConnection.HTTP_FORBIDDEN); + newKeyedDataFile(true); + + 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)"); + assertKeyOnlyMasked(); + } + + @Test + public void LicenseKey_NoResponse_LogsTheMaskedUrl() throws Exception { + when(httpClient.connect(any(URL.class))).thenReturn(null); + newKeyedDataFile(false); + + 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"); + 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 4ed689fc2..a1650c1da 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 @@ -374,7 +374,12 @@ public void DataUpdateService_Register_FileSystemWatcher() throws IOException { dataUpdate.registerDataFile(file); // Assert - assertNotNull(config.getWatchKey()); + // The automatic update switch governs the file system watcher. + if (autoUpdateEnabled) { + assertNotNull(config.getWatchKey()); + } else { + assertNull(config.getWatchKey()); + } } finally { // Make sure we tidy up the temp file. File tempFile = new File(tempData); @@ -890,10 +895,12 @@ 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 error to be logged so make sure it's + // We expect one warning to be logged so make sure it's // ignored in cleanup and verify its presence. - ignoreErrors = 1; - assertEquals(1, logger.errorsLogged.size()); + ignoreWranings = 1; + assertEquals(1, logger.warningsLogged.size()); + assertTrue(logger.warningsLogged.get(0).contains(errorText)); + assertEquals(0, logger.errorsLogged.size()); assertEquals(AUTO_UPDATE_HTTPS_ERR, completeEventArgs[0].getStatus()); } finally { @@ -1019,6 +1026,32 @@ public void DataUpdateService_CheckForUpdate_FileUpdated() { anyLong()); } + /** + * A programmatic update compares the data file on disk whether or not + * Automatic Update from File is enabled, and with automatic update off + * no file system watcher exists whatever the watcher flag says. + */ + @Test + public void DataUpdateService_CheckForUpdate_FileUpdated_AutoUpdateOffWatcherFlagDefault() { + // Arrange + OnPremiseAspectEngine engine = mock(OnPremiseAspectEngine.class); + DataFileConfigurationDefault config = new DataFileConfigurationDefault(); + config.setAutomaticUpdatesEnabled(false); + + AspectEngineDataFileDefault file = new AspectEngineDataFileDefault(); + file.setEngine(engine); + file.setConfiguration(config); + when(engine.getDataFileMetaData()).thenReturn(file); + + configureFileUpdate(engine); + + // Act + dataUpdate.checkForUpdate(engine); + + // Assert + verify(engine, times(1)).refreshData((String)any()); + } + @Test public void DataUpdateService_CheckForUpdate_UrlNoUpdate() throws IOException { // Getting no data from the URL will cause an error to be logged @@ -1345,8 +1378,8 @@ public void DataUpdateService_CheckForUpdate_FileUpdated_TimerSetAgain() { */ @Test public void DataUpdateService_CheckForUpdate_FileRefreshFails_TimerSetAgain() { - // updatedFileAvailable warns on each of its 10 tries. - ignoreWranings = 10; + // updatedFileAvailable logs one error once its tries are used up. + ignoreErrors = 1; // Arrange OnPremiseAspectEngine engine = @@ -1375,6 +1408,12 @@ public void DataUpdateService_CheckForUpdate_FileRefreshFails_TimerSetAgain() { assertEquals( DataUpdateService.AutoUpdateStatus.AUTO_UPDATE_REFRESH_FAILED, status); + String expected = "An error occurred when applying a data update " + + "to engine '" + engine.getClass().getSimpleName() + + "' after 10 tries."; + assertTrue( + "Expected '" + expected + "' but got " + logger.errorsLogged, + logger.errorsLogged.contains(expected)); verify(futureFactory, times(2 * timers)).schedule( any(Runnable.class), anyLong()); @@ -1688,8 +1727,8 @@ public void call(Object sender, DataUpdateService.DataUpdateCompleteArgs args) { assertTrue("The 'checkForUpdateComplete' " + "event was never fired", completed); - // Ignore the error that is logged due to the 429 - ignoreErrors = 1; + // Ignore the warning that is logged due to the 429 + ignoreWranings = 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.