golang sql driver: bad connection

[Raj]

Hi,

My program which has 10 user gourotines to read tables from a database and generates some stats. I am using github.com/alexbrainman/odbc to connect SQL Server 2012.

I am getting driver: bad connection frequently, but not always. Can somebody help me in debugging this?


Sart of the stack trace....

panic: driver: bad connection

goroutine 18 [running]:
panic(0x4fa740, 0xc04200c2b0)
    C:/Go/src/runtime/panic.go:500 +0x1af fp=0xc0421d70f0 sp=0xc0421d7060
main.process(0xc0420e4000, 0xc042165070)
    C:/Users/tgmsaven1/go/src/github.com/TGMNY/compstats/compstats.go:498 +0x274a fp=0xc0421d7f80 sp=0xc0421d70f0
runtime.goexit()
    C:/Go/src/runtime/asm_amd64.s:2086 +0x1 fp=0xc0421d7f88 sp=0xc0421d7f80
created by main.main
    C:/Users/tgmsaven1/go/src/github.com/TGMNY/compstats/compstats.go:268 +0xfc4

goroutine 1 [semacquire, 8 minutes]:
runtime.gopark(0x534e98, 0x5b4140, 0x51b357, 0xa, 0x19, 0x4)
    C:/Go/src/runtime/proc.go:259 +0x14f fp=0xc0424dd680 sp=0xc0424dd650
runtime.goparkunlock(0x5b4140, 0x51b357, 0xa, 0xc042072219, 0x4)
    C:/Go/src/runtime/proc.go:265 +0x65 fp=0xc0424dd6c0 sp=0xc0424dd680
runtime.semacquire(0xc04216507c, 0x1)
    C:/Go/src/runtime/sema.go:111 +0x222 fp=0xc0424dd728 sp=0xc0424dd6c0
sync.runtime_Semacquire(0xc04216507c)
    C:/Go/src/runtime/sema.go:47 +0x37 fp=0xc0424dd748 sp=0xc0424dd728
sync.(*WaitGroup).Wait(0xc042165070)
    C:/Go/src/sync/waitgroup.go:131 +0x9e fp=0xc0424dd798 sp=0xc0424dd748
main.main()
    C:/Users/tgmsaven1/go/src/github.com/TGMNY/compstats/compstats.go:310 +0x16c4 fp=0xc0424ddf48 sp=0xc0424dd798
runtime.main()
    C:/Go/src/runtime/proc.go:183 +0x1f0 fp=0xc0424ddfa0 sp=0xc0424ddf48
runtime.goexit()
    C:/Go/src/runtime/asm_amd64.s:2086 +0x1 fp=0xc0424ddfa8 sp=0xc0424ddfa0

goroutine 2 [force gc (idle), 8 minutes]:
runtime.gopark(0x534e98, 0x5ac210, 0x51c25d, 0xf, 0x534d14, 0x1)
    C:/Go/src/runtime/proc.go:259 +0x14f fp=0xc04205ff28 sp=0xc04205fef8
runtime.goparkunlock(0x5ac210, 0x51c25d, 0xf, 0xc042058014, 0x1)
    C:/Go/src/runtime/proc.go:265 +0x65 fp=0xc04205ff68 sp=0xc04205ff28
runtime.forcegchelper()
    C:/Go/src/runtime/proc.go:224 +0xb6 fp=0xc04205ffa0 sp=0xc04205ff68
runtime.goexit()
    C:/Go/src/runtime/asm_amd64.s:2086 +0x1 fp=0xc04205ffa8 sp=0xc04205ffa0
created by runtime.init.4
    C:/Go/src/runtime/proc.go:213 +0x3c

goroutine 3 [GC sweep wait]:
runtime.gopark(0x534e98, 0x5ac3e0, 0x51bb3d, 0xd, 0x462c14, 0x1)
    C:/Go/src/runtime/proc.go:259 +0x14f fp=0xc042061f18 sp=0xc042061ee8
runtime.goparkunlock(0x5ac3e0, 0x51bb3d, 0xd, 0x14, 0x1)
    C:/Go/src/runtime/proc.go:265 +0x65 fp=0xc042061f58 sp=0xc042061f18
runtime.bgsweep(0xc0420040e0)
    C:/Go/src/runtime/mgcsweep.go:79 +0x13c fp=0xc042061f98 sp=0xc042061f58
runtime.goexit()
    C:/Go/src/runtime/asm_amd64.s:2086 +0x1 fp=0xc042061fa0 sp=0xc042061f98
created by runtime.gcenable
    C:/Go/src/runtime/mgc.go:195 +0x68

goroutine 4 [finalizer wait, 8 minutes]:
runtime.gopark(0x534e98, 0x5c6870, 0x51bf5c, 0xe, 0x14, 0x1)
    C:/Go/src/runtime/proc.go:259 +0x14f fp=0xc04205bee8 sp=0xc04205beb8
runtime.goparkunlock(0x5c6870, 0x51bf5c, 0xe, 0x14, 0x1)
    C:/Go/src/runtime/proc.go:265 +0x65 fp=0xc04205bf28 sp=0xc04205bee8
runtime.runfinq()
    C:/Go/src/runtime/mfinal.go:158 +0xc1 fp=0xc04205bfa0 sp=0xc04205bf28
runtime.goexit()
    C:/Go/src/runtime/asm_amd64.s:2086 +0x1 fp=0xc04205bfa8 sp=0xc04205bfa0
created by runtime.createfing
    C:/Go/src/runtime/mfinal.go:139 +0x7a

goroutine 5 [chan receive, 8 minutes]:
runtime.gopark(0x534e98, 0xc042072298, 0x51b961, 0xc, 0x17, 0x3)
    C:/Go/src/runtime/proc.go:259 +0x14f fp=0xc04205de60 sp=0xc04205de30
runtime.goparkunlock(0xc042072298, 0x51b961, 0xc, 0x17, 0x3)
    C:/Go/src/runtime/proc.go:265 +0x65 fp=0xc04205dea0 sp=0xc04205de60
runtime.chanrecv(0x4f1220, 0xc042072240, 0xc04205df80, 0x1, 0x0)
    C:/Go/src/runtime/chan.go:496 +0x2ed fp=0xc04205df28 sp=0xc04205dea0
runtime.chanrecv2(0x4f1220, 0xc042072240, 0xc04205df80, 0x0)
    C:/Go/src/runtime/chan.go:383 +0x35 fp=0xc04205df60 sp=0xc04205df28
database/sql.(*DB).connectionOpener(0xc0420e4000)
    C:/Go/src/database/sql/sql.go:727 +0x51 fp=0xc04205df98 sp=0xc04205df60
runtime.goexit()
    C:/Go/src/runtime/asm_amd64.s:2086 +0x1 fp=0xc04205dfa0 sp=0xc04205df98
created by database/sql.Open
    C:/Go/src/database/sql/sql.go:493 +0x1ec

[Raj]

By the way I am using go1.7 beta2. Same error was appearing with go1.6 also.

What does those 8 minutes mean in stack trace?

[Ian Lance Taylor]

On Fri, Jul 8, 2016 at 7:50 AM, Raj <rajenderre...@gmail.com> wrote:
> By the way I am using go1.7 beta2. Same error was appearing with go1.6 also.
>
> What does those 8 minutes mean in stack trace?

Those annotations mean that those goroutines have been sitting around
waiting for something to happen for 8 minutes.

The stack trace is pointing you at line 498 of compstats.go. That
line is apparently panicing for some reason. I would start there.

Ian

> --
> You received this message because you are subscribed to the Google Groups
> "golang-nuts" group.
> To unsubscribe from this group and stop receiving emails from it, send an
> email to golang-nuts...@googlegroups.com.
> For more options, visit https://groups.google.com/d/optout.

[Raj]

Hi Ian,

Initially the program giving err driver: bad connection for rows.Err(). So I added panic with that error to get the stack trace.

for rows.Next() {
          //stats calculation
}
if err := rows.Err(); err != nil {
panic(err)   // this is line 498
}
rows.Close()

How can find out the reason for that error? Do I need to search in the library github.com/alexbrainman/odbc code?

[Konstantin Khomoutov]

On Fri, 8 Jul 2016 08:15:27 -0700 (PDT)
Raj <rajenderre...@gmail.com> wrote:

> Initially the program giving err driver: bad connection for rows.Err
> (). So I added panic with that error to get the stack trace.

That's very unfortunate as it works right against the debugging by
leading whoever reads your problem statement down the wrong road.

Please don't do that next time: state what's your original problem,
not what you think of it.

> for rows.Next() {
> //stats calculation
> }
> if err := rows.Err(); err != nil {

> panic(err) *// this is line 498*

> }
> rows.Close()
>
> How can find out the reason for that error? Do I need to search in
> the library github.com/alexbrainman/odbc

[...]

Well, instead of asking this question you could just `git grep` the
local clone (what `go get` did for you) of that repository:

odbc% git grep 'bad connection'
mssql_test.go: // driver.ErrBadConn ...

So this gives you a hint on that the error message you're seeing is
just what database/sql/driver.ErrBadConn's Error() message produces.

Let's verify this:

odbc% go doc database/sql/driver.ErrBadConn
var ErrBadConn = errors.New("driver: bad connection")
ErrBadConn should be returned by a driver to signal to the sql
package that a driver.Conn is in a bad state (such as the server
having earlier closed the connection) and the sql package should retry
on a new connection.

To prevent duplicate operations, ErrBadConn should NOT be returned
if there's a possibility that the database server might have performed
the operation. Even if the server sends back an error, you shouldn't
return ErrBadConn.

So yes, this is a legitimate error which should be returned by a
particular driver implementation (github.com/alexbrainman/odbc in your
case) to the database/sql code when the driver thinks something gone
awry with a particular DB connection it manages.

So off you go -- git-gerpping for ErrBadConn this time:

odbc% git grep -F ErrBadConn
conn.go: if err == driver.ErrBadConn {
error.go: return driver.ErrBadConn
mssql_test.go: // driver.ErrBadConn ...
mssql_test.go: if should, is := river.ErrBadConn ...
stmt.go: return nil, driver.ErrBadConn
tx.go: return nil, driver.ErrBadConn

So you go and explore this code to see which cases return ErrBadConn,
and find in error.go/NewError():

if r.State == "08S01" {
return driver.ErrBadConn
}

So you google for ODBC+state+"08S01" [1] and discover that ODBC uses
this connection state to mean "general network failure" or
"communication link failure".
Not terribly interesting but at least two points could be made out:
* The github.com/alexbrainman/odbc is likely not the cause of the
problem.
* You have to dig deeper.

The first round of digging deeper is reading through links found by
Google. Another stab could be studying what [2] offers.

One more possible hint: while I think your connectivity is in fact OK --
otherwise _all_ requests would fail -- I would verify that you're not
hitting some sort of software limit of your server platform. This could
be either an SQL Server limit -- if it's some sort of castrated
"edition", or this could be your OS limit -- say, a non-server Windows
platform has tight limits on the number of concurrent TCP connections
it's able to serve. If these possible causes are ruled out, the next
step I would do is disabling SSL for your connections to your MSSQL
instance and dumping the traffic using Microsoft Network Monitor (which
has excellent dissectors for the MS-TDS protocol) and studying it for
possible hints.

1. https://www.google.com/search?q=ODBC+STATE+"08S01"
2. https://www.microsoft.com/en-us/search/result.aspx?q=ODBC+STATE+08S01

[Raj]

On Friday, July 8, 2016 at 11:16:50 PM UTC+5:30, Konstantin Khomoutov wrote:

On Fri, 8 Jul 2016 08:15:27 -0700 (PDT)
Raj <rajenderre...@gmail.com> wrote:

> Initially the program giving err driver: bad connection for rows.Err
> (). So I added panic with that error to get the stack trace.

That's very unfortunate as it works right against the debugging by
leading whoever reads your problem statement down the wrong road.

Please don't do that next time: state what's your original problem,
not what you think of it.

 

OK. I was trying get the stack trace of the error path and completely messed up.

> for rows.Next() {
>           //stats calculation
> }
> if err := rows.Err(); err != nil {
> panic(err)   *// this is line 498*
> }
> rows.Close()
>
> How can find out the reason for that error? Do I need to search in
> the library github.com/alexbrainman/odbc
[...]

Well, instead of asking this question you could just `git grep` the
local clone (what `go get` did for you) of that repository:
 

Thank you very much for your help.
Yes, I did dig through the library after posting and ended up having same findings.
It would have helped if there was away to get stack trace of the error.

 

[Konstantin Khomoutov]

On Fri, 8 Jul 2016 11:34:53 -0700 (PDT)

That's possible by using runtime/debug.PrintStack() at the point where
you've got your error. But actually temporarily panic()ing is just
okay for such one-off debugguing.

On the other hand, where you think you'd need a stack trace, you might
just reconsider your approach to handling errors. Often when a
developer thinks they need a stack trace they instead just need _more
context_ of an error. The PathError type of the "os" standard package
is a good example of providing minimal context for an error related to
operating on filesystem objects. If you need systematic error handling
which would preserve some context where it would be worth it, you could
use something like [1].

1. http://dave.cheney.net/2016/04/27/dont-just-check-errors-handle-them-gracefully