使用外网地址大于20分钟的定时任务从第二次开始就Operation timed out #35

zhugw · 2017-11-12T09:01:30Z

局域网内有一个MongoDB服务

192.168.0.12:40000

使用lanproxy映射到外网项目中改用外网地址后 21分钟的定时任务第一次执行成功后面就执行失败了

# 第一次
[extractScheduler-1] driver.connection - Opened connection [connectionId{localValue:2, serverValue:1462175}] to 120.27.XXX.XXX:40000

# 第二次
[extractScheduler-1] driver.connection - Got socket exception on connection [connectionId{localValue:2, serverValue:1462175}] to 120.27.XXX.XXX:40000. All connections to 120.27.XXX.XXX:40000 will be closed.
[extractScheduler-1] driver.connection - Closed connection [connectionId{localValue:2, serverValue:1462175}] to 120.27.XXX.XXX:40000 because there was a socket exception raised by this connection.    

# 之后都是类似的错误

错误日志

Caused by: java.net.SocketException: Operation timed out
	at java.net.SocketInputStream.socketRead0(Native Method)
	at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)

wireshark抓包

如果使用内网地址的话就没有这个问题
如果使用外网地址但定时任务间隔时间小于20分钟的话也没问题

所以我现在怀疑是lanproxy的问题能不能帮忙确认一下？

The text was updated successfully, but these errors were encountered:

ffay · 2017-11-13T01:22:16Z

上一个版本设置的是20分钟连接没有活动就会移除，新版本已去除，可以下最新的发布包试试

zhugw · 2017-11-14T01:27:26Z

怎么更新后感觉不好使了呢？

git pull origin master
mvn clean package
cd distribution/proxys-server-0.1/
bin/stop.sh
bin/startup.sh

# 客户端一样的操作

等全部更新完后反而内网穿透不灵了呢？
服务端日志

2017-11-14 00:32:02,870 WARN [io.netty.channel.DefaultChannelPipeline] - <An exceptionCaught() event was fired, and it reached at the tail of the pipeline. It usually means the last handler in the pipeline did not handle the exception.>
java.io.IOException: Connection timed out
	at sun.nio.ch.FileDispatcherImpl.read0(Native Method)
	at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)
	at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)

2017-11-14 00:32:02,874 WARN [org.fengfei.lanproxy.server.ProxyChannelManager] - <channel closed, clear user channels, [id: 0xc643590a, L:/120.27.XXX.XXX:4900 ! R:/211.157.174.63:53718]>
2017-11-14 00:32:02,877 INFO [org.fengfei.lanproxy.server.ProxyChannelManager] - <disconnect user channel [id: 0x32e9b4a7, L:/120.27.XXX.XXX:9300 - R:/39.107.14.208:36370]>


2017-11-14 11:49:49,997 ERROR [org.fengfei.lanproxy.server.handlers.ServerChannelHandler] - <exception caught>
io.netty.handler.codec.TooLongFrameException: Adjusted frame length exceeds 2097152: 218785148 - discarded
	at io.netty.handler.codec.LengthFieldBasedFrameDecoder.fail(LengthFieldBasedFrameDecoder.java:499)

客户端日志

2017-11-13 22:42:06,573 WARN [org.fengfei.lanproxy.client.ProxyClientContainer] - <connect proxy server failed>
java.net.ConnectException: Connection refused: /120.27.XXX.XXX:4900
	at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
	at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:717)



2017-11-14 06:58:11,257 WARN [io.netty.channel.DefaultChannelPipeline] - <An exceptionCaught() event was fired, and it reached at the tail of the pipeline. It usually means the last handler in the pipeline did not handle the exception.>
java.io.IOException: Connection timed out
	at sun.nio.ch.FileDispatcherImpl.read0(Native Method)
	at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)

ffay · 2017-11-14T06:39:21Z

把之前的清理下重新启动，如果还有问题把server和client的启动日志发出来看看

zhugw · 2017-11-15T13:48:26Z

但是怎么清理呢？我试了下面的方案都不行

mvn clean 【单单clean】
rm -rf distribution && mvn clean 【删除distribution包后再clean】
rm -rf lanproxy && rm -f ~/.lanproxy/config.json && git clone XXX 【删除已下载的lanproxy包重新clone 同时删除已配置的客户端连接】

运行了一段时间后（大概一个小时多） proxy server 就有下面的错误

2017-11-15 11:22:19,297 ERROR [org.fengfei.lanproxy.server.handlers.ServerChannelHandler] - <exception caught>
java.io.IOException: Connection timed out
        at sun.nio.ch.FileDispatcherImpl.read0(Native Method)
        at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)
        at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)
        at sun.nio.ch.IOUtil.read(IOUtil.java:192)
        at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380)
        at io.netty.buffer.UnpooledUnsafeDirectByteBuf.setBytes(UnpooledUnsafeDirectByteBuf.java:357)
        at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:898)
        at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:242)
        at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:119)
        at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:528)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:485)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:399)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:371)
        at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
        at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:137)
        at java.lang.Thread.run(Thread.java:748)
2017-11-15 11:22:19,299 WARN [io.netty.channel.DefaultChannelPipeline] - <An exceptionCaught() event was fired, and it reached at the tail of the pipeline. It usually means the last handler in the pipeline did not handle the exception.>
java.io.IOException: Connection timed out
        at sun.nio.ch.FileDispatcherImpl.read0(Native Method)
        at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)
        at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)
        at sun.nio.ch.IOUtil.read(IOUtil.java:192)
        at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380)
        at io.netty.buffer.UnpooledUnsafeDirectByteBuf.setBytes(UnpooledUnsafeDirectByteBuf.java:357)
        at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:898)
        at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:242)
        at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:119)
        at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:528)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:485)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:399)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:371)
        at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
        at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:137)
        at java.lang.Thread.run(Thread.java:748)

有些proxy-client节点上有错误日志有些没有 proxy-client错误日志

017-11-15 18:34:31,481 ERROR [org.fengfei.lanproxy.client.handlers.ClientChannelHandler] - <exception caught>
java.io.IOException: Connection timed out
        at sun.nio.ch.FileDispatcherImpl.read0(Native Method)
        at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)
        at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)
        at sun.nio.ch.IOUtil.read(IOUtil.java:192)
        at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380)
        at io.netty.buffer.UnpooledUnsafeDirectByteBuf.setBytes(UnpooledUnsafeDirectByteBuf.java:357)
        at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:898)
        at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:242)
        at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:119)
        at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:528)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:485)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:399)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:371)
        at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)

另外虽然proxy-server 和 proxy-clients的进程都在但是管理界面上status都是Down的状态。

反正这个问题是升级后才开始有的不确定是代码的问题还是我的网络的问题如外网ip变化会有影响吗？因为我看server.log中有好几个外网地址

R:/211.157.XXX.XX:15848

R:/60.205.XXX.XX:64952

R:/140.205.XXX.XXX:55054

proxy-client 刚连接上的时候都是211这个地址但是后面也发现有很多60的地址以及一个140的地址

ffay · 2017-11-15T14:43:19Z

客户端和服务器用最新的代码，可以直接下载最新的发布包，再就是使用ssl 端口连接，不用明文端口
另外看看你用的mongodb客户端连接池有没有配置发送心跳包的功能，网络连接一个小时没有任何数据传输基本上已经被运营商中间路由移除了

zhugw · 2017-11-16T01:16:47Z

mongo有没有发送心跳包我不确定但是mysql肯定有

spring.datasource.test-while-idle=true
spring.datasource.time-between-eviction-runs-millis=30000
spring.datasource.validation-query=select 1

那为什么mysql所在的proxy client机器也是Down的状态呢？并且mongo和tomcat的client.log都没有异常日志单单mysql 的client.log有异常日志呢？（相隔了有8个小时多）

2017-11-15 10:12:21,399 INFO [org.fengfei.lanproxy.client.ProxyClientContainer] - <connect proxy server success, [id: 0x1b259c66, L:/192.168.0.25:36412 - R:/120.27.XXX.XXX:4900]>
2017-11-15 18:34:31,481 ERROR [org.fengfei.lanproxy.client.handlers.ClientChannelHandler] - <exception caught>
java.io.IOException: Connection timed out
        at sun.nio.ch.FileDispatcherImpl.read0(Native Method)
        at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)
        at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)
        at sun.nio.ch.IOUtil.read(IOUtil.java:192)
        at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380)
        at io.netty.buffer.UnpooledUnsafeDirectByteBuf.setBytes(UnpooledUnsafeDirectByteBuf.java:357)
        at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:898)
        at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:242)
        at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:119)
        at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:528)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:485)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:399)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:371)
        at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)

ffay · 2017-11-16T10:03:05Z

针对你这种情况做了些优化，可以再试试

zhugw · 2017-11-17T11:21:21Z

今天上午更新代码后又观察了一天好像恢复正常了如 mongo shell连上后若长时间没有操作能够自动恢复连接如下所示

> show collections
2017-11-17T19:12:14.204+0800 I NETWORK  [thread1] trying reconnect to 120.27.XXX.XXX:27017 (120.27.XXX.XXX) failed
2017-11-17T19:12:14.363+0800 I NETWORK  [thread1] reconnect 120.27.XXX.XXX:27017 (120.27.XXX.XXX) ok

mysql也一样

mysql> select version();
ERROR 2006 (HY000): MySQL server has gone away
No connection. Trying to reconnect...
Connection id:    203543
Current database: *** NONE ***

但是服务端仍发现了一些异常日志虽然不影响功能

2017-11-17 11:34:32,344 WARN [io.netty.channel.DefaultChannelPipeline] - <An exceptionCaught() event was fired, and it reached at the tail of the pipeline. It usually means the last handler in the pipeline did not handle the exception.>
java.io.IOException: Connection reset by peer
	at sun.nio.ch.FileDispatcherImpl.read0(Native Method)
	at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)

2017-11-17 14:05:55,353 WARN [io.netty.channel.DefaultChannelPipeline] - <An exceptionCaught() event was fired, and it reached at the tail of the pipeline. It usually means the last handler in the pipeline did not handle the exception.>
io.netty.handler.codec.TooLongFrameException: Adjusted frame length exceeds 2097152: 1195725860 - discarded
	at io.netty.handler.codec.LengthFieldBasedFrameDecoder.fail(LengthFieldBasedFrameDecoder.java:499)

ffay · 2017-11-18T04:55:45Z

最后那个异常我这也再观察下，很难重现，你那边如果找到了重现的方法也请告知一下

zhugw · 2017-11-18T08:41:21Z

刚看了下今天的日志又有TooLongFrameException

2017-11-18 04:15:38,698 WARN [io.netty.channel.DefaultChannelPipeline] - <An exceptionCaught() event was fired, and it reached at the tail of the pipeline. It usually means the last handler in the pipeline did not handle the exception.>
java.io.IOException: Connection reset by peer
	at sun.nio.ch.FileDispatcherImpl.read0(Native Method)


2017-11-18 14:33:52,180 ERROR [org.fengfei.lanproxy.server.handlers.ServerChannelHandler] - <exception caught>
io.netty.handler.codec.TooLongFrameException: Adjusted frame length exceeds 2097152: 1195725860 - discarded
	at io.netty.handler.codec.LengthFieldBasedFrameDecoder.fail(LengthFieldBasedFrameDecoder.java:499)

2017-11-18 14:33:52,181 WARN [io.netty.channel.DefaultChannelPipeline] - <An exceptionCaught() event was fired, and it reached at the tail of the pipeline. It usually means the last handler in the pipeline did not handle the exception.>
io.netty.handler.codec.TooLongFrameException: Adjusted frame length exceeds 2097152: 1195725860 - discarded
	at io.netty.handler.codec.LengthFieldBasedFrameDecoder.fail(LengthFieldBasedFrameDecoder.java:499)

我这边没做什么就是新开了一个终端 mongo shell 和 mysql client都连上了而已

ffay · 2017-11-18T11:07:05Z

TooLongFrameException 这个异常是正常的，不用管，是有人用浏览器访问了proxyserver的端口

zhugw closed this as completed Nov 20, 2017

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

使用外网地址大于20分钟的定时任务从第二次开始就Operation timed out #35

使用外网地址大于20分钟的定时任务从第二次开始就Operation timed out #35

zhugw commented Nov 12, 2017

ffay commented Nov 13, 2017

zhugw commented Nov 14, 2017 •

edited

Loading

ffay commented Nov 14, 2017 •

edited

Loading

zhugw commented Nov 15, 2017

ffay commented Nov 15, 2017

zhugw commented Nov 16, 2017

ffay commented Nov 16, 2017

zhugw commented Nov 17, 2017

ffay commented Nov 18, 2017

zhugw commented Nov 18, 2017

ffay commented Nov 18, 2017

使用外网地址 大于20分钟的定时任务从第二次开始就Operation timed out #35

使用外网地址 大于20分钟的定时任务从第二次开始就Operation timed out #35

Comments

zhugw commented Nov 12, 2017

ffay commented Nov 13, 2017

zhugw commented Nov 14, 2017 • edited Loading

ffay commented Nov 14, 2017 • edited Loading

zhugw commented Nov 15, 2017

ffay commented Nov 15, 2017

zhugw commented Nov 16, 2017

ffay commented Nov 16, 2017

zhugw commented Nov 17, 2017

ffay commented Nov 18, 2017

zhugw commented Nov 18, 2017

ffay commented Nov 18, 2017

使用外网地址大于20分钟的定时任务从第二次开始就Operation timed out #35

使用外网地址大于20分钟的定时任务从第二次开始就Operation timed out #35

zhugw commented Nov 14, 2017 •

edited

Loading

ffay commented Nov 14, 2017 •

edited

Loading