前言

这是一个真实的案例。发生在ASE SP1603 PL12及以后的版本。而所有的老版本1603 PL11以及以前的版本都不受影响，都能正常连接。

首先介绍一下DB Tunnel，它基本上只用于Cloud环境下对Sybase ASE(以下简称ASE)的连接。主要是因为所有连接都是在于SSL的，而且网络是隔离的。不能直接访问主机。所以，SAP提供了NEO SDK的一套纯Java工具，建立起一个SSL通道，充当DB的SSL proxy的功能。

分析

这个现象确实比较诡异，上边说的无法连接，也不完全准确。从测试人员的测试来看，它是在多次尝试的连接测试中，偶尔有那么一次两次连接可以生效。更准确的描述是：JDBC client connection to ASE DB 1603PL12 or later via NEO SDK tunnel often fails

使用我前边开发的Java命令行工具(ase.isql-1.0.2-16.0.03.12.30318-spring-boot.jar)，可以非常简单的模拟出来。在建立db tunnel以后，

neo.bat open-db-tunnel -h <cloudhost> -a <account> -u <user> -i <dbinstance>

连接测试连接的测试脚本bug12.bat，内容如下：

:ASE1603PL12
echo "sleep 2 seconds"
PING -n 2 127.0.0.1>nul

echo SELECT @@version | java  -jar .\target\ase.isql-1.0.2-16.0.03.12.30318-spring-boot.jar -S "jdbc:sybase:Tds:localhost:30015/{DBNAME}?ENABLE_SSL=true&SSL_TRUST_ALL_CERTS=true" -U USER -P password

for /l %%a in (0,0,1) do call :ASE1603PL12 %%a

从中间JDBC的相关log，能得到大量的：

2023-02-10 17:15:22 Connection time : 3633 Error: JZ00M: Login timed out. Check that your database server is running on the host and port number you specified. Also, check the database server for other conditions (such as a full tempdb) that might be causing it to hang.

2023-02-10 17:15:26 Connection time : 3031 Error: JZ00M: Login timed out. Check that your database server is running on the host and port number you specified. Also, check the database server for other conditions (such as a full tempdb) that might be causing it to hang.

2023-02-10 17:15:30 Connection time : 3032 Error: JZ00M: Login timed out. Check that your database server is running on the host and port number you specified. Also, check the database server for other conditions (such as a full tempdb) that might be causing it to hang.

2023-02-10 17:15:34 Connection time : 3030 Error: JZ00M: Login timed out. Check that your database server is running on the host and port number you specified. Also, check the database server for other conditions (such as a full tempdb) that might be causing it to hang.

下边只列出了一部分版本之间的测试结果：

而SDK Tunnel的log在连接失败(HANG)的时候，最后会报下边的错：

2022-10-17 16:08:30,381 ERROR [forwardingproxy-5-3] com.sap.core.connectivity.tunnel.core.handlers.AbstractErrorHandler: Input/output exception in forwarding-proxy; Closing channel: [id: 0xc4abfcd8, L:/10.180.0.88:30015 - R:/10.47.147.239:63378]
java.io.IOException: An existing connection was forcibly closed by the remote host
  at sun.nio.ch.SocketDispatcher.read0(Native Method) ~[?:1.8.0_341]
  at sun.nio.ch.SocketDispatcher.read(Unknown Source) ~[?:1.8.0_341]
  at sun.nio.ch.IOUtil.readIntoNativeBuffer(Unknown Source) ~[?:1.8.0_341]
  at sun.nio.ch.IOUtil.read(Unknown Source) ~[?:1.8.0_341]
  at sun.nio.ch.SocketChannelImpl.read(Unknown Source) ~[?:1.8.0_341]
  at io.netty.buffer.PooledByteBuf.setBytes(PooledByteBuf.java:253) ~[netty-all-4.1.68.Final.jar:4.1.68.Final]
  at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1132) ~[netty-all-4.1.68.Final.jar:4.1.68.Final]
  at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:350) ~[netty-all-4.1.68.Final.jar:4.1.68.Final]
  at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:151) [netty-all-4.1.68.Final.jar:4.1.68.Final]
  at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:719) [netty-all-4.1.68.Final.jar:4.1.68.Final]
  at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:655) [netty-all-4.1.68.Final.jar:4.1.68.Final]
  at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:581) [netty-all-4.1.68.Final.jar:4.1.68.Final]
  at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493) [netty-all-4.1.68.Final.jar:4.1.68.Final]
  at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986) [netty-all-4.1.68.Final.jar:4.1.68.Final]
  at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [netty-all-4.1.68.Final.jar:4.1.68.Final]
  at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [netty-all-4.1.68.Final.jar:4.1.68.Final]
  at java.lang.Thread.run(Unknown Source) [?:1.8.0_341]
2022-10-17 16:10:17,511 WARN  [forwardingproxy-5-4] com.sap.core.persistence.commands.tunnel.connection.DbTunnelManager$2: Tunnel reported an internal error, state of tunnel not clear
2022-10-17 16:10:17,526 WARN  [forwardingproxy-5-4] com.sap.core.persistence.commands.tunnel.connection.DbTunnelManager$2: Received unexpected error code 300 (connection closed by backend) from tunnel

经常相当长一段时间的比对分析，发现db-tunnel的行为基本一直没有发生什么变化。 一直是将packet尽量拆分成512。通过分析JDBC的TDS包，发现：一个541字节的packet会拆成两段：(512 + 29)

    0x0160:  0b45 c3d3 ab67 1481 2349 3919 0574 6046  .E...g..#I9..t`F
    0x0170:  eb5b d35e 6dd1 43cd 792f 2ec7 245c be87  .[.^m.C.y/..$\..
    0x0180:  2b2c 71c3 98f8 4cb7 f309 707f e387 f4db  +,q...L...p.....
    0x0190:  9728 a9a6 2364 0f40 974d 6d37 2419 9554  .(..#d.@.Mm7$..T
    0x01a0:  428d 8f05 8b6b 16ca b977 1616 25f4 bc44  B....k...w..%..D
    0x01b0:  27b5 e303 e7ec 705e e0c9 04cf 9a24 367a  '.....p^.....$6z
    0x01c0:  98b5 29bb 2d64 7eb5 2e35 3fde d049 d93e  ..).-d~..5?..I.>
    0x01d0:  7c97 e4f9 ad44 2155 d7b8 6b1e bad4 d9e5  |....D!U..k.....
    0x01e0:  8a70 6884 a068 e5f1 1c62 1f15 941c 0e47  .ph..h...b.....G
    0x01f0:  a3e2 4b46 8f30 d8f3 b538 bf86 86b5 75d6  ..KF.0...8....u.
    0x0200:  9bff a9be c738 5d2c 783f 06b3 1b28 480d  .....8],x?...(H.
    0x0210:  3a31 7489 983d 62ad f443 0cf2 23ff 43fd  :1t..=b..C..#.C.
    0x0220:  b8d9 c24b 0ae1 f4f1 770b 919c 45ba dc3a  ...K....w...E..:
    0x0230:  dc44 c8b6 6db8 77af cf09 be25 9dfd ee9f  .D..m.w....%....          NB: split is here:     ".D.."  <--->. "m.w....%...." 
    0x0240:  db0b 12ed 856c e1f4 e7fc e2ad 509f 6537  .....l......P.e7
    0x0250:  8c                                       .
17:16:12.873751 IP localhost.30015 > localhost.53812: Flags [.], ack 1127, win 6362, options [nop,nop,TS val 1044068216 ecr 3119475487], length 0
    0x0000:  4500 0034 0000 4000 4006 0000 7f00 0001  E..4..@.@.......
    0x0010:  7f00 0001 753f d234 de91 e88a 8ae8 9aa7  ....u?.4........
    0x0020:  8010 18da fe28 0000 0101 080a 3e3b 3778  .....(......>;7x
    0x0030:  b9ef 6b1f                                ..k.

因为整个过程以及相当长一段时间以内db tunnel的处理都没有发生变化。所以，问题应该极大可能出在ASE Server端对接收和处理SSL packet的方式上。

可是，这个问题非常特殊，它只发生在使用dbtunnel 的情况下。如果抛开这一层，ASE和jdbc之间以及isql之间都能良好的工作。于是在哪一个层次去尝试解决问题也成了关键。

这里不给最终的解决方案，一种到目前可行的解决方法是修改NEO SDK中的有关SSL通信处理的部分，让它不对>512的packet进行拆分。在proxy forward的选项里加入：

channel.config().setOption(ChannelOption.RCVBUF_ALLOCATOR, new AdaptiveRecvByteBufAllocator(1024,2048,65536));

也就是说让最小拆分的packet大小为1024.而不是512. 似乎这样修改以后，整个连接处理就变得正常了。

小结：

Cloud环境下如果出了底层的问题，处理起来将比非Cloud环境复杂的多。非Cloud环境，你至少可以手动搭建一个，快速模拟重现，然后层层DEBUG，而Cloud环境如果要完全搭建，从资源上和各个角度来看，有时候很难复现出一模一样的环境。

上边这个案例，就涉及到最终解决问题的方式，因为它本质上不能算是DB Tunnel的问题，它的行为一直没有发生变化。但是ASE自某一个版本以后(PL12及以后），对于SSL包大小的处理方式似乎变了，导致以前的proxy处理方式不可用。但是因为这个修复可能要调整的地方实在太大，代价也会非常大。因此，在哪个地方解决问题就需要协调了。

因为使用dbtunnel主要是DevOps或者部分DBA日常维护需要，因为，临时性的，可以将NEO SDK (dbtunnel)，打一个简单的patch，能够用上就好。

其实，从这中间也可以总结出一个教训，无论多复杂的软件，要保证最终的良好质量，就得有足够充分的测试用例。上边这个案例，应该是缺少一个db tunnel不断连接ASE的测试用例。它不是说每次都不能连。有时候也能连上（包大小小于512字节的情况下)。测试用例充分 的话，很容易就能重现出来。问题虽然不严重（毕竟不影响日常业务运行），但是确实值得引起重视。