x-pack/filebeat/input/{cel,httpjson,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.

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*
 

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
 	}
 

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 {

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,24 +32,26 @@ 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,
 	}
 }
 
 // LoggingRoundTripper is an http.RoundTripper that logs requests and responses.
 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 {