Fatal error: Assertion failed at misc.c:785 (es)

[mogikanin]

We are developing custom vpn client for windows, which parses messages from openvpn console output. Sometimes (by some our conditions) we are sending SIGTERM signal.
And there is fatal error, if send SIGTERM immediately after openvpn reports about SIGUSR1 signal.

Steps to reproduce:
send SIGTERM signal immediately after receiving log message about SIGUSR1.

03/23/2016 13:12:47 OpenVPN msg: SIGUSR1[soft,ping-restart] received, process restarting
03/23/2016 13:12:47 OpenVPN msg: Restart pause, 2 second(s)
03/23/2016 13:12:47 OpenVPN msg: Assertion failed at misc.c:785 (es)
03/23/2016 13:12:47 OpenVPN msg: Exiting due to fatal error

In case if I send SIGTERM after waiting 2 seconds, openvpn.exe closes normally (with restoring routes, etc).

Reproduced on Windows10 x64, Win7 x86, probably on other platforms too.

[Gert Döring]

How do I send signals on windows?

[mogikanin]

It may be done by several ways.

1. Via Management Interface. https://openvpn.net/index.php/open-source/documentation/miscellaneous/79-management-interface.html

COMMAND -- signal

2. Via config parameter --service exit-event.

https://openvpn.net/index.php/open-source/documentation/manuals/65-openvpn-20x-manpage.html

[Selva Nair]

I can confirm that this happens on 2.3.11 as well. Steps to reproduce:

With the tunnel established, connect to the MI of the client (say, by telnet) and in a quick succession issue two management commands:

signal SIGUSR1 
signal SIGTERM

The two commands should not be separated by more than 2 seconds as SIGTERM should be received during the restart pause which is 2 seconds in 2.3.x.

openvpn will abort with

FATAL: Assertion failed at misc.c:785 (es)

So something is setting or unsetting an env variable with a NULL env_set pointer.

[Selva Nair]

Looking further into this:
This is not a windows only issue, can reproduce on Linux too. Follow the same steps as above. Here is a stack trace just before the failing ASSERT (running latest release/2.3 branch)

#0  setenv_str_ex (es=0x0, name=0x48a845 "signal", value=0x488313 "init_instance", name_include=32772,
    name_exclude=0, name_replace=0 '\000', value_include=128, value_exclude=0, value_replace=0 '\000')
    at misc.c:785
#1  0x000000000042c975 in setenv_str (es=0x0, name=0x48a845 "signal", value=0x488313 "init_instance")
    at misc.c:741
#2  0x000000000042b57e in run_up_down (command=0x0, plugins=0x0, plugin_type=12, arg=0x6e4f58 "tun1",
    dev_type=0x0, tun_mtu=0, link_mtu=0, ifconfig_local=0x6e8408 "10.9.0.6",
    ifconfig_remote=0x6e8478 "255.255.255.0", context=0x487340 "init",
    signal_text=0x488313 "init_instance", script_type=0x487398 "route-pre-down", es=0x0) at misc.c:81
#3  0x000000000041e00f in do_close_tun (c=0x7fffffffd950, force=false) at init.c:1575
#4  0x0000000000422043 in close_instance (c=0x7fffffffd950) at init.c:3580
#5  0x0000000000422571 in close_context (c=0x7fffffffd950, sig=-1, flags=4) at init.c:3755
#6  0x0000000000421f68 in init_instance (c=0x7fffffffd950, env=0x6dcba0, flags=4) at init.c:3541
#7  0x0000000000421857 in init_instance_handle_signals (c=0x7fffffffd950, env=0x6dcba0, flags=4)
    at init.c:3301
#8  0x000000000043e777 in tunnel_point_to_point (c=0x7fffffffd950) at openvpn.c:70
#9  0x000000000043eb77 in openvpn_main (argc=5, argv=0x7fffffffe6a8) at openvpn.c:270
#10 0x000000000043ec8a in main (argc=5, argv=0x7fffffffe6a8) at openvpn.c:345

So run_up_down during SIGTERM exit is called with es = 0. This appears to be because during the restart pause in init_instance(..), c->c2.es will be NULL (cleared at re-entry to tunnel_point_to_point(..)) and that's when SIGTERM is received and run_up_down(..) called. Note that this call is made even if there are no scripts to execute.

The git master branch is not affected probably because of do_inherit_env(..) in init_instance(..) before the restart pause?

[slesru]

Hello!

Hit this issue yesterday while testing patch for another issue ( ​https://community.openvpn.net/openvpn/ticket/845 )

This is OpenVPN 2.3.14 on Ubuntu 16.10 x64, compiled with --enable-small.

And there is redirect-gateway in config.

If connect is OK, then everything is fine:

Fri Mar 24 09:16:15 2017 /sbin/route add -net 192.168.222.118 netmask 255.255.255.255 gw 192.168.22.221
Fri Mar 24 09:16:15 2017 /sbin/route del -net 0.0.0.0 netmask 0.0.0.0
Fri Mar 24 09:16:15 2017 /sbin/route add -net 0.0.0.0 netmask 0.0.0.0 gw 192.168.43.1
Fri Mar 24 09:16:15 2017 /sbin/route add -net 192.168.0.0 netmask 255.255.0.0 gw 192.168.43.1
Fri Mar 24 09:16:15 2017 /sbin/route add -net 10.0.0.0 netmask 255.0.0.0 gw 192.168.43.1
....
Ctrl-C somewhere here
....
Fri Mar 24 09:16:30 2017 /sbin/route del -net 10.0.0.0 netmask 255.0.0.0
Fri Mar 24 09:16:30 2017 /sbin/route del -net 192.168.0.0 netmask 255.255.0.0
Fri Mar 24 09:16:30 2017 /sbin/route del -net 192.168.222.118 netmask 255.255.255.255
Fri Mar 24 09:16:30 2017 /sbin/route del -net 0.0.0.0 netmask 0.0.0.0
Fri Mar 24 09:16:30 2017 /sbin/route add -net 0.0.0.0 netmask 0.0.0.0 gw 192.168.22.221

But if different cipher are on server and client side then there is no routes removal:

Fri Mar 24 09:17:00 2017 /sbin/route add -net 192.168.222.118 netmask 255.255.255.255 gw 192.168.22.221
Fri Mar 24 09:17:00 2017 /sbin/route del -net 0.0.0.0 netmask 0.0.0.0
Fri Mar 24 09:17:00 2017 /sbin/route add -net 0.0.0.0 netmask 0.0.0.0 gw 192.168.43.1
Fri Mar 24 09:17:00 2017 /sbin/route add -net 192.168.0.0 netmask 255.255.0.0 gw 192.168.43.1
Fri Mar 24 09:17:00 2017 /sbin/route add -net 10.0.0.0 netmask 255.0.0.0 gw 192.168.43.1
...
Fri Mar 24 09:17:30 2017 SIGUSR1[soft,connection-reset] received, process restarting
Fri Mar 24 09:17:30 2017 Restart pause, 5 second(s)
^{CFri Mar 24 09:17:32 2017 Assertion failed at misc.c:785
Fri Mar 24 09:17:32 2017 Exiting due to fatal error}

Because if this error...

Thank you!

[Gert Döring]

So, if I read this right, this bug only manifests on 2.3.x and not on 2.4.x and later, because environment handling has changed?

In that case, I'd suggest to just close this ticket now - we won't fix "non security critical bugs" in 2.3 anymore.

[slesru]

Hello!

We don't use 2.3 anylonger, only on old 3g modems, and we never hit this problem on modem because we always set the same cipher on both sides now.
I think this can be closed.

Thank you!

[Gert Döring]

Thanks for your feedback. Closing! One less to go... :-)

(With 2.4 servers and up, cipher mismatches are less likely anyway, due to cipher negotiation... provided a 2.4 client or a 2.3 client that is not using --enable-small)