Context deadline exceeded errors when calling API

[abezzub]

I am getting occasional context deadline exceeded (Client.Timeout exceeded while awaiting headers) when calling Graph API using the SDK. This happens on different resources (events, todo tasks, calendar view, etc). I am using default context without timeout set. Is it possible to configure the timeout used by the SDK?

[baywet]

Hi @abezzub
Thanks for using the Go SDK and for reaching out.
the default timeout is 100s if your context doesn't already contain a deadline.

You can perfectly pass in a context with a deadline to the chained API surface and the SDK should respect the new deadline.

[abezzub]

🤔 I verified our code does not set timeout on context before it is passed into SDK's functions. We call SDK functions in backend jobs, I see an example where timeout happened 37 seconds after the job started:

fields.causeType | *url.Error
fields.duration | 37.879397846
fields.errorString | failed to fetch calendar view page: Get "https://graph.microsoft.com/v1.0/me/calendar/calendarView?startDateTime=2022-10-17T10%3a12%3a02Z&endDateTime=2022-11-01T10%3a12%3a02Z&$top=10&$skip=70": context deadline exceeded (Client.Timeout exceeded while awaiting headers)

Based on the presence of top and skip in the URL I see that the failed request is one of the subsequent paging requests. This job loops through the calendar view and previous 6 requests succeeded before the last request timed out, all in 37 seconds.

Do you have any ideas on what I can try to debug this further? It does look like the timeout is not applied or handled correctly by the SDK.

This is the code that is looping through the pages of the calendar view, ctx is context.Background():

	min := timeMin.Format(time.RFC3339)
	max := timeMax.Format(time.RFC3339)

	calParams := &mscalendarview.CalendarViewRequestBuilderGetQueryParameters{
		StartDateTime: &min,
		EndDateTime:   &max,
		Top:           top,
	}
	calConfig := &mscalendarview.CalendarViewRequestBuilderGetRequestConfiguration{
		Headers:         ImmutableIDHeader(),
		QueryParameters: calParams,
	}

	result, err := graph.Client.Me().Calendar().CalendarView().Get(ctx, calConfig)
	if err != nil {
		return nil, errors.Wrap(err, "failed to fetch calendar view")
	}

	msEvents := result.GetValue()
	nextLink := result.GetOdataNextLink()

	for {
		if nextLink == nil {
			break
		}

		request := mscalendarview.NewCalendarViewRequestBuilder(*nextLink, graph.Adapter)
		result, err = request.Get(ctx, nil)
		if err != nil {
			return nil, errors.Wrap(err, "failed to fetch calendar view page")
		}

		for _, e := range result.GetValue() {
			msEvents = append(msEvents, e)
		}

		nextLink = result.GetOdataNextLink()
	}

	return msEvents, nil

[baywet]

First, the sdk offers a page iterator which iterates across the pages for you so you don't have to implement it yourself.

Then, is it possible that the code is running on a box which can have intermittent network latency? this seems like the connection time out is being reached here.

[abezzub]

Thanks, I will update the code to use the iterator and I will add retries around the API calls.

When digging in the logs I found a similar looking error, but it says request canceled and not deadline exceeded:

Get "https://graph.microsoft.com/v1.0/me/calendar/calendarView?startDateTime=2022-10-18T10%3a12%3a09Z&endDateTime=2022-11-02T10%3a12%3a09Z&$top=10&$skip=10": net/http: request canceled (Client.Timeout exceeded while awaiting headers)

Do you think this is a different issue?

[baywet]

I'm not sure what's happening networking wise with this application. But it is possible that the http client cancels the requests when it's been waiting for the response for too long, so the server knows nobody is expecting an answer anymore and can free up resources.

[abezzub]

I switched the code to use page iterator and retry when timeout error happens, but now it is failing with fetching next page failed:
https://github.com/microsoftgraph/msgraph-sdk-go-core/blob/main/page_iterator.go#L155

It looks like page iterator does not return the original error, so I'll have to roll back the code to the previous version, where paging was done manually and it was possible to see the actual error that was happening. Is it possible to update the page iterator to include the original error?

[baywet]

@rkodev do you think it'd be possible to include the inner error here? https://github.com/microsoftgraph/msgraph-sdk-go-core/blob/f0ae2b652111c67dbeb0c400a975353dfb39c934/page_iterator.go#L155

[abezzub]

Regarding the original issue, I can confirm adding retries reduced the number of context deadline exceeded errors, so this is no longer an issue for me. Thanks for your help.