Panic: not implemented errors with MSSQL (Azure Managed Instance)

[marevers]

We are experiencing panic: not implemented errors (and a subsequent crash of the exporter) when using it with an Azure Managed Instance MSSQL database. We have had success with other Azure-hosted MSSQL databases before, but the only difference is that the managed instance forces encrypted traffic which could be the cause of the issue. We have attempted changing the github.com/denisenkom/go-mssqldb dependency to a higher version but this unfortunately does not fix the issue.

Here's a stack trace of such an error happening:

panic: Not implemented

goroutine 45 [running]:
github.com/denisenkom/go-mssqldb.passthroughConn.SetWriteDeadline(...)
    /src/vendor/github.com/denisenkom/go-mssqldb/net.go:167
crypto/tls.(*Conn).SetWriteDeadline(...)
    /usr/local/go/src/crypto/tls/conn.go:151
crypto/tls.(*Conn).closeNotify(0xc000910700)
    /usr/local/go/src/crypto/tls/conn.go:1361 +0xdb
crypto/tls.(*Conn).Close(0xc0000cadb8)
    /usr/local/go/src/crypto/tls/conn.go:1331 +0x69
github.com/denisenkom/go-mssqldb.(*Conn).Close(0xc0000cadd0)
    /src/vendor/github.com/denisenkom/go-mssqldb/mssql.go:361 +0x28
database/sql.(*driverConn).finalClose.func2()
    /usr/local/go/src/database/sql/sql.go:646 +0x3c
database/sql.withLock({0x12eb6e8, 0xc000629e60}, 0xc0000cae88)
    /usr/local/go/src/database/sql/sql.go:3396 +0x8c
database/sql.(*driverConn).finalClose(0xc000629e60)
    /usr/local/go/src/database/sql/sql.go:644 +0x117

[dewey]

Looks like this is an upstream issue from the library you are using, there's an open issue there: https://github.com/denisenkom/go-mssqldb/issues/688

I'd suggest to bring it up there, once this is fixed we can update the dependencies on our end.

[marevers]

Yes, but the upstream issue was supposedly fixed in deniseenkom/go-mssqldb/releases/tag/v0.10.0 (at least for Go 1.16). I have tested it with that dependency, but it still does not seem to work.

However, if I build with Go 1.15, the issue is resolved. Apparently it has to do with the addition of a default write deadline in Conn.Close in Go 1.16.

[marevers]

I tested this again today with denisenkom/go-mssqldb v0.12.2 and it still comes up with the same issue. Other projects using the same driver report that it does fix the issue.

I ran with LOGLEVEL debug, but it does not seem to output any more information than I already had.

The exporter starts at 10:09:39. 2022-07-14T10:09:39+02:00 {"build_context":"(go=go1.17.8, user=, date=)","caller":"main.go:56","msg":"Starting sql_exporter","ts":"2022-07-14T08:09:39.471852111Z","version_info":"(version=, branch=, revision=)"}

It runs its first query at 10:09:40. 2022-07-14T10:09:40+02:00 {"caller":"job.go:204","job":"omniposmetrics-60m","level":"debug","msg":"Running Query","query":"mssql_omnipos_store_workstations","ts":"2022-07-14T08:09:40.270986729Z"}

Seemingly exactly two minutes later, at 10:11:40, the panic: Not implemented error occurs.

panic: Not implemented

goroutine 120 [running]:
github.com/denisenkom/go-mssqldb.passthroughConn.SetWriteDeadline(...)
    /src/vendor/github.com/denisenkom/go-mssqldb/net.go:167
crypto/tls.(*Conn).SetWriteDeadline(...)
    /usr/local/go/src/crypto/tls/conn.go:151
crypto/tls.(*Conn).closeNotify(0xc000183180)
    /usr/local/go/src/crypto/tls/conn.go:1361 +0xdb
crypto/tls.(*Conn).Close(0xc0007105b8)
    /usr/local/go/src/crypto/tls/conn.go:1331 +0x69
github.com/denisenkom/go-mssqldb.(*Conn).Close(0xc0007105d0)
    /src/vendor/github.com/denisenkom/go-mssqldb/mssql.go:361 +0x28
database/sql.(*driverConn).finalClose.func2()
    /usr/local/go/src/database/sql/sql.go:646 +0x3c
database/sql.withLock({0x131db48, 0xc0002aa3f0}, 0xc000710688)
    /usr/local/go/src/database/sql/sql.go:3396 +0x8c
database/sql.(*driverConn).finalClose(0xc0002aa3f0)
    /usr/local/go/src/database/sql/sql.go:644 +0x117
database/sql.(*driverConn).Close(0xc0002aa3f0)
    /usr/local/go/src/database/sql/sql.go:625 +0x149
database/sql.(*DB).connectionCleaner(0xc0005c29c0, 0x0)
    /usr/local/go/src/database/sql/sql.go:1085 +0x1f7
created by database/sql.(*DB).startCleanerLocked
    /usr/local/go/src/database/sql/sql.go:1055 +0x105

@dewey Is it possible that it disconnects from the database ungracefully after two minutes?

[dewey]

Unfortunately I don't have access to a MSSQL instance so I can't really investigate / fix that myself. If someone wants to give this a shot an open a MR we can get this merged.

[marevers]

@dewey I managed to fix the issue and opened a PR.