Skip to content

Commit

Permalink
Reduce repetition & use log
Browse files Browse the repository at this point in the history 
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
  • Loading branch information
@DrJosh9000
DrJosh9000 committed May 27, 2024
1 parent 6cc1264 commit d78130f
Showing 1 changed file with 74 additions and 98 deletions.
172 changes: 74 additions & 98 deletions collector/collector.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -12,6 +12,7 @@ import (
"net/http/httputil"
"net/textproto"
"net/url"
"os"
"strconv"
"strings"
"time"
Expand All @@ -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
Expand Down Expand Up @@ -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 <redacted>")

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)
Expand All @@ -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)
}
}

Expand Down Expand Up @@ -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)
Expand All @@ -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)
}
}

Expand Down Expand Up @@ -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 <redacted>")

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
}

0 comments on commit d78130f

Please sign in to comment.