luna-duclos / instrumentedsql Goto Github PK

The following code works with v0.0.8 of go-oci8, but breaks under v0.0.9 of go-oci8. The commit that triggers the issue is mattn/go-oci8@4a44977

stmt.NumInput() returning -1 is valid for a driver to return.

The issue stems that NumInput returning -1 is fine when driver.NamedValueChecker is used, but not fine when driver.ColumnConverter is used. Normally when both are implemented, only the NamedValueChecker is used, but when the driver NamedValueChecker returns driver.ErrSkip and the driver also implements the ColumnConverter interface, database/sql will use a wrapper (database/sql.ccChecker) to expose the ColumnConverter as if it were a NamedValueChecker. The problem arises that when NumInput returns -1 this causes the wrapper to return nil (without calling the drivers ColumnConverter) and no further functions are called. By comparison if the NamedValueChecker returns driver.ErrSkip and ColumnConverter is not implemented this causes database/sql.defaultCheckNamedValue to be called which performs a required conversion step.

Example application that exhibits the issue, runs fine with go-oci8 v0.0.8 (where NumInput() returns >= 0), fails on v0.0.9 or newer (where NumInput() returns -1). Swapping the comment on the wrappedDriver := line allows the code to work even on v0.0.9 of go-oci8 driver.

Additionally commenting out the wrappedStmt.ColumnConverter func in instrumentedsql also allows the code to run without issue.

package main

import (
	"context"
	"database/sql"
	"database/sql/driver"
	"flag"
	"fmt"
	"github.com/luna-duclos/instrumentedsql"
	"github.com/mattn/go-oci8"
)

type dsnConnector struct {
	driver driver.Driver
	dsn    string
}

func (t dsnConnector) Connect(_ context.Context) (driver.Conn, error) {
	return t.driver.Open(t.dsn)
}

func (t dsnConnector) Driver() driver.Driver {
	return t.driver
}

func main() {
	var (
		dbDSN = flag.String("db-dsn", "", "DB DSN")
	)
	flag.Parse()

	// switching the following two lines results in the code working
	wrappedDriver := instrumentedsql.WrapDriver(oci8.Driver)
	//wrappedDriver := oci8.Driver
	db := sql.OpenDB(dsnConnector{driver: wrappedDriver, dsn: *dbDSN})

	var err error
	var out int64

	err = db.QueryRow( `SELECT 1 FROM DUAL`).Scan(&out)
	if err != nil {
		fmt.Println("Error 0:", err) // This case doesn't error
	} else {
		fmt.Println("No error 0:", out)
	}

	err = db.QueryRow( `SELECT 1 FROM DUAL WHERE :1=0`, 0).Scan(&out)
	if err != nil {
		fmt.Println("Error 1:", err) // binary read for column 0 - error: binary.Write: invalid type int
	} else {
		fmt.Println("No error 1:", out)
	}

	err = db.QueryRow( `SELECT 1 FROM DUAL WHERE 1 >= :1`, sql.NullInt64{Int64: 1, Valid: true}).Scan(&out)
	if err != nil {
		fmt.Println("Error 2:", err) // ORA-01722: invalid number
	} else {
		fmt.Println("No error 2:", out)
	}

	err = db.QueryRow( `SELECT 1 FROM DUAL WHERE 1 >= :1`, sql.NullFloat64{Float64: 1, Valid: true}).Scan(&out)
	if err != nil {
		fmt.Println("Error 3:", err) // ORA-01722: invalid number
	} else {
		fmt.Println("No error 3:", out)
	}
}

pseudocode of logic differences when using go-oci8 vs wrapped in instrumentedsql:

oci8: implements NamedValueChecker but not ColumnConverter
	database/sql.driverArgsConnLocked logic
		calls NamedValueChecker
			NamedValueChecker returns driver.ErrSkip
		calls database/sql.defaultCheckNamedValue
			calls driver.DefaultParameterConverter.ConvertValue(nv.Value)

instrumentedsql wrapping oci8: implements NamedValueChecker and ColumnConverter
	database/sql.driverArgsConnLocked logic
		calls NamedValueChecker
			calls oci8.NamedValueChecker
				oci8.NamedValueChecker returns driver.ErrSkip
		calls database/sql.ccChecker ColumnConverter wrapper wrapping instrumentedsql.ColumnConverter
			// c.want is -1 in oci8 v0.0.9 and newer
			if c.want <= index {
				// ColumnConverter only accepts an index, so the wrapper bails out here returning nil
				return nil
			}
			// note that instrumentedsql.ColumnConverter is never called, just the existence of this func is enough to cause the issue
		since nil was returned not driver.ErrSkip, database/sql.defaultCheckNamedValue is not called -> this causes an error

A fix would be to only implement NamedValueChecker and not ColumnConverter on go1.9+ to avoid the side effect of ColumnConverter existing.

If a driver only implements ColumnConverter and not NamedValueChecker on go1.19+, or if a driver implements both and NamedValueChecker returns driver.ErrSkip, instrumentedsql can perform wrapping of ColumnConverter as a NamedValueChecker (a copy paste of database/sql.ccChecker would work, unfortunately it's not public to be able to use it as-is). The important distinction vs what happens now is that the wrapper must only be used if the underlying driver implements ColumnConverter. I suspect that NumInput returning -1 when ColumnConverter is implemented is not a valid condition.

It's a stated goal of the project that metrics, as well as logging and tracing should be exposed. This issue tracks the implementation of metrics in the codebase, and is open to discussion as to what kind of abstraction is suitable to allow different type of metrics exporters, such as statsd, prometheus.

A similar goal has been approached by the OpenCensus team, so I think we could take some inspiration from the existing OpenCensus stats.

I think there is a bug in how this package wraps the snowflake driver. Consider this example code:

// We should have two results each with a single row.
statements := "SHOW ROLES LIKE 'SYSADMIN';\nSHOW ROLES LIKE 'ACCOUNTADMIN';"

// Set up a Snowflake connection
cfg := &gosnowflake.Config{
	Account:   os.Getenv("SNOWFLAKE_ACCOUNT"),
	User:      os.Getenv("SNOWFLAKE_USER"),
	Password:  os.Getenv("SNOWFLAKE_PASSWORD"),
	Database:  os.Getenv("SNOWFLAKE_DATABASE"),
	Schema:    os.Getenv("SNOWFLAKE_SCHEMA"),
	Warehouse: os.Getenv("SNOWFLAKE_WAREHOUSE"),
}
dsn, err := gosnowflake.DSN(cfg)
if err != nil {
	log.Fatal(err)
}

// works
// db, err := sql.Open("snowflake", dsn)

// works
// sql.Register("snowflake-driver", &gosnowflake.SnowflakeDriver{})
// db, err := sql.Open("snowflake-driver", dsn)

// fails because rows.NextResultSet() is always false
sql.Register("snowflake-instrumented", instrumentedsql.WrapDriver(&gosnowflake.SnowflakeDriver{}))
db, err := sql.Open("snowflake-instrumented", dsn)

if err != nil {
	log.Fatal(err)
}
defer db.Close()

// Set up a context with a timeout
ctx := context.Background()
ctx, cancel := context.WithTimeout(ctx, 10*time.Second)
defer cancel()

// Query Snowflake using the WithMultiStatement method
multiStmtCtx, err := gosnowflake.WithMultiStatement(ctx, 0)
if err != nil {
	log.Fatal(err)
}
rows, err := db.QueryContext(multiStmtCtx, statements)

if err != nil {
	log.Fatal(err)
}
defer rows.Close()

// Process all the rows from all the queries and store the results in a list
results := make([]map[string]interface{}, 0)
processRows := func(rows *sql.Rows) error {
	// hidden
}

if err := processRows(rows); err != nil {
	log.Fatal(err)
}

for rows.NextResultSet() {
	if err := processRows(rows); err != nil {
		log.Fatal(err)
	}
}

marshalledResults, _ := json.Marshal(results)
fmt.Printf("%v", string(marshalledResults))

The rows.NextResultSet() is always false when wrapping the snowflake driver with instrumentedsql. Since this was only a problem when wrapping with instrumentedsql I think the issue is in this project. However, I should also note this older but seemly related gosnowflake issue. That being said, this should have been fixed in a later version with this issue. But again, sql.Register("snowflake-driver", &gosnowflake.SnowflakeDriver{}) this worked so that gives me confidence that the bug is not there.

Hi @luna-duclos,

Thank you for forking this and adding the features you have added!

I was wondering if you are still maintaining this project as I am planning on using it in another (big) project?

Cc: @aeneasr

Thanks you for the useful package.

In my MySQLopentracing case, each query will result to 4 records.

And the sql-conn-query has error driver.ErrSkip "driver: skip fast-path; continue as if unimplemented".
It is from MySQL driver, e.g.
https://github.com/go-sql-driver/mysql/blob/6be42e0ff99645d7d9626d779001a46e39c5f280/connection.go#L368-L370

Can I have any approach to ignore this error?
Do you think adding a condition err == nil || err == driver.ErrSkip is Okay?

Expected behaviour

When tagging a span as error, the opentracing specification states that one should add a tag named error.

Current behaviour

This package is adding a tag named err which does not get rendered appropriately by a tracing system that is OT compliant - see screenshot from Jaeger:

Proposal

Update https://github.com/luna-duclos/instrumentedsql/blob/master/opentracing/tracer.go#L52 such that it sets a tag named error instead.

✋@luna-duclos I am happy to raise PR if you agree with the above

	github.com/luna-duclos/instrumentedsql tested by
	github.com/luna-duclos/instrumentedsql.test imports
	github.com/luna-duclos/instrumentedsql/google imports
	cloud.google.com/go/trace: module cloud.google.com/go@latest (v0.46.2) found, but does not contain package cloud.google.com/go/trace

This package had been marked obsolete and has now been removed in the latest release, so this repo no longer builds if 0.46.2 is used.

googleapis/google-cloud-go@dc45690

Then method wrappedRows.Next always generates a span that contains an io.EOF error.
Should we ignore this error, which means no more rows are exist.

func (r wrappedRows) Next(dest []driver.Value) (err error) {
	if !r.hasOpExcluded(OpSQLRowsNext) {
		span := r.GetSpan(r.ctx).NewChild(OpSQLRowsNext)
		span.SetLabel("component", "database/sql")
		defer func() {
                        // Then last call of Next always generates an io.EOF error
			span.SetError(err)
			span.Finish()
		}()
	}

	start := time.Now()
	defer func() {
		r.Log(r.ctx, OpSQLRowsNext, "err", err, "duration", time.Since(start))
	}()

        // ref: https://github.com/luna-duclos/instrumentedsql/blob/ecad98b20aecc3b06d17c86f154726ebbf269650/sql.go#L579
	return r.parent.Next(dest)
}

Should we replace with this

                defer func() {
                        if err != io.EOF {
			    span.SetError(err)
                        }
			span.Finish()
		}()

ref: the comments of Rows.Next.

type Rows interface {
	// Next is called to populate the next row of data into
	// the provided slice. The provided slice will be the same
	// size as the Columns() are wide.
	//
	// Next should return io.EOF when there are no more rows.
	//
	// The dest should not be written to outside of Next. Care
	// should be taken when closing Rows not to modify
	// a buffer held in dest.
	Next(dest []Value) error
}

Expected

When the WithOmitArgs() is set, I expect query arguments to not be included in any of the spans.

Current behaviour

The arg tag is correctly omitted from the sql-conn-exec span, but it is included in the sql-stmt-exec. This may be specifically related to named queries?

Cc: @luna-duclos

https://github.com/luna-duclos/instrumentedsql/blob/master/sql.go#L310

If the wrapped driver implements neither Queryer nor QueryerContext, we log the query twice, once in QueryerContext and once when the statement is prepared and executed after ErrSkip. I propose it would be better to check earlier whether the driver implements these interfaces (we can cache the check if performance is a worry) and if not, immediately return ErrSkip from QueryerContext without extra logging (to better reflect the behavior of the unwrapped driver).

I am willing to work on a patch if this change sounds ok.

Currently if you run a query that returns a lot of rows, a separate span is created for sql-conn-query, and then different unrelated spans for sql-rows-next. If there is only one or two rows this isn't a big deal, but when there's a lot of rows (especially if it takes a considerable amount of time to read them all) it becomes quite difficult to see as the number of spans gets quite large and it's not possible to easily collapse the query down where it can be viewed easily.

This also occurs with transaction start and end with the queries run inside the transaction not being related at all either.

One could manually create a span around each query, but then that increases the boiler plate code required in a project. Ideally the library would have an option that when a query is run a span is created and all the related spans are created under that parent. Likewise when a transaction block is entered the same behaviour occurs.

Another option that the opentracing-contrib/go-stdlib/nethttp library (https://github.com/opentracing-contrib/go-stdlib/tree/master/nethttp) makes use of is creating a single span for the HTTP request, then using logs to signal the different stages. This approach probably wouldn't make much sense for transaction blocks, but could work well for queries and next row calls (1000 spans vs 1 span with 1000 logs for a query that returns 1000 rows)

I'm not sure if there's any technical restrictions around achieving either of these options. At a glance it seems transactions might be harder as you're passing a separate context.Context to each query you run within the transaction and some people might want to leverage spans in between the two. On the other hand though rows.Next() does not take a context so there isn't an opportunity to pass a different span here anyway so it seems like it would make sense to do something automatically in the library for this case.

sql_example_test.go brings many many many dependencies, just for testing.
This pollutes the go.sum of this package and the go.sum of downstream projects as well (even if using instrumentedsql just in tests) and makes hard for those projects to keep track of dependency to decide upgrades.

Please consider moving this test to a separate module to reduce go.sum pollution.

The list of possible messages received by a logger is part of the API and should be clearly documented.
The best should be to expose constants with the message (to reduce the risks of typo in a client wanting to match specific messages).

Problem

Presently, this library cannot deal with any breaking changes that may be introduced by dependencies (e.g. most notably opentracing & opencensus). If you were to clone the project and fetch the latest deps go get -u ./..., you will not be able to build:

opencensus/opencensus.go:38:30: s.parent.StartSpan undefined (type *trace.Span has no field or method StartSpan)
opencensus/opencensus.go:42:10: s.parent.SetAttributes undefined (type *trace.Span has no field or method SetAttributes)
opencensus/opencensus.go:42:46: trace.StringAttribute is not a type
opencensus/opencensus.go:50:10: s.parent.SetAttributes undefined (type *trace.Span has no field or method SetAttributes)
opencensus/opencensus.go:50:46: trace.StringAttribute is not a type

The above output indicates a breaking change to the opencensus library was made at some point. Ths is one of them - census-instrumentation/opencensus-go#595 - another exists as StartSpan(name string) is no longer a valid method.

This is problematic for contributors and those using the library with a newer/older version of a dependency. How are they supposed to know which one to use?

Proposal

• Start versioning dependencies using a dep manager like dep or go modules.
• Fix existing breakages
• Breaking changes introduced by dependencies may impact interfaces defined by this library (as shown above), therefore we must also start tagging releases as per discussed in #6 (comment)

Easiest solution will be add a dep manager, start using the latest & greatest versions of the dependencies, and moving forward follow proper practices by tagging releases. I can help with this.

Cc: @luna-duclos

The links in the README still point to the original project documentation while this fork is much more useful.

The Opentracing sematic conventions document "standardizes" some tags for different purposes, many APM implementations rely on these to properly display traces & spans.

Unfortunately this project does not make use of these. My proposal is to change this:)

This would mean e.g. in addtion or instead of having

span := c.GetSpan(ctx).NewChild(OpSQLTxBegin)
span.SetLabel("component", "database/sql")

one would have

span := c.GetSpan(ctx).NewChild(OpSQLTxBegin)
span.SetLabel("component", "luna-duclos")
span.SetLabel("db.type", "sql")

in all relevant places. Actually the component tag should be set by a calling app, so it should be configurable. In addition all places with

span.SetLabel("query", query)
if !c.OmitArgs {
    span.SetLabel("args", formatArgs(args))
}

would be changed to

span.SetLabel("db.statement", query)
if !c.OmitArgs {
    span.SetLabel("args", formatArgs(args))
}

Last, but not least, db.instance tag should be set as well.

If backwards compatibility is required, it could be achieved by the introduction of additional options. If you like I can create a PR.