proxyman/inbound/udpWorker在部分场景中会不断重复断开、建立链接

[Ovear]

你正在使用哪个版本的 V2Ray？

V2Ray 4.42.2 (V2Fly, a community-driven edition of V2Ray.) Custom (go1.17.1 linux/amd64)

你的使用场景是什么？

使用任意门映射远端UDP端口，本地和任意门监听的端口进行UDP通信。

你看到的异常现象是什么？

现象

在使用V2ray任意门代理udp链接的过程中，发现偶尔会出现本地到v2ray的udp链接没断开的情况下（udp src port 和 dst port均未发生变化），nginx一直报upstream timed out (110: Connection timed out) while proxying upgraded connection错误，同时v2ray也一直报错并重新建立链接（见下日志）。但是实际的udp链接除了产生较大的延迟波动外（切换链接时），收发功能看起来是正常的。

根据Nginx官方的描述：WebSocket proxying，如果websocket持续proxy_read_timeout（默认60秒）未交换任何数据，就会被nginx关闭链接，所以会产生上面的upstream timed out错误。

By default, the connection will be closed if the proxied server does not transmit any data within 60 seconds. This timeout can be increased with the proxy_read_timeout directive.

分析

经过分析日志后，发现v2ray对于同一条udp链接建立了多个链接，但是同时只使用了其中1个链接，导致其他链接空闲并被nginx关闭。但是在关闭的同时，又建立多一条链接，此时活跃的链接会切换，导致其他链接空闲被nginx关闭，重复循环。（见下日志）

在阅读源码后，发现了可能导致这个问题的原因：

udpWorker存在如下逻辑：
1.当存在活动链接时，udpWork会隔16秒，将超过8秒没有活动的链接，移出活动链接。其中8秒和16秒的两个数值，均是hardcore到代码中。[计时器代码] [移除活动链接代码]

2.当链接（包含本地的UDP链接和与远程v2ray服务端的链接）结束/发生异常时，在关闭链接的时候，不管有没有被clean调度器移出过，移出活动链接。[代码]

场景还原

这样就会出现以下的问题场景：
1.因为某些原因，导致v2ray未更新udp链接的活跃时间，可能原因如下

• 链接真的空闲了8秒。
• 网络异常导致的缓冲区满，无法处理数据。即便本地的UDP链接可能还是在向v2ray发送数据。

2.UDP链接被clean调度器移出活动链接
3.V2ray收到UDP数据（udp src port 和 dst port 未发生变化）2-3的时间可以很短，只要在物理链接被关闭之前发生，都可以
4.V2ray建立新UDP链接，并加入到活动链接表，并将数据交给任意门处理，此时建立了一条新的服务端链路来承载原先的UDP链接
5.原先的V2ray客户端与服务端之间的链接断开（任何原因都可以，包括nginx断开，tcp超时异常关闭等）
6.UDP链接被V2ray移出活动链接 --- 回到3，开始循环

最坏的情况下，如果链接的持续时间比较长，多次被clean调度器移出，可能产生多个承载链接。（目前观测到同时存在过3个）

解决方案

这个问题的根本原因是因为V2ray对同一个链接（V2ray目前认为在协议一致的情况下，只要UDP src ip/port 和 dst ip/port 一样，就是一个同一个链接），多次从活跃链接中移出。[代码]

所以需要在移出之前判断一下，若该链接已经被clean调度器移出过活跃链接表，在链接断开/发生错误的时候，就不需要再次从活动链接表移出了。

由于不熟悉V2ray的代码，所以就没直接提交PR，晚点试着修复下看看。考虑在udpConn结构体中，增加一个标志记录是否已经被clean调度器清除过了。

你期待看到的正常表现是怎样的？

重新建立承载链接后，原承载链接断开后，不重复把UDP链接移出活动链接表，承载链接切换不会循环进行。

请附上你的配置

客户端配置：

// 任意门配置
        "inbounds": [
            {
                "tag": "udp",
                "port": 443,
                "protocol": "dokodemo-door",
                "settings": {
                    "address": "1.1.1.1",
                    "port": 443,
                    "network": "udp",
                    "userLevel": 1
                }
            }
        ]

请附上出错时软件输出的错误日志

客户端错误日志：

// 核心错误日志（经过重新排序）
2021/09/26 08:07:53 [Debug] [336985752] proxy/dokodemo: processing connection from: 127.0.0.1:11111
2021/09/26 08:47:58 [Info] [336985752] app/proxyman/outbound: failed to process outbound traffic > proxy/vmess/outbound: connection ends > context canceled
2021/09/26 08:47:58 [Info] [336985752] app/proxyman/inbound: connection ends > proxy/dokodemo: connection ends > proxy/dokodemo: failed to transport response > io: read/write on closed pipe

2021/09/26 08:42:49 [Debug] [3463437710] proxy/dokodemo: processing connection from: 127.0.0.1:11111
2021/09/26 08:52:54 [Info] [3463437710] app/proxyman/outbound: failed to process outbound traffic > proxy/vmess/outbound: connection ends > context canceled
2021/09/26 08:52:54 [Info] [3463437710] app/proxyman/inbound: connection ends > proxy/dokodemo: connection ends > proxy/dokodemo: failed to transport response > io: read/write on closed pipe

2021/09/26 08:44:57 [Debug] [2370373823] proxy/dokodemo: processing connection from: 127.0.0.1:11111
2021/09/26 08:48:59 [Info] [2370373823] app/proxyman/outbound: failed to process outbound traffic > proxy/vmess/outbound: connection ends > websocket: close 1006 (abnormal closure): unexpected EOF
2021/09/26 08:48:59 [Info] [2370373823] app/proxyman/inbound: connection ends > proxy/dokodemo: connection ends > proxy/dokodemo: failed to transport response > io: read/write on closed pipe

2021/09/26 08:47:59 [Debug] [2657297962] proxy/dokodemo: processing connection from: 127.0.0.1:11111
2021/09/26 08:49:59 [Info] [2657297962] app/proxyman/outbound: failed to process outbound traffic > proxy/vmess/outbound: connection ends > websocket: close 1006 (abnormal closure): unexpected EOF
2021/09/26 08:49:59 [Info] [2657297962] app/proxyman/inbound: connection ends > proxy/dokodemo: connection ends > proxy/dokodemo: failed to transport response > io: read/write on closed pipe

2021/09/26 08:48:59 [Debug] [409420199] proxy/dokodemo: processing connection from: 127.0.0.1:11111
2021/09/26 08:50:59 [Info] [409420199] app/proxyman/outbound: failed to process outbound traffic > proxy/vmess/outbound: connection ends > websocket: close 1006 (abnormal closure): unexpected EOF
2021/09/26 08:50:59 [Info] [409420199] app/proxyman/inbound: connection ends > proxy/dokodemo: connection ends > proxy/dokodemo: failed to transport response > io: read/write on closed pipe

2021/09/26 08:49:59 [Debug] [3480422443] proxy/dokodemo: processing connection from: 127.0.0.1:11111
2021/09/26 08:51:59 [Info] [3480422443] app/proxyman/outbound: failed to process outbound traffic > proxy/vmess/outbound: connection ends > websocket: close 1006 (abnormal closure): unexpected EOF
2021/09/26 08:51:59 [Info] [3480422443] app/proxyman/inbound: connection ends > proxy/dokodemo: connection ends > proxy/dokodemo: failed to transport response > io: read/write on closed pipe

2021/09/26 08:50:59 [Debug] [11928109] proxy/dokodemo: processing connection from: 127.0.0.1:11111
2021/09/26 08:53:04 [Info] [11928109] app/proxyman/outbound: failed to process outbound traffic > proxy/vmess/outbound: connection ends > websocket: close 1006 (abnormal closure): unexpected EOF
2021/09/26 08:53:04 [Info] [11928109] app/proxyman/inbound: connection ends > proxy/dokodemo: connection ends > proxy/dokodemo: failed to transport response > io: read/write on closed pipe

2021/09/26 08:51:59 [Debug] [4120034857] proxy/dokodemo: processing connection from: 127.0.0.1:11111
2021/09/26 08:54:13 [Info] [4120034857] app/proxyman/outbound: failed to process outbound traffic > proxy/vmess/outbound: connection ends > websocket: close 1006 (abnormal closure): unexpected EOF
2021/09/26 08:54:13 [Info] [4120034857] app/proxyman/inbound: connection ends > proxy/dokodemo: connection ends > proxy/dokodemo: failed to transport response > io: read/write on closed pipe

2021/09/26 08:52:54 [Debug] [380371711] proxy/dokodemo: processing connection from: 127.0.0.1:11111
2021/09/26 08:53:10 [Info] [380371711] app/proxyman/outbound: failed to process outbound traffic > proxy/vmess/outbound: connection ends > transport/internet/websocket: Unable to proceed with delayed write > transport/internet/websocket: failed to dial to (wss://1.1.1.1:1111/aaa) with early data:  > dial tcp 1.1.1.1:1111: i/o timeout
2021/09/26 08:53:10 [Info] [380371711] app/proxyman/inbound: connection ends > proxy/dokodemo: connection ends > proxy/dokodemo: failed to transport response > io: read/write on closed pipe

[Ovear]

闲下来了，尝试修复一下试试，明天看看还会不会有问题。

https://github.com/ovear/v2ray-core/tree/fix-udp-double-remove-conn

[xiaokangwang]

从我的角度来看这个问题主要V2的UDP超时时间过短且无法设置，导致实际上还处于活跃状态的连接被关闭。我不太清楚对于服务器端来说，8秒后断开连接之后，由服务器再建立的连接还是不是同一个连接，所以感觉还需要再继续研究一下。如果同一个连接会被从另一个源地址发出的话，那就是另一个问题了。

[Ovear]

从我的角度来看这个问题主要V2的UDP超时时间过短且无法设置，导致实际上还处于活跃状态的连接被关闭。我不太清楚对于服务器端来说，8秒后断开连接之后，由服务器再建立的连接还是不是同一个连接，所以感觉还需要再继续研究一下。如果同一个连接会被从另一个源地址发出的话，那就是另一个问题了。

其实这个也有一部分原因，建立或者不建立新的链接其实是服务端行为，V2本身支持多种outbound，所以这个理论上是没有保证的，如果实现的相同链接的链接复用算是一种enhancement。

不过以上说的其实是另外一个问题，本次的问题还是在于v2重复将链接移除的问题，因为链接超时导致v2将本地到任意门的老的链接视为新建立的udp链接，这个行为是没问题的。但是在承载老udp链接关闭时，同时将新的udp链接关闭，这个行为是应该避免的。

[Ovear]

当然对于第一个问题，作为补充gost对于这种情况的做法是将其分为两个协议，即端口转发模式和隧道模式。
在隧道模式下，服务端到目标将会使用同一udp链接（即udp src port/ip始终保持一致）
而在端口转发模式下，服务端到目标不再保证上述行为，对于建立的新连接，服务器会对应建立一条新的链接。

[Ovear]

看了一下日志，这个问题的原因和猜测的一样，之前的修改确认解决了这个问题。

# 连接1建立
2021/09/27 08:21:06 [Debug] [430093377] proxy/dokodemo: processing connection from: 127.0.0.1:29892
2021/09/27 08:21:06 [Info] [430093377] proxy/dokodemo: received request for 127.0.0.1:29892
2021/09/27 08:21:06 [Info] [430093377] app/dispatcher: default route for udp:1.1.1.1:1111
2021/09/27 08:21:06 127.0.0.1:29892 accepted udp:1.1.1.1:1111
2021/09/27 08:21:06 [Info] [430093377] transport/internet/websocket: creating connection to tcp:2.2.2.2:2222
2021/09/27 08:21:06 [Info] [430093377] proxy/vmess/outbound: tunneling request to udp:1.1.1.1:1111 via tcp:2.2.2.2:2222
# 连接1被checker移除
2021/09/27 08:57:54 [Debug] app/proxyman/inbound: checker remove conn: &{lastActivityTime:1632704257 reader:0xc00009b720 writer:0xc00009b728 output:0x831700 remote:0xc00ne:0xc00105a9f0 uplink:<nil> downlink:<nil> inactive:true}

# 连接2建立
2021/09/27 08:57:54 [Debug] [2735844648] proxy/dokodemo: processing connection from: 127.0.0.1:29892
2021/09/27 08:57:54 [Info] [2735844648] proxy/dokodemo: received request for 127.0.0.1:29892
2021/09/27 08:57:54 [Info] [2735844648] app/dispatcher: default route for udp:1.1.1.1:1111
2021/09/27 08:57:54 [Info] [2735844648] transport/internet/websocket: creating connection to tcp:2.2.2.2:2222
2021/09/27 08:57:54 [Info] [2735844648] proxy/vmess/outbound: tunneling request to udp:1.1.1.1:1111 via tcp:2.2.2.2:2222
2021/09/27 08:57:54 127.0.0.1:29892 accepted udp:1.1.1.1:1111

# 连接1的承载链路断开
2021/09/27 09:06:11 [Info] [430093377] app/proxyman/outbound: failed to process outbound traffic > proxy/vmess/outbound: connection ends > context canceled
2021/09/27 09:06:11 [Info] [430093377] app/proxyman/inbound: connection ends > proxy/dokodemo: connection ends > proxy/dokodemo: failed to transport request > io: read/w
# 连接1已经被移除过，所以不再从活动连接中移除
2021/09/27 09:06:11 [Debug] [430093377] app/proxyman/inbound: connection already removed by checker: &{lastActivityTime:1632704257 reader:0xc00009b720 writer:0xc00009b7200870030 local:0xc000870060 done:0xc00105a9f0 uplink:<nil> downlink:<nil> inactive:true}

# 连接2被checker移除
2021/09/27 09:06:26 [Debug] app/proxyman/inbound: checker remove conn: &{lastActivityTime:1632704776 reader:0xc000381218 writer:0xc000381220 output:0x831700 remote:0xc00ne:0xc000276708 uplink:<nil> downlink:<nil> inactive:true}

# 连接3建立
2021/09/27 09:06:26 [Debug] [987382854] proxy/dokodemo: processing connection from: 127.0.0.1:29892
2021/09/27 09:06:26 [Info] [987382854] proxy/dokodemo: received request for 127.0.0.1:29892
2021/09/27 09:06:26 [Info] [987382854] app/dispatcher: default route for udp:1.1.1.1:1111
2021/09/27 09:06:26 [Info] [987382854] transport/internet/websocket: creating connection to tcp:2.2.2.2:2222
2021/09/27 09:06:26 [Info] [987382854] proxy/vmess/outbound: tunneling request to udp:1.1.1.1:1111 via tcp:2.2.2.2:2222
2021/09/27 09:06:26 127.0.0.1:29892 accepted udp:1.1.1.1:1111

# 连接2的承载链路断开
2021/09/27 09:09:08 [Info] [2735844648] app/proxyman/outbound: failed to process outbound traffic > proxy/vmess/outbound: connection ends > write tcp 113.88.96.91:54734-nection reset by peer
2021/09/27 09:09:08 [Info] [2735844648] app/proxyman/inbound: connection ends > proxy/dokodemo: connection ends > proxy/dokodemo: failed to transport response > io: read

# 连接2已经被移除过，所以不再从活动连接中移除
2021/09/27 09:09:08 [Debug] [2735844648] app/proxyman/inbound: connection already removed by checker: &{lastActivityTime:1632704776 reader:0xc000381218 writer:0xc0003812000aacd20 local:0xc000aacd50 done:0xc000276708 uplink:<nil> downlink:<nil> inactive:true}