Community discussions

MikroTik App
 
olegl
just joined
Topic Author
Posts: 4
Joined: Mon Sep 04, 2017 3:13 pm

mikrotik openvpn client stucks while initialization

Tue Sep 05, 2017 11:03 am

mikrotik openvpn client stucks while initialization

Hello.
I have a strange error with Mikrotik (RB951Ui-2HnD) working like OVPN-client.

On the server side we have a OpenVPN (2.4.0.) server with radiusplugin and freeradius.
On the client side we have a RB951Ui-2HnD authorizing via login+passwd.
Recently I`ve noticed strange behavior with Mikrotik.
While connecting to server I see on the client side
int ovpn-client disable 0
int ovpn-client enab 0
int ovpn-client moni 0
status: link established
mtu: 1500

но ovpn-out1 interface, no connection from mtik to server.

But from the server side I see
! attempt-1
Sep 4 16:16:28 localhost openvpn[17842]: TCP connection established with [AF_INET]10.104.20.52:43452
Sep 4 16:16:28 localhost openvpn[17842]: 10.104.20.52:43452 TLS: Initial packet from [AF_INET]10.104.20.52:43452, sid=41e848c9 bd415f2a
Sep 4 16:16:28 localhost openvpn[17842]: 10.104.20.52:43452 PLUGIN_CALL: POST /usr/lib64/openvpn/plugin/lib/radiusplugin.so/PLUGIN_AUTH_USER_PASS_VERIFY status=2
Sep 4 16:16:28 localhost openvpn[17842]: 10.104.20.52:43452 TLS: Username/Password authentication deferred for username 'user_login' [CN SET]
*** authorize ***
(('User-Name', '"user_login"'), ('User-Password', '"secret_passwd"'), ('NAS-IP-Address', '10.8.193.12'), ('NAS-Port', '1'), ('Service-Type', 'Outbound-User'), ('Calling-Station-Id', '"10.104.20.52"'), ('NAS-Identifier', '"vpnmm2.corp.domain.ru"'), ('Acct-Session-Id', '"8DCA4B081DA2258D1424A103C20B9991"'), ('NAS-Port-Type', 'Virtual'))
================================================================================
Sep 4 16:16:28 localhost openvpn[17842]: 10.104.20.52:43452 Data Channel Encrypt: Cipher 'AES-256-CBC' initialized with 256 bit key
Sep 4 16:16:28 localhost openvpn[17842]: 10.104.20.52:43452 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Sep 4 16:16:28 localhost openvpn[17842]: 10.104.20.52:43452 Data Channel Decrypt: Cipher 'AES-256-CBC' initialized with 256 bit key
Sep 4 16:16:28 localhost openvpn[17842]: 10.104.20.52:43452 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Sep 4 16:16:28 localhost openvpn[17842]: 10.104.20.52:43452 Control Channel: TLSv1.2, cipher TLSv1/SSLv3 ECDHE-RSA-AES256-GCM-SHA384
Sep 4 16:16:28 localhost openvpn[17842]: 10.104.20.52:43452 [user_login] Peer Connection Initiated with [AF_INET]10.104.20.52:43452
Sep 4 16:16:28 localhost openvpn[17842]: 10.104.20.52:43452 PUSH: Received control message: 'PUSH_REQUEST'
Sep 4 16:19:48 localhost openvpn[17842]: 10.104.20.52:43452 [user_login] Inactivity timeout (--ping-restart), restarting
Sep 4 16:19:48 localhost openvpn[17842]: 10.104.20.52:43452 SIGUSR1[soft,ping-restart] received, client-instance restarting

! attempt-2
Sep 4 16:19:48 localhost openvpn[17842]: TCP connection established with [AF_INET]10.104.20.52:43453
Sep 4 16:19:48 localhost openvpn[17842]: 10.104.20.52:43453 TLS: Initial packet from [AF_INET]10.104.20.52:43453, sid=00429836 6d54a0cc
Sep 4 16:19:48 localhost openvpn[17842]: 10.104.20.52:43453 PLUGIN_CALL: POST /usr/lib64/openvpn/plugin/lib/radiusplugin.so/PLUGIN_AUTH_USER_PASS_VERIFY status=2
Sep 4 16:19:48 localhost openvpn[17842]: 10.104.20.52:43453 TLS: Username/Password authentication deferred for username 'user_login' [CN SET]
Sep 4 16:19:48 localhost openvpn[17842]: 10.104.20.52:43453 Data Channel Encrypt: Cipher 'AES-256-CBC' initialized with 256 bit key
*** authorize ***
Sep 4 16:19:48 localhost openvpn[17842]: 10.104.20.52:43453 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
(('User-Name', '"user_login"'), ('User-Password', '"secret_passwd"'), ('NAS-IP-Address', '10.8.193.12'), ('NAS-Port', '1'), ('Service-Type', 'Outbound-User'), ('Calling-Station-Id', '"10.104.20.52"'), ('NAS-Identifier', '"vpnmm2.corp.domain.ru"'), ('Acct-Session-Id', '"E6B7A7911680C57399D410E137897871"'), ('NAS-Port-Type', 'Virtual'))
================================================================================
Sep 4 16:19:48 localhost openvpn[17842]: 10.104.20.52:43453 Data Channel Decrypt: Cipher 'AES-256-CBC' initialized with 256 bit key
Sep 4 16:19:48 localhost openvpn[17842]: 10.104.20.52:43453 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Sep 4 16:19:48 localhost openvpn[17842]: 10.104.20.52:43453 Control Channel: TLSv1.2, cipher TLSv1/SSLv3 ECDHE-RSA-AES256-GCM-SHA384
Sep 4 16:19:48 localhost openvpn[17842]: 10.104.20.52:43453 [user_login] Peer Connection Initiated with [AF_INET]10.104.20.52:43453
Sep 4 16:19:48 localhost openvpn[17842]: 10.104.20.52:43453 PUSH: Received control message: 'PUSH_REQUEST'

! attempt-3
Sep 4 16:20:34 localhost openvpn[17842]: TCP connection established with [AF_INET]10.104.20.52:43455
Sep 4 16:20:34 localhost openvpn[17842]: 10.104.20.52:43455 TLS: Initial packet from [AF_INET]10.104.20.52:43455, sid=a08f1e6d 70b4abd6
Sep 4 16:20:34 localhost openvpn[17842]: 10.104.20.52:43455 PLUGIN_CALL: POST /usr/lib64/openvpn/plugin/lib/radiusplugin.so/PLUGIN_AUTH_USER_PASS_VERIFY status=2
Sep 4 16:20:34 localhost openvpn[17842]: 10.104.20.52:43455 TLS: Username/Password authentication deferred for username 'user_login' [CN SET]
Sep 4 16:20:34 localhost openvpn[17842]: 10.104.20.52:43455 Data Channel Encrypt: Cipher 'AES-256-CBC' initialized with 256 bit key
*** authorize ***
Sep 4 16:20:34 localhost openvpn[17842]: 10.104.20.52:43455 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
(('User-Name', '"user_login"'), ('User-Password', '"secret_passwd"'), ('NAS-IP-Address', '10.8.193.12'), ('NAS-Port', '1'), ('Service-Type', 'Outbound-User'), ('Calling-Station-Id', '"10.104.20.52"'), ('NAS-Identifier', '"vpnmm2.corp.domain.ru"'), ('Acct-Session-Id', '"CAB38DAD87B9C70CC72E0B23400A3B40"'), ('NAS-Port-Type', 'Virtual'))
================================================================================
Sep 4 16:20:34 localhost openvpn[17842]: 10.104.20.52:43455 Data Channel Decrypt: Cipher 'AES-256-CBC' initialized with 256 bit key
Sep 4 16:20:34 localhost openvpn[17842]: 10.104.20.52:43455 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Sep 4 16:20:34 localhost openvpn[17842]: 10.104.20.52:43455 Control Channel: TLSv1.2, cipher TLSv1/SSLv3 ECDHE-RSA-AES256-GCM-SHA384
Sep 4 16:20:34 localhost openvpn[17842]: 10.104.20.52:43455 [user_login] Peer Connection Initiated with [AF_INET]10.104.20.52:43455
Sep 4 16:20:34 localhost openvpn[17842]: user_login/10.104.20.52:43455 OPTIONS IMPORT: reading client specific options from: ccd/user_login
Sep 4 16:20:34 localhost openvpn[17842]: user_login/10.104.20.52:43455 PLUGIN_CALL: POST /usr/lib64/openvpn/plugin/lib/radiusplugin.so/PLUGIN_CLIENT_CONNECT status=0
Sep 4 16:20:34 localhost openvpn[17842]: user_login/10.104.20.52:43455 OPTIONS IMPORT: reading client specific options from: /tmp/openvpn_cc_0f19287f4e0b2539e1de14574a88e6ee.tmp
Sep 4 16:20:34 localhost openvpn[17842]: user_login/10.104.20.52:43455 OPTIONS IMPORT: reading client specific options from: /tmp/openvpn_cc_67a25d76411f8ae5a6c4c9bc4c57f275.tmp
Sep 4 16:20:34 localhost openvpn[17842]: user_login/10.104.20.52:43455 MULTI: Learn: 10.99.254.7 -> user_login/10.104.20.52:43455
Sep 4 16:20:34 localhost openvpn[17842]: user_login/10.104.20.52:43455 MULTI: primary virtual IP for user_login/10.104.20.52:43455: 10.99.254.7
Sep 4 16:20:34 localhost openvpn[17842]: user_login/10.104.20.52:43455 PUSH: Received control message: 'PUSH_REQUEST'
Sep 4 16:20:34 localhost openvpn[17842]: user_login/10.104.20.52:43455 SENT CONTROL [user_login]: 'PUSH_REPLY,route 194.67.29.98 255.255.255.255,route 194.84.87.14 255.255.255.255,route 193.19.170.205 255.255.255.255,route 10.0.0.0 255.0.0.0,ping 5,ping-restart 200,persist-tun,persist-key,sndbuf 0,rcvbuf 0,route-gateway 10.98.0.1,topology subnet,ifconfig 10.99.254.7 255.254.0.0' (status=1)

What we see - is that client sending PUSH_REQUEST to the server before openvpn radiusplugin returns OK (status=0)
If it appears - some king of misordering appears , client stucks waiting for PUSH_REPLY, but server doesn`t sending PUSH_REPLY because he waits for radiusplugin return code.
ping-restart timeout will terminate this session.
In case of PUSH_REQUEST arrives after radiusplugin return code - everything is fine, connection is succesfully established in 2-3 seconds.

I`ve take another router (dlink dir-620 d1 with openwrt), set up openvpn as client - no problem appears.
10 attempts to connect to server - always PUSH_REQUEST arrives AFTER radiusplugin.

Is there any king of detailed description of RouterOS OpenVPN stages description?
What is happened between status: "link established" and status:"connected" ? Is it software error of this behaviour can be changed using some options ?
 
olegl
just joined
Topic Author
Posts: 4
Joined: Mon Sep 04, 2017 3:13 pm

Re: mikrotik openvpn client stucks while initialization

Tue Nov 21, 2017 8:51 am

freshing up the topic.
Any info about this problem?
 
olegl
just joined
Topic Author
Posts: 4
Joined: Mon Sep 04, 2017 3:13 pm

Re: mikrotik openvpn client stucks while initialization

Wed Dec 13, 2017 8:41 am

Problem solved.
Problem was on a server side
By default openvpn doest not enable this option
async-push -
enable async-push support for plugins providing deferred authentication @<:@default=no@:>@])
 
lamclennan
just joined
Posts: 18
Joined: Wed Aug 17, 2016 8:14 am
Location: Mungindi

Re: mikrotik openvpn client stucks while initialization

Fri Feb 21, 2020 6:32 am

Experienced this dialing a pfsense firewall OpenVPN server. I've had to put a 10ms tarpit in place to give LDAP time to respond as the client was very close. Emailed support in the hope the client could be improved, however, this may be a feature?

pfSense feature request raised https://redmine.pfsense.org/issues/10273 and looks to now be added to FreeBSD port