Dead code utest resurrection and timing w/ gh actions

Cyclerate=10 to test github actions part2
Debug and exception handling
Detailed error handler logging
System out diagnostics
Capture step included
Try-catch diagnostics.
sysout cleanup; general cleanup
This commit is contained in:
jeffbanks 2022-11-15 10:57:10 -06:00 committed by Jonathan Shook
parent 20ed4950d4
commit dcf7baf867
12 changed files with 233 additions and 188 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:
@ -31,10 +32,12 @@ jobs:
- name: mvn verify
run: mvn verify
- name: Capture
run: tar -cvf jbanks_files.tar [a-zA-Z]**/logs/*
- name: Archive Test Results
if: always()
uses: actions/upload-artifact@v3
with:
name: test-results
path: |
[a-zA-Z]**/logs/*
path: jbanks_files.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))
.asReadOnly();
.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

@ -91,7 +91,7 @@ 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());
}
}
/**
@ -99,7 +99,7 @@ public class NBCLI implements Function<String[], Integer> {
* }
*
* public static void main(String[] args) {
* @param strings
* @param args
* @return
*/
@Override
@ -117,7 +117,7 @@ public class NBCLI implements Function<String[], Integer> {
}
}
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 +150,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())
@ -476,15 +476,15 @@ public class NBCLI implements Function<String[], Integer> {
ScenariosResults scenariosResults = executor.awaitAllResults();
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,12 +16,19 @@
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 is in the house.");
}
@Override

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.debug("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.
*
* <p>
* TODO: move activity finisher threaad to this class and remove separate implementation
*/
public boolean awaitCompletion(int waitTime) {
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

@ -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,18 +63,18 @@ 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 {
logger.error("Unknown type for error handler: " + t);
throw new RuntimeException("Error in exception handler", t);
logger.error("Unknown type for error handler: " + t);
throw new RuntimeException("Error in exception handler", t);
}
}
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

@ -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;
@ -55,10 +54,10 @@ import java.util.stream.Collectors;
public class LoggerConfig extends ConfigurationFactory {
public static Map<String, String> STANDARD_FORMATS = Map.of(
"TERSE", "%8r %-5level [%t] %-12logger{0} %msg%n%throwable",
"VERBOSE", "%d{DEFAULT}{GMT} [%t] %logger %-5level: %msg%n%throwable",
"TERSE-ANSI", "%8r %highlight{%-5level} %style{%C{1.} [%t] %-12logger{0}} %msg%n%throwable",
"VERBOSE-ANSI", "%d{DEFAULT}{GMT} [%t] %highlight{%logger %-5level}: %msg%n%throwable"
"TERSE", "%8r %-5level [%t] %-12logger{0} %msg%n%throwable",
"VERBOSE", "%d{DEFAULT}{GMT} [%t] %logger %-5level: %msg%n%throwable",
"TERSE-ANSI", "%8r %highlight{%-5level} %style{%C{1.} [%t] %-12logger{0}} %msg%n%throwable",
"VERBOSE-ANSI", "%d{DEFAULT}{GMT} [%t] %highlight{%logger %-5level}: %msg%n%throwable"
);
/**
@ -66,7 +65,7 @@ public class LoggerConfig extends ConfigurationFactory {
* we squelch them to some reasonable level so they aren't a nuisance.
*/
public static Map<String, Level> BUILTIN_OVERRIDES = Map.of(
"oshi.util", Level.INFO
"oshi.util", Level.INFO
);
/**
@ -151,20 +150,20 @@ public class LoggerConfig extends ConfigurationFactory {
builder.setStatusLevel(internalLoggingStatusThreshold);
builder.add(
builder.newFilter(
"ThresholdFilter",
Filter.Result.ACCEPT,
Filter.Result.NEUTRAL
).addAttribute("level", builderThresholdLevel)
builder.newFilter(
"ThresholdFilter",
Filter.Result.ACCEPT,
Filter.Result.NEUTRAL
).addAttribute("level", builderThresholdLevel)
);
// CONSOLE appender
AppenderComponentBuilder appenderBuilder =
builder.newAppender("console", "CONSOLE")
.addAttribute("target", ConsoleAppender.Target.SYSTEM_OUT);
builder.newAppender("console", "CONSOLE")
.addAttribute("target", ConsoleAppender.Target.SYSTEM_OUT);
appenderBuilder.add(builder.newLayout("PatternLayout")
.addAttribute("pattern", consolePattern));
.addAttribute("pattern", consolePattern));
// appenderBuilder.add(
// builder.newFilter("MarkerFilter", Filter.Result.DENY, Filter.Result.NEUTRAL)
@ -174,8 +173,8 @@ public class LoggerConfig extends ConfigurationFactory {
// Log4J internal logging
builder.add(builder.newLogger("org.apache.logging.log4j", Level.DEBUG)
.add(builder.newAppenderRef("console"))
.addAttribute("additivity", false));
.add(builder.newAppenderRef("console"))
.addAttribute("additivity", false));
if (sessionName != null) {
@ -189,55 +188,55 @@ public class LoggerConfig extends ConfigurationFactory {
// LOGFILE appender
LayoutComponentBuilder logfileLayout = builder.newLayout("PatternLayout")
.addAttribute("pattern", logfilePattern);
.addAttribute("pattern", logfilePattern);
String filebase = getSessionName().replaceAll("\\s", "_");
String logfilePath = loggerDir.resolve(filebase + ".log").toString();
this.logfileLocation = logfilePath;
String archivePath = loggerDir.resolve(filebase + "-TIMESTAMP.log.gz").toString()
.replaceAll("TIMESTAMP", "%d{MM-dd-yy}");
.replaceAll("TIMESTAMP", "%d{MM-dd-yy}");
ComponentBuilder triggeringPolicy = builder.newComponent("Policies")
.addComponent(builder.newComponent("CronTriggeringPolicy").addAttribute("schedule", "0 0 0 * * ?"))
.addComponent(builder.newComponent("SizeBasedTriggeringPolicy").addAttribute("size", "100M"));
.addComponent(builder.newComponent("CronTriggeringPolicy").addAttribute("schedule", "0 0 0 * * ?"))
.addComponent(builder.newComponent("SizeBasedTriggeringPolicy").addAttribute("size", "100M"));
AppenderComponentBuilder logsAppenderBuilder =
builder.newAppender("SCENARIO_APPENDER", RollingFileAppender.PLUGIN_NAME)
.addAttribute("fileName", logfilePath)
.addAttribute("filePattern", archivePath)
.addAttribute("append", false)
.add(logfileLayout)
.addComponent(triggeringPolicy);
builder.newAppender("SCENARIO_APPENDER", RollingFileAppender.PLUGIN_NAME)
.addAttribute("fileName", logfilePath)
.addAttribute("filePattern", archivePath)
.addAttribute("append", false)
.add(logfileLayout)
.addComponent(triggeringPolicy);
builder.add(logsAppenderBuilder);
rootBuilder.add(
builder.newAppenderRef("SCENARIO_APPENDER")
.addAttribute("level", fileLevel)
builder.newAppenderRef("SCENARIO_APPENDER")
.addAttribute("level", fileLevel)
);
}
rootBuilder.add(
builder.newAppenderRef("console")
.addAttribute("level",
consoleLevel
)
builder.newAppenderRef("console")
.addAttribute("level",
consoleLevel
)
);
builder.add(rootBuilder);
BUILTIN_OVERRIDES.forEach((k, v) -> {
builder.add(builder.newLogger(k, v)
.add(builder.newAppenderRef("console"))
.add(builder.newAppenderRef("SCENARIO_APPENDER"))
.addAttribute("additivity", true));
.add(builder.newAppenderRef("console"))
.add(builder.newAppenderRef("SCENARIO_APPENDER"))
.addAttribute("additivity", true));
});
logLevelOverrides.forEach((k, v) -> {
Level olevel = Level.valueOf(v);
builder.add(builder.newLogger(k, olevel)
.add(builder.newAppenderRef("console"))
.add(builder.newAppenderRef("SCENARIO_APPENDER"))
.addAttribute("additivity", true));
.add(builder.newAppenderRef("console"))
.add(builder.newAppenderRef("SCENARIO_APPENDER"))
.addAttribute("additivity", true));
});
BuiltConfiguration builtConfig = builder.build();
@ -268,7 +267,7 @@ public class LoggerConfig extends ConfigurationFactory {
if (!Files.exists(loggerDir)) {
try {
FileAttribute<Set<PosixFilePermission>> attrs = PosixFilePermissions.asFileAttribute(
PosixFilePermissions.fromString("rwxrwx---")
PosixFilePermissions.fromString("rwxrwx---")
);
Path directory = Files.createDirectory(loggerDir, attrs);
} catch (Exception e) {
@ -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;
}
@ -334,9 +333,9 @@ public class LoggerConfig extends ConfigurationFactory {
}
List<File> toDelete = filesList.stream()
.sorted(fileTimeComparator)
.limit(remove)
.collect(Collectors.toList());
.sorted(fileTimeComparator)
.limit(remove)
.collect(Collectors.toList());
for (File file : toDelete) {
logger.info("removing extra logfile: " + file.getPath());

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;
@ -98,16 +101,16 @@ public class Scenario implements Callable<ScenarioResult> {
}
public Scenario(
String scenarioName,
String scriptfile,
Engine engine,
String progressInterval,
boolean wantsStackTraces,
boolean wantsCompiledScript,
String reportSummaryTo,
String commandLine,
Path logsPath,
Maturity minMaturity) {
String scenarioName,
String scriptfile,
Engine engine,
String progressInterval,
boolean wantsStackTraces,
boolean wantsCompiledScript,
String reportSummaryTo,
String commandLine,
Path logsPath,
Maturity minMaturity) {
this.scenarioName = scenarioName;
this.scriptfile = scriptfile;
@ -165,25 +168,24 @@ public class Scenario implements Callable<ScenarioResult> {
private void init() {
logger.debug("Using engine " + engine.toString());
MetricRegistry metricRegistry = ActivityMetrics.getMetricRegistry();
Context.Builder contextSettings = Context.newBuilder("js")
.allowHostAccess(HostAccess.ALL)
.allowNativeAccess(true)
.allowCreateThread(true)
.allowIO(true)
.allowHostClassLookup(s -> true)
.allowHostClassLoading(true)
.allowCreateProcess(true)
.allowAllAccess(true)
.allowEnvironmentAccess(EnvironmentAccess.INHERIT)
.allowPolyglotAccess(PolyglotAccess.ALL)
.option("js.ecmascript-version", "2020")
.option("js.nashorn-compat", "true");
.allowHostAccess(HostAccess.ALL)
.allowNativeAccess(true)
.allowCreateThread(true)
.allowIO(true)
.allowHostClassLookup(s -> true)
.allowHostClassLoading(true)
.allowCreateProcess(true)
.allowAllAccess(true)
.allowEnvironmentAccess(EnvironmentAccess.INHERIT)
.allowPolyglotAccess(PolyglotAccess.ALL)
.option("js.ecmascript-version", "2020")
.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
@ -205,9 +207,9 @@ public class Scenario implements Callable<ScenarioResult> {
// scriptEngine.put("metrics", new PolyglotMetricRegistryBindings(metricRegistry));
// scriptEngine.put("activities", new NashornActivityBindings(scenarioController));
scriptEngine.put("scenario", new PolyglotScenarioController(scenarioController));
scriptEngine.put("metrics", new PolyglotMetricRegistryBindings(metricRegistry));
scriptEngine.put("activities", new NashornActivityBindings(scenarioController));
scriptEngine.put("scenario", new PolyglotScenarioController(scenarioController));
scriptEngine.put("metrics", new PolyglotMetricRegistryBindings(metricRegistry));
scriptEngine.put("activities", new NashornActivityBindings(scenarioController));
for (ScriptingPluginInfo<?> extensionDescriptor : SandboxExtensionFinder.findAll()) {
if (!extensionDescriptor.isAutoLoading()) {
@ -216,15 +218,15 @@ public class Scenario implements Callable<ScenarioResult> {
}
Logger extensionLogger =
LogManager.getLogger("extensions." + extensionDescriptor.getBaseVariableName());
LogManager.getLogger("extensions." + extensionDescriptor.getBaseVariableName());
Object extensionObject = extensionDescriptor.getExtensionObject(
extensionLogger,
metricRegistry,
scriptEnv
extensionLogger,
metricRegistry,
scriptEnv
);
ScenarioMetadataAware.apply(extensionObject, getScenarioMetadata());
logger.trace("Adding extension object: name=" + extensionDescriptor.getBaseVariableName() +
" class=" + extensionObject.getClass().getSimpleName());
" class=" + extensionObject.getClass().getSimpleName());
scriptEngine.put(extensionDescriptor.getBaseVariableName(), extensionObject);
}
}
@ -232,10 +234,10 @@ public class Scenario implements Callable<ScenarioResult> {
private synchronized ScenarioMetadata getScenarioMetadata() {
if (this.scenarioMetadata == null) {
this.scenarioMetadata = new ScenarioMetadata(
this.startedAtMillis,
this.scenarioName,
SystemId.getNodeId(),
SystemId.getNodeFingerprint()
this.startedAtMillis,
this.scenarioName,
SystemId.getNodeId(),
SystemId.getNodeFingerprint()
);
}
return scenarioMetadata;
@ -249,15 +251,17 @@ public class Scenario implements Callable<ScenarioResult> {
startedAtMillis = System.currentTimeMillis();
Annotators.recordAnnotation(
Annotation.newBuilder()
.session(this.scenarioName)
.now()
.layer(Layer.Scenario)
.detail("engine", this.engine.toString())
.build()
Annotation.newBuilder()
.session(this.scenarioName)
.now()
.layer(Layer.Scenario)
.detail("engine", this.engine.toString())
.build()
);
init();
logger.debug("Running control script for " + getScenarioName() + ".");
for (String script : scripts) {
try {
Object result = null;
@ -270,20 +274,19 @@ public class Scenario implements Callable<ScenarioResult> {
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 + ")");
"interpreted from " + filename + ")");
Path written = Files.write(
Path.of(filename),
script.getBytes(StandardCharsets.UTF_8),
StandardOpenOption.TRUNCATE_EXISTING,
StandardOpenOption.CREATE
Path.of(filename),
script.getBytes(StandardCharsets.UTF_8),
StandardOpenOption.TRUNCATE_EXISTING,
StandardOpenOption.CREATE
);
BufferedReader reader = Files.newBufferedReader(written);
scriptEngine.eval(reader);
logger.debug("<- scenario control script completed (interpreted) " +
"from " + filename + ")");
"from " + filename + ")");
} else {
logger.debug("-> invoking main scenario script (interpreted)");
result = scriptEngine.eval(script);
@ -299,9 +302,12 @@ public class Scenario implements Callable<ScenarioResult> {
} catch (Exception e) {
this.state = State.Errored;
logger.error("Error in scenario, shutting down. (" + e.toString() + ")");
this.scenarioController.forceStopScenario(5000, false);
this.error = e;
throw new RuntimeException(e);
try {
this.scenarioController.forceStopScenario(5000, false);
} finally {
this.error = e;
throw new RuntimeException(e);
}
} finally {
System.out.flush();
System.err.flush();
@ -336,12 +342,12 @@ public class Scenario implements Callable<ScenarioResult> {
// We report the scenario state via annotation even for short runs
Annotation annotation = Annotation.newBuilder()
.session(this.scenarioName)
.interval(this.startedAtMillis, endedAtMillis)
.layer(Layer.Scenario)
.label("state", this.state.toString())
.detail("command_line", this.commandLine)
.build();
.session(this.scenarioName)
.interval(this.startedAtMillis, endedAtMillis)
.layer(Layer.Scenario)
.label("state", this.state.toString())
.detail("command_line", this.commandLine)
.build();
Annotators.recordAnnotation(annotation);
@ -356,14 +362,19 @@ public class Scenario implements Callable<ScenarioResult> {
}
public ScenarioResult call() {
runScenario();
String iolog = scriptEnv.getTimedLog();
ScenarioResult result = new ScenarioResult(iolog, this.startedAtMillis, this.endedAtMillis);
result.reportToLog();
doReportSummaries(reportSummaryTo, result);
ScenarioResult result = null;
try {
runScenario();
String iolog = scriptEnv.getTimedLog();
result = new ScenarioResult(iolog, this.startedAtMillis, this.endedAtMillis);
result.reportToLog();
doReportSummaries(reportSummaryTo, result);
} catch (Exception e) {
// note: this exception wasn't being handled here. thrown up the chain to trace issues.
logger.debug("runScenario exception received: " + e.getMessage());
throw e;
}
return result;
}
@ -391,8 +402,8 @@ public class Scenario implements Callable<ScenarioResult> {
break;
default:
String outName = summaryTo
.replaceAll("_SESSION_", getScenarioName())
.replaceAll("_LOGS_", logsPath.toString());
.replaceAll("_SESSION_", getScenarioName())
.replaceAll("_LOGS_", logsPath.toString());
try {
out = new PrintStream(new FileOutputStream(outName));
break;

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;
@ -256,6 +253,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,18 +19,26 @@ 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 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();
try {
env.runScenario();
} catch (Exception e) {
logger.debug("Scenario run encountered an exception: " + e.getMessage());
}
assertThat(env.getIOLog().get().get(0)).contains("loaded script environment...");
}

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", "cyclerate=10", "op=erroroncycle:erroroncycle=10", "cycles=100", "-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;