Skip to content

Commit

Permalink
Merge pull request #81 from muir/sixtyeight
Browse files Browse the repository at this point in the history
Add support for propagation with resty
  • Loading branch information
muir authored Oct 2, 2022
2 parents 1db6978 + 027fa8a commit 55ae5c3
Show file tree
Hide file tree
Showing 11 changed files with 697 additions and 92 deletions.
5 changes: 2 additions & 3 deletions go.mod
Original file line number Diff line number Diff line change
Expand Up @@ -4,10 +4,9 @@ go 1.16

require (
github.com/google/uuid v1.3.0
github.com/gorilla/mux v1.8.0
github.com/mohae/deepcopy v0.0.0-20170929034955-c48cc78d4826
github.com/muir/rest v0.0.0-20210822233606-6d02fb885933
github.com/phuslu/fasttime v1.0.2
github.com/muir/resty v0.0.1
github.com/pkg/errors v0.9.1
github.com/stretchr/testify v1.8.0
go.opentelemetry.io/otel v1.10.0
go.opentelemetry.io/otel/exporters/stdout/stdouttrace v1.10.0
Expand Down
19 changes: 11 additions & 8 deletions go.sum
Original file line number Diff line number Diff line change
Expand Up @@ -6,20 +6,16 @@ github.com/go-logr/logr v1.2.3 h1:2DntVwHkVopvECVRSlL5PSo9eG+cAkDCuckLubN+rq0=
github.com/go-logr/logr v1.2.3/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A=
github.com/go-logr/stdr v1.2.2 h1:hSWxHoqTgW2S2qGc0LTAI563KZ5YKYRhT3MFKZMbjag=
github.com/go-logr/stdr v1.2.2/go.mod h1:mMo/vtBO5dYbehREoey6XUKy/eSumjCCveDpRre4VKE=
github.com/go-resty/resty/v2 v2.7.0 h1:me+K9p3uhSmXtrBZ4k9jcEAfJmuC8IivWHwaLZwPrFY=
github.com/go-resty/resty/v2 v2.7.0/go.mod h1:9PWDzw47qPphMRFfhsyk0NnSgvluHcljSMVIq3w7q0I=
github.com/google/go-cmp v0.5.8 h1:e6P7q2lk1O+qJJb4BtCQXlK8vWEO8V1ZeuEdJNOqZyg=
github.com/google/go-cmp v0.5.8/go.mod h1:17dUlkBOakJ0+DkrSSNjCkIjxS6bF9zb3elmeNGIjoY=
github.com/google/uuid v1.3.0 h1:t6JiXgmwXMjEs8VusXIJk2BXHsn+wx8BZdTaoZ5fu7I=
github.com/google/uuid v1.3.0/go.mod h1:TIyPZe4MgqvfeYDBFedMoGGpEw/LqOeaOT+nhxU+yHo=
github.com/gorilla/mux v1.8.0 h1:i40aqfkR1h2SlN9hojwV5ZA91wcXFOvkdNIeFDP5koI=
github.com/gorilla/mux v1.8.0/go.mod h1:DVbg23sWSpFRCP0SfiEN6jmj59UnW/n46BH5rLB71So=
github.com/mohae/deepcopy v0.0.0-20170929034955-c48cc78d4826 h1:RWengNIwukTxcDr9M+97sNutRR1RKhG96O6jWumTTnw=
github.com/mohae/deepcopy v0.0.0-20170929034955-c48cc78d4826/go.mod h1:TaXosZuwdSHYgviHp1DAtfrULt5eUgsSMsZf+YrPgl8=
github.com/muir/rest v0.0.0-20210822233606-6d02fb885933 h1:gBIILIoUpMUWpQNSRdVSzF9xmBqbITPEkClLSyCxsAc=
github.com/muir/rest v0.0.0-20210822233606-6d02fb885933/go.mod h1:sUUGdWPRJgmDYo14DPXmZbkyqPOuy+Ec1gaEnhRuu0I=
github.com/phuslu/fasttime v1.0.0 h1:SUkNta9tJLy54glGb/Z4+/NJ7aXiLogVuSPEXAya6i8=
github.com/phuslu/fasttime v1.0.0/go.mod h1:1zflhZFowg3RSL0IpmWQ0AprKCKbTRKV9PEpVXDBZ7A=
github.com/phuslu/fasttime v1.0.2 h1:gmD27yB6vnQuhk4vtmoBOmjaXsF+wwmyjMtayoHHUko=
github.com/phuslu/fasttime v1.0.2/go.mod h1:1zflhZFowg3RSL0IpmWQ0AprKCKbTRKV9PEpVXDBZ7A=
github.com/muir/resty v0.0.1 h1:dSWIF/uLX01/AzniDi+XukP9Q6g5QO10DPVJsZ+49n0=
github.com/muir/resty v0.0.1/go.mod h1:Vjk1Uhi1m4/Och2tNJ2nxuGJnoaI8L0U4a27TbzKMR4=
github.com/pkg/errors v0.9.1 h1:FEBLx1zS214owpjy7qsBeixbURkuhQAwrK5UwLGTwt4=
github.com/pkg/errors v0.9.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0=
github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM=
Expand All @@ -37,8 +33,15 @@ go.opentelemetry.io/otel/sdk v1.10.0 h1:jZ6K7sVn04kk/3DNUdJ4mqRlGDiXAVuIG+MMENpT
go.opentelemetry.io/otel/sdk v1.10.0/go.mod h1:vO06iKzD5baltJz1zarxMCNHFpUlUiOy4s65ECtn6kE=
go.opentelemetry.io/otel/trace v1.10.0 h1:npQMbR8o7mum8uF95yFbOEJffhs1sbCOfDh8zAJiH5E=
go.opentelemetry.io/otel/trace v1.10.0/go.mod h1:Sij3YYczqAdz+EhmGhE6TpTxUO5/F/AzrK+kxfGqySM=
golang.org/x/net v0.0.0-20211029224645-99673261e6eb h1:pirldcYWx7rx7kE5r+9WsOXPXK0+WH5+uZ7uPmJ44uM=
golang.org/x/net v0.0.0-20211029224645-99673261e6eb/go.mod h1:9nx3DQGgdP8bBQD5qxJ1jj9UTztislL4KSBs9R2vV5Y=
golang.org/x/sys v0.0.0-20201119102817-f84b799fce68/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
golang.org/x/sys v0.0.0-20210423082822-04245dca01da/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
golang.org/x/sys v0.0.0-20210423185535-09eb48e85fd7 h1:iGu644GcxtEcrInvDsQRCwJjtCIOlT2V7IRt6ah2Whw=
golang.org/x/sys v0.0.0-20210423185535-09eb48e85fd7/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1/go.mod h1:bj7SfCRtBDWHUb9snDiAeCFNEtKQo2Wmx5Cou7ajbmo=
golang.org/x/text v0.3.6/go.mod h1:5Zoc/QRtKVWzQhOtBMvqHzDpF6irO9z98xDceosuGiQ=
golang.org/x/tools v0.0.0-20180917221912-90fa682c2a6e/go.mod h1:n7NCudcB/nEzxVGmLbDWY5pfWTLqBcC2KZ6jyYvM4mQ=
gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405 h1:yhCVgyC4o1eVCa2tZl7eS0r+SDo693bJlVdllGtEeKM=
gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM=
Expand Down
7 changes: 7 additions & 0 deletions logger.go
Original file line number Diff line number Diff line change
Expand Up @@ -143,6 +143,7 @@ func (sub *Sub) Log() *Log {
}

func (old *Log) newChildLog(seed Seed, description string, detached bool) *Log {
seed.spanSeed.traceBundle.TraceParent = seed.spanSeed.traceBundle.Trace
seed = seed.react(false, description)

type singleAlloc struct {
Expand Down Expand Up @@ -572,12 +573,16 @@ func (line *Line) Template(template string) {
line.log.hasActivity(true)
}

// Msg sends a log line. After Msg(), no further use of the *Line
// is allowed. Without calling Msg(), Template(), Msgf(), Msgs(),
// or Static(), the log line will not be sent or output.
func (line *Line) Msg(msg string) {
line.line.Msg(msg)
line.log.span.linePool.Put(line)
line.log.hasActivity(true)
}

// Msgf sends a log line, using fmt.Sprintf()-style formatting.
func (line *Line) Msgf(msg string, v ...interface{}) {
if !line.skip {
line.Msg(fmt.Sprintf(msg, v...))
Expand All @@ -593,6 +598,8 @@ func (line *Line) Static(msg string) {
line.log.hasActivity(true)
}

// Line starts a log line at the specified log level. If the log level
// is below the minimum log level, the line will be discarded.
func (log *Log) Line(level xopnum.Level) *Line { return log.logLine(level) }
func (log *Log) Debug() *Line { return log.Line(xopnum.DebugLevel) }
func (log *Log) Trace() *Line { return log.Line(xopnum.TraceLevel) }
Expand Down
6 changes: 3 additions & 3 deletions trace/trace.go
Original file line number Diff line number Diff line change
Expand Up @@ -69,17 +69,17 @@ func NewTrace() Trace {

var traceRE = regexp.MustCompile(`^([a-fA-F0-9]{2})-([a-fA-F0-9]{32})-([a-fA-F0-9]{16})-([a-fA-F0-9]{2})$`)

func TraceFromString(s string) Trace {
func TraceFromString(s string) (Trace, bool) {
m := traceRE.FindStringSubmatch(s)
if m == nil {
return NewTrace()
return NewTrace(), false
}
var trace Trace
trace.Version().SetString(m[1])
trace.TraceID().SetString(m[2])
trace.SpanID().SetString(m[3])
trace.Flags().SetString(m[4])
return trace
return trace, true
}

func (t *Trace) Version() WrappedHexBytes1 {
Expand Down
4 changes: 4 additions & 0 deletions xopconst/standard.go
Original file line number Diff line number Diff line change
Expand Up @@ -32,3 +32,7 @@ var (
SpanTypeHTTPClientRequest = SpanType.Iota("REST")
SpanTypeCronJob = SpanType.Iota("cron_job")
)

var RemoteTrace = xopat.Make{Key: "http.remote_trace", Namespace: "xop", Indexed: true, Prominence: 40,
Description: "The traceID and spanID for for the remote side of a outgoing HTTP request, if known"}.
LinkAttribute()
4 changes: 2 additions & 2 deletions xopmiddle/utils.go
Original file line number Diff line number Diff line change
Expand Up @@ -13,8 +13,8 @@ import (
// "traceparent" header
// Example: 00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01
func SetByTraceParentHeader(b *trace.Bundle, h string) {
parent := trace.TraceFromString(h)
if parent.IsZero() {
parent, ok := trace.TraceFromString(h)
if !ok {
b.Trace = trace.NewTrace()
b.Trace.TraceID().SetRandom()
b.Trace.SpanID().SetRandom()
Expand Down
242 changes: 242 additions & 0 deletions xopresty/resty.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,242 @@
/*
package xopresty adds to the resty package to
propagate xop context to through an HTTP request.
The resty package does not provide a way to have a
logger that knows which request it is logging about.
The resty package does not provide a way to know when
requests are complete.
There are open pull requests to solve both of these
issues. In the meantime, this package depends upon
https://github.com/muir/resty.
The agumented resty Client requires that a context that
has the parent log span be provided:
client.R().SetContext(log.IntoContext(context.Background()))
If there is no logger in the context, the request will fail.
If you use resty's Client.SetDebug(true), note that the output
will be logged at Debug level which is below the default
minimum level for xop.
*/
package xopresty

import (
"context"
"fmt"
"strings"
"time"

"github.com/muir/xop-go"
"github.com/muir/xop-go/trace"
"github.com/muir/xop-go/xopconst"

"github.com/muir/resty"
"github.com/pkg/errors"
)

var _ resty.Logger = restyLogger{}

type restyLogger struct {
log *xop.Log
}

func (rl restyLogger) Errorf(format string, v ...interface{}) { rl.log.Error().Msgf(format, v...) }
func (rl restyLogger) Warnf(format string, v ...interface{}) { rl.log.Warn().Msgf(format, v...) }
func (rl restyLogger) Debugf(format string, v ...interface{}) { rl.log.Debug().Msgf(format, v...) }

type contextKeyType struct{}

var contextKey = contextKeyType{}

type contextNameType struct{}

var contextNameKey = contextNameType{}

type contextValue struct {
b3Sent bool
b3Trace trace.Trace
response bool
log *xop.Log
retryCount int
originalStartTime time.Time
}

type config struct {
requestToName func(r *resty.Request) string
extraLogging ExtraLogging
}

type ClientOpt func(*config)

// WithNameGenerate provides a function to convert a request into
// a description for the span.
func WithNameGenerate(f func(*resty.Request) string) ClientOpt {
return func(config *config) {
config.requestToName = f
}
}

// ExtraLogging provides a hook for extra logging to be done.
// It is possible that the response parameter will be null.
// If error is not null, then the request has failed.
// ExtraLogging should only be called once but if another resty
// callback panic's, it is possible ExtraLogging will be called
// twice.
type ExtraLogging func(log *xop.Log, originalStartTime time.Time, retryCount int, request *resty.Request, response *resty.Response, err error)

func WithExtraLogging(f ExtraLogging) ClientOpt {
return func(config *config) {
config.extraLogging = f
}
}

// WithNameInDescription adds a span name to a context. If present,
// a name in context overrides WithNameGenerate.
func WithNameInContext(ctx context.Context, nameOrDescription string) context.Context {
return context.WithValue(ctx, contextNameKey, nameOrDescription)
}

func Client(client *resty.Client, opts ...ClientOpt) *resty.Client {
config := &config{
requestToName: func(r *resty.Request) string {
url := r.URL
i := strings.IndexByte(url, '?')
if i != -1 {
url = url[:i]
}
return r.Method + " " + url
},
extraLogging: func(log *xop.Log, originalStartTime time.Time, retryCount int, request *resty.Request, response *resty.Response, err error) {
},
}
for _, f := range opts {
f(config)
}

// c := *client
// c.Header = client.Header.Clone()
// clinet = &c
return client.
OnBeforeRequest(func(_ *resty.Client, r *resty.Request) error {
// OnBeforeRequest can execute multiple times for the same attempt if there
// are retries. It won't execute at all of the request is invalid.
ctx := r.Context()
cvRaw := ctx.Value(contextKey)
var cv *contextValue
if cvRaw != nil {
cv = cvRaw.(*contextValue)
cv.retryCount++
return nil
}
log, ok := xop.FromContext(r.Context())
if !ok {
return errors.Errorf("context is missing logger, use Request.SetContext(Log.IntoContext(request.Context()))")
}
nameRaw := ctx.Value(contextNameKey)
var name string
if nameRaw != nil {
name = nameRaw.(string)
} else {
name = config.requestToName(r)
}
log = log.Sub().Step(name)
cv = &contextValue{
originalStartTime: time.Now(),
log: log,
}
r.SetContext(context.WithValue(ctx, contextKey, cv))
r.SetLogger(restyLogger{log: log})

if r.Body != nil {
log.Trace().
Any("body", r.Body).
Static("request")
}

log.Span().EmbeddedEnum(xopconst.SpanTypeHTTPClientRequest)
log.Span().String(xopconst.URL, r.URL)
log.Span().String(xopconst.HTTPMethod, r.Method)
r.Header.Set("traceparent", log.Span().Bundle().Trace.String())
if !log.Span().TraceBaggage().IsZero() {
r.Header.Set("baggage", log.Span().TraceBaggage().String())
}
if !log.Span().TraceState().IsZero() {
r.Header.Set("state", log.Span().TraceState().String())
}
if log.Config().UseB3 {
b3Trace := log.Span().Bundle().Trace
b3Trace.SpanID().SetRandom()
r.Header.Set("b3",
b3Trace.GetTraceID().String()+"-"+
b3Trace.TraceID().String()+"-"+
b3Trace.GetFlags().String()[1:2]+"-"+
log.Span().Trace().GetSpanID().String())
cv.b3Trace = b3Trace
cv.b3Sent = true
}
return nil
}).
OnAfterResponse(func(_ *resty.Client, resp *resty.Response) error {
// OnAfterRequest is run for each individual request attempt
r := resp.Request
ctx := r.Context()
cvRaw := ctx.Value(contextKey)
var cv *contextValue
if cvRaw == nil {
return fmt.Errorf("xopresty: internal error, context missing in response")
}
cv = cvRaw.(*contextValue)
log := cv.log

tr := resp.Header().Get("traceresponse")
if tr != "" {
trace, ok := trace.TraceFromString(tr)
if ok {
cv.response = true
log.Info().Link(xopconst.RemoteTrace.Key(), trace).Static("traceresponse")
log.Span().Link(xopconst.RemoteTrace, trace)
} else {
log.Warn().String("header", tr).Static("invalid traceresponse received")
}
}
if r.Result != nil {
log.Info().Any("response", resp.Result()).Msg("received")
}
ti := r.TraceInfo()
if ti.TotalTime != 0 {
log.Info().
Duration("request_time.total", ti.TotalTime).
Duration("request_time.server", ti.ServerTime).
Duration("request_time.dns", ti.DNSLookup).
Static("timings")
}
return nil
}).
OnError(func(r *resty.Request, err error) {
ctx := r.Context()
cv := ctx.Value(contextKey).(*contextValue)
log := cv.log
var re *resty.ResponseError
if errors.As(err, &re) {
config.extraLogging(log, cv.originalStartTime, cv.retryCount, r, re.Response, re.Err)
} else {
config.extraLogging(log, cv.originalStartTime, cv.retryCount, r, nil, err)
}
}).
OnPanic(func(r *resty.Request, err error) {
ctx := r.Context()
cv := ctx.Value(contextKey).(*contextValue)
log := cv.log
config.extraLogging(log, cv.originalStartTime, cv.retryCount, r, nil, err)
}).
OnSuccess(func(c *resty.Client, resp *resty.Response) {
ctx := resp.Request.Context()
cv := ctx.Value(contextKey).(*contextValue)
log := cv.log
config.extraLogging(log, cv.originalStartTime, cv.retryCount, resp.Request, resp, nil)
})
}
Loading

0 comments on commit 55ae5c3

Please sign in to comment.