'route-up' script gets executed immediately after 'up' script, before connection gets established

[yurydev1]

Hi @all

Faced with this behaviour for quite a while, thought I don't understand something or specific host is not properly setup but now got strong opinion it doesn't work as expected since see the same behaviour on Ubuntu 20.04 server on various hosts and now, also, on entware (on Keenetic), so it doesn't look for me any longer like it's a question of proper setup or OS.

In client and server config (tun) I have following scripts

Code: Select all

up 		./10.0.x.2_routed.script_01.up.sh
route-up	./10.0.x.2_routed.script_05.route-up.sh
route-pre-down	./10.0.x.2_routed.script_06.route-pre-down.sh
down 		./10.0.x.2_routed.script_08.down.sh

Documentations states 'up' script should be executed after TCP/UDP socket bind and TUN/TAP open and 'route-up' - after connection authentication, either immediately after, or some number of seconds after as defined by the –route-delay option.

From logs I see that 'up' script is immediately followed by 'route-up' script without any delays and actual connection is authenticated few seconds later.

Code: Select all

Mon Sep 11 14:59:42 2023 us=818656 WARNING: No server certificate verification method has been enabled.  See http://openvpn.net/howto.html#mitm for more info.
Mon Sep 11 14:59:42 2023 us=818928 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Mon Sep 11 14:59:42 2023 us=825726 LZ4 compression initializing
Mon Sep 11 14:59:42 2023 us=826332 Control Channel MTU parms [ L:1558 D:1212 EF:38 EB:0 ET:0 EL:3 ]
Mon Sep 11 14:59:42 2023 us=830898 TUN/TAP device tun_10_0_13_2 opened
Mon Sep 11 14:59:42 2023 us=831239 TUN/TAP TX queue length set to 100
Mon Sep 11 14:59:42 2023 us=831347 do_ifconfig, tt->did_ifconfig_ipv6_setup=0
Mon Sep 11 14:59:42 2023 us=831401 /sbin/ip link set dev tun_10_0_x_2 up mtu 1500
Mon Sep 11 14:59:42 2023 us=844285 /sbin/ip addr add dev tun_10_0_x_2 local 10.0.111.2 peer 10.0.111.1
Mon Sep 11 14:59:42 2023 us=850003 ./10.0.x.2_routed.script_01.up.sh tun_10_0_13_2 1500 1558 10.0.111.2 10.0.111.1 init
<14>Sep 11 14:59:42 update-systemd-resolved: Link 'tun_10_0_13_2' coming up
<14>Sep 11 14:59:42 update-systemd-resolved: Adding IPv4 DNS Server 10.0.111.1
<14>Sep 11 14:59:42 update-systemd-resolved: Adding DNS Domain aaa-intra
<14>Sep 11 14:59:42 update-systemd-resolved: Adding DNS Routed Domain .
<14>Sep 11 14:59:42 update-systemd-resolved: SetLinkDNS(235 1 2 4 10 0 13 1)
<14>Sep 11 14:59:42 update-systemd-resolved: SetLinkDomains(235 2 aaa-intra false . true)
./10.0.x.2_routed.script_05.route-up.sh: 7: cannot create : Directory nonexistent
RTNETLINK answers: File exists
Mon Sep 11 14:59:43 2023 us=108332 Data Channel MTU parms [ L:1558 D:1450 EF:58 EB:395 ET:0 EL:3 ]
Mon Sep 11 14:59:43 2023 us=108538 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1558,tun-mtu 1500,proto UDPv4,ifconfig 10.0.111.1 10.0.111.2,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-client'
Mon Sep 11 14:59:43 2023 us=108589 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1558,tun-mtu 1500,proto UDPv4,ifconfig 10.0.111.2 10.0.111.1,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-server'
Mon Sep 11 14:59:43 2023 us=108692 TCP/UDP: Preserving recently used remote address: [AF_INET]78.XX.XX.XX:1234
Mon Sep 11 14:59:43 2023 us=108788 Socket Buffers: R=[212992->212992] S=[212992->212992]
Mon Sep 11 14:59:43 2023 us=108833 UDP link local: (not bound)
Mon Sep 11 14:59:43 2023 us=108877 UDP link remote: [AF_INET]78.XX.XX.XX:1234
Mon Sep 11 14:59:43 2023 us=183082 TLS: Initial packet from [AF_INET]78.XX.XX.XX:1234, sid=3f4f73a1 2967f1aa
Mon Sep 11 14:59:43 2023 us=249786 VERIFY OK: depth=1, C=UK, ST=London, L=London, O=Nnnnnnnn AM, OU=Nnnnnnnn AM IT, emailAddress=admin@nnnnnnnnnn.com
Mon Sep 11 14:59:43 2023 us=250732 VERIFY OK: depth=0, C=UK, ST=London, L=London, O=Nnnnnnnn AM, OU=Nnnnnnnn AM IT, CN=storage.rem.nnn-intra, emailAddress=admin@nnnnnnnnnn.com
Mon Sep 11 14:59:43 2023 us=344332 Outgoing Data Channel: Cipher 'AES-256-CBC' initialized with 256 bit key
Mon Sep 11 14:59:43 2023 us=344556 Outgoing Data Channel: Using 160 bit message hash 'SHA1' for HMAC authentication
Mon Sep 11 14:59:43 2023 us=344698 Incoming Data Channel: Cipher 'AES-256-CBC' initialized with 256 bit key
Mon Sep 11 14:59:43 2023 us=344849 Incoming Data Channel: Using 160 bit message hash 'SHA1' for HMAC authentication
Mon Sep 11 14:59:43 2023 us=345192 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, 2048 bit RSA
Mon Sep 11 14:59:43 2023 us=345394 [storage.rem.nnn-intra] Peer Connection Initiated with [AF_INET]78.XX.XX.XX:1234
Mon Sep 11 14:59:44 2023 us=585205 Initialization Sequence Completed

If for some reason client cannot connect to server then I'm getting into erroneous state since I expect 'route-up' gets executed when connection almost ready and I can, for example, change default route for specific destination to the the one via VPN tunnel and if the tunnel never establishes this leads non-working routes.

Is it something I don't understand in openvpn setup or it's an issue in openvpn. Tends to think it's my understanding since I couldn't find anyone complaining about the same problem.

[yurydev1]

For those who have the same question - I think I found the reason for seemingly wrong behaviour ('route-up' executed immediately after 'up') - the 'route-delay' parameter defines the behaviour, if omitted - 'route-up' will be executed immediately after mmediately after TUN/TAP device open and 'up' script execution and in case defined (even with 0) - only after connection established with the defined by 'route-delay' delay.