Stop retrying get-workflow-history with an impossibly-short timeout (#1171)

* Stop retrying get-workflow-history with an impossibly-short timeout

Previously, when a `GetWorkflow(...).Get(...)` call timed out while waiting
for the workflow to complete, this happened:
- N-1 requests of the default long-poll timeout occurred, and it correctly retried
- The final request would have something like 5 seconds left, so it performs that call
- The server gives up the request *slightly before* that timeout so it can return the
  next page token for a future request to use (as happened in the N-1 earlier requests)
- Since no history was received and there's still time left in the context (~50ms
  internally), another impossibly-short request was sent
- This request fails immediately with a "insufficient time for long poll request" error.
- *This bad-request error* is what is returned from `Get(...)`

Which is pretty clearly sub-optimal.
Both because we sent a request that is almost guaranteed to fail, and because the error
returned to the caller is fairly generic looking / doesn't describe what happened.

What happened is that we ran out of time.
So this now returns a DeadlineExceeded error, like any other timeout, and does not
cause that final request to occur.

Author: Groxx

internal/internal_workflow_client.go

@@ -512,12 +512,18 @@ func (wc *workflowClient) GetWorkflowHistory(
 		var err error
 	Loop:
 		for {
+			var isFinalLongPoll bool
 			err = backoff.Retry(ctx,
 				func() error {
 					var err1 error
 					tchCtx, cancel, opt := newChannelContext(ctx, wc.featureFlags, func(builder *contextBuilder) {
 						if isLongPoll {
 							builder.Timeout = defaultGetHistoryTimeoutInSecs * time.Second
+							deadline, ok := ctx.Deadline()
+							if ok && deadline.Before(time.Now().Add(builder.Timeout)) {
+								// insufficient time for another poll, so this needs to be the last attempt
+								isFinalLongPoll = true
+							}
 						}
 					})
 					defer cancel()
@@ -546,6 +552,13 @@ func (wc *workflowClient) GetWorkflowHistory(
 				return nil, err
 			}
 			if isLongPoll && len(response.History.Events) == 0 && len(response.NextPageToken) != 0 {
+				if isFinalLongPoll {
+					// essentially a deadline exceeded, the last attempt did not get a result.
+					// this is necessary because the server does not know if we are able to try again,
+					// so it returns an empty result slightly before a timeout occurs, so the next
+					// attempt's token can be returned if it wishes to retry.
+					return nil, fmt.Errorf("timed out waiting for the workflow to finish: %w", context.DeadlineExceeded)
+				}
 				request.NextPageToken = response.NextPageToken
 				continue Loop
 			}

internal/internal_workflow_client_test.go

@@ -30,6 +30,7 @@ import (
 	"time"
 
 	"go.uber.org/cadence/internal/common/serializer"
+	"go.uber.org/yarpc"
 
 	"go.uber.org/cadence/.gen/go/cadence/workflowservicetest"
 	"go.uber.org/cadence/.gen/go/shared"
@@ -293,6 +294,67 @@ func (s *historyEventIteratorSuite) TestIterator_Error() {
 	s.NotNil(err)
 }
 
+func (s *historyEventIteratorSuite) TestIterator_StopsTryingNearTimeout() {
+	// ensuring "when GetWorkflow().Get(...) times out while waiting", we return a timed-out error of some kind,
+	// and stop sending requests rather than trying again and getting some other kind of error.
+	// historically this led to a "bad request", insufficient time left for long poll, which was confusing and noisy.
+
+	filterType := shared.HistoryEventFilterTypeCloseEvent
+	reqNormal := getGetWorkflowExecutionHistoryRequest(filterType)
+	reqFinal := getGetWorkflowExecutionHistoryRequest(filterType)
+
+	// all items filtered out for both requests
+	resEmpty := &shared.GetWorkflowExecutionHistoryResponse{
+		History:       &shared.History{Events: nil}, // this or RawHistory must be non-nil, but they can be empty
+		NextPageToken: []byte{1, 2, 3, 4, 5},
+	}
+	reqFinal.NextPageToken = resEmpty.NextPageToken
+
+	s.True(time.Second < (defaultGetHistoryTimeoutInSecs*time.Second), "sanity check: default timeout must be longer than how long we extend the timeout for tests")
+
+	// begin with a deadline that is long enough to allow 2 requests
+	d := time.Now().Add((defaultGetHistoryTimeoutInSecs * time.Second) + time.Second)
+	baseCtx, cancel := context.WithDeadline(context.Background(), d)
+	defer cancel()
+	ctx := &fakeDeadlineContext{baseCtx, d}
+
+	// prep the iterator
+	iter := s.wfClient.GetWorkflowHistory(ctx, workflowID, runID, true, filterType)
+
+	// first attempt should occur, and trigger a second request with less than the requested timeout
+	s.workflowServiceClient.EXPECT().GetWorkflowExecutionHistory(gomock.Any(), reqNormal, gomock.Any()).DoAndReturn(func(_ context.Context, _ *shared.GetWorkflowExecutionHistoryRequest, _ ...yarpc.CallOption) (*shared.GetWorkflowExecutionHistoryResponse, error) {
+		// first request is being sent, modify the context to simulate time passing,
+		// and give the second request insufficient time to trigger another poll.
+		//
+		// without this, you should see an attempt at a third call, as the context is not canceled,
+		// and this mock took no time to respond.
+		ctx.d = time.Now().Add(time.Second)
+		return resEmpty, nil
+	}).Times(1)
+	// second request should occur, but not another
+	s.workflowServiceClient.EXPECT().GetWorkflowExecutionHistory(gomock.Any(), reqFinal, gomock.Any()).Return(resEmpty, nil).Times(1)
+
+	// trigger both paginated requests as part of the single HasNext call
+	s.True(iter.HasNext())
+	event, err := iter.Next()
+	s.Nil(event, "iterator should not have returned any events")
+	s.Error(err, "iterator should have errored")
+	// canceled may also be appropriate, but currently this is true
+	s.Truef(errors.Is(err, context.DeadlineExceeded), "iterator should have returned a deadline-exceeded error, but returned a: %#v", err)
+	s.Contains(err.Error(), "waiting for the workflow to finish", "should be descriptive of what happened")
+}
+
+// minor helper type to allow faking deadlines between calls, as we cannot normally modify a context that way.
+type fakeDeadlineContext struct {
+	context.Context
+
+	d time.Time
+}
+
+func (f *fakeDeadlineContext) Deadline() (time.Time, bool) {
+	return f.d, true
+}
+
 // workflowRunSuite
 
 type (