用 iperf3 并发测 SplitHTTP 会导致panic

vrnobody commented 1 week ago

完整性要求

[X] 我保证阅读了文档，了解所有我编写的配置文件项的含义，而不是大量堆砌看似有用的选项或默认值。
[X] 我搜索了issues，没有发现已提出的类似问题。

版本

Xray 1.8.15 404af13 (go1.22.4 windows/amd64)

描述

用 vless.splithttp.tls 执行 iperf3 -c 127.0.0.1 -p 6003 -P 2 -t 5 并发测速时会断流。禁用客户端的并发 upload 代码则没出现这种情况。改动的代码：https://github.com/vrnobody/xraycore/commit/cecbc2b574e5c2b521497c983615e8dc2b384934

iperf3 日志


iperf3 -c 127.0.0.1 -p 6003 -P 2 -t 5
ip: 10.10.10.10
Connecting to host 127.0.0.1, port 6003
[  5] local 127.0.0.1 port 14315 connected to 127.0.0.1 port 6003
[  7] local 127.0.0.1 port 14317 connected to 127.0.0.1 port 6003
[ ID] Interval           Transfer     Bitrate
[  5]   0.00-1.15   sec   111 MBytes   812 Mbits/sec
[  7]   0.00-1.15   sec  95.2 MBytes   695 Mbits/sec
[SUM]   0.00-1.15   sec   206 MBytes  1.51 Gbits/sec
- - - - - - - - - - - - - - - - - - - - - - - - -
[  5]   1.15-2.09   sec  72.4 MBytes   644 Mbits/sec
[  7]   1.15-2.09   sec  49.9 MBytes   444 Mbits/sec
[SUM]   1.15-2.09   sec   122 MBytes  1.09 Gbits/sec
- - - - - - - - - - - - - - - - - - - - - - - - -
[  5]   2.09-3.02   sec   115 MBytes  1.04 Gbits/sec
[  7]   2.09-3.02   sec  0.00 Bytes  0.00 bits/sec                     <---- 断流
[SUM]   2.09-3.02   sec   115 MBytes  1.04 Gbits/sec
- - - - - - - - - - - - - - - - - - - - - - - - -
[  5]   3.02-4.06   sec   130 MBytes  1.05 Gbits/sec
[  7]   3.02-4.06   sec  0.00 Bytes  0.00 bits/sec
[SUM]   3.02-4.06   sec   130 MBytes  1.05 Gbits/sec
- - - - - - - - - - - - - - - - - - - - - - - - -
[  5]   4.06-5.02   sec   112 MBytes   977 Mbits/sec
[  7]   4.06-5.02   sec  0.00 Bytes  0.00 bits/sec
[SUM]   4.06-5.02   sec   112 MBytes   977 Mbits/sec
- - - - - - - - - - - - - - - - - - - - - - - - -
[ ID] Interval           Transfer     Bitrate
[  5]   0.00-5.02   sec   541 MBytes   903 Mbits/sec                  sender
[  5]   0.00-5.08   sec   520 MBytes   859 Mbits/sec                  receiver
[  7]   0.00-5.02   sec   145 MBytes   242 Mbits/sec                  sender
[  7]   0.00-5.08   sec   116 MBytes   192 Mbits/sec                  receiver
[SUM]   0.00-5.02   sec   686 MBytes  1.15 Gbits/sec                  sender
[SUM]   0.00-5.08   sec   636 MBytes  1.05 Gbits/sec                  receiver

iperf Done.

相应的服务器日志


2024/06/20 21:13:24 [Info] [4272183898] app/proxyman/inbound: connection ends > proxy/vless/inbound: connection ends > proxy/vless/inbound: failed to transfer request payload > transport/internet/splithttp: packet queue is too large
2024/06/20 21:13:24 [Info] transport/internet/splithttp: sessionid does not exist
2024/06/20 21:13:24 [Info] transport/internet/splithttp: sessionid does not exist
2024/06/20 21:13:24 [Info] transport/internet/splithttp: sessionid does not exist
2024/06/20 21:13:24 [Info] transport/internet/splithttp: failed to upload > transport/internet/splithttp: splithttp packet queue closed
2024/06/20 21:13:24 [Info] transport/internet/splithttp: failed to upload > transport/internet/splithttp: splithttp packet queue closed
2024/06/20 21:13:24 [Info] transport/internet/splithttp: failed to upload > transport/internet/splithttp: splithttp packet queue closed

重现方式

本地运行 vless.splithttp.tls 服务器和客户端。用 iperf3 并发测 SplitHTTP。

客户端配置


{
  "log": {
    "loglevel": "warning"
  },
  "inbounds": [
    {
      "tag": "dkd",
      "listen": "127.0.0.1",
      "port": 6003,
      "protocol": "dokodemo-door",
      "settings": {
        "address": "127.0.0.1",
        "port": 5201,
        "network": "tcp"
      }
    }
  ],
  "outbounds": [
    {
      "protocol": "vless",
      "settings": {
        "vnext": [
          {
            "address": "127.0.0.1",
            "port": 6001,
            "users": [
              {
                "id": "bb4e2939-75dc-4384-aee4-50a2ef598a5a",
                "encryption": "none"
              }
            ]
          }
        ]
      },
      "tag": "agentout",
      "streamSettings": {
        "network": "splithttp",
        "security": "tls",
        "splithttpSettings": {
          "path": "/"
        },
        "tlsSettings": {
          "serverName": "mysite.com",
          "allowInsecure": true,
          "alpn": [
            "h2"
          ],
          "certificates": [
            {
              "certificateFile": "mysite.crt",
              "keyFile": "mysite.key"
            }
          ]
        }
      }
    }
  ]
}

服务端配置


{
  "log": {
    "loglevel": "debug"
  },
  "inbounds": [
    {
      "tag": "spin",
      "listen": "127.0.0.1",
      "port": 6001,
      "protocol": "vless",
      "settings": {
        "clients": [
          {
            "id": "bb4e2939-75dc-4384-aee4-50a2ef598a5a"
          }
        ],
        "decryption": "none"
      },
      "streamSettings": {
        "network": "splithttp",
        "security": "tls",
        "splithttpSettings": {
          "path": "/"
        },
        "tlsSettings": {
          "serverName": "mysite.com",
          "allowInsecure": true,
          "alpn": [
            "h2"
          ],
          "certificates": [
            {
              "certificateFile": "mysite.crt",
              "keyFile": "mysite.key"
            }
          ]
        }
      }
    }
  ],
  "outbounds": [
    {
      "tag": "direct",
      "protocol": "freedom"
    }
  ]
}

客户端日志


Xray 1.8.15 (Xray, Penetrates Everything.) 404af13 (go1.22.4 windows/amd64)
A unified platform for anti-censorship.
2024/06/20 21:12:39 [Info] infra/conf/serial: Reading config: stdin:
2024/06/20 21:12:39 [Warning] core: Xray 1.8.15 started
2024/06/20 21:13:22 127.0.0.1:14312 accepted tcp:127.0.0.1:5201 [dkd >> agentout]
2024/06/20 21:13:22 127.0.0.1:14315 accepted tcp:127.0.0.1:5201 [dkd >> agentout]
2024/06/20 21:13:22 127.0.0.1:14317 accepted tcp:127.0.0.1:5201 [dkd >> agentout]

服务端日志


Xray 1.8.15 (Xray, Penetrates Everything.) 404af13 (go1.22.4 windows/amd64)
A unified platform for anti-censorship.
2024/06/20 21:12:49 [Info] infra/conf/serial: Reading config: stdin:
2024/06/20 21:12:49 [Debug] app/log: Logger started
2024/06/20 21:12:49 [Debug] app/proxyman/inbound: creating stream worker on 127.0.0.1:6001
2024/06/20 21:12:49 [Info] transport/internet/splithttp: listening TCP(for SH) on 127.0.0.1:6001
2024/06/20 21:12:49 [Warning] core: Xray 1.8.15 started
2024/06/20 21:13:22 [Info] [647115761] proxy/vless/inbound: firstLen = 0
2024/06/20 21:13:22 [Info] [647115761] proxy/vless/inbound: received request for tcp:127.0.0.1:5201
2024/06/20 21:13:22 [Info] [647115761] app/dispatcher: default route for tcp:127.0.0.1:5201
2024/06/20 21:13:22 [Info] [647115761] transport/internet/tcp: dialing TCP to tcp:127.0.0.1:5201
2024/06/20 21:13:22 127.0.0.1:14313 accepted tcp:127.0.0.1:5201 [spin >> direct]
2024/06/20 21:13:22 [Debug] transport/internet: dialing to tcp:127.0.0.1:5201
2024/06/20 21:13:22 [Info] [647115761] proxy/freedom: connection opened to tcp:127.0.0.1:5201, local endpoint 127.0.0.1:14314, remote endpoint 127.0.0.1:5201
2024/06/20 21:13:22 [Info] [647115761] proxy: CopyRawConn readv
2024/06/20 21:13:22 [Info] [2821068503] proxy/vless/inbound: firstLen = 0
2024/06/20 21:13:22 [Info] [2821068503] proxy/vless/inbound: received request for tcp:127.0.0.1:5201
2024/06/20 21:13:22 [Info] [2821068503] app/dispatcher: default route for tcp:127.0.0.1:5201
2024/06/20 21:13:22 [Info] [2821068503] transport/internet/tcp: dialing TCP to tcp:127.0.0.1:5201
2024/06/20 21:13:22 [Debug] transport/internet: dialing to tcp:127.0.0.1:5201
2024/06/20 21:13:22 127.0.0.1:14313 accepted tcp:127.0.0.1:5201 [spin >> direct]
2024/06/20 21:13:22 [Info] [2821068503] proxy/freedom: connection opened to tcp:127.0.0.1:5201, local endpoint 127.0.0.1:14316, remote endpoint 127.0.0.1:5201
2024/06/20 21:13:22 [Info] [2821068503] proxy: CopyRawConn readv
2024/06/20 21:13:22 [Info] [4272183898] proxy/vless/inbound: firstLen = 0
2024/06/20 21:13:22 [Info] [4272183898] proxy/vless/inbound: received request for tcp:127.0.0.1:5201
2024/06/20 21:13:22 [Info] [4272183898] app/dispatcher: default route for tcp:127.0.0.1:5201
2024/06/20 21:13:22 [Info] [4272183898] transport/internet/tcp: dialing TCP to tcp:127.0.0.1:5201
2024/06/20 21:13:22 127.0.0.1:14313 accepted tcp:127.0.0.1:5201 [spin >> direct]
2024/06/20 21:13:22 [Debug] transport/internet: dialing to tcp:127.0.0.1:5201
2024/06/20 21:13:22 [Info] [4272183898] proxy/freedom: connection opened to tcp:127.0.0.1:5201, local endpoint 127.0.0.1:14318, remote endpoint 127.0.0.1:5201
2024/06/20 21:13:22 [Info] [4272183898] proxy: CopyRawConn readv
2024/06/20 21:13:24 [Info] [4272183898] app/proxyman/inbound: connection ends > proxy/vless/inbound: connection ends > proxy/vless/inbound: failed to transfer request payload > transport/internet/splithttp: packet queue is too large
2024/06/20 21:13:24 [Info] transport/internet/splithttp: sessionid does not exist
2024/06/20 21:13:24 [Info] transport/internet/splithttp: sessionid does not exist
2024/06/20 21:13:24 [Info] transport/internet/splithttp: sessionid does not exist
2024/06/20 21:13:24 [Info] transport/internet/splithttp: failed to upload > transport/internet/splithttp: splithttp packet queue closed
2024/06/20 21:13:24 [Info] transport/internet/splithttp: failed to upload > transport/internet/splithttp: splithttp packet queue closed
2024/06/20 21:13:24 [Info] transport/internet/splithttp: failed to upload > transport/internet/splithttp: splithttp packet queue closed
2024/06/20 21:13:24 [Info] transport/internet/splithttp: failed to upload > transport/internet/splithttp: splithttp packet queue closed
2024/06/20 21:13:24 [Info] transport/internet/splithttp: failed to upload > transport/internet/splithttp: splithttp packet queue closed
2024/06/20 21:13:24 [Info] transport/internet/splithttp: failed to upload > transport/internet/splithttp: splithttp packet queue closed
2024/06/20 21:13:24 [Info] transport/internet/splithttp: failed to upload > transport/internet/splithttp: splithttp packet queue closed
2024/06/20 21:13:24 [Info] transport/internet/splithttp: failed to upload > transport/internet/splithttp: splithttp packet queue closed
2024/06/20 21:13:24 [Info] transport/internet/splithttp: failed to upload > transport/internet/splithttp: splithttp packet queue closed
2024/06/20 21:13:27 http2: panic serving 127.0.0.1:14313: send on closed channel
goroutine 14362 [running]:
net/http.(*http2serverConn).runHandler.func1()
    net/http/h2_bundle.go:6185 +0x145
panic({0x1babd20?, 0x1f338a0?})
    runtime/panic.go:770 +0x132
github.com/xtls/xray-core/transport/internet/splithttp.(*UploadQueue).Push(...)
    github.com/xtls/xray-core/transport/internet/splithttp/upload_queue.go:39
github.com/xtls/xray-core/transport/internet/splithttp.(*requestHandler).ServeHTTP(0xc000341580, {0x1f48f10, 0xc000070a10}, 0xc00034f0e0)
    github.com/xtls/xray-core/transport/internet/splithttp/hub.go:92 +0x10d0
net/http.serverHandler.ServeHTTP({0x12de300?}, {0x1f48f10?, 0xc000070a10?}, 0xc000938000?)
    net/http/server.go:3137 +0x8e
net/http.initALPNRequest.ServeHTTP({{0x1f4b180?, 0xc00035e000?}, 0xc00033c388?, {0xc00034e5a8?}}, {0x1f48f10, 0xc000070a10}, 0xc00034f0e0)
    net/http/server.go:3745 +0x231
net/http.(*http2serverConn).runHandler(0xf0a3bd?, 0x0?, 0x0?, 0xb9538e724ac0b7ea?)
    net/http/h2_bundle.go:6192 +0xbb
2024/06/20 21:13:27 [Info] [2821068503] app/proxyman/inbound: connection ends > proxy/vless/inbound: connection ends > proxy/vless/inbound: failed to transfer request payload > io: read/write on closed pipe
created by net/http.(*http2serverConn).scheduleHandler in goroutine 18
    net/http/h2_bundle.go:6127 +0x21d
2024/06/20 21:13:27 http2: panic serving 127.0.0.1:14313: send on closed channel
goroutine 14313 [running]:
net/http.(*http2serverConn).runHandler.func1()
    net/http/h2_bundle.go:6185 +0x145
panic({0x1babd20?, 0x1f338a0?})
    runtime/panic.go:770 +0x132
github.com/xtls/xray-core/transport/internet/splithttp.(*UploadQueue).Push(...)
    github.com/xtls/xray-core/transport/internet/splithttp/upload_queue.go:39
github.com/xtls/xray-core/transport/internet/splithttp.(*requestHandler).ServeHTTP(0xc000341580, {0x1f48f10, 0xc000088098}, 0xc000239680)
    github.com/xtls/xray-core/transport/internet/splithttp/hub.go:92 +0x10d0
net/http.serverHandler.ServeHTTP({0x12de300?}, {0x1f48f10?, 0xc000088098?}, 0xc000338198?)
    net/http/server.go:3137 +0x8e
net/http.initALPNRequest.ServeHTTP({{0x1f4b180?, 0xc00035e000?}, 0xc00033c388?, {0xc00034e5a8?}}, {0x1f48f10, 0xc000088098}, 0xc000239680)
    net/http/server.go:3745 +0x231
net/http.(*http2serverConn).runHandler(0xf0a3bd?, 0x0?, 0x0?, 0x79567c94f6de264f?)
    net/http/h2_bundle.go:6192 +0xbb
created by net/http.(*http2serverConn).scheduleHandler in goroutine 18
    net/http/h2_bundle.go:6127 +0x21d
2024/06/20 21:13:27 http2: panic serving 127.0.0.1:14313: send on closed channel
goroutine 14289 [running]:
net/http.(*http2serverConn).runHandler.func1()
    net/http/h2_bundle.go:6185 +0x145
panic({0x1babd20?, 0x1f338a0?})
    runtime/panic.go:770 +0x132
github.com/xtls/xray-core/transport/internet/splithttp.(*UploadQueue).Push(...)
    github.com/xtls/xray-core/transport/internet/splithttp/upload_queue.go:39
github.com/xtls/xray-core/transport/internet/splithttp.(*requestHandler).ServeHTTP(0xc000341580, {0x1f48f10, 0xc0000709e0}, 0xc00034e900)
    github.com/xtls/xray-core/transport/internet/splithttp/hub.go:92 +0x10d0
net/http.serverHandler.ServeHTTP({0x12de300?}, {0x1f48f10?, 0xc0000709e0?}, 0xc000938000?)
    net/http/server.go:3137 +0x8e
net/http.initALPNRequest.ServeHTTP({{0x1f4b180?, 0xc00035e000?}, 0xc00033c388?, {0xc00034e5a8?}}, {0x1f48f10, 0xc0000709e0}, 0xc00034e900)
    net/http/server.go:3745 +0x231
net/http.(*http2serverConn).runHandler(0xf0a3bd?, 0x0?, 0x0?, 0x5f92480c83a9e612?)
    net/http/h2_bundle.go:6192 +0xbb
created by net/http.(*http2serverConn).scheduleHandler in goroutine 18
    net/http/h2_bundle.go:6127 +0x21d
2024/06/20 21:13:27 http2: panic serving 127.0.0.1:14313: send on closed channel
goroutine 14365 [running]:
net/http.(*http2serverConn).runHandler.func1()
    net/http/h2_bundle.go:6185 +0x145
panic({0x1babd20?, 0x1f338a0?})
    runtime/panic.go:770 +0x132
github.com/xtls/xray-core/transport/internet/splithttp.(*UploadQueue).Push(...)
    github.com/xtls/xray-core/transport/internet/splithttp/upload_queue.go:39
github.com/xtls/xray-core/transport/internet/splithttp.(*requestHandler).ServeHTTP(0xc000341580, {0x1f48f10, 0xc000071738}, 0xc00034f320)
    github.com/xtls/xray-core/transport/internet/splithttp/hub.go:92 +0x10d0
net/http.serverHandler.ServeHTTP({0x12de300?}, {0x1f48f10?, 0xc000071738?}, 0xc000938000?)
    net/http/server.go:3137 +0x8e
net/http.initALPNRequest.ServeHTTP({{0x1f4b180?, 0xc00035e000?}, 0xc00033c388?, {0xc00034e5a8?}}, {0x1f48f10, 0xc000071738}, 0xc00034f320)
    net/http/server.go:3745 +0x231
net/http.(*http2serverConn).runHandler(0xf0a3bd?, 0x0?, 0x0?, 0x8a13225019be90bc?)
    net/http/h2_bundle.go:6192 +0xbb
created by net/http.(*http2serverConn).scheduleHandler in goroutine 18
    net/http/h2_bundle.go:6127 +0x21d
2024/06/20 21:13:27 http2: panic serving 127.0.0.1:14313: send on closed channel
goroutine 14249 [running]:
net/http.(*http2serverConn).runHandler.func1()
    net/http/h2_bundle.go:6185 +0x145
panic({0x1babd20?, 0x1f338a0?})
    runtime/panic.go:770 +0x132
github.com/xtls/xray-core/transport/internet/splithttp.(*UploadQueue).Push(...)
    github.com/xtls/xray-core/transport/internet/splithttp/upload_queue.go:39
github.com/xtls/xray-core/transport/internet/splithttp.(*requestHandler).ServeHTTP(0xc000341580, {0x1f48f10, 0xc000282720}, 0xc00026eb40)
    github.com/xtls/xray-core/transport/internet/splithttp/hub.go:92 +0x10d0
net/http.serverHandler.ServeHTTP({0xc0008bfd50?}, {0x1f48f10?, 0xc000282720?}, 0xc000290380?)
    net/http/server.go:3137 +0x8e
net/http.initALPNRequest.ServeHTTP({{0x1f4b180?, 0xc00035e000?}, 0xc00033c388?, {0xc00034e5a8?}}, {0x1f48f10, 0xc000282720}, 0xc00026eb40)
    net/http/server.go:3745 +0x231
net/http.(*http2serverConn).runHandler(0xf0a3bd?, 0x0?, 0x0?, 0xbbd5d43a578af6a9?)
    net/http/h2_bundle.go:6192 +0xbb
created by net/http.(*http2serverConn).scheduleHandler in goroutine 18
    net/http/h2_bundle.go:6127 +0x21d
2024/06/20 21:13:27 http2: panic serving 127.0.0.1:14313: send on closed channel
goroutine 14360 [running]:
net/http.(*http2serverConn).runHandler.func1()
    net/http/h2_bundle.go:6185 +0x145
panic({0x1babd20?, 0x1f338a0?})
    runtime/panic.go:770 +0x132
github.com/xtls/xray-core/transport/internet/splithttp.(*UploadQueue).Push(...)
    github.com/xtls/xray-core/transport/internet/splithttp/upload_queue.go:39
github.com/xtls/xray-core/transport/internet/splithttp.(*requestHandler).ServeHTTP(0xc000341580, {0x1f48f10, 0xc0000709f0}, 0xc00034ec60)
    github.com/xtls/xray-core/transport/internet/splithttp/hub.go:92 +0x10d0
net/http.serverHandler.ServeHTTP({0x12de300?}, {0x1f48f10?, 0xc0000709f0?}, 0xc000938000?)
    net/http/server.go:3137 +0x8e
net/http.initALPNRequest.ServeHTTP({{0x1f4b180?, 0xc00035e000?}, 0xc00033c388?, {0xc00034e5a8?}}, {0x1f48f10, 0xc0000709f0}, 0xc00034ec60)
    net/http/server.go:3745 +0x231
net/http.(*http2serverConn).runHandler(0xf0a3bd?, 0x0?, 0x0?, 0x0?)
    net/http/h2_bundle.go:6192 +0xbb
created by net/http.(*http2serverConn).scheduleHandler in goroutine 18
    net/http/h2_bundle.go:6127 +0x21d
2024/06/20 21:13:27 http2: panic serving 127.0.0.1:14313: send on closed channel
goroutine 14361 [running]:
net/http.(*http2serverConn).runHandler.func1()
    net/http/h2_bundle.go:6185 +0x145
panic({0x1babd20?, 0x1f338a0?})
    runtime/panic.go:770 +0x132
github.com/xtls/xray-core/transport/internet/splithttp.(*UploadQueue).Push(...)
    github.com/xtls/xray-core/transport/internet/splithttp/upload_queue.go:39
github.com/xtls/xray-core/transport/internet/splithttp.(*requestHandler).ServeHTTP(0xc000341580, {0x1f48f10, 0xc000070a00}, 0xc00034eea0)
    github.com/xtls/xray-core/transport/internet/splithttp/hub.go:92 +0x10d0
net/http.serverHandler.ServeHTTP({0x12de300?}, {0x1f48f10?, 0xc000070a00?}, 0xc000938000?)
    net/http/server.go:3137 +0x8e
net/http.initALPNRequest.ServeHTTP({{0x1f4b180?, 0xc00035e000?}, 0xc00033c388?, {0xc00034e5a8?}}, {0x1f48f10, 0xc000070a00}, 0xc00034eea0)
    net/http/server.go:3745 +0x231
net/http.(*http2serverConn).runHandler(0xf0a3bd?, 0x0?, 0x0?, 0x4a8b79ccd1e04cdf?)
    net/http/h2_bundle.go:6192 +0xbb
created by net/http.(*http2serverConn).scheduleHandler in goroutine 18
    net/http/h2_bundle.go:6127 +0x21d
2024/06/20 21:13:27 http2: panic serving 127.0.0.1:14313: send on closed channel
goroutine 14248 [running]:
net/http.(*http2serverConn).runHandler.func1()
    net/http/h2_bundle.go:6185 +0x145
panic({0x1babd20?, 0x1f338a0?})
    runtime/panic.go:770 +0x132
github.com/xtls/xray-core/transport/internet/splithttp.(*UploadQueue).Push(...)
    github.com/xtls/xray-core/transport/internet/splithttp/upload_queue.go:39
github.com/xtls/xray-core/transport/internet/splithttp.(*requestHandler).ServeHTTP(0xc000341580, {0x1f48f10, 0xc000282718}, 0xc00026e7e0)
    github.com/xtls/xray-core/transport/internet/splithttp/hub.go:92 +0x10d0
net/http.serverHandler.ServeHTTP({0xc00060fd50?}, {0x1f48f10?, 0xc000282718?}, 0xc0002903f0?)
    net/http/server.go:3137 +0x8e
net/http.initALPNRequest.ServeHTTP({{0x1f4b180?, 0xc00035e000?}, 0xc00033c388?, {0xc00034e5a8?}}, {0x1f48f10, 0xc000282718}, 0xc00026e7e0)
    net/http/server.go:3745 +0x231
net/http.(*http2serverConn).runHandler(0xf0a3bd?, 0x0?, 0x0?, 0xaa3245c9754a98dd?)
    net/http/h2_bundle.go:6192 +0xbb
created by net/http.(*http2serverConn).scheduleHandler in goroutine 18
    net/http/h2_bundle.go:6127 +0x21d
2024/06/20 21:13:27 http2: panic serving 127.0.0.1:14313: send on closed channel
goroutine 14306 [running]:
net/http.(*http2serverConn).runHandler.func1()
    net/http/h2_bundle.go:6185 +0x145
panic({0x1babd20?, 0x1f338a0?})
    runtime/panic.go:770 +0x132
github.com/xtls/xray-core/transport/internet/splithttp.(*UploadQueue).Push(...)
    github.com/xtls/xray-core/transport/internet/splithttp/upload_queue.go:39
github.com/xtls/xray-core/transport/internet/splithttp.(*requestHandler).ServeHTTP(0xc000341580, {0x1f48f10, 0xc000088078}, 0xc000238480)
    github.com/xtls/xray-core/transport/internet/splithttp/hub.go:92 +0x10d0
net/http.serverHandler.ServeHTTP({0xc0037d7d50?}, {0x1f48f10?, 0xc000088078?}, 0xc0002861e0?)
    net/http/server.go:3137 +0x8e
net/http.initALPNRequest.ServeHTTP({{0x1f4b180?, 0xc00035e000?}, 0xc00033c388?, {0xc00034e5a8?}}, {0x1f48f10, 0xc000088078}, 0xc000238480)
    net/http/server.go:3745 +0x231
net/http.(*http2serverConn).runHandler(0xf0a3bd?, 0x0?, 0x0?, 0x8af2b536c5156bc3?)
2024/06/20 21:13:27 [Info] transport/internet/splithttp: sessionid does not exist
    net/http/h2_bundle.go:6192 +0xbb
created by net/http.(*http2serverConn).scheduleHandler in goroutine 18
    net/http/h2_bundle.go:6127 +0x21d
2024/06/20 21:13:27 [Info] transport/internet/splithttp: failed to upload > transport/internet/splithttp: splithttp packet queue closed
2024/06/20 21:13:28 [Info] [647115761] app/proxyman/inbound: connection ends > proxy/vless/inbound: connection ends > context canceled

mmmray commented 1 week ago

can you try to lower maxConcurrentUploads on the client instead? ~~is there a CDN inbetween?~~ seems not

mmmray commented 1 week ago

Forget about my questions, you provided all steps. I tried it now and I cannot reproduce it on either 1.8.15 or #3462, that is on Ubuntu 22.

possibly only an issue on Windows? Will take some time for me.

mmmray commented 1 week ago

I cannot reproduce this on Windows 10 either, neither with the 1.8.15 release for 64 bit, nor self-compiled main.

RPRX commented 1 week ago

试试 https://github.com/XTLS/Xray-core/releases/tag/v1.8.16

vrnobody commented 1 week ago

测试了 v1.8.16 仍然存在相同的问题。不确定和 iperf 版本是否有关系。

iperf3.exe --version
iperf 3.17.1 (cJSON 1.7.15)
CYGWIN_NT-10.0-19045 DESKTOP-VD1SRRF 3.5.3-1.x86_64 2024-04-03 17:25 UTC x86_64
Optional features available: CPU affinity setting, authentication, support IPv4 don't fragment, POSIX threads

我的电脑很慢，试试增加 -t -P 参数：

iperf3.exe -c 127.0.0.1 -p 6003 -t 15 -P 10

maxConcurrentUploads 是关键问题。完全禁止客户端并发 upload 可以消灭这个 bug 。

新的日志，没什么变化：

iperf logs


iperf3.exe -c 127.0.0.1 -p 6003 -t 10 -P 2
Connecting to host 127.0.0.1, port 6003
[  5] local 127.0.0.1 port 5361 connected to 127.0.0.1 port 6003
[  7] local 127.0.0.1 port 5363 connected to 127.0.0.1 port 6003
[ ID] Interval           Transfer     Bitrate
[  5]   0.00-1.02   sec  92.5 MBytes   762 Mbits/sec
[  7]   0.00-1.02   sec  95.4 MBytes   785 Mbits/sec
[SUM]   0.00-1.02   sec   188 MBytes  1.55 Gbits/sec
- - - - - - - - - - - - - - - - - - - - - - - - -
[  5]   1.02-2.00   sec  74.9 MBytes   640 Mbits/sec
[  7]   1.02-2.00   sec  79.9 MBytes   683 Mbits/sec
[SUM]   1.02-2.00   sec   155 MBytes  1.32 Gbits/sec
- - - - - - - - - - - - - - - - - - - - - - - - -
[  5]   2.00-3.02   sec  67.4 MBytes   557 Mbits/sec
[  7]   2.00-3.02   sec  74.9 MBytes   619 Mbits/sec
[SUM]   2.00-3.02   sec   142 MBytes  1.18 Gbits/sec
- - - - - - - - - - - - - - - - - - - - - - - - -
[  5]   3.02-4.01   sec  84.9 MBytes   717 Mbits/sec
[  7]   3.02-4.01   sec  74.9 MBytes   633 Mbits/sec
[SUM]   3.02-4.01   sec   160 MBytes  1.35 Gbits/sec
- - - - - - - - - - - - - - - - - - - - - - - - -
[  5]   4.01-5.02   sec  74.9 MBytes   623 Mbits/sec
[  7]   4.01-5.02   sec  77.5 MBytes   645 Mbits/sec
[SUM]   4.01-5.02   sec   152 MBytes  1.27 Gbits/sec
- - - - - - - - - - - - - - - - - - - - - - - - -
[  5]   5.02-6.00   sec  79.9 MBytes   679 Mbits/sec
[  7]   5.02-6.00   sec  72.2 MBytes   614 Mbits/sec
[SUM]   5.02-6.00   sec   152 MBytes  1.29 Gbits/sec
- - - - - - - - - - - - - - - - - - - - - - - - -
[  5]   6.00-7.01   sec  95.0 MBytes   794 Mbits/sec
[  7]   6.00-7.01   sec  17.6 MBytes   147 Mbits/sec
[SUM]   6.00-7.01   sec   113 MBytes   941 Mbits/sec
- - - - - - - - - - - - - - - - - - - - - - - - -
[  5]   7.01-8.01   sec   125 MBytes  1.04 Gbits/sec
[  7]   7.01-8.01   sec  0.00 Bytes  0.00 bits/sec                  <------------
[SUM]   7.01-8.01   sec   125 MBytes  1.04 Gbits/sec
- - - - - - - - - - - - - - - - - - - - - - - - -
[  5]   8.01-9.01   sec   115 MBytes   970 Mbits/sec
[  7]   8.01-9.01   sec  0.00 Bytes  0.00 bits/sec
[SUM]   8.01-9.01   sec   115 MBytes   970 Mbits/sec
- - - - - - - - - - - - - - - - - - - - - - - - -
[  5]   9.01-10.01  sec   117 MBytes   977 Mbits/sec
[  7]   9.01-10.01  sec  0.00 Bytes  0.00 bits/sec
[SUM]   9.01-10.01  sec   117 MBytes   977 Mbits/sec
- - - - - - - - - - - - - - - - - - - - - - - - -
[ ID] Interval           Transfer     Bitrate
[  5]   0.00-10.01  sec   926 MBytes   776 Mbits/sec                  sender                  <------------
[  5]   0.00-10.03  sec   906 MBytes   758 Mbits/sec                  receiver
[  7]   0.00-10.01  sec   492 MBytes   412 Mbits/sec                  sender                  <------------
[  7]   0.00-10.03  sec   454 MBytes   380 Mbits/sec                  receiver
[SUM]   0.00-10.01  sec  1.39 GBytes  1.19 Gbits/sec                  sender
[SUM]   0.00-10.03  sec  1.33 GBytes  1.14 Gbits/sec                  receiver

iperf Done.

server logs


xray.exe -c serv.json
Xray 1.8.16 (Xray, Penetrates Everything.) 9432a60 (go1.22.4 windows/amd64)
A unified platform for anti-censorship.
2024/06/21 23:49:51 [Info] infra/conf/serial: Reading config: serv.json
2024/06/21 23:49:51 [Debug] app/log: Logger started
2024/06/21 23:49:51 [Debug] app/proxyman/inbound: creating stream worker on 127.0.0.1:6001
2024/06/21 23:49:51 [Info] transport/internet/splithttp: listening TCP(for SH) on 127.0.0.1:6001
2024/06/21 23:49:51 [Warning] core: Xray 1.8.16 started
2024/06/21 23:50:02 [Info] [3811967589] proxy/vless/inbound: firstLen = 0
2024/06/21 23:50:05 [Info] [2285601385] proxy/vless/inbound: firstLen = 0
2024/06/21 23:50:05 [Info] [2285601385] proxy/vless/inbound: received request for tcp:127.0.0.1:5201
2024/06/21 23:50:05 [Info] [2285601385] app/dispatcher: default route for tcp:127.0.0.1:5201
2024/06/21 23:50:05 127.0.0.1:4086 accepted tcp:127.0.0.1:5201 [spin >> direct]
2024/06/21 23:50:05 [Info] [2285601385] transport/internet/tcp: dialing TCP to tcp:127.0.0.1:5201
2024/06/21 23:50:05 [Debug] transport/internet: dialing to tcp:127.0.0.1:5201
2024/06/21 23:50:05 [Info] [2285601385] proxy/freedom: connection opened to tcp:127.0.0.1:5201, local endpoint 127.0.0.1:4099, remote endpoint 127.0.0.1:5201
2024/06/21 23:50:05 [Info] [2285601385] proxy: CopyRawConn readv
2024/06/21 23:50:05 [Info] [4131515818] proxy/vless/inbound: firstLen = 0
2024/06/21 23:50:05 [Info] [4131515818] proxy/vless/inbound: received request for tcp:127.0.0.1:5201
2024/06/21 23:50:05 [Info] [4131515818] app/dispatcher: default route for tcp:127.0.0.1:5201
2024/06/21 23:50:05 [Info] [4131515818] transport/internet/tcp: dialing TCP to tcp:127.0.0.1:5201
2024/06/21 23:50:05 127.0.0.1:4086 accepted tcp:127.0.0.1:5201 [spin >> direct]
2024/06/21 23:50:05 [Debug] transport/internet: dialing to tcp:127.0.0.1:5201
2024/06/21 23:50:05 [Info] [4131515818] proxy/freedom: connection opened to tcp:127.0.0.1:5201, local endpoint 127.0.0.1:4101, remote endpoint 127.0.0.1:5201
2024/06/21 23:50:05 [Info] [4131515818] proxy: CopyRawConn readv
2024/06/21 23:50:05 [Info] [355862417] proxy/vless/inbound: firstLen = 0
2024/06/21 23:50:05 [Info] [355862417] proxy/vless/inbound: received request for tcp:127.0.0.1:5201
2024/06/21 23:50:05 [Info] [355862417] app/dispatcher: default route for tcp:127.0.0.1:5201
2024/06/21 23:50:05 [Info] [355862417] transport/internet/tcp: dialing TCP to tcp:127.0.0.1:5201
2024/06/21 23:50:05 [Debug] transport/internet: dialing to tcp:127.0.0.1:5201
2024/06/21 23:50:05 [Info] [355862417] proxy/freedom: connection opened to tcp:127.0.0.1:5201, local endpoint 127.0.0.1:4103, remote endpoint 127.0.0.1:5201
2024/06/21 23:50:05 [Info] [355862417] proxy: CopyRawConn readv
2024/06/21 23:50:05 127.0.0.1:4086 accepted tcp:127.0.0.1:5201 [spin >> direct]
2024/06/21 23:50:06 [Info] [4131515818] app/proxyman/inbound: connection ends > proxy/vless/inbound: connection ends > proxy/vless/inbound: failed to transfer request payload > transport/internet/splithttp: packet queue is too large
2024/06/21 23:50:06 [Info] transport/internet/splithttp: failed to upload > transport/internet/splithttp: splithttp packet queue closed
2024/06/21 23:50:06 [Info] transport/internet/splithttp: failed to upload > transport/internet/splithttp: splithttp packet queue closed
2024/06/21 23:50:06 [Info] transport/internet/splithttp: failed to upload > transport/internet/splithttp: splithttp packet queue closed
2024/06/21 23:50:06 [Info] transport/internet/splithttp: failed to upload > transport/internet/splithttp: splithttp packet queue closed
2024/06/21 23:50:06 [Info] transport/internet/splithttp: failed to upload > transport/internet/splithttp: splithttp packet queue closed
2024/06/21 23:50:06 [Info] transport/internet/splithttp: failed to upload > transport/internet/splithttp: splithttp packet queue closed
2024/06/21 23:50:06 [Info] transport/internet/splithttp: failed to upload > transport/internet/splithttp: splithttp packet queue closed
2024/06/21 23:50:06 [Info] transport/internet/splithttp: failed to upload > transport/internet/splithttp: splithttp packet queue closed
2024/06/21 23:50:06 [Info] transport/internet/splithttp: failed to upload > transport/internet/splithttp: splithttp packet queue closed
2024/06/21 23:50:06 [Info] [355862417] app/proxyman/inbound: connection ends > proxy/vless/inbound: connection ends > proxy/vless/inbound: failed to transfer request payload > transport/internet/splithttp: packet queue is too large
2024/06/21 23:50:06 [Info] transport/internet/splithttp: failed to upload > transport/internet/splithttp: splithttp packet queue closed
2024/06/21 23:50:06 [Info] transport/internet/splithttp: failed to upload > transport/internet/splithttp: splithttp packet queue closed
2024/06/21 23:50:06 [Info] transport/internet/splithttp: failed to upload > transport/internet/splithttp: splithttp packet queue closed
2024/06/21 23:50:06 [Info] transport/internet/splithttp: failed to upload > transport/internet/splithttp: splithttp packet queue closed
2024/06/21 23:50:06 [Info] transport/internet/splithttp: failed to upload > transport/internet/splithttp: splithttp packet queue closed
2024/06/21 23:50:06 [Info] transport/internet/splithttp: failed to upload > transport/internet/splithttp: splithttp packet queue closed
2024/06/21 23:50:06 [Info] transport/internet/splithttp: failed to upload > transport/internet/splithttp: splithttp packet queue closed
2024/06/21 23:50:06 [Info] transport/internet/splithttp: failed to upload > transport/internet/splithttp: splithttp packet queue closed
2024/06/21 23:50:11 [Info] [2285601385] app/proxyman/inbound: connection ends > proxy/vless/inbound: connection ends > context canceled

client logs


xray.exe -c client.json
Xray 1.8.16 (Xray, Penetrates Everything.) 9432a60 (go1.22.4 windows/amd64)
A unified platform for anti-censorship.
2024/06/21 23:49:54 [Info] infra/conf/serial: Reading config: client.json
2024/06/21 23:49:54 [Debug] app/log: Logger started
2024/06/21 23:49:54 [Debug] app/proxyman/inbound: creating stream worker on 127.0.0.1:6003
2024/06/21 23:49:54 [Info] transport/internet/tcp: listening TCP on 127.0.0.1:6003
2024/06/21 23:49:54 [Warning] core: Xray 1.8.16 started
2024/06/21 23:49:59 [Debug] [2608139424] proxy/dokodemo: processing connection from: 127.0.0.1:4085
2024/06/21 23:49:59 [Info] [2608139424] proxy/dokodemo: received request for 127.0.0.1:4085
2024/06/21 23:49:59 [Info] [2608139424] app/dispatcher: default route for tcp:127.0.0.1:5201
2024/06/21 23:49:59 [Info] [2608139424] transport/internet/splithttp: dialing splithttp to tcp:127.0.0.1:6001
2024/06/21 23:49:59 127.0.0.1:4085 accepted tcp:127.0.0.1:5201 [dkd >> agentout]
2024/06/21 23:49:59 [Debug] transport/internet: dialing to tcp:127.0.0.1:6001
2024/06/21 23:49:59 [Info] [2608139424] proxy/vless/outbound: tunneling request to tcp:127.0.0.1:5201 via 127.0.0.1:6001
2024/06/21 23:50:03 [Info] [2608139424] app/proxyman/inbound: connection ends > proxy/dokodemo: connection ends > context canceled
2024/06/21 23:50:05 [Debug] [1172667396] proxy/dokodemo: processing connection from: 127.0.0.1:4098
2024/06/21 23:50:05 [Info] [1172667396] proxy/dokodemo: received request for 127.0.0.1:4098
2024/06/21 23:50:05 [Info] [1172667396] app/dispatcher: default route for tcp:127.0.0.1:5201
2024/06/21 23:50:05 [Info] [1172667396] transport/internet/splithttp: dialing splithttp to tcp:127.0.0.1:6001
2024/06/21 23:50:05 [Info] [1172667396] proxy/vless/outbound: tunneling request to tcp:127.0.0.1:5201 via 127.0.0.1:6001
2024/06/21 23:50:05 127.0.0.1:4098 accepted tcp:127.0.0.1:5201 [dkd >> agentout]
2024/06/21 23:50:05 [Debug] [99350724] proxy/dokodemo: processing connection from: 127.0.0.1:4100
2024/06/21 23:50:05 [Info] [99350724] proxy/dokodemo: received request for 127.0.0.1:4100
2024/06/21 23:50:05 [Info] [99350724] app/dispatcher: default route for tcp:127.0.0.1:5201
2024/06/21 23:50:05 [Info] [99350724] transport/internet/splithttp: dialing splithttp to tcp:127.0.0.1:6001
2024/06/21 23:50:05 [Info] [99350724] proxy/vless/outbound: tunneling request to tcp:127.0.0.1:5201 via 127.0.0.1:6001
2024/06/21 23:50:05 127.0.0.1:4100 accepted tcp:127.0.0.1:5201 [dkd >> agentout]
2024/06/21 23:50:05 [Debug] [2725169439] proxy/dokodemo: processing connection from: 127.0.0.1:4102
2024/06/21 23:50:05 [Info] [2725169439] proxy/dokodemo: received request for 127.0.0.1:4102
2024/06/21 23:50:05 [Info] [2725169439] app/dispatcher: default route for tcp:127.0.0.1:5201
2024/06/21 23:50:05 [Info] [2725169439] transport/internet/splithttp: dialing splithttp to tcp:127.0.0.1:6001
2024/06/21 23:50:05 [Info] [2725169439] proxy/vless/outbound: tunneling request to tcp:127.0.0.1:5201 via 127.0.0.1:6001
2024/06/21 23:50:05 127.0.0.1:4102 accepted tcp:127.0.0.1:5201 [dkd >> agentout]
2024/06/21 23:50:06 [Info] [99350724] app/proxyman/inbound: connection ends > proxy/dokodemo: connection ends > proxy/dokodemo: failed to transport request > io: read/write on closed pipe
2024/06/21 23:50:06 [Info] transport/internet/splithttp: failed to send upload, bad status code:500 Internal Server Error
2024/06/21 23:50:06 [Info] transport/internet/splithttp: failed to send upload, bad status code:500 Internal Server Error
2024/06/21 23:50:06 [Info] transport/internet/splithttp: failed to send upload, bad status code:500 Internal Server Error
2024/06/21 23:50:06 [Info] transport/internet/splithttp: failed to send upload, bad status code:500 Internal Server Error
2024/06/21 23:50:06 [Info] transport/internet/splithttp: failed to send upload, bad status code:500 Internal Server Error
2024/06/21 23:50:06 [Info] transport/internet/splithttp: failed to send upload, bad status code:500 Internal Server Error
2024/06/21 23:50:06 [Info] transport/internet/splithttp: failed to send upload, bad status code:500 Internal Server Error
2024/06/21 23:50:06 [Info] transport/internet/splithttp: failed to send upload, bad status code:500 Internal Server Error
2024/06/21 23:50:06 [Info] transport/internet/splithttp: failed to send upload, bad status code:500 Internal Server Error
2024/06/21 23:50:06 [Info] [2725169439] app/proxyman/inbound: connection ends > proxy/dokodemo: connection ends > proxy/dokodemo: failed to transport request > io: read/write on closed pipe
2024/06/21 23:50:06 [Info] transport/internet/splithttp: failed to send upload, bad status code:500 Internal Server Error
2024/06/21 23:50:06 [Info] transport/internet/splithttp: failed to send upload, bad status code:500 Internal Server Error
2024/06/21 23:50:06 [Info] transport/internet/splithttp: failed to send upload, bad status code:500 Internal Server Error
2024/06/21 23:50:06 [Info] transport/internet/splithttp: failed to send upload, bad status code:500 Internal Server Error
2024/06/21 23:50:06 [Info] transport/internet/splithttp: failed to send upload, bad status code:500 Internal Server Error
2024/06/21 23:50:06 [Info] transport/internet/splithttp: failed to send upload, bad status code:500 Internal Server Error
2024/06/21 23:50:06 [Info] transport/internet/splithttp: failed to send upload, bad status code:500 Internal Server Error
2024/06/21 23:50:06 [Info] transport/internet/splithttp: failed to send upload, bad status code:500 Internal Server Error

vrnobody commented 1 week ago

Here are my findings. Because client upload data concurrently, for some reason, which I have no idea, some packets may be blocked permanently. So the upload queue will be filled up. Eventuality the server print out an error message "packet queue is too large".

I come up with two solutions.

Firt, disable concurrent-upload on client side. The code is https://github.com/vrnobody/xraycore/commit/cecbc2b574e5c2b521497c983615e8dc2b384934 which is targeting v1.8.15.

The second one is a little bit complicated. On the server side:

put packet with seqID smaller than (nextSeq + bufferSize) into upload queue
block other request, which do not meet the above requirement
after reader read from upload queue send an unblock signal
goto step 1

Here is a sample code https://github.com/vrnobody/xraycore/commit/a93adb5caf75996a6bd8690fcd513cf2c08d6d9e Targeting v1.8.15 too.

On my computer, both solutions are about 10% slower. I personally prefer the first one. It is much simpler.

mmmray commented 1 week ago

i think it is reasonable to say, when the user sets maxConcurrentUploads == 1, we

disable all the concurrency hacks on the client. I don't just mean the concurrent upload as you patched it, I also mean this thing which may also materialize as concurrency on the server, as it does not read the HTTP response
do not build any reassembly buffer at all. instead, chunks are written directly. we trust that the client waits for 200 OK to preserve ordering.

The problem I have with this is that it's only a workaround, there is a bug we don't understand.

block other request, which do not meet the above requirement

BTW. What happens if you set maxConcurrentUploads == 2000 on the server, and keep it at 10 (or 20) on the client?

vrnobody commented 1 week ago

After setting maxConcurrentUploads to 2000 on the server side with v1.8.16. Memory usage goes up to 5G and more. The bright side is disconnection problem disappeared. But network speed is not stable.

iperf3 -c 127.0.0.1 -p 6003 -t 120 -P 2

- - - - - - - - - - - - - - - - - - - - - - - - -
[  5]  70.73-87.47  sec  1.61 GBytes   824 Mbits/sec
[  7]  70.73-87.47  sec   920 MBytes   461 Mbits/sec
[SUM]  70.73-87.47  sec  2.50 GBytes  1.29 Gbits/sec
- - - - - - - - - - - - - - - - - - - - - - - - -
[  5]  87.47-96.02  sec   278 MBytes   273 Mbits/sec
[  7]  87.47-96.02  sec   304 MBytes   298 Mbits/sec
[SUM]  87.47-96.02  sec   582 MBytes   571 Mbits/sec
- - - - - - - - - - - - - - - - - - - - - - - - -
[  5]  96.02-99.31  sec   111 MBytes   283 Mbits/sec
[  7]  96.02-99.31  sec   117 MBytes   298 Mbits/sec
[SUM]  96.02-99.31  sec   227 MBytes   581 Mbits/sec
- - - - - - - - - - - - - - - - - - - - - - - - -
[  5]  99.31-103.95 sec  57.0 MBytes   103 Mbits/sec
[  7]  99.31-103.95 sec  69.5 MBytes   125 Mbits/sec
[SUM]  99.31-103.95 sec   126 MBytes   228 Mbits/sec
- - - - - - - - - - - - - - - - - - - - - - - - -
[  5] 104.00-105.55 sec  5.00 MBytes  27.1 Mbits/sec
[  7] 104.00-105.55 sec  7.50 MBytes  40.6 Mbits/sec
[SUM] 104.00-105.55 sec  12.5 MBytes  67.7 Mbits/sec
- - - - - - - - - - - - - - - - - - - - - - - - -
[  5] 105.55-112.30 sec   184 MBytes   228 Mbits/sec
[  7] 105.55-112.30 sec   275 MBytes   342 Mbits/sec
[SUM] 105.55-112.30 sec   459 MBytes   570 Mbits/sec
- - - - - - - - - - - - - - - - - - - - - - - - -
[  5] 112.30-118.06 sec   130 MBytes   189 Mbits/sec
[  7] 112.30-118.06 sec   236 MBytes   343 Mbits/sec
[SUM] 112.30-118.06 sec   365 MBytes   532 Mbits/sec
- - - - - - - - - - - - - - - - - - - - - - - - -
[  5] 118.06-125.12 sec   272 MBytes   323 Mbits/sec
[  7] 118.06-125.12 sec   260 MBytes   310 Mbits/sec
[SUM] 118.06-125.12 sec   532 MBytes   633 Mbits/sec
- - - - - - - - - - - - - - - - - - - - - - - - -
[  5] 125.12-131.00 sec   151 MBytes   215 Mbits/sec
[  7] 125.12-131.00 sec   135 MBytes   193 Mbits/sec
[SUM] 125.12-131.00 sec   286 MBytes   408 Mbits/sec
- - - - - - - - - - - - - - - - - - - - - - - - -
[  5] 131.00-135.49 sec   352 MBytes   658 Mbits/sec
[  7] 131.00-135.49 sec   239 MBytes   447 Mbits/sec
[SUM] 131.00-135.49 sec   591 MBytes  1.10 Gbits/sec
- - - - - - - - - - - - - - - - - - - - - - - - -
[  5] 135.49-142.05 sec   474 MBytes   606 Mbits/sec
[  7] 135.49-142.05 sec   552 MBytes   706 Mbits/sec
[SUM] 135.49-142.05 sec  1.00 GBytes  1.31 Gbits/sec
- - - - - - - - - - - - - - - - - - - - - - - - -

vrnobody commented 5 days ago

In order to figure out what is happening, I add some logging code to v1.8.15. https://github.com/vrnobody/xraycore/commit/0e2f8effded5daf2d760d70ed26852690d7f99a8

There is nothing interesting on the client side, so the following discussion is focusing on the server side. Let's take one request to explain what those logs mean.

// handle one client request with seq=2
2024/06/26 13:54:26 [Error] transport/internet/splithttp: handling: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=2

// read req.Body into variable "payload"
2024/06/26 13:54:26 [Error] transport/internet/splithttp: reading body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=2
2024/06/26 13:54:26 [Error] transport/internet/splithttp: readed body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=2 len: 8k

// push Packet into uploadQueue.pushedPackets
2024/06/26 13:54:26 [Error] transport/internet/splithttp: push: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=2
2024/06/26 13:54:26 [Error] transport/internet/splithttp: pushed: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=2

// client request handling finished
2024/06/26 13:54:26 [Error] transport/internet/splithttp: handled: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=2

// reader take one packet from uploadQueue.pushedPackets
2024/06/26 13:54:26 [Error] transport/internet/splithttp: pop: 9f16ef94-2abf-4643-a509-32d4ab082e6b with seq: 2

The full server log is too long, so I filter out the unimportant parts.

cat log-serv.txt | grep "9f16ef94" | grep -e "reading" -e "pushed" -e "pop" -e "readed" -e "dump" -- > log-sim.txt

Let's focus on seq=421 and seq=423

2024/06/26 13:54:31 [Error] transport/internet/splithttp: reading body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=420
2024/06/26 13:54:31 [Error] transport/internet/splithttp: readed body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=420 len: 16k
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pushed: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=420
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pop: 9f16ef94-2abf-4643-a509-32d4ab082e6b with seq: 420

// seq=421 begin to read req.Body
2024/06/26 13:54:31 [Error] transport/internet/splithttp: reading body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=421

// other requests arrived and are pushed into uploadQueue.pushedPackets
2024/06/26 13:54:31 [Error] transport/internet/splithttp: readed body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=413 len: 984k
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pushed: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=413
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pop: 9f16ef94-2abf-4643-a509-32d4ab082e6b with seq: 413
2024/06/26 13:54:31 [Error] transport/internet/splithttp: readed body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=412 len: 984k
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pushed: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=412
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pop: 9f16ef94-2abf-4643-a509-32d4ab082e6b with seq: 412
2024/06/26 13:54:31 [Error] transport/internet/splithttp: readed body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=416 len: 984k
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pushed: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=416
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pop: 9f16ef94-2abf-4643-a509-32d4ab082e6b with seq: 416
2024/06/26 13:54:31 [Error] transport/internet/splithttp: reading body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=424

// seq=423 is similar to seq=421
2024/06/26 13:54:31 [Error] transport/internet/splithttp: reading body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=423

2024/06/26 13:54:31 [Error] transport/internet/splithttp: reading body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=422
2024/06/26 13:54:31 [Error] transport/internet/splithttp: readed body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=411 len: 984k
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pushed: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=411
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pop: 9f16ef94-2abf-4643-a509-32d4ab082e6b with seq: 411
2024/06/26 13:54:31 [Error] transport/internet/splithttp: readed body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=424 len: 16k
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pushed: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=424
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pop: 9f16ef94-2abf-4643-a509-32d4ab082e6b with seq: 424
2024/06/26 13:54:31 [Error] transport/internet/splithttp: readed body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=410 len: 984k
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pushed: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=410
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pop: 9f16ef94-2abf-4643-a509-32d4ab082e6b with seq: 410
2024/06/26 13:54:31 [Error] transport/internet/splithttp: reading body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=426
2024/06/26 13:54:31 [Error] transport/internet/splithttp: readed body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=419 len: 752k
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pushed: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=419
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pop: 9f16ef94-2abf-4643-a509-32d4ab082e6b with seq: 419
2024/06/26 13:54:31 [Error] transport/internet/splithttp: reading body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=425
2024/06/26 13:54:31 [Error] transport/internet/splithttp: readed body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=418 len: 16k
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pushed: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=418
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pop: 9f16ef94-2abf-4643-a509-32d4ab082e6b with seq: 418
2024/06/26 13:54:31 [Error] transport/internet/splithttp: readed body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=417 len: 984k
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pushed: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=417
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pop: 9f16ef94-2abf-4643-a509-32d4ab082e6b with seq: 417
2024/06/26 13:54:31 [Error] transport/internet/splithttp: reading body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=427
2024/06/26 13:54:31 [Error] transport/internet/splithttp: reading body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=428
2024/06/26 13:54:31 [Error] transport/internet/splithttp: reading body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=429
2024/06/26 13:54:31 [Error] transport/internet/splithttp: reading body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=430
2024/06/26 13:54:31 [Error] transport/internet/splithttp: readed body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=425 len: 984k
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pushed: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=425
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pop: 9f16ef94-2abf-4643-a509-32d4ab082e6b with seq: 425
2024/06/26 13:54:31 [Error] transport/internet/splithttp: readed body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=408 len: 984k
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pushed: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=408
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pop: 9f16ef94-2abf-4643-a509-32d4ab082e6b with seq: 408
2024/06/26 13:54:31 [Error] transport/internet/splithttp: readed body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=430 len: 16k
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pushed: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=430

// seq=423 read in time and is pushed into uploadQueue.pushedPackets
2024/06/26 13:54:31 [Error] transport/internet/splithttp: readed body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=423 len: 984k
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pushed: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=423
2024/06/26 13:54:31 [Error] transport/internet/splithttp: reading body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=432
2024/06/26 13:54:31 [Error] transport/internet/splithttp: reading body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=431
2024/06/26 13:54:31 [Error] transport/internet/splithttp: reading body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=434
2024/06/26 13:54:31 [Error] transport/internet/splithttp: reading body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=433
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pop: 9f16ef94-2abf-4643-a509-32d4ab082e6b with seq: 430
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pop: 9f16ef94-2abf-4643-a509-32d4ab082e6b with seq: 423

2024/06/26 13:54:31 [Error] transport/internet/splithttp: readed body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=422 len: 984k
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pushed: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=422
2024/06/26 13:54:31 [Error] transport/internet/splithttp: readed body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=427 len: 984k
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pop: 9f16ef94-2abf-4643-a509-32d4ab082e6b with seq: 422
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pushed: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=427
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pop: 9f16ef94-2abf-4643-a509-32d4ab082e6b with seq: 427
2024/06/26 13:54:31 [Error] transport/internet/splithttp: readed body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=431 len: 984k
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pushed: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=431
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pop: 9f16ef94-2abf-4643-a509-32d4ab082e6b with seq: 431
2024/06/26 13:54:31 [Error] transport/internet/splithttp: reading body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=435
2024/06/26 13:54:31 [Error] transport/internet/splithttp: reading body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=436
2024/06/26 13:54:31 [Error] transport/internet/splithttp: readed body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=435 len: 16k
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pushed: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=435
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pop: 9f16ef94-2abf-4643-a509-32d4ab082e6b with seq: 435
2024/06/26 13:54:31 [Error] transport/internet/splithttp: readed body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=426 len: 984k
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pushed: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=426
2024/06/26 13:54:31 [Error] transport/internet/splithttp: reading body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=437
2024/06/26 13:54:31 [Error] transport/internet/splithttp: readed body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=437 len: 16k
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pushed: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=437
2024/06/26 13:54:31 [Error] transport/internet/splithttp: readed body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=433 len: 16k
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pushed: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=433
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pop: 9f16ef94-2abf-4643-a509-32d4ab082e6b with seq: 426
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pop: 9f16ef94-2abf-4643-a509-32d4ab082e6b with seq: 437
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pop: 9f16ef94-2abf-4643-a509-32d4ab082e6b with seq: 433
2024/06/26 13:54:31 [Error] transport/internet/splithttp: reading body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=438
2024/06/26 13:54:31 [Error] transport/internet/splithttp: readed body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=428 len: 984k
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pushed: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=428
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pop: 9f16ef94-2abf-4643-a509-32d4ab082e6b with seq: 428
2024/06/26 13:54:31 [Error] transport/internet/splithttp: reading body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=441
2024/06/26 13:54:31 [Error] transport/internet/splithttp: reading body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=439
2024/06/26 13:54:31 [Error] transport/internet/splithttp: reading body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=442
2024/06/26 13:54:31 [Error] transport/internet/splithttp: reading body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=440
2024/06/26 13:54:31 [Error] transport/internet/splithttp: readed body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=434 len: 984k
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pushed: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=434
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pop: 9f16ef94-2abf-4643-a509-32d4ab082e6b with seq: 434
2024/06/26 13:54:31 [Error] transport/internet/splithttp: readed body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=438 len: 984k
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pushed: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=438
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pop: 9f16ef94-2abf-4643-a509-32d4ab082e6b with seq: 438
2024/06/26 13:54:31 [Error] transport/internet/splithttp: reading body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=444
2024/06/26 13:54:31 [Error] transport/internet/splithttp: reading body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=443
2024/06/26 13:54:31 [Error] transport/internet/splithttp: readed body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=429 len: 984k
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pushed: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=429
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pop: 9f16ef94-2abf-4643-a509-32d4ab082e6b with seq: 429
2024/06/26 13:54:31 [Error] transport/internet/splithttp: readed body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=442 len: 16k
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pushed: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=442
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pop: 9f16ef94-2abf-4643-a509-32d4ab082e6b with seq: 442
2024/06/26 13:54:31 [Error] transport/internet/splithttp: reading body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=446
2024/06/26 13:54:31 [Error] transport/internet/splithttp: reading body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=445
2024/06/26 13:54:31 [Error] transport/internet/splithttp: readed body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=443 len: 16k
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pushed: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=443
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pop: 9f16ef94-2abf-4643-a509-32d4ab082e6b with seq: 443
2024/06/26 13:54:31 [Error] transport/internet/splithttp: readed body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=436 len: 984k
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pushed: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=436
2024/06/26 13:54:31 [Error] transport/internet/splithttp: readed body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=444 len: 984k
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pushed: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=444
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pop: 9f16ef94-2abf-4643-a509-32d4ab082e6b with seq: 436
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pop: 9f16ef94-2abf-4643-a509-32d4ab082e6b with seq: 444
2024/06/26 13:54:31 [Error] transport/internet/splithttp: reading body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=448
2024/06/26 13:54:31 [Error] transport/internet/splithttp: reading body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=449
2024/06/26 13:54:31 [Error] transport/internet/splithttp: reading body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=447
2024/06/26 13:54:31 [Error] transport/internet/splithttp: readed body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=447 len: 16k
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pushed: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=447
2024/06/26 13:54:31 [Error] transport/internet/splithttp: readed body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=440 len: 984k
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pushed: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=440
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pop: 9f16ef94-2abf-4643-a509-32d4ab082e6b with seq: 447
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pop: 9f16ef94-2abf-4643-a509-32d4ab082e6b with seq: 440
2024/06/26 13:54:31 [Error] transport/internet/splithttp: reading body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=451
2024/06/26 13:54:31 [Error] transport/internet/splithttp: reading body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=450
2024/06/26 13:54:31 [Error] transport/internet/splithttp: readed body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=432 len: 984k
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pushed: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=432
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pop: 9f16ef94-2abf-4643-a509-32d4ab082e6b with seq: 432

// packet queue is too large error
2024/06/26 13:54:31 [Error] transport/internet/splithttp: dump session: 9f16ef94-2abf-4643-a509-32d4ab082e6b seq: 421 heap size: 21 chan size: 0

2024/06/26 13:54:31 [Error] transport/internet/splithttp: readed body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=451 len: 984k
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pushed: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=451

// unfortunately, the uploadQueue is full before seq=421 is finished reading.
2024/06/26 13:54:31 [Error] transport/internet/splithttp: readed body: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=421 len: 984k
2024/06/26 13:54:31 [Error] transport/internet/splithttp: pushed: /?session=9f16ef94-2abf-4643-a509-32d4ab082e6b&seq=421

Full server log is here. log-serv.txt

RPRX commented 10 hours ago

@mmmray 有进展吗

mmmray commented 9 hours ago

I can look into it next week.

@vrnobody Sorry for the lack of reply, I forgot to write, I didn't understand the logs or what pattern you were seeing in them, are you saying that with certain requests like 421, the request body Read is hanging?

XTLS / Xray-core