From fda7f749554b6537c5cbd16d3b0f9326e398844b Mon Sep 17 00:00:00 2001 From: Michael McLawhorn Date: Mon, 16 Oct 2017 12:24:56 -0500 Subject: [PATCH 1/2] Implementing mandatory uncaught exception logging on loader tasks. --- CHANGELOG.md | 4 ++ .../application/DimensionValueLoadTask.java | 2 +- .../bard/webservice/application/LoadTask.java | 24 +++++++++- .../metadata/DataSourceMetadataLoadTask.java | 2 +- .../application/LoadTaskSpec.groovy | 48 ++++++++++++++++++- 5 files changed, 75 insertions(+), 5 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 66dde68a71..3f4920d1bd 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -179,6 +179,10 @@ Current are made available. +- [Added mandatory logging for LoadTask errors] + * Finalized `run()` in `LoadTask` with mandatory logging of exceptions. + * Created mandatory runInner to replace run in all `LoadTask` instances + - [Substitute preflight method wildcard character with explicit allowed methods](https://github.com/yahoo/fili/pull/545) * Modify ResponseCorsFilter Allowed Methods header to explicitly list allowed methods. Some browsers do not support a wildcard header value. diff --git a/fili-core/src/main/java/com/yahoo/bard/webservice/application/DimensionValueLoadTask.java b/fili-core/src/main/java/com/yahoo/bard/webservice/application/DimensionValueLoadTask.java index 09d273884c..85466ed384 100644 --- a/fili-core/src/main/java/com/yahoo/bard/webservice/application/DimensionValueLoadTask.java +++ b/fili-core/src/main/java/com/yahoo/bard/webservice/application/DimensionValueLoadTask.java @@ -59,7 +59,7 @@ public DimensionValueLoadTask(Collection dimensionRowProvi } @Override - public void run() { + public void runInner() { dimensionRowProviders.forEach(DimensionValueLoader::load); // tell all dimensionRowProviders to load lastRunTimestamp.set(DateTime.now()); diff --git a/fili-core/src/main/java/com/yahoo/bard/webservice/application/LoadTask.java b/fili-core/src/main/java/com/yahoo/bard/webservice/application/LoadTask.java index 3348efcce7..447ed7c309 100644 --- a/fili-core/src/main/java/com/yahoo/bard/webservice/application/LoadTask.java +++ b/fili-core/src/main/java/com/yahoo/bard/webservice/application/LoadTask.java @@ -18,7 +18,9 @@ * @param The type of the result returned by the task associated with this loader. */ public abstract class LoadTask implements Runnable { + private static final Logger LOG = LoggerFactory.getLogger(LoadTask.class); + public static final String LOAD_TASK_ERROR_FORMAT = "Exception while running %s: %s"; protected final String loaderName; protected final long delay; @@ -26,6 +28,8 @@ public abstract class LoadTask implements Runnable { protected final boolean isPeriodic; protected ScheduledFuture future; + private boolean failed = false; + /** * Creates a one-off loader. * @@ -50,8 +54,22 @@ public LoadTask(String loaderName, long delay, long period) { this.isPeriodic = period > 0; } + /** + * Internal implementation of {@link LoadTask#run()} task that will be used so that {@link LoadTask#run()} can + * add mandatory exception handling. + */ + public abstract void runInner(); + @Override - public abstract void run(); + public final void run() { + try { + runInner(); + } catch (RuntimeException t) { + LOG.error(String.format(LOAD_TASK_ERROR_FORMAT, getName(), t.getMessage()), t); + failed = true; + throw t; + } + }; /** * Return the name of this loader. @@ -157,4 +175,8 @@ public void invoke(Throwable error) { LOG.error("{}: Async request to druid failed:", getName(), error); } } + + public boolean isFailed() { + return failed; + } } diff --git a/fili-core/src/main/java/com/yahoo/bard/webservice/metadata/DataSourceMetadataLoadTask.java b/fili-core/src/main/java/com/yahoo/bard/webservice/metadata/DataSourceMetadataLoadTask.java index 1c55a02994..13fa941ad3 100644 --- a/fili-core/src/main/java/com/yahoo/bard/webservice/metadata/DataSourceMetadataLoadTask.java +++ b/fili-core/src/main/java/com/yahoo/bard/webservice/metadata/DataSourceMetadataLoadTask.java @@ -97,7 +97,7 @@ public DataSourceMetadataLoadTask( } @Override - public void run() { + public void runInner() { physicalTableDictionary.values().stream() .map(PhysicalTable::getDataSourceNames) .flatMap(Set::stream) diff --git a/fili-core/src/test/groovy/com/yahoo/bard/webservice/application/LoadTaskSpec.groovy b/fili-core/src/test/groovy/com/yahoo/bard/webservice/application/LoadTaskSpec.groovy index 621e9ef9d9..58a262a009 100644 --- a/fili-core/src/test/groovy/com/yahoo/bard/webservice/application/LoadTaskSpec.groovy +++ b/fili-core/src/test/groovy/com/yahoo/bard/webservice/application/LoadTaskSpec.groovy @@ -5,8 +5,12 @@ package com.yahoo.bard.webservice.application import static spock.util.matcher.HamcrestMatchers.closeTo import static spock.util.matcher.HamcrestSupport.expect +import com.yahoo.bard.webservice.data.dimension.TimeoutException import com.yahoo.bard.webservice.druid.client.FailureCallback import com.yahoo.bard.webservice.druid.client.HttpErrorCallback +import com.yahoo.bard.webservice.logging.TestLogAppender + +import com.fasterxml.jackson.databind.ObjectMapper import spock.lang.Ignore import spock.lang.Specification @@ -18,6 +22,8 @@ import java.util.concurrent.TimeUnit @Timeout(30) // Fail test if hangs class LoadTaskSpec extends Specification { + TestLogAppender logAppender = new TestLogAppender() + // All times are in millis unless specified otherwise int expectedDelay = 500 int expectedPeriod = 500 @@ -42,7 +48,7 @@ class LoadTaskSpec extends Specification { } @Override - void run() { + void runInner() { start = System.currentTimeMillis() sleep(expectedDuration) end = System.currentTimeMillis() @@ -60,7 +66,7 @@ class LoadTaskSpec extends Specification { } @Override - void run() { + void runInner() { start = System.currentTimeMillis() sleep(expectedDuration) end = System.currentTimeMillis() @@ -231,4 +237,42 @@ class LoadTaskSpec extends Specification { cleanup: scheduler.shutdownNow() } + + class FailingTestLoadTask extends LoadTaskSpec.OneOffTestLoadTask { + + + public static final String UNIQUE_VALUE_1 = "UNIQUE_VALUE_1" + + FailingTestLoadTask(long delay) { + super(delay) + } + + @Override + void runInner() { + throw new TimeoutException(UNIQUE_VALUE_1); + } + } + + + def "Test error gets logged on failed test"() { + setup: + setup: "Instantiate a task scheduler" + ObjectMapper MAPPER = new ObjectMappersSuite().getMapper() + + + TaskScheduler scheduler = new TaskScheduler(2) + LoadTask loader = new FailingTestLoadTask(expectedDelay) + loader.setFuture( + scheduler.schedule( + loader, + 1, + TimeUnit.MILLISECONDS + ) + ) + Thread.sleep(10) + + expect: + loader.failed + logAppender.getMessages().find { it.contains(/UNIQUE_VALUE_1/) } + } } From 46a55a5734714042b3b15380f5f1acebe96727e8 Mon Sep 17 00:00:00 2001 From: Michael McLawhorn Date: Thu, 19 Oct 2017 10:55:15 -0500 Subject: [PATCH 2/2] Address PR comments --- CHANGELOG.md | 2 +- .../bard/webservice/application/LoadTask.java | 4 ++-- .../dimension/impl/LuceneSearchProvider.java | 2 +- .../webservice/web/ErrorMessageFormat.java | 7 +++++-- .../application/LoadTaskSpec.groovy | 20 +++---------------- 5 files changed, 12 insertions(+), 23 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 3f4920d1bd..046c821368 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -179,7 +179,7 @@ Current are made available. -- [Added mandatory logging for LoadTask errors] +- [Added mandatory logging for LoadTask errors](https://github.com/yahoo/fili/pull/553) * Finalized `run()` in `LoadTask` with mandatory logging of exceptions. * Created mandatory runInner to replace run in all `LoadTask` instances diff --git a/fili-core/src/main/java/com/yahoo/bard/webservice/application/LoadTask.java b/fili-core/src/main/java/com/yahoo/bard/webservice/application/LoadTask.java index 447ed7c309..3fd451b602 100644 --- a/fili-core/src/main/java/com/yahoo/bard/webservice/application/LoadTask.java +++ b/fili-core/src/main/java/com/yahoo/bard/webservice/application/LoadTask.java @@ -4,6 +4,7 @@ import com.yahoo.bard.webservice.druid.client.FailureCallback; import com.yahoo.bard.webservice.druid.client.HttpErrorCallback; +import com.yahoo.bard.webservice.web.ErrorMessageFormat; import org.slf4j.Logger; import org.slf4j.LoggerFactory; @@ -20,7 +21,6 @@ public abstract class LoadTask implements Runnable { private static final Logger LOG = LoggerFactory.getLogger(LoadTask.class); - public static final String LOAD_TASK_ERROR_FORMAT = "Exception while running %s: %s"; protected final String loaderName; protected final long delay; @@ -65,7 +65,7 @@ public final void run() { try { runInner(); } catch (RuntimeException t) { - LOG.error(String.format(LOAD_TASK_ERROR_FORMAT, getName(), t.getMessage()), t); + LOG.error(ErrorMessageFormat.LOAD_TASK_FAILURE.logFormat(getName(), t.getMessage()), t); failed = true; throw t; } diff --git a/fili-core/src/main/java/com/yahoo/bard/webservice/data/dimension/impl/LuceneSearchProvider.java b/fili-core/src/main/java/com/yahoo/bard/webservice/data/dimension/impl/LuceneSearchProvider.java index 43e20f7f27..6c0989f664 100644 --- a/fili-core/src/main/java/com/yahoo/bard/webservice/data/dimension/impl/LuceneSearchProvider.java +++ b/fili-core/src/main/java/com/yahoo/bard/webservice/data/dimension/impl/LuceneSearchProvider.java @@ -458,7 +458,7 @@ public void clearDimension() { writer.deleteAll(); writer.commit(); } catch (IOException e) { - LOG.error(ErrorMessageFormat.FAIL_TO_WIPTE_LUCENE_INDEX_DIR.format(luceneDirectory)); + LOG.error(ErrorMessageFormat.FAIL_TO_WIPE_LUCENE_INDEX_DIR.format(luceneDirectory)); throw new RuntimeException(e); } diff --git a/fili-core/src/main/java/com/yahoo/bard/webservice/web/ErrorMessageFormat.java b/fili-core/src/main/java/com/yahoo/bard/webservice/web/ErrorMessageFormat.java index 1fb859852d..d90a6116ca 100644 --- a/fili-core/src/main/java/com/yahoo/bard/webservice/web/ErrorMessageFormat.java +++ b/fili-core/src/main/java/com/yahoo/bard/webservice/web/ErrorMessageFormat.java @@ -261,9 +261,12 @@ public enum ErrorMessageFormat implements MessageFormatter { UNABLE_TO_CREATE_DIR("Unable to create directory %s."), UNABLE_TO_DELETE_DIR("Unable to delete directory %s."), - FAIL_TO_WIPTE_LUCENE_INDEX_DIR("Failed to wipte Lucene index at directory: %s"), - REQUEST_PROCESSING_EXCEPTION("Exception processing request: %s") + FAIL_TO_WIPE_LUCENE_INDEX_DIR("Failed to wipe Lucene index at directory: %s"), + + REQUEST_PROCESSING_EXCEPTION("Exception processing request: %s"), + + LOAD_TASK_FAILURE("Exception while running %s: %s") ; private final String messageFormat; diff --git a/fili-core/src/test/groovy/com/yahoo/bard/webservice/application/LoadTaskSpec.groovy b/fili-core/src/test/groovy/com/yahoo/bard/webservice/application/LoadTaskSpec.groovy index 58a262a009..0cc68c2224 100644 --- a/fili-core/src/test/groovy/com/yahoo/bard/webservice/application/LoadTaskSpec.groovy +++ b/fili-core/src/test/groovy/com/yahoo/bard/webservice/application/LoadTaskSpec.groovy @@ -10,8 +10,6 @@ import com.yahoo.bard.webservice.druid.client.FailureCallback import com.yahoo.bard.webservice.druid.client.HttpErrorCallback import com.yahoo.bard.webservice.logging.TestLogAppender -import com.fasterxml.jackson.databind.ObjectMapper - import spock.lang.Ignore import spock.lang.Specification import spock.lang.Timeout @@ -240,8 +238,7 @@ class LoadTaskSpec extends Specification { class FailingTestLoadTask extends LoadTaskSpec.OneOffTestLoadTask { - - public static final String UNIQUE_VALUE_1 = "UNIQUE_VALUE_1" + public static final String UNIQUE_VALUE_1 = "FailingTestLoadTask.UNIQUE_VALUE_1" FailingTestLoadTask(long delay) { super(delay) @@ -253,26 +250,15 @@ class LoadTaskSpec extends Specification { } } - def "Test error gets logged on failed test"() { - setup: setup: "Instantiate a task scheduler" - ObjectMapper MAPPER = new ObjectMappersSuite().getMapper() - - TaskScheduler scheduler = new TaskScheduler(2) LoadTask loader = new FailingTestLoadTask(expectedDelay) - loader.setFuture( - scheduler.schedule( - loader, - 1, - TimeUnit.MILLISECONDS - ) - ) + loader.setFuture(scheduler.schedule(loader,1, TimeUnit.MILLISECONDS)) Thread.sleep(10) expect: loader.failed - logAppender.getMessages().find { it.contains(/UNIQUE_VALUE_1/) } + logAppender.getMessages().find { it.contains(/FailingTestLoadTask.UNIQUE_VALUE_1/) } } }