From cfc829275c2122e2a343953979bacb29c952c97f Mon Sep 17 00:00:00 2001 From: Daniel Nephin Date: Tue, 27 Jul 2021 17:06:59 -0400 Subject: [PATCH 1/3] http: don't log an error if the request is cancelled Now that we have at least one endpoint that uses context for cancellation we can encounter this scenario where the returned error is a context.Cancelled or context.DeadlineExceeded. If the request.Context().Err() is not nil, then we know the request itself was cancelled, so we can log a different message at Info level, instad of the error. --- agent/http.go | 20 ++++++++++++++------ 1 file changed, 14 insertions(+), 6 deletions(-) diff --git a/agent/http.go b/agent/http.go index 60195f2a5..409ecbda4 100644 --- a/agent/http.go +++ b/agent/http.go @@ -432,12 +432,20 @@ func (s *HTTPHandlers) wrap(handler endpoint, methods []string) http.HandlerFunc } handleErr := func(err error) { - httpLogger.Error("Request error", - "method", req.Method, - "url", logURL, - "from", req.RemoteAddr, - "error", err, - ) + if req.Context().Err() != nil { + httpLogger.Info("Request cancelled", + "method", req.Method, + "url", logURL, + "from", req.RemoteAddr, + "error", err) + } else { + httpLogger.Error("Request error", + "method", req.Method, + "url", logURL, + "from", req.RemoteAddr, + "error", err) + } + switch { case isForbidden(err): resp.WriteHeader(http.StatusForbidden) From 057e8320f9a8968a3d8481d3036f8a179e1beb4d Mon Sep 17 00:00:00 2001 From: Daniel Nephin Date: Tue, 27 Jul 2021 17:55:00 -0400 Subject: [PATCH 2/3] streaming: set a default timeout The blocking query backend sets the default value on the server side. The streaming backend does not using blocking queries, so we must set the timeout on the client. --- agent/agent.go | 1 + agent/config/runtime.go | 13 +++++++++++++ agent/rpcclient/health/health.go | 3 +++ agent/rpcclient/health/health_test.go | 28 +++++++++++++++++++++++++++ 4 files changed, 45 insertions(+) diff --git a/agent/agent.go b/agent/agent.go index ac81fb9a5..c13553629 100644 --- a/agent/agent.go +++ b/agent/agent.go @@ -395,6 +395,7 @@ func New(bd BaseDeps) (*Agent, error) { Logger: bd.Logger.Named("rpcclient.health"), }, UseStreamingBackend: a.config.UseStreamingBackend, + QueryOptionDefaults: config.ApplyDefaultQueryOptions(a.config), } a.serviceManager = NewServiceManager(&a) diff --git a/agent/config/runtime.go b/agent/config/runtime.go index 5a2857919..eae903737 100644 --- a/agent/config/runtime.go +++ b/agent/config/runtime.go @@ -1930,3 +1930,16 @@ func isFloat(t reflect.Type) bool { return t.Kind() == reflect.Float32 || t.Kind func isComplex(t reflect.Type) bool { return t.Kind() == reflect.Complex64 || t.Kind() == reflect.Complex128 } + +// ApplyDefaultQueryOptions returns a function which will set default values on +// the options based on the configuration. The RuntimeConfig must not be nil. +func ApplyDefaultQueryOptions(config *RuntimeConfig) func(options *structs.QueryOptions) { + return func(options *structs.QueryOptions) { + switch { + case options.MaxQueryTime > config.MaxQueryTime: + options.MaxQueryTime = config.MaxQueryTime + case options.MaxQueryTime == 0: + options.MaxQueryTime = config.DefaultQueryTime + } + } +} diff --git a/agent/rpcclient/health/health.go b/agent/rpcclient/health/health.go index 9d20f3caa..004101144 100644 --- a/agent/rpcclient/health/health.go +++ b/agent/rpcclient/health/health.go @@ -17,6 +17,7 @@ type Client struct { MaterializerDeps MaterializerDeps CacheName string UseStreamingBackend bool + QueryOptionDefaults func(options *structs.QueryOptions) } type NetRPC interface { @@ -38,6 +39,8 @@ func (c *Client) ServiceNodes( req structs.ServiceSpecificRequest, ) (structs.IndexedCheckServiceNodes, cache.ResultMeta, error) { if c.useStreaming(req) && (req.QueryOptions.UseCache || req.QueryOptions.MinQueryIndex > 0) { + c.QueryOptionDefaults(&req.QueryOptions) + result, err := c.ViewStore.Get(ctx, c.newServiceRequest(req)) if err != nil { return structs.IndexedCheckServiceNodes{}, cache.ResultMeta{}, err diff --git a/agent/rpcclient/health/health_test.go b/agent/rpcclient/health/health_test.go index 09da967bd..9ac67805f 100644 --- a/agent/rpcclient/health/health_test.go +++ b/agent/rpcclient/health/health_test.go @@ -3,10 +3,12 @@ package health import ( "context" "testing" + "time" "github.com/stretchr/testify/require" "github.com/hashicorp/consul/agent/cache" + "github.com/hashicorp/consul/agent/config" "github.com/hashicorp/consul/agent/structs" "github.com/hashicorp/consul/agent/submatview" ) @@ -25,6 +27,7 @@ func TestClient_ServiceNodes_BackendRouting(t *testing.T) { ViewStore: &fakeViewStore{}, CacheName: "cache-no-streaming", UseStreamingBackend: true, + QueryOptionDefaults: config.ApplyDefaultQueryOptions(&config.RuntimeConfig{}), } _, _, err := c.ServiceNodes(context.Background(), tc.req) @@ -233,3 +236,28 @@ func TestClient_Notify_BackendRouting(t *testing.T) { }) } } + +func TestClient_ServiceNodes_SetsDefaults(t *testing.T) { + store := &fakeViewStore{} + c := &Client{ + ViewStore: store, + CacheName: "cache-no-streaming", + UseStreamingBackend: true, + QueryOptionDefaults: config.ApplyDefaultQueryOptions(&config.RuntimeConfig{ + MaxQueryTime: 200 * time.Second, + DefaultQueryTime: 100 * time.Second, + }), + } + + req := structs.ServiceSpecificRequest{ + Datacenter: "dc1", + ServiceName: "web1", + QueryOptions: structs.QueryOptions{MinQueryIndex: 22}, + } + + _, _, err := c.ServiceNodes(context.Background(), req) + require.NoError(t, err) + + require.Len(t, store.calls, 1) + require.Equal(t, 100*time.Second, store.calls[0].CacheInfo().Timeout) +} From 2937f3165d1fffa1b33c1b782d35fc106a5d5a58 Mon Sep 17 00:00:00 2001 From: Daniel Nephin Date: Tue, 27 Jul 2021 17:58:23 -0400 Subject: [PATCH 3/3] add changelog --- .changelog/10707.txt | 6 ++++++ 1 file changed, 6 insertions(+) create mode 100644 .changelog/10707.txt diff --git a/.changelog/10707.txt b/.changelog/10707.txt new file mode 100644 index 000000000..ddb4dec62 --- /dev/null +++ b/.changelog/10707.txt @@ -0,0 +1,6 @@ +```release-note:bug +streaming: set the default wait timeout for health queries +``` +```release-note:bug +http: log cancelled requests as such at the INFO level, instead of logging them as errored requests. +```