3

jdbc访问KingbaseES数据库SocketTimeoutException Read timed out - nwwhile

 1 year ago
source link: https://www.cnblogs.com/nwwhile/p/17131372.html
Go to the source link to view the article. You can view the picture content, updated content and better typesetting reading experience. If the link is broken, please click the button below to view the snapshot at that time.

jdbc访问KingbaseES数据库发生异常：SocketTimeoutException Read timed out

一、异常现象：

应用显示ERROR信息：

Caused By: java.net.SocketTimeoutException: Read timed out
           at java.base/java.net.SocketInputStream.socketRead(Native Method)
           at java.base/java.net.SocketInputStream.socketRead(SocketInputStream.java:115)
           at java.base/java.net.SocketInputStream.read(SocketInputStream.java:168)
           at java.base/java.net.SocketInputStream.read(SocketInputStream.java:140)
...
Com.kingbase8.util.KSQLException: An I/O error occurred while sending to this backend.
at com.kingbase8.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:345) 
at com.kingbase8.jdbc.KbStatement.executeInternal(KbStatement.java:472) 
at com.kingbase8.jdbc.KbStatement.execute(KbStatement.java:392) 
at com.kingbase8.jdbc.KbPreparedStatement.executeWithFlags(KbPreparedStatement.java:191) 
at com.kingbase8.jdbc.KbPreparedStatement.execute(KbPreparedStatement.java:180) 
at com.alibaba.druid.filter.FilterChainImpl.preparedStatement_executeQuery(FilterChainImpl.java:3446) 
at com.alibaba.druid.filter.FilterEventAdapter.preparedStatement_executeQuery(FilterEventAdapter.java:434)
at com.alibaba.druid.filter.FilterChainImpl.peparedStatement_executeQuery(FilterChainImpl.java:3444)
at com.alibaba.druid.filter.FilterEventAdapter.preparedStatement_executeQuery(FilterAdapter.java:434)

二、基本信息：

Java 应用 + SpingBoot 框架 + Druid-1.2.15版本数据源 + CentOS Linux release 7.9(2009)

应用服务器IP地址10.10.10.16，数据库服务器IP地址10.10.10.36

三、排查过程：

使用到的系统工具：tcpdump、strace

tcpdump 是一款 Linux 平台的抓包工具。它可以抓取涵盖整个 TCP/IP 协议族的数据包，支持针对网络层、协议、主机、端口的过滤，并提供 and、or、not 等逻辑语句来过滤无用的信息。tcpdump基于底层libpcap库开发，运行需要root权限。
strace是一个可用于诊断、调试和分析的Linux用户空间跟踪器。可以使用它来监控用户空间进程和内核的交互，比如系统调用、信号传递、进程状态变更等。strace作为一种动态跟踪工具，能够高效地定位进程和服务故障、分析程序hang住或者程序崩溃的原因，其跟踪程序执行过程中产生的系统调用及接收到的信号，帮助我们分析程序或命令执行中遇到的异常情况，使用strace跟踪挂死程序，如果最后一行系统调用显示完整，程序在逻辑代码处挂死；如果最后一行系统调用显示不完整，程序在该系统调用处挂死。

1、检查数据库参数配置

检查kingbase.conf、 kingbase.auto.conf配置文件tcp开头的参数，在Linux系统参数默认值都为0，表示使用系统默认值，取值为linux操作系统sysctl -a对应的参数值。在等效的套接字选项可用系统以及 Windows支持，在Linux系统上设置无效。如果在linux系统部署的数据库服务器上设置非0值，应用跟数据库之间存在访问限制或者防火墙，也会导致应用连接的SocketTimeoutException。

$ cat /home/kingbase/data/kingbase.conf | grep tcp_*
# see "man 7 tcp" for details
#tcp_keepalives_idle = 0                # TCP_KEEPIDLE, in seconds;
#tcp_keepalives_interval = 0            # TCP_KEEPINTVL, in seconds;
#tcp_keepalives_count = 0               # TCP_KEEPCNT;
#tcp_user_timeout = 0                   # TCP_USER_TIMEOUT, in milliseconds;

$ cat /home/kingbase/data/kingbase.auto.conf | grep tcp_*

经检查数据库配置文件均使用默认值0.

2、在jdbc连接串添加socketTimeout/connectTimeout/loggerLevel/loggerFile参数

一般情况下，SocketTimeoutException异常在jdbc url只需添加socketTimeout参数就可以解决此问题。

# 在jdbc连接串添加以下参数
socketTimeout=120
connectTimeout=120
loggerLevel=trace
loggerFile=/opt/jdbc.log
# 完整的jdbc url连接串例子
jdbc:kingbase8://10.10.10.36:54321/test?currentSchema=public&socketTimeout=120&connectTimeout=120&loggerLevel=trace&loggerFile=/opt/jdbc.log

通过给jdbc url连接串添加参数，打印jdbc连接日志，应用访问依然是提示同样的错误信息。参数无效？

Caused By: java.net.SocketTimeoutException: Read timed out
           at java.base/java.net.SocketInputStream.socketRead0(Native Method)
           at java.base/java.net.SocketInputStream.socketRead(SocketInputStream.java:115)
           at java.base/java.net.SocketInputStream.read(SocketInputStream.java:168)
           at java.base/java.net.SocketInputStream.read(SocketInputStream.java:140)
...
Com.kingbase8.util.KSQLException: An I/O error occurred while sending to this backend.
at com.kingbase8.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:345) 
at com.kingbase8.jdbc.KbStatement.executeInternal(KbStatement.java:472) 
at com.kingbase8.jdbc.KbStatement.execute(KbStatement.java:392) 
at com.kingbase8.jdbc.KbPreparedStatement.executeWithFlags(KbPreparedStatement.java:191) 
at com.kingbase8.jdbc.KbPreparedStatement.execute(KbPreparedStatement.java:180) 
at com.alibaba.druid.filter.FilterChainImpl.preparedStatement_executeQuery(FilterChainImpl.java:3446) 
at com.alibaba.druid.filter.FilterEventAdapter.preparedStatement_executeQuery(FilterEventAdapter.java:434)
at com.alibaba.druid.filter.FilterChainImpl.peparedStatement_executeQuery(FilterChainImpl.java:3444)
at com.alibaba.druid.filter.FilterEventAdapter.preparedStatement_executeQuery(FilterAdapter.java:434)

3、使用tcpdump排除网络原因：

# host 填写需要监听的ip地址，
# port 填写需要舰艇的端口
# enp0s17 ip地址对应的网卡名称
# tcpdump.out 使用tcpdump抓包生成的文件
tcpdump -nv -i enp0s17: '((ip[1:1] - ((ip[0]&0xf)<<2)) - ((tcp[12]&0xf0)>>2)) != 0' and host 10.10.10.36 and port 54321  -XX > tcpdump.out 2>&1

使用tcpdump抓取应用对应模块访问数据库直到发生Read timed out异常期间的数据包。

# 由于日志有点多，只筛选出发生异常连接的tcpdump信息
# TCP三次握手的过程：
# 第一次握手10.10.10.16.58209 > 10.10.10.36.54321: 请求来自10.10.10.16端口是58209，目标的IP地址是10.10.10.36端口是54321。Flags [SEW] 这里SEW看作是S就行，表示客户端的SYN请求，seq为614136864
# 第二次握手10.10.10.36.54321 > 10.10.10.16.58209: 10.10.10.36回复来自10.10.10.16的请求，Flags [S.] S表示SYN回复，.表示ack，seq 614136865 = 客户端seq + 1。
# 第三次握手10.10.10.16.58209 > 10.10.10.36.54321: 客户端到目标端 Flags为[.]，表示ack确认，此时TCP三次握手建立成功。

10:26:18.832836 IP (tos 0x2,ECT(0), ttl 128, id 21814, offset 0, flags [DF], proto TCP (6), length 52)
    10.10.10.16.58209 > 10.10.10.36.54321: Flags [SEW], cksum 0x2c80 (correct), seq 614136864, win 8192, options [mss 1460,nop,wscale 8,nop,nop,sackOK], length 0
	0x0000:  fa16 3ecc 3d29 fa16 3e6f ab70 0800 4502  ..>.=)..>o.p..E.
	0x0010:  0034 5536 4000 8006 5c0a 11a7 1310 11a7  .4U6@...\.......
	0x0020:  1324 e361 d431 249a fc20 0000 0000 80c2  .$.a.1$.........
	0x0030:  2000 2c80 0000 0204 05b4 0103 0308 0101  ..,.............
	0x0040:  0402                                     ..
10:26:18.832851 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 52)
    10.10.10.36.54321 > 10.10.10.16.58209: Flags [S.], cksum 0x49a8 (incorrect -> 0x97b3), seq 1234893263, ack 614136865, win 29200, options [mss 1460,nop,nop,sackOK,nop,wscale 9], length 0
	0x0000:  fa16 3e6f ab70 fa16 3ecc 3d29 0800 4500  ..>o.p..>.=)..E.
	0x0010:  0034 0000 4000 4006 f142 11a7 1324 11a7  .4..@[email protected]...$..
	0x0020:  1310 d431 e361 499a f9cf 249a fc21 8012  ...1.aI...$..!..
	0x0030:  7210 49a8 0000 0204 05b4 0101 0402 0103  r.I.............
	0x0040:  0309                                     ..
10:26:18.833060 IP (tos 0x0, ttl 128, id 21815, offset 0, flags [DF], proto TCP (6), length 40)
    10.10.10.16.58209 > 10.10.10.36.54321: Flags [.], cksum 0x4897 (correct), ack 1, win 513, length 0
	0x0000:  fa16 3ecc 3d29 fa16 3e6f ab70 0800 4500  ..>.=)..>o.p..E.
	0x0010:  0028 5537 4000 8006 5c17 11a7 1310 11a7  .(U7@...\.......
	0x0020:  1324 e361 d431 249a fc21 499a f9d0 5010  .$.a.1$..!I...P.
	0x0030:  0201 4897 0000 0000 0000 0000            ..H.........
	
# 以下就是实际数据传输过程，可以看到tcp的分段传输，客户端到目标短的数据seq 1:9,目标短响应ack 9。依此类推。通过分析tcpdump日志，没有发现异常情况，排除数据库服务器网络原因。
10:26:18.833386 IP (tos 0x0, ttl 128, id 21816, offset 0, flags [DF], proto TCP (6), length 48)
    10.10.10.16.58209 > 10.10.10.36.54321: Flags [P.], cksum 0x2d7e (correct), seq 1:9, ack 1, win 513, length 8
	0x0000:  fa16 3ecc 3d29 fa16 3e6f ab70 0800 4500  ..>.=)..>o.p..E.
	0x0010:  0030 5538 4000 8006 5c0e 11a7 1310 11a7  .0U8@...\.......
	0x0020:  1324 e361 d431 249a fc21 499a f9d0 5018  .$.a.1$..!I...P.
	0x0030:  0201 2d7e 0000 0000 0008 04d2 162f       ..-~........./
10:26:18.833386 IP (tos 0x0, ttl 128, id 21816, offset 0, flags [DF], proto TCP (6), length 48)
    10.10.10.16.58209 > 10.10.10.36.54321: Flags [P.], cksum 0x2d7e (correct), seq 1:9, ack 1, win 513, length 8
	0x0000:  fa16 3ecc 3d29 fa16 3e6f ab70 0800 4500  ..>.=)..>o.p..E.
	0x0010:  0030 5538 4000 8006 5c0e 11a7 1310 11a7  .0U8@...\.......
	0x0020:  1324 e361 d431 249a fc21 499a f9d0 5018  .$.a.1$..!I...P.
	0x0030:  0201 2d7e 0000 0000 0008 04d2 162f       ..-~........./
10:26:22.723238 IP (tos 0x0, ttl 128, id 21983, offset 0, flags [DF], proto TCP (6), length 428)
    10.10.10.16.58209 > 10.10.10.36.54321: Flags [P.], cksum 0xbfcf (correct), seq 3358:3746, ack 1919, win 511, length 388
	0x0000:  fa16 3ecc 3d29 fa16 3e6f ab70 0800 4500  ..>.=)..>o.p..E.
	0x0010:  01ac 55df 4000 8006 59eb 11a7 1310 11a7  [email protected].......
	0x0020:  1324 e361 d431 249b 093e 499b 014e 5018  .$.a.1$..>I..NP.
	0x0030:  01ff bfcf 0000 5000 0001 2c00 7365 6c65  ......P...,.sele
	0x0040:  6374 2063 6f75 6e74 282a 2920 746f 7461  ct.count(*).tota
	0x0050:  6c0a 2020 2020 2020 2020 6672 6f6d 2070  l.........from.p
	0x0060:  6572 6d69 7373 696f 6e5f 696e 666f 0a20  ermission_info..
	0x0070:  2020 2020 2020 2077 6865 7265 2064 656c  .......where.del
	0x0080:  6574 655f 666c 6167 203d 2027 3027 0a20  ete_flag.=.'0'..
	0x0090:  2020 2020 2020 2020 0a20 2020 2020 2020  ................
	0x00a0:  2020 0a20 2020 2020 2020 2020 0a20 2020  ................
	0x00b0:  2020 2020 2020 0a20 2020 2020 2020 2020  ................
	0x00c0:  2020 2061 6e64 2064 6f75 6274 5f73 7461  ...and.doubt_sta
	0x00d0:  7465 203d 2024 310a 2020 2020 2020 2020  te.=.$1.........
	0x00e0:  200a 2020 2020 2020 2020 200a 2020 2020  ................
	0x00f0:  2020 2020 2020 2020 616e 6420 6572 726f  ........and.erro
	0x0100:  725f 7374 6174 6520 3d20 2432 0a20 2020  r_state.=.$2....
	0x0110:  2020 2020 2020 0a20 2020 2020 2020 2020  ................
	0x0120:  0a20 2020 2020 2020 2020 0a20 2020 2020  ................
	0x0130:  2020 2020 2020 2061 6e64 2073 6f75 7263  .......and.sourc
	0x0140:  655f 6465 7061 7274 6d65 6e74 5f69 6420  e_department_id.
	0x0150:  3d20 2433 0000 0320 0004 1320 0004 1320  =.$3............
	0x0160:  0004 1342 0000 0040 0000 0003 0000 0000  ...B...@........
	0x0170:  0000 0003 0000 0001 3000 0000 0130 0000  ........0....0..
	0x0180:  0020 6639 6434 3831 6364 3037 6336 3465  ..f9d481cd07c64e
	0x0190:  3939 6164 3435 3038 3665 6237 6538 6130  99ad45086eb7e8a0
	0x01a0:  3038 0000 4400 0000 0650 0045 0000 0009  08..D....P.E....
	0x01b0:  0000 0000 0053 0000 0004                 .....S....
10:26:22.723272 IP (tos 0x0, ttl 64, id 5340, offset 0, flags [DF], proto TCP (6), length 40)
    10.10.10.36.54321 > 10.10.10.16.58209: Flags [.], cksum 0x499c (incorrect -> 0x3431), ack 3746, win 72, length 0
	0x0000:  fa16 3e6f ab70 fa16 3ecc 3d29 0800 4500  ..>o.p..>.=)..E.
	0x0010:  0028 14dc 4000 4006 dc72 11a7 1324 11a7  .(..@[email protected]...$..
	0x0020:  1310 d431 e361 499b 014e 249b 0ac2 5010  ...1.aI..N$...P.
	0x0030:  0048 499c 0000                           .HI...
10:26:22.941670 IP (tos 0x0, ttl 64, id 5341, offset 0, flags [DF], proto TCP (6), length 118)
    10.10.10.36.54321 > 10.10.10.16.58209: Flags [P.], cksum 0x49ea (incorrect -> 0x3e06), seq 1919:1997, ack 3746, win 72, length 78
	0x0000:  fa16 3e6f ab70 fa16 3ecc 3d29 0800 4500  ..>o.p..>.=)..E.
	0x0010:  0076 14dd 4000 4006 dc23 11a7 1324 11a7  .v..@.@..#...$..
	0x0020:  1310 d431 e361 499b 014e 249b 0ac2 5018  ...1.aI..N$...P.
	0x0030:  0048 49ea 0000 3100 0000 0432 0000 0004  .HI...1....2....
	0x0040:  5400 0000 1e00 0174 6f74 616c 0000 0000  T......total....
	0x0050:  0000 0000 0000 1400 08ff ffff ff00 0044  ...............D
	0x0060:  0000 0010 0001 0000 0006 3134 3634 3939  ..........146499
	0x0070:  4300 0000 0d53 454c 4543 5420 3100 5a00  C....SELECT.1.Z.
	0x0080:  0000 0549                                ...I
10:26:22.950436 IP (tos 0x0, ttl 128, id 22267, offset 0, flags [DF], proto TCP (6), length 428)
    10.10.10.16.58209 > 10.10.10.36.54321: Flags [P.], cksum 0xbafe (correct), seq 3746:4134, ack 1997, win 511, length 388
	0x0000:  fa16 3ecc 3d29 fa16 3e6f ab70 0800 4500  ..>.=)..>o.p..E.
	0x0010:  01ac 56fb 4000 8006 58cf 11a7 1310 11a7  [email protected].......
	0x0020:  1324 e361 d431 249b 0ac2 499b 019c 5018  .$.a.1$...I...P.
	0x0030:  01ff bafe 0000 5000 0001 2c00 7365 6c65  ......P...,.sele
	0x0040:  6374 2063 6f75 6e74 282a 2920 746f 7461  ct.count(*).tota
	0x0050:  6c0a 2020 2020 2020 2020 6672 6f6d 2070  l.........from.p
	0x0060:  756e 6973 686d 656e 745f 696e 666f 0a20  unishment_info..
	0x0070:  2020 2020 2020 2077 6865 7265 2064 656c  .......where.del
	0x0080:  6574 655f 666c 6167 203d 2027 3027 0a20  ete_flag.=.'0'..
	0x0090:  2020 2020 2020 2020 0a20 2020 2020 2020  ................
	0x00a0:  2020 0a20 2020 2020 2020 2020 0a20 2020  ................
	0x00b0:  2020 2020 2020 0a20 2020 2020 2020 2020  ................
	0x00c0:  2020 2061 6e64 2064 6f75 6274 5f73 7461  ...and.doubt_sta
	0x00d0:  7465 203d 2024 310a 2020 2020 2020 2020  te.=.$1.........
	0x00e0:  200a 2020 2020 2020 2020 200a 2020 2020  ................
	0x00f0:  2020 2020 2020 2020 616e 6420 6572 726f  ........and.erro
	0x0100:  725f 7374 6174 6520 3d20 2432 0a20 2020  r_state.=.$2....
	0x0110:  2020 2020 2020 0a20 2020 2020 2020 2020  ................
	0x0120:  0a20 2020 2020 2020 2020 0a20 2020 2020  ................
	0x0130:  2020 2020 2020 2061 6e64 2073 6f75 7263  .......and.sourc
	0x0140:  655f 6465 7061 7274 6d65 6e74 5f69 6420  e_department_id.
	0x0150:  3d20 2433 0000 0320 0004 1320 0004 1320  =.$3............
	0x0160:  0004 1342 0000 0040 0000 0003 0000 0000  ...B...@........
	0x0170:  0000 0003 0000 0001 3000 0000 0130 0000  ........0....0..
	0x0180:  0020 6639 6434 3831 6364 3037 6336 3465  ..f9d481cd07c64e
	0x0190:  3939 6164 3435 3038 3665 6237 6538 6130  99ad45086eb7e8a0
	0x01a0:  3038 0000 4400 0000 0650 0045 0000 0009  08..D....P.E....
	0x01b0:  0000 0000 0053 0000 0004                 .....S....
10:26:22.950471 IP (tos 0x0, ttl 64, id 5342, offset 0, flags [DF], proto TCP (6), length 40)
    10.10.10.36.54321 > 10.10.10.16.58209: Flags [.], cksum 0x499c (incorrect -> 0x325d), ack 4134, win 74, length 0
	0x0000:  fa16 3e6f ab70 fa16 3ecc 3d29 0800 4500  ..>o.p..>.=)..E.
	0x0010:  0028 14de 4000 4006 dc70 11a7 1324 11a7  .(..@[email protected]...$..
	0x0020:  1310 d431 e361 499b 019c 249b 0c46 5010  ...1.aI...$..FP.
	0x0030:  004a 499c 0000                           .JI...
10:26:23.550825 IP (tos 0x0, ttl 64, id 5343, offset 0, flags [DF], proto TCP (6), length 118)
    10.10.10.36.54321 > 10.10.10.16.58209: Flags [P.], cksum 0x49ea (incorrect -> 0x4538), seq 1997:2075, ack 4134, win 74, length 78
	0x0000:  fa16 3e6f ab70 fa16 3ecc 3d29 0800 4500  ..>o.p..>.=)..E.
	0x0010:  0076 14df 4000 4006 dc21 11a7 1324 11a7  .v..@.@..!...$..
	0x0020:  1310 d431 e361 499b 019c 249b 0c46 5018  ...1.aI...$..FP.
	0x0030:  004a 49ea 0000 3100 0000 0432 0000 0004  .JI...1....2....
	0x0040:  5400 0000 1e00 0174 6f74 616c 0000 0000  T......total....
	0x0050:  0000 0000 0000 1400 08ff ffff ff00 0044  ...............D
	0x0060:  0000 0010 0001 0000 0006 3236 3031 3534  ..........260154
	0x0070:  4300 0000 0d53 454c 4543 5420 3100 5a00  C....SELECT.1.Z.
	0x0080:  0000 0549                                ...I

关于tcpdump Flags 标志位

[S]  表示seq:
在建立连接时使用，用来同步序号。当 SYN=1，ACK=0 时，表示这是一个请求建立连接的报文段；当 SYN=1，ACK=1 时，表示对方同意建立连接。SYN=1 时，说明这是一个请求建立连接或同意建立连接的报文。
[S.] 表示seq和ack:
[.]  表示ack:
确认序号标志，为1时表示确认号有效，为0表示报文中不含确认信息，忽略确认号字段。我们称携带ACK标识的TCP报文段为确认报文段。TCP 规定，连接建立后，ACK 必须为 1。
[F]  表示FIN:
标记数据是否发送完毕。如果 FIN=1，表示数据已经发送完成，可以释放连接,我们称携带FIN标志的TCP报文段为结束报文段。
[P]  表示有DATA数据传输:
Push为1表示是带有push标志的数据，指示接收方在接收到该报文段以后，应优先将这个报文段交给应用程序，而不是在tcp内核缓冲区排队。
[R]  表示连接重置:
表示是否重置连接。如果 RST=1，说明 TCP 连接出现了严重错误（如主机崩溃），必须释放连接，然后再重新建立连接。
[E]  表示ECN-Echo:
用来在 TCP 三次握手时表明一个 TCP 端是具备 ECN 功能的。在数据传输过程中，它也用来表明接收到的 TCP 包的 IP 头部的 ECN 被设置为 11，即网络线路拥堵。
[W]  表示ECN CWR:
（Congestion Window Reduce）拥塞窗口减少标志，用来表明它接收到了设置 ECE 标志的 TCP 包。并且，发送方收到消息之后，通过减小发送窗口的大小来降低发送速率。

4、使用strace分析程序在系统调用遇到的异常情况：

# strace输出信息，无异常信息，应用访问数据返回正常，进程也正常退出
strace: Process 176337 attached
10:28:50 epoll_wait(3, [{EPOLLIN, {u32=18386056, u64=18386056}}], 1, -1) = 1
10:28:50 recvfrom(10, "Q\0\0\0\26select * from tb;\0", 8192, 0, NULL, NULL) = 23
10:28:50 lseek(89, 0, SEEK_END)         = 450560
10:28:50 lseek(89, 0, SEEK_END)         = 450560
10:28:50 sendto(10, "T\0\0\0002\0\2id\0\0\0@a\0\1\0\0\0\27\0\4\377\377\377\377\0\0name"..., 8192, 0, NULL, 0) = 8192
10:28:50 sendto(10, "\0\2\0\0\0\003349\0\0\0\6Tes349D\0\0\0\27\0\2\0\0\0\00335"..., 8192, 0, NULL, 0) = 8192
10:28:50 sendto(10, "0\0\0\0\6Tes690D\0\0\0\27\0\2\0\0\0\003691\0\0\0\6Tes"..., 8192, 0, NULL, 0) = 8192
10:28:50 sendto(10, "1029\0\0\0\7Tes1029D\0\0\0\31\0\2\0\0\0\0041030\0\0"..., 8192, 0, NULL, 0) = 8192
10:28:50 sendto(10, "44\0\0\0\7Tes1344D\0\0\0\31\0\2\0\0\0\0041345\0\0\0\7"..., 8192, 0, NULL, 0) = 8192
10:28:50 sendto(10, "\0\0\0\7Tes1659D\0\0\0\31\0\2\0\0\0\0041660\0\0\0\7Te"..., 8192, 0, NULL, 0) = 8192
10:28:50 sendto(10, "\0\7Tes1974D\0\0\0\31\0\2\0\0\0\0041975\0\0\0\7Tes1"..., 8192, 0, NULL, 0) = 8192
10:28:50 sendto(10, "Tes2289D\0\0\0\31\0\2\0\0\0\0042290\0\0\0\7Tes229"..., 8192, 0, NULL, 0) = 8192
10:28:50 sendto(10, "s2604D\0\0\0\31\0\2\0\0\0\0042605\0\0\0\7Tes2605D"..., 8192, 0, NULL, 0) = 8192
10:28:50 sendto(10, "919D\0\0\0\31\0\2\0\0\0\0042920\0\0\0\7Tes2920D\0\0"..., 8192, 0, NULL, 0) = 8192
10:28:50 sendto(10, "4D\0\0\0\31\0\2\0\0\0\0043235\0\0\0\7Tes3235D\0\0\0\31"..., 8192, 0, NULL, 0) = 8192
10:28:50 sendto(10, "\0\0\0\31\0\2\0\0\0\0043550\0\0\0\7Tes3550D\0\0\0\31\0\2"..., 8192, 0, NULL, 0) = 8192
10:28:50 sendto(10, "\0\31\0\2\0\0\0\0043865\0\0\0\7Tes3865D\0\0\0\31\0\2\0\0"..., 8192, 0, NULL, 0) = 8192
10:28:50 sendto(10, "\0\2\0\0\0\0044180\0\0\0\7Tes4180D\0\0\0\31\0\2\0\0\0\4"..., 8192, 0, NULL, 0) = 8192
10:28:50 sendto(10, "\0\0\0\0044495\0\0\0\7Tes4495D\0\0\0\31\0\2\0\0\0\00444"..., 8192, 0, NULL, 0) = 8192
10:28:50 sendto(10, "\0\0044810\0\0\0\7Tes4810D\0\0\0\31\0\2\0\0\0\0044811"..., 8192, 0, NULL, 0) = 8192
10:28:50 sendto(10, "5125\0\0\0\7Tes5125D\0\0\0\31\0\2\0\0\0\0045126\0\0"..., 8192, 0, NULL, 0) = 8192
10:28:50 sendto(10, "40\0\0\0\7Tes5440D\0\0\0\31\0\2\0\0\0\0045441\0\0\0\7"..., 8192, 0, NULL, 0) = 8192
10:28:50 sendto(10, "\0\0\0\7Tes5755D\0\0\0\31\0\2\0\0\0\0045756\0\0\0\7Te"..., 8192, 0, NULL, 0) = 8192
10:28:50 sendto(10, "\0\7Tes6070D\0\0\0\31\0\2\0\0\0\0046071\0\0\0\7Tes6"..., 8192, 0, NULL, 0) = 8192
10:28:50 sendto(10, "Tes6385D\0\0\0\31\0\2\0\0\0\0046386\0\0\0\7Tes638"..., 8192, 0, NULL, 0) = 8192
10:28:50 sendto(10, "s6700D\0\0\0\31\0\2\0\0\0\0046701\0\0\0\7Tes6701D"..., 8192, 0, NULL, 0) = 8192
10:28:50 sendto(10, "015D\0\0\0\31\0\2\0\0\0\0047016\0\0\0\7Tes7016D\0\0"..., 8192, 0, NULL, 0) = 8192
10:28:50 sendto(10, "0D\0\0\0\31\0\2\0\0\0\0047331\0\0\0\7Tes7331D\0\0\0\31"..., 8192, 0, NULL, 0) = 8192
10:28:50 sendto(10, "\0\0\0\31\0\2\0\0\0\0047646\0\0\0\7Tes7646D\0\0\0\31\0\2"..., 8192, 0, NULL, 0) = 8192
10:28:50 sendto(10, "\0\31\0\2\0\0\0\0047961\0\0\0\7Tes7961D\0\0\0\31\0\2\0\0"..., 8192, 0, NULL, 0) = 8192
10:28:50 sendto(10, "\0\2\0\0\0\48276\0\0\0\7Tes8276D\0\0\0\31\0\2\0\0\0\4"..., 8192, 0, NULL, 0) = 8192
10:28:50 sendto(10, "\0\0\0\48591\0\0\0\7Tes8591D\0\0\0\31\0\2\0\0\0\485"..., 8192, 0, NULL, 0) = 8192
10:28:50 sendto(10, "\0\48906\0\0\0\7Tes8906D\0\0\0\31\0\2\0\0\0\48907"..., 8192, 0, NULL, 0) = 8192
10:28:50 sendto(10, "9221\0\0\0\7Tes9221D\0\0\0\31\0\2\0\0\0\49222\0\0"..., 8192, 0, NULL, 0) = 8192
10:28:50 sendto(10, "36\0\0\0\7Tes9536D\0\0\0\31\0\2\0\0\0\49537\0\0\0\7"..., 8192, 0, NULL, 0) = 8192
10:28:50 sendto(8, "\2\0\0\0\230\0\0\0\3102\0\0\1\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 152, 0, NULL, 0) = 152
10:28:50 sendto(8, "\20\0\0\0\200\0\0\0\2\0\0\0\0\0\0\0\n\0\0\0\3102\0\0\t\0\0\0\0\0\0\0"..., 128, 0, NULL, 0) = 128
10:28:50 sendto(8, "\21\0\0\0H\0\0\0\1\0\0\0\0\0\0\0\0\0\0\6\n\0\0\0\3102\0\0\0\0\0\0"..., 72, 0, NULL, 0) = 72
10:28:50 sendto(8, "\22\0\0\0\260\0\0\0\1\0\0\0\0\0\0\0\n\0\0\0\3102\0\0g\276\262&\243.\36\336"..., 176, 0, NULL, 0) = 176
10:28:50 sendto(10, "\0\0\0\7Tes9851D\0\0\0\31\0\2\0\0\0\49852\0\0\0\7Te"..., 3963, 0, NULL, 0) = 3963
10:28:50 recvfrom(10, 0xf26060, 8192, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
10:28:50 epoll_wait(3, [{EPOLLIN|EPOLLHUP, {u32=18386056, u64=18386056}}], 1, -1) = 1
10:28:50 recvfrom(10, "X\0\0\0\4", 8192, 0, NULL, NULL) = 5
10:28:50 sendto(8, "\20\0\0\0H\0\0\0\1\0\0\0\0\0\0\0\n\0\0\0\3102\0\0\t\0\0\0\0\0\0\0"..., 72, 0, NULL, 0) = 72
10:28:50 sendto(8, "\21\0\0\0H\0\0\0\1\0\0\0\0\0\0\0\0\0\0\6\n\0\0\0\3102\0\0\0\0\0\0"..., 72, 0, NULL, 0) = 72
10:28:50 epoll_ctl(3, EPOLL_CTL_MOD, 11, {EPOLLIN|EPOLLERR|EPOLLHUP, {u32=18386080, u64=18386080}}) = 0
10:28:50 exit_group(0)                  = ?
10:28:50 +++ exited with 0 +++

通过strace跟踪应用访问数据库执行查询过程中进程的所有系统调用以及进程所接收到的所有的信号值，发现数据库返回正常，未发现异常信息。应用如果在数据库访问出现异常，那么在strace跟踪日志会显示发生的异常信息。

进程在执行过程中有异常发生strace跟踪进程日志的信息输出：

# 可以看到有Connection timed out异常信息输出
[pid 23164] 10:37:47 close(39)          = 0
[pid 23164] 10:37:47 epoll_wait(25,  <unfinished ...>
[pid 23128] 10:37:48 mprotect(0x7f872bd70000, 4096, PROT_READ) = 0
[pid 23128] 10:37:48 mprotect(0x7f872bd70000, 4096, PROT_READ|PROT_WRITE) = 0
[pid 23128] 10:37:48 mprotect(0x7f872bd71000, 4096, PROT_NONE) = 0
[pid 23128] 10:37:48 mprotect(0x7f872bd71000, 4096, PROT_READ) = 0
[pid 80913] 10:38:21 <... restart_syscall resumed>) = -1 ETIMEDOUT (Connection timed out)
[pid 80914] 10:38:21 <... restart_syscall resumed>) = -1 ETIMEDOUT (Connection timed out)

5、系统跟网络相关内核参数检查

# 客户机认为连接断开并通知应用层之前发送并未获确认的探测器数
net.ipv4.tcp_keepalive_probes=3
# 发送的最后一个数据包与第一个保持活动探测器之间的时间间隔
net.ipv4.tcp_keepalive_time=1200
# 发送后续保持活动探测器的时间间隔
net.ipv4.tcp_keepalive_intvl=30

6、Druid连接池

既然Druid连接池是阿里巴巴开源的数据库连接池项目，在GitHub看看是否有相同的问题。

项目地址：https://github.com/alibaba/druid

经过一番搜索终于发现问题所在，具体信息请参考：

https://github.com/alibaba/druid/releases

Druid 1.2.12版本发布，连接池默认指定socketTimeout，增强SQL Parser

Druid 1.2.13版本发布，修复连接池默认指定socketTimeout导致的问题

https://github.com/alibaba/druid/issues/4946

驱动参数中loginTimeout和socketTimeout传入了Integer类型导致失效或NPE

四、问题原因：

1.项目现场使用的Druid版本是1.2.15，属于是已经fix4946 bug之后的版本，在druid数据源url连接串添加socketTimeout=120，但是实际情况跟驱动参数中socketTimeout传入了Integer类型导致失效相同。

2.根据Druid 1.2.12版本说明：连接池DruidDataSource支持新的配置connectTimeout和socketTimeout，分别都是10秒。这个默认值会减少因为网络丢包时导致的连接池无法创建链接。但是如果应用执行的sql超过socketTimeout默认值会发生异常（建议根据实际情况设置合理的值，避免应用执行sql时长超过默认值发生SocketTimeoutException）。

3.根据Druid 1.2.12版本说明问题原因应该是：在使用Druid数据源的场景且Druid版本>=1.2.12，Druid数据源socketTimeout默认值会覆盖url连接串里面的socketTimeout。这样就可以解释第1条在druid数据源url连接串添加socketTimeout无效的情况。

解决过程：

第一次报错：druid数据源 url 未添加 sockettimeout=120，druid 数据源未添加 socket-timeout=300000
第二次报错：druid数据源 url 添加 sockettimeout=120，druid 数据源未添加 socket-timeout=300000
第三次：druid 数据源添加 socket-timeout=300000 connect-timeout=300000问题解决。

五、解决方法：

在druid数据源配置添加 socket-timeout、connect-timeout参数

druid:
  datasource:
    username: root
    password: 123456
    url: jdbc:mysql://10.10.10.36:54321/test?characterEncoding=utf-8
    driver-class-name: com.kingbase8.Driver

    #druid 数据源专有配置
    initialSize: 5
    minIdle: 5
    maxActive: 20
    maxWait: 60000
    timeBetweenEvictionRunsMillis: 60000
    minEvictableIdleTimeMillis: 300000
    validationQuery: SELECT 1 FROM DUAL
    testWhileIdle: true
    testOnBorrow: false
    testOnReturn: false
    poolPreparedStatements: true

    #配置监控统计拦截的filters，stat:监控统计、log4j：日志记录、wall：防御sql注入
    #如果允许时报错  java.lang.ClassNotFoundException: org.apache.log4j.Priority
    filters: stat,wall,log4j
    stat-view-servlet:
    	login-username: admin
    	login-password: admin
    	enabled: true
    	url-pattern: /druid/*
    socket-timeout: 300000
    connect-timeout: 300000

再次进行访问测试，问题解决。

解决java.net.SocketTimeoutException: Read timed out异常问题后，An I/O error occurred while sending to this backend.问题随之消失。

六、关于Read timed out、Connect timed out:

  1. “connect timed out” 是在指定时间内TCP连接未创建成功时jdk抛出的异常
  2. “Read timed out”是在调用socketread后，指定时间内未收到响应时 jdk抛出的异常， 假如一个http响应10k, 每次socket read 4k, 那么就需要发起3次read的请求，假如timeout设置3秒，那么就允许每次read都等待3秒，最差的情况就是大概6秒读完数据，当然这得是极端的网络情况， 所以大部分情况下都是客户端发起请求后，在指定时间内收到的服务器的回包响应。

report

Recommend

About Joyk


Aggregate valuable and interesting links.
Joyk means Joy of geeK