BUG on OMR? (call trace) Enhancement in debug logs: getpeername: Socket not connected

xabix commented 4 years ago

Expected Behavior

Hello,

Can these errors be more precise to know which interface it relates to?

1/ daemon.err /usr/bin/ss-local[19207]: getpeername: Socket not connected 2/ daemon.err /usr/bin/ss-redir[19209]: remote recv: Operation timed out 3/ user.notice post-tracking-post-tracking: omrvpn down because gateway down

Sometimes my connection falls, and I am never able to identify why (so losing VoIP calls ...) Mon Apr 6 15:24:58 2020 user.notice post-tracking-post-tracking: Tunnel down use ShadowSocks for UDP Mon Apr 6 15:24:58 2020 user.notice Shadowsocks: Rules DOWN

In general, is there a way to increase the log level to have more insight on the errors?

Specifications

OpenMPTCProuter version: v0.54.7 r0+12509-04a21c26a0

Ysurac commented 4 years ago

Difficult to add more details to these errors:

ss-local and ss-redir are related to shadowsocks (not possible to be more verbose here)
omrvpn down because gateway down mean that the gateway of interface omrvpn doesn't answer to ping, the gateway is the local address of the VPN on the VPS side. So the VPN is down.
The "tunnel down use shadowsocks for UDP" mean that the VPN doesn't answer, so shadowsocks is used for UDP and this mean no aggregation for UDP

VPN down error are related to the connection between WANs and the VPS.

xabix commented 4 years ago

My setup is to use

Therefore when Glory fails there is an automatic fall back to Shadowsocks in UDP. Is there a way to control the fall back? what I mean is having 3 different WANs with ADSL and 4G, I would be suprised that none of them work at the same time. So the issue should be in the VPS side (as locally if OMR is failing nothing will work whatever the WANs and the VPS).

If I look on the VPS I see:

Apr 6 15:09:32 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 6 15:09:35 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 6 15:10:10 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 6 15:10:39 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 6 15:11:47 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 6 15:11:52 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 6 15:11:53 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 6 15:12:26 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 6 15:12:27 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 6 15:14:24 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 6 15:14:26 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 6 15:14:50 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 6 15:15:10 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 6 15:15:26 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 6 15:16:08 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 6 15:16:22 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 6 15:16:23 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 6 15:17:12 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 6 15:17:18 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 6 15:17:20 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 6 15:17:41 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 6 15:17:51 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 6 15:17:52 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 6 15:18:05 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 6 15:18:08 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 6 15:18:11 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 6 15:18:53 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 6 15:18:59 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 6 15:21:03 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 6 15:22:59 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 6 15:23:25 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 6 15:23:35 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 6 15:23:43 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 6 15:24:01 XabiX omr-admin.py[1985]: DEBUG: password true Apr 6 15:24:01 XabiX omr-admin.py[1985]: DEBUG: Get config... Apr 6 15:24:01 XabiX omr-admin.py[1985]: DEBUG: Get config... shadowsocks Apr 6 15:24:01 XabiX omr-admin.py[1985]: DEBUG: Get config... glorytun Apr 6 15:24:01 XabiX omr-admin.py[1985]: DEBUG: Get config... dsvpn Apr 6 15:24:01 XabiX omr-admin.py[1985]: DEBUG: Get config... iperf3 Apr 6 15:24:01 XabiX omr-admin.py[1985]: DEBUG: Get config... openvpn Apr 6 15:24:01 XabiX omr-admin.py[1985]: DEBUG: Get config... mlvpn Apr 6 15:24:01 XabiX omr-admin.py[1985]: DEBUG: Get config... mptcp Apr 6 15:24:01 XabiX omr-admin.py[1985]: DEBUG: Get config... ipv6 Apr 6 15:24:01 XabiX omr-admin.py[1985]: DEBUG: get server IPv4 Apr 6 15:24:01 XabiX omr-admin.py[1985]: DEBUG: get hostname Apr 6 15:24:01 XabiX omr-admin.py[1985]: DEBUG: Get config: done Apr 6 15:24:02 XabiX omr-admin.py[1985]: DEBUG: password true Apr 6 15:24:02 XabiX omr-admin.py[1985]: DEBUG: password true Apr 6 15:24:02 XabiX omr-admin.py[1985]: DEBUG: Get config... Apr 6 15:24:02 XabiX omr-admin.py[1985]: DEBUG: Get config... shadowsocks Apr 6 15:24:02 XabiX omr-admin.py[1985]: DEBUG: Get config... glorytun Apr 6 15:24:02 XabiX omr-admin.py[1985]: DEBUG: Get config... dsvpn Apr 6 15:24:02 XabiX omr-admin.py[1985]: DEBUG: Get config... iperf3 Apr 6 15:24:02 XabiX omr-admin.py[1985]: DEBUG: Get config... openvpn Apr 6 15:24:02 XabiX omr-admin.py[1985]: DEBUG: Get config... mlvpn Apr 6 15:24:02 XabiX omr-admin.py[1985]: DEBUG: Get config... mptcp Apr 6 15:24:02 XabiX omr-admin.py[1985]: DEBUG: Get config... ipv6 Apr 6 15:24:02 XabiX omr-admin.py[1985]: DEBUG: get server IPv4 Apr 6 15:24:02 XabiX omr-admin.py[1985]: DEBUG: get hostname Apr 6 15:24:02 XabiX omr-admin.py[1985]: DEBUG: Get config: done Apr 6 15:24:03 XabiX omr-admin.py[1985]: DEBUG: Get config... Apr 6 15:24:03 XabiX omr-admin.py[1985]: DEBUG: Get config... shadowsocks Apr 6 15:24:03 XabiX omr-admin.py[1985]: DEBUG: Get config... glorytun Apr 6 15:24:03 XabiX omr-admin.py[1985]: DEBUG: Get config... dsvpn Apr 6 15:24:03 XabiX omr-admin.py[1985]: DEBUG: Get config... iperf3 Apr 6 15:24:03 XabiX omr-admin.py[1985]: DEBUG: Get config... openvpn Apr 6 15:24:03 XabiX omr-admin.py[1985]: DEBUG: Get config... mlvpn Apr 6 15:24:03 XabiX omr-admin.py[1985]: DEBUG: Get config... mptcp Apr 6 15:24:03 XabiX omr-admin.py[1985]: DEBUG: Get config... ipv6 Apr 6 15:24:03 XabiX omr-admin.py[1985]: DEBUG: get server IPv4 Apr 6 15:24:03 XabiX omr-admin.py[1985]: DEBUG: get hostname Apr 6 15:24:03 XabiX omr-admin.py[1985]: DEBUG: Get config: done Apr 6 15:24:03 XabiX omr-admin.py[1985]: DEBUG: Get config... Apr 6 15:24:03 XabiX omr-admin.py[1985]: DEBUG: Get config... shadowsocks Apr 6 15:24:03 XabiX omr-admin.py[1985]: DEBUG: Get config... glorytun Apr 6 15:24:03 XabiX omr-admin.py[1985]: DEBUG: Get config... dsvpn Apr 6 15:24:03 XabiX omr-admin.py[1985]: DEBUG: Get config... iperf3 Apr 6 15:24:03 XabiX omr-admin.py[1985]: DEBUG: Get config... openvpn Apr 6 15:24:03 XabiX omr-admin.py[1985]: DEBUG: Get config... mlvpn Apr 6 15:24:03 XabiX omr-admin.py[1985]: DEBUG: Get config... mptcp Apr 6 15:24:03 XabiX omr-admin.py[1985]: DEBUG: Get config... ipv6 Apr 6 15:24:03 XabiX omr-admin.py[1985]: DEBUG: get server IPv4 Apr 6 15:24:03 XabiX omr-admin.py[1985]: DEBUG: get hostname Apr 6 15:24:03 XabiX omr-admin.py[1985]: DEBUG: Get config: done Apr 6 15:24:03 XabiX omr-admin.py[1985]: DEBUG: Get config... Apr 6 15:24:03 XabiX omr-admin.py[1985]: DEBUG: Get config... shadowsocks Apr 6 15:24:03 XabiX omr-admin.py[1985]: DEBUG: Get config... glorytun Apr 6 15:24:03 XabiX omr-admin.py[1985]: DEBUG: Get config... dsvpn Apr 6 15:24:03 XabiX omr-admin.py[1985]: DEBUG: Get config... iperf3 Apr 6 15:24:03 XabiX omr-admin.py[1985]: DEBUG: Get config... openvpn Apr 6 15:24:03 XabiX omr-admin.py[1985]: DEBUG: Get config... mlvpn Apr 6 15:24:03 XabiX omr-admin.py[1985]: DEBUG: Get config... mptcp Apr 6 15:24:03 XabiX omr-admin.py[1985]: DEBUG: Get config... ipv6 Apr 6 15:24:03 XabiX omr-admin.py[1985]: DEBUG: get server IPv4 Apr 6 15:24:03 XabiX omr-admin.py[1985]: DEBUG: get hostname Apr 6 15:24:03 XabiX omr-admin.py[1985]: DEBUG: Get config: done Apr 6 15:25:27 XabiX ss-server[896]: server recv: Connection reset by peer Apr 6 15:25:51 XabiX ss-server[896]: getpeername: Transport endpoint is not connected Apr 6 15:26:14 XabiX omr-admin.py[1985]: DEBUG: password true

Apr 6 15:22:14 XabiX kernel: [595704.543500] Shorewall:net-fw:DROP:IN=eth0 OUT= MAC=a6:ee:69:bf:0d:d8:00:1c:73:44:59:c6:08:00 SRC=195.54.167.40 DST=149.91.xxx.xxx LEN=40 TOS=0x00 PREC=0x00 TTL=242 ID=14145 PROTO=TCP SPT=50901 DPT=49194 WINDOW=1024 RES=0x00 SYN URGP=0 Apr 6 15:22:25 XabiX kernel: [595716.067246] Shorewall:net-fw:DROP:IN=eth0 OUT= MAC=a6:ee:69:bf:0d:d8:00:1c:73:44:59:c6:08:00 SRC=185.209.0.32 DST=149.91.xxx.xxx LEN=40 TOS=0x08 PREC=0x20 TTL=237 ID=46805 PROTO=TCP SPT=49966 DPT=3400 WINDOW=1024 RES=0x00 SYN URGP=0 Apr 6 15:22:26 XabiX kernel: [595716.475634] Shorewall:net-fw:DROP:IN=eth0 OUT= MAC=a6:ee:69:bf:0d:d8:00:1c:73:44:59:c6:08:00 SRC=195.54.166.225 DST=149.91.xxx.xxx LEN=40 TOS=0x00 PREC=0x00 TTL=243 ID=32259 PROTO=TCP SPT=50901 DPT=6379 WINDOW=1024 RES=x00 SYN URGP=0 Apr 6 15:22:42 XabiX kernel: [595732.640013] Shorewall:net-fw:DROP:IN=eth0 OUT= MAC=a6:ee:69:bf:0d:8:00:1c:73:44:59:c6:08:00 SRC=185.209.0.89 DST=149.91.xxx.xxx LEN=40 TOS=0x08 PREC=0x20 TTL=237 ID=50280 PROTO=TCP SPT=41904 DPT=11000 WINDOW=1024 RES=0x0 SYN URGP=0 Apr 6 15:22:43 XabiX kernel: [595733.572200] Shorewall:net-fw:DROP:IN=eth0 OUT= MAC=a6:ee:69:bf:0d:8:00:1c:73:44:59:c6:08:00 SRC=185.175.93.27 DST=149.91.xxx.xxx LEN=40 TOS=0x00 PREC=0x00 TTL=250 ID=19190 PROTO=TCP SPT=56348 DPT=52851 WINDOW=1024 RES=0x0 SYN URGP=0 Apr 6 15:22:51 XabiX kernel: [595741.428279] Shorewall:net-fw:DROP:IN=eth0 OUT= MAC=a6:ee:69:bf:0d:8:00:1c:73:44:59:c6:08:00 SRC=83.23.183.60 DST=149.91.xxx.xxx LEN=227 TOS=0x00 PREC=0x00 TTL=110 ID=54025 PROTO=UDP SPT=50568 DPT=54007 LEN=207 Apr 6 15:23:25 XabiX kernel: [595776.081465] Shorewall:net-fw:DROP:IN=eth0 OUT= MAC=a6:ee:69:bf:0d:d8:00:1c:73:44:59:c6:08:00 SRC=104.238.222.122 DST=149.91.xxx.xxx LEN=444 TOS=0x00 PREC=0x00 TTL=48 ID=42796 DF PROTO=UDP SPT=5108 DPT=5060 LEN=424 Apr 6 15:23:41 XabiX kernel: [595792.192556] Shorewall:net-fw:DROP:IN=eth0 OUT= MAC=a6:ee:69:bf:0d:d8:00:1c:73:44:59:c6:08:00 SRC=176.113.115.246 DST=149.91.xxx.xxx LEN=40 TOS=0x00 PREC=0x00 TTL=237 ID=47224 PROTO=TCP SPT=50932 DPT=38239 WINDOW=1024 RES=0x00 SYN URGP=0 Apr 6 15:23:42 XabiX kernel: [595793.351601] Shorewall:net-fw:DROP:IN=eth0 OUT= MAC=a6:ee:69:bf:0d:d8:00:1c:73:44:59:c6:08:00 SRC=80.82.77.234 DST=149.91.xxx.xxx LEN=40 TOS=0x00 PREC=0x00 TTL=250 ID=64521 PROTO=TCP SPT=55361 DPT=64689 WINDOW=1024 RES=0x00 SYN URGP=0 Apr 6 15:23:57 XabiX kernel: [595808.196582] Shorewall:net-fw:DROP:IN=eth0 OUT= MAC=a6:ee:69:bf:0d:d8:00:1c:73:44:59:c6:08:00 SRC=91.199.118.137 DST=149.91.xxx.xxx LEN=40 TOS=0x00 PREC=0x20 TTL=240 ID=47814 PROTO=TCP SPT=58851 DPT=83 WINDOW=1024 RES=0x00 SYN URGP=0 Apr 6 15:23:59 XabiX kernel: [595810.337671] Shorewall:net-fw:DROP:IN=eth0 OUT= MAC=a6:ee:69:bf:0d:d8:00:1c:73:44:59:c6:08:00 SRC=223.71.167.165 DST=149.91.xxx.xxx LEN=44 TOS=0x04 PREC=0x00 TTL=114 ID=35632 PROTO=TCP SPT=10458 DPT=9500 WINDOW=29200 RES=0x00 SYN URGP=0 Apr 6 15:24:00 XabiX kernel: [595810.521724] Shorewall:net-fw:DROP:IN=eth0 OUT= MAC=a6:ee:69:bf:0d:d8:00:1c:73:44:59:c6:08:00 SRC=213.217.0.70 DST=149.91.xxx.xxx LEN=40 TOS=0x00 PREC=0x00 TTL=243 ID=41689 PROTO=TCP SPT=50903 DPT=35994 WINDOW=1024 RES=0x00 SYN URGP=0 Apr 6 15:24:01 XabiX kernel: [595811.619206] Shorewall:net-fw:DROP:IN=eth0 OUT= MAC=a6:ee:69:bf:0d:d8:00:1c:73:44:59:c6:08:00 SRC=114.34.70.142 DST=149.91.xxx.xxx LEN=40 TOS=0x00 PREC=0x00 TTL=43 ID=53565 PROTO=TCP SPT=11509 DPT=23 WINDOW=477 RES=0x00 SYN URGP=0 Apr 6 15:24:19 XabiX kernel: [595830.040091] Shorewall:net-fw:DROP:IN=eth0 OUT= MAC=a6:ee:69:bf:0d:d8:00:1c:73:44:59:c6:08:00 SRC=80.82.78.100 DST=149.91.xxx.xxx LEN=57 TOS=0x00 PREC=0x00 TTL=250 ID=54321 PROTO=UDP SPT=48906 DPT=48899 LEN=37 Apr 6 15:24:33 XabiX kernel: [595843.821747] Shorewall:net-fw:DROP:IN=eth0 OUT= MAC=a6:ee:69:bf:0d:d8:00:1c:73:44:59:c6:08:00 SRC=87.251.74.9 DST=149.91.xxx.xxx LEN=40 TOS=0x00 PREC=0x00 TTL=245 ID=5534 PROTO=TCP SPT=51698 DPT=3165 WINDOW=1024 RES=0x00 SYN URGP=0 Apr 6 15:24:54 XabiX kernel: [595865.313336] Shorewall:net-fw:DROP:IN=eth0 OUT= MAC=a6:ee:69:bf:0d:d8:00:1c:73:44:59:c6:08:00 SRC=146.185.25.184 DST=149.91.xxx.xxx LEN=40 TOS=0x00 PREC=0x00 TTL=239 ID=54321 PROTO=TCP SPT=7549 DPT=7549 WINDOW=65535 RES=0x00 SYN URGP=0 Apr 6 15:24:57 XabiX kernel: [595867.772801] Shorewall:net-fw:DROP:IN=eth0 OUT= MAC=a6:ee:69:bf:0d:d8:00:1c:73:44:59:c6:08:00 SRC=176.113.115.65 DST=149.91.xxx.xxx LEN=40 TOS=0x00 PREC=0x00 TTL=243 ID=8535 PROTO=TCP SPT=47847 DPT=40761 WINDOW=1024 RES=0x00 SYN URGP=0 Apr 6 15:24:57 XabiX kernel: [595867.980907] Shorewall:net-fw:DROP:IN=eth0 OUT= MAC=a6:ee:69:bf:0d:d8:00:1c:73:44:59:c6:08:00 SRC=185.175.93.11 DST=149.91.xxx.xxx LEN=40 TOS=0x00 PREC=0x00 TTL=250 ID=39988 PROTO=TCP SPT=57059 DPT=38413 WINDOW=1024 RES=0x00 SYN URGP=0

By the way, I noticed the same type of logs between message, syslog and daemon etc... maybe worth reducing the number of fils logging the shorewall deny logs as they seem duplicated in 3 files. I don't think this as any impact on the VPS side though.

Ysurac commented 4 years ago

You can configure what you want on VPS side... Log are the default config. You can set MPTCP master as the interface that is more stable (ADSL, fiber,...). But, as I said, the problem can be between WANs and VPS.

xabix commented 4 years ago

Thanks Ysurac! As alwayes very helpful.

I will not touch the log level in the VPS as I don't want to mess up :) And yes I have my Master interface set to ADSL Orange which is most stable and quick WAN so not sure what can happen betweeen my WANs and the VPS :). Anyway I may give a try with another VPS. I am using https://www.pulseheberg.com/vps

xabix commented 4 years ago

Hello, I still face the issue: Apr 7 13:49:24 XabiX ss-server[896]: remote recv: Connection reset by peer

Fullmesh

Index, Address-ID, Backup, IP-address, if-idx IPv4, next v4-index: 5 2, 3, 0, 192.168.2.2 7 3, 4, 0, 192.168.3.2 8 4, 5, 0, 192.168.9.2 9 IPv6, next v6-index: 2

WAN1

1: 192.168.2.1 2: 3: 193.249.214.206 [PARTIAL] +PartialTCP IP::TTL IP::CheckSum 4: 193.252.100.34 [PARTIAL] +PartialTCP IP::TTL IP::CheckSum 5: 193.251.126.10 [PARTIAL] +PartialTCP IP::TTL IP::CheckSum 6: 193.252.98.102 [PARTIAL] +PartialTCP IP::TTL IP::CheckSum 7: 193.253.13.206 IP::TTL IP::CheckSum 8: 9: 178.255.102.44 IP::TTL IP::CheckSum 10: 149.91.xxx.xxx TCP::SrcPort TCP::DstPort TCP::SeqNumber TCP::AckNumber TCP::DataOffset TCP::Flags TCP::WindowsSize TCP::CheckSum IP::TotalLength IP::Identification IP::TTL IP::CheckSum IP::SourceIP IP::DestinationIP +TCPOptionMaxSegSize TCPOptionMPTCPCapable::Sender's Key

Result: < Ethernet (14 bytes) :: DestinationMAC = 7a:cb:0a:6b:6f:ec , SourceMAC = 48:83:c7:38:0d:60 , Type = 0x800 , > < IP (20 bytes) :: Version = 4 , HeaderLength = 5 , DiffServicesCP = 0 , ExpCongestionNot = 0 , TotalLength = 56 , Identification = 0x0 , Flags = 2 , FragmentOffset = 0 , TTL = 53 , Protocol = 0x6 , CheckSum = 0x950d , SourceIP = 149.91.xxx.xxx , DestinationIP = 192.168.2.2 , > < TCP (20 bytes) :: SrcPort = 65101 , DstPort = 36415 , SeqNumber = 1592583445 , AckNumber = 2097620317 , DataOffset = 9 , Reserved = 0 , Flags = ( SYN ACK ) , WindowsSize = 65535 , CheckSum = 0x4791 , UrgPointer = 0 , > < TCPOptionMaxSegSize (4 bytes) :: Kind = 2 , Length = 4 , MaxSegSize = 1460 , > < TCPOptionMPTCPCapable (12 bytes) :: Kind = 30 , Length = 12 , Subtype = 0 , Version = 0 , Checksum = 1 (Checksum Enabled) , Flags = 0 , Crypto = 1 (HMAC-SHA1) , Sender's Key = Sender's Key = 9884525243855844440 , >

WAN2

1: 192.168.3.1 2: 194.149.169.69 IP::TTL IP::CheckSum 3: 194.149.172.102 IP::TTL IP::CheckSum 4: 37.77.34.38 IP::TTL IP::CheckSum 5: 37.77.34.75 IP::TTL IP::CheckSum 6: 178.255.102.44 IP::TTL IP::CheckSum 7: 149.91.xxx.xxx TCP::SrcPort TCP::DstPort TCP::SeqNumber TCP::AckNumber TCP::DataOffset TCP::Flags TCP::WindowsSize TCP::CheckSum IP::TotalLength IP::Identification IP::TTL IP::CheckSum IP::SourceIP IP::DestinationIP +TCPOptionMaxSegSize TCPOptionMPTCPCapable::Sender's Key

Result: < Ethernet (14 bytes) :: DestinationMAC = 9a:e3:fe:56:63:f3 , SourceMAC = 00:07:cb:4f:97:51 , Type = 0x800 , > < IP (20 bytes) :: Version = 4 , HeaderLength = 5 , DiffServicesCP = 0 , ExpCongestionNot = 0 , TotalLength = 56 , Identification = 0x0 , Flags = 2 , FragmentOffset = 0 , TTL = 56 , Protocol = 0x6 , CheckSum = 0x910d , SourceIP = 149.91.xxx.xxx , DestinationIP = 192.168.3.2 , > < TCP (20 bytes) :: SrcPort = 65101 , DstPort = 42359 , SeqNumber = 1996887494 , AckNumber = 1279959361 , DataOffset = 9 , Reserved = 0 , Flags = ( SYN ACK ) , WindowsSize = 65535 , CheckSum = 0xd74d , UrgPointer = 0 , > < TCPOptionMaxSegSize (4 bytes) :: Kind = 2 , Length = 4 , MaxSegSize = 1460 , > < TCPOptionMPTCPCapable (12 bytes) :: Kind = 30 , Length = 12 , Subtype = 0 , Version = 0 , Checksum = 1 (Checksum Enabled) , Flags = 0 , Crypto = 1 (HMAC-SHA1) , Sender's Key = Sender's Key = 2149819598405958871 , >

WAN3:

1: 192.168.9.1 2: 3: 4: 10.64.21.83 TCP::DataOffset TCP::CheckSum IP::DiffServicesCP IP::TotalLength IP::TTL IP::CheckSum +TCPOptionMaxSegSize 5: 6: 7: 8: 9: 10: 11: 12: 13: 14: 15: 16: 17: * 18: 149.91.xxx.xxx TCP::SrcPort TCP::DstPort TCP::SeqNumber TCP::AckNumber TCP::DataOffset TCP::Flags TCP::WindowsSize TCP::CheckSum IP::DiffServicesCP IP::TotalLength IP::Identification IP::TTL IP::CheckSum IP::SourceIP IP::DestinationIP +TCPOptionMaxSegSize TCPOptionMPTCPCapable::Sender's Key

Result: < Ethernet (14 bytes) :: DestinationMAC = 1e:e5:a1:00:ea:2e , SourceMAC = b0:eb:57:21:a4:9e , Type = 0x800 , > < IP (20 bytes) :: Version = 4 , HeaderLength = 5 , DiffServicesCP = 8 , ExpCongestionNot = 0 , TotalLength = 56 , Identification = 0x0 , Flags = 2 , FragmentOffset = 0 , TTL = 55 , Protocol = 0x6 , CheckSum = 0x8bed , SourceIP = 149.91.xxx.xxx , DestinationIP = 192.168.9.2 , > < TCP (20 bytes) :: SrcPort = 65101 , DstPort = 28847 , SeqNumber = 3158692749 , AckNumber = 1226050300 , DataOffset = 9 , Reserved = 0 , Flags = ( SYN ACK ) , WindowsSize = 65535 , CheckSum = 0xf6a1 , UrgPointer = 0 , > < TCPOptionMaxSegSize (4 bytes) :: Kind = 2 , Length = 4 , MaxSegSize = 1400 , > < TCPOptionMPTCPCapable (12 bytes) :: Kind = 30 , Length = 12 , Subtype = 0 , Version = 0 , Checksum = 1 (Checksum Enabled) , Flags = 0 , Crypto = 1 (HMAC-SHA1) , Sender's Key = Sender's Key = 5591908639557794393 , >

dmesg on OMR:

[27245.932177] ------------[ cut here ]------------
[27245.933566] WARNING: CPU: 0 PID: 0 at tcp_data_queue.cold.56+0xc/0x4b
[27245.933800] Modules linked in: ath9k ath9k_common rtl8192cu rtl8192c_common rtl_usb rt2800usb rt2800lib qcserial option iwlmvm iwldvm ipw cdc_mbim ath9k_hw ath usb_wwan usb_serial_simple ti_usb_3410_5052 sr9700 smsc95xx sierra_net sierra rtlwifi rtl8xxxu rtl8187 rt2x00usb rt2x00lib rndis_host qmi_wwan pppoe ppp_async pl2303 oti6858 nf_nat_pptp nf_conntrack_pptp mt7601u mos7720 mct_u232 mcs7830 mac80211 lzo lz4 keyspan kalmia iwlwifi iptable_nat ipt_REJECT ipt_MASQUERADE huawei_cdc_ncm garmin_gps ftdi_sio ebtable_nat ebtable_filter ebtable_broute dm9601 cypress_m8 cp210x ch341 cfg80211 cdc_subset cdc_ncm cdc_ether cdc_eem belkin_sa bas_gigaset ax88179_178a asix ark3116 xt_time xt_tcpudp xt_tcpmss xt_statistic xt_state xt_socket xt_recent xt_quota xt_policy xt_pkttype xt_owner xt_ndpi xt_nat xt_multiport
[27245.941226]  xt_mark xt_mac xt_limit xt_length xt_iface xt_hl xt_helper xt_hashlimit xt_esp xt_ecn xt_dscp xt_conntrack xt_connmark xt_connlimit xt_connbytes xt_condition xt_comment xt_addrtype xt_TRACE xt_TPROXY xt_TCPMSS xt_REDIRECT xt_LOG xt_IPMARK xt_HL xt_FLOWOFFLOAD xt_DSCP xt_CT xt_CLASSIFY xt_ACCOUNT wireguard visor via_velocity via_rhine usbserial usbnet usb_gigaset tulip ts_fsm ts_bm solos_pci sky2 skge sis900 sis190 ser_gigaset rtl8150 r8712u(C) r8169 r8152 r6040 pppox ppp_generic pegasus pcnet32 nf_tproxy_ipv6 nf_tproxy_ipv4 nf_socket_ipv6 nf_socket_ipv4 nf_reject_ipv4 nf_nat_tftp nf_nat_snmp_basic nf_nat_sip nf_nat_proto_gre nf_nat_irc nf_nat_ipv4 nf_nat_h323 nf_nat_ftp nf_nat_amanda nf_log_ipv4 nf_flow_table_hw nf_flow_table nf_conntrack_tftp nf_conntrack_snmp nf_conntrack_sip nf_conntrack_rtcache
[27245.946478]  nf_conntrack_proto_gre nf_conntrack_netlink nf_conntrack_irc nf_conntrack_h323 nf_conntrack_ftp nf_conntrack_broadcast ts_kmp nf_conntrack_amanda nf_conncount ne2k_pci mmc_spi macvlan lzo_decompress lzo_compress lz4_compress kaweth iptable_raw iptable_mangle iptable_filter ipt_ah ipt_ECN ipheth ip6table_raw ip_tables hso gigaset forcedeth ezusb ethoc et131x ebtables ebt_vlan ebt_stp ebt_redirect ebt_pkttype ebt_mark_m ebt_mark ebt_limit ebt_among ebt_802_3 e1000e e100 crc7 crc_itu_t crc_ccitt compat_xtables compat cdc_wdm cdc_acm bnx2 atl2 atl1e atl1c atl1 asn1_decoder arptable_filter arpt_mangle arp_tables 8390 8139too 8139cp sch_cake sch_teql sch_sfq sch_red sch_prio sch_pie sch_multiq sch_gred sch_fq sch_dsmark sch_codel em_text em_nbyte em_meta em_cmp act_simple act_police act_pedit
[27245.959760]  act_ipt act_gact act_csum sch_tbf sch_ingress sch_htb sch_hfsc em_u32 cls_u32 cls_tcindex cls_route cls_matchall cls_fw cls_flow cls_basic act_skbedit act_mirred configs evdev i2c_gpio i2c_dev spi_ks8995 ledtrig_heartbeat xt_set ip_set_list_set ip_set_hash_netportnet ip_set_hash_netport ip_set_hash_netnet ip_set_hash_netiface ip_set_hash_net ip_set_hash_mac ip_set_hash_ipportnet ip_set_hash_ipportip ip_set_hash_ipport ip_set_hash_ipmark ip_set_hash_ip ip_set_bitmap_port ip_set_bitmap_ipmac ip_set_bitmap_ip ip_set nfnetlink ip6table_nat ip6t_NPT ip6t_MASQUERADE nf_nat_ipv6 nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 nf_log_ipv6 nf_log_common ip6table_mangle ip6table_filter ip6_tables ip6t_REJECT x_tables nf_reject_ipv6 swconfig isdn_bsdcomp dss1_divert isdn slhc 3c59x igb e1000
[27245.965464]  ifb nat46 ip6_udp_tunnel udp_tunnel sit sctp libcrc32c ipcomp6 xfrm6_tunnel esp6 ah6 xfrm4_tunnel ipcomp esp4 ah4 tunnel6 tunnel4 ip_tunnel hfcpci hfcmulti veth tun mISDN_dsp l1oip mISDN_core xfrm_user xfrm_ipcomp af_key xfrm_algo vfat fat br2684 atm nls_utf8 nls_iso8859_1 nls_cp437 zram zsmalloc natsemi eeprom_93cx6 sha256_ssse3 sha256_generic sha1_ssse3 sha1_generic seqiv jitterentropy_rng drbg md5 hmac ghash_generic gcm echainiv des_generic deflate ctr cbc authenc crypto_acompress sdhci_pltfm xhci_plat_hcd ehci_platform gpio_button_hotplug button_hotplug tg3 b44 ssb ptp realtek broadcom bcm_phy_lib pps_core mii libphy
[27245.971776] CPU: 0 PID: 0 Comm: swapper/0 Tainted: G         C        4.19.108 #0
[27245.972118] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.12.1-0-ga5cab58e9a3f-prebuilt.qemu.org 04/01/2014
[27245.972510] RIP: 0010:tcp_data_queue.cold.56+0xc/0x4b
[27245.972723] Code: ff 8b b3 30 05 00 00 44 89 f9 44 89 f2 48 c7 c7 38 ad 05 82 e8 29 5f 99 ff e9 07 d7 ff ff 48 c7 c7 88 5d fb 81 e8 18 5f 99 ff <0f> 0b e9 6a e2 ff ff 48 c7 c7 70 ad 05 82 e8 05 5f 99 ff 41 8b 84
[27245.973305] RSP: 0018:ffff88801f203b48 EFLAGS: 00010286
[27245.973520] RAX: 0000000000000024 RBX: ffff88801c307500 RCX: 0000000000000000
[27245.973757] RDX: ffff88801f21bc00 RSI: ffff88801f2163b8 RDI: ffff88801f2163b8
[27245.973995] RBP: ffff88801f203b80 R08: 0000000000000000 R09: 00000000000002b6
[27245.974244] R10: 0000000000000008 R11: 0000000000000000 R12: ffff88801af03d40
[27245.974484] R13: 0000000000000002 R14: 0000000000000001 R15: ffff88801af044a8
[27245.974732] FS:  0000000000000000(0000) GS:ffff88801f200000(0000) knlGS:0000000000000000
[27245.975086] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[27245.975312] CR2: 00007f7167983d84 CR3: 000000001e3a6000 CR4: 0000000000140ef0
[27245.975553] Call Trace:
[27245.975738]  <IRQ>
[27245.976007]  tcp_rcv_established+0x1ca/0x580
[27245.976212]  tcp_v4_do_rcv+0x181/0x220
[27245.976410]  tcp_v4_rcv+0xc0d/0xda0
[27245.976787]  ? nf_ct_l4proto_register_one+0x462/0x9e0 [nf_conntrack]
[27245.977022]  ip_local_deliver_finish+0xa7/0x1c0
[27245.977230]  ip_local_deliver+0x91/0xc0
[27245.977429]  ? ip_sublist_rcv_finish+0x60/0x60
[27245.977636]  ip_rcv_finish+0x3a/0x40
[27245.977832]  ip_rcv+0x87/0xb0
[27245.978020]  ? ip_rcv_finish_core.isra.0+0x2b0/0x2b0
[27245.978234]  __netif_receive_skb_one_core+0x43/0x50
[27245.978446]  __netif_receive_skb+0x21/0x60
[27245.978648]  netif_receive_skb_internal+0x28/0x80
[27245.978943]  napi_gro_complete+0x54/0xa0
[27245.979144]  napi_gro_flush+0x81/0xc0
[27245.979346]  napi_complete_done+0x92/0x100
[27245.979549]  virtqueue_napi_complete+0x2a/0x70
[27245.979755]  virtnet_poll+0x2dd/0x2f0
[27245.979952]  net_rx_action+0xd8/0x240
[27245.980149]  __do_softirq+0xb9/0x202
[27245.980346]  irq_exit+0x62/0x90
[27245.980535]  do_IRQ+0x7f/0xe0
[27245.980723]  common_interrupt+0xf/0xf
[27245.980919]  </IRQ>
[27245.981096] RIP: 0010:native_safe_halt+0x17/0x20
[27245.981390] Code: 00 a8 08 75 c3 e9 77 ff ff ff 90 90 90 90 90 90 90 90 90 55 8b 05 69 24 bb 00 48 89 e5 85 c0 7e 07 0f 00 2d fb 1d 5f 00 fb f4 <5d> c3 0f 1f 80 00 00 00 00 55 8b 05 49 24 bb 00 48 89 e5 85 c0 7e
[27245.981979] RSP: 0018:ffffffff82203e48 EFLAGS: 00000246 ORIG_RAX: ffffffffffffffd1
[27245.982326] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 000000000001a440
[27245.982567] RDX: 000000000296b062 RSI: ffffffff82233250 RDI: 0000000000000000
[27245.982807] RBP: ffffffff82203e48 R08: 0000000000000124 R09: 0000000000000000
[27245.983047] R10: 8080808080808080 R11: 0000000000000000 R12: 0000000000000000
[27245.983291] R13: 0000000000000000 R14: ffff88801ffd58c0 R15: 0000000000000000
[27245.983533]  ? tsc_verify_tsc_adjust+0x39/0xc0
[27245.983739]  default_idle+0x10/0x20
[27245.983934]  arch_cpu_idle+0x10/0x20
[27245.984214]  default_idle_call+0x27/0x30
[27245.984415]  do_idle+0x164/0x180
[27245.984607]  cpu_startup_entry+0x5f/0x70
[27245.984807]  rest_init+0x99/0x9b
[27245.984998]  start_kernel+0x554/0x561
[27245.985195]  x86_64_start_reservations+0x29/0x2b
[27245.985403]  x86_64_start_kernel+0x71/0x74
[27245.985606]  secondary_startup_64+0xa4/0xb0
[27245.985809] ---[ end trace 8f8ebb1ae243217a ]---

on VPS:

Apr 7 13:49:24 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 7 13:50:35 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 7 13:52:26 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 7 13:52:29 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 7 13:52:30 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 7 13:52:30 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 7 13:52:46 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 7 13:53:58 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 7 13:54:56 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 7 13:54:59 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 7 13:55:06 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 7 13:56:48 XabiX ss-server[896]: remote recv: Connection reset by peer Apr 7 13:56:50 XabiX glorytun-tcp-run[1152]: 94.102.49.65.41768: connected Apr 7 13:56:50 XabiX glorytun-tcp-run[1152]: bad packet [8EE28FDC8EE28FDD8EE28FDE] ! Apr 7 13:56:50 XabiX glorytun-tcp-run[1152]: 94.102.49.65.41768: key exchange failed

If I reboot OMR, it works back. Anyway to capture live traffic on OMR in the cmd ?

xabix commented 4 years ago

@Ysurac Hi Yannick, any change to tell me if the call trace above can help to pinpoint the issue? otherwise I may close the issue and wait for the new kernel 5.4 :). When do you expect to release 0.55?

Merci

Ysurac commented 4 years ago

This looks like an issue with the VM, like not enough resources really available.

Ysurac / openmptcprouter

BUG on OMR? (call trace) Enhancement in debug logs: getpeername: Socket not connected #956

Expected Behavior

Specifications