[Q] Timeouts for non-existent wildcard requests with carbonapi, go-carbon and carbonapi_v3_pb

[easterhanu]

Using carbonapi v0.16.0~1, go-carbon v0.16.2 and carbonapi_v3_pb protocol between carbonapi and go-carbon's carbonserver.

If Grafana makes a wildcard request for a non-existent metric such as service.foobar.*.nosuchmetric, and go-carbon does not yet have the result in cache, go-carbon responds with an HTTP 200 and a null result set:

[2023-01-12T17:48:43.440+0200] DEBUG [carbonserver] find cache miss {"handler": "find", "url": "/metrics/find/?format=carbonapi_v3_pb", "peer": "10.0.22.18:42282", "carbonapi_uuid": "0cd207e2-3665-45df-be7b-b8b91a9ac798", "carbonzipper_uuid": "0cd207e2-3665-45df-be7b-b8b91a9ac798", "query": ["service.foobar.*.nosuchmetric"], "format": "carbonapi_v3_pb"}
[2023-01-12T17:48:43.440+0200] DEBUG [carbonserver] expandGlobs result {"handler": "find", "url": "/metrics/find/?format=carbonapi_v3_pb", "peer": "10.0.22.18:42282", "carbonapi_uuid": "0cd207e2-3665-45df-be7b-b8b91a9ac798", "carbonzipper_uuid": "0cd207e2-3665-45df-be7b-b8b91a9ac798", "query": ["service.foobar.*.nosuchmetric"], "format": "carbonapi_v3_pb", "action": "expandGlobs", "metrics": ["service.foobar.*.nosuchmetric"], "result": [{"Name":"service.foobar.*.nosuchmetric","Files":null,"Leafs":null}]}
[2023-01-12T17:48:43.441+0200] DEBUG [carbonserver] will send out response {"handler": "find", "url": "/metrics/find/?format=carbonapi_v3_pb", "peer": "10.0.22.18:42282", "carbonapi_uuid": "0cd207e2-3665-45df-be7b-b8b91a9ac798", "carbonzipper_uuid": "0cd207e2-3665-45df-be7b-b8b91a9ac798", "query": ["service.foobar.*.nosuchmetric"], "format": "carbonapi_v3_pb", "response": {"metrics":[{"name":"service.foobar.*.nosuchmetric","matches":[]}]}}
[2023-01-12T17:48:43.441+0200] INFO [access] find success {"handler": "find", "url": "/metrics/find/?format=carbonapi_v3_pb", "peer": "10.0.22.18:42282", "carbonapi_uuid": "0cd207e2-3665-45df-be7b-b8b91a9ac798", "carbonzipper_uuid": "0cd207e2-3665-45df-be7b-b8b91a9ac798", "query": ["service.foobar.*.nosuchmetric"], "format": "carbonapi_v3_pb", "runtime_seconds": 0.00120234, "Files": 0, "find_cache_enabled": true, "from_cache": false, "http_code": 200}

Carbonapi's zipper receives the null result, but does not pass it on - instead, carbonapi waits until it times out (30 secs in the example) and returns an HTTP 502 to Grafana:

2023-01-12T17:48:43.443+0200	DEBUG	zipper	got some find responses	{"type": "broadcastGroup", "groupName": "go-carbon_group_1", "type": "find", "request": ["service.foobar.*.nosuchmetric"], "backends_count": 2, "response_count": 2, "have_errors": false, "errors": null, "response": "&MultiGlobResponse{Metrics:[]GlobResponse{GlobResponse{Name:service.foobar.*.nosuchmetric,Matches:[]GlobMatch{},},},}"}
2023-01-12T17:49:13.433+0200	DEBUG	zipper	errors while fetching data from backends	{"type": "broadcastGroup", "groupName": "root", "type": "fetch", "request": ["service.foobar.*.nosuchmetric"], "carbonapi_uuid": "0cd207e2-3665-45df-be7b-b8b91a9ac798", "httpCode": 503, "errors": ["timeout while fetching Response"]}
2023-01-12T17:49:13.433+0200	DEBUG	zipper	had errors while fetching result	{"function": "FetchProtoV3", "carbonapi_uuid": "0cd207e2-3665-45df-be7b-b8b91a9ac798", "errors": "timeout while fetching Response", "errorsVerbose": "timeout while fetching Response\nHTTP Code: 503\n\ngithub.com/go-graphite/carbonapi/zipper/types.init\n\t/root/go/src/github.com/go-graphite/carbonapi/zipper/types/errors.go:27\nruntime.doInit\n\t/usr/local/go/src/runtime/proc.go:6321\nruntime.doInit\n\t/usr/local/go/src/runtime/proc.go:6298\nruntime.doInit\n\t/usr/local/go/src/runtime/proc.go:6298\nruntime.doInit\n\t/usr/local/go/src/runtime/proc.go:6298\nruntime.main\n\t/usr/local/go/src/runtime/proc.go:233\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1594", "httpCode": 503}
2023-01-12T17:49:13.434+0200	DEBUG	zipper	no metrics fetched	{"function": "FetchProtoV3", "carbonapi_uuid": "0cd207e2-3665-45df-be7b-b8b91a9ac798", "errors": "timeout while fetching Response", "errorsVerbose": "timeout while fetching Response\nHTTP Code: 503\n\ngithub.com/go-graphite/carbonapi/zipper/types.init\n\t/root/go/src/github.com/go-graphite/carbonapi/zipper/types/errors.go:27\nruntime.doInit\n\t/usr/local/go/src/runtime/proc.go:6321\nruntime.doInit\n\t/usr/local/go/src/runtime/proc.go:6298\nruntime.doInit\n\t/usr/local/go/src/runtime/proc.go:6298\nruntime.doInit\n\t/usr/local/go/src/runtime/proc.go:6298\nruntime.main\n\t/usr/local/go/src/runtime/proc.go:233\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1594"}
2023-01-12T17:49:13.434+0200	DEBUG	render	error response or no response	{"carbonapi_uuid": "0cd207e2-3665-45df-be7b-b8b91a9ac798", "username": "", "request_headers": {"X-Panel-Id":"2"}, "error": ["timeout while fetching Response"]}
2023-01-12T17:49:13.435+0200	ERROR	access	request failed	{"data": {"handler":"render","carbonapi_uuid":"0cd207e2-3665-45df-be7b-b8b91a9ac798","url":"/render","peer_ip":"193.166.1.218","host":"127.0.0.1:8080","format":"json","use_cache":true,"targets":["service.foobar.*.nosuchmetric"],"cache_timeout":60,"runtime":30.004379443,"http_code":503,"reason":"timeout while fetching Response","from":1673516880,"until":1673538480,"from_raw":"-6h","until_raw":"now","uri":"/render","from_cache":false,"used_backend_cache":false,"request_headers":{"X-Panel-Id":"2"}}}

Once the request has timed out, if I refresh the panel in Grafana, and go-carbon now has the data in query cache, go-carbon responds with an HTTP 404 instead:

[2023-01-12T17:56:00.968+0200] DEBUG [carbonserver] query cache hit {"handler": "find", "url": "/metrics/find/?format=carbonapi_v3_pb", "peer": "10.0.22.18:57926", "carbonapi_uuid": "5430711c-8814-4209-9990-2d40d520953a", "carbonzipper_uuid": "5430711c-8814-4209-9990-2d40d520953a", "query": ["service.foobar.*.nosuchmetric"], "format": "carbonapi_v3_pb"}
[2023-01-12T17:56:00.968+0200] ERROR [access] find failed {"handler": "find", "url": "/metrics/find/?format=carbonapi_v3_pb", "peer": "10.0.22.18:57926", "carbonapi_uuid": "5430711c-8814-4209-9990-2d40d520953a", "carbonzipper_uuid": "5430711c-8814-4209-9990-2d40d520953a", "query": ["service.foobar.*.nosuchmetric"], "format": "carbonapi_v3_pb", "runtime_seconds": 0.000722059, "reason": "Not Found", "error": "Not Found", "http_code": 404}

This is something carbonapi understands, and it immediately responds with an HTTP 200 to Grafana, which is the desired behavior.

If I switch to the older carbonapi_v2_pb protocol, I get no timeouts with non-existent wildcards, as go-carbon always responds with an HTTP 404, whether it had the result in cache or not.

Is the HTTP 200 null result response with go-carbon and carbonapi_v3_pb intended behavior, a configuration issue or a bug?

[deniszh]

Yes, looks like a bug. 404 response should be consistent.