Skip to content

Commit

Permalink
Merge pull request #283 from CheeseStick/junjung/adding-more-logs
Browse files Browse the repository at this point in the history 
Adding more debug traces for HTTP and enhance security
  • Loading branch information
@DrJosh9000
DrJosh9000 authored May 27, 2024
2 parents e4f2827 + d78130f commit e89164f
Showing 1 changed file with 76 additions and 67 deletions.
143 changes: 76 additions & 67 deletions collector/collector.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -6,10 +6,13 @@ import (
"errors"
"fmt"
"log"
"maps"
"net/http"
"net/http/httptrace"
"net/http/httputil"
"net/textproto"
"net/url"
"os"
"strconv"
"strings"
"time"
Expand All @@ -28,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 @@ -144,37 +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{
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 @@ -189,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 @@ -288,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 @@ -333,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 @@ -400,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 e89164f

Please sign in to comment.