This PR adds an option to otelgorm to include query variables in the db.statement attribute. I noticed that query variables were being included by default, but this may not be suitable for most users as query variables can contain sensitive values and would be a security issue if included in traces. For that reason, I've made including query variables opt-in.

Before:

SELECT "x" FROM "y" WHERE email_address = '[email protected]'

UPDATE "z" SET "address"='123 Canwefixit Street' WHERE "user_id" = 'bobthebuilder'

After:

SELECT "x" FROM "y" WHERE email_address = '?'

UPDATE "z" SET "address"='?' WHERE "user_id" = '?'

Example

l := otelzap.Ctx(ctx).WithOptions(zap.Fields(zap.String("FOO", "BAR")))
l.Info("Hello")

I expect that there will be FOO:BAR field.

The field is added to the zap encoder, but only for *zap.Logger. skipCaller is ignored: https://github.com/uptrace/opentelemetry-go-extra/blob/main/otelzap/otelzap.go#L31

type Logger struct {
	*zap.Logger
	skipCaller *zap.Logger

After that code is using skipCaller for log output (https://github.com/uptrace/opentelemetry-go-extra/blob/main/otelzap/otelzap.go#L262).

IMO someone forgot to add to func (l *Logger) WithOptions(opts ...zap.Option) *Logger

	clone.skipCaller = l.skipCaller.WithOptions(opts...)

https://github.com/uptrace/opentelemetry-go-extra/blob/main/otelzap/otelzap.go#L63

In the Readme .it say otelzap.WithTraceIDField(true) configures the logger to add trace_id field to structured log messages

but actually it does not.

func (s SugaredLoggerWithCtx) Debugw(msg string, keysAndValues ...interface{}) {
	s.s.logKVs(s.ctx, zap.DebugLevel, msg, keysAndValues)
	s.s.skipCaller.Debugw(msg, keysAndValues...)
}

I found in logKVs function,it change keysAndValues,and return, but outside,the code does not use the return value ,so that's why there is no trace-id in the log file

Hey, I think something is messed up in the folder structure and module structure.

I'm including and running the otelsql. golangci-lint fails with

WARN [runner] Can't run linter goanalysis_metalinter: inspect: failed to load package otelsql: could not load export data: no export data for "github.com/uptrace/opentelemetry-go-extra/otelsql"

this is the online package in happens in, probably because github.com/uptrace/opentelemetry-go-extra/otelsql is not the actual url of the module. (you get 404 if u go there)

Cheers

Hey :) Cool pkg. I've been trying it out with a Fiber + otel + zap setup, works good. execpt from mild inconsistencies in behavoiur (which I fixed in my PR)

Code:

log := otelzap.New(zap.L(), otelzap.WithTraceIDField(true), otelzap.WithMinLevel(zap.DebugLevel))
log.Ctx(c.UserContext()).Info("no trace_id field!")
log.InfoContext(c.UserContext(), "have trace_id field :)")

Results in

2021-11-25T08:50:53.737Z        INFO    [email protected]/otelzap.go:259   no trace_id field! 
2021-11-25T08:50:53.737Z        INFO    [email protected]/otelzap.go:101   have trace_id field :)     {"trace_id": "40ed735823dc565b8b9bf7db2da42b10"}

Btw the tracing in my otel-collector works just fine, it's just the logger :)

I'm trying to use otelzap as middleware for fiber, but I'm not seeing log messages provided with a span context showing up in the span output. Trace IDs also do not appear in the log message, despite the logger option being present. Also perhaps relevant, Fiber is being run with Immutable set to true.

Here is the middleware function with some additional code comments:

func (a *ManagementAPI) RequestLogging(c *fiber.Ctx) error {
	start := time.Now()

	c.Next()

        // c.UserContext() is set by an earlier middleware function that creates a "request" span
	ctx, span := a.config.Tracer(ServiceName).Start(c.UserContext(), "request_log")
	defer span.End()

        // a.logger has type *otelzap.Logger
	a.logger.Ctx(ctx).Info(
		fmt.Sprintf("%s", c.Path()),
		zap.Int("status", c.Response().StatusCode()),
		zap.String("method", c.Method()),
		zap.String("path", c.Path()),
		zap.String("ip", c.IP()),
		zap.ByteString("user_agent", c.Request().Header.UserAgent()),
		zap.Int64("latency_ns", time.Now().Sub(start).Nanoseconds()),
		// zap.String("trace_id", span.SpanContext().TraceID().String()),
	)

	return nil
}

The span context coming from c.UserContext() also appears to be valid, as it does link parent and child spans correctly.

The logger being used in the middleware function is created by this function:

func L(name string) *otelzap.Logger {
	return otelzap.New(zap.L().Named(name), otelzap.WithTraceIDField(true))
}

Before then, the global loggers are set up like so:

func InitializeGlobalLogger(c LoggingConfig) error {
	zapConfig, err := zapConfig(c)
	if err != nil {
		return fmt.Errorf("problem creating zap configuration: %w\n", err)
	}

	zapLogger := zap.Must(zapConfig.Build())
	zapLogger = zapLogger.With(zap.String("id", c.AppID()))
	defer zapLogger.Sync()

	otelLogger := otelzap.New(zapLogger, otelzap.WithTraceIDField(true))
	defer otelLogger.Sync()

	zap.ReplaceGlobals(zapLogger)
	otelzap.ReplaceGlobals(otelLogger)

	return nil
}

The project is using go 1.19, and these versions may be relevant:

	go.uber.org/zap v1.23.0
	github.com/uptrace/opentelemetry-go-extra/otelutil v0.1.17 // indirect
	github.com/uptrace/opentelemetry-go-extra/otelzap v0.1.17 // indirect
	go.opentelemetry.io/otel v1.11.2 // indirect
	go.opentelemetry.io/otel/exporters/stdout/stdouttrace v1.11.2 // indirect
	go.opentelemetry.io/otel/sdk v1.11.2 // indirect
	go.opentelemetry.io/otel/trace v1.11.2 // indirect

Any help would be greatly appreciated.

The otelgorm package utilizes replacement the statement context when the before is called...

https://github.com/uptrace/opentelemetry-go-extra/blob/fcc6618cc37ccf42377873b4b898db73c5081384/otelgorm/otelgorm.go#L97-L101

However, the statement context is never restored to its original in the corresponding after() call. Thus, after the execution of the query finishes, if the db.Statement object is reused, then the context of the statement will still be using the context corresponding to the now-ended span.

The following is a failing test case:

  {
    do: func(ctx context.Context, db *gorm.DB) {
      var count int64
      query := db.WithContext(ctx).Table("generate_series(1, 10)")
      _, _ = query.Select("*").Rows()
      _ = query.Count(&count)
    },
    require: func(t *testing.T, spans []sdktrace.ReadOnlySpan) {
      require.Equal(t, 2, len(spans))
      require.Equal(
        t,
        spans[0].Parent().SpanID().String(),
        spans[1].Parent().SpanID().String(),
      )
    },
  }

In do, you can see two separate queries being run (with Rows() and Count()). To me, the spans generated for these two queries should have the same parent. Instead, otelgorm is making the span of the second query a child of the first. If I added a third execution using the query value, that span would be a child of the second. Ideally, the plugin would restore the statement back to it's original so the statement could be reused.

The only way I could think of doing this was to store the original context in the newly derived context, and then during the after callback pop it out. But that seemed error prone given that Gorm doesn't enforce the ordering of callbacks, so we'd have to hope another callback isn't trying to do the same thing but with a different ordering.

This PR:

Causes the plugin to not create spans when Gorm makes callbacks with sessions marked as DryRun. This is technically a backwards-incompatible change, as users will not see the same spans emitted as before (see below for rationale).

It also adds in a new WithDryRunSpans() option for otelgorm. When this option is enabled, functionality reverts to how the plugin operated prior (e.g., adding spans for DryRun callbacks).

Why:

There are times that Gorm will trigger the Query() callback with DryRun specified. This is often because either the user has asked for a SQL query to be rendered but not run, or in our case because Gorm makes multiple Query() calls to render the various subqueries making up a larger query. This causes spurious spans being created for what isn't even a call to the database. We would rather not see these spans, as we mostly care about the times we ARE making a request to a database.

Here is an example of one of our traces currently. During the request, we run 8 SQL queries, but there are 20 total spans generated. The group of 12 spans on the bottom don't represent calls to the database, but instead rendering of subqueries.

Here is what this trace looks like as a result of the change. Now, only the 8 queries that hit the database are shown.

This change would cause DryRun callbacks to not create spans by default, but instead adds for an option to enable creating spans in these cases. This is technically a backwards-incompatible change, but probably one that most users want.

pgx driver overrides CheckNamedValue to empty, which causes the driver to fail from working.

The otelsql should call connection NamedValueChecker if there is such available.

If not, return ErrSkip.

Here's the fix https://github.com/oshurubura/opentelemetry-go-extra/commit/73d420c07429c6ebd18effe6551844345eece864. I'd love to create PR, but could you please let me know what else is required for a PR to be accepted and merged into the main trunk?

This MR fixes #30. The commit message is pretty clear. Feel free to update the wording.

I added 2 test cases: for the simplest case with an array of strings and the complex one with an array of durations. IMO other cases should work without any issues as well.

This PR adds an option to otelgorm to not report DB stats metrics. Some users like myself may not be currently using OpenTelemetry for metrics and wish to be able to disable this functionality. This functionality might also overlap or conflict with the Prometheus plugin for gorm: https://gorm.io/docs/prometheus.html

I suspect the attributes provided to OpenDB are being dropped inside sqlOpenDB when setting up db.Stats reporting via ReportDBStatsMetrics.

func sqlOpenDB(connector driver.Connector, instrum *dbInstrum) *sql.DB {
	db := sql.OpenDB(connector)
	ReportDBStatsMetrics(db, WithMeterProvider(instrum.meterProvider))
	return db
}

should probably look something like this

func sqlOpenDB(connector driver.Connector, instrum *dbInstrum) *sql.DB {
	db := sql.OpenDB(connector)
	ReportDBStatsMetrics(db, WithMeterProvider(instrum.meterProvider), WithAttributes(instrum.attrs))
	return db
}

I'm not seeing the db.system label on any of the db.Stats metrics but it is still present as expected on the query.timing metric that comes from the tracing collection.

My current workaround is to direct register the db.Stats collection with ReportDBStatsMetrics but that doesn't disable the automatic collection started by OpenDB.

This PR aims to add a possibility to dynamically resolve fields from the provided context and fix #59.

Our use case is that Datadog requires us to provide both the spanId and the traceId to the logged message in the keys dd.span_id and dd.trace_id. In addition, Datadog expects the trace information to be in another format for traces and logs to be correlated. This change will make it possible for us to configure this transformation in the logger itself instead of providing the transformation in every log message.

Below is a sample implementation for Datadog with this change that will print the converted trace information: ERROR example/main.go:29 hello from zap {"dd.trace_id": "2730366003796952559", "dd.span_id": "2730366003796952559"}

func main() {
    l, err := zap.NewDevelopment()
    if err != nil {
        panic(err)
    }
    logger = otelzap.New(l, WithDatadogFields())
    
    ctx, span := tracer.Start(context.Background(), "root")
    defer span.End()

    logger.Ctx(ctx).Error("hello from zap")
}

func WithDatadogFields() otelzap.Option {
	convertTraceId := func(id string) string {
		if len(id) < 16 {
			return ""
		}
		if len(id) > 16 {
			id = id[16:]
		}
		intValue, err := strconv.ParseUint(id, 16, 64)
		if err != nil {
			return ""
		}
		return strconv.FormatUint(intValue, 10)
	}

	return otelzap.WithDynamicFields(func(ctx context.Context) []zap.Field {
		fields := make([]zap.Field, 0)
		span := trace.SpanFromContext(ctx)
		if span.IsRecording() {
			fields = append(fields, zap.String("dd.trace_id", convertTraceId(span.SpanContext().TraceID().String())))
			fields = append(fields, zap.String("dd.span_id", convertTraceId(span.SpanContext().SpanID().String())))
		}
		return fields
	})
}

Trying to create a wrapper pkg for otelzap logger

package logger

type logger struct {
	z  *zap.SugaredLogger
	oz *otelzap.SugaredLogger
}

var globalLogger *logger

func init() {
	level := getLoggerLevel(os.Getenv("LOGGER_LEVEL"))

	encoderConfig := zap.NewProductionEncoderConfig()
	encoderConfig.EncodeTime = zapcore.RFC3339TimeEncoder

	zapLogger, err := zap.Config{
		Level:            zap.NewAtomicLevelAt(level),
		Development:      true,
		Encoding:         "console",
		EncoderConfig:    encoderConfig,
		OutputPaths:      []string{"stderr"},
		ErrorOutputPaths: []string{"stderr"},
	}.Build(zap.WithCaller(true), zap.AddStacktrace(zapcore.ErrorLevel), zap.AddCallerSkip(1))
	if err != nil {
		panic(err)
	}

	globalLogger = &logger{
		z:  zapLogger.Sugar(),
		oz: otelzap.New(zapLogger, otelzap.WithCaller(false), otelzap.WithTraceIDField(true)).Sugar(),
	}
}

func DebugwContext(ctx context.Context, msg string, keysAndValues ...interface{}) {
	globalLogger.oz.DebugwContext(ctx, msg, keysAndValues...)
}

But when i try to execute DebugwContext which uses otelzap logger i see a caller(even if im passed caller false option and don't see a traceId field)

logger.DebugwContext(ctx, "i'm traced btw", []interface{}{}...)

output:
2022-10-14T10:45:54+03:00       debug   logger/logger.go:83     i'm traced btw

Hi. First, thanks for the great work instrumenting these libs!

I came across this issue while setting up otelgorm and otelzap.

Problem: when configuring gorm with both otelgorm and an otelzap logger, the otelzap logger will not emit span events or add span attributes (like a trace_id), for SQL logging.

I.e., configure gorm with:

	db, err := gorm.Open(postgres.Open(dsn), &gorm.Config{
		Logger: gormLogger, // a thin wrapper around otelzap to fit gorm's logger interface.
	})

        db.Use(otelgorm.NewPlugin())
        
        db.WithContext(someCtx).Exec("select 1")

I think this happens because: gorm calls otelgorm before calling its configured logger (see here), so:

1. otelgorm does its job and ends the span
2. when called to log the statement's SQL, otelzap checks if the span is recording (it's not), skips its job and emits an uninstrumented log.

I see two ways to fix this:

• Update gorm to be able to log before running callbacks. I can see why this would be hard.
• Do not use gorm's Logger config to log SQL. Instead create a gorm.Plugin to log SQL, carefully configuring it to run before otelgorm.

The second one is a hack the user might build if (1) instrumented SQL logging is very important and (2) we can't change gorm.

otelgorm has the WithoutQueryVariables() option to keep the emitted statement unparameterized. I would like to emit statements that are partially parameterized. My use-case is: my service occasionally handles information which I do not want logged. On the other hand, it's really useful being able to see which IDs a database statement actually hit.

One way to satisfy this is providing something like:

func WithQueryVariableFilter(predicate func(var interface{}) bool) Option

.. and I could provide a filter that only allows uuid strings (etc)

Thoughts? I'd be happy to open a PR.