search

SagerNet / sing-box

The universal proxy platform
https://sing-box.sagernet.org/
Other
20k stars 2.38k forks source link

shadowsocks inbound会大概率发生无法连接问题 #389

Closed zakuwaki closed 1 year ago

zakuwaki commented 1 year ago

Welcome

Description of the problem

Version of sing-box

```console $ sing-box version sing-box version 1.2-beta5 Environment: go1.20.1 linux/amd64 Tags: with_utls,with_reality_server,with_gvisor,with_wireguard,with_clash_api Revision: 5ce3ddee9be640c309a23341951434861dc4c2e0 CGO: disabled ```

Server and client configuration file

server config

```json { "inbounds": [ { "tag": "shadowsocks", "type": "shadowsocks", "listen": "0.0.0.0", "listen_port": 11111, "sniff": true, "sniff_override_destination": true, "domain_strategy": "ipv4_only", "proxy_protocol": true, "proxy_protocol_accept_no_header": true, "method": "chacha20-ietf-poly1305", "password": "MyShadowSocks" } ] } ```

Server and client log file

After run curl -x socks5://127.0.0.1:11080 baidu.com 10 times in client.

server log

```console INFO[0000] inbound/shadowsocks[shadowsocks]: tcp server started at 0.0.0.0:11111 DEBUG[0000] inbound/shadowsocks[shadowsocks]: proxy protocol enabled INFO[0000] inbound/shadowsocks[shadowsocks]: udp server started at 0.0.0.0:11111 INFO[0000] sing-box started (0.00s) INFO[0016] [1669360279] inbound/shadowsocks[shadowsocks]: inbound connection from 172.16.16.10:54887 ERROR[0016] [1669360279] inbound/shadowsocks[shadowsocks]: process connection from 172.16.16.10:54887: shadowsocks: serve TCP from 172.16.16.10:54887: bad header INFO[0025] [3236578734] inbound/shadowsocks[shadowsocks]: inbound connection from 172.16.16.10:54891 INFO[0025] [1450153818] inbound/shadowsocks[shadowsocks]: inbound connection to baidu.com:80 DEBUG[0025] [1450153818] router: sniffed protocol: http, domain: baidu.com DEBUG[0025] [1450153818] dns: lookup domain baidu.com INFO[0025] [1450153818] dns: lookup succeed for baidu.com: 39.156.66.10 110.242.68.66 DEBUG[0025] [1450153818] dns: resolved [39.156.66.10 110.242.68.66] INFO[0025] [1450153818] outbound/direct: outbound connection to baidu.com:80 INFO[0027] [1412197415] inbound/shadowsocks[shadowsocks]: inbound connection from 172.16.16.10:54893 INFO[0027] [3506050020] inbound/shadowsocks[shadowsocks]: inbound connection to baidu.com:80 DEBUG[0027] [3506050020] router: sniffed protocol: http, domain: baidu.com DEBUG[0027] [3506050020] dns: lookup domain baidu.com INFO[0027] [3506050020] dns: lookup succeed for baidu.com: 39.156.66.10 110.242.68.66 DEBUG[0027] [3506050020] dns: resolved [39.156.66.10 110.242.68.66] INFO[0027] [3506050020] outbound/direct: outbound connection to baidu.com:80 INFO[0028] [1184179253] inbound/shadowsocks[shadowsocks]: inbound connection from 172.16.16.10:54895 ERROR[0028] [1184179253] inbound/shadowsocks[shadowsocks]: process connection from 172.16.16.10:54895: shadowsocks: serve TCP from 172.16.16.10:54895: bad header DEBUG[0030] [3236578734] inbound/shadowsocks[shadowsocks]: connection closed: process connection from 172.16.16.10:54891: shadowsocks: serve TCP from 172.16.16.10:54891: upload: EOF | download: EOF DEBUG[0032] [1412197415] inbound/shadowsocks[shadowsocks]: connection closed: process connection from 172.16.16.10:54893: shadowsocks: serve TCP from 172.16.16.10:54893: upload: EOF | download: EOF INFO[0039] [3865879120] inbound/shadowsocks[shadowsocks]: inbound connection from 172.16.16.10:54897 INFO[0039] [351637647] inbound/shadowsocks[shadowsocks]: inbound connection to baidu.com:80 DEBUG[0039] [351637647] router: sniffed protocol: http, domain: baidu.com DEBUG[0039] [351637647] dns: lookup domain baidu.com INFO[0039] [351637647] dns: lookup succeed for baidu.com: 39.156.66.10 110.242.68.66 DEBUG[0039] [351637647] dns: resolved [39.156.66.10 110.242.68.66] INFO[0039] [351637647] outbound/direct: outbound connection to baidu.com:80 INFO[0041] [3333398797] inbound/shadowsocks[shadowsocks]: inbound connection from 172.16.16.10:54899 INFO[0041] [1395405936] inbound/shadowsocks[shadowsocks]: inbound connection to baidu.com:80 DEBUG[0041] [1395405936] router: sniffed protocol: http, domain: baidu.com DEBUG[0041] [1395405936] dns: lookup domain baidu.com INFO[0041] [1395405936] dns: lookup succeed for baidu.com: 39.156.66.10 110.242.68.66 DEBUG[0041] [1395405936] dns: resolved [39.156.66.10 110.242.68.66] INFO[0041] [1395405936] outbound/direct: outbound connection to baidu.com:80 INFO[0041] [1941823927] inbound/shadowsocks[shadowsocks]: inbound connection from 172.16.16.10:54901 INFO[0041] [1093581788] inbound/shadowsocks[shadowsocks]: inbound connection to baidu.com:80 DEBUG[0041] [1093581788] router: sniffed protocol: http, domain: baidu.com DEBUG[0041] [1093581788] dns: lookup domain baidu.com INFO[0041] [1093581788] dns: lookup succeed for baidu.com: 39.156.66.10 110.242.68.66 DEBUG[0041] [1093581788] dns: resolved [39.156.66.10 110.242.68.66] INFO[0041] [1093581788] outbound/direct: outbound connection to baidu.com:80 INFO[0042] [726119205] inbound/shadowsocks[shadowsocks]: inbound connection from 172.16.16.10:54903 INFO[0042] [1288538890] inbound/shadowsocks[shadowsocks]: inbound connection to baidu.com:80 DEBUG[0042] [1288538890] router: sniffed protocol: http, domain: baidu.com DEBUG[0042] [1288538890] dns: lookup domain baidu.com INFO[0042] [1288538890] dns: lookup succeed for baidu.com: 39.156.66.10 110.242.68.66 DEBUG[0042] [1288538890] dns: resolved [39.156.66.10 110.242.68.66] INFO[0042] [1288538890] outbound/direct: outbound connection to baidu.com:80 INFO[0043] [1296311414] inbound/shadowsocks[shadowsocks]: inbound connection from 172.16.16.10:54905 ERROR[0043] [1296311414] inbound/shadowsocks[shadowsocks]: process connection from 172.16.16.10:54905: shadowsocks: serve TCP from 172.16.16.10:54905: bad header DEBUG[0045] [3865879120] inbound/shadowsocks[shadowsocks]: connection closed: process connection from 172.16.16.10:54897: shadowsocks: serve TCP from 172.16.16.10:54897: upload: EOF | download: EOF DEBUG[0046] [3333398797] inbound/shadowsocks[shadowsocks]: connection closed: process connection from 172.16.16.10:54899: shadowsocks: serve TCP from 172.16.16.10:54899: upload: EOF | download: EOF DEBUG[0047] [1941823927] inbound/shadowsocks[shadowsocks]: connection closed: process connection from 172.16.16.10:54901: shadowsocks: serve TCP from 172.16.16.10:54901: upload: EOF | download: EOF DEBUG[0047] [726119205] inbound/shadowsocks[shadowsocks]: connection closed: process connection from 172.16.16.10:54903: shadowsocks: serve TCP from 172.16.16.10:54903: upload: EOF | download: EOF ```
zakuwaki commented 1 year ago

@nekohasekai Full log updated, please check.

zakuwaki commented 1 year ago

猜测和proxyproto有关

  1. 关闭proxyproto，代理正常
  2. 开启proxyproto且开启AcceptNoHeader，前置使用frp代理（开启proxyproto），正常
  3. 开启proxyproto且开启AcceptNoHeader，直接连接，大概率发生bad header错误
zakuwaki commented 1 year ago

准备抽时间review一下go-proxyproto库

nekohasekai commented 1 year ago

proxyprotocol 与 shadowsocks 2022 冲突了。

我认为这是预期的行为，并且似乎没有需要同时启用两者的场景。

zakuwaki commented 1 year ago

cc @nekohasekai

update: 这里写bug了

https://github.com/SagerNet/sing/blob/9fab0a9f430498ccf5c3af86284c22cfbcc0775c/common/bufio/cache.go#L31

https://github.com/SagerNet/sing-shadowsocks/blob/59babbdfa595082c71e45960ba3a2307ee1a02f8/shadowaead/service.go#L97

观测到一个现象，proxyproto返回的错误都是proxyproto.ErrNoProxyProtocol，这个是符合预期的，因为此时只会Peek而非Read这里的bufReader

https://github.com/SagerNet/sing-box/blob/8151bcfd6b25a960ab52956531bc3021f119cee0/common/proxyproto/listener.go#L24

然后打印bufReader.Buffered()时，发现当值为32的时候，会引发shadowsocks bad header的错误

```console ./sing-box/sing-box-linux run -c server.json INFO[0000] inbound/shadowsocks[shadowsocks]: tcp server started at 0.0.0.0:11111 DEBUG[0000] inbound/shadowsocks[shadowsocks]: proxy protocol enabled INFO[0000] inbound/shadowsocks[shadowsocks]: udp server started at 0.0.0.0:11111 INFO[0000] sing-box started (0.00s) bufReader.Buffered(): 73 INFO[0002] [1826390410] inbound/shadowsocks[shadowsocks]: inbound connection from 127.0.0.1:59214 INFO[0002] [2752276131] inbound/shadowsocks[shadowsocks]: inbound connection to 192.168.1.2:7500 DEBUG[0002] [2752276131] router: sniffed protocol: http, domain: 192.168.1.2:7500 INFO[0002] [2752276131] outbound/direct: outbound connection to 192.168.1.2:7500 bufReader.Buffered(): 187 INFO[0005] [1196959689] inbound/shadowsocks[shadowsocks]: inbound connection from 127.0.0.1:42350 INFO[0005] [4135582938] inbound/shadowsocks[shadowsocks]: inbound connection to 192.168.1.2:7500 DEBUG[0005] [4135582938] router: sniffed protocol: http, domain: 192.168.1.2:7500 INFO[0005] [4135582938] outbound/direct: outbound connection to 192.168.1.2:7500 DEBUG[0007] [1826390410] inbound/shadowsocks[shadowsocks]: connection closed: process connection from 127.0.0.1:59214: shadowsocks: serve TCP from 127.0.0.1:59214: upload: EOF | download: EOF DEBUG[0010] [1196959689] inbound/shadowsocks[shadowsocks]: connection closed: process connection from 127.0.0.1:42350: shadowsocks: serve TCP from 127.0.0.1:42350: download: EOF | upload: EOF bufReader.Buffered(): 73 INFO[0012] [3747199149] inbound/shadowsocks[shadowsocks]: inbound connection from 127.0.0.1:42356 INFO[0012] [3376685688] inbound/shadowsocks[shadowsocks]: inbound connection to 192.168.1.2:7500 DEBUG[0012] [3376685688] router: sniffed protocol: http, domain: 192.168.1.2:7500 INFO[0012] [3376685688] outbound/direct: outbound connection to 192.168.1.2:7500 bufReader.Buffered(): 73 INFO[0015] [4270936520] inbound/shadowsocks[shadowsocks]: inbound connection from 127.0.0.1:56630 INFO[0015] [4291108170] inbound/shadowsocks[shadowsocks]: inbound connection to 192.168.1.2:7500 DEBUG[0015] [4291108170] router: sniffed protocol: http, domain: 192.168.1.2:7500 INFO[0015] [4291108170] outbound/direct: outbound connection to 192.168.1.2:7500 bufReader.Buffered(): 32 INFO[0016] [1560412478] inbound/shadowsocks[shadowsocks]: inbound connection from 127.0.0.1:56646 ERROR[0016] [1560412478] inbound/shadowsocks[shadowsocks]: process connection from 127.0.0.1:56646: shadowsocks: serve TCP from 127.0.0.1:56646: bad header DEBUG[0017] [3747199149] inbound/shadowsocks[shadowsocks]: connection closed: process connection from 127.0.0.1:42356: shadowsocks: serve TCP from 127.0.0.1:42356: upload: EOF | download: EOF DEBUG[0020] [4270936520] inbound/shadowsocks[shadowsocks]: connection closed: process connection from 127.0.0.1:56630: shadowsocks: serve TCP from 127.0.0.1:56630: upload: EOF | download: EOF bufReader.Buffered(): 73 INFO[0022] [925753815] inbound/shadowsocks[shadowsocks]: inbound connection from 127.0.0.1:56658 INFO[0022] [2551408035] inbound/shadowsocks[shadowsocks]: inbound connection to 192.168.1.2:7500 DEBUG[0022] [2551408035] router: sniffed protocol: http, domain: 192.168.1.2:7500 INFO[0022] [2551408035] outbound/direct: outbound connection to 192.168.1.2:7500 bufReader.Buffered(): 73 INFO[0022] [473422139] inbound/shadowsocks[shadowsocks]: inbound connection from 127.0.0.1:56662 INFO[0022] [2732474225] inbound/shadowsocks[shadowsocks]: inbound connection to 192.168.1.2:7500 DEBUG[0022] [2732474225] router: sniffed protocol: http, domain: 192.168.1.2:7500 INFO[0022] [2732474225] outbound/direct: outbound connection to 192.168.1.2:7500 bufReader.Buffered(): 187 INFO[0023] [4272009832] inbound/shadowsocks[shadowsocks]: inbound connection from 127.0.0.1:56672 INFO[0023] [958959604] inbound/shadowsocks[shadowsocks]: inbound connection to 192.168.1.2:7500 DEBUG[0023] [958959604] router: sniffed protocol: http, domain: 192.168.1.2:7500 INFO[0023] [958959604] outbound/direct: outbound connection to 192.168.1.2:7500 bufReader.Buffered(): 73 INFO[0024] [2920983564] inbound/shadowsocks[shadowsocks]: inbound connection from 127.0.0.1:56688 INFO[0024] [130902130] inbound/shadowsocks[shadowsocks]: inbound connection to 192.168.1.2:7500 DEBUG[0024] [130902130] router: sniffed protocol: http, domain: 192.168.1.2:7500 INFO[0024] [130902130] outbound/direct: outbound connection to 192.168.1.2:7500 bufReader.Buffered(): 73 INFO[0024] [3863091621] inbound/shadowsocks[shadowsocks]: inbound connection from 127.0.0.1:56698 INFO[0024] [1349939965] inbound/shadowsocks[shadowsocks]: inbound connection to 192.168.1.2:7500 DEBUG[0024] [1349939965] router: sniffed protocol: http, domain: 192.168.1.2:7500 INFO[0024] [1349939965] outbound/direct: outbound connection to 192.168.1.2:7500 bufReader.Buffered(): 73 INFO[0025] [3987505104] inbound/shadowsocks[shadowsocks]: inbound connection from 127.0.0.1:36342 INFO[0025] [1155606959] inbound/shadowsocks[shadowsocks]: inbound connection to 192.168.1.2:7500 DEBUG[0025] [1155606959] router: sniffed protocol: http, domain: 192.168.1.2:7500 INFO[0025] [1155606959] outbound/direct: outbound connection to 192.168.1.2:7500 bufReader.Buffered(): 73 INFO[0026] [766814299] inbound/shadowsocks[shadowsocks]: inbound connection from 127.0.0.1:36354 INFO[0026] [3070898319] inbound/shadowsocks[shadowsocks]: inbound connection to 192.168.1.2:7500 DEBUG[0026] [3070898319] router: sniffed protocol: http, domain: 192.168.1.2:7500 INFO[0026] [3070898319] outbound/direct: outbound connection to 192.168.1.2:7500 bufReader.Buffered(): 73 INFO[0026] [4254985195] inbound/shadowsocks[shadowsocks]: inbound connection from 127.0.0.1:36368 INFO[0026] [3837274179] inbound/shadowsocks[shadowsocks]: inbound connection to 192.168.1.2:7500 DEBUG[0026] [3837274179] router: sniffed protocol: http, domain: 192.168.1.2:7500 INFO[0026] [3837274179] outbound/direct: outbound connection to 192.168.1.2:7500 DEBUG[0027] [925753815] inbound/shadowsocks[shadowsocks]: connection closed: process connection from 127.0.0.1:56658: shadowsocks: serve TCP from 127.0.0.1:56658: upload: EOF | download: EOF bufReader.Buffered(): 73 INFO[0027] [3623672902] inbound/shadowsocks[shadowsocks]: inbound connection from 127.0.0.1:36380 INFO[0027] [3493904884] inbound/shadowsocks[shadowsocks]: inbound connection to 192.168.1.2:7500 DEBUG[0027] [3493904884] router: sniffed protocol: http, domain: 192.168.1.2:7500 INFO[0027] [3493904884] outbound/direct: outbound connection to 192.168.1.2:7500 DEBUG[0027] [473422139] inbound/shadowsocks[shadowsocks]: connection closed: process connection from 127.0.0.1:56662: shadowsocks: serve TCP from 127.0.0.1:56662: upload: EOF | download: EOF bufReader.Buffered(): 32 INFO[0028] [679004201] inbound/shadowsocks[shadowsocks]: inbound connection from 127.0.0.1:36382 ERROR[0028] [679004201] inbound/shadowsocks[shadowsocks]: process connection from 127.0.0.1:36382: shadowsocks: serve TCP from 127.0.0.1:36382: bad header DEBUG[0028] [4272009832] inbound/shadowsocks[shadowsocks]: connection closed: process connection from 127.0.0.1:56672: shadowsocks: serve TCP from 127.0.0.1:56672: upload: EOF | download: EOF DEBUG[0029] [2920983564] inbound/shadowsocks[shadowsocks]: connection closed: process connection from 127.0.0.1:56688: shadowsocks: serve TCP from 127.0.0.1:56688: upload: EOF | download: EOF DEBUG[0029] [3863091621] inbound/shadowsocks[shadowsocks]: connection closed: process connection from 127.0.0.1:56698: shadowsocks: serve TCP from 127.0.0.1:56698: upload: EOF | download: EOF DEBUG[0030] [3987505104] inbound/shadowsocks[shadowsocks]: connection closed: process connection from 127.0.0.1:36342: shadowsocks: serve TCP from 127.0.0.1:36342: upload: EOF | download: EOF DEBUG[0031] [766814299] inbound/shadowsocks[shadowsocks]: connection closed: process connection from 127.0.0.1:36354: shadowsocks: serve TCP from 127.0.0.1:36354: download: EOF | upload: EOF DEBUG[0031] [4254985195] inbound/shadowsocks[shadowsocks]: connection closed: process connection from 127.0.0.1:36368: shadowsocks: serve TCP from 127.0.0.1:36368: download: EOF | upload: EOF DEBUG[0032] [3623672902] inbound/shadowsocks[shadowsocks]: connection closed: process connection from 127.0.0.1:36380: shadowsocks: serve TCP from 127.0.0.1:36380: upload: EOF | download: EOF ```

初步分析是和这里有关

https://github.com/SagerNet/sing-box/blob/8151bcfd6b25a960ab52956531bc3021f119cee0/common/proxyproto/listener.go#L30-L35

当我在L28后插入下列代码时，相关的问题不在复现

    _, err = bufReader.Peek(64)
    if err != nil {
        return nil, err
    }
zakuwaki commented 1 year ago

针对sing的设计问题，发起了一个mr https://github.com/SagerNet/sing/pull/23

Wq2021hz commented 10 months ago

與shadowsocket衝突