SQL Server连接问题案例解析（3）

  • Article

本文是SQL Server 连接问题案例解析系列的最后一个博文，在今天的案例中，除了分析Netmon日志，还会分享一些分析ODBC Trace的经验。

首先来介绍一下这个案例中客户遇到的问题：

客户在Linux服务器上使用UNIXODBC2.3.0将客户端连接到SQL Server数据库。当客户端连接运行在同一个实例中的非镜像数据库时，没有任何问题发生。但如果客户端连接镜像数据库，则会出现以下报错：

client=n/a (n/a) unixODBC-2.3.0 64-bit /ab/home/misc/64/unixODBC/lib/libodbc.so

ABINITIO(DB00001): Failed connecting to the database <ALGO_PROD>.

ABINITIO(DB00001):

ABINITIO(DB16000): ODBC Error

ABINITIO(DB16000): SQLCODE: 20020

ABINITIO(DB16000): SQLSTATE: 08S01

ABINITIO(DB16000): MESSAGE: [unixODBC][FreeTDS][SQL Server]Bad token from the server: Datastream processing out of sync

ABINITIO(DB16000): ODBC Error

ABINITIO(DB16000): SQLCODE: 0

ABINITIO(DB16000): SQLSTATE: 08001

ABINITIO(DB16000): MESSAGE: [unixODBC][FreeTDS][SQL Server]Unable to connect to data source

ABINITIO(DB00067): Current DB Environment:

ABINITIO(DB00067):

ABINITIO(*): Database Package Version 3-1-6-4-e11-1

其中值得注意的是应用程序运行在Linux上，客户端使用了ODBC。那么在Linux上有几种方法连接SQL Server呢？第一种是通过JDBC；OLEDB Client没有Linux版本，而ODBC是一个标准的接口，所以第三方的ODBC是可以连接SQL Server的，所以另外一种方法就是客户这种使用第三方ODBC进行连接。

接下来我们进行了几个基本的检查：

1. 检查连接字符串，确认其中服务器名正确，其值为principal server；

2. 如果客户端使用的是OLEDB或.net的provider，我们在连接字符串中可以指定failover partner，而在客户的连接字符串中，没有写failover partner，只写了principal server name；同时也确认，在连接时，数据库确实在principal server name中指定的服务器上运行。

以上两个检查可以排查掉一些基本的错误，如错误的连接镜像数据库。

3. 客户的连接超时设置为15秒，但错误信息会立即报出。这个现象是不是让大家想到了在案例2中介绍到的.Net Framework的bug造成的连接问题呢？难道ODBC也有这个bug吗？

    为了进一步验证，我们将连接超时的设置改为120秒，但是错误还是会马上报出。当超时时间被调长，重试时间也会相应的增长（计算公式：RetryTime = PreviousRetryTime + ( 0.08 *LoginTimeout) ），而此处错误仍然立即出现，说明这个问题和案例2中的问题是没有关系的。

为了进一步调查， 我们在问题发生时，在principal server 和mirror server上抓取了Netmon日志。不管客户端是什么，我们分析Netmon日志的方法是一样的，使用客户端的IP address对principal server上收集到的Netmon日志进行过滤后，得到如下：


 
可以看到：

  1. 首先，客户端主动连接SQL Server，发了一个sync包到SQL Server；SQL Server收到sync包之后ack了这个包，告诉客户端这个包被收到了；客户端收到了SQL回复的包后又发送了一个包给SQL Server，告诉SQL Server之前回复的包已被收到了。这三个包保证了双向连接的通顺，这也就是我们常说的三次握手。三次握手之后在TCP层面通过就建立起了连接。
  2. 顺序向下看，三次握手结束后，客户端发送了prelogin 包，并且SQL Server使用了TDS response 对这个包进行ack。客户端收到TDS Response之后，也再次ack了这个包。（TCP的一个重要特征就是所有发出的包，对方都会ack，对方发过来的包也是同理。）
  3. 接下来客户端向服务端发送了一个TDS Data，之后就开始进行NTLM authentication了。可以看到服务端对收到challenge进行了response并返回SPID70（frame276），并且客户端也对这个response进行了ack（frame 277）。

        看到这里为止我们会发现这时客户端已经连接上了SQL Server，但接下来发生的事情非常奇怪：

        客户端在ack response之后迅速发送了一个fin包（TCP:Flags=…A…F）结束了会话（frame278）。

客户测试了若干次，而在Netmon 日志中，后续若干次的行为也都是一样的，都是客户端在ack NTLM response后结束会话。但由此也可以见，造成这个问题的原因应该是客户端。

当查看客户的连接字符串时，我们发现连接字符串中有一个client trace的选项，打开这个选项后，连接时会在客户端生成了一个ODBC Trace。

查看客户端trace时，我们首先可以定位到错误信息是"Unable to connect to data source"，在这个错误信息报出前，有TDS_INT_CANCEL(2)返回，继续向上查看日志，可以看到Changed query state from IDLE to DEAD。而在DEAD前客户端的最后一个动作是获取了一个值为53的token，获取之后状态就变成了DEAD:

token.c:337:looking for login token, got e3(ENVCHANGE)

token.c:122:tds_process_default_tokens() marker is e3(ENVCHANGE)

token.c:337:looking for login token, got 53()

token.c:122:tds_process_default_tokens() marker is 53()

util.c:156:Changed query state from IDLE to DEAD

util.c:331:tdserror(0x5de19d0, 0x5df9530, 20020, 0)

odbc.c:2270:msgno 20020 20003

util.c:361:tdserror: client library returned TDS_INT_CANCEL(2)

util.c:384:tdserror: returning TDS_INT_CANCEL(2)

token.c:256:Unknown marker: 83(53)!!

login.c:466:login packet accepted

util.c:331:tdserror(0x5de19d0, 0x5df9530, 20002, 0)

odbc.c:2270:msgno 20002 20003

util.c:361:tdserror: client library returned TDS_INT_CANCEL(2)

util.c:384:tdserror: returning TDS_INT_CANCEL(2)

mem.c:615:tds_free_all_results()

error.c:412:odbc_errs_add: "Unable to connect to data source"

 

继续向上查看客户端 Trace，会看到以下信息：

net.c:555:Received header

0000 04 01 02 35 00 49 01 00- |...5.I..|

 

net.c:609:Received packet

0000 04 01 02 35 00 49 01 00-e3 35 00 01 13 41 00 6c |...5.I.. .5...A.l|

0010 00 67 00 6f 00 5f 00 43-00 6f 00 6c 00 6c 00 61 |.g.o._.C .o.l.l.a|

0020 00 74 00 65 00 72 00 61-00 6c 00 5f 00 52 00 65 |.t.e.r.a .l._.R.e|

0030 00 70 00 06 6d 00 61 00-73 00 74 00 65 00 72 00 |.p..m.a. s.t.e.r.|

…….

大家有没有觉得这部分输出有点眼熟呢？

既然客户端总是在收到服务端的NTLM response后结束会话，那我们不妨返回Netmon把这个response包展开来看一看：

此时大家会发现，之前觉得眼熟的信息原来是和Netmon中包的Hex Details信息非常相似。

比较客户端Trace和Netmon包中的信息，会发现其实客户端是在分段读取包中的Token，每读到一部分，在trace中就会有一段相应的输出。在读到这个出错的“53”之前，客户端已经成功的读到了多个token，以以下trace为例：

token.c:337:looking for login token, got e3(ENVCHANGE)

token.c:122:tds_process_default_tokens() marker is e3(ENVCHANGE)

token.c:337:looking for login token, got ab(INFO)

token.c:122:tds_process_default_tokens() marker is ab(INFO)

token.c:2588:tds_process_msg() reading message 5701 from server

token.c:2661:tds_process_msg() calling client msg handler

odbc.c:2270:msgno 5701 20003

token.c:2674:tds_process_msg() returning TDS_SUCCEED

token.c:337:looking for login token, got e3(ENVCHANGE)

token.c:122:tds_process_default_tokens() marker is e3(ENVCHANGE)

token.c:2419:tds_process_env_chg(): 5 bytes of collation data received

token.c:2420:tds->collation was

0000 00 00 00 00 00 - |.....|

 

iconv.c:988:setting server single-byte charset to "CP1252"

token.c:2430:tds->collation now

0000 09 04 d0 00 34 - |....4|

 

其实这一段对应的就是包中collation的token：

那么collation之后值为“53”的token到底是什么呢？展开查看它的详细信息，发现这是一个Real Time Log Shipping，Real Time Log Shipping就是指Mirror：

也就是说，当客户端读到Mirror的token时无法识别，因此客户端认为这是一个有问题的包，就把连接finish掉了。

与成功连接生成的trace进行比较（客户端可以成功连接未配置镜像的数据库），会发现在好的连接的trace中，没有读取“53”这部分内容，读取完collation之后就继续读取了包中后续的内容。

结论：当目标数据库使用了数据库镜像时，SQL Server会在响应的TDS 包中返回额外的信息，告诉客户端这是一个镜像数据库。但客户端无法识别这部分信息，认为这是一个错误的包，因而结束了连接。

原因：

在微软官方文档中有明确指出Microsoft ODBC Driver 11 for SQL Server on Linux不支持数据库镜像：

The programming features of the Microsoft ODBC Driver 11 for SQL Server on Linux are based on ODBC in SQL Server Native Client (SQL Server Native Client (ODBC)). SQL Server Native Client is based on ODBC in Windows Data Access Components (ODBC Programmer's Reference).

 Features That Are Not Available ：

The following features are not available in this release of the ODBC driver on Linux: https://technet.microsoft.com/en-us/library/hh568445(v=sql.110).aspx

  • bulk copy functions (bcp_batch, for example)
  • distributed transactions (SQL_ATTR_ENLIST_IN_DTC attribute is not supported)
  • database mirroring
  • FILESTREAM
  • profiling ODBC driver performance, discussed in SQLSetConnectAttr, the following performance-related connection attributes:
    • SQL_COPT_SS_PERF_DATA
    • SQL_COPT_SS_PERF_DATA_LOG
    • SQL_COPT_SS_PERF_DATA_LOG_NOW
    • SQL_COPT_SS_PERF_QUERY
    • SQL_COPT_SS_PERF_QUERY_INTERVAL
    • SQL_COPT_SS_PERF_QUERY_LOG

UNIXODBC 2.3.0也很可能不支持数据库镜像。在客户与第三方确认后，这一点得到了证实。这个问题的根本原因就是UNIXODBC2.3.0不支持SQL Server数据库镜像。

解决方案：

通过使用JDBC driver在Linux服务器上连接使用了镜像的SQL Server数据库。关于Microsoft JDBC driver对与数据库镜像的支持信息，可以参考以下官方文档：

Database mirroring is primarily a software solution for increasing database availability and data redundancy. The Microsoft SQL Server JDBC Driver provides implicit support for database mirroring, so that the developer does not need to write any code or take any other action when it has been configured for the database.

Using Database Mirroring (JDBC)https://technet.microsoft.com/en-us/library/aa342332(v=sql.105).aspx

这就是今天的分享，之后我们将会发布关于SQL Server性能案例解析的系列，请持续关注本博客的更新。