From 9c6710361de8b9c5f5d58bba444516fd8fe7af15 Mon Sep 17 00:00:00 2001 From: Dan Kortschak Date: Wed, 27 Mar 2024 07:10:55 +1030 Subject: [PATCH] x-pack/filebeat/input/{cel,httpjson,http_endpoint,internal/httplog}: add debugging bread crumbs When debugging issues in cel and httpjson the request trace log facility can be very useful, but the separated nature of the log can add friction since the only tie between the agent logs and the request trace logs is the time stamp. This adds an additional log message to the agent logs at DEBUG that marks the creation of a request transaction, noting the transaction ID into the agent logs. A similar addition is made to http_endpoint. --- CHANGELOG.next.asciidoc | 1 + x-pack/filebeat/input/cel/input.go | 2 +- .../filebeat/input/http_endpoint/handler.go | 25 +++++++++++++++---- x-pack/filebeat/input/http_endpoint/input.go | 15 ++++++++++- x-pack/filebeat/input/httpjson/input.go | 2 +- .../input/internal/httplog/roundtripper.go | 17 ++++++++----- 6 files changed, 48 insertions(+), 14 deletions(-) diff --git a/CHANGELOG.next.asciidoc b/CHANGELOG.next.asciidoc index 988dca7934d..853b96230b6 100644 --- a/CHANGELOG.next.asciidoc +++ b/CHANGELOG.next.asciidoc @@ -184,6 +184,7 @@ Setting environmental variable ELASTIC_NETINFO:false in Elastic Agent pod will d - Parse more fields from Elasticsearch slowlogs {pull}38295[38295] - Update CEL mito extensions to v1.10.0 to add keys/values helper. {pull}38504[38504] - Add support for Active Directory an entity analytics provider. {pull}37919[37919] +- Add debugging breadcrumb to logs when writing request trace log. {pull}38636[38636] *Auditbeat* diff --git a/x-pack/filebeat/input/cel/input.go b/x-pack/filebeat/input/cel/input.go index edd7c053018..3428a730ce3 100644 --- a/x-pack/filebeat/input/cel/input.go +++ b/x-pack/filebeat/input/cel/input.go @@ -725,7 +725,7 @@ func newClient(ctx context.Context, cfg config, log *logp.Logger) (*http.Client, const margin = 1e3 // 1OkB ought to be enough room for all the remainder of the trace details. maxSize := cfg.Resource.Tracer.MaxSize * 1e6 - trace = httplog.NewLoggingRoundTripper(c.Transport, traceLogger, max(0, maxSize-margin)) + trace = httplog.NewLoggingRoundTripper(c.Transport, traceLogger, max(0, maxSize-margin), log) c.Transport = trace } diff --git a/x-pack/filebeat/input/http_endpoint/handler.go b/x-pack/filebeat/input/http_endpoint/handler.go index 3d0948489ac..d21ac145174 100644 --- a/x-pack/filebeat/input/http_endpoint/handler.go +++ b/x-pack/filebeat/input/http_endpoint/handler.go @@ -13,12 +13,14 @@ import ( "net" "net/http" "reflect" + "strconv" "time" "github.com/google/cel-go/cel" "github.com/google/cel-go/checker/decls" "github.com/google/cel-go/common/types" "github.com/google/cel-go/common/types/ref" + "go.uber.org/atomic" "go.uber.org/zap" "go.uber.org/zap/zapcore" "google.golang.org/protobuf/types/known/structpb" @@ -42,10 +44,12 @@ var ( ) type handler struct { - metrics *inputMetrics - publisher stateless.Publisher - log *logp.Logger - validator apiValidator + metrics *inputMetrics + publisher stateless.Publisher + log *logp.Logger + validator apiValidator + txBaseID string // Random value to make transaction IDs unique. + txIDCounter *atomic.Uint64 // Transaction ID counter that is incremented for each request. reqLogger *zap.Logger host, scheme string @@ -185,9 +189,11 @@ func (h *handler) logRequest(r *http.Request, status int, respBody []byte) { zap.ByteString("http.response.body.content", respBody), ) } + txID := h.nextTxID() + h.log.Debugw("new request trace transaction", "id", txID) // Limit request logging body size to 10kiB. const maxBodyLen = 10 * (1 << 10) - httplog.LogRequest(h.reqLogger, r, maxBodyLen, extra...) + httplog.LogRequest(h.reqLogger.With(zap.String("transaction.id", txID)), r, maxBodyLen, extra...) if scheme != "" { r.URL.Scheme = scheme } @@ -196,6 +202,15 @@ func (h *handler) logRequest(r *http.Request, status int, respBody []byte) { } } +func (h *handler) nextTxID() string { + count := h.txIDCounter.Inc() + return h.formatTxID(count) +} + +func (h *handler) formatTxID(count uint64) string { + return h.txBaseID + "-" + strconv.FormatUint(count, 10) +} + func (h *handler) sendResponse(w http.ResponseWriter, status int, message string) { w.Header().Add("Content-Type", "application/json") w.WriteHeader(status) diff --git a/x-pack/filebeat/input/http_endpoint/input.go b/x-pack/filebeat/input/http_endpoint/input.go index 7d5055ebe65..6bb79ea72be 100644 --- a/x-pack/filebeat/input/http_endpoint/input.go +++ b/x-pack/filebeat/input/http_endpoint/input.go @@ -7,6 +7,8 @@ package http_endpoint import ( "context" "crypto/tls" + "encoding/base32" + "encoding/binary" "errors" "fmt" "net" @@ -18,6 +20,7 @@ import ( "github.com/rcrowley/go-metrics" "go.elastic.co/ecszap" + "go.uber.org/atomic" "go.uber.org/zap" "go.uber.org/zap/zapcore" @@ -297,7 +300,10 @@ func (s *server) getErr() error { func newHandler(ctx context.Context, c config, prg *program, pub stateless.Publisher, log *logp.Logger, metrics *inputMetrics) http.Handler { h := &handler{ - log: log, + log: log, + txBaseID: newID(), + txIDCounter: atomic.NewUint64(0), + publisher: pub, metrics: metrics, validator: apiValidator{ @@ -344,6 +350,13 @@ func newHandler(ctx context.Context, c config, prg *program, pub stateless.Publi return h } +// newID returns an ID derived from the current time. +func newID() string { + var data [8]byte + binary.LittleEndian.PutUint64(data[:], uint64(time.Now().UnixNano())) + return base32.HexEncoding.WithPadding(base32.NoPadding).EncodeToString(data[:]) +} + // inputMetrics handles the input's metric reporting. type inputMetrics struct { unregister func() diff --git a/x-pack/filebeat/input/httpjson/input.go b/x-pack/filebeat/input/httpjson/input.go index 6757883a8a1..0def1cbd8b6 100644 --- a/x-pack/filebeat/input/httpjson/input.go +++ b/x-pack/filebeat/input/httpjson/input.go @@ -264,7 +264,7 @@ func newNetHTTPClient(ctx context.Context, cfg *requestConfig, log *logp.Logger, if maxSize < 0 { maxSize = 0 } - netHTTPClient.Transport = httplog.NewLoggingRoundTripper(netHTTPClient.Transport, traceLogger, maxSize) + netHTTPClient.Transport = httplog.NewLoggingRoundTripper(netHTTPClient.Transport, traceLogger, maxSize, log) } if reg != nil { diff --git a/x-pack/filebeat/input/internal/httplog/roundtripper.go b/x-pack/filebeat/input/internal/httplog/roundtripper.go index eac54d7378f..e8d5f8765ca 100644 --- a/x-pack/filebeat/input/internal/httplog/roundtripper.go +++ b/x-pack/filebeat/input/internal/httplog/roundtripper.go @@ -17,6 +17,7 @@ import ( "strconv" "time" + "github.com/elastic/elastic-agent-libs/logp" "go.uber.org/atomic" "go.uber.org/zap" "go.uber.org/zap/zapcore" @@ -31,14 +32,15 @@ const TraceIDKey = contextKey("trace.id") type contextKey string // NewLoggingRoundTripper returns a LoggingRoundTripper that logs requests and -// responses to the provided logger. -func NewLoggingRoundTripper(next http.RoundTripper, logger *zap.Logger, maxBodyLen int) *LoggingRoundTripper { +// responses to the provided logger. Transaction creation is logged to log. +func NewLoggingRoundTripper(next http.RoundTripper, logger *zap.Logger, maxBodyLen int, log *logp.Logger) *LoggingRoundTripper { return &LoggingRoundTripper{ transport: next, maxBodyLen: maxBodyLen, - logger: logger, + txLog: logger, txBaseID: newID(), txIDCounter: atomic.NewUint64(0), + log: log, } } @@ -46,9 +48,10 @@ func NewLoggingRoundTripper(next http.RoundTripper, logger *zap.Logger, maxBodyL type LoggingRoundTripper struct { transport http.RoundTripper maxBodyLen int // The maximum length of a body. Longer bodies will be truncated. - logger *zap.Logger // Destination logger. + txLog *zap.Logger // Destination logger. txBaseID string // Random value to make transaction IDs unique. txIDCounter *atomic.Uint64 // Transaction ID counter that is incremented for each request. + log *logp.Logger } // RoundTrip implements the http.RoundTripper interface, logging @@ -80,8 +83,10 @@ type LoggingRoundTripper struct { // event.original (the response without body from httputil.DumpResponse) func (rt *LoggingRoundTripper) RoundTrip(req *http.Request) (*http.Response, error) { // Create a child logger for this request. - log := rt.logger.With( - zap.String("transaction.id", rt.nextTxID()), + txID := rt.nextTxID() + rt.log.Debugw("new request trace transaction", "id", txID) + log := rt.txLog.With( + zap.String("transaction.id", txID), ) if v := req.Context().Value(TraceIDKey); v != nil {