Log ES queries

[albertteoh]

Requirement - what kind of business use case are you trying to solve?

Lack of visibility into Elasticsearch queries executed by readers.

See: #2816 (comment)

Proposal - what do you suggest to solve the problem or improve the existing situation?

Add a package-level helper function that can be used when logging service, operation and span queries:

func logQuery(logger *zap.Logger, query *elastic.SearchSource) {
	// Ignore errors since we're only debug logging and should not prevent queries from being executed.
	qMap, _ := query.Source()
	qJson, _ := json.Marshal(qMap)
	logger.Debug("Querying elasticsearch", zap.String("query", string(qJson)))
}

Any open questions to address

Logging queries requires the ability to build the query beforehand and, ideally, reuse this same query object to execute against Elasticsearch.

Unfortunately, for service and operation queries, existing code uses SearchService which does not provide a means to set a query source for execution, leading to duplicating the query object, unlike span searches which use MultiSearch() that allows setting the query source in its individual search requests.

[dekimsey]

FWIW, the logging configuration itself is not being set on es.client, so log levels being set by jaeger don't affect the es client library. It would be helpful if those logging messages were populated when addressing ES issues.

I ran into this when my ES was throwing access errors. All that's currently logged is (in effect):

message: HTTP handler, Internal Server Error
error: elastic: Error 403 (Forbidden)
stacktrace:
github.com/jaegertracing/jaeger/cmd/query/app.(*APIHandler).handleError
	github.com/jaegertracing/jaeger/cmd/query/app/http_handler.go:435
github.com/jaegertracing/jaeger/cmd/query/app.(*APIHandler).search
	github.com/jaegertracing/jaeger/cmd/query/app/http_handler.go:223
net/http.HandlerFunc.ServeHTTP
	net/http/server.go:2012
github.com/opentracing-contrib/go-stdlib/nethttp.MiddlewareFunc.func5
	github.com/opentracing-contrib/[email protected]/nethttp/server.go:140
net/http.HandlerFunc.ServeHTTP
	net/http/server.go:2012
net/http.HandlerFunc.ServeHTTP
	net/http/server.go:2012
github.com/gorilla/mux.(*Router).ServeHTTP
	github.com/gorilla/[email protected]/mux.go:210
github.com/jaegertracing/jaeger/cmd/query/app.additionalHeadersHandler.func1
	github.com/jaegertracing/jaeger/cmd/query/app/additional_headers_handler.go:28
net/http.HandlerFunc.ServeHTTP
	net/http/server.go:2012
github.com/gorilla/handlers.CompressHandlerLevel.func1
	github.com/gorilla/[email protected]/compress.go:148
net/http.HandlerFunc.ServeHTTP
	net/http/server.go:2012
github.com/gorilla/handlers.recoveryHandler.ServeHTTP
	github.com/gorilla/[email protected]/recovery.go:78
net/http.serverHandler.ServeHTTP
	net/http/server.go:2807
net/http.(*conn).serve
	net/http/server.go:1895

Looks like the client exposes a number of helpers that could set these values client.SetErrorLog. With SetInfoLog and SetTraceLog knobs as well.

[albertteoh]

Nice! Thanks for the tip @dekimsey, I think this is better than the initial proposal. I just tried out setting trace level logs and could see the query logged out, along with the results. I'll have a go at putting together a PR based on your suggestion.