Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Remote peer's TCP disconnect is not detected #9

Closed
lstipakov opened this issue Dec 21, 2022 · 8 comments
Closed

Remote peer's TCP disconnect is not detected #9

lstipakov opened this issue Dec 21, 2022 · 8 comments
Assignees
@ordex
Labels
bug Something isn't working

Comments

@lstipakov
Copy link
Member

lstipakov commented Dec 21, 2022 •
edited
Loading

Steps to reproduce:

  • Run openvpn server with ovpn-dco (I used version 0.1.20221107) and proto tcp
  • Connect with the client
  • Disconnect the client

Expected results:

  • ovpn-dco module should send OVPN_CMD_DEL_PEER to userspace with the reason OVPN_DEL_PEER_REASON_TEARDOWN or OVPN_DEL_PEER_REASON_TRANSPORT_ERROR
  • userspace should handle that and remove client instance

Actual results:

  • ovpn-dco doesn't detect connection termination and instead notifies userspace only when keepalive message cannot be sent (cannot send TCP packet to peer 0: -104)

Client log:

2022-12-21 14:19:05 us=828000 ovpn-dco device [OpenVPN Data Channel Offload] opened
2022-12-21 14:19:05 us=875000 TCP_CLIENT link local: (not bound)
2022-12-21 14:19:05 us=875000 TCP_CLIENT link remote: [AF_INET]111.222.333.444:1194
2022-12-21 14:19:05 us=875000 MANAGEMENT: >STATE:1671625145,WAIT,,,,,,
2022-12-21 14:19:05 us=921000 MANAGEMENT: >STATE:1671625145,AUTH,,,,,,
2022-12-21 14:19:05 us=921000 TLS: Initial packet from [AF_INET]111.222.333.444:1194, sid=104a46b8 03896379
2022-12-21 14:19:06 us=15000 VERIFY OK: depth=1, CN=LeeviCA5
2022-12-21 14:19:06 us=31000 VERIFY OK: depth=0, CN=example.com
2022-12-21 14:19:06 us=171000 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, peer certificate: 2048 bit RSA, signature: RSA-SHA256
2022-12-21 14:19:06 us=171000 [example.com] Peer Connection Initiated with [AF_INET]111.222.333.444:1194
2022-12-21 14:19:06 us=312000 PUSH: Received control message: 'PUSH_REPLY,tun-ipv6,route-gateway 10.58.0.1,topology subnet,ping 30,ping-restart 180,ifconfig-ipv6 2001:db8:0:456::1000/64 2001:db8:0:456::1,ifconfig 10.58.0.2 255.255.255.0,peer-id 0,cipher AES-256-GCM,protocol-flags cc-exit tls-ekm,tun-mtu 1500'
2022-12-21 14:19:06 us=312000 OPTIONS IMPORT: timers and/or timeouts modified
2022-12-21 14:19:06 us=312000 OPTIONS IMPORT: --ifconfig/up options modified
2022-12-21 14:19:06 us=312000 OPTIONS IMPORT: route-related options modified
2022-12-21 14:19:06 us=312000 OPTIONS IMPORT: peer-id set
2022-12-21 14:19:06 us=312000 OPTIONS IMPORT: data channel crypto options modified
2022-12-21 14:19:06 us=312000 OPTIONS IMPORT: tun-mtu set to 1500
2022-12-21 14:19:06 us=312000 interactive service msg_channel=164
2022-12-21 14:19:06 us=312000 do_ifconfig, ipv4=1, ipv6=1
2022-12-21 14:19:06 us=312000 MANAGEMENT: >STATE:1671625146,ASSIGN_IP,,10.58.0.2,,,,,2001:db8:0:456::1000
2022-12-21 14:19:06 us=312000 INET address service: add 10.58.0.2/24
2022-12-21 14:19:06 us=312000 IPv4 MTU set to 1500 on interface 36 using service
2022-12-21 14:19:06 us=312000 INET6 address service: add 2001:db8:0:456::1000/128
2022-12-21 14:19:06 us=312000 add_route_ipv6(2001:db8:0:456::/64 -> 2001:db8:0:456::1000 metric 0) dev OpenVPN Data Channel Offload
2022-12-21 14:19:06 us=312000 IPv6 route addition via service succeeded
2022-12-21 14:19:06 us=312000 IPv6 MTU set to 1500 on interface 36 using service
2022-12-21 14:19:06 us=312000 Data Channel: using negotiated cipher 'AES-256-GCM'
2022-12-21 14:19:06 us=312000 Data Channel MTU parms [ mss_fix:1386 max_frag:0 tun_mtu:1500 tun_max_mtu:1600 headroom:136 payload:1768 tailroom:562 ET:0 ]
2022-12-21 14:19:06 us=312000 Initialization Sequence Completed
2022-12-21 14:19:06 us=312000 MANAGEMENT: >STATE:1671625146,CONNECTED,SUCCESS,10.58.0.2,111.222.333.444,1194,,,2001:db8:0:456::1000
2022-12-21 14:19:14 us=406000 Closing DCO interface
2022-12-21 14:19:14 us=406000 delete_route_ipv6(2001:db8:0:456::/64)
2022-12-21 14:19:14 us=406000 IPv6 route deletion via service succeeded
2022-12-21 14:19:14 us=406000 INET6 address service: remove 2001:db8:0:456::1000/128
2022-12-21 14:19:14 us=406000 Deleting IPv4 dns servers on 'OpenVPN Data Channel Offload' (if_index = 36) using service
2022-12-21 14:19:14 us=546000 IPv4 dns servers deleted using service
2022-12-21 14:19:14 us=546000 INET address service: remove 10.58.0.2/24
2022-12-21 14:19:14 us=546000 SIGTERM[hard,] received, process exiting
2022-12-21 14:19:14 us=546000 MANAGEMENT: >STATE:1671625154,EXITING,SIGTERM,,,,,

Server log:

Dec 21 14:19:05 host openvpn[113195]: TCPv4_SERVER link remote: [AF_INET]111.222.333.444:56580
Dec 21 14:19:05 host openvpn[113195]: 111.222.333.444:56580 TLS: Initial packet from [AF_INET]111.222.333.444:56580, sid=19ddce8f eb423716
Dec 21 14:19:05 host openvpn[113195]: 111.222.333.444:56580 VERIFY OK: depth=1, CN=LeeviCA5
Dec 21 14:19:05 host openvpn[113195]: 111.222.333.444:56580 VERIFY OK: depth=0, CN=client40
Dec 21 14:19:05 host openvpn[113195]: 111.222.333.444:56580 peer info: IV_VER=2.6_beta1
Dec 21 14:19:05 host openvpn[113195]: 111.222.333.444:56580 peer info: IV_PLAT=win
Dec 21 14:19:05 host openvpn[113195]: 111.222.333.444:56580 peer info: IV_TCPNL=1
Dec 21 14:19:05 host openvpn[113195]: 111.222.333.444:56580 peer info: IV_MTU=1600
Dec 21 14:19:05 host openvpn[113195]: 111.222.333.444:56580 peer info: IV_NCP=2
Dec 21 14:19:05 host openvpn[113195]: 111.222.333.444:56580 peer info: IV_CIPHERS=AES-256-GCM:AES-128-GCM:CHACHA20-POLY1305
Dec 21 14:19:05 host openvpn[113195]: 111.222.333.444:56580 peer info: IV_PROTO=478
Dec 21 14:19:05 host openvpn[113195]: 111.222.333.444:56580 peer info: IV_LZO_STUB=1
Dec 21 14:19:05 host openvpn[113195]: 111.222.333.444:56580 peer info: IV_COMP_STUB=1
Dec 21 14:19:05 host openvpn[113195]: 111.222.333.444:56580 peer info: IV_COMP_STUBv2=1
Dec 21 14:19:05 host openvpn[113195]: 111.222.333.444:56580 peer info: IV_GUI_VER=OpenVPN_GUI_11
Dec 21 14:19:05 host openvpn[113195]: 111.222.333.444:56580 peer info: IV_SSO=openurl,crtext
Dec 21 14:19:05 host openvpn[113195]: 111.222.333.444:56580 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, peer certificate: 2048 bit RSA, signature: RSA-SHA256
Dec 21 14:19:05 host openvpn[113195]: 111.222.333.444:56580 [client40] Peer Connection Initiated with [AF_INET]111.222.333.444:56580
Dec 21 14:19:05 host openvpn[113195]: client40/111.222.333.444:56580 MULTI_sva: pool returned IPv4=10.58.0.2, IPv6=2001:db8:0:456::1000
Dec 21 14:19:05 host kernel: [2598861.565751] tun0: ovpn_netlink_new_peer: adding peer with endpoint=(null)/TCP id=0 VPN-IPv4=10.58.0.2 VPN-IPv6=2001:db8:0:456::1000
Dec 21 14:19:05 host kernel: [2598861.565781] tun0: ovpn_peer_keepalive_set: scheduling keepalive for peer 0: interval=30 timeout=360
Dec 21 14:19:05 host kernel: [2598861.565873] ********* Cipher gcm(aes) (encrypt)
Dec 21 14:19:05 host kernel: [2598861.565873] *** IV size=12
Dec 21 14:19:05 host kernel: [2598861.565874] *** req size=88
Dec 21 14:19:05 host kernel: [2598861.565875] *** block size=1
Dec 21 14:19:05 host kernel: [2598861.565876] *** auth size=16
Dec 21 14:19:05 host kernel: [2598861.565876] *** alignmask=0xf
Dec 21 14:19:05 host kernel: [2598861.565879] ********* Cipher gcm(aes) (decrypt)
Dec 21 14:19:05 host kernel: [2598861.565880] *** IV size=12
Dec 21 14:19:05 host kernel: [2598861.565881] *** req size=88
Dec 21 14:19:05 host kernel: [2598861.565881] *** block size=1
Dec 21 14:19:05 host kernel: [2598861.565882] *** auth size=16
Dec 21 14:19:05 host kernel: [2598861.565882] *** alignmask=0xf
Dec 21 14:19:05 host kernel: [2598861.565883] tun0: ovpn_netlink_new_key: new key installed (id=0) for peer 0
Dec 21 14:19:05 host kernel: [2598861.566086] tun0: ovpn_netlink_packet: sending userspace packet to peer 0...
Dec 21 14:19:05 host openvpn[113195]: client40/111.222.333.444:56580 MULTI: Learn: 10.58.0.2 -> client40/111.222.333.444:56580
Dec 21 14:19:05 host openvpn[113195]: client40/111.222.333.444:56580 MULTI: primary virtual IP for client40/111.222.333.444:56580: 10.58.0.2
Dec 21 14:19:05 host openvpn[113195]: client40/111.222.333.444:56580 MULTI: Learn: 2001:db8:0:456::1000 -> client40/111.222.333.444:56580
Dec 21 14:19:05 host openvpn[113195]: client40/111.222.333.444:56580 MULTI: primary virtual IPv6 for client40/111.222.333.444:56580: 2001:db8:0:456::1000
Dec 21 14:19:05 host openvpn[113195]: client40/111.222.333.444:56580 Data Channel: using negotiated cipher 'AES-256-GCM'
Dec 21 14:19:05 host openvpn[113195]: client40/111.222.333.444:56580 Data Channel MTU parms [ mss_fix:1386 max_frag:0 tun_mtu:1500 tun_max_mtu:1600 headroom:136 payload:1768 tailroom:562 ET:0 ]
Dec 21 14:19:05 host openvpn[113195]: client40/111.222.333.444:56580 SENT CONTROL [client40]: 'PUSH_REPLY,tun-ipv6,route-gateway 10.58.0.1,topology subnet,ping 30,ping-restart 180,ifconfig-ipv6 2001:db8:0:456::1000/64 2001:db8:0:456::1,ifconfig 10.58.0.2 255.255.255.0,peer-id 0,cipher AES-256-GCM,protocol-flags cc-exit tls-ekm,tun-mtu 1500' (status=1)
Dec 21 14:19:05 host kernel: [2598861.617955] tun0: ovpn_netlink_send_packet: sending packet to userspace, len: 34
Dec 21 14:19:19 host kernel: [2598875.297775] tun0: no peer to send data to
Dec 21 14:19:35 host openvpn[113195]: client40/111.222.333.444:56580 SIGTERM[soft,ovpn-dco: transport error] received, client-instance exiting
Dec 21 14:19:35 host kernel: [2598891.680449] tun0: ovpn_peer_ping: sending ping to peer 0
Dec 21 14:19:35 host kernel: [2598891.680488] ovpn_tcp_tx_work: cannot send TCP packet to peer 0: -104
Dec 21 14:19:35 host kernel: [2598891.680511] tun0: tun0: deleting peer with id 0, reason 3
Dec 21 14:20:22 host kernel: [2598938.780711] tun0: no peer to send data to
Dec 21 14:22:27 host kernel: [2599063.698978] tun0: no peer to send data to
Dec 21 14:26:54 host kernel: [2599329.918418] tun0: no peer to send data to
Dec 21 14:35:21 host kernel: [2599837.782652] tun0: no peer to send data to

As it can be seen from the logs above, client disconnected at 14:19:14 and server removed client instance at 14:19:35 when ovpn-dco wasn't able to send keepalive message.
@ordex
Copy link
Member

ordex commented Jan 11, 2023

A fix has been pushed to the master branch. Userspace does not need to be patched, although I have sent a patch over the ml to improve logging in this specific scenario.

@lstipakov want to give it a go?

@ordex ordex self-assigned this Jan 11, 2023
@ordex ordex added the bug Something isn't working label Jan 11, 2023
@lstipakov
Copy link
Member Author

I can confirm that it works.

Userspace OpenVPN 2.6_rc1 [git:release/2.6/bfd0ef36c46f8326]
Kernel OpenVPN data channel offload (ovpn-dco) 0.1.20221107-2-g0c71691 -- (C) 2020-2022 OpenVPN, Inc.

After stopping client I got this in server log:

openvpn[151316]: client40/185.38.2.3:53157 SIGTERM[soft,ovpn-dco: unknown reason] received, client-instance exiting
kernel: [4485892.570554] tun0: deleting peer with id 0, reason 4

I was able to reconnect without any issues.

With this patch I see the proper log message:

openvpn[152253]: client40/185.38.2.3:53439 SIGTERM[soft,ovpn-dco: transport disconnected] received, client-instance exiting

@cron2
Copy link
Contributor

cron2 commented Jan 12, 2023 via email

@cron2 cron2 reopened this Jan 12, 2023
@ordex
Copy link
Member

ordex commented Jan 15, 2023

@cron2 may it be related to the other issue? I.e. netlink buffer got full and some messages got lost?

@cron2
Copy link
Contributor

cron2 commented Jan 15, 2023 via email

@ordex
Copy link
Member

ordex commented Jan 16, 2023

Good question, but I don't know. DEL_PEER is delivered in multicast, so there is no "read a unicast message on your socket". And I am not sure if we are performing any read since we are not getting notified of any new message.

But yeah, I would also expect $some error at that point...So maybe this was not the right hint

@ordex
Copy link
Member

ordex commented Jan 16, 2023

@cron2 from the log, would you be able to check if you received a DEL_PEER for all peers or if indeed we are missing some of them? This would help understanding where the issue is (i.e. event not sent/received at all or event not properly handled)

@ordex
Copy link
Member

ordex commented Mar 14, 2023

The issue has been reported as fixed. The latest ovpn-dco release moves control packets back to the transport sockets rather than using netlink, and thanks to this also diusconnection detection is handled again in userspace directly.

@ordex ordex closed this as completed Mar 14, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@ordex ordex

Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@lstipakov @ordex @cron2