go-mssqldb: Azure SQL. long query - driver: bad connection

got a headache with a strange behavior when working with SQL Azure.

this code causes “driver: bad connection” error when executing second select

var dbConnString = "server=ttt.database.windows.net;port=1433;user id=user;password=pass;database=db;log=63"

func connect() (*sql.DB, error) {
    db, err := sql.Open("mssql", dbConnString)
    if err != nil {
        return nil, err
    }
    err = db.Ping()
    if err != nil {
        return nil, err
    }
    return db, nil
}

func main() {
    // open db in this function
    db, err := connect()
    if err != nil {
        return
    }
    defer db.Close() // close db in this function

    fmt.Println("SEL 1")
    _, err = db.Exec("SELECT 1")
    if err != nil {
                fmt.Println("Sel error: " + err.Error())
        return
    }

    fmt.Println("SEL bad")

    _, err = db.Exec(`SELECT 2 -- long query FFD8FFE000104A46494600010100000100010000FFDB0043000302020302020303030304030304050805050404050A070706080C0A0C0C0B0A0B0B0D0E12100D0E110E0B0B1016101113141515150C0F171816141812141514FFDB00430103040405040509050509140D0B0D141414141414141414141414141414141414141414141414141414141414141414141414141414140419D47E2AFC78F89DA0F80FC2BAA412EB9ACCCD1406EA28228A3554692491D8A70A91A3B9C02C4290AACC403D67C50D4E0F0D780C78ABC07F1BEDBC656F16BF36853E99A86896DA56A2EAB10923BE82DBCD99DED1C6E5F3241132B6D5299276C1FB05F8A74CF82BFB6C781EFF00C7773FF08A5AE99797D61A83EAB1B43F629DED2E2DC24C08CC5895D558BE027258A8048F45FD0419D47E2AFC78F89DA0F80FC2BAA412EB9ACCCD1406EA28228A3554692491D8A70A91A3B9C02C4290AACC403D67C50D4E0F0D780C78ABC07F1BEDBC656F16BF36853E99A86896DA56A2EAB10923BE82DBCD99DED1C6E5F3241132B6D5299276C1FB05F8A74CF82BFB6C781EFF00C7773FF08A5AE99797D61A83EAB1B43F629DED2E2DC24C08CC5895D558BE027258A8048F45FDAE0F8907ECE7A38F8EF83FB409F18DF7F677DBB67F687FC23BB5FCCDDE4FCBF66FB7F9DE479BC6CDFF0067FDD66803E60FF85E9E38FF00A0E7FE4A41FF00C45765F06F52F8ADF1F3E27683E03F0C6AB04DAEEB3334507DAA2B78A28D551A49247629C2A468EE700B10B85566201E03C3FF0013758F0CF85AFF0040B4B3F0F4D617BE679B2EA1E1BD3AF2ED77A046F2     
    141414141414141414FFC00011080438078003012200021101031101FFC4001F0000010501010101010100000000000000000102030405060708090A0BFFC400B5100002010303020403050504040000017D01020300041105122131410613516107227114328191A1082342B1C11552D1F02433627282090A161718191A25262728292A3435363738393A434445464748494A530F8907ECE7A38F8EF83FB409F18DF7F677DBB67F687FC23BB5FCCDDE4FCBF66FB7F9DE479BC6CDFF0067FDD66803E60FF85E9E38FF00A0E7FE4A41FF00C45765F06F52F8ADF1F3E27683E03F0C6AB04DAEEB3334507DAA2B78A28D551A49247629C2A468EE700B10B85566201E03C3FF0013758F0CF85AFF0040B4B3F0F4D617BE679B2EA1E1BD3AF2ED77A046F2
        `)
    if err != nil {
        fmt.Println("error: " + err.Error())
    }
}

log:

2016/08/31 16:46:36 (1 row(s) affected) 2016/08/31 16:46:36 (1 row(s) affected) 2016/08/31 16:46:36 SELECT 1 2016/08/31 16:46:36 (1 row(s) affected) 2016/08/31 16:46:36 SELECT 2 – long query FFD8FFE000104A46494600010100000100010000FFDB004300030202030202030303030403030 … cut … … cut … … cut … … cut … 78A28D551A49247629C2A468EE700B10B85566201E03C3FF0013758F0CF85AFF0040B4B3F0F4D617BE679B2EA1E1BD3AF2ED77A046F2

2016/08/31 16:46:36 got error: read tcp 172.17.0.35:49981->191.235.193.75:1433: wsarecv: An existing connection was forcibly closed by the remote host. 2016/08/31 16:46:36 (1 row(s) affected) 2016/08/31 16:46:36 (1 row(s) affected) 2016/08/31 16:46:36 SELECT 2 – long query FFD8FFE000104A46494600010100000100010000FFDB004300030202030202030303030403030 4050805050404050A070706080C0A0C0C0B0A0B0B0D0E12100D0E110E0B0B1016101113141515150C0F171816141812141514FFDB004301030404050 … cut … … cut … … cut … … cut … 78A28D551A49247629C2A468EE700B10B85566201E03C3FF0013758F0CF85AFF0040B4B3F0F4D617BE679B2EA1E1BD3AF2ED77A046F2

2016/08/31 16:46:36 got error: read tcp 172.17.0.35:49982->191.235.193.75:1433: wsarecv: An existing connection was forcibly closed by the remote host. 2016/08/31 16:46:37 (1 row(s) affected) 2016/08/31 16:46:37 (1 row(s) affected) 2016/08/31 16:46:37 SELECT 2 – long query FFD8FFE000104A46494600010100000100010000FFDB004300030202030202030303030403030 4050805050404050A070706080C0A0C0C0B0A0B0B0D0E12100D0E110E0B0B1016101113141515150C0F171816141812141514FFDB004301030404050 … cut … … cut … … cut … … cut … 78A28D551A49247629C2A468EE700B10B85566201E03C3FF0013758F0CF85AFF0040B4B3F0F4D617BE679B2EA1E1BD3AF2ED77A046F2

2016/08/31 16:46:37 got error: read tcp 172.17.0.35:49983->191.235.193.75:1433: wsarecv: An existing connection was forcibly closed by the remote host.

error: driver: bad connection

so as we see there is 3 attempt to execute long query (why???) and we have “wsarecv error by unknown reason” for each of them

tried to connect and run with SQL2005 - no problems at all. wireshark doesn’t hep because connection with sql azure is encrypted

got problem only with long queries (I’m inserting images into database like 0x123456…), all the rest of db routine working well

About this issue

  • Original URL
  • State: closed
  • Created 8 years ago
  • Reactions: 1
  • Comments: 43 (3 by maintainers)

Commits related to this issue

Most upvoted comments

this continues to be a problem for me… but I keep working around the issue by refactoring my SQL but it’s getting harder with each failure.

I was finally able to use Microsoft Message Analyzer on it. Notes for future self:

  • Run on port 1433
  • Force client to use fixed certs (no forward security suites)
  • Create self signed cert and add to MMA and SQL Server

According to MMA, it isn’t seeing a EOM message type at the end of the SQL Batch packet. Sometimes this isn’t a problem, but maybe sometimes it is? Unsure. I’m also seeing odd NULL bytes inserted into the SQL Batch data. I’m unsure if that is a problem with MMA or if there really is an issue with the driver writing NULL values.

I don’t think I’ve seen any issue when SQL can fit in a single TDS packet.

No. I’m currently working on some database/sql issues for go1.9 that need to get done before the first cut. I’ll see if I can work on it tomorrow morning.

Hello! Do you have an ETA on this issue?

And another note:

select protocol_type, MASTER.dbo.fn_varbintohexstr(CONVERT(varBINARY(4), protocol_version)) protocol_version from sys.dm_exec_connections

produced these results. I would have expected one row or one row per supported TDS version

protocol_type	protocol_version
TSQL	0x74000004
TSQL	0x74000004
TSQL	0x74000004
TSQL	0x74000004
TSQL	0x74000004
TSQL	0x00000000
TSQL	0x74000004
TSQL	0x74000004
TSQL	0x74000004
TSQL	0x00000000
TSQL	0x74000004
TSQL	0x74000004
TSQL	0x74000004
TSQL	0x00000000
TSQL	0x00000000
TSQL	0x74000004
TSQL	0x00000000
TSQL	0x00000000
TSQL	0x74000004
TSQL	0x74000004
TSQL	0x74000004
TSQL	0x74000004
TSQL	0x74000004
TSQL	0x00000000
TSQL	0x00000000
TSQL	0x74000004
TSQL	0x74000004
TSQL	0x74000004
TSQL	0x74000004
TSQL	0x74000004
TSQL	0x74000004

Here is some interesting information… There is clearly a problem with the server in that it must be performing some sort of sanity check on the SQL and if it looks suspicious that is resets the connection. I suppose this must be some sort of DOS or PEN protection. For example I had a small SQL that looks like: select getdate()*/}} d and it resulted in a connection reset.