From 30b5ed125301ef78f7d8d6847a65fb574b068de3 Mon Sep 17 00:00:00 2001 From: Vasiliy Tolstov Date: Sun, 25 Dec 2022 15:35:05 +0300 Subject: [PATCH 1/4] rewrite wrapper Signed-off-by: Vasiliy Tolstov --- common.go | 30 ++++++++-------- conn.go | 100 +++++++++++++++++++++++++++++++++++++++++++++++------ doc.go | 2 +- go.mod | 2 +- go.sum | 4 +-- options.go | 30 +++++++++------- stats.go | 41 ++++++++++++++++++++++ stmt.go | 58 +++++++++++++++++++++++++++---- wrapper.go | 51 --------------------------- 9 files changed, 220 insertions(+), 98 deletions(-) create mode 100644 stats.go delete mode 100644 wrapper.go diff --git a/common.go b/common.go index cfc80d7..a7c5d91 100644 --- a/common.go +++ b/common.go @@ -3,25 +3,12 @@ package wrapper import ( "database/sql/driver" "errors" + "fmt" ) // ErrUnsupported is an error returned when the underlying driver doesn't provide a given function. var ErrUnsupported = errors.New("operation unsupported by the underlying driver") -/* -// newSpan creates a new opentracing.Span instance from the given context. -func (t *tracer) newSpan(ctx context.Context) opentracing.Span { - name := t.nameFunc(ctx) - var opts []opentracing.StartSpanOption - parent := opentracing.SpanFromContext(ctx) - if parent != nil { - opts = append(opts, opentracing.ChildOf(parent.Context())) - } - span := t.t.StartSpan(name, opts...) - return span -} -*/ - // namedValueToValue converts driver arguments of NamedValue format to Value format. Implemented in the same way as in // database/sql ctxutil.go. func namedValueToValue(named []driver.NamedValue) ([]driver.Value, error) { @@ -34,3 +21,18 @@ func namedValueToValue(named []driver.NamedValue) ([]driver.Value, error) { } return dargs, nil } + +func namedValueToLabels(named []driver.NamedValue) []interface{} { + largs := make([]interface{}, len(named)*2) + var name string + for _, param := range named { + if param.Name != "" { + name = param.Name + } else { + name = fmt.Sprintf("$%d", param.Ordinal) + } + + largs = append(largs, name, param.Value) + } + return largs +} diff --git a/conn.go b/conn.go index ac1614d..4c54a8a 100644 --- a/conn.go +++ b/conn.go @@ -3,6 +3,9 @@ package wrapper import ( "context" "database/sql/driver" + "fmt" + + "go.unistack.org/micro/v3/tracer" ) // wrapperConn defines a wrapper for driver.Conn @@ -36,27 +39,62 @@ 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, "BeginTx") + var nctx context.Context + var span tracer.Span + + name := getQueryName(ctx) + if name != "" { + nctx, span = w.opts.Tracer.Start(ctx, "BeginTx "+name) + } else { + nctx, span = w.opts.Tracer.Start(ctx, "BeginTx") + } + if name == "" { + name = "unknown" + } + span.AddLabels("query", name) if connBeginTx, ok := w.conn.(driver.ConnBeginTx); ok { tx, err := connBeginTx.BeginTx(nctx, opts) if err != nil { + span.AddLabels("error", true) return nil, err } return &wrapperTx{tx: tx, opts: w.opts, span: span}, nil } - return w.conn.Begin() + tx, err := w.conn.Begin() + if err != nil { + span.AddLabels("error", true) + } + return tx, err } // PrepareContext implements driver.ConnPrepareContext PrepareContext func (w *wrapperConn) PrepareContext(ctx context.Context, query string) (driver.Stmt, error) { + var nctx context.Context + var span tracer.Span + + name := getQueryName(ctx) + if name != "" { + nctx, span = w.opts.Tracer.Start(ctx, "BeginTx "+name) + } else { + nctx, span = w.opts.Tracer.Start(ctx, "BeginTx") + } + if name == "" { + name = "unknown" + } + span.AddLabels("query", name) if connPrepareContext, ok := w.conn.(driver.ConnPrepareContext); ok { - stmt, err := connPrepareContext.PrepareContext(ctx, query) + stmt, err := connPrepareContext.PrepareContext(nctx, query) if err != nil { + span.AddLabels("error", true) return nil, err } return &wrapperStmt{stmt: stmt, opts: w.opts}, nil } - return w.conn.Prepare(query) + stmt, err := w.conn.Prepare(query) + if err != nil { + span.AddLabels("error", true) + } + return stmt, err } // Exec implements driver.Execer Exec @@ -69,17 +107,37 @@ func (w *wrapperConn) Exec(query string, args []driver.Value) (driver.Result, er // Exec implements driver.StmtExecContext ExecContext func (w *wrapperConn) ExecContext(ctx context.Context, query string, args []driver.NamedValue) (driver.Result, error) { - nctx, span := w.opts.Tracer.Start(ctx, "ExecContext") + var nctx context.Context + var span tracer.Span + name := getQueryName(ctx) + if name != "" { + nctx, span = w.opts.Tracer.Start(ctx, "ExecContext "+name) + } else { + nctx, span = w.opts.Tracer.Start(ctx, "ExecContext") + } defer span.Finish() + if name == "" { + name = "unknown" + } + span.AddLabels("args", fmt.Sprintf("%v", namedValueToLabels(args))) + span.AddLabels("query", name) if execerContext, ok := w.conn.(driver.ExecerContext); ok { - r, err := execerContext.ExecContext(nctx, query, args) - return r, err + res, err := execerContext.ExecContext(nctx, query, args) + if err != nil { + span.AddLabels("error", true) + } + return res, err } values, err := namedValueToValue(args) if err != nil { + span.AddLabels("error", true) return nil, err } - return w.Exec(query, values) + res, err := w.Exec(query, values) + if err != nil { + span.AddLabels("error", true) + } + return res, err } // Ping implements driver.Pinger Ping @@ -101,16 +159,36 @@ func (w *wrapperConn) Query(query string, args []driver.Value) (driver.Rows, err } // QueryContext implements Driver.QueryerContext QueryContext -func (w *wrapperConn) QueryContext(ctx context.Context, query string, args []driver.NamedValue) (rows driver.Rows, err error) { - nctx, span := w.opts.Tracer.Start(ctx, "QueryContext") +func (w *wrapperConn) QueryContext(ctx context.Context, query string, args []driver.NamedValue) (driver.Rows, error) { + var nctx context.Context + var span tracer.Span + name := getQueryName(ctx) + if name != "" { + nctx, span = w.opts.Tracer.Start(ctx, "QueryContext "+name) + } else { + nctx, span = w.opts.Tracer.Start(ctx, "QueryContext") + } defer span.Finish() + if name == "" { + name = "unknown" + } + span.AddLabels("args", fmt.Sprintf("%v", namedValueToLabels(args))) + span.AddLabels("query", name) if queryerContext, ok := w.conn.(driver.QueryerContext); ok { rows, err := queryerContext.QueryContext(nctx, query, args) + if err != nil { + span.AddLabels("error", true) + } return rows, err } values, err := namedValueToValue(args) if err != nil { + span.AddLabels("error", true) return nil, err } - return w.Query(query, values) + rows, err := w.Query(query, values) + if err != nil { + span.AddLabels("error", true) + } + return rows, err } diff --git a/doc.go b/doc.go index fb88238..37dc5bd 100644 --- a/doc.go +++ b/doc.go @@ -1,2 +1,2 @@ // package wrapper provides SQL driver wrapper with micro tracing, logging, metering capabilities -package wrapper +package wrapper // import go.unistack.org/micro-wrapper-sql/v3 diff --git a/go.mod b/go.mod index bc0fb22..e4c4e9b 100644 --- a/go.mod +++ b/go.mod @@ -2,4 +2,4 @@ module go.unistack.org/micro-wrapper-sql/v3 go 1.16 -require go.unistack.org/micro/v3 v3.9.15 +require go.unistack.org/micro/v3 v3.9.17 diff --git a/go.sum b/go.sum index 68036f9..206e177 100644 --- a/go.sum +++ b/go.sum @@ -74,8 +74,8 @@ github.com/xeipuuv/gojsonschema v1.2.0/go.mod h1:anYRn/JVcOK2ZgGU+IjEV4nwlhoK5sQ go.opentelemetry.io/proto/otlp v0.7.0/go.mod h1:PqfVotwruBrMGOCsRd/89rSnXhoiJIqeYNgFYFoEGnI= go.unistack.org/micro-proto/v3 v3.3.1 h1:nQ0MtWvP2G3QrpOgawVOPhpZZYkq6umTGDqs8FxJYIo= go.unistack.org/micro-proto/v3 v3.3.1/go.mod h1:cwRyv8uInM2I7EbU7O8Fx2Ls3N90Uw9UCCcq4olOdfE= -go.unistack.org/micro/v3 v3.9.15 h1:Mv1/0jsySwIvm9+IvXTYj/X4bJCNChbwtf2ZV2ZDbk8= -go.unistack.org/micro/v3 v3.9.15/go.mod h1:gI4RkJKHLPW7KV6h4+ZBOZD997MRvFRXMPQIHpozikI= +go.unistack.org/micro/v3 v3.9.17 h1:EJ9/XR9OTo/up/3aqWjaKS2YsWMA66b0dx+pc/0vIl8= +go.unistack.org/micro/v3 v3.9.17/go.mod h1:gI4RkJKHLPW7KV6h4+ZBOZD997MRvFRXMPQIHpozikI= golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w= golang.org/x/crypto v0.0.0-20200622213623-75b288015ac9/go.mod h1:LzIPMQfyMNhhGPhUkYOs5KpL4U8rLKemX1yGLhDgUto= golang.org/x/exp v0.0.0-20190121172915-509febef88a4/go.mod h1:CJ0aWSM057203Lf6IL+f9T1iT9GByDxfZKAQTCR3kQA= diff --git a/options.go b/options.go index 468f29c..014f682 100644 --- a/options.go +++ b/options.go @@ -14,8 +14,6 @@ var ( DefaultMeterStatsInterval = 5 * time.Second // DefaultMeterMetricPrefix holds default metric prefix DefaultMeterMetricPrefix = "micro_sql_" - // DefaultMeterLabelPrefix holds default label prefix - DefaultMeterLabelPrefix = "micro_" ) var ( @@ -25,7 +23,8 @@ var ( IdleConnections = "idle_connections" WaitConnections = "wait_connections" BlockedSeconds = "blocked_seconds" - MaxIdleClosed = "max_idletime_closed" + MaxIdleClosed = "max_idle_closed" + MaxIdletimeClosed = "max_idletime_closed" MaxLifetimeClosed = "max_lifetime_closed" // RequestTotal = "request_total" @@ -48,7 +47,6 @@ type Options struct { ServiceName string ServiceVersion string ServiceID string - MeterLabelPrefix string MeterMetricPrefix string MeterStatsInterval time.Duration LoggerLevel logger.Level @@ -65,12 +63,20 @@ func NewOptions(opts ...Option) Options { Tracer: tracer.DefaultTracer, MeterStatsInterval: DefaultMeterStatsInterval, MeterMetricPrefix: DefaultMeterMetricPrefix, - MeterLabelPrefix: DefaultMeterLabelPrefix, LoggerLevel: logger.ErrorLevel, } for _, o := range opts { o(&options) } + + options.Meter = options.Meter.Clone( + meter.MetricPrefix(options.MeterMetricPrefix), + meter.Labels( + labelHost, options.DatabaseHost, + labelDatabase, options.DatabaseName, + ), + ) + return options } @@ -81,13 +87,6 @@ func MetricInterval(td time.Duration) Option { } } -// LabelPrefix specifies prefix for each label -func LabelPrefix(pref string) Option { - return func(o *Options) { - o.MeterLabelPrefix = pref - } -} - // MetricPrefix specifies prefix for each metric func MetricPrefix(pref string) Option { return func(o *Options) { @@ -137,3 +136,10 @@ func QueryName(ctx context.Context, name string) context.Context { } return context.WithValue(ctx, queryNameKey{}, name) } + +func getQueryName(ctx context.Context) string { + if v, ok := ctx.Value(queryNameKey{}).(string); ok { + return v + } + return "" +} diff --git a/stats.go b/stats.go new file mode 100644 index 0000000..c184581 --- /dev/null +++ b/stats.go @@ -0,0 +1,41 @@ +package wrapper // import "go.unistack.org/micro-wrapper-sql/v3" + +import ( + "context" + "database/sql" + "time" +) + +type Statser interface { + Stats() sql.DBStats +} + +func NewStatsMeter(ctx context.Context, db Statser, opts ...Option) { + options := NewOptions(opts...) + + go func() { + ticker := time.NewTicker(options.MeterStatsInterval) + defer ticker.Stop() + + for { + select { + case <-ctx.Done(): + return + case <-ticker.C: + if db == nil { + return + } + stats := db.Stats() + options.Meter.Counter(MaxOpenConnections).Set(uint64(stats.MaxOpenConnections)) + options.Meter.Counter(OpenConnections).Set(uint64(stats.OpenConnections)) + options.Meter.Counter(InuseConnections).Set(uint64(stats.InUse)) + options.Meter.Counter(IdleConnections).Set(uint64(stats.Idle)) + options.Meter.Counter(WaitConnections).Set(uint64(stats.WaitCount)) + options.Meter.FloatCounter(BlockedSeconds).Set(stats.WaitDuration.Seconds()) + options.Meter.Counter(MaxIdleClosed).Set(uint64(stats.MaxIdleClosed)) + options.Meter.Counter(MaxIdletimeClosed).Set(uint64(stats.MaxIdleTimeClosed)) + options.Meter.Counter(MaxLifetimeClosed).Set(uint64(stats.MaxLifetimeClosed)) + } + } + }() +} diff --git a/stmt.go b/stmt.go index d2f971c..cd7a290 100644 --- a/stmt.go +++ b/stmt.go @@ -3,6 +3,9 @@ package wrapper import ( "context" "database/sql/driver" + "fmt" + + "go.unistack.org/micro/v3/tracer" ) // wrapperStmt defines a wrapper for driver.Stmt @@ -33,29 +36,72 @@ func (w *wrapperStmt) Query(args []driver.Value) (driver.Rows, error) { // ExecContext implements driver.ExecerContext ExecContext func (w *wrapperStmt) ExecContext(ctx context.Context, query string, args []driver.NamedValue) (driver.Result, error) { - nctx, span := w.opts.Tracer.Start(ctx, "ExecContext") + var nctx context.Context + var span tracer.Span + name := getQueryName(ctx) + if name != "" { + nctx, span = w.opts.Tracer.Start(ctx, "ExecContext "+name) + } else { + nctx, span = w.opts.Tracer.Start(ctx, "ExecContext") + } defer span.Finish() + if name == "" { + name = "unknown" + } + span.AddLabels("args", fmt.Sprintf("%v", namedValueToLabels(args))) + span.AddLabels("query", name) if execerContext, ok := w.stmt.(driver.ExecerContext); ok { - return execerContext.ExecContext(nctx, query, args) + res, err := execerContext.ExecContext(nctx, query, args) + if err != nil { + span.AddLabels("error", true) + } + return res, err } values, err := namedValueToValue(args) if err != nil { + span.AddLabels("error", true) return nil, err } - return w.Exec(values) + res, err := w.Exec(values) + if err != nil { + span.AddLabels("error", true) + } + return res, err } // QueryContext implements Driver.QueryerContext QueryContext -func (w *wrapperStmt) QueryContext(ctx context.Context, query string, args []driver.NamedValue) (rows driver.Rows, err error) { - nctx, span := w.opts.Tracer.Start(ctx, "QueryContext") +func (w *wrapperStmt) QueryContext(ctx context.Context, query string, args []driver.NamedValue) (driver.Rows, error) { + var nctx context.Context + var span tracer.Span + name := getQueryName(ctx) + if name != "" { + nctx, span = w.opts.Tracer.Start(ctx, "QueryContext "+name) + } else { + nctx, span = w.opts.Tracer.Start(ctx, "QueryContext") + } defer span.Finish() + if name == "" { + name = "unknown" + } + span.AddLabels("args", fmt.Sprintf("%v", namedValueToLabels(args))) + span.AddLabels("query", name) if queryerContext, ok := w.stmt.(driver.QueryerContext); ok { rows, err := queryerContext.QueryContext(nctx, query, args) + if err != nil { + span.AddLabels("error", true) + } return rows, err } values, err := namedValueToValue(args) if err != nil { + if err != nil { + span.AddLabels("error", true) + } return nil, err } - return w.Query(values) + rows, err := w.Query(values) + if err != nil { + span.AddLabels("error", true) + } + return rows, err } diff --git a/wrapper.go b/wrapper.go deleted file mode 100644 index cc40af9..0000000 --- a/wrapper.go +++ /dev/null @@ -1,51 +0,0 @@ -package wrapper // import "go.unistack.org/micro-wrapper-sql/v3" - -import ( - "context" - "database/sql" - "time" - - "go.unistack.org/micro/v3/meter" -) - -type Statser interface { - Stats() sql.DBStats -} - -func NewStatsMeter(ctx context.Context, db Statser, opts ...Option) { - options := NewOptions(opts...) - - m := options.Meter.Clone( - meter.LabelPrefix(options.MeterLabelPrefix), - meter.MetricPrefix(options.MeterMetricPrefix), - meter.Labels( - labelHost, options.DatabaseHost, - labelDatabase, options.DatabaseName, - ), - ) - - go func() { - ticker := time.NewTicker(options.MeterStatsInterval) - defer ticker.Stop() - - for { - select { - case <-ctx.Done(): - return - case <-ticker.C: - if db == nil { - return - } - stats := db.Stats() - m.Counter(MaxOpenConnections).Set(uint64(stats.MaxOpenConnections)) - m.Counter(OpenConnections).Set(uint64(stats.OpenConnections)) - m.Counter(InuseConnections).Set(uint64(stats.InUse)) - m.Counter(IdleConnections).Set(uint64(stats.Idle)) - m.Counter(WaitConnections).Set(uint64(stats.WaitCount)) - m.FloatCounter(BlockedSeconds).Set(stats.WaitDuration.Seconds()) - m.Counter(MaxIdleClosed).Set(uint64(stats.MaxIdleClosed)) - m.Counter(MaxLifetimeClosed).Set(uint64(stats.MaxLifetimeClosed)) - } - } - }() -} -- 2.45.2 From c06d87fe0adb6d9adc91a5517b9e0c753213b544 Mon Sep 17 00:00:00 2001 From: Vasiliy Tolstov Date: Sat, 31 Dec 2022 15:50:03 +0300 Subject: [PATCH 2/4] complete tracer Signed-off-by: Vasiliy Tolstov --- conn.go | 85 ++++++++++++++++++++++++--------------------------------- stmt.go | 42 ++++++++++++---------------- 2 files changed, 54 insertions(+), 73 deletions(-) diff --git a/conn.go b/conn.go index 4c54a8a..c277bab 100644 --- a/conn.go +++ b/conn.go @@ -4,8 +4,6 @@ import ( "context" "database/sql/driver" "fmt" - - "go.unistack.org/micro/v3/tracer" ) // wrapperConn defines a wrapper for driver.Conn @@ -39,23 +37,16 @@ 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) { - var nctx context.Context - var span tracer.Span - - name := getQueryName(ctx) - if name != "" { - nctx, span = w.opts.Tracer.Start(ctx, "BeginTx "+name) - } else { - nctx, span = w.opts.Tracer.Start(ctx, "BeginTx") + nctx, span := w.opts.Tracer.Start(ctx, "BeginTx") + span.AddLabels("op", "BeginTx") + if name := getQueryName(ctx); name != "" { + span.AddLabels("query", name) } - if name == "" { - name = "unknown" - } - span.AddLabels("query", name) if connBeginTx, ok := w.conn.(driver.ConnBeginTx); ok { tx, err := connBeginTx.BeginTx(nctx, opts) if err != nil { span.AddLabels("error", true) + span.AddLabels("err", err.Error()) return nil, err } return &wrapperTx{tx: tx, opts: w.opts, span: span}, nil @@ -63,29 +54,23 @@ func (w *wrapperConn) BeginTx(ctx context.Context, opts driver.TxOptions) (drive tx, err := w.conn.Begin() if err != nil { span.AddLabels("error", true) + span.AddLabels("err", err.Error()) } return tx, err } // PrepareContext implements driver.ConnPrepareContext PrepareContext func (w *wrapperConn) PrepareContext(ctx context.Context, query string) (driver.Stmt, error) { - var nctx context.Context - var span tracer.Span - - name := getQueryName(ctx) - if name != "" { - nctx, span = w.opts.Tracer.Start(ctx, "BeginTx "+name) - } else { - nctx, span = w.opts.Tracer.Start(ctx, "BeginTx") + nctx, span := w.opts.Tracer.Start(ctx, "PrepareContext") + span.AddLabels("op", "PrepareContext") + if name := getQueryName(ctx); name != "" { + span.AddLabels("query", name) } - if name == "" { - name = "unknown" - } - span.AddLabels("query", name) if connPrepareContext, ok := w.conn.(driver.ConnPrepareContext); ok { stmt, err := connPrepareContext.PrepareContext(nctx, query) if err != nil { span.AddLabels("error", true) + span.AddLabels("err", err.Error()) return nil, err } return &wrapperStmt{stmt: stmt, opts: w.opts}, nil @@ -93,6 +78,7 @@ func (w *wrapperConn) PrepareContext(ctx context.Context, query string) (driver. stmt, err := w.conn.Prepare(query) if err != nil { span.AddLabels("error", true) + span.AddLabels("err", err.Error()) } return stmt, err } @@ -107,35 +93,33 @@ func (w *wrapperConn) Exec(query string, args []driver.Value) (driver.Result, er // Exec implements driver.StmtExecContext ExecContext func (w *wrapperConn) ExecContext(ctx context.Context, query string, args []driver.NamedValue) (driver.Result, error) { - var nctx context.Context - var span tracer.Span - name := getQueryName(ctx) - if name != "" { - nctx, span = w.opts.Tracer.Start(ctx, "ExecContext "+name) - } else { - nctx, span = w.opts.Tracer.Start(ctx, "ExecContext") + nctx, span := w.opts.Tracer.Start(ctx, "ExecContext") + span.AddLabels("op", "ExecContext") + if name := getQueryName(ctx); name != "" { + span.AddLabels("query", name) } defer span.Finish() - if name == "" { - name = "unknown" + if len(args) > 0 { + span.AddLabels("args", fmt.Sprintf("%v", namedValueToLabels(args))) } - span.AddLabels("args", fmt.Sprintf("%v", namedValueToLabels(args))) - span.AddLabels("query", name) if execerContext, ok := w.conn.(driver.ExecerContext); ok { res, err := execerContext.ExecContext(nctx, query, args) if err != nil { span.AddLabels("error", true) + span.AddLabels("err", err.Error()) } return res, err } values, err := namedValueToValue(args) if err != nil { span.AddLabels("error", true) + span.AddLabels("err", err.Error()) return nil, err } res, err := w.Exec(query, values) if err != nil { span.AddLabels("error", true) + span.AddLabels("err", err.Error()) } return res, err } @@ -145,7 +129,12 @@ func (w *wrapperConn) Ping(ctx context.Context) error { if pinger, ok := w.conn.(driver.Pinger); ok { nctx, span := w.opts.Tracer.Start(ctx, "Ping") defer span.Finish() - return pinger.Ping(nctx) + err := pinger.Ping(nctx) + if err != nil { + span.AddLabels("error", true) + span.AddLabels("err", err.Error()) + return err + } } return ErrUnsupported } @@ -160,35 +149,33 @@ func (w *wrapperConn) Query(query string, args []driver.Value) (driver.Rows, err // QueryContext implements Driver.QueryerContext QueryContext func (w *wrapperConn) QueryContext(ctx context.Context, query string, args []driver.NamedValue) (driver.Rows, error) { - var nctx context.Context - var span tracer.Span - name := getQueryName(ctx) - if name != "" { - nctx, span = w.opts.Tracer.Start(ctx, "QueryContext "+name) - } else { - nctx, span = w.opts.Tracer.Start(ctx, "QueryContext") + nctx, span := w.opts.Tracer.Start(ctx, "QueryContext") + span.AddLabels("op", "QueryContext") + if name := getQueryName(ctx); name != "" { + span.AddLabels("query", name) } defer span.Finish() - if name == "" { - name = "unknown" + if len(args) > 0 { + span.AddLabels("args", fmt.Sprintf("%v", namedValueToLabels(args))) } - span.AddLabels("args", fmt.Sprintf("%v", namedValueToLabels(args))) - span.AddLabels("query", name) if queryerContext, ok := w.conn.(driver.QueryerContext); ok { rows, err := queryerContext.QueryContext(nctx, query, args) if err != nil { span.AddLabels("error", true) + span.AddLabels("err", err.Error()) } return rows, err } values, err := namedValueToValue(args) if err != nil { span.AddLabels("error", true) + span.AddLabels("err", err.Error()) return nil, err } rows, err := w.Query(query, values) if err != nil { span.AddLabels("error", true) + span.AddLabels("err", err.Error()) } return rows, err } diff --git a/stmt.go b/stmt.go index cd7a290..2f32147 100644 --- a/stmt.go +++ b/stmt.go @@ -4,8 +4,6 @@ import ( "context" "database/sql/driver" "fmt" - - "go.unistack.org/micro/v3/tracer" ) // wrapperStmt defines a wrapper for driver.Stmt @@ -36,59 +34,53 @@ func (w *wrapperStmt) Query(args []driver.Value) (driver.Rows, error) { // ExecContext implements driver.ExecerContext ExecContext func (w *wrapperStmt) ExecContext(ctx context.Context, query string, args []driver.NamedValue) (driver.Result, error) { - var nctx context.Context - var span tracer.Span - name := getQueryName(ctx) - if name != "" { - nctx, span = w.opts.Tracer.Start(ctx, "ExecContext "+name) - } else { - nctx, span = w.opts.Tracer.Start(ctx, "ExecContext") + nctx, span := w.opts.Tracer.Start(ctx, "ExecContext") + span.AddLabels("op", "ExecContext") + if name := getQueryName(ctx); name != "" { + span.AddLabels("query", name) } defer span.Finish() - if name == "" { - name = "unknown" + if len(args) > 0 { + span.AddLabels("args", fmt.Sprintf("%v", namedValueToLabels(args))) } - span.AddLabels("args", fmt.Sprintf("%v", namedValueToLabels(args))) - span.AddLabels("query", name) if execerContext, ok := w.stmt.(driver.ExecerContext); ok { res, err := execerContext.ExecContext(nctx, query, args) if err != nil { span.AddLabels("error", true) + span.AddLabels("err", err.Error()) } return res, err } values, err := namedValueToValue(args) if err != nil { span.AddLabels("error", true) + span.AddLabels("err", err.Error()) return nil, err } res, err := w.Exec(values) if err != nil { span.AddLabels("error", true) + span.AddLabels("err", err.Error()) } return res, err } // QueryContext implements Driver.QueryerContext QueryContext func (w *wrapperStmt) QueryContext(ctx context.Context, query string, args []driver.NamedValue) (driver.Rows, error) { - var nctx context.Context - var span tracer.Span - name := getQueryName(ctx) - if name != "" { - nctx, span = w.opts.Tracer.Start(ctx, "QueryContext "+name) - } else { - nctx, span = w.opts.Tracer.Start(ctx, "QueryContext") + nctx, span := w.opts.Tracer.Start(ctx, "QueryContext") + span.AddLabels("op", "QueryContext") + if name := getQueryName(ctx); name != "" { + span.AddLabels("query", name) } defer span.Finish() - if name == "" { - name = "unknown" + if len(args) > 0 { + span.AddLabels("args", fmt.Sprintf("%v", namedValueToLabels(args))) } - span.AddLabels("args", fmt.Sprintf("%v", namedValueToLabels(args))) - span.AddLabels("query", name) if queryerContext, ok := w.stmt.(driver.QueryerContext); ok { rows, err := queryerContext.QueryContext(nctx, query, args) if err != nil { span.AddLabels("error", true) + span.AddLabels("err", err.Error()) } return rows, err } @@ -96,12 +88,14 @@ func (w *wrapperStmt) QueryContext(ctx context.Context, query string, args []dri if err != nil { if err != nil { span.AddLabels("error", true) + span.AddLabels("err", err.Error()) } return nil, err } rows, err := w.Query(values) if err != nil { span.AddLabels("error", true) + span.AddLabels("err", err.Error()) } return rows, err } -- 2.45.2 From b2eb8e6c5cd390e6dc4d707597f92776eff533b6 Mon Sep 17 00:00:00 2001 From: Vasiliy Tolstov Date: Thu, 5 Jan 2023 16:03:21 +0300 Subject: [PATCH 3/4] complete meter Signed-off-by: Vasiliy Tolstov --- common.go | 1 + conn.go | 167 ++++++++++++++++++++++++++++++++++++++++++++++++----- options.go | 20 +++++-- stmt.go | 73 +++++++++++++++++++---- tx.go | 6 +- 5 files changed, 235 insertions(+), 32 deletions(-) diff --git a/common.go b/common.go index a7c5d91..3b59ff8 100644 --- a/common.go +++ b/common.go @@ -22,6 +22,7 @@ func namedValueToValue(named []driver.NamedValue) ([]driver.Value, error) { return dargs, nil } +// namedValueToLabels convert driver arguments to interface{} slice func namedValueToLabels(named []driver.NamedValue) []interface{} { largs := make([]interface{}, len(named)*2) var name string diff --git a/conn.go b/conn.go index c277bab..632760b 100644 --- a/conn.go +++ b/conn.go @@ -4,6 +4,7 @@ import ( "context" "database/sql/driver" "fmt" + "time" ) // wrapperConn defines a wrapper for driver.Conn @@ -14,79 +15,160 @@ type wrapperConn struct { // Prepare implements driver.Conn Prepare func (w *wrapperConn) Prepare(query string) (driver.Stmt, error) { + labels := []string{labelMethod, "Prepare", labelQuery, labelUnknown} + ts := time.Now() stmt, err := w.conn.Prepare(query) + te := time.Since(ts).Seconds() if err != nil { + 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) return nil, err } + 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) return &wrapperStmt{stmt: stmt, opts: w.opts}, nil } // Close implements driver.Conn Close func (w *wrapperConn) Close() error { - return w.conn.Close() + labels := []string{labelMethod, "Close"} + ts := time.Now() + err := w.conn.Close() + te := time.Since(ts).Seconds() + if err != nil { + w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelFailure)...).Inc() + } 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) + return err } // Begin implements driver.Conn Begin func (w *wrapperConn) Begin() (driver.Tx, error) { + labels := []string{labelMethod, "Begin"} + ts := time.Now() + // nolint:staticcheck tx, err := w.conn.Begin() + te := time.Since(ts).Seconds() if err != nil { + 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) return nil, err } + 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) return &wrapperTx{tx: tx, opts: w.opts}, nil } // 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, "BeginTx") - span.AddLabels("op", "BeginTx") - if name := getQueryName(ctx); name != "" { + span.AddLabels("method", "BeginTx") + name := getQueryName(ctx) + if name != "" { span.AddLabels("query", name) + } else { + name = labelUnknown } + labels := []string{labelMethod, "BeginTx", labelQuery, name} if connBeginTx, ok := w.conn.(driver.ConnBeginTx); ok { + ts := time.Now() tx, err := connBeginTx.BeginTx(nctx, opts) + te := time.Since(ts).Seconds() if err != nil { + 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()) return nil, err } + w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelSuccess)...).Inc() return &wrapperTx{tx: tx, opts: w.opts, span: span}, nil } + ts := time.Now() + // nolint:staticcheck tx, err := w.conn.Begin() + te := time.Since(ts).Seconds() if err != nil { + 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()) } - return tx, err + 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) + return tx, nil } // PrepareContext implements driver.ConnPrepareContext PrepareContext func (w *wrapperConn) PrepareContext(ctx context.Context, query string) (driver.Stmt, error) { nctx, span := w.opts.Tracer.Start(ctx, "PrepareContext") - span.AddLabels("op", "PrepareContext") - if name := getQueryName(ctx); name != "" { + span.AddLabels("method", "PrepareContext") + name := getQueryName(ctx) + if name != "" { span.AddLabels("query", name) + } else { + name = labelUnknown } + labels := []string{labelMethod, "PrepareContext", labelQuery, name} if connPrepareContext, ok := w.conn.(driver.ConnPrepareContext); ok { + ts := time.Now() stmt, err := connPrepareContext.PrepareContext(nctx, query) + te := time.Since(ts).Seconds() if err != nil { + 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()) return nil, err } + 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) return &wrapperStmt{stmt: stmt, opts: w.opts}, nil } + ts := time.Now() stmt, err := w.conn.Prepare(query) + te := time.Since(ts).Seconds() if err != nil { + 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()) } - return stmt, err + 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) + return stmt, nil } // Exec implements driver.Execer Exec func (w *wrapperConn) Exec(query string, args []driver.Value) (driver.Result, error) { + // nolint:staticcheck + labels := []string{labelMethod, "Exec", labelQuery, labelUnknown} if execer, ok := w.conn.(driver.Execer); ok { - return execer.Exec(query, args) + ts := time.Now() + res, err := execer.Exec(query, args) + te := time.Since(ts).Seconds() + if err != nil { + w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelFailure)...).Inc() + } 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) + return res, err } return nil, ErrUnsupported } @@ -94,20 +176,32 @@ func (w *wrapperConn) Exec(query string, args []driver.Value) (driver.Result, er // Exec implements driver.StmtExecContext ExecContext func (w *wrapperConn) ExecContext(ctx context.Context, query string, args []driver.NamedValue) (driver.Result, error) { nctx, span := w.opts.Tracer.Start(ctx, "ExecContext") - span.AddLabels("op", "ExecContext") - if name := getQueryName(ctx); name != "" { + span.AddLabels("method", "ExecContext") + name := getQueryName(ctx) + if name != "" { span.AddLabels("query", name) + } else { + name = labelUnknown } defer span.Finish() if len(args) > 0 { span.AddLabels("args", fmt.Sprintf("%v", namedValueToLabels(args))) } + labels := []string{labelMethod, "ExecContext", labelQuery, name} if execerContext, ok := w.conn.(driver.ExecerContext); ok { + ts := time.Now() res, err := execerContext.ExecContext(nctx, query, args) + te := time.Since(ts).Seconds() if err != nil { + w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelFailure)...).Inc() span.AddLabels("error", true) span.AddLabels("err", err.Error()) + } else { + w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelSuccess)...).Inc() } + 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) return res, err } values, err := namedValueToValue(args) @@ -116,11 +210,19 @@ func (w *wrapperConn) ExecContext(ctx context.Context, query string, args []driv span.AddLabels("err", err.Error()) return nil, err } + ts := time.Now() + // nolint:staticcheck res, err := w.Exec(query, values) + te := time.Since(ts).Seconds() if err != nil { + w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelFailure)...).Inc() span.AddLabels("error", true) span.AddLabels("err", 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) return res, err } @@ -129,20 +231,40 @@ func (w *wrapperConn) Ping(ctx context.Context) error { if pinger, ok := w.conn.(driver.Pinger); ok { nctx, span := w.opts.Tracer.Start(ctx, "Ping") defer span.Finish() + labels := []string{labelMethod, "Ping"} + ts := time.Now() err := pinger.Ping(nctx) + te := time.Since(ts).Seconds() if err != nil { + w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelFailure)...).Inc() span.AddLabels("error", true) span.AddLabels("err", err.Error()) return err + } 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) } return ErrUnsupported } // Query implements driver.Queryer Query func (w *wrapperConn) Query(query string, args []driver.Value) (driver.Rows, error) { + // nolint:staticcheck if queryer, ok := w.conn.(driver.Queryer); ok { - return queryer.Query(query, args) + labels := []string{labelMethod, "Query", labelQuery, labelUnknown} + ts := time.Now() + rows, err := queryer.Query(query, args) + te := time.Since(ts).Seconds() + if err != nil { + w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelFailure)...).Inc() + } 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) + return rows, err } return nil, ErrUnsupported } @@ -150,20 +272,31 @@ func (w *wrapperConn) Query(query string, args []driver.Value) (driver.Rows, err // QueryContext implements Driver.QueryerContext QueryContext func (w *wrapperConn) QueryContext(ctx context.Context, query string, args []driver.NamedValue) (driver.Rows, error) { nctx, span := w.opts.Tracer.Start(ctx, "QueryContext") - span.AddLabels("op", "QueryContext") - if name := getQueryName(ctx); name != "" { + span.AddLabels("method", "QueryContext") + name := getQueryName(ctx) + if name != "" { span.AddLabels("query", name) + } else { + name = labelUnknown } defer span.Finish() if len(args) > 0 { span.AddLabels("args", fmt.Sprintf("%v", namedValueToLabels(args))) } + labels := []string{labelMethod, "QueryContext", labelQuery, name} if queryerContext, ok := w.conn.(driver.QueryerContext); ok { + ts := time.Now() rows, err := queryerContext.QueryContext(nctx, query, args) + te := time.Since(ts).Seconds() if err != nil { + w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelFailure)...).Inc() span.AddLabels("error", true) span.AddLabels("err", 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) return rows, err } values, err := namedValueToValue(args) @@ -172,10 +305,18 @@ func (w *wrapperConn) QueryContext(ctx context.Context, query string, args []dri span.AddLabels("err", err.Error()) return nil, err } + ts := time.Now() + // nolint:staticcheck rows, err := w.Query(query, values) + te := time.Since(ts).Seconds() if err != nil { + w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelFailure)...).Inc() span.AddLabels("error", true) span.AddLabels("err", 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) return rows, err } diff --git a/options.go b/options.go index 014f682..3f0301a 100644 --- a/options.go +++ b/options.go @@ -27,10 +27,14 @@ var ( MaxIdletimeClosed = "max_idletime_closed" MaxLifetimeClosed = "max_lifetime_closed" - // RequestTotal = "request_total" - // RequestLatencyMicroseconds = "request_latency_microseconds" - // RequestDurationSeconds = "request_duration_seconds" + meterRequestTotal = "request_total" + meterRequestLatencyMicroseconds = "request_latency_microseconds" + meterRequestDurationSeconds = "request_duration_seconds" + labelUnknown = "unknown" + labelQuery = "query" + labelMethod = "method" + labelStatus = "status" labelSuccess = "success" labelFailure = "failure" labelHost = "db_host" @@ -44,9 +48,6 @@ type Options struct { Tracer tracer.Tracer DatabaseHost string DatabaseName string - ServiceName string - ServiceVersion string - ServiceID string MeterMetricPrefix string MeterStatsInterval time.Duration LoggerLevel logger.Level @@ -120,6 +121,13 @@ func Logger(l logger.Logger) Option { } } +// LoggerLevel passes logger.Level option +func LoggerLevel(lvl logger.Level) Option { + return func(o *Options) { + o.LoggerLevel = lvl + } +} + // Tracer passes tracer.Tracer to wrapper func Tracer(t tracer.Tracer) Option { return func(o *Options) { diff --git a/stmt.go b/stmt.go index 2f32147..0aade11 100644 --- a/stmt.go +++ b/stmt.go @@ -4,6 +4,7 @@ import ( "context" "database/sql/driver" "fmt" + "time" ) // wrapperStmt defines a wrapper for driver.Stmt @@ -14,7 +15,18 @@ type wrapperStmt struct { // Close implements driver.Stmt Close func (w *wrapperStmt) Close() error { - return w.stmt.Close() + labels := []string{labelMethod, "Close"} + ts := time.Now() + err := w.stmt.Close() + te := time.Since(ts).Seconds() + if err != nil { + w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelFailure)...).Inc() + } 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) + return err } // NumInput implements driver.Stmt NumInput @@ -24,39 +36,76 @@ func (w *wrapperStmt) NumInput() int { // Exec implements driver.Stmt Exec func (w *wrapperStmt) Exec(args []driver.Value) (driver.Result, error) { - return w.stmt.Exec(args) + // nolint:staticcheck + labels := []string{labelMethod, "Exec"} + ts := time.Now() + res, err := w.stmt.Exec(args) + te := time.Since(ts).Seconds() + if err != nil { + w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelFailure)...).Inc() + } 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) + return res, err } // Query implements driver.Stmt Query func (w *wrapperStmt) Query(args []driver.Value) (driver.Rows, error) { - return w.stmt.Query(args) + labels := []string{labelMethod, "Query"} + ts := time.Now() + // nolint:staticcheck + rows, err := w.stmt.Query(args) + te := time.Since(ts).Seconds() + if err != nil { + w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelFailure)...).Inc() + } 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) + return rows, err } // ExecContext implements driver.ExecerContext ExecContext func (w *wrapperStmt) ExecContext(ctx context.Context, query string, args []driver.NamedValue) (driver.Result, error) { nctx, span := w.opts.Tracer.Start(ctx, "ExecContext") - span.AddLabels("op", "ExecContext") - if name := getQueryName(ctx); name != "" { + span.AddLabels("method", "ExecContext") + name := getQueryName(ctx) + if name != "" { span.AddLabels("query", name) + } else { + name = labelUnknown } defer span.Finish() if len(args) > 0 { span.AddLabels("args", fmt.Sprintf("%v", namedValueToLabels(args))) } + labels := []string{labelMethod, "ExecContext", labelQuery, name} if execerContext, ok := w.stmt.(driver.ExecerContext); ok { + ts := time.Now() res, err := execerContext.ExecContext(nctx, query, args) + te := time.Since(ts).Seconds() if err != nil { + w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelFailure)...).Inc() span.AddLabels("error", true) span.AddLabels("err", 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) return res, err } 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()) return nil, err } + // nolint:staticcheck res, err := w.Exec(values) if err != nil { span.AddLabels("error", true) @@ -68,9 +117,12 @@ func (w *wrapperStmt) ExecContext(ctx context.Context, query string, args []driv // QueryContext implements Driver.QueryerContext QueryContext func (w *wrapperStmt) QueryContext(ctx context.Context, query string, args []driver.NamedValue) (driver.Rows, error) { nctx, span := w.opts.Tracer.Start(ctx, "QueryContext") - span.AddLabels("op", "QueryContext") - if name := getQueryName(ctx); name != "" { + span.AddLabels("method", "QueryContext") + name := getQueryName(ctx) + if name != "" { span.AddLabels("query", name) + } else { + name = labelUnknown } defer span.Finish() if len(args) > 0 { @@ -86,12 +138,11 @@ func (w *wrapperStmt) QueryContext(ctx context.Context, query string, args []dri } values, err := namedValueToValue(args) if err != nil { - if err != nil { - span.AddLabels("error", true) - span.AddLabels("err", err.Error()) - } + span.AddLabels("error", true) + span.AddLabels("err", err.Error()) return nil, err } + // nolint:staticcheck rows, err := w.Query(values) if err != nil { span.AddLabels("error", true) diff --git a/tx.go b/tx.go index f0fbd50..9f23047 100644 --- a/tx.go +++ b/tx.go @@ -18,7 +18,8 @@ func (w *wrapperTx) Commit() error { if w.span != nil { defer w.span.Finish() } - return w.tx.Commit() + err := w.tx.Commit() + return err } // Rollback implements driver.Tx Rollback @@ -26,5 +27,6 @@ func (w *wrapperTx) Rollback() error { if w.span != nil { defer w.span.Finish() } - return w.tx.Rollback() + err := w.tx.Rollback() + return err } -- 2.45.2 From 43ee6ceb81212101dbf83ab3b34d577a11496cb8 Mon Sep 17 00:00:00 2001 From: Vasiliy Tolstov Date: Fri, 6 Jan 2023 23:24:39 +0300 Subject: [PATCH 4/4] add logger Signed-off-by: Vasiliy Tolstov --- conn.go | 136 +++++++++++++++++++++++++++++++++++++++++++---------- driver.go | 10 ++++ go.mod | 2 +- go.sum | 4 +- options.go | 31 ++++++++++++ stmt.go | 88 ++++++++++++++++++++++++++++++---- tx.go | 16 +++++++ 7 files changed, 251 insertions(+), 36 deletions(-) diff --git a/conn.go b/conn.go index 632760b..f9612db 100644 --- a/conn.go +++ b/conn.go @@ -18,16 +18,26 @@ func (w *wrapperConn) Prepare(query string) (driver.Stmt, error) { labels := []string{labelMethod, "Prepare", labelQuery, labelUnknown} ts := time.Now() stmt, err := w.conn.Prepare(query) - te := time.Since(ts).Seconds() + td := time.Since(ts) + te := td.Seconds() if err != nil { 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.Fields(w.opts.LoggerObserver(context.TODO(), "Prepare", labelUnknown, td, err)...).Log(context.TODO(), w.opts.LoggerLevel) + } return nil, err } 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.Fields(w.opts.LoggerObserver(context.TODO(), "QueryContext", labelUnknown, td, err)...).Log(context.TODO(), w.opts.LoggerLevel) + } + return &wrapperStmt{stmt: stmt, opts: w.opts}, nil } @@ -36,7 +46,8 @@ func (w *wrapperConn) Close() error { labels := []string{labelMethod, "Close"} ts := time.Now() err := w.conn.Close() - te := time.Since(ts).Seconds() + td := time.Since(ts) + te := td.Seconds() if err != nil { w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelFailure)...).Inc() } else { @@ -44,6 +55,11 @@ func (w *wrapperConn) Close() error { } w.opts.Meter.Summary(meterRequestLatencyMicroseconds, labels...).Update(te) w.opts.Meter.Histogram(meterRequestDurationSeconds, labels...).Update(te) + + if w.opts.LoggerEnabled { + w.opts.Logger.Fields(w.opts.LoggerObserver(context.TODO(), "QueryContext", labelUnknown, td, err)...).Log(context.TODO(), w.opts.LoggerLevel) + } + return err } @@ -53,16 +69,23 @@ func (w *wrapperConn) Begin() (driver.Tx, error) { ts := time.Now() // nolint:staticcheck tx, err := w.conn.Begin() - te := time.Since(ts).Seconds() + td := time.Since(ts) + te := td.Seconds() if err != nil { 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.Fields(w.opts.LoggerObserver(context.TODO(), "Begin", labelUnknown, td, err)...).Log(context.TODO(), w.opts.LoggerLevel) + } return nil, err } 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.Fields(w.opts.LoggerObserver(context.TODO(), "Begin", labelUnknown, td, err)...).Log(context.TODO(), w.opts.LoggerLevel) + } return &wrapperTx{tx: tx, opts: w.opts}, nil } @@ -80,22 +103,30 @@ func (w *wrapperConn) BeginTx(ctx context.Context, opts driver.TxOptions) (drive if connBeginTx, ok := w.conn.(driver.ConnBeginTx); ok { ts := time.Now() tx, err := connBeginTx.BeginTx(nctx, opts) - te := time.Since(ts).Seconds() + td := time.Since(ts) + te := td.Seconds() if err != nil { 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()) + if w.opts.LoggerEnabled { + w.opts.Logger.Fields(w.opts.LoggerObserver(context.TODO(), "BeginTx", name, td, err)...).Log(context.TODO(), w.opts.LoggerLevel) + } return nil, err } w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelSuccess)...).Inc() + if w.opts.LoggerEnabled { + w.opts.Logger.Fields(w.opts.LoggerObserver(context.TODO(), "BeginTx", name, td, err)...).Log(context.TODO(), w.opts.LoggerLevel) + } return &wrapperTx{tx: tx, opts: w.opts, span: span}, nil } ts := time.Now() // nolint:staticcheck tx, err := w.conn.Begin() - te := time.Since(ts).Seconds() + td := time.Since(ts) + te := td.Seconds() if err != nil { w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelFailure)...).Inc() w.opts.Meter.Summary(meterRequestLatencyMicroseconds, labels...).Update(te) @@ -106,6 +137,9 @@ func (w *wrapperConn) BeginTx(ctx context.Context, opts driver.TxOptions) (drive 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.Fields(w.opts.LoggerObserver(context.TODO(), "BeginTx", name, td, err)...).Log(context.TODO(), w.opts.LoggerLevel) + } return tx, nil } @@ -120,26 +154,34 @@ func (w *wrapperConn) PrepareContext(ctx context.Context, query string) (driver. name = labelUnknown } labels := []string{labelMethod, "PrepareContext", labelQuery, name} - if connPrepareContext, ok := w.conn.(driver.ConnPrepareContext); ok { + if conn, ok := w.conn.(driver.ConnPrepareContext); ok { ts := time.Now() - stmt, err := connPrepareContext.PrepareContext(nctx, query) - te := time.Since(ts).Seconds() + stmt, err := conn.PrepareContext(nctx, query) + td := time.Since(ts) + te := td.Seconds() if err != nil { 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()) + if w.opts.LoggerEnabled { + w.opts.Logger.Fields(w.opts.LoggerObserver(context.TODO(), "PrepareContext", name, td, err)...).Log(context.TODO(), w.opts.LoggerLevel) + } return nil, err } 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.Fields(w.opts.LoggerObserver(context.TODO(), "PrepareContext", name, td, err)...).Log(context.TODO(), w.opts.LoggerLevel) + } return &wrapperStmt{stmt: stmt, opts: w.opts}, nil } ts := time.Now() stmt, err := w.conn.Prepare(query) - te := time.Since(ts).Seconds() + td := time.Since(ts) + te := td.Seconds() if err != nil { w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelFailure)...).Inc() w.opts.Meter.Summary(meterRequestLatencyMicroseconds, labels...).Update(te) @@ -150,6 +192,9 @@ func (w *wrapperConn) PrepareContext(ctx context.Context, query string) (driver. 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.Fields(w.opts.LoggerObserver(context.TODO(), "PrepareContext", name, td, err)...).Log(context.TODO(), w.opts.LoggerLevel) + } return stmt, nil } @@ -160,7 +205,8 @@ func (w *wrapperConn) Exec(query string, args []driver.Value) (driver.Result, er if execer, ok := w.conn.(driver.Execer); ok { ts := time.Now() res, err := execer.Exec(query, args) - te := time.Since(ts).Seconds() + td := time.Since(ts) + te := td.Seconds() if err != nil { w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelFailure)...).Inc() } else { @@ -168,8 +214,14 @@ 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.Fields(w.opts.LoggerObserver(context.TODO(), "Exec", labelUnknown, td, err)...).Log(context.TODO(), w.opts.LoggerLevel) + } return res, err } + if w.opts.LoggerEnabled { + w.opts.Logger.Fields(w.opts.LoggerObserver(context.TODO(), "Exec", labelUnknown, 0, ErrUnsupported)...).Log(context.TODO(), w.opts.LoggerLevel) + } return nil, ErrUnsupported } @@ -188,10 +240,11 @@ func (w *wrapperConn) ExecContext(ctx context.Context, query string, args []driv span.AddLabels("args", fmt.Sprintf("%v", namedValueToLabels(args))) } labels := []string{labelMethod, "ExecContext", labelQuery, name} - if execerContext, ok := w.conn.(driver.ExecerContext); ok { + if conn, ok := w.conn.(driver.ExecerContext); ok { ts := time.Now() - res, err := execerContext.ExecContext(nctx, query, args) - te := time.Since(ts).Seconds() + res, err := conn.ExecContext(nctx, query, args) + td := time.Since(ts) + te := td.Seconds() if err != nil { w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelFailure)...).Inc() span.AddLabels("error", true) @@ -202,18 +255,25 @@ func (w *wrapperConn) ExecContext(ctx context.Context, query string, args []driv 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.Fields(w.opts.LoggerObserver(context.TODO(), "ExecContext", name, td, err)...).Log(context.TODO(), w.opts.LoggerLevel) + } return res, err } values, err := namedValueToValue(args) if err != nil { span.AddLabels("error", true) span.AddLabels("err", err.Error()) + if w.opts.LoggerEnabled { + w.opts.Logger.Fields(w.opts.LoggerObserver(context.TODO(), "ExecContext", labelUnknown, 0, err)...).Log(context.TODO(), w.opts.LoggerLevel) + } return nil, err } ts := time.Now() // nolint:staticcheck res, err := w.Exec(query, values) - te := time.Since(ts).Seconds() + td := time.Since(ts) + te := td.Seconds() if err != nil { w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelFailure)...).Inc() span.AddLabels("error", true) @@ -223,22 +283,29 @@ 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.Fields(w.opts.LoggerObserver(context.TODO(), "ExecContext", name, td, err)...).Log(context.TODO(), w.opts.LoggerLevel) + } return res, err } // Ping implements driver.Pinger Ping func (w *wrapperConn) Ping(ctx context.Context) error { - if pinger, ok := w.conn.(driver.Pinger); ok { + if conn, ok := w.conn.(driver.Pinger); ok { nctx, span := w.opts.Tracer.Start(ctx, "Ping") defer span.Finish() labels := []string{labelMethod, "Ping"} ts := time.Now() - err := pinger.Ping(nctx) - te := time.Since(ts).Seconds() + err := conn.Ping(nctx) + td := time.Since(ts) + 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()) + if w.opts.LoggerEnabled { + w.opts.Logger.Fields(w.opts.LoggerObserver(context.TODO(), "Ping", labelUnknown, td, err)...).Log(context.TODO(), w.opts.LoggerLevel) + } return err } else { w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelSuccess)...).Inc() @@ -246,17 +313,21 @@ func (w *wrapperConn) Ping(ctx context.Context) error { w.opts.Meter.Summary(meterRequestLatencyMicroseconds, labels...).Update(te) w.opts.Meter.Histogram(meterRequestDurationSeconds, labels...).Update(te) } + if w.opts.LoggerEnabled { + w.opts.Logger.Fields(w.opts.LoggerObserver(context.TODO(), "Ping", labelUnknown, 0, ErrUnsupported)...).Log(context.TODO(), w.opts.LoggerLevel) + } return ErrUnsupported } // Query implements driver.Queryer Query func (w *wrapperConn) Query(query string, args []driver.Value) (driver.Rows, error) { // nolint:staticcheck - if queryer, ok := w.conn.(driver.Queryer); ok { + if conn, ok := w.conn.(driver.Queryer); ok { labels := []string{labelMethod, "Query", labelQuery, labelUnknown} ts := time.Now() - rows, err := queryer.Query(query, args) - te := time.Since(ts).Seconds() + rows, err := conn.Query(query, args) + td := time.Since(ts) + te := td.Seconds() if err != nil { w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelFailure)...).Inc() } else { @@ -264,8 +335,14 @@ 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.Fields(w.opts.LoggerObserver(context.TODO(), "Query", labelUnknown, td, err)...).Log(context.TODO(), w.opts.LoggerLevel) + } return rows, err } + if w.opts.LoggerEnabled { + w.opts.Logger.Fields(w.opts.LoggerObserver(context.TODO(), "Query", labelUnknown, 0, ErrUnsupported)...).Log(context.TODO(), w.opts.LoggerLevel) + } return nil, ErrUnsupported } @@ -284,10 +361,11 @@ func (w *wrapperConn) QueryContext(ctx context.Context, query string, args []dri span.AddLabels("args", fmt.Sprintf("%v", namedValueToLabels(args))) } labels := []string{labelMethod, "QueryContext", labelQuery, name} - if queryerContext, ok := w.conn.(driver.QueryerContext); ok { + if conn, ok := w.conn.(driver.QueryerContext); ok { ts := time.Now() - rows, err := queryerContext.QueryContext(nctx, query, args) - te := time.Since(ts).Seconds() + rows, err := conn.QueryContext(nctx, query, args) + td := time.Since(ts) + te := td.Seconds() if err != nil { w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelFailure)...).Inc() span.AddLabels("error", true) @@ -297,18 +375,25 @@ func (w *wrapperConn) QueryContext(ctx context.Context, query string, args []dri } w.opts.Meter.Summary(meterRequestLatencyMicroseconds, labels...).Update(te) w.opts.Meter.Histogram(meterRequestDurationSeconds, labels...).Update(te) + if w.opts.LoggerEnabled { + w.opts.Logger.Fields(w.opts.LoggerObserver(context.TODO(), "QueryContext", name, td, err)...).Log(context.TODO(), w.opts.LoggerLevel) + } return rows, err } values, err := namedValueToValue(args) if err != nil { span.AddLabels("error", true) span.AddLabels("err", err.Error()) + if w.opts.LoggerEnabled { + w.opts.Logger.Fields(w.opts.LoggerObserver(context.TODO(), "QueryContext", name, 0, err)...).Log(context.TODO(), w.opts.LoggerLevel) + } return nil, err } ts := time.Now() // nolint:staticcheck rows, err := w.Query(query, values) - te := time.Since(ts).Seconds() + td := time.Since(ts) + te := td.Seconds() if err != nil { w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelFailure)...).Inc() span.AddLabels("error", true) @@ -318,5 +403,8 @@ func (w *wrapperConn) QueryContext(ctx context.Context, query string, args []dri } w.opts.Meter.Summary(meterRequestLatencyMicroseconds, labels...).Update(te) w.opts.Meter.Histogram(meterRequestDurationSeconds, labels...).Update(te) + if w.opts.LoggerEnabled { + w.opts.Logger.Fields(w.opts.LoggerObserver(context.TODO(), "QueryContext", name, td, err)...).Log(context.TODO(), w.opts.LoggerLevel) + } return rows, err } diff --git a/driver.go b/driver.go index c242f37..eb44e14 100644 --- a/driver.go +++ b/driver.go @@ -1,7 +1,9 @@ package wrapper import ( + "context" "database/sql/driver" + "time" ) // wrapperDriver defines a wrapper for driver.Driver @@ -17,9 +19,17 @@ func NewWrapper(d driver.Driver, opts ...Option) driver.Driver { // Open implements driver.Driver Open func (w *wrapperDriver) Open(name string) (driver.Conn, error) { + ts := time.Now() c, err := w.driver.Open(name) + td := time.Since(ts) + + if w.opts.LoggerEnabled { + w.opts.Logger.Fields(w.opts.LoggerObserver(context.TODO(), "Open", labelUnknown, td, err)...).Log(context.TODO(), w.opts.LoggerLevel) + } + if err != nil { return nil, err } + return &wrapperConn{conn: c, opts: w.opts}, nil } diff --git a/go.mod b/go.mod index e4c4e9b..c9ef2fc 100644 --- a/go.mod +++ b/go.mod @@ -2,4 +2,4 @@ module go.unistack.org/micro-wrapper-sql/v3 go 1.16 -require go.unistack.org/micro/v3 v3.9.17 +require go.unistack.org/micro/v3 v3.9.19 diff --git a/go.sum b/go.sum index 206e177..c652651 100644 --- a/go.sum +++ b/go.sum @@ -74,8 +74,8 @@ github.com/xeipuuv/gojsonschema v1.2.0/go.mod h1:anYRn/JVcOK2ZgGU+IjEV4nwlhoK5sQ go.opentelemetry.io/proto/otlp v0.7.0/go.mod h1:PqfVotwruBrMGOCsRd/89rSnXhoiJIqeYNgFYFoEGnI= go.unistack.org/micro-proto/v3 v3.3.1 h1:nQ0MtWvP2G3QrpOgawVOPhpZZYkq6umTGDqs8FxJYIo= go.unistack.org/micro-proto/v3 v3.3.1/go.mod h1:cwRyv8uInM2I7EbU7O8Fx2Ls3N90Uw9UCCcq4olOdfE= -go.unistack.org/micro/v3 v3.9.17 h1:EJ9/XR9OTo/up/3aqWjaKS2YsWMA66b0dx+pc/0vIl8= -go.unistack.org/micro/v3 v3.9.17/go.mod h1:gI4RkJKHLPW7KV6h4+ZBOZD997MRvFRXMPQIHpozikI= +go.unistack.org/micro/v3 v3.9.19 h1:HFeHr20hnrs60EnlKWwrvQLTXILu3qhmHqs98jlqmqk= +go.unistack.org/micro/v3 v3.9.19/go.mod h1:gI4RkJKHLPW7KV6h4+ZBOZD997MRvFRXMPQIHpozikI= golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w= golang.org/x/crypto v0.0.0-20200622213623-75b288015ac9/go.mod h1:LzIPMQfyMNhhGPhUkYOs5KpL4U8rLKemX1yGLhDgUto= golang.org/x/exp v0.0.0-20190121172915-509febef88a4/go.mod h1:CJ0aWSM057203Lf6IL+f9T1iT9GByDxfZKAQTCR3kQA= diff --git a/options.go b/options.go index 3f0301a..c253b3e 100644 --- a/options.go +++ b/options.go @@ -2,6 +2,7 @@ package wrapper import ( "context" + "fmt" "time" "go.unistack.org/micro/v3/logger" @@ -14,6 +15,17 @@ var ( DefaultMeterStatsInterval = 5 * time.Second // DefaultMeterMetricPrefix holds default metric prefix 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)} + if err != nil { + labels = append(labels, "error", err.Error()) + } + if query != labelUnknown { + labels = append(labels, "query", query) + } + return labels + } ) var ( @@ -51,6 +63,8 @@ type Options struct { MeterMetricPrefix string MeterStatsInterval time.Duration LoggerLevel logger.Level + LoggerEnabled bool + LoggerObserver func(ctx context.Context, method string, name string, td time.Duration, err error) []interface{} } // Option func signature @@ -65,6 +79,7 @@ func NewOptions(opts ...Option) Options { MeterStatsInterval: DefaultMeterStatsInterval, MeterMetricPrefix: DefaultMeterMetricPrefix, LoggerLevel: logger.ErrorLevel, + LoggerObserver: DefaultLoggerObserver, } for _, o := range opts { o(&options) @@ -78,6 +93,8 @@ func NewOptions(opts ...Option) Options { ), ) + options.Logger = options.Logger.Clone(logger.WithCallerSkipCount(1)) + return options } @@ -121,6 +138,13 @@ func Logger(l logger.Logger) Option { } } +// LoggerEnabled enable sql logging +func LoggerEnabled(b bool) Option { + return func(o *Options) { + o.LoggerEnabled = b + } +} + // LoggerLevel passes logger.Level option func LoggerLevel(lvl logger.Level) Option { return func(o *Options) { @@ -128,6 +152,13 @@ func LoggerLevel(lvl logger.Level) Option { } } +// LoggerObserver passes observer to fill logger fields +func LoggerObserver(obs func(context.Context, string, string, time.Duration, error) []interface{}) Option { + return func(o *Options) { + o.LoggerObserver = obs + } +} + // Tracer passes tracer.Tracer to wrapper func Tracer(t tracer.Tracer) Option { return func(o *Options) { diff --git a/stmt.go b/stmt.go index 0aade11..f5705ee 100644 --- a/stmt.go +++ b/stmt.go @@ -18,7 +18,8 @@ func (w *wrapperStmt) Close() error { labels := []string{labelMethod, "Close"} ts := time.Now() err := w.stmt.Close() - te := time.Since(ts).Seconds() + td := time.Since(ts) + te := td.Seconds() if err != nil { w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelFailure)...).Inc() } else { @@ -26,6 +27,10 @@ func (w *wrapperStmt) Close() error { } w.opts.Meter.Summary(meterRequestLatencyMicroseconds, labels...).Update(te) w.opts.Meter.Histogram(meterRequestDurationSeconds, labels...).Update(te) + + if w.opts.LoggerEnabled { + w.opts.Logger.Fields(w.opts.LoggerObserver(context.TODO(), "Close", labelUnknown, td, err)...).Log(context.TODO(), w.opts.LoggerLevel) + } return err } @@ -36,11 +41,12 @@ func (w *wrapperStmt) NumInput() int { // Exec implements driver.Stmt Exec func (w *wrapperStmt) Exec(args []driver.Value) (driver.Result, error) { - // nolint:staticcheck labels := []string{labelMethod, "Exec"} ts := time.Now() + // nolint:staticcheck res, err := w.stmt.Exec(args) - te := time.Since(ts).Seconds() + td := time.Since(ts) + te := td.Seconds() if err != nil { w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelFailure)...).Inc() } else { @@ -48,6 +54,10 @@ func (w *wrapperStmt) Exec(args []driver.Value) (driver.Result, error) { } w.opts.Meter.Summary(meterRequestLatencyMicroseconds, labels...).Update(te) w.opts.Meter.Histogram(meterRequestDurationSeconds, labels...).Update(te) + + if w.opts.LoggerEnabled { + w.opts.Logger.Fields(w.opts.LoggerObserver(context.TODO(), "Exec", labelUnknown, td, err)...).Log(context.TODO(), w.opts.LoggerLevel) + } return res, err } @@ -57,7 +67,8 @@ func (w *wrapperStmt) Query(args []driver.Value) (driver.Rows, error) { ts := time.Now() // nolint:staticcheck rows, err := w.stmt.Query(args) - te := time.Since(ts).Seconds() + td := time.Since(ts) + te := td.Seconds() if err != nil { w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelFailure)...).Inc() } else { @@ -65,6 +76,10 @@ func (w *wrapperStmt) Query(args []driver.Value) (driver.Rows, error) { } w.opts.Meter.Summary(meterRequestLatencyMicroseconds, labels...).Update(te) w.opts.Meter.Histogram(meterRequestDurationSeconds, labels...).Update(te) + + if w.opts.LoggerEnabled { + w.opts.Logger.Fields(w.opts.LoggerObserver(context.TODO(), "Query", labelUnknown, td, err)...).Log(context.TODO(), w.opts.LoggerLevel) + } return rows, err } @@ -83,10 +98,11 @@ func (w *wrapperStmt) ExecContext(ctx context.Context, query string, args []driv span.AddLabels("args", fmt.Sprintf("%v", namedValueToLabels(args))) } labels := []string{labelMethod, "ExecContext", labelQuery, name} - if execerContext, ok := w.stmt.(driver.ExecerContext); ok { + if conn, ok := w.stmt.(driver.ExecerContext); ok { ts := time.Now() - res, err := execerContext.ExecContext(nctx, query, args) - te := time.Since(ts).Seconds() + res, err := conn.ExecContext(nctx, query, args) + td := time.Since(ts) + te := td.Seconds() if err != nil { w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelFailure)...).Inc() span.AddLabels("error", true) @@ -96,6 +112,10 @@ func (w *wrapperStmt) 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.Fields(w.opts.LoggerObserver(context.TODO(), "ExecContext", name, td, err)...).Log(context.TODO(), w.opts.LoggerLevel) + } return res, err } values, err := namedValueToValue(args) @@ -103,13 +123,30 @@ func (w *wrapperStmt) ExecContext(ctx context.Context, query string, args []driv w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelFailure)...).Inc() span.AddLabels("error", true) span.AddLabels("err", err.Error()) + + if w.opts.LoggerEnabled { + w.opts.Logger.Fields(w.opts.LoggerObserver(context.TODO(), "ExecContext", name, 0, err)...).Log(context.TODO(), w.opts.LoggerLevel) + } return nil, err } + ts := time.Now() // nolint:staticcheck res, err := w.Exec(values) + td := time.Since(ts) + 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()) + } 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.Fields(w.opts.LoggerObserver(context.TODO(), "ExecContext", name, td, err)).Log(context.TODO(), w.opts.LoggerLevel) } return res, err } @@ -128,25 +165,58 @@ func (w *wrapperStmt) QueryContext(ctx context.Context, query string, args []dri if len(args) > 0 { span.AddLabels("args", fmt.Sprintf("%v", namedValueToLabels(args))) } - if queryerContext, ok := w.stmt.(driver.QueryerContext); ok { - rows, err := queryerContext.QueryContext(nctx, query, args) + labels := []string{labelMethod, "QueryContext", labelQuery, name} + if conn, ok := w.stmt.(driver.QueryerContext); ok { + ts := time.Now() + rows, err := conn.QueryContext(nctx, query, args) + td := time.Since(ts) + 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()) + } 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.Fields(w.opts.LoggerObserver(context.TODO(), "QueryContext", name, td, err)).Log(context.TODO(), w.opts.LoggerLevel) } return rows, err } 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()) + + if w.opts.LoggerEnabled { + w.opts.Logger.Fields(w.opts.LoggerObserver(context.TODO(), "QueryContext", name, 0, err)...).Log(context.TODO(), w.opts.LoggerLevel) + } return nil, err } + ts := time.Now() // nolint:staticcheck rows, err := w.Query(values) + td := time.Since(ts) + 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()) + } 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.Fields(w.opts.LoggerObserver(context.TODO(), "QueryContext", name, td, err)...).Log(context.TODO(), w.opts.LoggerLevel) } return rows, err } diff --git a/tx.go b/tx.go index 9f23047..7aae403 100644 --- a/tx.go +++ b/tx.go @@ -1,7 +1,9 @@ package wrapper import ( + "context" "database/sql/driver" + "time" "go.unistack.org/micro/v3/tracer" ) @@ -18,7 +20,14 @@ func (w *wrapperTx) Commit() error { if w.span != nil { defer w.span.Finish() } + ts := time.Now() err := w.tx.Commit() + td := time.Since(ts) + + if w.opts.LoggerEnabled { + w.opts.Logger.Fields(w.opts.LoggerObserver(context.TODO(), "Commit", labelUnknown, td, err)...).Log(context.TODO(), w.opts.LoggerLevel) + } + return err } @@ -27,6 +36,13 @@ func (w *wrapperTx) Rollback() error { if w.span != nil { defer w.span.Finish() } + ts := time.Now() err := w.tx.Rollback() + td := time.Since(ts) + + if w.opts.LoggerEnabled { + w.opts.Logger.Fields(w.opts.LoggerObserver(context.TODO(), "Rollback", labelUnknown, td, err)...).Log(context.TODO(), w.opts.LoggerLevel) + } + return err } -- 2.45.2