[Bug]: SQLGetDiagRec error when instrumenting Db2 created with sql.Open()

[yabinma]

Problem Description

Dear team,

As the doc mentioned in https://www.ibm.com/docs/en/instana-observability/225?topic=go-collector-common-operations#how-to-instrument-a-database-connection-created-with-sqlopen , it could instrument a database connection created with sql.Open().

And then I followed the instruction to do it as below,

`	// Create a new instana.Sensor instance
sensor := instana.NewSensor("dv-api-instana-db")

// Instrument the driver
instana.InstrumentSQLDriver(sensor, "go_ibm_db", &db2.Driver{})

// Create an instance of *sql.DB to use for database queries
db, err := instana.SQLOpen("go_ibm_db", con)`

But the test failed with error "SQLGetDiagRec failed: ret=-2". I debugged the code and found go-sensor could not work properly with Db2 Go driver implementation go_ibm_db (https://github.com/ibmdb/go_ibm_db)

go-sensor will register a driver named as XXX_with_instana, and then when instana.SQLOpen(), it will also look up the driver name with suffix "_with_instana". In my case, the driver name is go_ibm_db__with_instana.

Looking at the code in https://github.com/ibmdb/go_ibm_db/blob/f4db66e52b44096ec048ffb01e8932712a4c9c74/driver.go#L23, when initializing/register a driver, there are extra steps. This might be the reason why the registered driver go_ibm_db__with_instana could not work properly with go_ibm_db.

Can you please have a check and make a plan to support go_ibm_db?

---

Or at least a change to https://github.com/instana/go-sensor/blob/ba09ff927b50605fbac4f9e9932a4c846e525477/instrumentation_sql.go#L55 , in the SQLOpen function, there is a step to always add a suffix "_with_instana".

func SQLOpen(driverName, dataSourceName string) (*sql.DB, error) {

	if !strings.HasSuffix(driverName, "_with_instana") {
		driverName += "_with_instana"
	}

	return sql.Open(driverName, dataSourceName)
}

Actually in go_ibm_db, it will register a driver with the original name, 'go_ibm_db' in this case. So when running sql.Open("go_ibm_db", dataSourceName), it does work( by commenting the lines as below). This is a local test only. I don't know if all the other functions work or not.

	//if !strings.HasSuffix(driverName, "_with_instana") {
	//	driverName += "_with_instana"
	//}

I am thinking if a parameter added to SQLOpen(), to add an option if a suffix is added to the original driver name.

Minimal, Complete, Verifiable, Example

No response

Go Version

go 1.18.5

go.mod

github.com/ibmdb/go_ibm_db v0.4.1
github.com/instana/go-sensor v1.43.4

go env

N/A

[willianpc]

Hi @maxatcn , thanks for taking the time to report the issue. We will take a look at it.

[willianpc]

Hi @maxatcn ,

Could you try to use SQLInstrumentAndOpen instead of InstrumentSQLDriver and SQLOpen? In the traditional way - which is the one you are using at the moment - the Go instrumentation works for drivers without extra options.

In the case of ibm_db, there is some extra init settings, which are missed by &db2.Driver{}.

The following should work as intended:

import (
  _ "github.com/ibmdb/go_ibm_db"
  ...
)
...

// Create a new instana.Sensor instance
sensor := instana.NewSensor("dv-api-instana-db")

// Create an instance of *sql.DB to use for database queries
db, err := instana.SQLInstrumentAndOpen(sensor, "go_ibm_db", con)
...

Let us know if this solution solves the problem. Cheers,

_ Willian

[yabinma]

Thanks @willianpc for the update. I tested it today. The "SQLGetDiagRec failed" issue is fixed. It looks the Go code connects to Instana agent successfully.

The new issue, the metrics does not show in Instana console.

I opened the DEBUG in log level, the log shows as below,

2022/09/01 11:20:58 instana: DEBUG: initializing agent
2022/09/01 11:20:58 instana: WARN: Stan is on the scene. Starting Instana instrumentation.
2022/09/01 11:20:58 instana: DEBUG: initializing fsm
2022/09/01 11:20:58 instana: DEBUG: initializing meter
2022/09/01 11:20:58 instana: DEBUG: initialized Instana sensor v1.43.4
2022/09/01 11:20:58 instana: DEBUG: checking host 10.187.28.138
2022/09/01 11:20:58 instana: DEBUG: agent lookup success 10.187.28.138
2022/09/01 11:20:58 instana: DEBUG: announcing sensor to the agent
2022/09/01 11:20:58 instana: INFO: error while reading proc/9/cpuset:open proc/9/cpuset: no such file or directory
2022/09/01 11:20:58 instana: DEBUG: got cmdline from /proc: ./dvapi-server
2022/09/01 11:20:58 Serving dvapi at https://[::]:3300
2022/09/01 11:20:58 instana: INFO: failed to send a request to http://10.187.28.138:42699/com.instana.plugin.golang.discovery: 404 Not Found
2022/09/01 11:20:58 instana: DEBUG: Cannot announce sensor. Scheduling retry.
2022/09/01 11:21:06 instana: DEBUG: no span context provided with GET /docs
2022/09/01 11:21:16 instana: DEBUG: no span context provided with GET /docs
2022/09/01 11:21:16 instana: DEBUG: no span context provided with GET /docs
2022/09/01 11:21:18 instana: DEBUG: announcing sensor to the agent
2022/09/01 11:21:18 instana: INFO: error while reading proc/9/cpuset:open proc/9/cpuset: no such file or directory
2022/09/01 11:21:18 instana: DEBUG: got cmdline from /proc: ./dvapi-server
2022/09/01 11:21:18 instana: INFO: Host agent available. We're in business. Announced pid:22095
2022/09/01 11:21:18 instana: DEBUG: testing communication with the agent
2022/09/01 11:21:26 instana: DEBUG: no span context provided with GET /docs
2022/09/01 11:21:26 instana: DEBUG: no span context provided with GET /docs
2022/09/01 11:21:36 instana: DEBUG: no span context provided with GET /docs
2022/09/01 11:21:36 instana: DEBUG: no span context provided with GET /docs
2022/09/01 11:21:41 instana: DEBUG: no span context provided with GET /v1/virtualize/loading/status
2022/09/01 11:21:46 instana: DEBUG: no span context provided with GET /docs
2022/09/01 11:21:46 instana: DEBUG: no span context provided with GET /docs
2022/09/01 11:21:56 instana: DEBUG: no span context provided with GET /docs
2022/09/01 11:21:56 instana: DEBUG: no span context provided with GET /docs
2022/09/01 11:22:06 instana: DEBUG: no span context provided with GET /docs
2022/09/01 11:22:06 instana: DEBUG: no span context provided with GET /docs
2022/09/01 11:22:15 instana: DEBUG: no span context provided with GET /v1/virtualize/loading/status
2022/09/01 11:22:16 instana: DEBUG: no span context provided with GET /docs
2022/09/01 11:22:16 instana: DEBUG: no span context provided with GET /docs
2022/09/01 11:22:26 instana: DEBUG: no span context provided with GET /docs
2022/09/01 11:22:26 instana: DEBUG: no span context provided with GET /docs
2022/09/01 11:22:36 instana: DEBUG: no span context provided with GET /docs
2022/09/01 11:22:36 instana: DEBUG: no span context provided with GET /docs
2022/09/01 11:22:37 instana: DEBUG: no span context provided with GET /v1/datasource/objectstore_connections
2022/09/01 11:22:37 instana: DEBUG: no span context provided with GET /v2/catalog/primary

Any clue to find the root cause? Anything more required please let me know. Thanks.

[willianpc]

That's great news!

About your issue with not getting spans in Instana, unfortunately this goes out of the scope of the Go tracer itself. I kindly ask you to read the documentation at https://www.ibm.com/docs/en/instana-observability/current?topic=technologies-monitoring-go or file a support ticket on Zendesk.

In case you opt for the latter, it would be useful to provide some code snippet to help the Support team to identify the issue.

Best, _ Willian