Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Include the Sim Error Activity Type Stack trace #1518

Merged
merged 5 commits into from
Jul 29, 2024
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -469,8 +469,13 @@ void directiveIdIncluded() throws IOException {
final var exception = reason.data();

// The error includes the directive id that was executing
// and the executing activity type and stack trace
assertTrue(exception.containsKey("executingDirectiveId"));
assertTrue(exception.containsKey("executingActivityType"));
assertEquals(dirId, exception.getInt("executingDirectiveId"));
assertEquals("DaemonCheckerActivity", exception.getString("executingActivityType"));
Mythicaeda marked this conversation as resolved.
Show resolved Hide resolved
assertTrue(exception.containsKey("activityStackTrace"));
assertEquals("DaemonCheckerActivity", exception.getString("activityStackTrace"));

// The error message is correct
assertEquals("Minutes elapsed is incorrect. TimeTrackerDaemon may have stopped.\n\tExpected: 1 Actual: 59",
Expand All @@ -496,7 +501,7 @@ void directiveIdOnDescendant() throws IOException {
// Setup: Insert a directive that will throw
int dirId = hasura.insertActivity(
fooPlan,
"DaemonCheckerSpawner",
"DaemonTaskActivity",
"01:00:00",
Json.createObjectBuilder().add("minutesElapsed", 1).add("spawnDelay", 1).build());

Expand All @@ -512,21 +517,29 @@ void directiveIdOnDescendant() throws IOException {
final var exception = reason.data();

// The error includes the directive id that was executing
// and the executing activity type and stack trace
assertTrue(exception.containsKey("executingDirectiveId"));
assertEquals(dirId, exception.getInt("executingDirectiveId"));
assertTrue(exception.containsKey("executingActivityType"));
assertEquals(dirId, exception.getInt("executingDirectiveId"));
assertEquals("DaemonTaskActivity", exception.getString("executingActivityType"));
assertTrue(exception.containsKey("activityStackTrace"));
assertEquals("DaemonTaskActivity\n"
+ "|-DaemonCheckerSpawner\n"
+ "|--DaemonCheckerActivity", exception.getString("activityStackTrace"));

// The error message is correct
assertEquals("Minutes elapsed is incorrect. TimeTrackerDaemon may have stopped.\n\tExpected: 1 Actual: 60",
assertEquals("Minutes elapsed is incorrect. TimeTrackerDaemon may have stopped.\n\tExpected: 1 Actual: 61",
reason.message());

// The error was thrown at the correct time
assertTrue(exception.containsKey("utcTimeDoy"));
assertEquals("2023-001T01:01:00", exception.getString("utcTimeDoy"));
assertEquals("2023-001T01:02:00", exception.getString("utcTimeDoy"));

// The trace starts at the original exception and doesn't include the intermediary SpanException and SimulationException
final var expectedStart = """
java.lang.RuntimeException: Minutes elapsed is incorrect. TimeTrackerDaemon may have stopped.
\tExpected: 1 Actual: 60
\tExpected: 1 Actual: 61
\tat gov.nasa.jpl.aerie.foomissionmodel.activities.DaemonCheckerActivity.run(DaemonCheckerActivity.java""";
assertTrue(reason.trace().startsWith(expectedStart));
}
Expand All @@ -551,8 +564,11 @@ void noDirectiveIdOnDaemon() throws IOException {

final var exception = reason.data();

// The error does not include any directive ids
// The error does not include any directive ids,
// executingActivityType, and activityStackTrace
assertFalse(exception.containsKey("executingDirectiveId"));
assertFalse(exception.containsKey("executingActivityType"));
assertFalse(exception.containsKey("activityStackTrace"));

// The error message is correct
assertEquals("Daemon task exception raised.", reason.message());
Expand Down Expand Up @@ -594,8 +610,11 @@ void noDirectiveIdDaemonMidDirective() throws IOException {

final var exception = reason.data();

// The error does not include any directive ids
// The error does not include any directive ids,
// executingActivityType, and activityStackTrace
assertFalse(exception.containsKey("executingDirectiveId"));
assertFalse(exception.containsKey("executingActivityType"));
assertFalse(exception.containsKey("activityStackTrace"));

// The error message is correct
assertEquals("Daemon task exception raised.", reason.message());
Expand Down
Original file line number Diff line number Diff line change
@@ -0,0 +1,25 @@
package gov.nasa.jpl.aerie.foomissionmodel.activities;

import gov.nasa.jpl.aerie.foomissionmodel.Mission;
import gov.nasa.jpl.aerie.merlin.framework.annotations.ActivityType;
import gov.nasa.jpl.aerie.merlin.protocol.types.Duration;

import static gov.nasa.jpl.aerie.foomissionmodel.generated.ActivityActions.call;
import static gov.nasa.jpl.aerie.merlin.framework.ModelActions.delay;

/**
* An activity that spawns a DaemonCheckerSpawner which spawns a DaemonCheckerActivity after delaying.
* Useful for testing the behavior of exceptions thrown by child activities and the stack trace back
* to this activity.
*
* @param minutesElapsed The expected number of minutes elapsed when the DaemonCheckerActivity begins
* @param spawnDelay The number of minutes to delay between the start of this activity and spawning the DaemonCheckerActivity
*/
@ActivityType("DaemonTaskActivity")
public record DaemonTaskActivity(int minutesElapsed, int spawnDelay) {
@ActivityType.EffectModel
public void run(final Mission mission) {
delay(Duration.of(spawnDelay, Duration.MINUTE));
call(mission, new DaemonCheckerSpawner(minutesElapsed,spawnDelay));
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -16,6 +16,7 @@
@WithActivityType(ZeroDurationUncontrollableActivity.class)
@WithActivityType(DaemonCheckerActivity.class)
@WithActivityType(DaemonCheckerSpawner.class)
@WithActivityType(DaemonTaskActivity.class)

@WithActivityType(DecompositionTestActivities.ParentActivity.class)
@WithActivityType(DecompositionTestActivities.ChildActivity.class)
Expand All @@ -30,6 +31,7 @@
import gov.nasa.jpl.aerie.foomissionmodel.activities.ControllableDurationActivity;
import gov.nasa.jpl.aerie.foomissionmodel.activities.DaemonCheckerActivity;
import gov.nasa.jpl.aerie.foomissionmodel.activities.DaemonCheckerSpawner;
import gov.nasa.jpl.aerie.foomissionmodel.activities.DaemonTaskActivity;
import gov.nasa.jpl.aerie.foomissionmodel.activities.DecompositionTestActivities;
import gov.nasa.jpl.aerie.foomissionmodel.activities.FooActivity;
import gov.nasa.jpl.aerie.foomissionmodel.activities.LateRiserActivity;
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -40,9 +40,14 @@ public static CachedSimulationEngine empty(final MissionModel<?> missionModel, f
} catch (SpanException ex) {
// Swallowing the spanException as the internal `spanId` is not user meaningful info.
final var topics = missionModel.getTopics();
final var directiveId = engine.getDirectiveIdFromSpan(activityTopic, topics, ex.spanId);
if (directiveId.isPresent()) {
throw new SimulationException(Duration.ZERO, simulationStartTime, directiveId.get(), ex.cause);
final var directiveDetail = engine.getDirectiveDetailsFromSpan(activityTopic, topics, ex.spanId);
if (directiveDetail.directiveId().isPresent()) {
throw new SimulationException(
Duration.ZERO,
simulationStartTime,
directiveDetail.directiveId().get(),
directiveDetail.activityStackTrace(),
ex.cause);
}
throw new SimulationException(Duration.ZERO, simulationStartTime, ex.cause);
} catch (Throwable ex) {
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -305,9 +305,14 @@ public static <Model> SimulationResultsComputerInputs simulateWithCheckpoints(
elapsedTime = engine.getElapsedTime();
// Swallowing the spanException as the internal `spanId` is not user meaningful info.
final var topics = missionModel.getTopics();
final var directiveId = engine.getDirectiveIdFromSpan(activityTopic, topics, ex.spanId);
if (directiveId.isPresent()) {
throw new SimulationException(elapsedTime, simulationStartTime, directiveId.get(), ex.cause);
final var directiveDetail = engine.getDirectiveDetailsFromSpan(activityTopic, topics, ex.spanId);
if (directiveDetail.directiveId().isPresent()) {
throw new SimulationException(
elapsedTime,
simulationStartTime,
directiveDetail.directiveId().get(),
directiveDetail.activityStackTrace(),
ex.cause);
}
throw new SimulationException(elapsedTime, simulationStartTime, ex.cause);
} catch (Throwable ex) {
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -109,9 +109,14 @@ public static <Model> SimulationResults simulate(
} catch (SpanException ex) {
// Swallowing the spanException as the internal `spanId` is not user meaningful info.
final var topics = missionModel.getTopics();
final var directiveId = engine.getDirectiveIdFromSpan(activityTopic, topics, ex.spanId);
if(directiveId.isPresent()) {
throw new SimulationException(engine.getElapsedTime(), simulationStartTime, directiveId.get(), ex.cause);
final var directiveDetail = engine.getDirectiveDetailsFromSpan(activityTopic, topics, ex.spanId);
if(directiveDetail.directiveId().isPresent()) {
throw new SimulationException(
engine.getElapsedTime(),
simulationStartTime,
directiveDetail.directiveId().get(),
directiveDetail.activityStackTrace(),
ex.cause);
}
throw new SimulationException(engine.getElapsedTime(), simulationStartTime, ex.cause);
} catch (Throwable ex) {
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -7,7 +7,9 @@
import java.time.format.DateTimeFormatter;
import java.time.format.DateTimeFormatterBuilder;
import java.time.temporal.ChronoField;
import java.util.List;
import java.util.Optional;
import java.util.stream.Collectors;

import static gov.nasa.jpl.aerie.merlin.protocol.types.Duration.HOUR;
import static gov.nasa.jpl.aerie.merlin.protocol.types.Duration.MICROSECOND;
Expand All @@ -28,20 +30,34 @@ public class SimulationException extends RuntimeException {
public final Instant instant;
public final Throwable cause;
public final Optional<ActivityDirectiveId> directiveId;
public final Optional<String> activityType;
public final Optional<String> activityStackTrace;

public SimulationException(final Duration elapsedTime, final Instant startTime, final Throwable cause) {
super("Exception occurred " + formatDuration(elapsedTime) + " into the simulation at " + formatInstant(addDurationToInstant(startTime, elapsedTime)), cause);
this.directiveId = Optional.empty();
this.activityType = Optional.empty();
this.activityStackTrace = Optional.empty();
this.elapsedTime = elapsedTime;
this.instant = addDurationToInstant(startTime, elapsedTime);
this.cause = cause;
}

public SimulationException(final Duration elapsedTime, final Instant startTime, final ActivityDirectiveId directiveId, final Throwable cause) {
public SimulationException(
final Duration elapsedTime,
final Instant startTime,
final ActivityDirectiveId directiveId,
final List<SerializedActivity> activityStackTrace,
final Throwable cause) {
super("Exception occurred " + formatDuration(elapsedTime)
+ " into the simulation at " + formatInstant(addDurationToInstant(startTime, elapsedTime))
+ " while simulating activity directive with id " +directiveId.id(), cause);
this.directiveId = Optional.of(directiveId);
this.activityType = activityStackTrace.isEmpty() ? Optional.empty() : Optional.of(activityStackTrace.getFirst().getTypeName());
this.activityStackTrace = activityStackTrace.isEmpty() ? Optional.empty(): Optional.of(activityStackTrace.stream().map( serializedActivity -> {
final var index = activityStackTrace.indexOf(serializedActivity);
return (index > 0 ? "|" : "") +"-".repeat(index) + serializedActivity.getTypeName();
}).collect(Collectors.joining("\n")));
this.elapsedTime = elapsedTime;
this.instant = addDurationToInstant(startTime, elapsedTime);
this.cause = cause;
Expand Down
Original file line number Diff line number Diff line change
@@ -0,0 +1,10 @@
package gov.nasa.jpl.aerie.merlin.driver.engine;

import gov.nasa.jpl.aerie.merlin.driver.ActivityDirectiveId;
import gov.nasa.jpl.aerie.merlin.driver.SerializedActivity;
import gov.nasa.jpl.aerie.merlin.protocol.types.SerializedValue;

import java.util.List;
import java.util.Optional;

public record DirectiveDetail(Optional<ActivityDirectiveId> directiveId, List<SerializedActivity> activityStackTrace) {}
Original file line number Diff line number Diff line change
Expand Up @@ -53,6 +53,7 @@
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import java.util.function.Consumer;
import java.util.stream.Collectors;

/**
* A representation of the work remaining to do during a simulation, and its accumulated results.
Expand Down Expand Up @@ -676,29 +677,36 @@ void extractOutput(final SerializableTopic<T> topic, final Event ev, final SpanI
}
}


/**
* Get an Activity Directive Id from a SpanId, if the span is a descendent of a directive.
*/
public Optional<ActivityDirectiveId> getDirectiveIdFromSpan(
public DirectiveDetail getDirectiveDetailsFromSpan(
final Topic<ActivityDirectiveId> activityTopic,
final Iterable<SerializableTopic<?>> serializableTopics,
final SpanId spanId
) {
// Collect per-span information from the event graph.
final var spanInfo = new SpanInfo();
for (final var point : this.timeline) {
if (!(point instanceof TemporalEventSource.TimePoint.Commit p)) continue;

final var trait = new SpanInfo.Trait(serializableTopics, activityTopic);
p.events().evaluate(trait, trait::atom).accept(spanInfo);
}
final var spanInfo = computeSpanInfo(activityTopic, serializableTopics, this.timeline);

// Identify the nearest ancestor directive
// Identify the nearest ancestor directive by walking up the parent
// span tree. Save the activity trace along the way
Optional<SpanId> directiveSpanId = Optional.of(spanId);
final var activityStackTrace = new LinkedList<SerializedActivity>();
while (directiveSpanId.isPresent() && !spanInfo.isDirective(directiveSpanId.get())) {
activityStackTrace.add(spanInfo.input().get(directiveSpanId.get()));
directiveSpanId = this.getSpan(directiveSpanId.get()).parent();
}
return directiveSpanId.map(spanInfo::getDirective);

// Add final top level parent activity to the stack trace if present
if (directiveSpanId.isPresent()) {
activityStackTrace.add(spanInfo.input().get(directiveSpanId.get()));
}

return new DirectiveDetail(
directiveSpanId.map(spanInfo::getDirective),
// remove null activities from the stack trace and reverse order
activityStackTrace.stream().filter(a -> a != null).collect(Collectors.toList()).reversed());
}

public record SimulationActivityExtract(
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -97,6 +97,8 @@ public void simulate(
.add("elapsedTime", SimulationException.formatDuration(ex.elapsedTime))
.add("utcTimeDoy", SimulationException.formatInstant(ex.instant));
ex.directiveId.ifPresent(directiveId -> errorMsgBuilder.add("executingDirectiveId", directiveId.id()));
ex.activityType.ifPresent(activityType -> errorMsgBuilder.add("executingActivityType", activityType));
ex.activityStackTrace.ifPresent(activityStackTrace -> errorMsgBuilder.add("activityStackTrace", activityStackTrace));
writer.failWith(b -> b
.type("SIMULATION_EXCEPTION")
.message(ex.cause.getMessage())
Expand Down
Loading