package main import ( "bytes" "context" "crypto/tls" "fmt" "io" "io/ioutil" "net/http/httptrace" "strings" "time" "github.com/aws/aws-sdk-go/aws/request" ) // RequestLatency provides latencies for the SDK API request and its attempts. type RequestLatency struct { Latency time.Duration Validate time.Duration Build time.Duration Attempts []RequestAttemptLatency } // RequestAttemptLatency provides latencies for an individual request attempt. type RequestAttemptLatency struct { Latency time.Duration Err error Sign time.Duration Send time.Duration HTTP HTTPLatency Unmarshal time.Duration UnmarshalError time.Duration WillRetry bool Retry time.Duration } // HTTPLatency provides latencies for an HTTP request. type HTTPLatency struct { Latency time.Duration ConnReused bool GetConn time.Duration DNS time.Duration Connect time.Duration TLS time.Duration WriteHeader time.Duration WriteRequest time.Duration WaitResponseFirstByte time.Duration ReadHeader time.Duration ReadBody time.Duration } // RequestTrace provides the structure to store SDK request attempt latencies. // Use TraceRequest as a API operation request option to capture trace metrics // for the individual request. type RequestTrace struct { Start, Finish time.Time ValidateStart, ValidateDone time.Time BuildStart, BuildDone time.Time ReadResponseBody bool Attempts []*RequestAttemptTrace } // Latency returns the latencies of the request trace components. func (t RequestTrace) Latency() RequestLatency { var attempts []RequestAttemptLatency for _, a := range t.Attempts { attempts = append(attempts, a.Latency()) } latency := RequestLatency{ Latency: safeTimeDelta(t.Start, t.Finish), Validate: safeTimeDelta(t.ValidateStart, t.ValidateDone), Build: safeTimeDelta(t.BuildStart, t.BuildDone), Attempts: attempts, } return latency } // TraceRequest is a SDK request Option that will add request handlers to an // individual request to track request latencies per attempt. Must be used only // for a single request call per RequestTrace value. func (t *RequestTrace) TraceRequest(r *request.Request) { t.Start = time.Now() r.Handlers.Complete.PushBack(t.onComplete) r.Handlers.Validate.PushFront(t.onValidateStart) r.Handlers.Validate.PushBack(t.onValidateDone) r.Handlers.Build.PushFront(t.onBuildStart) r.Handlers.Build.PushBack(t.onBuildDone) var attempt *RequestAttemptTrace // Signing and Start attempt r.Handlers.Sign.PushFront(func(rr *request.Request) { attempt = &RequestAttemptTrace{Start: time.Now()} attempt.SignStart = attempt.Start }) r.Handlers.Sign.PushBack(func(rr *request.Request) { attempt.SignDone = time.Now() }) // Ensure that the http trace added to the request always uses the original // context instead of each following attempt's context to prevent conflict // with previous http traces used. origContext := r.Context() // Send r.Handlers.Send.PushFront(func(rr *request.Request) { attempt.SendStart = time.Now() attempt.HTTPTrace = NewHTTPTrace(origContext) rr.SetContext(attempt.HTTPTrace) }) r.Handlers.Send.PushBack(func(rr *request.Request) { attempt.SendDone = time.Now() defer func() { attempt.HTTPTrace.Finish = time.Now() }() if rr.Error != nil { return } attempt.HTTPTrace.ReadHeaderDone = time.Now() if t.ReadResponseBody { attempt.HTTPTrace.ReadBodyStart = time.Now() var w bytes.Buffer if _, err := io.Copy(&w, rr.HTTPResponse.Body); err != nil { rr.Error = err return } rr.HTTPResponse.Body.Close() rr.HTTPResponse.Body = ioutil.NopCloser(&w) attempt.HTTPTrace.ReadBodyDone = time.Now() } }) // Unmarshal r.Handlers.Unmarshal.PushFront(func(rr *request.Request) { attempt.UnmarshalStart = time.Now() }) r.Handlers.Unmarshal.PushBack(func(rr *request.Request) { attempt.UnmarshalDone = time.Now() }) // Unmarshal Error r.Handlers.UnmarshalError.PushFront(func(rr *request.Request) { attempt.UnmarshalErrorStart = time.Now() }) r.Handlers.UnmarshalError.PushBack(func(rr *request.Request) { attempt.UnmarshalErrorDone = time.Now() }) // Retry handling and delay r.Handlers.Retry.PushFront(func(rr *request.Request) { attempt.RetryStart = time.Now() attempt.Err = rr.Error }) r.Handlers.AfterRetry.PushBack(func(rr *request.Request) { attempt.RetryDone = time.Now() attempt.WillRetry = rr.WillRetry() }) // Complete Attempt r.Handlers.CompleteAttempt.PushBack(func(rr *request.Request) { attempt.Finish = time.Now() t.Attempts = append(t.Attempts, attempt) }) } func (t *RequestTrace) String() string { var w strings.Builder l := t.Latency() writeDurField(&w, "Latency", l.Latency) writeDurField(&w, "Validate", l.Validate) writeDurField(&w, "Build", l.Build) writeField(&w, "Attempts", "%d", len(t.Attempts)) for i, a := range t.Attempts { fmt.Fprintf(&w, "\n\tAttempt: %d, %s", i, a) } return w.String() } func (t *RequestTrace) onComplete(*request.Request) { t.Finish = time.Now() } func (t *RequestTrace) onValidateStart(*request.Request) { t.ValidateStart = time.Now() } func (t *RequestTrace) onValidateDone(*request.Request) { t.ValidateDone = time.Now() } func (t *RequestTrace) onBuildStart(*request.Request) { t.BuildStart = time.Now() } func (t *RequestTrace) onBuildDone(*request.Request) { t.BuildDone = time.Now() } // RequestAttemptTrace provides a structure for storing trace information on // the SDK's request attempt. type RequestAttemptTrace struct { Start, Finish time.Time Err error SignStart, SignDone time.Time SendStart, SendDone time.Time HTTPTrace *HTTPTrace UnmarshalStart, UnmarshalDone time.Time UnmarshalErrorStart, UnmarshalErrorDone time.Time WillRetry bool RetryStart, RetryDone time.Time } // Latency returns the latencies of the request attempt trace components. func (t *RequestAttemptTrace) Latency() RequestAttemptLatency { return RequestAttemptLatency{ Latency: safeTimeDelta(t.Start, t.Finish), Err: t.Err, Sign: safeTimeDelta(t.SignStart, t.SignDone), Send: safeTimeDelta(t.SendStart, t.SendDone), HTTP: t.HTTPTrace.Latency(), Unmarshal: safeTimeDelta(t.UnmarshalStart, t.UnmarshalDone), UnmarshalError: safeTimeDelta(t.UnmarshalErrorStart, t.UnmarshalErrorDone), WillRetry: t.WillRetry, Retry: safeTimeDelta(t.RetryStart, t.RetryDone), } } func (t *RequestAttemptTrace) String() string { var w strings.Builder l := t.Latency() writeDurField(&w, "Latency", l.Latency) writeDurField(&w, "Sign", l.Sign) writeDurField(&w, "Send", l.Send) writeDurField(&w, "Unmarshal", l.Unmarshal) writeDurField(&w, "UnmarshalError", l.UnmarshalError) writeField(&w, "WillRetry", "%t", l.WillRetry) writeDurField(&w, "Retry", l.Retry) fmt.Fprintf(&w, "\n\t\tHTTP: %s", t.HTTPTrace) if t.Err != nil { fmt.Fprintf(&w, "\n\t\tError: %v", t.Err) } return w.String() } // HTTPTrace provides the trace time stamps of the HTTP request's segments. type HTTPTrace struct { context.Context Start, Finish time.Time GetConnStart, GetConnDone time.Time Reused bool DNSStart, DNSDone time.Time ConnectStart, ConnectDone time.Time TLSHandshakeStart, TLSHandshakeDone time.Time WriteHeaderDone time.Time WriteRequestDone time.Time FirstResponseByte time.Time ReadHeaderStart, ReadHeaderDone time.Time ReadBodyStart, ReadBodyDone time.Time } // NewHTTPTrace returns a initialized HTTPTrace for an // httptrace.ClientTrace, based on the context passed. func NewHTTPTrace(ctx context.Context) *HTTPTrace { t := &HTTPTrace{ Start: time.Now(), } trace := &httptrace.ClientTrace{ GetConn: t.getConn, GotConn: t.gotConn, PutIdleConn: t.putIdleConn, GotFirstResponseByte: t.gotFirstResponseByte, Got100Continue: t.got100Continue, DNSStart: t.dnsStart, DNSDone: t.dnsDone, ConnectStart: t.connectStart, ConnectDone: t.connectDone, TLSHandshakeStart: t.tlsHandshakeStart, TLSHandshakeDone: t.tlsHandshakeDone, WroteHeaders: t.wroteHeaders, Wait100Continue: t.wait100Continue, WroteRequest: t.wroteRequest, } t.Context = httptrace.WithClientTrace(ctx, trace) return t } // Latency returns the latencies for an HTTP request. func (t *HTTPTrace) Latency() HTTPLatency { latency := HTTPLatency{ Latency: safeTimeDelta(t.Start, t.Finish), ConnReused: t.Reused, WriteHeader: safeTimeDelta(t.GetConnDone, t.WriteHeaderDone), WriteRequest: safeTimeDelta(t.GetConnDone, t.WriteRequestDone), WaitResponseFirstByte: safeTimeDelta(t.WriteRequestDone, t.FirstResponseByte), ReadHeader: safeTimeDelta(t.ReadHeaderStart, t.ReadHeaderDone), ReadBody: safeTimeDelta(t.ReadBodyStart, t.ReadBodyDone), } if !t.Reused { latency.GetConn = safeTimeDelta(t.GetConnStart, t.GetConnDone) latency.DNS = safeTimeDelta(t.DNSStart, t.DNSDone) latency.Connect = safeTimeDelta(t.ConnectStart, t.ConnectDone) latency.TLS = safeTimeDelta(t.TLSHandshakeStart, t.TLSHandshakeDone) } else { latency.GetConn = safeTimeDelta(t.Start, t.GetConnDone) } return latency } func (t *HTTPTrace) String() string { var w strings.Builder l := t.Latency() writeDurField(&w, "Latency", l.Latency) writeField(&w, "ConnReused", "%t", l.ConnReused) writeDurField(&w, "GetConn", l.GetConn) writeDurField(&w, "WriteHeader", l.WriteHeader) writeDurField(&w, "WriteRequest", l.WriteRequest) writeDurField(&w, "WaitResponseFirstByte", l.WaitResponseFirstByte) writeDurField(&w, "ReadHeader", l.ReadHeader) writeDurField(&w, "ReadBody", l.ReadBody) if !t.Reused { fmt.Fprintf(&w, "\n\t\t\tConn: ") writeDurField(&w, "DNS", l.DNS) writeDurField(&w, "Connect", l.Connect) writeDurField(&w, "TLS", l.TLS) } return w.String() } func (t *HTTPTrace) getConn(hostPort string) { t.GetConnStart = time.Now() } func (t *HTTPTrace) gotConn(info httptrace.GotConnInfo) { t.GetConnDone = time.Now() t.Reused = info.Reused } func (t *HTTPTrace) putIdleConn(err error) {} func (t *HTTPTrace) gotFirstResponseByte() { t.FirstResponseByte = time.Now() t.ReadHeaderStart = t.FirstResponseByte } func (t *HTTPTrace) got100Continue() {} func (t *HTTPTrace) dnsStart(info httptrace.DNSStartInfo) { t.DNSStart = time.Now() } func (t *HTTPTrace) dnsDone(info httptrace.DNSDoneInfo) { t.DNSDone = time.Now() } func (t *HTTPTrace) connectStart(network, addr string) { t.ConnectStart = time.Now() } func (t *HTTPTrace) connectDone(network, addr string, err error) { t.ConnectDone = time.Now() } func (t *HTTPTrace) tlsHandshakeStart() { t.TLSHandshakeStart = time.Now() } func (t *HTTPTrace) tlsHandshakeDone(state tls.ConnectionState, err error) { t.TLSHandshakeDone = time.Now() } func (t *HTTPTrace) wroteHeaders() { t.WriteHeaderDone = time.Now() } func (t *HTTPTrace) wait100Continue() {} func (t *HTTPTrace) wroteRequest(info httptrace.WroteRequestInfo) { t.WriteRequestDone = time.Now() } func safeTimeDelta(start, end time.Time) time.Duration { if start.IsZero() || end.IsZero() || start.After(end) { return 0 } return end.Sub(start) } func writeField(w io.Writer, field string, format string, args ...interface{}) error { _, err := fmt.Fprintf(w, "%s: "+format+", ", append([]interface{}{field}, args...)...) return err } func writeDurField(w io.Writer, field string, dur time.Duration) error { if dur == 0 { return nil } _, err := fmt.Fprintf(w, "%s: %s, ", field, dur) return err }