From d78130f5ee92693508d9ad8411335dd18ba7ea42 Mon Sep 17 00:00:00 2001 From: Josh Deprez Date: Mon, 27 May 2024 16:20:23 +1000 Subject: [PATCH] Reduce repetition & use log log.Print includes a timestamp by default, and debug logging is stderr-flavoured output. The only tweaks needed are to log with more precise timestamps --- collector/collector.go | 172 ++++++++++++++++++----------------------- 1 file changed, 74 insertions(+), 98 deletions(-) diff --git a/collector/collector.go b/collector/collector.go index a20307f..69bfc73 100644 --- a/collector/collector.go +++ b/collector/collector.go @@ -12,6 +12,7 @@ import ( "net/http/httputil" "net/textproto" "net/url" + "os" "strconv" "strings" "time" @@ -30,9 +31,9 @@ const ( PollDurationHeader = `Buildkite-Agent-Metrics-Poll-Duration` ) -var ( - ErrUnauthorized = errors.New("unauthorized") -) +var ErrUnauthorized = errors.New("unauthorized") + +var traceLog = log.New(os.Stderr, "TRACE", log.Ldate|log.Ltime|log.Lmicroseconds|log.Lshortfile|log.Lmsgprefix) type Collector struct { Endpoint string @@ -146,68 +147,7 @@ func (c *Collector) collectAllQueues(httpClient *http.Client, result *Result) er req.Header.Set("Authorization", fmt.Sprintf("Token %s", c.Token)) if c.DebugHttp { - trace := &httptrace.ClientTrace{ - GetConn: func(hostPort string) { - fmt.Printf("getting connection to %s: %v\n", hostPort, time.Now()) - }, - GotConn: func(info httptrace.GotConnInfo) { - fmt.Printf("got connection [reused?: %t, idle?: %t (time: %v)]: %v\n", - info.Reused, info.WasIdle, info.IdleTime, time.Now()) - }, - PutIdleConn: func(err error) { - if err != nil { - fmt.Printf("Failed to put connection idle with error - %v: %v\n", err, time.Now()) - return - } - fmt.Printf("connection successfully put idle: %v\n", time.Now()) - }, - GotFirstResponseByte: func() { - fmt.Printf("received first response byte: %v\n", time.Now()) - }, - Got1xxResponse: func(code int, header textproto.MIMEHeader) error { - fmt.Printf("received %d with header %v: %v\n", code, header, time.Now()) - return err - }, - DNSStart: func(_ httptrace.DNSStartInfo) { - fmt.Printf("dns start: %v\n", time.Now()) - }, - DNSDone: func(_ httptrace.DNSDoneInfo) { - fmt.Printf("dns done: %v\n", time.Now()) - }, - ConnectStart: func(_, _ string) { - fmt.Printf("connection start: %v\n", time.Now()) - }, - ConnectDone: func(_, _ string, _ error) { - fmt.Printf("connection done: %v\n", time.Now()) - }, - TLSHandshakeStart: func() { - fmt.Printf("TLS Handshake start: %v\n", time.Now()) - }, - TLSHandshakeDone: func(_ tls.ConnectionState, _ error) { - fmt.Printf("TLS Handshake done: %v\n", time.Now()) - }, - WroteHeaders: func() { - fmt.Printf("wrote headers: %v\n", time.Now()) - }, - WroteRequest: func(_ httptrace.WroteRequestInfo) { - fmt.Printf("wrote request: %v\n", time.Now()) - }, - } - - req = req.WithContext(httptrace.WithClientTrace(req.Context(), trace)) - - // Don't leak the token in the logs. Temporarily replace the Header - // with a clone in order to redact the token. - origHeader := req.Header - req.Header = maps.Clone(origHeader) - req.Header.Set("Authorization", "Token ") - - dump, err := httputil.DumpRequest(req, true) - if err != nil { - fmt.Printf("Couldn't dump request: %v\n", err) - } - fmt.Printf("DEBUG request uri=%s\n%s\n", req.URL, dump) - req.Header = origHeader + req = traceHTTPRequest(req) } res, err := httpClient.Do(req) @@ -222,7 +162,7 @@ func (c *Collector) collectAllQueues(httpClient *http.Client, result *Result) er if c.DebugHttp { if dump, err := httputil.DumpResponse(res, true); err == nil { - log.Printf("DEBUG response uri=%s\n%s\n", req.URL, dump) + traceLog.Printf("response uri=%s\n%s", req.URL, dump) } } @@ -321,37 +261,7 @@ func (c *Collector) collectQueue(httpClient *http.Client, result *Result, queue req.Header.Set("Authorization", fmt.Sprintf("Token %s", c.Token)) if c.DebugHttp { - trace := &httptrace.ClientTrace{ - DNSStart: func(_ httptrace.DNSStartInfo) { - fmt.Printf("dns start: %v\n", time.Now()) - }, - DNSDone: func(_ httptrace.DNSDoneInfo) { - fmt.Printf("dns done: %v\n", time.Now()) - }, - ConnectStart: func(_, _ string) { - fmt.Printf("connection start: %v\n", time.Now()) - }, - ConnectDone: func(_, _ string, _ error) { - fmt.Printf("connection done: %v\n", time.Now()) - }, - TLSHandshakeStart: func() { - fmt.Printf("TLS Handshake start: %v\n", time.Now()) - }, - TLSHandshakeDone: func(_ tls.ConnectionState, _ error) { - fmt.Printf("TLS Handshake done: %v\n", time.Now()) - }, - WroteHeaders: func() { - fmt.Printf("wrote headers: %v\n", time.Now()) - }, - WroteRequest: func(_ httptrace.WroteRequestInfo) { - fmt.Printf("wrote request: %v\n", time.Now()) - }, - } - - req = req.WithContext(httptrace.WithClientTrace(req.Context(), trace)) - if dump, err := httputil.DumpRequest(req, true); err == nil { - log.Printf("DEBUG request uri=%s\n%s\n", req.URL, dump) - } + req = traceHTTPRequest(req) } res, err := httpClient.Do(req) @@ -366,7 +276,7 @@ func (c *Collector) collectQueue(httpClient *http.Client, result *Result, queue if c.DebugHttp { if dump, err := httputil.DumpResponse(res, true); err == nil { - log.Printf("DEBUG response uri=%s\n%s\n", req.URL, dump) + traceLog.Printf("response uri=%s\n%s", req.URL, dump) } } @@ -433,3 +343,69 @@ func (r Result) Dump() { } } } + +func traceHTTPRequest(req *http.Request) *http.Request { + trace := &httptrace.ClientTrace{ + GetConn: func(hostPort string) { + traceLog.Printf("getting connection to %s\n", hostPort) + }, + GotConn: func(info httptrace.GotConnInfo) { + traceLog.Printf("got connection [reused?: %t, idle?: %t (time: %v)]", info.Reused, info.WasIdle, info.IdleTime) + }, + PutIdleConn: func(err error) { + if err != nil { + traceLog.Printf("Failed to put connection idle with error - %v", err) + return + } + traceLog.Printf("connection successfully put idle") + }, + GotFirstResponseByte: func() { + traceLog.Printf("received first response byte") + }, + Got1xxResponse: func(code int, header textproto.MIMEHeader) error { + traceLog.Printf("received %d with header %v", code, header) + return nil + }, + DNSStart: func(_ httptrace.DNSStartInfo) { + traceLog.Print("dns start") + }, + DNSDone: func(_ httptrace.DNSDoneInfo) { + traceLog.Print("dns done") + }, + ConnectStart: func(_, _ string) { + traceLog.Print("connection start") + }, + ConnectDone: func(_, _ string, _ error) { + traceLog.Print("connection done") + }, + TLSHandshakeStart: func() { + traceLog.Print("TLS Handshake start") + }, + TLSHandshakeDone: func(_ tls.ConnectionState, _ error) { + traceLog.Print("TLS Handshake done") + }, + WroteHeaders: func() { + traceLog.Print("wrote headers") + }, + WroteRequest: func(_ httptrace.WroteRequestInfo) { + traceLog.Print("wrote request") + }, + } + + req = req.WithContext(httptrace.WithClientTrace(req.Context(), trace)) + + // Don't leak the token in the logs. Temporarily replace the Header + // with a clone in order to redact the token. + origHeader := req.Header + defer func() { req.Header = origHeader }() + req.Header = maps.Clone(origHeader) + req.Header.Set("Authorization", "Token ") + + dump, err := httputil.DumpRequest(req, true) + if err != nil { + traceLog.Printf("Couldn't dump request: %v", err) + return req + } + traceLog.Printf("request uri=%s\n%s", req.URL, dump) + return req +}