Instrumenting gorm SQL logging with otelgorm and otelzap

[igrayson]

trafficstars

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.

[igrayson]

Ultimately we're not blocked by this. We don't want to log fully unredacted SQL, so we won't enable gorm's Logger in production — and we don't really need tracing in pre-production.

[igrayson]

Another way to mitigate this: change otelzap to always add trace_id to zap.Logger calls, if it's available — even if the span is no longer recording. This seems like a generally good thing to do.

[vmihailenco]

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.

Using a gorm.Plugin sounds like a proper solution here if you want queries with trace ids in your logs.

even if the span is no longer recording

I'd assume trace id to be zero if span is not recording.

[igrayson]

I'd assume trace id to be zero if span is not recording.

It remains available. Before I tried otelzap, we had a small hook to add it without checking isrecording().