Ubuntu – How to configure upstart for OpenVPN instance which is using the down-root plugin

openvpnUbuntu

  • Ubuntu 14.04
  • OpenVPN 2.3.2
  • Init daemon: upstart

server config file:

topology net30
mode server
tls-server
push "route-gateway 192.168.0.1"
ifconfig 192.168.0.1 192.168.0.2
ifconfig-pool 192.168.0.5 192.168.0.9

port 1196
proto udp
dev tun
keepalive 10 120
comp-lzo
user nobody
group nogroup
persist-key
persist-tun
status /var/log/openvpn/devops.log 1
syslog vpn-devops
verb 15
writepid /var/run/openvpn/devops.pid
ca /etc/openvpn/devops/ca.crt
cert /etc/openvpn/devops/server.crt
key /etc/openvpn/devops/server.key
dh /etc/openvpn/dh.pem
ifconfig-pool-persist /var/lib/openvpn/devops.ipp
client-config-dir /etc/openvpn/devops/ccd
crl-verify /etc/openvpn/devops/crl.pem
client-to-client

Problem: whenever restarting the service, I saw this in the log file:

May 17 14:32:08 t-xhyve vpn-devops[21013]: TCP/UDP: Closing socket
May 17 14:32:08 t-xhyve vpn-devops[21013]: Closing TUN/TAP interface
May 17 14:32:08 t-xhyve vpn-devops[21013]: /sbin/ip addr del dev tun1 local 192.168.0.1 peer 192.168.0.2
May 17 14:32:08 t-xhyve vpn-devops[21013]: Linux ip addr del failed: external program exited with error status: 2

The reason is OpenVPN is running as nobody user which don't have permission to delete the tunnel interface. So, I would like to use the down-root plugin to call a down script with root privileges.

plugin /usr/lib/openvpn/openvpn-plugin-down-root.so /usr/share/openvpn/down.sh

/usr/share/openvpn/down.sh

#!/bin/sh

/sbin/ip addr del dev $1 local $4 peer $5

then try to restart but I got this:

May 17 14:49:47 t-xhyve vpn-devops[23001]: /sbin/ip addr del dev tun1 local 192.168.0.1 peer 192.168.0.2
May 17 14:49:47 t-xhyve vpn-devops[23228]: PKCS#11: __pkcs11h_forkFixup entry pid=23228, activate_slotevent=1
May 17 14:49:47 t-xhyve vpn-devops[23228]: PKCS#11: __pkcs11h_forkFixup return
May 17 14:49:47 t-xhyve vpn-devops[23001]: Linux ip addr del failed: external program exited with error status: 2
May 17 14:49:47 t-xhyve vpn-devops[23001]: PLUGIN_CALL: PRE type=PLUGIN_DOWN
May 17 14:49:47 t-xhyve vpn-devops[23001]: ARGV[0] = '/usr/lib/openvpn/openvpn-plugin-down-root.so'
May 17 14:49:47 t-xhyve vpn-devops[23001]: ARGV[1] = 'tun1'
May 17 14:49:47 t-xhyve vpn-devops[23001]: ARGV[2] = '1500'
May 17 14:49:47 t-xhyve vpn-devops[23001]: ARGV[3] = '1542'
May 17 14:49:47 t-xhyve vpn-devops[23001]: ARGV[4] = '192.168.0.1'
May 17 14:49:47 t-xhyve vpn-devops[23001]: ARGV[5] = '192.168.0.2'
May 17 14:49:47 t-xhyve vpn-devops[23001]: ARGV[6] = 'init'
May 17 14:49:47 t-xhyve vpn-devops[23001]: ENVP[0] = 'dev=tun1'
May 17 14:49:47 t-xhyve vpn-devops[23001]: ENVP[1] = 'link_mtu=1542'
May 17 14:49:47 t-xhyve vpn-devops[23001]: ENVP[2] = 'tun_mtu=1500'
May 17 14:49:47 t-xhyve vpn-devops[23001]: ENVP[3] = 'script_context=init'
May 17 14:49:47 t-xhyve vpn-devops[23001]: ENVP[4] = 'signal=sigterm'
May 17 14:49:47 t-xhyve vpn-devops[23001]: ENVP[5] = 'redirect_gateway=0'
May 17 14:49:47 t-xhyve vpn-devops[23001]: ENVP[6] = 'dev_type=tun'
May 17 14:49:47 t-xhyve vpn-devops[23001]: ENVP[7] = 'ifconfig_remote=192.168.0.2'
May 17 14:49:47 t-xhyve vpn-devops[23001]: ENVP[8] = 'ifconfig_local=192.168.0.1'
May 17 14:49:47 t-xhyve vpn-devops[23001]: ENVP[9] = 'config=/etc/openvpn/devops/config'
May 17 14:49:47 t-xhyve vpn-devops[23001]: ENVP[10] = 'verb=15'
May 17 14:49:47 t-xhyve vpn-devops[23001]: ENVP[11] = 'daemon=0'
May 17 14:49:47 t-xhyve vpn-devops[23001]: ENVP[12] = 'daemon_log_redirect=0'
May 17 14:49:47 t-xhyve vpn-devops[23001]: ENVP[13] = 'daemon_start_time=1463471367'
May 17 14:49:47 t-xhyve vpn-devops[23001]: ENVP[14] = 'daemon_pid=23001'
May 17 14:49:47 t-xhyve vpn-devops[23001]: ENVP[15] = 'proto_1=udp'
May 17 14:49:47 t-xhyve vpn-devops[23001]: ENVP[16] = 'local_port_1=1196'
May 17 14:49:47 t-xhyve vpn-devops[23001]: ENVP[17] = 'remote_port_1=1196'
May 17 14:49:47 t-xhyve vpn-devops[23001]: PLUGIN_CALL: POST /usr/lib/openvpn/openvpn-plugin-down-root.so/PLUGIN_DOWN status=1
May 17 14:49:47 t-xhyve vpn-devops[23001]: PLUGIN_CALL: plugin function PLUGIN_DOWN failed with status 1: /usr/lib/openvpn/openvpn-plugin-down-root.so
May 17 14:49:47 t-xhyve vpn-devops[23001]: ERROR: up/down plugin call failed
May 17 14:49:47 t-xhyve vpn-devops[23001]: Exiting due to fatal error
May 17 14:49:50 t-xhyve openvpn-devops-upstart: RTNETLINK answers: Operation not permitted
May 17 14:49:50 t-xhyve openvpn-devops-upstart: DOWN-ROOT: Error sending script execution signal to background process

I have some questions:

  1. Why OpenVPN still call this?

    /sbin/ip addr del dev tun1 local 192.168.0.1 peer 192.168.0.2

  2. Why do I got this?

    May 17 14:49:47 t-xhyve vpn-devops[23001]: ERROR: up/down plugin call failed
May 17 14:49:47 t-xhyve vpn-devops[23001]: Exiting due to fatal error
May 17 14:49:50 t-xhyve openvpn-devops-upstart: RTNETLINK answers: Operation not permitted
May 17 14:49:50 t-xhyve openvpn-devops-upstart: DOWN-ROOT: Error sending script execution signal to background process

How to solve it?

Are there any app-armor profiles in place?

No.

Try modifying the shell script to do cat /proc/self/status >/tmp/temp.txt and printing out the result here.

/usr/share/openvpn/down.sh

#!/bin/sh

cat /proc/self/status >/tmp/temp.txt
#/sbin/ip addr del dev $1 local $4 peer $5

when restarting:

May 18 16:51:00 t-xhyve vpn-devops[17930]: TCP/UDP: Closing socket
May 18 16:51:00 t-xhyve vpn-devops[17930]: Closing TUN/TAP interface
May 18 16:51:00 t-xhyve vpn-devops[17930]: /sbin/ip addr del dev tun1 local 192.168.0.1 peer 192.168.0.2
May 18 16:51:00 t-xhyve vpn-devops[18520]: PKCS#11: __pkcs11h_forkFixup entry pid=18520, activate_slotevent=1
May 18 16:51:00 t-xhyve vpn-devops[18520]: PKCS#11: __pkcs11h_forkFixup return
May 18 16:51:00 t-xhyve vpn-devops[17930]: Linux ip addr del failed: external program exited with error status: 2
May 18 16:51:00 t-xhyve vpn-devops[17930]: PLUGIN_CALL: PRE type=PLUGIN_DOWN
May 18 16:51:00 t-xhyve vpn-devops[17930]: ARGV[0] = '/usr/lib/openvpn/openvpn-plugin-down-root.so'
May 18 16:51:00 t-xhyve vpn-devops[17930]: ARGV[1] = 'tun1'
May 18 16:51:00 t-xhyve vpn-devops[17930]: ARGV[2] = '1500'
May 18 16:51:00 t-xhyve vpn-devops[17930]: ARGV[3] = '1542'
May 18 16:51:00 t-xhyve vpn-devops[17930]: ARGV[4] = '192.168.0.1'
May 18 16:51:00 t-xhyve vpn-devops[17930]: ARGV[5] = '192.168.0.2'
May 18 16:51:00 t-xhyve vpn-devops[17930]: ARGV[6] = 'init'
May 18 16:51:00 t-xhyve vpn-devops[17930]: ENVP[0] = 'dev=tun1'
May 18 16:51:00 t-xhyve vpn-devops[17930]: ENVP[1] = 'link_mtu=1542'
May 18 16:51:00 t-xhyve vpn-devops[17930]: ENVP[2] = 'tun_mtu=1500'
May 18 16:51:00 t-xhyve vpn-devops[17930]: ENVP[3] = 'script_context=init'
May 18 16:51:00 t-xhyve vpn-devops[17930]: ENVP[4] = 'signal=sigterm'
May 18 16:51:00 t-xhyve vpn-devops[17930]: ENVP[5] = 'redirect_gateway=0'
May 18 16:51:00 t-xhyve vpn-devops[17930]: ENVP[6] = 'dev_type=tun'
May 18 16:51:00 t-xhyve vpn-devops[17930]: ENVP[7] = 'ifconfig_remote=192.168.0.2'
May 18 16:51:00 t-xhyve vpn-devops[17930]: ENVP[8] = 'ifconfig_local=192.168.0.1'
May 18 16:51:00 t-xhyve vpn-devops[17930]: ENVP[9] = 'config=/etc/openvpn/devops/config'
May 18 16:51:00 t-xhyve vpn-devops[17930]: ENVP[10] = 'verb=15'
May 18 16:51:00 t-xhyve vpn-devops[17930]: ENVP[11] = 'daemon=0'
May 18 16:51:00 t-xhyve vpn-devops[17930]: ENVP[12] = 'daemon_log_redirect=0'
May 18 16:51:00 t-xhyve vpn-devops[17930]: ENVP[13] = 'daemon_start_time=1463564660'
May 18 16:51:00 t-xhyve vpn-devops[17930]: ENVP[14] = 'daemon_pid=17930'
May 18 16:51:00 t-xhyve vpn-devops[17930]: ENVP[15] = 'proto_1=udp'
May 18 16:51:00 t-xhyve vpn-devops[17930]: ENVP[16] = 'local_port_1=1196'
May 18 16:51:00 t-xhyve vpn-devops[17930]: ENVP[17] = 'remote_port_1=1196'
May 18 16:51:00 t-xhyve vpn-devops[17930]: PLUGIN_CALL: POST /usr/lib/openvpn/openvpn-plugin-down-root.so/PLUGIN_DOWN status=1
May 18 16:51:00 t-xhyve vpn-devops[17930]: PLUGIN_CALL: plugin function PLUGIN_DOWN failed with status 1: /usr/lib/openvpn/openvpn-plugin-down-root.so
May 18 16:51:00 t-xhyve vpn-devops[17930]: ERROR: up/down plugin call failed
May 18 16:51:00 t-xhyve vpn-devops[17930]: Exiting due to fatal error
May 18 16:51:00 t-xhyve [2016-05-18 16:51:00,738][WARN ]May 18 16:51:01 t-xhyve openvpn-devops-upstart: RTNETLINK answers: Operation not permitted
May 18 16:51:01 t-xhyve openvpn-devops-upstart: DOWN-ROOT: Error sending script execution signal to background process

The process restarted but the log file (/tmp/temp.txt) was not created.

Sure, running that script manually worked fine:

bash -x /usr/share/openvpn/down.sh
 + cat /proc/self/status
 + 

cat /tmp/temp.txt
Name:   cat
State:  R (running)
Tgid:   19246
Ngid:   0
Pid:    19246
PPid:   19245
...

Specifying the full path didn't help:

May 19 03:52:11 t-xhyve openvpn-devops-upstart: RTNETLINK answers: Operation not permitted
May 19 03:52:11 t-xhyve openvpn-devops-upstart: DOWN-ROOT: Error sending script execution signal to background process
May 19 03:52:11 t-xhyve openvpn-devops-upstart: DOWN-ROOT: BACKGROUND: INIT command='/bin/cat /proc/self/status > /tmp/temp.txt'

How are you starting/stopping the service?

@rda: here's the upstart file:

start on (net-device-up
          and local-filesystems
          and runlevel [2345]
          and started rsyslog)
stop on runlevel [!2345]

respawn
respawn limit 6 60

pre-start script
    if [ ! -e /var/run/openvpn ]; then
        mkdir -m 0770 /var/run/openvpn
        chown nobody:nogroup /var/run/openvpn
    fi
end script

exec /usr/sbin/openvpn --config /etc/openvpn/devops/config
post-stop exec sleep 5

An alternative script without using start-stop-daemon, which sends SIGTERM to the main process in an pre-stop script stanza, could look as follows:

I added a pre-stop script as you suggested:

start on (net-device-up
          and local-filesystems
          and runlevel [2345]
          and started rsyslog)
stop on runlevel [!2345]

respawn
respawn limit 6 60

env PIDFILE="/var/run/openvpn/devops.pid"

pre-start script
    if [ ! -e /var/run/openvpn ]; then
        mkdir -m 0770 /var/run/openvpn
        chown nobody:nogroup /var/run/openvpn
    fi
end script

exec /usr/sbin/openvpn --config /etc/openvpn/devops/config

pre-stop script
  PID=`cat $PIDFILE`
  kill -15 $PID
  sleep 1
  if [ "$?" -eq 0 ]; then
    rm -f $PIDFILE
  else
    echo "Unable to stop VPN '$NAME'"
  fi
end script

post-stop exec sleep 5

then I tried to restart using restart openvpn-devops and still got this:

May 25 02:41:54 t-xhyve openvpn-devops-upstart: RTNETLINK answers: Operation not permitted
May 25 02:41:54 t-xhyve openvpn-devops-upstart: DOWN-ROOT: Error sending script execution signal to background process
May 25 02:41:54 t-xhyve openvpn-devops-upstart: DOWN-ROOT: BACKGROUND: INIT command='/bin/cat /proc/self/status > /tmp/temp.txt'

Best Answer

I try to answer the questions in reverse order:

2. Why do I get this?

DOWN-ROOT: Error sending script execution signal to background process

When the down-root plugin is used, the main process will fork() before it drops the root privileges. The module will then remain in a wait state until it receives a message from the main process via pipe to execute the down-script (see readme). The main process will send this message to the down-root module's process when it receives SIGTERM.

As mentioned in this OpenVPN bug with the systemd service configuration file, this error is most likely caused in conjunction with upstart (the default init daemon used by ubuntu 14.04), which will send SIGTERM to both processes. The down-root module's process will terminate, before it has a chance to do its job, calling the down-script.

Use the /etc/init.d/openvpn shipped with Ubuntu to start and stop the service or fix it in the upstart script. A very simple working upstart script could look as follows. Note that it uses start-stop-daemon to send the correct signals.

Create a file /etc/init/openvpn.conf

start on (net-device-up
          and local-filesystems
          and runlevel [2345]
          and started rsyslog)
stop on runlevel [!2345]

respawn
respawn limit 6 60

env PIDFILE="/var/run/openvpn/devops.pid"

pre-start script
    if [ ! -e /var/run/openvpn ]; then
        mkdir -m 0770 /var/run/openvpn
        chown nobody:nogroup /var/run/openvpn
    fi
end script

exec start-stop-daemon --start --quiet --oknodo \
  --pidfile /var/run/openvpn/devops.pid \
  --exec /usr/sbin/openvpn -- --config /etc/openvpn/devops/config < /dev/null

pre-stop script
  exec start-stop-daemon --stop --quiet --oknodo \
    --pidfile $PIDFILE --exec /usr/sbin/openvpn --retry 5
  if [ "$?" -eq 0 ]; then
    rm -f $PIDFILE
  else
    echo "Unable to stop VPN"
  fi
end script

post-stop exec sleep 5

An alternative script without using start-stop-daemon, which sends SIGTERM to the main process in a pre-stop script stanza, could look as follows:

start on (net-device-up
          and local-filesystems
          and runlevel [2345]
          and started rsyslog)
stop on runlevel [!2345]

respawn
respawn limit 6 60

env PIDFILE="/var/run/openvpn/devops.pid"

pre-start script
    if [ ! -e /var/run/openvpn ]; then
        mkdir -m 0770 /var/run/openvpn
        chown nobody:nogroup /var/run/openvpn
    fi
end script

exec /usr/sbin/openvpn --config /etc/openvpn/devops/config

pre-stop script
  PID=`cat $PIDFILE`
  kill -15 $PID
  sleep 1
  if [ "$?" -eq 0 ]; then
    rm -f $PIDFILE
  else
    echo "Unable to stop VPN"
  fi
end script

post-stop exec sleep 5

Controlling the upstart job:

initctl <command> openvpn
  • <command>: start, stop, restart

This should remove the error above and run the down.sh script correctly, but the following error will still show up:

Linux ip addr del failed: external program exited with error status: 2

This error occurs in the first place, because ip addr del is executed after the TUN/TAP interface has already been closed.

More on this below.

1. Why does OpenVPN still call this?

/sbin/ip addr del dev tun1 local 192.168.0.1 peer 192.168.0.2

This is caused by the directive ifconfig, which will add/del the IP-address of the TUN/TAP interface when starting/stopping the service. (See manpage)

To circumvent this behavior, modify the configuration as follows.

OpenVPN server configuration file:

topology net30
mode server
tls-server
push "route-gateway 192.168.0.1"
ifconfig 192.168.0.1 192.168.0.2
ifconfig-pool 192.168.0.5 192.168.0.9
ifconfig-noexec
up /usr/share/openvpn/up.sh
down-pre
plugin /usr/lib/openvpn/openvpn-plugin-down-root.so /usr/share/openvpn/down.sh
script-security 2
port 1196
proto udp
dev tun
keepalive 10 120
comp-lzo
user nobody
group nogroup
persist-key
persist-tun
status /var/log/openvpn/devops.log 1
syslog vpn-devops
verb 15
writepid /var/run/openvpn/devops.pid
ca /etc/openvpn/devops/ca.crt
cert /etc/openvpn/devops/server.crt
key /etc/openvpn/devops/server.key
dh /etc/openvpn/dh.pem
ifconfig-pool-persist /var/lib/openvpn/devops.ipp
client-config-dir /etc/openvpn/devops/ccd
crl-verify /etc/openvpn/devops/crl.pem
client-to-client
  • ifconfig-noexec: Don't execute ifconfig commands, pass --ifconfig parameters to scripts.
  • up: Running an up-script to set an IP-address is required due to ifconfig-noexec
  • down-pre: Call --down script before, rather than after, TUN/TAP close.
  • script-security 2: Allow calling of built-in executables and user-defined scripts.

UP script /usr/share/openvpn/up.sh:

#!/bin/sh

/sbin/ip addr add dev $1 local $4 peer $5
/sbin/ip link set dev $1 up

DOWN script /usr/share/openvpn/down.sh:

#!/bin/sh

/sbin/ip addr del dev $1 local $4 peer $5
/sbin/ip link set dev $1 down

The UP / DOWN scripts will also bring the interface up and down (although not required).

Make sure they are executable:

chmod +x /usr/share/openvpn/up.sh
chmod +x /usr/share/openvpn/down.sh

Alternatively use a persistent TUN interface

OpenVPN server configuration file (edit/add those lines):

dev tun1
# down-pre
  • dev tun1: We'll be using a persistent TUN interface
  • # down-pre: Not required using persistent interface

Finally create a persistent TUN interface:

openvpn --mktun --dev tun1

This builds a persistent tunnel tun1 that lives through multiple instantiations of OpenVPN and dies only when it is deleted with openvpn --rmtun --dev tun1 or the machine is rebooted.

Troubleshooting

Here are some additional troubleshooting steps if the configuration is correct as shown above and the following error still shows up:

DOWN-ROOT: Error sending script execution signal to background process

Start the OpenVPN instance, i.e. with upstart:

initctl start openvpn

Check what PID the processes have:

ps -ef | grep "[o]penvpn"

# or more specific for our devops server example
ps -ef | grep "[o]penvpn/devops"

# this should show 2 openvpn processes
UID        PID  PPID  C STIME TTY          TIME CMD
nobody    3590     1  0 21:49 ?        00:00:00 /usr/sbin/openvpn --config /etc/openvpn/devops/config
root      3593  3590  0 21:49 ?        00:00:00 /usr/sbin/openvpn --config /etc/openvpn/devops/config

While tailing the logs, kill the main openvpn process (running as user nobody) manually with SIGTERM using its PID

kill -15 3590

Or alternatively in a single line:

kill -15 `ps -ef | grep "^[n]obody .* /usr/sbin/openvpn --config /etc/openvpn/devops/config$" | awk '{print $2}'`

The condensed log output should look like this (without the DOWN-ROOT: Error ...):

vpn-devops[3590]: TCP/UDP: Closing socket
vpn-devops[3590]: PLUGIN_CALL: PRE type=PLUGIN_DOWN
upstart-devops  : DOWN-ROOT: BACKGROUND: received command code: 0
vpn-devops[3590]: PLUGIN_CALL: POST /usr/lib/openvpn/openvpn-plugin-down-root.so/PLUGIN_DOWN status=0
vpn-devops[3590]: Closing TUN/TAP interface
vpn-devops[3590]: PLUGIN_CLOSE: /usr/lib/openvpn/openvpn-plugin-down-root.so
vpn-devops[3590]: PID packet_id_free
vpn-devops[3590]: SIGTERM[hard,] received, process exiting
upstart-devops  : DOWN-ROOT: close
upstart-devops  : DOWN-ROOT: BACKGROUND: received command code: 1
upstart-devops  : DOWN-ROOT: BACKGROUND: EXIT
kernel: init    : ovpn-devops main process ended, respawning
Related Topic