From 275783b13542469140b739f0a5c03d1636217c8b 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 it 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 988dca7934d5..853b96230b6c 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 edd7c0530183..3428a730ce34 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 3d0948489ac8..d21ac145174c 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 7d5055ebe653..6bb79ea72bec 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 6757883a8a12..0def1cbd8b6b 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 eac54d7378f5..e8d5f8765ca8 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 {