go-mssqldb does not respect context.Context

[skaji]

Describe the bug

For example, I expected that the following code timeouts with 100msec:

db, _ := sql.Open("mssql", "sqlserver://example.com:9999")
ctx, _ := context.WithTimeout(context.Background(), 100*time.Millisecond)
db.PingContext(ctx)

But it turns out that it timeouts not with 100msec, but with 15sec.

To Reproduce

package main

import (
	"context"
	"database/sql"
	"log"
	"os"
	"time"

	_ "github.com/denisenkom/go-mssqldb"
)

func main() {
	log.SetFlags(log.Lmicroseconds)

	connString := "sqlserver://example.com:9999"
	if len(os.Args) > 1 {
		connString = os.Args[1]
	}
	db, err := sql.Open("mssql", connString)
	if err != nil {
		log.Fatal(err)
	}
	defer db.Close()

	ping := func() {
		ctx, cancel := context.WithTimeout(context.Background(), 100*time.Millisecond)
		defer cancel()
		log.Println("start ping")
		err = db.PingContext(ctx)
		log.Println("finish ping with error", err)
	}

	ticker := time.NewTicker(time.Second)
	defer ticker.Stop()
	for range ticker.C {
		ping()
	}
}

case1

You will see connect error:

> ./main 'sqlserver://example.com:9999'
06:54:54.842494 start ping
06:55:09.843382 finish ping with error Unable to open tcp connection with host 'example.com:9999': dial tcp 93.184.216.34:9999: i/o timeout

case2

Assume sql server is running at 10.20.194.53:11433. Then

# terminal1
> ./main 'sqlserver://10.20.194.53:11433'
07:14:20.777979 start ping
07:14:20.796036 finish ping with error <nil>
07:14:21.777938 start ping
07:14:21.780660 finish ping with error <nil>
07:14:22.777946 start ping
...

On other terminal, execute iptables to drop packets to 10.20.194.53:11433:

# terminal2
> iptables -A OUTPUT -d 10.20.194.53 -m tcp -p tcp --dport 11433 -j DROP

Then you see the following read error in terminal1:

# terminal1
07:14:28.777926 start ping
07:15:07.807776 finish ping with error read tcp 10.20.145.18:52690->10.20.194.53:11433: read: connection reset by peer

Expected behavior

Timeout with 100msec

Further technical details

SQL Server version: Any
Operating system: Any

Additional context

I know that 15sec is the dial timeout that is optionally specified via the connect URL.

My point is that go-mssqldb should respect context.Context per method, such as PingContext, QueryContext, ExecContext etc.

[skaji]

I think we can refer to the core net/http library for how to implement timeouts and canceling.

[chris-rossi]

I've reproduced the issue and I will investigate further.

[excavador]

We have ureliable network between AWS eu-west-1 (Ireland) and London data-center.
The connection is closed, often without any additional packets.

As result I see lond-running dead connections without which does not respect connect_timeout option (1) and context (2).

I have configured context.Timeout to 10 minutes and connection timeout to 20 minutes.
Right now I can see 30-minutes long attempt to connect (in one connection) and about 40 minutes long attempt to execute query (second connection)

It happens after long (about 1 hour) inactivity.

Seems like, keepalive does not work as well

Fortunately, out daemons export pprof and I can dump stack-traces for that.

1 @ 0x431290 0x405b58 0x405b2e 0x40585b 0x9c0a24 0x9c15eb 0x9c1664 0x9c61de 0x8fdf91 0x8fdf91 0x87789e 0x886feb 0x88624d 0x87f439 0x8801c4 0x9ecbd8 0x9efba9 0xb82809 0xa2b98a 0xa303f5 0xb764c9 0xae678b 0x45ec51
#	0x9c0a23	github.com/denisenkom/go-mssqldb.(*Conn).simpleProcessResp+0xe3							external/com_github_denisenkom_go_mssqldb/mssql.go:207
#	0x9c15ea	github.com/denisenkom/go-mssqldb.(*Conn).processBeginResponse+0x8a						external/com_github_denisenkom_go_mssqldb/mssql.go:312
#	0x9c1663	github.com/denisenkom/go-mssqldb.(*Conn).begin+0x103								external/com_github_denisenkom_go_mssqldb/mssql.go:286
#	0x9c61dd	github.com/denisenkom/go-mssqldb.(*Conn).BeginTx+0x7d								external/com_github_denisenkom_go_mssqldb/mssql.go:926

2 @ 0x431290 0x42c02a 0x42b5f5 0x4dd365 0x4de2df 0x4de2c1 0x5a86ff 0x5bbd28 0x9c822c 0x49bee7 0x4c8d99 0x4c8da4 0x9b292a 0x9d4981 0x9d4966 0x45ec51
#	0x42b5f4	internal/poll.runtime_pollWait+0x54					GOROOT/src/runtime/netpoll.go:184
#	0x4dd364	internal/poll.(*pollDesc).wait+0x44					GOROOT/src/internal/poll/fd_poll_runtime.go:87
#	0x4de2de	internal/poll.(*pollDesc).waitRead+0x1ce				GOROOT/src/internal/poll/fd_poll_runtime.go:92
#	0x4de2c0	internal/poll.(*FD).Read+0x1b0						GOROOT/src/internal/poll/fd_unix.go:169
#	0x5a86fe	net.(*netFD).Read+0x4e							GOROOT/src/net/fd_unix.go:202
#	0x5bbd27	net.(*conn).Read+0x67							GOROOT/src/net/net.go:184
#	0x9c822b	github.com/denisenkom/go-mssqldb.(*timeoutConn).Read+0x5b		external/com_github_denisenkom_go_mssqldb/net.go:28
#	0x49bee6	io.ReadAtLeast+0x86							GOROOT/src/io/io.go:310
#	0x4c8d98	io.ReadFull+0x2d8							GOROOT/src/io/io.go:329
#	0x4c8da3	encoding/binary.Read+0x2e3						GOROOT/src/encoding/binary/binary.go:239
#	0x9b2929	github.com/denisenkom/go-mssqldb.(*tdsBuffer).readNextPacket+0xa9	external/com_github_denisenkom_go_mssqldb/buf.go:142
#	0x9d4980	github.com/denisenkom/go-mssqldb.(*tdsBuffer).BeginRead+0xa0		external/com_github_denisenkom_go_mssqldb/buf.go:164
#	0x9d4965	github.com/denisenkom/go-mssqldb.processSingleResponse+0x85		external/com_github_denisenkom_go_mssqldb/token.go:569

1 @ 0x431290 0x405b58 0x405b2e 0x40585b 0x9c3dee 0x9c3c72 0x9c66ee 0x90310b 0x90310b 0x8777b0 0x8837f3 0x87e790 0x881c96 0xb71d11 0xb7ec30 0xb7e7b2 0xb821ff 0x9ecca6 0x9efba9 0xb82809 0xa2b98a 0xa303f5 0xb764c9 0xae678b 0x45ec51
#	0x9c3ded	github.com/denisenkom/go-mssqldb.(*Stmt).processQueryResponse+0xfd							external/com_github_denisenkom_go_mssqldb/mssql.go:603
#	0x9c3c71	github.com/denisenkom/go-mssqldb.(*Stmt).queryContext+0xd1								external/com_github_denisenkom_go_mssqldb/mssql.go:591
#	0x9c66ed	github.com/denisenkom/go-mssqldb.(*Stmt).QueryContext+0x15d								external/com_github_denisenkom_go_mssqldb/mssql.go:948
#	0x8777af	database/sql.ctxDriverStmtQuery+0x20f											GOROOT/src/database/sql/ctxutil.go:82
#	0x8837f2	database/sql.rowsiFromStatement+0x182											GOROOT/src/database/sql/sql.go:2604
#	0x87e78f	database/sql.(*DB).queryDC+0x22f											GOROOT/src/database/sql/sql.go:1622
#	0x881c95	database/sql.(*Tx).QueryContext+0x115											GOROOT/src/database/sql/sql.go:2291