frps到frpc连接断开，不能再恢复连接。client error message: reconnect to server error: i/o deadline reached

ghcoba commented 6 years ago

现象：

运行过程中出现frps到frpc的连接断开，frpc在frps上启动的全部连接断开并一直处于offline状态。frps无法再访问frpc。 client端log显示：reconnect to server error: i/o deadline reached. （dashboard可访问，dashboard中显示与client的连接为断开， client为offline。）
在客户端热重载配置后，可恢复frps到frpc的连接。

frpc 客户端 enviroment: 版本 version $ ./frpc -v 0.20.0

操作系统 os $ uname -a FreeBSD st05 11.1-RELEASE-p10 FreeBSD 11.1-RELEASE-p10 #0: Tue May 8 05:21:56 UTC 2018
root@amd64-builder.daemonology.net:/usr/obj/usr/src/sys/GENERIC amd64

(ref: frps 服务器端版本 $ frps -v 0.20.0 操作系统 $ uname -a Linux ss.xxxxx.xxx 2.6.32-042stab124.2 #1 SMP Fri Sep 1 20:42:18 MSK 2017 x86_64 x86_64 x86_64 GNU/Linux )

配置（frpc） Configures you used:

frpc.ini

[common] server_addr = 210.16.xxx.xx server_port = 7000 protocol = kcp admin_addr = 127.0.0.1 admin_port = 7400

log_file = /etc/frp/frpc.log log_level = info log_max_days = 3

pool_count = 5 tcp_mux = true

login_fail_exit = false

[ssh] type = tcp local_ip = 127.0.0.1 local_port = 22 remote_port = 6000 use_encryption = false use_compression = true

[cloud] privilege_mode = true type = http local_port = 4080 remote_port = 80 custom_domains = cloud.xxxxx.xxx use_encryption = false use_compression = true

[p2p_ssh] type = xtcp local_ip = 127.0.0.1 local_port = 22

[svr_http_proxy] type = tcp remote_port = 3080 plugin = http_proxy

------------------ end of frpc.ini 配置（frps） frps.ini

[common] bind_addr = 0.0.0.0 bind_port = 7000

kcp_bind_port = 7000

bind_udp_port = 7001

vhost_http_port = 4080 vhost_https_port = 8443

dashboard_addr = 0.0.0.0 dashboard_port = 7500 dashboard_user = admin dashboard_pwd = adminxxxxx

log_file = /etc/frp/frps.log log_level = info log_max_days = 3

privilege_mode = true allow_ports = 25,110,143,443,465,993,995,3080,3081,4000-90000

heartbeat_timeout = 30

max_pool_count = 50

max_ports_per_client = 0

authentication_timeout = 0

tcp_mux = true ------------------ end of frps.ini

frpc.log - error occured @ 00:41:09

2018/06/12 00:00:16 [I] [control.go:407] [664b8e81b1bcf16b] try to reconnect to server... 2018/06/12 00:00:26 [W] [control.go:410] [664b8e81b1bcf16b] reconnect to server error: i/o deadline$ 2018/06/12 00:00:46 [I] [control.go:407] [664b8e81b1bcf16b] try to reconnect to server... 2018/06/12 00:00:49 [I] [control.go:246] [664b8e81b1bcf16b] login to server success, get run id [66$ 2018/06/12 00:00:49 [I] [control.go:169] [664b8e81b1bcf16b] [ssh] start proxy success 2018/06/12 00:00:49 [I] [control.go:169] [664b8e81b1bcf16b] [cloud] start proxy success 2018/06/12 00:00:49 [I] [control.go:169] [664b8e81b1bcf16b] [p2p_ssh] start proxy success 2018/06/12 00:00:49 [I] [control.go:169] [664b8e81b1bcf16b] [svr_http_proxy] start proxy success 2018/06/12 00:28:06 [E] [control.go:152] [664b8e81b1bcf16b] work connection closed, EOF 2018/06/12 00:28:06 [E] [control.go:152] [664b8e81b1bcf16b] work connection closed, EOF 2018/06/12 00:28:06 [E] [control.go:152] [664b8e81b1bcf16b] work connection closed, EOF 2018/06/12 00:28:06 [I] [control.go:308] [664b8e81b1bcf16b] control writer is closing 2018/06/12 00:28:06 [E] [control.go:152] [664b8e81b1bcf16b] work connection closed, EOF 2018/06/12 00:28:06 [E] [control.go:152] [664b8e81b1bcf16b] work connection closed, EOF 2018/06/12 00:28:06 [I] [control.go:407] [664b8e81b1bcf16b] try to reconnect to server... 2018/06/12 00:28:16 [W] [control.go:410] [664b8e81b1bcf16b] reconnect to server error: i/o deadline$ 2018/06/12 00:28:17 [I] [control.go:407] [664b8e81b1bcf16b] try to reconnect to server... 2018/06/12 00:28:27 [W] [control.go:410] [664b8e81b1bcf16b] reconnect to server error: i/o deadline$ 2018/06/12 00:28:29 [I] [control.go:407] [664b8e81b1bcf16b] try to reconnect to server... 2018/06/12 00:28:39 [W] [control.go:410] [664b8e81b1bcf16b] reconnect to server error: i/o deadline$ ....

2018/06/12 00:30:27 [I] [control.go:407] [664b8e81b1bcf16b] try to reconnect to server... 2018/06/12 00:30:37 [W] [control.go:410] [664b8e81b1bcf16b] reconnect to server error: i/o deadline$ 2018/06/12 00:30:57 [I] [control.go:407] [664b8e81b1bcf16b] try to reconnect to server... 2018/06/12 00:30:57 [I] [control.go:246] [664b8e81b1bcf16b] login to server success, get run id [66$ 2018/06/12 00:30:57 [I] [control.go:169] [664b8e81b1bcf16b] [cloud] start proxy success 2018/06/12 00:30:57 [I] [control.go:169] [664b8e81b1bcf16b] [p2p_ssh] start proxy success 2018/06/12 00:30:57 [I] [control.go:169] [664b8e81b1bcf16b] [svr_http_proxy] start proxy success 2018/06/12 00:30:57 [I] [control.go:169] [664b8e81b1bcf16b] [ssh] start proxy success

error occured. 错误出现的位置time stamp: 00:41:09

2018/06/12 00:41:09 [E] [control.go:152] [664b8e81b1bcf16b] work connection closed, EOF 2018/06/12 00:41:09 [I] [control.go:308] [664b8e81b1bcf16b] control writer is closing 2018/06/12 00:41:09 [E] [control.go:152] [664b8e81b1bcf16b] work connection closed, EOF 2018/06/12 00:41:09 [I] [control.go:407] [664b8e81b1bcf16b] try to reconnect to server... 2018/06/12 00:41:09 [E] [control.go:152] [664b8e81b1bcf16b] work connection closed, EOF 2018/06/12 00:41:09 [E] [control.go:152] [664b8e81b1bcf16b] work connection closed, EOF 2018/06/12 00:41:09 [E] [control.go:152] [664b8e81b1bcf16b] work connection closed, EOF 2018/06/12 00:41:09 [E] [control.go:152] [664b8e81b1bcf16b] work connection closed, EOF 2018/06/12 00:41:19 [W] [control.go:410] [664b8e81b1bcf16b] reconnect to server error: i/o deadline$ 2018/06/12 00:41:20 [I] [control.go:407] [664b8e81b1bcf16b] try to reconnect to server... 2018/06/12 00:41:30 [W] [control.go:410] [664b8e81b1bcf16b] reconnect to server error: i/o deadline$ 2018/06/12 00:41:32 [I] [control.go:407] [664b8e81b1bcf16b] try to reconnect to server... 2018/06/12 00:41:42 [W] [control.go:410] [664b8e81b1bcf16b] reconnect to server error: i/o deadline$ 2018/06/12 00:41:46 [I] [control.go:407] [664b8e81b1bcf16b] try to reconnect to server... 2018/06/12 00:41:56 [W] [control.go:410] [664b8e81b1bcf16b] reconnect to server error: i/o deadline$ 2018/06/12 00:42:04 [I] [control.go:407] [664b8e81b1bcf16b] try to reconnect to server... 2018/06/12 00:42:14 [W] [control.go:410] [664b8e81b1bcf16b] reconnect to server error: i/o deadline$ ......

2018/06/12 00:54:11 [W] [control.go:410] [664b8e81b1bcf16b] reconnect to server error: i/o deadline$ 2018/06/12 00:54:31 [I] [control.go:407] [664b8e81b1bcf16b] try to reconnect to server... 2018/06/12 00:54:41 [W] [control.go:410] [664b8e81b1bcf16b] reconnect to server error: i/o deadline$ 2018/06/12 00:55:01 [I] [control.go:407] [664b8e81b1bcf16b] try to reconnect to server... 2018/06/12 00:55:11 [W] [control.go:410] [664b8e81b1bcf16b] reconnect to server error: i/o deadline$ 2018/06/12 00:55:31 [I] [control.go:407] [664b8e81b1bcf16b] try to reconnect to server... 2018/06/12 00:55:41 [W] [control.go:410] [664b8e81b1bcf16b] reconnect to server error: i/o deadline$ 2018/06/12 00:56:01 [I] [control.go:407] [664b8e81b1bcf16b] try to reconnect to server... 2018/06/12 00:56:11 [W] [control.go:410] [664b8e81b1bcf16b] reconnect to server error: i/o deadline$ ---- end frpc.log

frps.log

2018/06/12 00:40:31 [I] [proxy.go:87] [664b8e81b1bcf16b] [cloud] get a new work connection: [120.22$ 2018/06/12 00:40:36 [I] [proxy.go:87] [664b8e81b1bcf16b] [cloud] get a new work connection: [120.22$ 2018/06/12 00:40:37 [I] [proxy.go:87] [664b8e81b1bcf16b] [cloud] get a new work connection: [120.22$ 2018/06/12 00:40:41 [I] [proxy.go:87] [664b8e81b1bcf16b] [cloud] get a new work connection: [120.22$ 2018/06/12 00:40:45 [I] [proxy.go:87] [664b8e81b1bcf16b] [cloud] get a new work connection: [120.22$ 2018/06/12 00:41:01 [I] [proxy.go:87] [664b8e81b1bcf16b] [cloud] get a new work connection: [120.22$

error occure 错误出现的位置 time 00:41:09 - lose connection

2018/06/12 00:41:09 [I] [control.go:220] [664b8e81b1bcf16b] control writer is closing 2018/06/12 00:41:09 [I] [proxy.go:73] [664b8e81b1bcf16b] [svr_http_proxy] proxy closing 2018/06/12 00:41:09 [I] [proxy.go:73] [664b8e81b1bcf16b] [ssh] proxy closing 2018/06/12 00:41:09 [I] [proxy.go:73] [664b8e81b1bcf16b] [cloud] proxy closing 2018/06/12 00:41:09 [I] [proxy.go:73] [664b8e81b1bcf16b] [p2p_ssh] proxy closing 2018/06/12 00:41:09 [I] [control.go:292] [664b8e81b1bcf16b] client exit success 2018/06/12 00:41:09 [I] [proxy.go:119] [664b8e81b1bcf16b] [ssh] listener is closed 2018/06/12 00:41:09 [W] [newhttp.go:202] http: proxy error: EOF 2018/06/12 00:41:09 [I] [proxy.go:119] [664b8e81b1bcf16b] [svr_http_proxy] listener is closed 2018/06/12 00:41:09 [W] [newhttp.go:202] http: proxy error: EOF 2018/06/12 00:41:29 [W] [newhttp.go:202] http: proxy error: no such domain 2018/06/12 00:41:30 [W] [newhttp.go:202] http: proxy error: no such domain 2018/06/12 00:41:35 [W] [newhttp.go:202] http: proxy error: no such domain 2018/06/12 00:41:48 [W] [newhttp.go:202] http: proxy error: no such domain 2018/06/12 00:43:51 [I] [dashboard_api.go:67] Http request: [/api/serverinfo] 2018/06/12 00:43:51 [I] [dashboard_api.go:64] Http response [/api/serverinfo]: code [0] 2018/06/12 00:43:59 [I] [dashboard_api.go:178] Http request: [/api/proxy/tcp] 2018/06/12 00:43:59 [I] [dashboard_api.go:174] Http response [/api/proxy/tcp]: code [0] 2018/06/12 00:43:59 [I] [dashboard_api.go:175] /api/proxy/tcp 2018/06/12 00:43:59 [I] [dashboard_api.go:176] 2018/06/12 00:49:50 [I] [dashboard_api.go:178] Http request: [/api/proxy/tcp] 2018/06/12 00:49:50 [I] [dashboard_api.go:174] Http response [/api/proxy/tcp]: code [0] 2018/06/12 00:49:50 [I] [dashboard_api.go:175] /api/proxy/tcp 2018/06/12 00:49:50 [I] [dashboard_api.go:176] --- end frps.log

dashboard message about error:

Name cloud Type http Domains[ "cloud.xxxx.xxx" ] SubDomain locations[ "" ] Host Rewrite Encryption false Compression true Last Start06-12 00:58:01 (在客户端进行热重载配置后重新启动的连接) Last Close06-12 00:41:09 （发生错误的时间。连接断开。从服务器端无法访问frpc端） --- end dashboard message

Steps to reproduce the issue: 有时会出现连接断开，无法再从服务器端访问到frpc。（但是可以访问服务端的dashboard，dashboard显示与client的连接为断开， client为offline。）

Describe the results you received:

运行过程中出现frps到frpc的连接断开，frpc在frps上启动的全部连接断开并一直处于offline状态。frps无法再访问frpc。 client端log显示：reconnect to server error: i/o deadline reached.
在客户端热重载配置后，可恢复frps到frpc的连接。

注：在客户端重启frpc后，可以建立连接，恢复从服务器端访问客户端。（使用 frpc reload -c ./frpc.ini）

Describe the results you expected: (预期正确的结果为不出现frps到frpc的连接断开的情况)

Additional information you deem important (e.g. issue happens only occasionally): ( 此故障有时出现，不出现问题时很长时间都工作正常。未发现重现此故障的方法。

相关配置：

服务器端： OS- centos, VPS。安装有 shadowsocks-libev server, nginx web server to forward 80/443 port traffic to local 4080 and encapsulated through kcp using 7000 port to connect with remote frpc client.
远端客户端：OS-freebsd 11.1。安装有nginx/php-fpm/postgresql/php-app-server. )

Can you point out what caused this issue (optional) (可能是frpc端的问题。热重载frpc.ini配置后可恢复工作（frps端不做处理的情况下）)

fatedier commented 6 years ago

重连超时了，还是检查下网络环境了，网络问题可能比较复杂。

ghcoba commented 6 years ago

在trace记录中一直会出现“join connections closed”，这个是程序在作什么动作？

--- frpc.log (log_level = trace ) -- 2018/06/13 22:03:34 [D] [proxy_manager.go:135] [cloud] start a new work connection, localAddr: 10.0.0.9:58981 remoteAddr: 210.16.120.37:70$ 2018/06/13 22:03:34 [D] [proxy.go:450] [cloud] join connections, localConn(l[127.0.0.1:47587] r[127.0.0.1:4080]) workConn(l[10.0.0.9:58981$ 2018/06/13 22:03:34 [D] [proxy.go:453] [cloud] join connections closed 2018/06/13 22:03:35 [D] [proxy_manager.go:135] [cloud] start a new work connection, localAddr: 10.0.0.9:58981 remoteAddr: 210.16.120.37:70$ 2018/06/13 22:03:35 [D] [proxy.go:450] [cloud] join connections, localConn(l[127.0.0.1:23955] r[127.0.0.1:4080]) workConn(l[10.0.0.9:58981$ 2018/06/13 22:03:35 [D] [proxy.go:453] [cloud] join connections closed 2018/06/13 22:03:36 [D] [proxy_manager.go:135] [cloud] start a new work connection, localAddr: 10.0.0.9:58981 remoteAddr: 210.16.120.37:70$ 2018/06/13 22:03:36 [D] [proxy.go:450] [cloud] join connections, localConn(l[127.0.0.1:43938] r[127.0.0.1:4080]) workConn(l[10.0.0.9:58981$ 2018/06/13 22:03:36 [D] [proxy.go:453] [cloud] join connections closed 2018/06/13 22:03:56 [D] [control.go:340] [e8d56b95b222c004] send heartbeat to server 2018/06/13 22:03:56 [D] [control.go:361] [e8d56b95b222c004] receive heartbeat from server 2018/06/13 22:04:02 [D] [proxy_manager.go:135] [cloud] start a new work connection, localAddr: 10.0.0.9:58981 remoteAddr: 210.16.120.37:70$ 2018/06/13 22:04:02 [D] [proxy.go:450] [cloud] join connections, localConn(l[127.0.0.1:56835] r[127.0.0.1:4080]) workConn(l[10.0.0.9:58981$ 2018/06/13 22:04:02 [D] [proxy.go:453] [cloud] join connections closed 2018/06/13 22:04:26 [D] [control.go:340] [e8d56b95b222c004] send heartbeat to server 2018/06/13 22:04:26 [D] [control.go:361] [e8d56b95b222c004] receive heartbeat from server 2018/06/13 22:04:28 [D] [proxy_manager.go:135] [cloud] start a new work connection, localAddr: 10.0.0.9:58981 remoteAddr: 210.16.120.37:70$ 2018/06/13 22:04:28 [D] [proxy.go:450] [cloud] join connections, localConn(l[127.0.0.1:59070] r[127.0.0.1:4080]) workConn(l[10.0.0.9:58981$ 2018/06/13 22:04:28 [D] [proxy.go:453] [cloud] join connections closed 2018/06/13 22:04:56 [D] [control.go:340] [e8d56b95b222c004] send heartbeat to server 2018/06/13 22:04:56 [D] [control.go:361] [e8d56b95b222c004] receive heartbeat from server 2018/06/13 22:04:58 [D] [proxy_manager.go:135] [cloud] start a new work connection, localAddr: 10.0.0.9:58981 remoteAddr: 210.16.120.37:70$ 2018/06/13 22:04:58 [D] [proxy.go:450] [cloud] join connections, localConn(l[127.0.0.1:25133] r[127.0.0.1:4080]) workConn(l[10.0.0.9:58981$ 2018/06/13 22:04:58 [D] [proxy.go:453] [cloud] join connections closed 2018/06/13 22:05:26 [D] [control.go:340] [e8d56b95b222c004] send heartbeat to server 2018/06/13 22:05:26 [D] [control.go:361] [e8d56b95b222c004] receive heartbeat from server 2018/06/13 22:05:28 [D] [proxy_manager.go:135] [cloud] start a new work connection, localAddr: 10.0.0.9:58981 remoteAddr: 210.16.120.37:70$ 2018/06/13 22:05:28 [D] [proxy.go:450] [cloud] join connections, localConn(l[127.0.0.1:44651] r[127.0.0.1:4080]) workConn(l[10.0.0.9:58981$ 2018/06/13 22:05:28 [D] [proxy.go:453] [cloud] join connections closed

ghcoba commented 6 years ago

(re-open)

fatedier commented 6 years ago

这个从内容中应该就能看出来，记录了每一次 frpc 相关连接的建立和断开。

ghcoba commented 6 years ago

谢谢。我再观察一段时间网络情况。我先关闭这个issue。

lin2code commented 6 years ago

你是用的腾讯云吗我也是这样，不定时会有几分钟连不上。用阿里云一晚上都稳的，腾讯云出现两次大概

john-shine commented 5 years ago

看是不是路由器开启了透明代理

RayXu14 commented 4 years ago

请问什么是热重载配置

Waterkin commented 2 years ago

同有这个问题，用的是腾讯云报错信息： control writer is closing proxy closing listener is closed: accept tcp [::]:6000: use of closed network connection client exit success