Merge pull request #57 from unistack-org/fixes

tracing fixes

.github/workflows/autoapprove.yml

@@ -13,7 +13,7 @@ jobs:
     runs-on: ubuntu-latest
     steps:
       - name: approve
-        uses: hmarr/auto-approve-action@v2
+        uses: hmarr/auto-approve-action@v3
         if: github.actor == 'vtolstov' || github.actor == 'dependabot[bot]'
         id: approve
         with:

.github/workflows/build.yml

@@ -10,13 +10,13 @@ jobs:
     runs-on: ubuntu-latest
     steps:
     - name: setup
-      uses: actions/setup-go@v2
+      uses: actions/setup-go@v3
       with:
-        go-version: 1.16
+        go-version: 1.17
     - name: checkout
       uses: actions/checkout@v3
     - name: cache
-      uses: actions/cache@v2
+      uses: actions/cache@v3
       with:
         path: ~/go/pkg/mod
         key: ${{ runner.os }}-go-${{ hashFiles('**/go.sum') }}
@@ -34,7 +34,7 @@ jobs:
       - name: checkout
         uses: actions/checkout@v3
       - name: lint
-        uses: golangci/golangci-lint-action@v3.1.0
+        uses: golangci/golangci-lint-action@v3.3.1
         continue-on-error: true
         with:
           # Required: the version of golangci-lint is required and must be specified without patch version: we always use the latest patch version.

.github/workflows/codeql-analysis.yml

@@ -45,12 +45,12 @@ jobs:
     - name: checkout
       uses: actions/checkout@v3
     - name: setup
-      uses: actions/setup-go@v2
+      uses: actions/setup-go@v3
       with:
-        go-version: 1.16
+        go-version: 1.17
     # Initializes the CodeQL tools for scanning.
     - name: init
-      uses: github/codeql-action/init@v1
+      uses: github/codeql-action/init@v2
       with:
         languages: ${{ matrix.language }}
         # If you wish to specify custom queries, you can do so here or in a config file.
@@ -61,7 +61,7 @@ jobs:
     # Autobuild attempts to build any compiled languages  (C/C++, C#, or Java).
     # If this step fails, then you should remove it and run the build manually (see below)
     - name: autobuild
-      uses: github/codeql-action/autobuild@v1
+      uses: github/codeql-action/autobuild@v2
 
     # ℹ️ Command-line programs to run using the OS shell.
     # 📚 https://git.io/JvXDl
@@ -75,4 +75,4 @@ jobs:
     #   make release
 
     - name: analyze
-      uses: github/codeql-action/analyze@v1
+      uses: github/codeql-action/analyze@v2

.github/workflows/dependabot-automerge.yml

@@ -15,7 +15,7 @@ jobs:
     steps:
       - name: metadata
         id: metadata
-        uses: dependabot/fetch-metadata@v1.3.0
+        uses: dependabot/fetch-metadata@v1.3.5
         with:
           github-token: "${{ secrets.TOKEN }}"
       - name: merge

.github/workflows/pr.yml

@@ -10,13 +10,13 @@ jobs:
     runs-on: ubuntu-latest
     steps:
     - name: setup
-      uses: actions/setup-go@v2
+      uses: actions/setup-go@v3
       with:
-        go-version: 1.16
+        go-version: 1.17
     - name: checkout
       uses: actions/checkout@v3
     - name: cache
-      uses: actions/cache@v2
+      uses: actions/cache@v3
       with:
         path: ~/go/pkg/mod
         key: ${{ runner.os }}-go-${{ hashFiles('**/go.sum') }}
@@ -34,7 +34,7 @@ jobs:
       - name: checkout
         uses: actions/checkout@v3
       - name: lint
-        uses: golangci/golangci-lint-action@v3.1.0
+        uses: golangci/golangci-lint-action@v3.3.1
         continue-on-error: true
         with:
           # Required: the version of golangci-lint is required and must be specified without patch version: we always use the latest patch version.

README.md

@@ -1,8 +1,10 @@
-# micro-wrapper-sqlpackage postgres
+# micro-wrapper-sql
 
 Example for For postgres 
 
 ```go
+package storage
+
 import (
 	"fmt"
 	"net/url"
@@ -11,6 +13,7 @@ import (
 	"github.com/jackc/pgx/v4"
 	"github.com/jackc/pgx/v4/stdlib"
 	"github.com/jmoiron/sqlx"
+	wrapper "go.unistack.org/micro-wrapper-sql/v3"
 )
 
 func Connect(cfg *PostgresConfig) (*sqlx.DB, error) {
@@ -35,15 +38,25 @@ func Connect(cfg *PostgresConfig) (*sqlx.DB, error) {
 		"application_name":            cfg.AppName,
 	}
 	// may be needed for pbbouncer, needs to check
-	//dbConf.PreferSimpleProtocol = true
+	// dbConf.PreferSimpleProtocol = true
 	// register pgx conn
 	dsn := stdlib.RegisterConnConfig(dbConf)
 
 
-  sql.Register("micro-wrapper-sql", wrapper.WrapDriver(
+  wrapper.DefaultMeterStatsInterval = 1 * time.Second
-    &stdlib.Driver{}, 
+	logger.DefaultLogger = logger.NewLogger(logger.WithLevel(logger.DebugLevel))
-    wrapper.Tracer(some.NewTracer()),
+
+	if err := logger.DefaultLogger.Init(); err != nil {
+		t.Fatal(err)
+	}
+
+	sql.Register("micro-wrapper-sql", wrapper.NewWrapper(&sqlite.Driver{},
+		wrapper.DatabaseHost("localhost"),
+		wrapper.DatabaseName("mydb"),
+		wrapper.LoggerLevel(logger.DebugLevel),
+		wrapper.LoggerEnabled(true),
 	))
+
   wdb, err := sql.Open("micro-wrapper-sql", dsn)
 	if err != nil {
 		return nil, err

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
 }
+
+// namedValueToLabels convert driver arguments to interface{} slice
+func namedValueToLabels(named []driver.NamedValue) []interface{} {
+	largs := make([]interface{}, 0, 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, fmt.Sprintf("%s=%s", name, param.Value))
+	}
+	return largs
+}

conn.go

@@ -3,114 +3,472 @@ package wrapper
 import (
 	"context"
 	"database/sql/driver"
+	"fmt"
+	"time"
+
+	"go.unistack.org/micro/v3/tracer"
 )
 
+var _ driver.Conn = &wrapperConn{}
+
 // wrapperConn defines a wrapper for driver.Conn
 type wrapperConn struct {
 	conn driver.Conn
 	opts Options
+	ctx  context.Context
 }
 
 // Prepare implements driver.Conn Prepare
 func (w *wrapperConn) Prepare(query string) (driver.Stmt, error) {
+	var ctx context.Context
+	if w.ctx != nil {
+		ctx = w.ctx
+	} else {
+		ctx = context.Background()
+	}
+
+	labels := []string{labelMethod, "Prepare", labelQuery, labelUnknown}
+	ts := time.Now()
 	stmt, err := w.conn.Prepare(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)
+
+		if w.opts.LoggerEnabled {
+			w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "Prepare", labelUnknown, td, err)...).Log(ctx, w.opts.LoggerLevel)
+		}
 		return nil, err
 	}
-	return &wrapperStmt{stmt: stmt, opts: w.opts}, nil
+	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(ctx, "Prepare", labelUnknown, td, err)...).Log(ctx, w.opts.LoggerLevel)
+	}
+
+	return &wrapperStmt{stmt: stmt, opts: w.opts, ctx: ctx}, nil
 }
 
 // Close implements driver.Conn Close
 func (w *wrapperConn) Close() error {
-	return w.conn.Close()
+	var ctx context.Context
+	if w.ctx != nil {
+		ctx = w.ctx
+	} else {
+		ctx = context.Background()
+	}
+
+	labels := []string{labelMethod, "Close"}
+	ts := time.Now()
+	err := w.conn.Close()
+	td := time.Since(ts)
+	te := td.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)
+
+	if w.opts.LoggerEnabled {
+		w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "Close", labelUnknown, td, err)...).Log(ctx, w.opts.LoggerLevel)
+	}
+
+	return err
 }
 
 // Begin implements driver.Conn Begin
 func (w *wrapperConn) Begin() (driver.Tx, error) {
+	var ctx context.Context
+	if w.ctx != nil {
+		ctx = w.ctx
+	} else {
+		ctx = context.Background()
+	}
+
+	labels := []string{labelMethod, "Begin"}
+	ts := time.Now()
+	// nolint:staticcheck
 	tx, err := w.conn.Begin()
+	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(ctx, "Begin", labelUnknown, td, err)...).Log(ctx, w.opts.LoggerLevel)
+		}
 		return nil, err
 	}
-	return &wrapperTx{tx: tx, opts: w.opts}, nil
+	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(ctx, "Begin", labelUnknown, td, err)...).Log(ctx, w.opts.LoggerLevel)
+	}
+	return &wrapperTx{tx: tx, opts: w.opts, ctx: ctx}, 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")
+	nctx, span := w.opts.Tracer.Start(ctx, "Transaction")
+	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)
+		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(ctx, "BeginTx", name, td, err)...).Log(ctx, w.opts.LoggerLevel)
+			}
 			return nil, err
 		}
-		return &wrapperTx{tx: tx, opts: w.opts, span: span}, nil
+		w.opts.Meter.Counter(meterRequestTotal, append(labels, labelStatus, labelSuccess)...).Inc()
+		if w.opts.LoggerEnabled {
+			w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "BeginTx", name, td, err)...).Log(ctx, w.opts.LoggerLevel)
 		}
-	return w.conn.Begin()
+		w.ctx = nctx
+		return &wrapperTx{ctx: ctx, tx: tx, opts: w.opts, span: span, conn: w}, nil
+	}
+	ts := time.Now()
+	// nolint:staticcheck
+	tx, err := w.conn.Begin()
+	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())
+	}
+	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(ctx, "BeginTx", name, td, err)...).Log(ctx, w.opts.LoggerLevel)
+	}
+	w.ctx = nctx
+	return &wrapperTx{ctx: ctx, tx: tx, opts: w.opts, span: span, conn: w}, nil
 }
 
 // PrepareContext implements driver.ConnPrepareContext PrepareContext
 func (w *wrapperConn) PrepareContext(ctx context.Context, query string) (driver.Stmt, error) {
-	if connPrepareContext, ok := w.conn.(driver.ConnPrepareContext); ok {
+	var nctx context.Context
-		stmt, err := connPrepareContext.PrepareContext(ctx, query)
+	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
+	}
+	labels := []string{labelMethod, "PrepareContext", labelQuery, name}
+	if conn, ok := w.conn.(driver.ConnPrepareContext); ok {
+		ts := time.Now()
+		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(ctx, "PrepareContext", name, td, err)...).Log(ctx, w.opts.LoggerLevel)
+			}
 			return nil, err
 		}
-		return &wrapperStmt{stmt: stmt, opts: w.opts}, nil
+		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(ctx, "PrepareContext", name, td, err)...).Log(ctx, w.opts.LoggerLevel)
 		}
-	return w.conn.Prepare(query)
+		return &wrapperStmt{stmt: stmt, opts: w.opts, ctx: nctx}, nil
+	}
+	ts := time.Now()
+	stmt, err := w.conn.Prepare(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())
+	}
+	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(ctx, "PrepareContext", name, td, err)...).Log(ctx, w.opts.LoggerLevel)
+	}
+	return stmt, nil
 }
 
 // Exec implements driver.Execer Exec
 func (w *wrapperConn) Exec(query string, args []driver.Value) (driver.Result, error) {
+	var ctx context.Context
+	if w.ctx != nil {
+		ctx = w.ctx
+	} else {
+		ctx = context.Background()
+	}
+	// 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)
+		td := time.Since(ts)
+		te := td.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)
+		if w.opts.LoggerEnabled {
+			w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "Exec", labelUnknown, td, err)...).Log(ctx, w.opts.LoggerLevel)
+		}
+		return res, err
+	}
+	if w.opts.LoggerEnabled {
+		w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "Exec", labelUnknown, 0, ErrUnsupported)...).Log(ctx, w.opts.LoggerLevel)
 	}
 	return nil, ErrUnsupported
 }
 
 // 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
+	if w.ctx != nil {
+		nctx, span = w.opts.Tracer.Start(w.ctx, "ExecContext")
+	} else {
+		nctx, span = w.opts.Tracer.Start(ctx, "ExecContext")
+	}
+	span.AddLabels("method", "ExecContext")
+	name := getQueryName(ctx)
+	if name != "" {
+		span.AddLabels("query", name)
+	} else {
+		name = labelUnknown
+	}
 	defer span.Finish()
-	if execerContext, ok := w.conn.(driver.ExecerContext); ok {
+	if len(args) > 0 {
-		r, err := execerContext.ExecContext(nctx, query, args)
+		span.AddLabels("args", fmt.Sprintf("%v", namedValueToLabels(args)))
-		return r, err
+	}
+	labels := []string{labelMethod, "ExecContext", labelQuery, name}
+	if conn, ok := w.conn.(driver.ExecerContext); ok {
+		ts := time.Now()
+		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)
+			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)
+		if w.opts.LoggerEnabled {
+			w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "ExecContext", name, td, err)...).Log(ctx, 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(ctx, "ExecContext", labelUnknown, 0, err)...).Log(ctx, w.opts.LoggerLevel)
+		}
 		return nil, err
 	}
-	return w.Exec(query, values)
+	ts := time.Now()
+	// nolint:staticcheck
+	res, err := w.Exec(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(ctx, "ExecContext", name, td, err)...).Log(ctx, 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")
+		var nctx context.Context
+		var span tracer.Span
+		if w.ctx != nil {
+			nctx, span = w.opts.Tracer.Start(w.ctx, "Ping")
+		} else {
+			nctx, span = w.opts.Tracer.Start(ctx, "Ping")
+		}
 		defer span.Finish()
-		return pinger.Ping(nctx)
+		labels := []string{labelMethod, "Ping"}
+		ts := time.Now()
+		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(ctx, "Ping", labelUnknown, td, err)...).Log(ctx, w.opts.LoggerLevel)
+			}
+			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)
+	}
+	if w.opts.LoggerEnabled {
+		w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "Ping", labelUnknown, 0, ErrUnsupported)...).Log(ctx, w.opts.LoggerLevel)
 	}
 	return ErrUnsupported
 }
 
 // Query implements driver.Queryer Query
 func (w *wrapperConn) Query(query string, args []driver.Value) (driver.Rows, error) {
-	if queryer, ok := w.conn.(driver.Queryer); ok {
+	var ctx context.Context
-		return queryer.Query(query, args)
+	if w.ctx != nil {
+		ctx = w.ctx
+	} else {
+		ctx = context.Background()
+	}
+	// nolint:staticcheck
+	if conn, ok := w.conn.(driver.Queryer); ok {
+		labels := []string{labelMethod, "Query", labelQuery, labelUnknown}
+		ts := time.Now()
+		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 {
+			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(ctx, "Query", labelUnknown, td, err)...).Log(ctx, w.opts.LoggerLevel)
+		}
+		return rows, err
+	}
+	if w.opts.LoggerEnabled {
+		w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "Query", labelUnknown, 0, ErrUnsupported)...).Log(ctx, w.opts.LoggerLevel)
 	}
 	return nil, ErrUnsupported
 }
 
 // QueryContext implements Driver.QueryerContext QueryContext
-func (w *wrapperConn) QueryContext(ctx context.Context, query string, args []driver.NamedValue) (rows driver.Rows, err error) {
+func (w *wrapperConn) QueryContext(ctx context.Context, query string, args []driver.NamedValue) (driver.Rows, error) {
-	nctx, span := w.opts.Tracer.Start(ctx, "QueryContext")
+	var nctx context.Context
+	var span tracer.Span
+	if w.ctx != nil {
+		nctx, span = w.opts.Tracer.Start(w.ctx, "QueryContext")
+	} else {
+		nctx, span = w.opts.Tracer.Start(ctx, "QueryContext")
+	}
+	span.AddLabels("method", "QueryContext")
+	name := getQueryName(ctx)
+	if name != "" {
+		span.AddLabels("query", name)
+	} else {
+		name = labelUnknown
+	}
 	defer span.Finish()
-	if queryerContext, ok := w.conn.(driver.QueryerContext); ok {
+	if len(args) > 0 {
-		rows, err := queryerContext.QueryContext(nctx, query, args)
+		span.AddLabels("args", fmt.Sprintf("%v", namedValueToLabels(args)))
+	}
+	labels := []string{labelMethod, "QueryContext", labelQuery, name}
+	if conn, ok := w.conn.(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(ctx, "QueryContext", name, td, err)...).Log(ctx, 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(ctx, "QueryContext", name, 0, err)...).Log(ctx, w.opts.LoggerLevel)
+		}
 		return nil, err
 	}
-	return w.Query(query, values)
+	ts := time.Now()
+	// nolint:staticcheck
+	rows, err := w.Query(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(ctx, "QueryContext", name, td, err)...).Log(ctx, w.opts.LoggerLevel)
+	}
+	return rows, err
 }

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

driver.go

@@ -1,25 +1,36 @@
 package wrapper
 
 import (
+	"context"
 	"database/sql/driver"
+	"time"
 )
 
 // wrapperDriver defines a wrapper for driver.Driver
 type wrapperDriver struct {
 	driver driver.Driver
 	opts   Options
+	ctx    context.Context
 }
 
 // NewWrapper creates and returns a new SQL driver with passed capabilities
 func NewWrapper(d driver.Driver, opts ...Option) driver.Driver {
-	return &wrapperDriver{driver: d, opts: NewOptions(opts...)}
+	return &wrapperDriver{driver: d, opts: NewOptions(opts...), ctx: context.Background()}
 }
 
 // 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(w.ctx, "Open", labelUnknown, td, err)...).Log(w.ctx, w.opts.LoggerLevel)
+	}
+
 	if err != nil {
 		return nil, err
 	}
-	return &wrapperConn{conn: c, opts: w.opts}, nil
+
+	return &wrapperConn{conn: c, opts: w.opts, ctx: w.ctx}, nil
 }

go.mod

@@ -2,4 +2,4 @@ module go.unistack.org/micro-wrapper-sql/v3
 
 go 1.16
 
-require go.unistack.org/micro/v3 v3.8.21
+require go.unistack.org/micro/v3 v3.10.0

go.sum

@@ -10,10 +10,10 @@ github.com/client9/misspell v0.3.4/go.mod h1:qj6jICC3Q7zFZvVWo7KLAzC3yx5G7kyvSDk
 github.com/cncf/udpa/go v0.0.0-20191209042840-269d4d468f6f/go.mod h1:M8M6+tZqaGXZJjfX53e64911xZQV5JYwmTeXPW+k8Sc=
 github.com/cncf/udpa/go v0.0.0-20201120205902-5459f2c99403/go.mod h1:WmhPx2Nbnhtbo57+VJT5O0JRkEi1Wbu0z5j0R8u5Hbk=
 github.com/cncf/xds/go v0.0.0-20210312221358-fbca930ec8ed/go.mod h1:eXthEFrGJvWHgFFCl3hGmgk+/aYT6PnTQLykKQRLhEs=
+github.com/creack/pty v1.1.9/go.mod h1:oKZEueFk5CKHvIhNR5MUki03XCEU+Q6VDXinZuGJ33E=
 github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
 github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
 github.com/docopt/docopt-go v0.0.0-20180111231733-ee0de3bc6815/go.mod h1:WwZ+bS3ebgob9U8Nd0kOddGdZWjyMGR8Wziv+TBNwSE=
-github.com/ef-ds/deque v1.0.4/go.mod h1:gXDnTC3yqvBcHbq2lcExjtAcVrOnJCbMcZXmuj8Z4tg=
 github.com/envoyproxy/go-control-plane v0.9.0/go.mod h1:YTl/9mNaCwkRvm6d1a2C3ymFceY/DCBVvsKhRF0iEA4=
 github.com/envoyproxy/go-control-plane v0.9.1-0.20191026205805-5f8ba28d4473/go.mod h1:YTl/9mNaCwkRvm6d1a2C3ymFceY/DCBVvsKhRF0iEA4=
 github.com/envoyproxy/go-control-plane v0.9.4/go.mod h1:6rpuAdCZL397s3pYoYcLgu1mIlRU8Am5FuJP05cCM98=
@@ -22,7 +22,6 @@ github.com/envoyproxy/go-control-plane v0.9.9-0.20210512163311-63b5d3c536b0/go.m
 github.com/envoyproxy/protoc-gen-validate v0.1.0/go.mod h1:iSmxcyjqTsJpI2R4NaDN7+kN2VEUnK/pcBlmesArF7c=
 github.com/flowstack/go-jsonschema v0.1.1/go.mod h1:yL7fNggx1o8rm9RlgXv7hTBWxdBM0rVwpMwimd3F3N0=
 github.com/ghodss/yaml v1.0.0/go.mod h1:4dBDuWmgqj2HViK6kFavaiC9ZROes6MMH2rRYeMEF04=
-github.com/golang-jwt/jwt/v4 v4.2.0/go.mod h1:/xlHOz8bRuivTWchD4jCa+NbatV+wEUSzwAxVc6locg=
 github.com/golang/glog v0.0.0-20160126235308-23def4e6c14b/go.mod h1:SBH7ygxi8pfUlaOkMMuAQtPIUF8ecWP5IEl/CR7VP2Q=
 github.com/golang/mock v1.1.1/go.mod h1:oTYuIxOrZwtPieC+H1uAHpcLFnEyAGVDL/k47Jfbm0A=
 github.com/golang/protobuf v1.2.0/go.mod h1:6lQm79b+lXiMfvg/cZm0SGofjICqVBUtrP5yJMmIC1U=
@@ -37,21 +36,28 @@ github.com/golang/protobuf v1.4.1/go.mod h1:U8fpvMrcmy5pZrNK1lt4xCsGvpyWQ/VVv6QD
 github.com/golang/protobuf v1.4.2/go.mod h1:oDoupMAO8OvCJWAcko0GGGIgR6R6ocIYbsSw735rRwI=
 github.com/golang/protobuf v1.4.3/go.mod h1:oDoupMAO8OvCJWAcko0GGGIgR6R6ocIYbsSw735rRwI=
 github.com/golang/protobuf v1.5.0/go.mod h1:FsONVRAS9T7sI+LIUmWTfcYkHO4aIWwzhcaSAoJOfIk=
+github.com/golang/protobuf v1.5.2 h1:ROPKBNFfQgOUMifHyP+KYbvpjbdoFNs+aK7DXlji0Tw=
 github.com/golang/protobuf v1.5.2/go.mod h1:XVQd3VNwM+JqD3oG2Ue2ip4fOMUkwXdXDdiuN0vRsmY=
-github.com/google/gnostic v0.6.6/go.mod h1:Nm8234We1lq6iB9OmlgNv3nH91XLLVZHCDayfA3xq+E=
+github.com/google/gnostic v0.6.9 h1:ZK/5VhkoX835RikCHpSUJV9a+S3e1zLh59YnyWeBW+0=
+github.com/google/gnostic v0.6.9/go.mod h1:Nm8234We1lq6iB9OmlgNv3nH91XLLVZHCDayfA3xq+E=
 github.com/google/go-cmp v0.2.0/go.mod h1:oXzfMopK8JAjlY9xF4vHSVASa0yLyX7SntLO5aqRK0M=
 github.com/google/go-cmp v0.3.0/go.mod h1:8QqcDgzrUqlUb/G2PQTWiueGozuR1884gddMywk6iLU=
 github.com/google/go-cmp v0.3.1/go.mod h1:8QqcDgzrUqlUb/G2PQTWiueGozuR1884gddMywk6iLU=
 github.com/google/go-cmp v0.4.0/go.mod h1:v8dTdLbMG2kIc/vJvl+f65V22dbkXbowE6jgT/gNBxE=
 github.com/google/go-cmp v0.5.0/go.mod h1:v8dTdLbMG2kIc/vJvl+f65V22dbkXbowE6jgT/gNBxE=
-github.com/google/go-cmp v0.5.5 h1:Khx7svrCpmxxtHBq5j2mp/xVjsi8hQMfNLvJFAlrGgU=
 github.com/google/go-cmp v0.5.5/go.mod h1:v8dTdLbMG2kIc/vJvl+f65V22dbkXbowE6jgT/gNBxE=
+github.com/google/go-cmp v0.5.7 h1:81/ik6ipDQS2aGcBfIN5dHDB36BwrStyeAQquSYCV4o=
+github.com/google/go-cmp v0.5.7/go.mod h1:n+brtR0CgQNWTVd5ZUFpTBC8YFBDLK/h/bpaJ8/DtOE=
 github.com/google/uuid v1.1.2/go.mod h1:TIyPZe4MgqvfeYDBFedMoGGpEw/LqOeaOT+nhxU+yHo=
 github.com/grpc-ecosystem/grpc-gateway v1.16.0/go.mod h1:BDjrQk3hbvj6Nolgz8mAMFbcEtjT1g+wF4CSlocrBnw=
-github.com/imdario/mergo v0.3.12/go.mod h1:jmQim1M+e3UYxmgPu/WyfjB3N3VflVyUjjjwH0dnCYA=
+github.com/imdario/mergo v0.3.13/go.mod h1:4lJ1jqUDcsbIECGy0RUJAXNIhg+6ocWgb1ALK2O4oXg=
 github.com/kr/pretty v0.2.0/go.mod h1:ipq/a2n7PKx3OHsz4KJII5eveXtPO4qwEXGdVfWzfnI=
+github.com/kr/pretty v0.2.1 h1:Fmg33tUaq4/8ym9TJN1x7sLJnHVwhP33CNkpYV/7rwI=
+github.com/kr/pretty v0.2.1/go.mod h1:ipq/a2n7PKx3OHsz4KJII5eveXtPO4qwEXGdVfWzfnI=
 github.com/kr/pty v1.1.1/go.mod h1:pFQYn66WHrOpPYNljwOMqo10TkYh1fy3cYio2l3bCsQ=
 github.com/kr/text v0.1.0/go.mod h1:4Jbv+DJW3UT/LiOwJeYQe1efqtUx/iVham/4vfdArNI=
+github.com/kr/text v0.2.0 h1:5Nx0Ya0ZqY2ygV366QzturHI13Jq95ApcVaJBhpS+AY=
+github.com/kr/text v0.2.0/go.mod h1:eLer722TekiGuMkidMxC/pM04lWEeraHUUmBw8l2grE=
 github.com/patrickmn/go-cache v2.1.0+incompatible/go.mod h1:3Qf8kWWT7OJRJbdiICTKqZju1ZixQ/KpMGzzAfe6+WQ=
 github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
 github.com/prometheus/client_model v0.0.0-20190812154241-14fe0d1b01d4/go.mod h1:xMI15A0UPsDsEKsMN9yxemIoYk6Tm2C1GtYGdfGttqA=
@@ -66,10 +72,10 @@ github.com/xeipuuv/gojsonpointer v0.0.0-20180127040702-4e3ac2762d5f/go.mod h1:N2
 github.com/xeipuuv/gojsonreference v0.0.0-20180127040603-bd5ef7bd5415/go.mod h1:GwrjFmJcFw6At/Gs6z4yjiIwzuJ1/+UwLxMQDVQXShQ=
 github.com/xeipuuv/gojsonschema v1.2.0/go.mod h1:anYRn/JVcOK2ZgGU+IjEV4nwlhoK5sQluxsYJ78Id3Y=
 go.opentelemetry.io/proto/otlp v0.7.0/go.mod h1:PqfVotwruBrMGOCsRd/89rSnXhoiJIqeYNgFYFoEGnI=
-go.unistack.org/micro-proto/v3 v3.2.1 h1:z7+V97LcAwMbBiYStmf8b6fFk2UPJTzni+rxNqk4NrI=
+go.unistack.org/micro-proto/v3 v3.3.1 h1:nQ0MtWvP2G3QrpOgawVOPhpZZYkq6umTGDqs8FxJYIo=
-go.unistack.org/micro-proto/v3 v3.2.1/go.mod h1:ZltVWNECD5yK+40+OCONzGw4OtmSdTpVi8/KFgo9dqM=
+go.unistack.org/micro-proto/v3 v3.3.1/go.mod h1:cwRyv8uInM2I7EbU7O8Fx2Ls3N90Uw9UCCcq4olOdfE=
-go.unistack.org/micro/v3 v3.8.21 h1:8vYxtIlPnCBZ888BrQSP6+b0CFQcn5FiaqDpI5XqorQ=
+go.unistack.org/micro/v3 v3.10.0 h1:nPtk5Pfwk524HyezGtQ3m3vbK4LdvXqWLI7HgeilYOk=
-go.unistack.org/micro/v3 v3.8.21/go.mod h1:aBOCQ6SkAwKMRI7Q1CIsQA2S88ibyJfweJZlT1M2qpE=
+go.unistack.org/micro/v3 v3.10.0/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=
@@ -85,7 +91,6 @@ golang.org/x/net v0.0.0-20190404232315-eb5bcb51f2a3/go.mod h1:t9HGtf8HONx5eT2rtn
 golang.org/x/net v0.0.0-20200822124328-c89045814202/go.mod h1:/O7V0waA8r7cgGh81Ro3o1hOxt32SMVPicZroKQ2sZA=
 golang.org/x/net v0.0.0-20210405180319-a5a99cb37ef4/go.mod h1:p54w0d4576C0XHj96bSt6lcn1PtDYWL6XObtHCRCNQM=
 golang.org/x/net v0.0.0-20210805182204-aaa1db679c0d/go.mod h1:9nx3DQGgdP8bBQD5qxJ1jj9UTztislL4KSBs9R2vV5Y=
-golang.org/x/net v0.0.0-20210928044308-7d9f5e0b762b/go.mod h1:9nx3DQGgdP8bBQD5qxJ1jj9UTztislL4KSBs9R2vV5Y=
 golang.org/x/oauth2 v0.0.0-20180821212333-d2e6202438be/go.mod h1:N/0e6XlmueqKjAGxoOufVs8QHGRruUQn6yWY3a++T0U=
 golang.org/x/oauth2 v0.0.0-20200107190931-bf48bf16ab8d/go.mod h1:gOpvHmFTYa4IltrdGE7lF6nIHvwfUNPOp7c8zoXwtLw=
 golang.org/x/sync v0.0.0-20180314180146-1d60e4601c6f/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM=
@@ -138,14 +143,17 @@ google.golang.org/protobuf v1.23.1-0.20200526195155-81db48ad09cc/go.mod h1:EGpAD
 google.golang.org/protobuf v1.25.0/go.mod h1:9JNX74DMeImyA3h4bdi1ymwjUzf21/xIlbajtzgsN7c=
 google.golang.org/protobuf v1.26.0-rc.1/go.mod h1:jlhhOSvTdKEhbULTjvd4ARK9grFBp09yW+WbY/TyQbw=
 google.golang.org/protobuf v1.26.0/go.mod h1:9q0QmTI4eRPtz6boOQmLYwt+qCgq0jsYwAQnmE0givc=
-google.golang.org/protobuf v1.27.1 h1:SnqbnDw1V7RiZcXPx5MEeqPv2s79L9i7BJUlG/+RurQ=
 google.golang.org/protobuf v1.27.1/go.mod h1:9q0QmTI4eRPtz6boOQmLYwt+qCgq0jsYwAQnmE0givc=
+google.golang.org/protobuf v1.28.1 h1:d0NfwRgPtno5B1Wa6L2DAG+KivqkdutMf1UhdNx175w=
+google.golang.org/protobuf v1.28.1/go.mod h1:HV8QOd/L58Z+nl8r43ehVNZIU/HEI6OcFqwMG9pJV4I=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
+gopkg.in/check.v1 v1.0.0-20190902080502-41f04d3bba15 h1:YR8cESwS4TdDjEe65xsg0ogRM/Nc3DYOhEAlW+xobZo=
 gopkg.in/check.v1 v1.0.0-20190902080502-41f04d3bba15/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
 gopkg.in/yaml.v2 v2.2.2/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI=
 gopkg.in/yaml.v2 v2.2.3/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI=
-gopkg.in/yaml.v2 v2.3.0/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI=
 gopkg.in/yaml.v3 v3.0.0-20200615113413-eeeca48fe776/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM=
 gopkg.in/yaml.v3 v3.0.0-20210107192922-496545a6307b/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM=
+gopkg.in/yaml.v3 v3.0.0 h1:hjy8E9ON/egN1tAYqKb61G10WtihqetD4sz2H+8nIeA=
+gopkg.in/yaml.v3 v3.0.0/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM=
 honnef.co/go/tools v0.0.0-20190102054323-c2f93a96b099/go.mod h1:rf3lG4BRIbNafJWhAfAdb/ePZxsR/4RtNHQocxwk9r4=
 honnef.co/go/tools v0.0.0-20190523083050-ea95bdfd59fc/go.mod h1:rf3lG4BRIbNafJWhAfAdb/ePZxsR/4RtNHQocxwk9r4=

options.go

@@ -2,6 +2,7 @@ package wrapper
 
 import (
 	"context"
+	"fmt"
 	"time"
 
 	"go.unistack.org/micro/v3/logger"
@@ -14,8 +15,17 @@ var (
 	DefaultMeterStatsInterval = 5 * time.Second
 	// DefaultMeterMetricPrefix holds default metric prefix
 	DefaultMeterMetricPrefix = "micro_sql_"
-	// DefaultMeterLabelPrefix holds default label prefix
+	// DefaultLoggerObserver used to prepare labels for logger
-	DefaultMeterLabelPrefix = "micro_"
+	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 (
@@ -25,13 +35,18 @@ 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"
+	meterRequestTotal               = "request_total"
-	//	RequestLatencyMicroseconds = "request_latency_microseconds"
+	meterRequestLatencyMicroseconds = "request_latency_microseconds"
-	//	RequestDurationSeconds    = "request_duration_seconds"
+	meterRequestDurationSeconds     = "request_duration_seconds"
 
+	labelUnknown  = "unknown"
+	labelQuery    = "query"
+	labelMethod   = "method"
+	labelStatus   = "status"
 	labelSuccess  = "success"
 	labelFailure  = "failure"
 	labelHost     = "db_host"
@@ -45,13 +60,11 @@ type Options struct {
 	Tracer             tracer.Tracer
 	DatabaseHost       string
 	DatabaseName       string
-	ServiceName        string
-	ServiceVersion     string
-	ServiceID          string
-	MeterLabelPrefix   string
 	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,12 +78,23 @@ func NewOptions(opts ...Option) Options {
 		Tracer:             tracer.DefaultTracer,
 		MeterStatsInterval: DefaultMeterStatsInterval,
 		MeterMetricPrefix:  DefaultMeterMetricPrefix,
-		MeterLabelPrefix:   DefaultMeterLabelPrefix,
 		LoggerLevel:        logger.ErrorLevel,
+		LoggerObserver:     DefaultLoggerObserver,
 	}
 	for _, o := range opts {
 		o(&options)
 	}
+
+	options.Meter = options.Meter.Clone(
+		meter.MetricPrefix(options.MeterMetricPrefix),
+		meter.Labels(
+			labelHost, options.DatabaseHost,
+			labelDatabase, options.DatabaseName,
+		),
+	)
+
+	options.Logger = options.Logger.Clone(logger.WithCallerSkipCount(1))
+
 	return options
 }
 
@@ -81,13 +105,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) {
@@ -121,6 +138,27 @@ 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) {
+		o.LoggerLevel = lvl
+	}
+}
+
+// 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) {
@@ -137,3 +175,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 ""
+}

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))
+			}
+		}
+	}()
+}

stmt.go

@@ -3,17 +3,46 @@ package wrapper
 import (
 	"context"
 	"database/sql/driver"
+	"fmt"
+	"time"
+
+	"go.unistack.org/micro/v3/tracer"
 )
 
+var _ driver.Stmt = &wrapperStmt{}
+
 // wrapperStmt defines a wrapper for driver.Stmt
 type wrapperStmt struct {
 	stmt driver.Stmt
 	opts Options
+	ctx  context.Context
 }
 
 // Close implements driver.Stmt Close
 func (w *wrapperStmt) Close() error {
-	return w.stmt.Close()
+	var ctx context.Context
+	if w.ctx != nil {
+		ctx = w.ctx
+	} else {
+		ctx = context.Background()
+	}
+	labels := []string{labelMethod, "Close"}
+	ts := time.Now()
+	err := w.stmt.Close()
+	td := time.Since(ts)
+	te := td.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)
+
+	if w.opts.LoggerEnabled {
+		w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "Close", labelUnknown, td, err)...).Log(ctx, w.opts.LoggerLevel)
+	}
+	return err
 }
 
 // NumInput implements driver.Stmt NumInput
@@ -23,39 +52,206 @@ 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)
+	var ctx context.Context
+	if w.ctx != nil {
+		ctx = w.ctx
+	} else {
+		ctx = context.Background()
+	}
+	labels := []string{labelMethod, "Exec"}
+	ts := time.Now()
+	// nolint:staticcheck
+	res, err := w.stmt.Exec(args)
+	td := time.Since(ts)
+	te := td.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)
+
+	if w.opts.LoggerEnabled {
+		w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "Exec", labelUnknown, td, err)...).Log(ctx, w.opts.LoggerLevel)
+	}
+	return res, err
 }
 
 // Query implements driver.Stmt Query
 func (w *wrapperStmt) Query(args []driver.Value) (driver.Rows, error) {
-	return w.stmt.Query(args)
+	var ctx context.Context
+	if w.ctx != nil {
+		ctx = w.ctx
+	} else {
+		ctx = context.Background()
+	}
+	labels := []string{labelMethod, "Query"}
+	ts := time.Now()
+	// nolint:staticcheck
+	rows, err := w.stmt.Query(args)
+	td := time.Since(ts)
+	te := td.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)
+
+	if w.opts.LoggerEnabled {
+		w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "Query", labelUnknown, td, err)...).Log(ctx, w.opts.LoggerLevel)
+	}
+	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")
+	var nctx context.Context
+	var span tracer.Span
+	if w.ctx != nil {
+		nctx, span = w.opts.Tracer.Start(w.ctx, "ExecContext")
+	} else {
+		nctx, span = w.opts.Tracer.Start(ctx, "ExecContext")
+	}
+	span.AddLabels("method", "ExecContext")
+	name := getQueryName(ctx)
+	if name != "" {
+		span.AddLabels("query", name)
+	} else {
+		name = labelUnknown
+	}
 	defer span.Finish()
-	if execerContext, ok := w.stmt.(driver.ExecerContext); ok {
+	if len(args) > 0 {
-		return execerContext.ExecContext(nctx, query, args)
+		span.AddLabels("args", fmt.Sprintf("%v", namedValueToLabels(args)))
+	}
+	labels := []string{labelMethod, "ExecContext", labelQuery, name}
+	if conn, ok := w.stmt.(driver.ExecerContext); ok {
+		ts := time.Now()
+		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)
+			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(ctx, "ExecContext", name, td, err)...).Log(ctx, w.opts.LoggerLevel)
+		}
+		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())
+
+		if w.opts.LoggerEnabled {
+			w.opts.Logger.Fields(w.opts.LoggerObserver(ctx, "ExecContext", name, 0, err)...).Log(ctx, w.opts.LoggerLevel)
+		}
 		return nil, err
 	}
-	return w.Exec(values)
+	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(ctx, "ExecContext", name, td, err)).Log(ctx, w.opts.LoggerLevel)
+	}
+	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) {
+func (w *wrapperStmt) QueryContext(ctx context.Context, query string, args []driver.NamedValue) (driver.Rows, error) {
-	nctx, span := w.opts.Tracer.Start(ctx, "QueryContext")
+	var nctx context.Context
+	var span tracer.Span
+	if w.ctx != nil {
+		nctx, span = w.opts.Tracer.Start(w.ctx, "QueryContext")
+	} else {
+		nctx, span = w.opts.Tracer.Start(ctx, "QueryContext")
+	}
+	span.AddLabels("method", "QueryContext")
+	name := getQueryName(ctx)
+	if name != "" {
+		span.AddLabels("query", name)
+	} else {
+		name = labelUnknown
+	}
 	defer span.Finish()
-	if queryerContext, ok := w.stmt.(driver.QueryerContext); ok {
+	if len(args) > 0 {
-		rows, err := queryerContext.QueryContext(nctx, query, args)
+		span.AddLabels("args", fmt.Sprintf("%v", namedValueToLabels(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(ctx, "QueryContext", name, td, err)).Log(ctx, 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(ctx, "QueryContext", name, 0, err)...).Log(ctx, w.opts.LoggerLevel)
+		}
 		return nil, err
 	}
-	return w.Query(values)
+	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(ctx, "QueryContext", name, td, err)...).Log(ctx, w.opts.LoggerLevel)
+	}
+	return rows, err
 }

tx.go

@@ -1,16 +1,22 @@
 package wrapper
 
 import (
+	"context"
 	"database/sql/driver"
+	"time"
 
 	"go.unistack.org/micro/v3/tracer"
 )
 
+var _ driver.Tx = &wrapperTx{}
+
 // wrapperTx defines a wrapper for driver.Tx
 type wrapperTx struct {
 	tx   driver.Tx
 	span tracer.Span
 	opts Options
+	conn *wrapperConn
+	ctx  context.Context
 }
 
 // Commit implements driver.Tx Commit
@@ -18,7 +24,22 @@ func (w *wrapperTx) Commit() error {
 	if w.span != nil {
 		defer w.span.Finish()
 	}
-	return w.tx.Commit()
+	ts := time.Now()
+	err := w.tx.Commit()
+	td := time.Since(ts)
+
+	if err != nil {
+		w.span.AddLabels("error", true)
+		w.span.AddLabels("err", err.Error())
+	}
+
+	if w.opts.LoggerEnabled {
+		w.opts.Logger.Fields(w.opts.LoggerObserver(w.ctx, "Commit", labelUnknown, td, err)...).Log(w.ctx, w.opts.LoggerLevel)
+	}
+
+	w.ctx = nil
+
+	return err
 }
 
 // Rollback implements driver.Tx Rollback
@@ -26,5 +47,20 @@ func (w *wrapperTx) Rollback() error {
 	if w.span != nil {
 		defer w.span.Finish()
 	}
-	return w.tx.Rollback()
+	ts := time.Now()
+	err := w.tx.Rollback()
+	td := time.Since(ts)
+
+	if err != nil {
+		w.span.AddLabels("error", true)
+		w.span.AddLabels("err", err.Error())
+	}
+
+	if w.opts.LoggerEnabled {
+		w.opts.Logger.Fields(w.opts.LoggerObserver(w.ctx, "Rollback", labelUnknown, td, err)...).Log(w.ctx, w.opts.LoggerLevel)
+	}
+
+	w.ctx = nil
+
+	return err
 }

wrapper.go

@@ -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))
-			}
-		}
-	}()
-}