heiher/hev-socks5-tproxy

`[E] socks5 tproxy udp addr` confusing log message

cattyhouse opened this issue · 23 comments

cattyhouse commented

when start hev-socks5-tproxy with this config:

socks5:
  port: 1080
  address: 127.0.0.1
  # Socks5 UDP relay mode (tcp|udp)
  udp: 'udp'
  # Socks5 server username
  #username: 'username'
  # Socks5 server password
  #password: 'password'
  # Socket mark
  #mark: 438

tcp:
  port: 1081
  address: '127.0.0.1'

udp:
  port: 1081
  address: '127.0.0.1'

# Redirect DNS to local server on gateway
#   [address]:port <-> [upstream]:53 (dnsmasq)
#dns:
  # DNS port
  #port: 1053
  # DNS address
  #address: '::'
  # DNS upstream
  #upstream: 127.0.0.1

misc:
#  task-stack-size: 8192 # task stack size (bytes)
#  connect-timeout: 5000 # connect timeout (ms)
#  read-write-timeout: 60000 # read-write timeout (ms)
#  log-file: stderr # stdout or file-path
  log-level: error # debug, info or warn or error
#  pid-file: /run/hev-socks5-tproxy.pid
  limit-nofile: 65535

upstream socks5 server is provided by pagefault's trojan-r client, everything works as expected. but hev-socks5-tproxy's log [E] socks5 tproxy udp addr is confusing, why is this an [E] error log?

by the way, i build hev-socks5-tproxy with this version: 6a85b48

cattyhouse commented

it from here? does it indicate something went wrong?

hev-socks5-tproxy/src/hev-socks5-tproxy.c

Line 139 in 6a85b48

LOG_E ("socks5 tproxy udp addr");

cattyhouse commented

another related question:

if change udp: 'udp' to udp: 'tcp', i know this mode only works with hev-socks5-server, it does not work with trojan-r socks5 listening. when sending a udp packet like dig @1.1.1.1 example.com (udp packet), hev-socks5-tproxy just exit with Segmentation fault, i know it will fail, but that could be handled better with some error message instead of exit with seg fault. (side note, in this case trojan-r log shows: socks: unsupported command 0x5), just some thoughts, not a big issue if one knows how to configure the udp: parameter.

heiher commented

it from here? does it indicate something went wrong?

hev-socks5-tproxy/src/hev-socks5-tproxy.c

Line 139 in 6a85b48

LOG_E ("socks5 tproxy udp addr");

This error message from the DNS part. I'll add a condition to skip trying to start the DNS task if it does not exist.

heiher commented

another related question:

if change udp: 'udp' to udp: 'tcp', i know this mode only works with hev-socks5-server, it does not work with trojan-r socks5 listening. when sending a udp packet like dig @1.1.1.1 example.com (udp packet), hev-socks5-tproxy just exit with Segmentation fault, i know it will fail, but that could be handled better with some error message instead of exit with seg fault. (side note, in this case trojan-r log shows: socks: unsupported command 0x5), just some thoughts, not a big issue if one knows how to configure the udp: parameter.

Thanks. I'll fix it.

cattyhouse commented

Thanks. I'll fix it.

i found another hev-socks5-tproxy Segmentation fault when upstream socks5 server stopped/killed/quit/no longer listening. can you reproduce this behavior on your side? on : commit 11adf5e .

2.5.2 release was fine, but producing tons of logs (20000+) in a short time

heiher commented

Thanks. I'll fix it.

i found another hev-socks5-tproxy Segmentation fault when upstream socks5 server stopped/killed/quit/no longer listening. can you reproduce this behavior on your side?

on : commit 11adf5e

No, I can't. I also cannot reproduce the above cmd 0x5 unsupported crash.

heiher commented

2.5.2 release was fine, but producing tons of logs (20000+) in a short time

Have you bypass the socks5 server upstream outgoing connections to prevent them from going to tproxy again and getting stuck in an infinite loop?

cattyhouse commented

2.5.2 release was fine, but producing tons of logs (20000+) in a short time

Have you bypass the socks5 server upstream outgoing connections to prevent them from going to tproxy again and getting stuck in an infinite loop?

yes i did that, it is not related to iptables rules.

I mean in this case/steps :

  1. trojan-r socks5 listen : 127.0.0.1:1080
  2. hev tproxy listen 1081, connect to 1080
  3. kill trojan-r
  4. do any network connection, curl example.com

2.5.2 release : producing logs : [E] 0xffffa623ead0 socks5 session connect , [E] 0xffffa623ead0 socks5 client connect. which is expected, not an issue, i can redirect these kind log to /dev/null via systemd service.

commit 11adf5e : Segmentation fault

heiher commented

Could you re-compile hev-socks5-tproxy by follow steps? and upload full logs and core dump file?

make clean
make CFLAGS="-g -O0" STRIP=true -j32
misc:
  log-file: hs5t.log
  log-level: debug
heiher commented

Could you also try hev-socks5-server, does it cause the same crash?

cattyhouse commented

Could you also try hev-socks5-server, does it cause the same crash?

i tested this with systemd-run --scope --slice=bypassproxy.slice ./hev-socks5-server-linux-arm64 ./hev-socks5-server.yml, and i always have iptables -A OUTPUT -m cgroup --path bypassproxy.slice -j RETURN, which means this program will direct connect to internet, when i curl a blocked site like google (with dns cache, so resolving is ok), hev-socks5-server will not be able to connnect to it (due to blocked by great fire wall), after timeout, hev-socks5-server is still running, but hev-socks5-tproxy Segmentation fault.

heiher commented

Could you also try hev-socks5-server, does it cause the same crash?

i tested this with systemd-run --scope --slice=bypassproxy.slice ./hev-socks5-server-linux-arm64 ./hev-socks5-server.yml, and i always have iptables -A OUTPUT -m cgroup --path bypassproxy.slice -j RETURN, which means this program will direct connect to internet, when i curl a blocked site like google (with dns cache, so resolving is ok), hev-socks5-server will not be able to connnect to it (due to blocked by great fire wall), after timeout, hev-socks5-server is still running, but hev-socks5-tproxy Segmentation fault.

Okay. I suggest enabling debug-level logging. If there is a substantial amount of output, it's possible that a loop is still occurring, and the cgroup-based bypass may not be functioning correctly.

cattyhouse commented 
hs5t.log

file hev-socks5-tproxy.debug ; ll hev-socks5-tproxy.debug

hev-socks5-tproxy.debug: ELF 64-bit LSB executable, ARM aarch64, version 1 (SYSV), statically linked, stripped
-rwxr-xr-x 1 root root 708K Jan  6 22:33 hev-socks5-tproxy.debug

all logs:

# cat hs5t.log
[2024-01-06 22:44:28] [D] socks5 tproxy init
[2024-01-06 22:44:28] [D] tsocks cache init
[2024-01-06 22:44:28] [D] socks5 tproxy run
[2024-01-06 22:44:28] [D] socks5 event task run
[2024-01-06 22:44:28] [D] socks5 tcp task run
[2024-01-06 22:44:28] [D] socks5 tproxy tcp socket
[2024-01-06 22:44:28] [D] socks5 udp task run
[2024-01-06 22:44:28] [D] socks5 tproxy udp socket
[2024-01-06 22:44:28] [D] socks5 dns task run
[2024-01-06 22:44:32] [D] socks5 tcp session new
[2024-01-06 22:44:32] [D] 0xffffb499ea30 socks5 construct
[2024-01-06 22:44:32] [D] 0xffffb499ea30 socks5 client construct
[2024-01-06 22:44:32] [D] 0xffffb499ea30 socks5 client tcp construct ip
[2024-01-06 22:44:32] [I] 0xffffb499ea30 socks5 client tcp -> [1.1.1.1]:80
[2024-01-06 22:44:32] [D] 0xffffb499ea30 socks5 session tcp construct
[2024-01-06 22:44:32] [D] 0xffffb499ea30 socks5 session tcp new
cattyhouse commented

can you build a debug version? i think it is related to zig cc, this is how i cross build it

make CC='zig cc -target aarch64-linux-musl' AR='zigar' RANLIB='zigranlib' CFLAGS="-g -O0" STRIP=true -j32

cattyhouse commented

It's zig cc/musl issue. I just build with glibc statically, no problem whatsoever.

  • 👀1
cattyhouse commented

One note from glibc:

/usr/bin/ld: third-part/hev-task-system/bin/libhev-task-system.a(hev-task-dns-proxy.o): in function `hev_task_dns_server_handler':
hev-task-dns-proxy.c:(.text+0xd0): warning: Using 'getaddrinfo' in statically linked applications requires at runtime the shared libraries from the glibc version used for linking

heiher commented

One note from glibc:

/usr/bin/ld: third-part/hev-task-system/bin/libhev-task-system.a(hev-task-dns-proxy.o): in function `hev_task_dns_server_handler': hev-task-dns-proxy.c:(.text+0xd0): warning: Using 'getaddrinfo' in statically linked applications requires at runtime the shared libraries from the glibc version used for linking

so musl cc is preferred for static linking.

cattyhouse commented

One note from glibc:
/usr/bin/ld: third-part/hev-task-system/bin/libhev-task-system.a(hev-task-dns-proxy.o): in function `hev_task_dns_server_handler': hev-task-dns-proxy.c:(.text+0xd0): warning: Using 'getaddrinfo' in statically linked applications requires at runtime the shared libraries from the glibc version used for linking

so musl cc is preferred for static linking.

i think the differences between musl.cc and zig cc is that the former uses gcc as compiler the latter uses clang as compiler. they both use musl-libc as libc though.

so the issue could be that the code you write is gcc preferred and not fully compatible with clang

cattyhouse commented

新的调试信息你看看

make

 make clean ; make CC='zig cc -target aarch64-linux-musl' AR=zigar RANLIB=zigranlib CFLAGS="-g -O0" STRIP=true -j

file info

file bin/hev-socks5-tproxy

bin/hev-socks5-tproxy: ELF 64-bit LSB executable, ARM aarch64, version 1 (SYSV), statically linked, with debug_info, not stripped

size info

ll bin/hev-socks5-tproxy

-rwxr-xr-x 1 user user 3.3M Jan  7 11:13 bin/hev-socks5-tproxy

gdb info

gdb start

# gdb --args ./hev-socks5-tproxy ./tproxy.yml
GNU gdb (Debian 13.1-3) 13.1
Copyright (C) 2023 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "aarch64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<https://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
    <http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from ./hev-socks5-tproxy...

gdb run

(gdb) r
Starting program: /root/hev_trojan_r/hev-socks5-tproxy ./tproxy.yml
[0xfffff7ffc0a0] alloc size: 384
[0xfffff7ffc0a0] alloc size: 64
[0xfffff7ffc0a0] alloc size: 64
[0xfffff7ffc0a0] alloc size: 448
[0xfffff7ffc0a0] alloc size: 64
[0xfffff7ffc0a0] alloc size: 448
[0xfffff7ffc0a0] alloc size: 64
[0xfffff7ffc0a0] alloc size: 448
[0xfffff7ffc0a0] alloc size: 64
[0xfffff7ffc0a0] alloc size: 448
[0xfffff7ffc0a0] alloc size: 64
[New LWP 10270]
[0xfffff7ffc0a0] alloc size: 64
[0xfffff7ffc0a0] cached_count: 1
[0xfffff7ffc0a0] cached_count: 2
[0xfffff7ffc0a0] alloc size: 1536
[0xfffff7ffc0a0] alloc size: 128
[0xfffff7ffc0a0] alloc size: 64

Thread 1 "hev-socks5-tpro" received signal SIGSEGV, Segmentation fault.
0x000000000114b1c0 in printf_core (f=0x0, f@entry=0xfffff7fc5e10, fmt=0x1001508 "[%p] cached_count: %u\n",
    ap=ap@entry=0xfffff7fc5f30, nl_arg=nl_arg@entry=0xfffff7fc5e60, nl_type=nl_type@entry=0xfffff7fc5f00)
    at /opt/zig/lib/libc/musl/src/stdio/vfprintf.c:431
431     /opt/zig/lib/libc/musl/src/stdio/vfprintf.c: No such file or directory.

gdb bt

(gdb) bt
#0  0x000000000114b1c0 in printf_core (f=0x0, f@entry=0xfffff7fc5e10, fmt=0x1001508 "[%p] cached_count: %u\n",
    ap=ap@entry=0xfffff7fc5f30, nl_arg=nl_arg@entry=0xfffff7fc5e60, nl_type=nl_type@entry=0xfffff7fc5f00)
    at /opt/zig/lib/libc/musl/src/stdio/vfprintf.c:431
#1  0x000000000114b07c in vfprintf (f=0x118d008 <__stdout_FILE>, fmt=0x1001508 "[%p] cached_count: %u\n", ap=...)
    at /opt/zig/lib/libc/musl/src/stdio/vfprintf.c:673
#2  0x000000000114af04 in printf (fmt=0x1001508 "[%p] cached_count: %u\n") at /opt/zig/lib/libc/musl/src/stdio/printf.c:9
#3  0x000000000114126c in _hev_memory_allocator_free (allocator=0xfffff7ffc0a0, ptr=0xfffff7fd9440)
    at src/mem/slice/hev-memory-allocator-slice.c:212
#4  0x000000000113f2bc in hev_memory_allocator_free (self=0xfffff7ffc0a0, ptr=0xfffff7fd9440)
    at src/mem/base/hev-memory-allocator.c:112
#5  0x000000000113ed7c in hev_free (ptr=0xfffff7fd9440) at src/mem/api/hev-memory-allocator-api.c:71
#6  0x0000000001038638 in hev_socks5_client_write_request (self=0xfffff7fd9a30) at src/core/src/hev-socks5-client.c:161
#7  0x00000000010361d4 in hev_socks5_client_handshake (self=0xfffff7fd9a30) at src/core/src/hev-socks5-client.c:299
#8  0x000000000104cf64 in hev_socks5_session_run (base=0xfffff7fd9a30) at src/hev-socks5-session.c:51
#9  0x0000000001050a10 in hev_tproxy_session_run (self=0xfffff7fd9a30) at src/hev-tproxy-session.c:18
#10 0x000000000104e1b0 in hev_socks5_tcp_session_task_entry (data=0xfffff7fd9a30) at src/hev-socks5-tproxy.c:235
#11 0x0000000001130f90 in hev_task_executer (task=0xfffff7fd9230) at src/kern/task/hev-task-executer.c:19
#12 0x0000000001142244 in hev_task_execute () at src/arch/arm/hev-task-execute-aarch64.s:18
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

gdb thread apply all bt

(gdb) thread apply all bt

Thread 2 (LWP 10270 "hev-socks5-tpro"):
#0  sccp (nr=22, u=<optimized out>, v=281474842188472, w=256, x=-1, y=0, z=8) at /opt/zig/lib/libc/musl/src/thread/__syscall_cp.c:10
#1  0x0000000001142efc in epoll_pwait (fd=<optimized out>, ev=0x100, cnt=<optimized out>, to=<optimized out>, sigs=0x0) at /opt/zig/lib/libc/musl/src/linux/epoll.c:28
#2  epoll_wait (fd=<optimized out>, ev=0x100, cnt=<optimized out>, to=<optimized out>) at /opt/zig/lib/libc/musl/src/linux/epoll.c:37
#3  0x00000000011382a8 in hev_task_io_reactor_wait (self=0xfffff7fd9830, events=0xfffff7fb5ab8, count=256, timeout=-1) at src/kern/io/hev-task-io-reactor-epoll.h:54
#4  0x0000000001137b80 in hev_task_aide_entry (data=0x0) at src/kern/aide/hev-task-aide.c:44
#5  0x0000000001150f58 in start (p=0xfffff7fb6b00) at /opt/zig/lib/libc/musl/src/thread/pthread_create.c:207
#6  0x0000000001150f9c in __clone () at /opt/zig/lib/libc/musl/src/thread/aarch64/clone.s:28
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

Thread 1 (LWP 10268 "hev-socks5-tpro"):
#0  0x000000000114b1c0 in printf_core (f=0x0, f@entry=0xfffff7fc5e10, fmt=0x1001508 "[%p] cached_count: %u\n", ap=ap@entry=0xfffff7fc5f30, nl_arg=nl_arg@entry=0xfffff7fc5e60, nl_type=nl_type@entry=0xfffff7fc5f00) at /opt/zig/lib/libc/musl/src/stdio/vfprintf.c:431
#1  0x000000000114b07c in vfprintf (f=0x118d008 <__stdout_FILE>, fmt=0x1001508 "[%p] cached_count: %u\n", ap=...) at /opt/zig/lib/libc/musl/src/stdio/vfprintf.c:673
#2  0x000000000114af04 in printf (fmt=0x1001508 "[%p] cached_count: %u\n") at /opt/zig/lib/libc/musl/src/stdio/printf.c:9
#3  0x000000000114126c in _hev_memory_allocator_free (allocator=0xfffff7ffc0a0, ptr=0xfffff7fd9440) at src/mem/slice/hev-memory-allocator-slice.c:212
#4  0x000000000113f2bc in hev_memory_allocator_free (self=0xfffff7ffc0a0, ptr=0xfffff7fd9440) at src/mem/base/hev-memory-allocator.c:112
#5  0x000000000113ed7c in hev_free (ptr=0xfffff7fd9440) at src/mem/api/hev-memory-allocator-api.c:71
#6  0x0000000001038638 in hev_socks5_client_write_request (self=0xfffff7fd9a30) at src/core/src/hev-socks5-client.c:161
#7  0x00000000010361d4 in hev_socks5_client_handshake (self=0xfffff7fd9a30) at src/core/src/hev-socks5-client.c:299
#8  0x000000000104cf64 in hev_socks5_session_run (base=0xfffff7fd9a30) at src/hev-socks5-session.c:51
#9  0x0000000001050a10 in hev_tproxy_session_run (self=0xfffff7fd9a30) at src/hev-tproxy-session.c:18
#10 0x000000000104e1b0 in hev_socks5_tcp_session_task_entry (data=0xfffff7fd9a30) at src/hev-socks5-tproxy.c:235
#11 0x0000000001130f90 in hev_task_executer (task=0xfffff7fd9230) at src/kern/task/hev-task-executer.c:19
#12 0x0000000001142244 in hev_task_execute () at src/arch/arm/hev-task-execute-aarch64.s:18
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
cattyhouse commented

compiler + libc combination update:

  1. gcc + glibc OK (just make)
  2. gcc + musl OK (using musl.cc toolchain)
  3. clang + glibc OK (zig cc -target aarch64-linux-gnu)
  4. clang + musl SEG FAULT ( zig cc -target aarch64-linux-musl )

2 vs 4 difference : 4 has newer musl version, now change zig to use version 0.9 which uses older musl libc to match that with 2 , can't compile

LINK  bin/libhev-task-system.a
ld.lld: error: undefined symbol: __aarch64_ldadd4_relax
>>> referenced by hev-object.c:32 (src/core/src/hev-object.c:32)
>>>               build/core/src/hev-object.o:(hev_object_ref)
>>> referenced by hev-object.c:47 (src/core/src/hev-object.c:47)
>>>               build/core/src/hev-object.o:(hev_object_unref)
make: *** [Makefile:90: bin/hev-socks5-tproxy] Error 1
cattyhouse commented

close this for another issue