From 34c80e29bce592c4af304f25f18ac0d13a72c5b2 Mon Sep 17 00:00:00 2001 From: Vasiliy Tolstov Date: Fri, 1 Sep 2023 14:32:27 +0300 Subject: [PATCH] tracing updates Signed-off-by: Vasiliy Tolstov --- common.go | 16 ++++++- conn.go | 125 +++++++++++++++++++++++++---------------------------- driver.go | 32 +++++++------- go.mod | 5 ++- go.sum | 8 ++++ options.go | 24 +++++----- stmt.go | 85 ++++++++++++++++++------------------ tx.go | 10 ++--- 8 files changed, 162 insertions(+), 143 deletions(-) diff --git a/common.go b/common.go index b975d8d..4c3d5ce 100644 --- a/common.go +++ b/common.go @@ -4,6 +4,7 @@ import ( "database/sql/driver" "errors" "fmt" + "runtime" ) //go:generate sh -c "go run gen.go > wrap_gen.go" @@ -31,7 +32,20 @@ func namedValueToLabels(named []driver.NamedValue) []interface{} { } else { name = fmt.Sprintf("$%d", param.Ordinal) } - largs = append(largs, fmt.Sprintf("%s=%s", name, param.Value)) + largs = append(largs, fmt.Sprintf("%s=%v", name, param.Value)) } return largs } + +// getCallerName get the name of the function A where A() -> B() -> GetFunctionCallerName() +func getCallerName() string { + pc, _, _, ok := runtime.Caller(3) + details := runtime.FuncForPC(pc) + var callerName string + if ok && details != nil { + callerName = details.Name() + } else { + callerName = labelUnknown + } + return callerName +} diff --git a/conn.go b/conn.go index 8613229..cc41536 100644 --- a/conn.go +++ b/conn.go @@ -6,6 +6,7 @@ import ( "fmt" "time" + requestid "go.unistack.org/micro-wrapper-requestid/v3" "go.unistack.org/micro/v3/tracer" ) @@ -15,9 +16,9 @@ var ( _ driver.ConnPrepareContext = (*wrapperConn)(nil) _ driver.Pinger = (*wrapperConn)(nil) _ driver.Validator = (*wrapperConn)(nil) - _ driver.Queryer = (*wrapperConn)(nil) + _ driver.Queryer = (*wrapperConn)(nil) // nolint:staticcheck _ driver.QueryerContext = (*wrapperConn)(nil) - _ driver.Execer = (*wrapperConn)(nil) + _ driver.Execer = (*wrapperConn)(nil) // nolint:staticcheck _ driver.ExecerContext = (*wrapperConn)(nil) // _ driver.Connector // _ driver.Driver @@ -57,7 +58,7 @@ func (w *wrapperConn) Close() error { w.opts.Meter.Histogram(meterRequestDurationSeconds, labels...).Update(te) if w.opts.LoggerEnabled && w.opts.Logger.V(w.opts.LoggerLevel) { - w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "Close", labelUnknown, td, err)...).Log(ctx, w.opts.LoggerLevel) + w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "Close", getCallerName(), td, err)...).Log(ctx, w.opts.LoggerLevel) } return err @@ -82,7 +83,7 @@ func (w *wrapperConn) Begin() (driver.Tx, error) { w.opts.Meter.Summary(meterRequestLatencyMicroseconds, labels...).Update(te) w.opts.Meter.Histogram(meterRequestDurationSeconds, labels...).Update(te) if w.opts.LoggerEnabled && w.opts.Logger.V(w.opts.LoggerLevel) { - w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "Begin", labelUnknown, td, err)...).Log(ctx, w.opts.LoggerLevel) + w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "Begin", getCallerName(), td, err)...).Log(ctx, w.opts.LoggerLevel) } return nil, err } @@ -90,7 +91,7 @@ func (w *wrapperConn) Begin() (driver.Tx, error) { w.opts.Meter.Summary(meterRequestLatencyMicroseconds, labels...).Update(te) w.opts.Meter.Histogram(meterRequestDurationSeconds, labels...).Update(te) if w.opts.LoggerEnabled && w.opts.Logger.V(w.opts.LoggerLevel) { - w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "Begin", labelUnknown, td, err)...).Log(ctx, w.opts.LoggerLevel) + w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "Begin", getCallerName(), td, err)...).Log(ctx, w.opts.LoggerLevel) } return &wrapperTx{tx: tx, opts: w.opts, ctx: ctx}, nil @@ -98,13 +99,12 @@ func (w *wrapperConn) Begin() (driver.Tx, error) { // BeginTx implements driver.ConnBeginTx BeginTx func (w *wrapperConn) BeginTx(ctx context.Context, opts driver.TxOptions) (driver.Tx, error) { - nctx, span := w.opts.Tracer.Start(ctx, "Transaction") - span.AddLabels("method", "BeginTx") + nctx, span := w.opts.Tracer.Start(ctx, "sdk.database", tracer.WithSpanKind(tracer.SpanKindClient)) + span.AddLabels("db.method", "BeginTx") name := getQueryName(ctx) - if name != "" { - span.AddLabels("query", name) - } else { - name = labelUnknown + span.AddLabels("db.statement", name) + if id, ok := ctx.Value(requestid.XRequestIDKey).(string); ok { + span.AddLabels("x-request-id", id) } labels := []string{labelMethod, "BeginTx", labelQuery, name} @@ -121,16 +121,15 @@ func (w *wrapperConn) BeginTx(ctx context.Context, opts driver.TxOptions) (drive w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelFailure)...).Inc() w.opts.Meter.Summary(meterRequestLatencyMicroseconds, labels...).Update(te) w.opts.Meter.Histogram(meterRequestDurationSeconds, labels...).Update(te) - span.AddLabels("error", true) - span.AddLabels("err", err.Error()) + span.SetStatus(tracer.SpanStatusError, err.Error()) if w.opts.LoggerEnabled && w.opts.Logger.V(w.opts.LoggerLevel) { - w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "BeginTx", name, td, err)...).Log(ctx, w.opts.LoggerLevel) + w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "BeginTx", getCallerName(), td, err)...).Log(ctx, w.opts.LoggerLevel) } return nil, err } w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelSuccess)...).Inc() if w.opts.LoggerEnabled && w.opts.Logger.V(w.opts.LoggerLevel) { - w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "BeginTx", name, td, err)...).Log(ctx, w.opts.LoggerLevel) + w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "BeginTx", getCallerName(), td, err)...).Log(ctx, w.opts.LoggerLevel) } return &wrapperTx{tx: tx, opts: w.opts, ctx: ctx, span: span}, nil } @@ -144,7 +143,7 @@ func (w *wrapperConn) Prepare(query string) (driver.Stmt, error) { ctx = context.Background() } - labels := []string{labelMethod, "Prepare", labelQuery, labelUnknown} + labels := []string{labelMethod, "Prepare", labelQuery, getCallerName()} ts := time.Now() stmt, err := w.conn.Prepare(query) td := time.Since(ts) @@ -153,9 +152,8 @@ func (w *wrapperConn) Prepare(query string) (driver.Stmt, error) { w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelFailure)...).Inc() w.opts.Meter.Summary(meterRequestLatencyMicroseconds, labels...).Update(te) w.opts.Meter.Histogram(meterRequestDurationSeconds, labels...).Update(te) - if w.opts.LoggerEnabled && w.opts.Logger.V(w.opts.LoggerLevel) { - w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "Prepare", labelUnknown, td, err)...).Log(ctx, w.opts.LoggerLevel) + w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "Prepare", getCallerName(), td, err)...).Log(ctx, w.opts.LoggerLevel) } return nil, err } @@ -164,7 +162,7 @@ func (w *wrapperConn) Prepare(query string) (driver.Stmt, error) { w.opts.Meter.Histogram(meterRequestDurationSeconds, labels...).Update(te) if w.opts.LoggerEnabled && w.opts.Logger.V(w.opts.LoggerLevel) { - w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "Prepare", labelUnknown, td, err)...).Log(ctx, w.opts.LoggerLevel) + w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "Prepare", getCallerName(), td, err)...).Log(ctx, w.opts.LoggerLevel) } return wrapStmt(stmt, query, w.opts), nil @@ -174,19 +172,18 @@ func (w *wrapperConn) Prepare(query string) (driver.Stmt, error) { func (w *wrapperConn) PrepareContext(ctx context.Context, query string) (driver.Stmt, error) { var nctx context.Context var span tracer.Span - if w.ctx != nil { - nctx, span = w.opts.Tracer.Start(w.ctx, "PrepareContext") - } else { - nctx, span = w.opts.Tracer.Start(ctx, "PrepareContext") - } - span.AddLabels("method", "PrepareContext") - name := getQueryName(ctx) - if name != "" { - span.AddLabels("query", name) - } else { - name = labelUnknown - } + if w.ctx != nil { + nctx, span = w.opts.Tracer.Start(w.ctx, "sdk.database", tracer.WithSpanKind(tracer.SpanKindClient)) + } else { + nctx, span = w.opts.Tracer.Start(ctx, "sdk.database", tracer.WithSpanKind(tracer.SpanKindClient)) + } + span.AddLabels("db.method", "PrepareContext") + name := getQueryName(ctx) + span.AddLabels("db.statement", name) + if id, ok := ctx.Value(requestid.XRequestIDKey).(string); ok { + span.AddLabels("x-request-id", id) + } labels := []string{labelMethod, "PrepareContext", labelQuery, name} conn, ok := w.conn.(driver.ConnPrepareContext) if !ok { @@ -201,10 +198,9 @@ func (w *wrapperConn) PrepareContext(ctx context.Context, query string) (driver. w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelFailure)...).Inc() w.opts.Meter.Summary(meterRequestLatencyMicroseconds, labels...).Update(te) w.opts.Meter.Histogram(meterRequestDurationSeconds, labels...).Update(te) - span.AddLabels("error", true) - span.AddLabels("err", err.Error()) + span.SetStatus(tracer.SpanStatusError, err.Error()) if w.opts.LoggerEnabled && w.opts.Logger.V(w.opts.LoggerLevel) { - w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "PrepareContext", name, td, err)...).Log(ctx, w.opts.LoggerLevel) + w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "PrepareContext", getCallerName(), td, err)...).Log(ctx, w.opts.LoggerLevel) } return nil, err } @@ -212,7 +208,7 @@ func (w *wrapperConn) PrepareContext(ctx context.Context, query string) (driver. w.opts.Meter.Summary(meterRequestLatencyMicroseconds, labels...).Update(te) w.opts.Meter.Histogram(meterRequestDurationSeconds, labels...).Update(te) if w.opts.LoggerEnabled && w.opts.Logger.V(w.opts.LoggerLevel) { - w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "PrepareContext", name, td, err)...).Log(ctx, w.opts.LoggerLevel) + w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "PrepareContext", getCallerName(), td, err)...).Log(ctx, w.opts.LoggerLevel) } return wrapStmt(stmt, query, w.opts), nil @@ -226,7 +222,7 @@ func (w *wrapperConn) Exec(query string, args []driver.Value) (driver.Result, er } else { ctx = context.Background() } - labels := []string{labelMethod, "Exec", labelQuery, labelUnknown} + labels := []string{labelMethod, "Exec", labelQuery, getCallerName()} // nolint:staticcheck conn, ok := w.conn.(driver.Execer) @@ -246,7 +242,7 @@ func (w *wrapperConn) Exec(query string, args []driver.Value) (driver.Result, er w.opts.Meter.Summary(meterRequestLatencyMicroseconds, labels...).Update(te) w.opts.Meter.Histogram(meterRequestDurationSeconds, labels...).Update(te) if w.opts.LoggerEnabled && w.opts.Logger.V(w.opts.LoggerLevel) { - w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "Exec", labelUnknown, td, err)...).Log(ctx, w.opts.LoggerLevel) + w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "Exec", getCallerName(), td, err)...).Log(ctx, w.opts.LoggerLevel) } return res, err } @@ -257,23 +253,21 @@ func (w *wrapperConn) ExecContext(ctx context.Context, query string, args []driv var span tracer.Span if w.ctx != nil { - nctx, span = w.opts.Tracer.Start(w.ctx, "ExecContext") + nctx, span = w.opts.Tracer.Start(w.ctx, "sdk.database", tracer.WithSpanKind(tracer.SpanKindClient)) } else { - nctx, span = w.opts.Tracer.Start(ctx, "ExecContext") + nctx, span = w.opts.Tracer.Start(ctx, "sdk.database", tracer.WithSpanKind(tracer.SpanKindClient)) } - span.AddLabels("method", "ExecContext") + span.AddLabels("db.method", "ExecContext") name := getQueryName(ctx) - if name != "" { - span.AddLabels("query", name) - } else { - name = labelUnknown + span.AddLabels("db.statement", name) + if id, ok := ctx.Value(requestid.XRequestIDKey).(string); ok { + span.AddLabels("x-request-id", id) } defer span.Finish() if len(args) > 0 { - span.AddLabels("args", fmt.Sprintf("%v", namedValueToLabels(args))) + span.AddLabels("db.args", fmt.Sprintf("%v", namedValueToLabels(args))) } labels := []string{labelMethod, "ExecContext", labelQuery, name} - fmt.Printf("EXECCONTETX args %#+v\n", args) conn, ok := w.conn.(driver.ExecerContext) if !ok { @@ -287,8 +281,7 @@ func (w *wrapperConn) ExecContext(ctx context.Context, query string, args []driv te := td.Seconds() if err != nil { w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelFailure)...).Inc() - span.AddLabels("error", true) - span.AddLabels("err", err.Error()) + span.SetStatus(tracer.SpanStatusError, err.Error()) } else { w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelSuccess)...).Inc() } @@ -296,7 +289,7 @@ func (w *wrapperConn) ExecContext(ctx context.Context, query string, args []driv w.opts.Meter.Summary(meterRequestLatencyMicroseconds, labels...).Update(te) w.opts.Meter.Histogram(meterRequestDurationSeconds, labels...).Update(te) if w.opts.LoggerEnabled && w.opts.Logger.V(w.opts.LoggerLevel) { - w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "ExecContext", name, td, err)...).Log(ctx, w.opts.LoggerLevel) + w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "ExecContext", getCallerName(), td, err)...).Log(ctx, w.opts.LoggerLevel) } return res, err @@ -318,9 +311,9 @@ func (w *wrapperConn) Ping(ctx context.Context) error { var nctx context.Context var span tracer.Span if w.ctx != nil { - nctx, span = w.opts.Tracer.Start(w.ctx, "Ping") + nctx, span = w.opts.Tracer.Start(w.ctx, "sdk.database", tracer.WithSpanKind(tracer.SpanKindClient)) } else { - nctx, span = w.opts.Tracer.Start(ctx, "Ping") + nctx, span = w.opts.Tracer.Start(ctx, "sdk.database", tracer.WithSpanKind(tracer.SpanKindClient)) } defer span.Finish() labels := []string{labelMethod, "Ping"} @@ -330,10 +323,9 @@ func (w *wrapperConn) Ping(ctx context.Context) error { te := td.Seconds() if err != nil { w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelFailure)...).Inc() - span.AddLabels("error", true) - span.AddLabels("err", err.Error()) + span.SetStatus(tracer.SpanStatusError, err.Error()) if w.opts.LoggerEnabled && w.opts.Logger.V(w.opts.LoggerLevel) { - w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "Ping", labelUnknown, td, err)...).Log(ctx, w.opts.LoggerLevel) + w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "Ping", getCallerName(), td, err)...).Log(ctx, w.opts.LoggerLevel) } return err } else { @@ -359,7 +351,7 @@ func (w *wrapperConn) Query(query string, args []driver.Value) (driver.Rows, err return nil, driver.ErrSkip } - labels := []string{labelMethod, "Query", labelQuery, labelUnknown} + labels := []string{labelMethod, "Query", labelQuery, getCallerName()} ts := time.Now() rows, err := conn.Query(query, args) td := time.Since(ts) @@ -372,7 +364,7 @@ func (w *wrapperConn) Query(query string, args []driver.Value) (driver.Rows, err w.opts.Meter.Summary(meterRequestLatencyMicroseconds, labels...).Update(te) w.opts.Meter.Histogram(meterRequestDurationSeconds, labels...).Update(te) if w.opts.LoggerEnabled && w.opts.Logger.V(w.opts.LoggerLevel) { - w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "Query", labelUnknown, td, err)...).Log(ctx, w.opts.LoggerLevel) + w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "Query", getCallerName(), td, err)...).Log(ctx, w.opts.LoggerLevel) } return rows, err } @@ -381,21 +373,21 @@ func (w *wrapperConn) Query(query string, args []driver.Value) (driver.Rows, err func (w *wrapperConn) QueryContext(ctx context.Context, query string, args []driver.NamedValue) (driver.Rows, error) { var nctx context.Context var span tracer.Span + if w.ctx != nil { - nctx, span = w.opts.Tracer.Start(w.ctx, "QueryContext") + nctx, span = w.opts.Tracer.Start(w.ctx, "sdk.database", tracer.WithSpanKind(tracer.SpanKindClient)) } else { - nctx, span = w.opts.Tracer.Start(ctx, "QueryContext") + nctx, span = w.opts.Tracer.Start(ctx, "sdk.database", tracer.WithSpanKind(tracer.SpanKindClient)) } - span.AddLabels("method", "QueryContext") + span.AddLabels("db.method", "QueryContext") name := getQueryName(ctx) - if name != "" { - span.AddLabels("query", name) - } else { - name = labelUnknown + span.AddLabels("db.statement", name) + if id, ok := ctx.Value(requestid.XRequestIDKey).(string); ok { + span.AddLabels("x-request-id", id) } defer span.Finish() if len(args) > 0 { - span.AddLabels("args", fmt.Sprintf("%v", namedValueToLabels(args))) + span.AddLabels("db.args", fmt.Sprintf("%v", namedValueToLabels(args))) } labels := []string{labelMethod, "QueryContext", labelQuery, name} conn, ok := w.conn.(driver.QueryerContext) @@ -409,15 +401,14 @@ func (w *wrapperConn) QueryContext(ctx context.Context, query string, args []dri te := td.Seconds() if err != nil { w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelFailure)...).Inc() - span.AddLabels("error", true) - span.AddLabels("err", err.Error()) + span.SetStatus(tracer.SpanStatusError, err.Error()) } else { w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelSuccess)...).Inc() } w.opts.Meter.Summary(meterRequestLatencyMicroseconds, labels...).Update(te) w.opts.Meter.Histogram(meterRequestDurationSeconds, labels...).Update(te) if w.opts.LoggerEnabled && w.opts.Logger.V(w.opts.LoggerLevel) { - w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "QueryContext", name, td, err)...).Log(ctx, w.opts.LoggerLevel) + w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "QueryContext", getCallerName(), td, err)...).Log(ctx, w.opts.LoggerLevel) } return rows, err diff --git a/driver.go b/driver.go index b2d03cd..7397ec0 100644 --- a/driver.go +++ b/driver.go @@ -24,16 +24,9 @@ type conn interface { // wrapperDriver defines a wrapper for driver.Driver type wrapperDriver struct { - driver driver.Driver - connector driver.Connector - opts Options - ctx context.Context -} - -type wrapperConnector struct { driver driver.Driver - name string opts Options + ctx context.Context } // NewWrapper creates and returns a new SQL driver with passed capabilities @@ -41,17 +34,26 @@ func NewWrapper(d driver.Driver, opts ...Option) driver.Driver { return &wrapperDriver{driver: d, opts: NewOptions(opts...), ctx: context.Background()} } -/* +type wrappedConnector struct { + connector driver.Connector + name string + opts Options + ctx context.Context +} + +func NewWrapperConnector(c driver.Connector, opts ...Option) driver.Connector { + return &wrappedConnector{connector: c, opts: NewOptions(opts...), ctx: context.Background()} +} + // Connect implements driver.Driver Connect -func (w *wrapperConnector) Connect(ctx context.Context) (driver.Conn, error) { - return w.driver.Connect(ctx) +func (w *wrappedConnector) Connect(ctx context.Context) (driver.Conn, error) { + return w.connector.Connect(ctx) } // Driver implements driver.Driver Driver -func (w *wrapperConnector) Driver() driver.Driver { - return w.driver +func (w *wrappedConnector) Driver() driver.Driver { + return w.connector.Driver() } -*/ /* // Connect implements driver.Driver OpenConnector @@ -78,7 +80,7 @@ func (w *wrapperDriver) Open(name string) (driver.Conn, error) { td := time.Since(ts) if w.opts.LoggerEnabled { - w.opts.Logger.Fields(w.opts.LoggerObserver(w.ctx, "Open", labelUnknown, td, err)...).Log(w.ctx, w.opts.LoggerLevel) + w.opts.Logger.Fields(w.opts.LoggerObserver(w.ctx, "Open", getCallerName(), td, err)...).Log(w.ctx, w.opts.LoggerLevel) } if err != nil { return nil, err diff --git a/go.mod b/go.mod index 5f04dae..0f33da8 100644 --- a/go.mod +++ b/go.mod @@ -2,4 +2,7 @@ module go.unistack.org/micro-wrapper-sql/v3 go 1.19 -require go.unistack.org/micro/v3 v3.10.25 +require ( + go.unistack.org/micro-wrapper-requestid/v3 v3.8.7 + go.unistack.org/micro/v3 v3.10.25 +) diff --git a/go.sum b/go.sum index 79b5710..bd1e0f7 100644 --- a/go.sum +++ b/go.sum @@ -1,2 +1,10 @@ +github.com/imdario/mergo v0.3.14/go.mod h1:WBLT9ZmE3lPoWsEzCh9LPo3TiwVN+ZKEjmz+hD27ysY= +github.com/patrickmn/go-cache v2.1.0+incompatible/go.mod h1:3Qf8kWWT7OJRJbdiICTKqZju1ZixQ/KpMGzzAfe6+WQ= +github.com/silas/dag v0.0.0-20211117232152-9d50aa809f35/go.mod h1:7RTUFBdIRC9nZ7/3RyRNH1bdqIShrDejd1YbLwgPS+I= +go.unistack.org/micro-wrapper-requestid/v3 v3.8.7 h1:gXyiO7gPT0wNE7XEJIrwS2Y4cqylbeBMmlNYGwIS3io= +go.unistack.org/micro-wrapper-requestid/v3 v3.8.7/go.mod h1:W92jAyoOoTFgGXgYu26BZi+R+IwJVH5N+BPnnp0NuiY= +go.unistack.org/micro/v3 v3.10.19/go.mod h1:XIArw29f0b3uvF4cq96X/nQt2f0J2OGnjh8J+DBbC0s= go.unistack.org/micro/v3 v3.10.25 h1:A0epdZHOqjnXx103wwFhPKgmvVVbScvfbmn3HmHz1wE= go.unistack.org/micro/v3 v3.10.25/go.mod h1:ALkeXpqChYDjx8KPi7tz9mmIyOnob6nlNswsg8BnZjQ= +gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= +gopkg.in/yaml.v3 v3.0.1/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM= diff --git a/options.go b/options.go index eff4053..0e42ab4 100644 --- a/options.go +++ b/options.go @@ -17,7 +17,7 @@ var ( DefaultMeterMetricPrefix = "micro_sql_" // DefaultLoggerObserver used to prepare labels for logger DefaultLoggerObserver = func(ctx context.Context, method string, query string, td time.Duration, err error) []interface{} { - labels := []interface{}{"method", method, "took", fmt.Sprintf("%v", td)} + labels := []interface{}{"db.method", method, "took", fmt.Sprintf("%v", td)} if err != nil { labels = append(labels, "error", err.Error()) } @@ -29,18 +29,18 @@ var ( ) var ( - MaxOpenConnections = "max_open_connections" - OpenConnections = "open_connections" - InuseConnections = "inuse_connections" - IdleConnections = "idle_connections" - WaitConnections = "wait_connections" + MaxOpenConnections = "max_open_conn" + OpenConnections = "open_conn" + InuseConnections = "inuse_conn" + IdleConnections = "idle_conn" + WaitConnections = "waited_conn" BlockedSeconds = "blocked_seconds" MaxIdleClosed = "max_idle_closed" - MaxIdletimeClosed = "max_idletime_closed" - MaxLifetimeClosed = "max_lifetime_closed" + MaxIdletimeClosed = "closed_max_idle" + MaxLifetimeClosed = "closed_max_lifetime" meterRequestTotal = "request_total" - meterRequestLatencyMicroseconds = "request_latency_microseconds" + meterRequestLatencyMicroseconds = "latency_microseconds" meterRequestDurationSeconds = "request_duration_seconds" labelUnknown = "unknown" @@ -78,7 +78,7 @@ func NewOptions(opts ...Option) Options { Tracer: tracer.DefaultTracer, MeterStatsInterval: DefaultMeterStatsInterval, MeterMetricPrefix: DefaultMeterMetricPrefix, - LoggerLevel: logger.DebugLevel, + LoggerLevel: logger.ErrorLevel, LoggerObserver: DefaultLoggerObserver, } for _, o := range opts { @@ -177,8 +177,8 @@ func QueryName(ctx context.Context, name string) context.Context { } func getQueryName(ctx context.Context) string { - if v, ok := ctx.Value(queryNameKey{}).(string); ok { + if v, ok := ctx.Value(queryNameKey{}).(string); ok && v != labelUnknown { return v } - return "" + return getCallerName() } diff --git a/stmt.go b/stmt.go index 868767c..f1a75f4 100644 --- a/stmt.go +++ b/stmt.go @@ -6,6 +6,7 @@ import ( "fmt" "time" + requestid "go.unistack.org/micro-wrapper-requestid/v3" "go.unistack.org/micro/v3/tracer" ) @@ -46,7 +47,7 @@ func (w *wrapperStmt) Close() error { w.opts.Meter.Histogram(meterRequestDurationSeconds, labels...).Update(te) if w.opts.LoggerEnabled && w.opts.Logger.V(w.opts.LoggerLevel) { - w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "Close", labelUnknown, td, err)...).Log(ctx, w.opts.LoggerLevel) + w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "Close", getCallerName(), td, err)).Log(ctx, w.opts.LoggerLevel) } return err } @@ -87,7 +88,7 @@ func (w *wrapperStmt) Exec(args []driver.Value) (driver.Result, error) { w.opts.Meter.Histogram(meterRequestDurationSeconds, labels...).Update(te) if w.opts.LoggerEnabled && w.opts.Logger.V(w.opts.LoggerLevel) { - w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "Exec", labelUnknown, td, err)...).Log(ctx, w.opts.LoggerLevel) + w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "Exec", getCallerName(), td, err)).Log(ctx, w.opts.LoggerLevel) } return res, err @@ -103,8 +104,7 @@ func (w *wrapperStmt) Query(args []driver.Value) (driver.Rows, error) { } labels := []string{labelMethod, "Query"} ts := time.Now() - // nolint:staticcheck - rows, err := w.stmt.Query(args) + rows, err := w.stmt.Query(args) // nolint:staticcheck td := time.Since(ts) te := td.Seconds() if err != nil { @@ -116,31 +116,40 @@ func (w *wrapperStmt) Query(args []driver.Value) (driver.Rows, error) { w.opts.Meter.Histogram(meterRequestDurationSeconds, labels...).Update(te) if w.opts.LoggerEnabled && w.opts.Logger.V(w.opts.LoggerLevel) { - w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "Query", labelUnknown, td, err)...).Log(ctx, w.opts.LoggerLevel) + w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "Query", getCallerName(), td, err)).Log(ctx, w.opts.LoggerLevel) } return rows, err } +// ColumnConverter implements driver.ColumnConverter +func (w *wrapperStmt) ColumnConverter(idx int) driver.ValueConverter { + s, ok := w.stmt.(driver.ColumnConverter) // nolint:staticcheck + if !ok { + return nil + } + return s.ColumnConverter(idx) +} + // ExecContext implements driver.StmtExecContext ExecContext func (w *wrapperStmt) ExecContext(ctx context.Context, args []driver.NamedValue) (driver.Result, error) { var nctx context.Context var span tracer.Span + if w.ctx != nil { - nctx, span = w.opts.Tracer.Start(w.ctx, "ExecContext") + nctx, span = w.opts.Tracer.Start(w.ctx, "sdk.database", tracer.WithSpanKind(tracer.SpanKindClient)) } else { - nctx, span = w.opts.Tracer.Start(ctx, "ExecContext") + nctx, span = w.opts.Tracer.Start(ctx, "sdk.database", tracer.WithSpanKind(tracer.SpanKindClient)) } - span.AddLabels("method", "ExecContext") + span.AddLabels("db.method", "ExecContext") name := getQueryName(ctx) - if name != "" { - span.AddLabels("query", name) - } else { - name = labelUnknown - } + span.AddLabels("db.statement", name) defer span.Finish() if len(args) > 0 { - span.AddLabels("args", fmt.Sprintf("%v", namedValueToLabels(args))) + span.AddLabels("db.args", fmt.Sprintf("%v", namedValueToLabels(args))) + } + if id, ok := ctx.Value(requestid.XRequestIDKey).(string); ok { + span.AddLabels("x-request-id", id) } labels := []string{labelMethod, "ExecContext", labelQuery, name} @@ -151,8 +160,7 @@ func (w *wrapperStmt) ExecContext(ctx context.Context, args []driver.NamedValue) te := td.Seconds() if err != nil { w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelFailure)...).Inc() - span.AddLabels("error", true) - span.AddLabels("err", err.Error()) + span.SetStatus(tracer.SpanStatusError, err.Error()) } else { w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelSuccess)...).Inc() } @@ -160,7 +168,7 @@ func (w *wrapperStmt) ExecContext(ctx context.Context, args []driver.NamedValue) w.opts.Meter.Histogram(meterRequestDurationSeconds, labels...).Update(te) if w.opts.LoggerEnabled && w.opts.Logger.V(w.opts.LoggerLevel) { - w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "ExecContext", name, td, err)...).Log(ctx, w.opts.LoggerLevel) + w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "ExecContext", name, td, err)).Log(ctx, w.opts.LoggerLevel) } return res, err } @@ -168,11 +176,10 @@ func (w *wrapperStmt) ExecContext(ctx context.Context, args []driver.NamedValue) values, err := namedValueToValue(args) if err != nil { w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelFailure)...).Inc() - span.AddLabels("error", true) - span.AddLabels("err", err.Error()) + span.SetStatus(tracer.SpanStatusError, err.Error()) if w.opts.LoggerEnabled && w.opts.Logger.V(w.opts.LoggerLevel) { - w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "ExecContext", name, 0, err)...).Log(ctx, w.opts.LoggerLevel) + w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "ExecContext", name, 0, err)).Log(ctx, w.opts.LoggerLevel) } return nil, err } @@ -182,8 +189,7 @@ func (w *wrapperStmt) ExecContext(ctx context.Context, args []driver.NamedValue) te := td.Seconds() if err != nil { w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelFailure)...).Inc() - span.AddLabels("error", true) - span.AddLabels("err", err.Error()) + span.SetStatus(tracer.SpanStatusError, err.Error()) } else { w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelSuccess)...).Inc() } @@ -192,7 +198,7 @@ func (w *wrapperStmt) ExecContext(ctx context.Context, args []driver.NamedValue) w.opts.Meter.Histogram(meterRequestDurationSeconds, labels...).Update(te) if w.opts.LoggerEnabled && w.opts.Logger.V(w.opts.LoggerLevel) { - w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "ExecContext", name, td, err)...).Log(ctx, w.opts.LoggerLevel) + w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "ExecContext", name, td, err)).Log(ctx, w.opts.LoggerLevel) } return res, err @@ -202,21 +208,21 @@ func (w *wrapperStmt) ExecContext(ctx context.Context, args []driver.NamedValue) func (w *wrapperStmt) QueryContext(ctx context.Context, args []driver.NamedValue) (driver.Rows, error) { var nctx context.Context var span tracer.Span + if w.ctx != nil { - nctx, span = w.opts.Tracer.Start(w.ctx, "QueryContext") + nctx, span = w.opts.Tracer.Start(w.ctx, "sdk.database", tracer.WithSpanKind(tracer.SpanKindClient)) } else { - nctx, span = w.opts.Tracer.Start(ctx, "QueryContext") + nctx, span = w.opts.Tracer.Start(ctx, "sdk.database", tracer.WithSpanKind(tracer.SpanKindClient)) } - span.AddLabels("method", "QueryContext") + span.AddLabels("db.method", "QueryContext") name := getQueryName(ctx) - if name != "" { - span.AddLabels("query", name) - } else { - name = labelUnknown - } + span.AddLabels("db.statement", name) defer span.Finish() if len(args) > 0 { - span.AddLabels("args", fmt.Sprintf("%v", namedValueToLabels(args))) + span.AddLabels("db.args", fmt.Sprintf("%v", namedValueToLabels(args))) + } + if id, ok := ctx.Value(requestid.XRequestIDKey).(string); ok { + span.AddLabels("x-request-id", id) } labels := []string{labelMethod, "QueryContext", labelQuery, name} if conn, ok := w.stmt.(driver.StmtQueryContext); ok { @@ -226,8 +232,7 @@ func (w *wrapperStmt) QueryContext(ctx context.Context, args []driver.NamedValue te := td.Seconds() if err != nil { w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelFailure)...).Inc() - span.AddLabels("error", true) - span.AddLabels("err", err.Error()) + span.SetStatus(tracer.SpanStatusError, err.Error()) } else { w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelSuccess)...).Inc() } @@ -236,7 +241,7 @@ func (w *wrapperStmt) QueryContext(ctx context.Context, args []driver.NamedValue w.opts.Meter.Histogram(meterRequestDurationSeconds, labels...).Update(te) if w.opts.LoggerEnabled && w.opts.Logger.V(w.opts.LoggerLevel) { - w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "QueryContext", name, td, err)...).Log(ctx, w.opts.LoggerLevel) + w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "QueryContext", name, td, err)).Log(ctx, w.opts.LoggerLevel) } return rows, err } @@ -245,11 +250,10 @@ func (w *wrapperStmt) QueryContext(ctx context.Context, args []driver.NamedValue if err != nil { w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelFailure)...).Inc() - span.AddLabels("error", true) - span.AddLabels("err", err.Error()) + span.SetStatus(tracer.SpanStatusError, err.Error()) if w.opts.LoggerEnabled && w.opts.Logger.V(w.opts.LoggerLevel) { - w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "QueryContext", name, 0, err)...).Log(ctx, w.opts.LoggerLevel) + w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "QueryContext", name, 0, err)).Log(ctx, w.opts.LoggerLevel) } return nil, err } @@ -259,8 +263,7 @@ func (w *wrapperStmt) QueryContext(ctx context.Context, args []driver.NamedValue te := td.Seconds() if err != nil { w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelFailure)...).Inc() - span.AddLabels("error", true) - span.AddLabels("err", err.Error()) + span.SetStatus(tracer.SpanStatusError, err.Error()) } else { w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelSuccess)...).Inc() } @@ -269,7 +272,7 @@ func (w *wrapperStmt) QueryContext(ctx context.Context, args []driver.NamedValue w.opts.Meter.Histogram(meterRequestDurationSeconds, labels...).Update(te) if w.opts.LoggerEnabled && w.opts.Logger.V(w.opts.LoggerLevel) { - w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "QueryContext", name, td, err)...).Log(ctx, w.opts.LoggerLevel) + w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "QueryContext", name, td, err)).Log(ctx, w.opts.LoggerLevel) } return rows, err diff --git a/tx.go b/tx.go index ddc3e6a..362e422 100644 --- a/tx.go +++ b/tx.go @@ -26,14 +26,13 @@ func (w *wrapperTx) Commit() error { if w.span != nil { if err != nil { - w.span.AddLabels("error", true) - w.span.AddLabels("err", err.Error()) + w.span.SetStatus(tracer.SpanStatusError, err.Error()) } w.span.Finish() } if w.opts.LoggerEnabled && w.opts.Logger.V(w.opts.LoggerLevel) { - w.opts.Logger.Fields(w.opts.LoggerObserver(w.ctx, "Commit", labelUnknown, td, err)...).Log(w.ctx, w.opts.LoggerLevel) + w.opts.Logger.Fields(w.opts.LoggerObserver(w.ctx, "Commit", getCallerName(), td, err)).Log(w.ctx, w.opts.LoggerLevel) } w.ctx = nil @@ -49,14 +48,13 @@ func (w *wrapperTx) Rollback() error { if w.span != nil { if err != nil { - w.span.AddLabels("error", true) - w.span.AddLabels("err", err.Error()) + w.span.SetStatus(tracer.SpanStatusError, err.Error()) } w.span.Finish() } if w.opts.LoggerEnabled && w.opts.Logger.V(w.opts.LoggerLevel) { - w.opts.Logger.Fields(w.opts.LoggerObserver(w.ctx, "Rollback", labelUnknown, td, err)...).Log(w.ctx, w.opts.LoggerLevel) + w.opts.Logger.Fields(w.opts.LoggerObserver(w.ctx, "Rollback", getCallerName(), td, err)).Log(w.ctx, w.opts.LoggerLevel) } w.ctx = nil