Querying a running workflow makes it spam previously logged messages

[rorueda]

Expected Behavior

Querying a workflow doesn't generate additional logs.

Actual Behavior

Querying a workflow generates additional logs.

Steps to Reproduce the Problem

I added an additional test to DirectQueryReplaysDontSpamLogWithWorkflowExecutionExceptionsTest.java to reproduce the issue.

@Rule
public SDKTestWorkflowRule testWorkflowRule =
    SDKTestWorkflowRule.newBuilder()
        .setWorkflowTypes(TestWorkflowNonRetryableFlag.class, LogAndKeepRunningWorkflow.class)
        .setActivityImplementations(new TestActivities.TestActivitiesImpl())
        .build();

@Test
public void queriedWorkflowFailureDoesntProduceAdditionalLogsWhenWorkflowIsNotCompleted()
    throws InterruptedException {
  TestWorkflows.QueryableWorkflow workflow =
      testWorkflowRule.newWorkflowStub(TestWorkflows.QueryableWorkflow.class);

  WorkflowExecution execution = WorkflowClient.start(workflow::execute);
  Thread.sleep(500);
  assertEquals(
      "Workflow execution exception should be logged",
      1,
      workflowExecuteRunnableLoggerAppender.list.size());

  TestWorkflows.QueryableWorkflow queryStub =
      testWorkflowRule
          .getWorkflowClient()
          .newWorkflowStub(TestWorkflows.QueryableWorkflow.class, execution.getWorkflowId());
  assertEquals("my-state", queryStub.getState());
  assertEquals("There was only one execution.", 1, workflowCodeExecutionCount.get());
  assertEquals(
      "Only the original exception should be logged.",
      1,
      workflowExecuteRunnableLoggerAppender.list.size());

  testWorkflowRule.invalidateWorkflowCache();
  assertEquals("my-state", queryStub.getState());
  assertEquals(
      "There was two executions - one original and one full replay for query.",
      2,
      workflowCodeExecutionCount.get());
  assertEquals(
      "Only the original exception should be logged.",
      1,
      workflowExecuteRunnableLoggerAppender.list.size());

  queryStub.mySignal("exit");
  assertEquals("my-state", queryStub.getState());
  assertEquals(
      "There was three executions - one original and two full replays for query.",
      3,
      workflowCodeExecutionCount.get());
  assertEquals(
      "Only the original exception should be logged.",
      1,
      workflowExecuteRunnableLoggerAppender.list.size());
}

public static class LogAndKeepRunningWorkflow implements TestWorkflows.QueryableWorkflow {
  private final org.slf4j.Logger logger;
  private final TestActivities.VariousTestActivities activities;
  private boolean exit;

  public LogAndKeepRunningWorkflow() {
    activities =
        Workflow.newActivityStub(
            TestActivities.VariousTestActivities.class,
            ActivityOptions.newBuilder()
                .setStartToCloseTimeout(Duration.ofSeconds(10))
                .setRetryOptions(RetryOptions.newBuilder().setMaximumAttempts(1).build())
                .build());
    logger = Workflow.getLogger("io.temporal.internal.sync.WorkflowExecutionHandler");
  }

  @Override
  public String execute() {
    workflowCodeExecutionCount.incrementAndGet();
    while (true) {
      try {
        activities.throwIO();
      } catch (ActivityFailure e) {
        logger.error("Unexpected error on activity", e);
        Workflow.await(() -> exit);
        if (exit) {
          return "exit";
        }
      }
    }
  }

  @Override
  public String getState() {
    return "my-state";
  }

  @Override
  public void mySignal(String value) {
    exit = true;
  }
}

I found that the logs are generated because replaying is being set to false here:

sdk-java/temporal-sdk/src/main/java/io/temporal/internal/statemachines/WorkflowStateMachines.java

Lines 456 to 462 in 5e5cf0b

	// We don't explicitly check if the event is a command event here because it's already handled
	// above.
	if (replaying
	&& lastTask
	&& event.getEventType() != EventType.EVENT_TYPE_WORKFLOW_TASK_COMPLETED) {
	replaying = false;
	}

I saw that there were changes to those lines recently, but I've tested with 1.23.1, 1.23.2 and master and the issue is present in all of them. I first noticed the issue in production when upgrading from 1.19.1 to 1.23.1.

Specifications

• Version: 1.23.1 / 1.23.2 / master
• Platform: Ubuntu 22

[Quinn-With-Two-Ns]

This is already fixed by a41c64e and will be included in the next SDK release

[rorueda]

I can't rule out my test being wrong, but I have just tested on top of the current last commit 5e5cf0b and it still fails. Any idea why?

[Quinn-With-Two-Ns]

hm let me try to get your test running on my machine