OpenVPN server does not start properly on boot

Bug #1689833 reported by AW
16
This bug affects 2 people
Affects Status Importance Assigned to Milestone
openvpn (Ubuntu)
Triaged
Medium
Unassigned
systemd (Ubuntu)
Invalid
Undecided
Unassigned

Bug Description

OpenVPN intermittently fails to bind to local address during boot on Ubuntu Server 16.04.2 LTS. Sometimes it succeeds, sometimes it does not.

/var/log/openvpn.log
Wed May 10 15:42:02 2017 OpenVPN 2.3.10 x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [EPOLL] [PKCS11] [MH] [IPv6] built on Feb 2 2016
Wed May 10 15:42:02 2017 library versions: OpenSSL 1.0.2g 1 Mar 2016, LZO 2.08
Wed May 10 15:42:02 2017 Diffie-Hellman initialized with 2048 bit key
Wed May 10 15:42:02 2017 Control Channel Authentication: using './easy-rsa/keys/ta.key' as a OpenVPN static key file
Wed May 10 15:42:02 2017 Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Wed May 10 15:42:02 2017 Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Wed May 10 15:42:02 2017 Socket Buffers: R=[212992->212992] S=[212992->212992]
Wed May 10 15:42:02 2017 TCP/UDP: Socket bind failed on local address [AF_INET]192.168.4.254:1194: Cannot assign requested address
Wed May 10 15:42:02 2017 Exiting due to fatal error

In case it does not start, running 'sudo service openvpn start' fixes that problem.

/var/log/openvpn.log
Wed May 10 15:42:43 2017 OpenVPN 2.3.10 x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [EPOLL] [PKCS11] [MH] [IPv6] built on Feb 2 2016
Wed May 10 15:42:43 2017 library versions: OpenSSL 1.0.2g 1 Mar 2016, LZO 2.08
Wed May 10 15:42:43 2017 Diffie-Hellman initialized with 2048 bit key
Wed May 10 15:42:43 2017 Control Channel Authentication: using './easy-rsa/keys/ta.key' as a OpenVPN static key file
Wed May 10 15:42:43 2017 Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Wed May 10 15:42:43 2017 Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Wed May 10 15:42:43 2017 Socket Buffers: R=[212992->212992] S=[212992->212992]
Wed May 10 15:42:43 2017 ROUTE_GATEWAY 192.168.4.1/255.255.255.0 IFACE=ens4 HWADDR=52:54:00:f0:26:0c
Wed May 10 15:42:43 2017 TUN/TAP device tun0 opened
Wed May 10 15:42:43 2017 TUN/TAP TX queue length set to 100
Wed May 10 15:42:43 2017 do_ifconfig, tt->ipv6=0, tt->did_ifconfig_ipv6_setup=0
Wed May 10 15:42:43 2017 /sbin/ip link set dev tun0 up mtu 1500
Wed May 10 15:42:43 2017 /sbin/ip addr add dev tun0 local 172.16.1.1 peer 172.16.1.2
Wed May 10 15:42:43 2017 /sbin/ip route add 172.16.1.0/24 via 172.16.1.2
Wed May 10 15:42:43 2017 GID set to nogroup
Wed May 10 15:42:43 2017 UID set to nobody
Wed May 10 15:42:43 2017 UDPv4 link local (bound): [AF_INET]192.168.4.254:1194
Wed May 10 15:42:43 2017 UDPv4 link remote: [undef]
Wed May 10 15:42:43 2017 MULTI: multi_init called, r=256 v=256
Wed May 10 15:42:43 2017 IFCONFIG POOL: base=172.16.1.4 size=62, ipv6=0
Wed May 10 15:42:43 2017 IFCONFIG POOL LIST
Wed May 10 15:42:43 2017 Initialization Sequence Completed

My guess is that systemd starts OpenVPN too early before the network is brought up sufficiently. Running 'sudo systemctl edit --full openvpn' and adding 'Wants=network-online.target' does not change that behaviour.

user@server:~$ sudo systemd-analyze critical-chain
graphical.target @2.160s
└─multi-user.target @2.159s
  └─ntp.service @2.054s +104ms
    └─remote-fs.target @2.052s
      └─remote-fs-pre.target @2.052s
        └─open-iscsi.service @1.993s +57ms
          └─iscsid.service @1.942s +47ms
            └─network-online.target @1.941s
              └─network.target @1.929s
                └─networking.service @1.793s +134ms
                  └─apparmor.service @1.140s +395ms
                    └─local-fs.target @1.140s
                      └─local-fs-pre.target @1.139s
                        └─lvm2-monitor.service @602ms +536ms
                          └─lvm2-lvmetad.service @773ms
                            └─systemd-journald.socket @574ms
                              └─-.slice @500ms

The boot time is quite short. Clean install with the additional packages ntp and openssh-server. This happens both on bare metal and as a Virtual Machine (KVM) as well.

/etc/openvpn/server.conf
local 192.168.4.254
port 1194
proto udp
dev tun
ca ./easy-rsa/keys/ca.crt
cert ./easy-rsa/keys/crt.crt
key ./easy-rsa/keys/key.key
dh ./easy-rsa/keys/dh2048.pem
tls-auth ./easy-rsa/keys/ta.key 0
server 172.16.1.0 255.255.255.0
ifconfig-pool-persist ipp.txt
push "route 192.168.0.0 255.255.255.0"
push "route 192.168.4.0 255.255.255.0"
keepalive 10 120
comp-lzo
max-clients 5
user nobody
group nogroup
persist-key
persist-tun
status openvpn-status.log
log-append /var/log/openvpn.log
verb 3

/etc/network/interfaces
# The loopback network interface
auto lo
iface lo inet loopback

# The primary network interface
auto ens3
iface ens3 inet static
  address 192.168.0.1
  netmask 255.255.255.0
  network 192.168.0.0
  broadcast 192.168.0.255

# The secondary network interface
auto ens4
iface ens4 inet static
  address 192.168.4.254
  netmask 255.255.255.0
  network 192.168.4.0
  broadcast 192.168.4.255
  gateway 192.168.4.1

user@server:~$ sudo apt-cache policy openvpn
openvpn:
  Installed: 2.3.10-1ubuntu2
  Candidate: 2.3.10-1ubuntu2
  Version table:
 *** 2.3.10-1ubuntu2 500
        500 http://de.archive.ubuntu.com/ubuntu xenial/main amd64 Packages
        100 /var/lib/dpkg/status

user@server:~$ sudo apt-cache policy systemd
systemd:
  Installed: 229-4ubuntu17
  Candidate: 229-4ubuntu17
  Version table:
 *** 229-4ubuntu17 500
        500 http://de.archive.ubuntu.com/ubuntu xenial-updates/main amd64 Packages
        100 /var/lib/dpkg/status
     229-4ubuntu10 500
        500 http://security.ubuntu.com/ubuntu xenial-security/main amd64 Packages
     229-4ubuntu4 500
        500 http://de.archive.ubuntu.com/ubuntu xenial/main amd64 Packages

AW (jnx)
description: updated
Revision history for this message
Nish Aravamudan (nacc) wrote :

Thank you for reporting this bug. I will add it to the server team backlog, as it does appear to be a real issue.

Changed in openvpn (Ubuntu):
status: New → Triaged
Revision history for this message
Andreas Hasenack (ahasenack) wrote :

I finally got to confirm this. I had to install ntp to see the same problem in my vm. Before that, openvpn was always running after a reboot.

The moment I installed ntp and rebooted, I got the issue:
Mon Nov 20 19:17:41 2017 TCP/UDP: Socket bind failed on local address [AF_INET]10.0.6.10:1194: Cannot assign requested address
Mon Nov 20 19:17:41 2017 Exiting due to fatal error

root@04-57:~# systemctl status <email address hidden>
● <email address hidden> - OpenVPN connection to server
   Loaded: loaded (/lib/systemd/system/openvpn@.service; disabled; vendor preset: enabled)
   Active: failed (Result: exit-code) since Mon 2017-11-20 19:17:41 UTC; 1min 30s ago
     Docs: man:openvpn(8)
           https://community.openvpn.net/openvpn/wiki/Openvpn23ManPage
           https://community.openvpn.net/openvpn/wiki/HOWTO
  Process: 577 ExecStart=/usr/sbin/openvpn --daemon ovpn-%i --status /run/openvpn/%i.status 10 --cd /etc/openvpn --script-security 2 --config /etc/openvpn/%i.conf --writepid /run/openvpn/%i.pid (code=exited, sta
 Main PID: 612 (code=exited, status=1/FAILURE)

Nov 20 19:17:41 04-57 systemd[1]: Starting OpenVPN connection to server...
Nov 20 19:17:41 04-57 systemd[1]: Started OpenVPN connection to server.
Nov 20 19:17:41 04-57 systemd[1]: <email address hidden>: Main process exited, code=exited, status=1/FAILURE
Nov 20 19:17:41 04-57 systemd[1]: <email address hidden>: Unit entered failed state.
Nov 20 19:17:41 04-57 systemd[1]: <email address hidden>: Failed with result 'exit-code'.
lines 1-14/14 (END)

Revision history for this message
Simon Déziel (sdeziel) wrote :

A possible workaround would be to add "Restart=on-failure" in the "[Service]" section of the systemd unit.

Revision history for this message
Andreas Hasenack (ahasenack) wrote :
Revision history for this message
Andreas Hasenack (ahasenack) wrote :

> My guess is that systemd starts OpenVPN too early before the network is brought
> up sufficiently. Running 'sudo systemctl edit --full openvpn' and adding
> 'Wants=network-online.target' does not change that behaviour.

I tried this to test:
[Unit]
(...)
After=syslog.target network-online.target
Wants=network-online.target

It then worked. Can you give that a shot?

Upstream adopted a mixed approach and split the services into a server and client part, and adopted different after/wants values for each (see https://github.com/OpenVPN/openvpn/commit/28bd79ac980488dbfce2e8136287e38c6f35a043)

I don't think we can take an approach as the above for a stable release update, though.

Revision history for this message
Andreas Hasenack (ahasenack) wrote :

In fact, our current openvpn package in bionic is using just these After and Wants values:
After=network-online.target
Wants=network-online.target

Changed in systemd (Ubuntu):
status: New → Invalid
Revision history for this message
Andreas Hasenack (ahasenack) wrote :
Revision history for this message
AW (jnx) wrote :

I tried your suggested settings on fresh installs including all updates but this still regularly fails to bind the address. I have those servers running as virtual machines with Qemu/KVM.
If I do the same thing on bare metal, the binding will succeed in like 95% of boots.

/var/log/openvpn.log:
Tue Apr 10 11:40:44 2018 OpenVPN 2.3.10 x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [EPOLL] [PKCS11] [MH] [IPv6] built on Jun 22 2017
Tue Apr 10 11:40:44 2018 library versions: OpenSSL 1.0.2g 1 Mar 2016, LZO 2.08
Tue Apr 10 11:40:44 2018 Diffie-Hellman initialized with 2048 bit key
Tue Apr 10 11:40:44 2018 Control Channel Authentication: using './easy-rsa/keys/ta.key' as a OpenVPN static key file
Tue Apr 10 11:40:44 2018 Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Tue Apr 10 11:40:44 2018 Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Tue Apr 10 11:40:44 2018 Socket Buffers: R=[212992->212992] S=[212992->212992]
Tue Apr 10 11:40:44 2018 TCP/UDP: Socket bind failed on local address [AF_INET]192.168.11.254:1194: Cannot assign requested address
Tue Apr 10 11:40:44 2018 Exiting due to fatal error

Revision history for this message
Andreas Hasenack (ahasenack) wrote :

@jnx, the 192.168.11.254 address you are trying to bind to, is that the normal nic of that machine? Or something else, like a wifi interface, or something that would only come up after the user logs in, assuming this is a desktop?

Revision history for this message
AW (jnx) wrote :

It's the normal builtin NIC on a headless server. Tried with different hardware as well:

 *-network
       description: Ethernet interface
       product: 82574L Gigabit Network Connection
       vendor: Intel Corporation

 *-network
       description: Ethernet interface
       product: NetXtreme BCM5720 Gigabit Ethernet PCIe
       vendor: Broadcom Corporation

 *-network
       description: Ethernet interface
       product: Virtio network device
       vendor: Red Hat, Inc

Revision history for this message
Nanzikambe (nanzikambe) wrote :

Also affected by this bug, fresh Ubuntu Ubuntu 16.04.6 LTS minimal server install + openvpn

/var/log/openvpn-XXXX.log:

Sun Mar 17 14:45:59 2019 us=746742 TCP/UDP: Socket bind failed on local address [AF_INET]XXX.XXX.XXX.131:1094: Cannot assign requested address
Sun Mar 17 14:45:59 2019 us=746750 Exiting due to fatal error

Where XXX.XXX.XXX.131 is an IP aliased to eth0 (aliased eth0:1) in /etc/network/interfaces:

auto eth0:1
allow-hotplug eth0:1
iface eth0:1 inet static
  address XXX.XXX.XXX.131
  netmask 255.255.255.224

None of the workarounds listed in this bug or here https://www.freedesktop.org/wiki/Software/systemd/NetworkTarget/ work - occurs 100% every boot.

I can repeat this reliably on a fresh minimal install + openvpn + alias on primary interface

Revision history for this message
Nanzikambe (nanzikambe) wrote :

Seems upstream kindly solved this bug, the solution is to:

In /etc/default/openvpn

AUTOSTART="none"

In /etc/network/interfaces

iface ethX inet static
  address XXX.XXX.XXX.XX
  netmask 255.255.255.0
  openvpn my_vpn_name

Where ethX is your interface (ex, eth0 for a regular interface, eth0:1 for an alias of an interface), my_vpn_name is the base filename without the .conf suffix of your /etc/openvpn/my_vpn_name.conf file.

To explain, the above causes the script /etc/network/if-up.d/openvpn to get executed, this in turn executes systemctl --no-block start openvpn@my_vpn_name which starts the openvpn after the interface or alias is brought up.

Revision history for this message
Sebastien Bacher (seb128) wrote :

Do you have a pointer to the upstream discussion?

Revision history for this message
Christian Ehrhardt  (paelzer) wrote :

Note: the if the solution needs an ifupdown hook like shown in comment #12 in >=Bionic I'd ask you to take a look for networkd-dispatch (the final solution for almost all of these bugs is that the upstream project starts to listen o netlink to pick up late ready IP addresses)

FYI: There seem to be a whole class of issues like this so Rbasak added it also to a card that tracks related work.

Bryce Harrington (bryce)
Changed in openvpn (Ubuntu):
importance: Undecided → Medium
Robie Basak (racb)
tags: added: network-online-ordering
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.