Skip to content

Commit 643e6d4

Browse files
authored
Instrument flaky test: TestWorkflowTaskAndActivityTaskTimeoutsWorkflow (#9137)
## Summary - Add logging to test with the aim of helping diagnosis next time it times out Tested by: ``` go test -v -count 1 -tags test_dep go.temporal.io/server/tests -run='WorkflowTestSuite/TestWorkflowTaskAndActivityTaskTimeoutsWorkflow' ```
1 parent 378687f commit 643e6d4

1 file changed

Lines changed: 28 additions & 3 deletions

File tree

‎tests/workflow_test.go‎

Lines changed: 28 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -1289,14 +1289,34 @@ func (s *WorkflowTestSuite) TestWorkflowTaskAndActivityTaskTimeoutsWorkflow() {
12891289
T: s.T(),
12901290
}
12911291

1292+
// This test is flaky: it has been seen to cause the 35m test timeout to be exceeded
1293+
// occasionally. It currently has atypically detailed info-level logging with the aim of
1294+
// diagnosing the reason for the timeout.
1295+
const testTag = "[TestWorkflowTaskAndActivityTaskTimeoutsWorkflow] "
1296+
testStart := time.Now()
1297+
var lastDropTime time.Time
12921298
for i := 0; i < 8; i++ {
1299+
iterStart := time.Now()
12931300
dropWorkflowTask := (i%2 == 0)
1294-
s.Logger.Info("Calling Workflow Task", tag.Counter(i))
1301+
s.Logger.Info(testTag+"iteration starting",
1302+
tag.Counter(i),
1303+
tag.NewBoolTag("drop_task", dropWorkflowTask),
1304+
tag.NewDurationTag("time_since_test_start", time.Since(testStart)),
1305+
tag.NewDurationTag("time_since_last_drop", time.Since(lastDropTime)))
12951306
var err error
12961307
if dropWorkflowTask {
12971308
_, err = poller.PollAndProcessWorkflowTask(testcore.WithDumpHistory, testcore.WithDropTask)
1309+
lastDropTime = time.Now()
1310+
s.Logger.Info(testTag+"dropped workflow task",
1311+
tag.Counter(i),
1312+
tag.NewDurationTag("poll_duration", time.Since(iterStart)))
12981313
} else {
12991314
_, err = poller.PollAndProcessWorkflowTask(testcore.WithDumpHistory, testcore.WithExpectedAttemptCount(2))
1315+
s.Logger.Info(testTag+"processed workflow task (expected attempt=2)",
1316+
tag.Counter(i),
1317+
tag.NewDurationTag("poll_duration", time.Since(iterStart)),
1318+
tag.NewDurationTag("time_since_last_drop", time.Since(lastDropTime)),
1319+
tag.Error(err))
13001320
}
13011321
if err != nil {
13021322
s.PrintHistoryEventsCompact(s.GetHistory(s.Namespace().String(), &commonpb.WorkflowExecution{
@@ -1306,13 +1326,18 @@ func (s *WorkflowTestSuite) TestWorkflowTaskAndActivityTaskTimeoutsWorkflow() {
13061326
}
13071327
s.True(err == nil || errors.Is(err, testcore.ErrNoTasks))
13081328
if !dropWorkflowTask {
1309-
s.Logger.Info("Calling PollAndProcessActivityTask", tag.Counter(i))
1329+
activityStart := time.Now()
1330+
s.Logger.Info(testTag+"polling activity task", tag.Counter(i))
13101331
err = poller.PollAndProcessActivityTask(i%4 == 0)
1332+
s.Logger.Info(testTag+"activity task poll completed",
1333+
tag.Counter(i),
1334+
tag.NewDurationTag("activity_poll_duration", time.Since(activityStart)),
1335+
tag.Error(err))
13111336
s.True(err == nil || errors.Is(err, testcore.ErrNoTasks))
13121337
}
13131338
}
13141339

1315-
s.Logger.Info("Waiting for workflow to complete", tag.WorkflowRunID(we.RunId))
1340+
s.Logger.Info(testTag+"waiting for workflow to complete", tag.WorkflowRunID(we.RunId))
13161341

13171342
s.False(workflowComplete)
13181343
_, err := poller.PollAndProcessWorkflowTask(testcore.WithDumpHistory)

0 commit comments

Comments
 (0)