Merge pull request #781 from nosqlbench/780-sporadic-buildtest-failures-gh-actions

Sporadic test failures w/ gh actions
This commit is contained in:
Jonathan Shook 2022-11-22 18:14:30 -06:00 committed by GitHub
commit eaefd9a1b2
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
19 changed files with 314 additions and 238 deletions

View File

@ -10,6 +10,7 @@ jobs:
steps:
- uses: actions/checkout@v3
name: checkout nosqlbench
- uses: actions/setup-java@v3
name: setup java
with:
@ -25,16 +26,19 @@ jobs:
key: ${{ runner.os }}-m2-${{ hashFiles('**/pom.xml') }}
restore-keys: ${{ runner.os }}-m2
- name: mvn package
- name: mvn-package
run: mvn package
- name: mvn verify
- name: mvn-verify
run: mvn verify
- name: Capture
if: success() || failure()
run: tar -cvf logfiles.tar [a-zA-Z]**/logs/*
- name: Archive Test Results
if: always()
if: success() || failure()
uses: actions/upload-artifact@v3
with:
name: test-results
path: |
[a-zA-Z]**/logs/*
path: logfiles.tar

View File

@ -28,7 +28,7 @@ import java.util.Map;
* Cause a blocking call to delay the initialization
* of this owning operation for a number of milliseconds.
*/
@Service(value= DiagTask.class,selector = "erroroncycle")
@Service(value = DiagTask.class, selector = "erroroncycle")
public class DiagTask_erroroncycle implements DiagTask {
private String name;
@ -36,21 +36,21 @@ public class DiagTask_erroroncycle implements DiagTask {
@Override
public void applyConfig(NBConfiguration cfg) {
this.name = cfg.get("name",String.class);
error_on_cycle = cfg.get("erroroncycle",long.class);
this.name = cfg.get("name", String.class);
error_on_cycle = cfg.get("erroroncycle", long.class);
}
@Override
public NBConfigModel getConfigModel() {
return ConfigModel.of(DiagTask_erroroncycle.class)
.add(Param.required("name",String.class))
.add(Param.defaultTo("erroroncycle",1L))
.add(Param.required("name", String.class))
.add(Param.defaultTo("erroroncycle", 1L))
.asReadOnly();
}
@Override
public Map<String, Object> apply(Long aLong, Map<String, Object> stringObjectMap) {
if (error_on_cycle==aLong) {
if (error_on_cycle == aLong) {
throw new RuntimeException("Diag was requested to stop on cycle " + error_on_cycle);
}
return Map.of();

View File

@ -63,10 +63,10 @@ import java.util.stream.Collectors;
public class NBCLI implements Function<String[], Integer> {
private static Logger logger;
private static LoggerConfig loggerConfig;
private static int EXIT_OK = 0;
private static int EXIT_WARNING = 1;
private static int EXIT_ERROR = 2;
private static final LoggerConfig loggerConfig;
private static final int EXIT_OK = 0;
private static final int EXIT_WARNING = 1;
private static final int EXIT_ERROR = 2;
static {
loggerConfig = new LoggerConfig();
@ -83,6 +83,7 @@ public class NBCLI implements Function<String[], Integer> {
* Only call System.exit with the body of main. This is so that other scenario
* invocations are handled functionally by {@link #apply(String[])}, which allows
* for scenario encapsulation and concurrent testing.
*
* @param args Command Line Args
*/
public static void main(String[] args) {
@ -91,15 +92,17 @@ public class NBCLI implements Function<String[], Integer> {
int statusCode = cli.apply(args);
System.exit(statusCode);
} catch (Exception e) {
System.out.println("Not expected issue in main: " + e.getMessage());
}
}
}
}
/**
* return null;
* }
*
* public static void main(String[] args) {
* @param strings
*
* @param args
* @return
*/
@Override
@ -114,10 +117,11 @@ public class NBCLI implements Function<String[], Integer> {
if (arg.toLowerCase(Locale.ROOT).startsWith("-v") || (arg.toLowerCase(Locale.ROOT).equals("--show-stacktraces"))) {
showStackTraces = true;
break;
}
}
String error = ScenarioErrorHandler.handle(e, showStackTraces);
String error = NBCLIErrorHandler.handle(e, showStackTraces);
// Commented for now, as the above handler should do everything needed.
if (error != null) {
System.err.println("Scenario stopped due to error. See logs for details.");
@ -150,7 +154,7 @@ public class NBCLI implements Function<String[], Integer> {
.setConsolePattern(globalOptions.getConsoleLoggingPattern())
.setLogfileLevel(globalOptions.getScenarioLogLevel())
.setLogfilePattern(globalOptions.getLogfileLoggingPattern())
.getLoggerLevelOverrides(globalOptions.getLogLevelOverrides())
.setLoggerLevelOverrides(globalOptions.getLogLevelOverrides())
.setMaxLogs(globalOptions.getLogsMax())
.setLogsDirectory(globalOptions.getLogsDirectory())
.setAnsiEnabled(globalOptions.isEnableAnsi())
@ -175,10 +179,10 @@ public class NBCLI implements Function<String[], Integer> {
// Invoke any bundled app which matches the name of the first non-option argument, if it exists.
// If it does not, continue with no fanfare. Let it drop through to other command resolution methods.
if (args.length>0 && args[0].matches("\\w[\\w\\d-_.]+")) {
if (args.length > 0 && args[0].matches("\\w[\\w\\d-_.]+")) {
ServiceSelector<BundledApp> apploader = ServiceSelector.of(args[0], ServiceLoader.load(BundledApp.class));
BundledApp app = apploader.get().orElse(null);
if (app!=null) {
if (app != null) {
String[] appargs = Arrays.copyOfRange(args, 1, args.length);
logger.info("invoking bundled app '" + args[0] + "' (" + app.getClass().getSimpleName() + ").");
globalOptions.setWantsStackTraces(true);
@ -211,10 +215,10 @@ public class NBCLI implements Function<String[], Integer> {
DockerMetricsManager.GRAFANA_TAG, globalOptions.getDockerGrafanaTag(),
DockerMetricsManager.PROM_TAG, globalOptions.getDockerPromTag(),
DockerMetricsManager.TSDB_RETENTION, String.valueOf(globalOptions.getDockerPromRetentionDays()),
DockerMetricsManager.GRAPHITE_SAMPLE_EXPIRY,"10m",
DockerMetricsManager.GRAPHITE_CACHE_SIZE,"5000",
DockerMetricsManager.GRAPHITE_LOG_LEVEL,globalOptions.getGraphiteLogLevel(),
DockerMetricsManager.GRAPHITE_LOG_FORMAT,"logfmt"
DockerMetricsManager.GRAPHITE_SAMPLE_EXPIRY, "10m",
DockerMetricsManager.GRAPHITE_CACHE_SIZE, "5000",
DockerMetricsManager.GRAPHITE_LOG_LEVEL, globalOptions.getGraphiteLogLevel(),
DockerMetricsManager.GRAPHITE_LOG_FORMAT, "logfmt"
);
dmh.startMetrics(dashboardOptions);
@ -262,7 +266,7 @@ public class NBCLI implements Function<String[], Integer> {
for (ServiceLoader.Provider<BundledApp> provider : loader.stream().toList()) {
Class<? extends BundledApp> appType = provider.type();
String name = appType.getAnnotation(Service.class).selector();
System.out.println(String.format("%-40s %s",name,appType.getCanonicalName()));
System.out.printf("%-40s %s%n", name, appType.getCanonicalName());
}
return EXIT_OK;
}
@ -316,25 +320,25 @@ public class NBCLI implements Function<String[], Integer> {
Path writeTo = Path.of(data.asPath().getFileName().toString());
if (Files.exists(writeTo)) {
throw new BasicError("A file named " + writeTo.toString() + " exists. Remove it first.");
throw new BasicError("A file named " + writeTo + " exists. Remove it first.");
}
try {
Files.writeString(writeTo, data.getCharBuffer(), StandardCharsets.UTF_8);
} catch (IOException e) {
throw new BasicError("Unable to write to " + writeTo.toString() + ": " + e.getMessage());
throw new BasicError("Unable to write to " + writeTo + ": " + e.getMessage());
}
logger.info("Copied internal resource '" + data.asPath() + "' to '" + writeTo.toString() + "'");
logger.info("Copied internal resource '" + data.asPath() + "' to '" + writeTo + "'");
return EXIT_OK;
}
if (options.wantsInputTypes()) {
InputType.FINDER.getAllSelectors().forEach((k,v) -> System.out.println(k + " (" + v.name() + ")"));
InputType.FINDER.getAllSelectors().forEach((k, v) -> System.out.println(k + " (" + v.name() + ")"));
return EXIT_OK;
}
if (options.wantsMarkerTypes()) {
OutputType.FINDER.getAllSelectors().forEach((k,v) -> System.out.println(k + " (" + v.name() + ")"));
OutputType.FINDER.getAllSelectors().forEach((k, v) -> System.out.println(k + " (" + v.name() + ")"));
return EXIT_OK;
}
@ -464,27 +468,27 @@ public class NBCLI implements Function<String[], Integer> {
executor.execute(scenario);
while (true) {
Optional<ScenarioResult> pendingResult = executor.getPendingResult(scenario.getScenarioName());
if (pendingResult.isEmpty()) {
LockSupport.parkNanos(100000000L);
} else {
break;
}
}
// while (true) {
// Optional<ScenarioResult> pendingResult = executor.getPendingResult(scenario.getScenarioName());
// if (pendingResult.isPresent()) {
// break;
// }
// LockSupport.parkNanos(100000000L);
// }
ScenariosResults scenariosResults = executor.awaitAllResults();
logger.debug("Total of " + scenariosResults.getSize() + " result object returned from ScenariosExecutor");
ActivityMetrics.closeMetrics(options.wantsEnableChart());
//scenariosResults.reportToLog();
scenariosResults.reportToLog();
ShutdownManager.shutdown();
// logger.info(scenariosResults.getExecutionSummary());
logger.info(scenariosResults.getExecutionSummary());
if (scenariosResults.hasError()) {
Exception exception = scenariosResults.getOne().getException().get();
// logger.warn(scenariosResults.getExecutionSummary());
ScenarioErrorHandler.handle(exception, options.wantsStackTraces());
logger.warn(scenariosResults.getExecutionSummary());
NBCLIErrorHandler.handle(exception, options.wantsStackTraces());
System.err.println(exception.getMessage()); // TODO: make this consistent with ConsoleLogging sequencing
return EXIT_ERROR;
} else {

View File

@ -16,16 +16,24 @@
package io.nosqlbench.engine.core.lifecycle;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
public class ActivityExceptionHandler implements Thread.UncaughtExceptionHandler {
private static final Logger logger = LogManager.getLogger(ActivityExceptionHandler.class);
private final ActivityExecutor executor;
public ActivityExceptionHandler(ActivityExecutor executor) {
this.executor = executor;
logger.debug(() -> "Activity exception handler starting up for executor '" + executor + "'");
}
@Override
public void uncaughtException(Thread t, Throwable e) {
logger.error("Uncaught exception in thread '" + t.getName() + ", state[" + t.getState() + "], notifying executor '" + executor + "'");
executor.notifyException(t, e);
}
}

View File

@ -15,14 +15,14 @@
*/
package io.nosqlbench.engine.core.lifecycle;
import io.nosqlbench.api.annotations.Annotation;
import io.nosqlbench.api.annotations.Layer;
import io.nosqlbench.api.engine.activityimpl.ActivityDef;
import io.nosqlbench.api.engine.activityimpl.ParameterMap;
import io.nosqlbench.engine.api.activityapi.core.*;
import io.nosqlbench.engine.api.activityapi.core.progress.ProgressCapable;
import io.nosqlbench.engine.api.activityapi.core.progress.ProgressMeterDisplay;
import io.nosqlbench.api.engine.activityimpl.ActivityDef;
import io.nosqlbench.api.engine.activityimpl.ParameterMap;
import io.nosqlbench.engine.core.annotation.Annotators;
import io.nosqlbench.api.annotations.Annotation;
import io.nosqlbench.api.annotations.Layer;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
@ -155,8 +155,8 @@ public class ActivityExecutor implements ActivityController, ParameterMap.Listen
}
public synchronized RuntimeException forceStopScenario(int initialMillisToWait) {
activitylogger.debug("FORCE STOP/before alias=(" + activity.getAlias() + ")");
activitylogger.debug("FORCE STOP/before alias=(" + activity.getAlias() + ")");
activity.setRunState(RunState.Stopped);
executorService.shutdown();
@ -214,23 +214,29 @@ public class ActivityExecutor implements ActivityController, ParameterMap.Listen
}
public boolean finishAndShutdownExecutor(int secondsToWait) {
activitylogger.debug("REQUEST STOP/before alias=(" + activity.getAlias() + ")");
activitylogger.debug("REQUEST STOP/before alias=(" + activity.getAlias() + ")");
logger.debug("Stopping executor for " + activity.getAlias() + " when work completes.");
executorService.shutdown();
boolean wasStopped = false;
try {
executorService.shutdown();
logger.trace(() -> "awaiting termination with timeout of " + secondsToWait + " seconds");
wasStopped = executorService.awaitTermination(secondsToWait, TimeUnit.SECONDS);
} catch (InterruptedException ie) {
logger.trace("interrupted while awaiting termination");
wasStopped = false;
logger.warn("while waiting termination of activity " + activity.getAlias() + ", " + ie.getMessage());
logger.warn("while waiting termination of shutdown " + activity.getAlias() + ", " + ie.getMessage());
activitylogger.debug("REQUEST STOP/exception alias=(" + activity.getAlias() + ") wasstopped=" + wasStopped);
} catch (RuntimeException e) {
logger.trace("Received exception while awaiting termination: " + e.getMessage());
wasStopped = true;
stoppingException = e;
} finally {
logger.trace(() -> "finally shutting down activity " + this.getActivity().getAlias());
activity.shutdownActivity();
logger.trace("closing auto-closeables");
activity.closeAutoCloseables();
activity.setRunState(RunState.Stopped);
@ -241,6 +247,7 @@ public class ActivityExecutor implements ActivityController, ParameterMap.Listen
logger.trace(() -> "an exception caused the activity to stop:" + stoppingException.getMessage());
throw stoppingException;
}
activitylogger.debug("REQUEST STOP/after alias=(" + activity.getAlias() + ") wasstopped=" + wasStopped);
return wasStopped;
@ -278,11 +285,13 @@ public class ActivityExecutor implements ActivityController, ParameterMap.Listen
* This is the canonical way to wait for an activity to finish. It ties together
* any way that an activity can finish under one blocking call.
* This should be awaited asynchronously from the control layer in separate threads.
*
* TODO: move activity finisher threaad to this class and remove separate implementation
* <p>
* TODO: move activity finisher thread to this class and remove separate implementation
*/
public boolean awaitCompletion(int waitTime) {
logger.debug(()-> "awaiting completion of '" + this.getActivity().getAlias() + "'");
boolean finished = finishAndShutdownExecutor(waitTime);
Annotators.recordAnnotation(Annotation.newBuilder()
.session(sessionId)
.interval(startedAt, this.stoppedAt)
@ -412,7 +421,7 @@ public class ActivityExecutor implements ActivityController, ParameterMap.Listen
* Await a thread (aka motor/slot) entering a specific SlotState
*
* @param m motor instance
* @param waitTime milliseconds to wait, total
* @param waitTime milliseco`nds to wait, total
* @param pollTime polling interval between state checks
* @param desiredRunStates any desired SlotState
* @return true, if the desired SlotState was detected
@ -521,7 +530,7 @@ public class ActivityExecutor implements ActivityController, ParameterMap.Listen
}
public synchronized void notifyException(Thread t, Throwable e) {
//logger.error("Uncaught exception in activity thread forwarded to activity executor:", e);
logger.debug(() -> "Uncaught exception in activity thread forwarded to activity executor: " + e.getMessage());
this.stoppingException = new RuntimeException("Error in activity thread " + t.getName(), e);
forceStopScenario(10000);
}

View File

@ -16,7 +16,11 @@
package io.nosqlbench.engine.core.lifecycle;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
public class ActivityFinisher extends Thread {
private final static Logger logger = LogManager.getLogger(ActivityFinisher.class);
private final ActivityExecutor executor;
private final int timeout;
@ -30,10 +34,17 @@ public class ActivityFinisher extends Thread {
@Override
public void run() {
logger.debug(this + " awaiting async completion of " + executor.getActivity().getAlias() + " on " + executor + " for timeout " + timeout);
result = executor.awaitCompletion(timeout);
logger.debug(this + " awaited async completion of " + executor.getActivity().getAlias());
}
public boolean getResult() {
return result;
}
@Override
public String toString() {
return this.getClass().getSimpleName()+"/" + executor.getActivity().getAlias();
}
}

View File

@ -17,9 +17,9 @@
package io.nosqlbench.engine.core.lifecycle;
import io.nosqlbench.api.errors.BasicError;
import org.graalvm.polyglot.PolyglotException;
import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.graalvm.polyglot.PolyglotException;
import javax.script.ScriptException;
@ -32,28 +32,28 @@ import javax.script.ScriptException;
* <ol>
* <li>Report an error in the most intelligible way to the user.</li>
* </ol>
*
* <p>
* That is all. When this error handler is invoked, it is a foregone conclusion that the scenario
* is not able to continue, else the error would have been trapped and handled internal to a lower-level
* class. It is the calling exception handler's responsibility to finally shut down the scenario
* cleanly and return appropriately. Thus, <em>You should not throw errors from this class. You should only
* unwrap and explain errors, sending contents to the logfile as appropriate.</em>
*
*/
public class ScenarioErrorHandler {
public class NBCLIErrorHandler {
private final static Logger logger = LogManager.getLogger("ERRORHANDLER");
public static String handle(Throwable t, boolean wantsStackTraces) {
if (wantsStackTraces) {
StackTraceElement[] st = Thread.currentThread().getStackTrace();
for (int i = 0; i < 10; i++) {
if (st.length>i) {
if (st.length > i) {
String className = st[i].getClassName();
String fileName = st[i].getFileName();
int lineNumber = st[i].getLineNumber();
logger.trace("st["+i+"]:" + className +","+fileName+":"+lineNumber);
logger.trace("st[" + i + "]:" + className + "," + fileName + ":" + lineNumber);
}
}
}
@ -63,7 +63,7 @@ public class ScenarioErrorHandler {
} else if (t instanceof BasicError) {
logger.trace("Handling basic error: " + t);
return handleBasicError((BasicError) t, wantsStackTraces);
} else if (t instanceof Exception){
} else if (t instanceof Exception) {
logger.trace("Handling general exception: " + t);
return handleInternalError((Exception) t, wantsStackTraces);
} else {
@ -74,7 +74,7 @@ public class ScenarioErrorHandler {
private static String handleInternalError(Exception e, boolean wantsStackTraces) {
String prefix = "internal error: ";
if (e.getCause()!=null && !e.getCause().getClass().getCanonicalName().contains("io.nosqlbench")) {
if (e.getCause() != null && !e.getCause().getClass().getCanonicalName().contains("io.nosqlbench")) {
prefix = "Error from driver or included library: ";
}
@ -95,13 +95,13 @@ public class ScenarioErrorHandler {
if (cause instanceof PolyglotException) {
Throwable hostException = ((PolyglotException) cause).asHostException();
if (hostException instanceof BasicError) {
handleBasicError((BasicError)hostException, wantsStackTraces);
handleBasicError((BasicError) hostException, wantsStackTraces);
} else {
handle(hostException, wantsStackTraces);
}
} else {
if (wantsStackTraces) {
logger.error("Unknown script exception:",e);
logger.error("Unknown script exception:", e);
} else {
logger.error(e.getMessage());
logger.error("for the full stack trace, run with --show-stacktraces");
@ -112,7 +112,7 @@ public class ScenarioErrorHandler {
private static String handleBasicError(BasicError e, boolean wantsStackTraces) {
if (wantsStackTraces) {
logger.error(e.getMessage(),e);
logger.error(e.getMessage(), e);
} else {
logger.error(e.getMessage());
logger.error("for the full stack trace, run with --show-stacktraces");

View File

@ -431,6 +431,7 @@ public class ScenarioController {
* @return true, if all activities completed before the timer expired, false otherwise
*/
public boolean awaitCompletion(long waitTimeMillis) {
logger.debug(() -> "awaiting completion");
boolean completed = true;
long remaining = waitTimeMillis;
@ -443,7 +444,9 @@ public class ScenarioController {
for (ActivityFinisher finisher : finishers) {
try {
logger.debug("joining finisher " + finisher.getName());
finisher.join(waitTimeMillis);
logger.debug("joined finisher " + finisher.getName());
} catch (InterruptedException ignored) {
}
}

View File

@ -54,17 +54,19 @@ public class ScenarioResult {
private final long startedAt;
private final long endedAt;
private Exception exception;
private final Exception exception;
private final String iolog;
public ScenarioResult(String iolog, long startedAt, long endedAt) {
this.iolog = iolog;
this.startedAt = startedAt;
this.endedAt = endedAt;
public ScenarioResult(Exception e, String iolog, long startedAt, long endedAt) {
logger.debug("populating "+(e==null? "NORMAL" : "ERROR")+" scenario result");
if (logger.isDebugEnabled()) {
StackTraceElement[] st = Thread.currentThread().getStackTrace();
for (int i = 0; i < st.length; i++) {
logger.debug(":AT " + st[i].getFileName()+":"+st[i].getLineNumber()+":"+st[i].getMethodName());
if (i>10) break;
}
public ScenarioResult(Exception e, long startedAt, long endedAt) {
this.iolog = e.getMessage();
}
this.iolog = ((iolog!=null) ? iolog + "\n\n" : "") + (e!=null? e.getMessage() : "");
this.startedAt = startedAt;
this.endedAt = endedAt;
this.exception = e;
@ -147,15 +149,14 @@ public class ScenarioResult {
StringBuilder sb = new StringBuilder();
ActivityMetrics.getMetricRegistry().getMetrics().forEach((k, v) -> {
if (v instanceof Counting) {
long count = ((Counting) v).getCount();
if (v instanceof Counting counting) {
long count = counting.getCount();
if (count > 0) {
NBMetricsSummary.summarize(sb, k, v);
}
} else if (v instanceof Gauge) {
Object value = ((Gauge) v).getValue();
if (value != null && value instanceof Number) {
Number n = (Number) value;
} else if (v instanceof Gauge<?> gauge) {
Object value = gauge.getValue();
if (value instanceof Number n) {
if (n.doubleValue() != 0) {
NBMetricsSummary.summarize(sb, k, v);
}

View File

@ -27,7 +27,6 @@ import java.util.Map;
public class ScenariosResults {
private static final Logger logger = LogManager.getLogger(ScenariosResults.class);
private final String scenariosExecutorName;
private final Map<Scenario, ScenarioResult> scenarioResultMap = new LinkedHashMap<>();
@ -77,4 +76,8 @@ public class ScenariosResults {
return this.scenarioResultMap.values().stream()
.anyMatch(r -> r.getException().isPresent());
}
public int getSize() {
return this.scenarioResultMap.size();
}
}

View File

@ -29,15 +29,14 @@ import org.apache.logging.log4j.core.config.ConfigurationSource;
import org.apache.logging.log4j.core.config.builder.api.*;
import org.apache.logging.log4j.core.config.builder.impl.BuiltConfiguration;
import java.nio.file.attribute.*;
import java.io.File;
import java.io.FileFilter;
import java.io.IOException;
import java.net.URI;
import java.nio.file.Files;
import java.nio.file.Path;
import java.nio.file.attribute.FileAttribute;
import java.nio.file.attribute.PosixFilePermission;
import java.nio.file.attribute.PosixFilePermissions;
import java.util.*;
import java.util.stream.Collectors;
@ -280,22 +279,22 @@ public class LoggerConfig extends ConfigurationFactory {
public LoggerConfig setConsolePattern(String consoleLoggingPattern) {
consoleLoggingPattern= (ansiEnabled && STANDARD_FORMATS.containsKey(consoleLoggingPattern+"-ANSI"))
? consoleLoggingPattern+"-ANSI" : consoleLoggingPattern;
consoleLoggingPattern = (ansiEnabled && STANDARD_FORMATS.containsKey(consoleLoggingPattern + "-ANSI"))
? consoleLoggingPattern + "-ANSI" : consoleLoggingPattern;
this.consolePattern = STANDARD_FORMATS.getOrDefault(consoleLoggingPattern, consoleLoggingPattern);
return this;
}
public LoggerConfig setLogfilePattern(String logfileLoggingPattern) {
logfileLoggingPattern= (logfileLoggingPattern.endsWith("-ANSI") && STANDARD_FORMATS.containsKey(logfileLoggingPattern))
? logfileLoggingPattern.substring(logfileLoggingPattern.length()-5) : logfileLoggingPattern;
logfileLoggingPattern = (logfileLoggingPattern.endsWith("-ANSI") && STANDARD_FORMATS.containsKey(logfileLoggingPattern))
? logfileLoggingPattern.substring(logfileLoggingPattern.length() - 5) : logfileLoggingPattern;
this.logfileLocation = STANDARD_FORMATS.getOrDefault(logfileLoggingPattern, logfileLoggingPattern);
return this;
}
public LoggerConfig getLoggerLevelOverrides(Map<String, String> logLevelOverrides) {
public LoggerConfig setLoggerLevelOverrides(Map<String, String> logLevelOverrides) {
this.logLevelOverrides = logLevelOverrides;
return this;
}

View File

@ -17,8 +17,13 @@ package io.nosqlbench.engine.core.script;
import com.codahale.metrics.MetricRegistry;
import com.oracle.truffle.js.scriptengine.GraalJSScriptEngine;
import io.nosqlbench.engine.api.extensions.ScriptingPluginInfo;
import io.nosqlbench.api.annotations.Annotation;
import io.nosqlbench.api.annotations.Layer;
import io.nosqlbench.api.engine.metrics.ActivityMetrics;
import io.nosqlbench.api.metadata.ScenarioMetadata;
import io.nosqlbench.api.metadata.ScenarioMetadataAware;
import io.nosqlbench.api.metadata.SystemId;
import io.nosqlbench.engine.api.extensions.ScriptingPluginInfo;
import io.nosqlbench.engine.api.scripting.ScriptEnvBuffer;
import io.nosqlbench.engine.core.annotation.Annotators;
import io.nosqlbench.engine.core.lifecycle.ActivityProgressIndicator;
@ -27,14 +32,12 @@ import io.nosqlbench.engine.core.lifecycle.ScenarioController;
import io.nosqlbench.engine.core.lifecycle.ScenarioResult;
import io.nosqlbench.engine.core.metrics.PolyglotMetricRegistryBindings;
import io.nosqlbench.nb.annotations.Maturity;
import io.nosqlbench.api.annotations.Annotation;
import io.nosqlbench.api.annotations.Layer;
import io.nosqlbench.api.metadata.ScenarioMetadata;
import io.nosqlbench.api.metadata.ScenarioMetadataAware;
import io.nosqlbench.api.metadata.SystemId;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.graalvm.polyglot.*;
import org.graalvm.polyglot.Context;
import org.graalvm.polyglot.EnvironmentAccess;
import org.graalvm.polyglot.HostAccess;
import org.graalvm.polyglot.PolyglotAccess;
import javax.script.Compilable;
import javax.script.CompiledScript;
@ -68,6 +71,12 @@ public class Scenario implements Callable<ScenarioResult> {
private Exception error;
private ScenarioMetadata scenarioMetadata;
private ScenarioResult result;
public Optional<ScenarioResult> getResultIfComplete() {
return Optional.ofNullable(this.result);
}
public enum State {
Scheduled,
@ -162,10 +171,9 @@ public class Scenario implements Callable<ScenarioResult> {
return this;
}
private void init() {
private void initializeScriptingEngine() {
logger.debug("Using engine " + engine.toString());
MetricRegistry metricRegistry = ActivityMetrics.getMetricRegistry();
Context.Builder contextSettings = Context.newBuilder("js")
@ -183,7 +191,7 @@ public class Scenario implements Callable<ScenarioResult> {
.option("js.nashorn-compat", "true");
org.graalvm.polyglot.Engine.Builder engineBuilder = org.graalvm.polyglot.Engine.newBuilder();
engineBuilder.option("engine.WarnInterpreterOnly","false");
engineBuilder.option("engine.WarnInterpreterOnly", "false");
org.graalvm.polyglot.Engine polyglotEngine = engineBuilder.build();
// TODO: add in, out, err for this scenario
@ -241,12 +249,11 @@ public class Scenario implements Callable<ScenarioResult> {
return scenarioMetadata;
}
public void runScenario() {
private synchronized void runScenario() {
scenarioShutdownHook = new ScenarioShutdownHook(this);
Runtime.getRuntime().addShutdownHook(scenarioShutdownHook);
state = State.Running;
startedAtMillis = System.currentTimeMillis();
Annotators.recordAnnotation(
Annotation.newBuilder()
@ -256,21 +263,21 @@ public class Scenario implements Callable<ScenarioResult> {
.detail("engine", this.engine.toString())
.build()
);
init();
initializeScriptingEngine();
logger.debug("Running control script for " + getScenarioName() + ".");
for (String script : scripts) {
try {
Object result = null;
if (scriptEngine instanceof Compilable && wantsCompiledScript) {
if (scriptEngine instanceof Compilable compilableEngine && wantsCompiledScript) {
logger.debug("Using direct script compilation");
Compilable compilableEngine = (Compilable) scriptEngine;
CompiledScript compiled = compilableEngine.compile(script);
logger.debug("-> invoking main scenario script (compiled)");
result = compiled.eval();
logger.debug("<- scenario script completed (compiled)");
} else {
if (scriptfile != null && !scriptfile.isEmpty()) {
String filename = scriptfile.replace("_SESSION_", scenarioName);
logger.debug("-> invoking main scenario script (" +
"interpreted from " + filename + ")");
@ -292,16 +299,21 @@ public class Scenario implements Callable<ScenarioResult> {
}
if (result != null) {
logger.debug("scenario result: type(" + result.getClass().getCanonicalName() + "): value:" + result.toString());
logger.debug("scenario result: type(" + result.getClass().getCanonicalName() + "): value:" + result);
}
System.err.flush();
System.out.flush();
} catch (Exception e) {
this.state = State.Errored;
logger.error("Error in scenario, shutting down. (" + e.toString() + ")");
logger.error("Error in scenario, shutting down. (" + e + ")");
try {
this.scenarioController.forceStopScenario(5000, false);
} catch (Exception eInner) {
logger.debug("Found inner exception while forcing stop with rethrow=false: " + eInner);
} finally {
this.error = e;
throw new RuntimeException(e);
}
} finally {
System.out.flush();
System.err.flush();
@ -355,14 +367,29 @@ public class Scenario implements Callable<ScenarioResult> {
return endedAtMillis;
}
public ScenarioResult call() {
/**
* This should be the only way to get a ScenarioResult for a Scenario.
*
* @return
*/
public synchronized ScenarioResult call() {
if (result == null) {
try {
runScenario();
} catch (Exception e) {
if (this.error!=null) {
logger.debug("OVERLAPPING ERRORS: prior" + this.error.getMessage() + ", current:" + e.getMessage());
}
this.error = e;
} finally {
logger.debug((this.error == null ? "NORMAL" : "ERRORED") + " scenario run");
}
String iolog = scriptEnv.getTimedLog();
ScenarioResult result = new ScenarioResult(iolog, this.startedAtMillis, this.endedAtMillis);
this.result = new ScenarioResult(this.error, iolog, this.startedAtMillis, this.endedAtMillis);
result.reportToLog();
doReportSummaries(reportSummaryTo, result);
}
return result;
}

View File

@ -16,10 +16,7 @@
package io.nosqlbench.engine.core.script;
import io.nosqlbench.engine.core.lifecycle.IndexedThreadFactory;
import io.nosqlbench.engine.core.lifecycle.ScenarioController;
import io.nosqlbench.engine.core.lifecycle.ScenarioResult;
import io.nosqlbench.engine.core.lifecycle.ScenariosResults;
import io.nosqlbench.engine.core.lifecycle.*;
import io.nosqlbench.api.errors.BasicError;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
@ -92,7 +89,6 @@ public class ScenariosExecutor {
long waitedAt = System.currentTimeMillis();
long updateAt = Math.min(timeoutAt, waitedAt + updateInterval);
while (!isShutdown && System.currentTimeMillis() < timeoutAt) {
while (!isShutdown && System.currentTimeMillis() < updateAt) {
try {
long timeRemaining = updateAt - System.currentTimeMillis();
@ -112,7 +108,13 @@ public class ScenariosExecutor {
}
Map<Scenario, ScenarioResult> scenarioResultMap = new LinkedHashMap<>();
getAsyncResultStatus()
.entrySet().forEach(es -> scenarioResultMap.put(es.getKey(), es.getValue().orElse(null)));
.entrySet()
.forEach(
es -> scenarioResultMap.put(
es.getKey(),
es.getValue().orElse(null)
)
);
return new ScenariosResults(this, scenarioResultMap);
}
@ -149,7 +151,8 @@ public class ScenariosExecutor {
oResult = Optional.of(resultFuture.get());
} catch (Exception e) {
long now = System.currentTimeMillis();
oResult = Optional.of(new ScenarioResult(e, now, now));
logger.debug("creating exceptional scenario result from getAsyncResultStatus");
oResult = Optional.of(new ScenarioResult(e, "errored output", now, now));
}
}
@ -176,23 +179,8 @@ public class ScenariosExecutor {
* @param scenarioName the scenario name of interest
* @return an optional result
*/
public Optional<ScenarioResult> getPendingResult(String scenarioName) {
Future<ScenarioResult> resultFuture1 = submitted.get(scenarioName).resultFuture;
if (resultFuture1 == null) {
throw new BasicError("Unknown scenario name:" + scenarioName);
}
long now = System.currentTimeMillis();
if (resultFuture1.isDone()) {
try {
return Optional.ofNullable(resultFuture1.get());
} catch (Exception e) {
return Optional.of(new ScenarioResult(e, now, now));
}
} else if (resultFuture1.isCancelled()) {
return Optional.of(new ScenarioResult(new Exception("result was cancelled."), now, now));
}
return Optional.empty();
public Optional<Future<ScenarioResult>> getPendingResult(String scenarioName) {
return Optional.ofNullable(submitted.get(scenarioName)).map(s -> s.resultFuture);
}
public synchronized void stopScenario(String scenarioName) {
@ -200,6 +188,7 @@ public class ScenariosExecutor {
}
public synchronized void stopScenario(String scenarioName, boolean rethrow) {
logger.debug("#stopScenario(name=" + scenarioName + ", rethrow="+ rethrow+")");
Optional<Scenario> pendingScenario = getPendingScenario(scenarioName);
if (pendingScenario.isPresent()) {
ScenarioController controller = pendingScenario.get().getScenarioController();
@ -256,6 +245,7 @@ public class ScenariosExecutor {
}
public synchronized void notifyException(Thread t, Throwable e) {
logger.debug(() -> "Scenario executor uncaught exception: " + e.getMessage());
this.stoppingException = new RuntimeException("Error in scenario thread " + t.getName(), e);
}

View File

@ -19,19 +19,27 @@ package io.nosqlbench.engine.core;
import io.nosqlbench.engine.api.scripting.ScriptEnvBuffer;
import io.nosqlbench.engine.core.script.Scenario;
import io.nosqlbench.nb.annotations.Maturity;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.junit.jupiter.api.Test;
import static org.assertj.core.api.Assertions.assertThat;
public class ScenarioTest {
private final Logger logger = LogManager.getLogger(ScenarioTest.class);
@Test
public void shouldLoadScriptText() {
ScriptEnvBuffer buffer = new ScriptEnvBuffer();
Scenario env = new Scenario("testing", Scenario.Engine.Graalvm, "stdout:300", Maturity.Any);
env.addScriptText("print('loaded script environment...');\n");
env.runScenario();
assertThat(env.getIOLog().get().get(0)).contains("loaded script environment...");
Scenario scenario = new Scenario("testing", Scenario.Engine.Graalvm, "stdout:300", Maturity.Any);
scenario.addScriptText("print('loaded script environment...');\n");
try {
var result=scenario.call();
} catch (Exception e) {
logger.debug("Scenario run encountered an exception: " + e.getMessage());
}
assertThat(scenario.getIOLog().get().get(0)).contains("loaded script environment...");
}
}

View File

@ -41,6 +41,7 @@ import org.joda.time.format.DateTimeFormat;
import java.io.CharArrayWriter;
import java.io.PrintWriter;
import java.util.*;
import java.util.concurrent.Future;
@Service(value = WebServiceObject.class, selector = "scenario-executor")
@Singleton
@ -233,8 +234,9 @@ public class ScenarioExecutorEndpoint implements WebServiceObject {
Optional<Scenario> pendingScenario = executor.getPendingScenario(scenarioName);
if (pendingScenario.isPresent()) {
Optional<ScenarioResult> pendingResult = executor.getPendingResult(scenarioName);
return new LiveScenarioView(pendingScenario.get(), pendingResult.orElse(null));
Optional<Future<ScenarioResult>> pendingResult = executor.getPendingResult(scenarioName);
Future<ScenarioResult> scenarioResultFuture = pendingResult.get();
return new LiveScenarioView(pendingScenario.get());
} else {
throw new RuntimeException("Scenario name '" + scenarioName + "' not found.");
}

View File

@ -19,7 +19,6 @@ package io.nosqlbench.engine.rest.transfertypes;
import com.fasterxml.jackson.annotation.JsonProperty;
import com.fasterxml.jackson.annotation.JsonPropertyDescription;
import io.nosqlbench.engine.api.activityapi.core.progress.ProgressMeterDisplay;
import io.nosqlbench.engine.core.lifecycle.ScenarioResult;
import io.nosqlbench.engine.core.script.Scenario;
import java.util.ArrayList;
@ -29,21 +28,16 @@ import java.util.List;
public class LiveScenarioView {
private final Scenario scenario;
private final ScenarioResult result;
public LiveScenarioView(Scenario scenario, ScenarioResult result) {
public LiveScenarioView(Scenario scenario) {
this.scenario = scenario;
this.result = result;
}
@JsonProperty
@JsonPropertyDescription("Optionally populated result, "+
" present only if there was an error or the scenario is complete")
public ResultView getResult() {
if (result==null) {
return null;
}
return new ResultView(result);
return new ResultView(scenario.getResultIfComplete().orElse(null));
}
@JsonProperty("scenario_name")

View File

@ -27,14 +27,17 @@ public class ResultView {
}
public String getIOLog() {
if (result!=null) {
return result.getIOLog();
}
public String getError() {
if (result.getException().isPresent()) {
return result.getException().get().getMessage();
} else {
return "";
}
}
public String getError() {
if (result!=null && result.getException().isPresent()) {
return result.getException().get().getMessage();
}
return "";
}
}

View File

@ -57,28 +57,28 @@ class ExitStatusIntegrationTests {
assertThat(result.exitStatus).isEqualTo(2);
}
// Temporarily disabled for triage
// TODO: figure out if github actions is an issue for this test.
// It passes locally, but fails spuriously in github actions runner
// @Test
// public void testExitStatusOnActivityThreadException() {
// ProcessInvoker invoker = new ProcessInvoker();
// invoker.setLogDir("logs/test");
// ProcessResult result = invoker.run("exitstatus_threadexception", 30,
// "java", "-jar", JARNAME, "--logs-dir", "logs/test", "run", "driver=diag", "throwoncycle=10", "cycles=1000", "cyclerate=10", "-vvv"
// );
// String stdout = result.getStdoutData().stream().collect(Collectors.joining("\n"));
// assertThat(stdout).contains("Diag was asked to throw an error on cycle 10");
// assertThat(result.exitStatus).isEqualTo(2);
// }
@Test
void testExitStatusOnActivityBasicCommandException() {
ProcessInvoker invoker = new ProcessInvoker();
invoker.setLogDir("logs/test");
// Forcing a thread exception via basic command issue.
ProcessResult result = invoker.run("exitstatus_threadexception", 30,
"java", "-jar", JARNAME, "--logs-dir", "logs/test/threadexcep", "--logs-level", "debug", "run",
"driver=diag", "cyclerate=10", "not_a_thing", "cycles=100", "-vvv"
);
String stdout = String.join("\n", result.getStdoutData());
assertThat(stdout).contains("Could not recognize command");
assertThat(result.exitStatus).isEqualTo(2);
}
@Test
void testExitStatusOnActivityOpException() {
ProcessInvoker invoker = new ProcessInvoker();
invoker.setLogDir("logs/test");
ProcessResult result = invoker.run("exitstatus_asyncstoprequest", 30,
java, "-jar", JARNAME, "--logs-dir", "logs/test/asyncstop", "run",
"driver=diag", "cyclerate=1", "op=erroroncycle:erroroncycle=10", "cycles=2000", "-vvv"
"java", "-jar", JARNAME, "--logs-dir", "logs/test/asyncstop", "--logs-level", "debug", "run",
"driver=diag", "threads=2", "cyclerate=10", "op=erroroncycle:erroroncycle=10", "cycles=500", "-vvv"
);
assertThat(result.exception).isNull();
String stdout = String.join("\n", result.getStdoutData());

View File

@ -16,10 +16,16 @@
package io.nosqlbench.cli.testing;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import java.io.File;
import java.util.concurrent.TimeUnit;
public class ProcessInvoker {
private static final Logger logger = LogManager.getLogger(ProcessInvoker.class);
private File runDirectory = new File(".");
private File logDirectory = new File(".");
@ -49,13 +55,17 @@ public class ProcessInvoker {
try {
result.cmdDir = new File(".").getCanonicalPath();
process = pb.start();
var handle = process.toHandle();
boolean terminated = process.waitFor(timeoutSeconds, TimeUnit.SECONDS);
if (!terminated) {
process.destroyForcibly().waitFor();
result.exception = new RuntimeException("timed out waiting for process, so it was shutdown forcibly.");
}
} catch (Exception e) {
if (process != null) {
logger.debug("Exception received, with exit value: " + process.exitValue());
}
result.exception = e;
} finally {
result.startNanosTime = startNanosTime;
@ -66,7 +76,7 @@ public class ProcessInvoker {
if (process != null) {
result.exitStatus = process.exitValue();
} else {
result.exitStatus=255;
result.exitStatus = 255;
}
}
return result;