Ubuntu
openvpn package

openvpn broken after unattended security upgrade

Bug #1700079 reported by Dr. Jens Harbott
50
This bug affects 9 people
Affects Status Importance Assigned to Milestone
openvpn (Ubuntu)
Confirmed
Undecided
Marc Deslauriers

Bug Description

After openvpn has been upgraded automatically today, client VPN connections are broken, getting no response from the server anymore. After a restart of the openvpn service on the server, the issue is fixed. Seen on multiple servers by me and others in #ubuntu-server. From /var/log/apt/history.log:

Start-Date: 2017-06-23 13:57:41
Commandline: /usr/bin/unattended-upgrade
Upgrade: openvpn:amd64 (2.3.10-1ubuntu2, 2.3.10-1ubuntu2.1)
End-Date: 2017-06-23 13:57:42

Tried downgrade and manual "unattended-upgrade" again, could not reproduce. In the syslog I can see that after the initial upgrade openvpn got stopped again 4 seconds later:

Jun 23 13:57:42 vpn01 ovpn-server[24927]: OpenVPN 2.3.10 x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [EPOLL] [PKCS11] [MH] [IPv6] built on Jun 22 2017
Jun 23 13:57:42 vpn01 ovpn-server[24927]: library versions: OpenSSL 1.0.2g 1 Mar 2016, LZO 2.08
...
Jun 23 13:57:42 vpn01 ovpn-server[24928]: Initialization Sequence Completed
Jun 23 13:57:46 vpn01 ovpn-server[24928]: event_wait : Interrupted system call (code=4)
Jun 23 13:57:46 vpn01 ovpn-server[24928]: /sbin/ip route del xxxx
Jun 23 13:57:46 vpn01 ovpn-server[24928]: Closing TUN/TAP interface
Jun 23 13:57:46 vpn01 ovpn-server[24928]: /sbin/ip addr del dev tun0 local xxxx peer xxxx
Jun 23 13:57:46 vpn01 ovpn-server[24928]: SIGTERM[hard,] received, process exiting

Dr. Jens Harbott (j-harbott)
tags: added: regression-update
Revision history for this message
Steve Langasek (vorlon) wrote :

Assigning to Marc initially; this doesn't look to me like a regression introduced in the SRU, but it will need investigation (and it would be nice to have it fixed).

Changed in openvpn (Ubuntu):
assignee: nobody → Marc Deslauriers (mdeslaur)
Revision history for this message
Launchpad Janitor (janitor) wrote :

Status changed to 'Confirmed' because the bug affects multiple users.

Changed in openvpn (Ubuntu):
status: New → Confirmed
Revision history for this message
Marc Deslauriers (mdeslaur) wrote :

Do you have an upgrade log from the same time period?

Revision history for this message
Dr. Jens Harbott (j-harbott) wrote :

I'm not sure what upgrade log you are referrin to, this is the matching output from /var/log/apt/term.log:

Log started: 2017-06-23 13:57:41
(Reading database ... ^M(Reading database ... 5%^M(Reading database ... 10%^M(Reading database ... 15%^M(Reading database ... 20%^M(Reading database ... 25%^M(Reading database ... 3
0%^M(Reading database ... 35%^M(Reading database ... 40%^M(Reading database ... 45%^M(Reading database ... 50%^M(Reading database ... 55%^M(Reading database ... 60%^M(Reading databa
se ... 65%^M(Reading database ... 70%^M(Reading database ... 75%^M(Reading database ... 80%^M(Reading database ... 85%^M(Reading database ... 90%^M(Reading database ... 95%^M(Reading database ... 100%^M(Reading database ... 408678 files and directories currently installed.)
Preparing to unpack .../openvpn_2.3.10-1ubuntu2.1_amd64.deb ...
Unpacking openvpn (2.3.10-1ubuntu2.1) over (2.3.10-1ubuntu2) ...
Processing triggers for libc-bin (2.23-0ubuntu9) ...
Processing triggers for systemd (229-4ubuntu13) ...
Processing triggers for ureadahead (0.100.0-19) ...
Setting up openvpn (2.3.10-1ubuntu2.1) ...
 * Restarting virtual private network daemon(s)...
 * Stopping VPN 'server'
   ...done.
 * Restarting VPN 'server'
Processing triggers for libc-bin (2.23-0ubuntu9) ...
Log ended: 2017-06-23 13:57:42

Revision history for this message
Marc Deslauriers (mdeslaur) wrote :

Could you please add /var/log/dpkg.log too? Thanks.

Revision history for this message
Marc Deslauriers (mdeslaur) wrote :

Reporter's dpkg.log:

2017-06-23 13:57:41 startup archives unpack
2017-06-23 13:57:42 upgrade openvpn:amd64 2.3.10-1ubuntu2 2.3.10-1ubuntu2.1
2017-06-23 13:57:42 status triggers-pending libc-bin:amd64 2.23-0ubuntu9
2017-06-23 13:57:42 status half-configured openvpn:amd64 2.3.10-1ubuntu2
2017-06-23 13:57:42 status unpacked openvpn:amd64 2.3.10-1ubuntu2
2017-06-23 13:57:42 status half-installed openvpn:amd64 2.3.10-1ubuntu2
2017-06-23 13:57:42 status triggers-pending systemd:amd64 229-4ubuntu13
2017-06-23 13:57:42 status triggers-pending ureadahead:amd64 0.100.0-19
2017-06-23 13:57:42 status half-installed openvpn:amd64 2.3.10-1ubuntu2
2017-06-23 13:57:42 status unpacked openvpn:amd64 2.3.10-1ubuntu2.1
2017-06-23 13:57:42 status unpacked openvpn:amd64 2.3.10-1ubuntu2.1
2017-06-23 13:57:42 trigproc libc-bin:amd64 2.23-0ubuntu9 <none>
2017-06-23 13:57:42 status half-configured libc-bin:amd64 2.23-0ubuntu9
2017-06-23 13:57:42 status installed libc-bin:amd64 2.23-0ubuntu9
2017-06-23 13:57:42 trigproc systemd:amd64 229-4ubuntu13 <none>
2017-06-23 13:57:42 status half-configured systemd:amd64 229-4ubuntu13
2017-06-23 13:57:42 status installed systemd:amd64 229-4ubuntu13
2017-06-23 13:57:42 trigproc ureadahead:amd64 0.100.0-19 <none>
2017-06-23 13:57:42 status half-configured ureadahead:amd64 0.100.0-19
2017-06-23 13:57:42 status installed ureadahead:amd64 0.100.0-19
2017-06-23 13:57:42 startup packages configure
2017-06-23 13:57:42 configure openvpn:amd64 2.3.10-1ubuntu2.1 <none>
2017-06-23 13:57:42 status triggers-pending libc-bin:amd64 2.23-0ubuntu9
2017-06-23 13:57:42 status unpacked openvpn:amd64 2.3.10-1ubuntu2.1
2017-06-23 13:57:42 status unpacked openvpn:amd64 2.3.10-1ubuntu2.1
2017-06-23 13:57:42 status unpacked openvpn:amd64 2.3.10-1ubuntu2.1
2017-06-23 13:57:42 status unpacked openvpn:amd64 2.3.10-1ubuntu2.1
2017-06-23 13:57:42 status unpacked openvpn:amd64 2.3.10-1ubuntu2.1
2017-06-23 13:57:42 status unpacked openvpn:amd64 2.3.10-1ubuntu2.1
2017-06-23 13:57:42 status unpacked openvpn:amd64 2.3.10-1ubuntu2.1
2017-06-23 13:57:42 status half-configured openvpn:amd64 2.3.10-1ubuntu2.1
2017-06-23 13:57:42 status installed openvpn:amd64 2.3.10-1ubuntu2.1
2017-06-23 13:57:42 trigproc libc-bin:amd64 2.23-0ubuntu9 <none>
2017-06-23 13:57:42 status half-configured libc-bin:amd64 2.23-0ubuntu9
2017-06-23 13:57:42 status installed libc-bin:amd64 2.23-0ubuntu9
2017-06-23 13:57:42 startup packages configure

Revision history for this message
Chris Schnatz (cschnatz) wrote :

We are having the accept same issue on several of our clients starting an 23th June at around 5 am and the numbers was ground till 6pm

/var/log/openvpn.log
Fri Jun 23 11:15:40 2017 OpenVPN 2.3.10 x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [EPOLL] [PKCS11] [MH] [IPv6] built on Jun 22 2017
Fri Jun 23 11:15:40 2017 library versions: OpenSSL 1.0.2g 1 Mar 2016, LZO 2.08
...
Fri Jun 23 11:15:44 2017 Initialization Sequence Completed
Fri Jun 23 11:16:13 2017 event_wait : Interrupted system call (code=4)
Fri Jun 23 11:16:13 2017 /sbin/ip route del XXXX/32
Fri Jun 23 11:16:13 2017 Closing TUN/TAP interface
Fri Jun 23 11:16:13 2017 /sbin/ip addr del dev tun99 XXXXX/16
Fri Jun 23 11:16:13 2017 SIGTERM[hard,] received, process exiting

/var/log/syslog
Jun 23 11:15:40 systemd[1]: Reloading.
Jun 23 11:15:40 systemd[1]: snapd.refresh.timer: Adding 4h 4min 14.083585s random time.
Jun 23 11:15:40 systemd[1]: Started ACPI event daemon.
Jun 23 11:15:41 systemd[1]: Reloading.
Jun 23 11:15:42 systemd[1]: snapd.refresh.timer: Adding 10min 16.345182s random time.
Jun 23 11:15:42 systemd[1]: Started ACPI event daemon.
Jun 23 11:16:13 apt.systemd.daily[30326]: Traceback (most recent call last):
Jun 23 11:16:13 apt.systemd.daily[30326]: File "/usr/bin/unattended-upgrade", line 1473, in <module>
Jun 23 11:16:13 apt.systemd.daily[30326]: main(options)
Jun 23 11:16:13 apt.systemd.daily[30326]: File "/usr/bin/unattended-upgrade", line 1411, in main
Jun 23 11:16:13 apt.systemd.daily[30326]: log_content = get_dpkg_log_content(logfile_dpkg, install_start_time)
Jun 23 11:16:13 apt.systemd.daily[30326]: File "/usr/bin/unattended-upgrade", line 1079, in get_dpkg_log_content
Jun 23 11:16:13 apt.systemd.daily[30326]: for line in fp.readlines():
Jun 23 11:16:13 apt.systemd.daily[30326]: File "/usr/lib/python3.5/codecs.py", line 321, in decode
Jun 23 11:16:13 apt.systemd.daily[30326]: (result, consumed) = self._buffer_decode(data, self.errors, final)
Jun 23 11:16:13 apt.systemd.daily[30326]: UnicodeDecodeError: 'utf-8' codec can't decode byte 0xfc in position 762: invalid start byte
Jun 23 11:16:13 systemd[1]: Started Daily apt activities.
Jun 23 11:16:13 systemd[1]: apt-daily.timer: Adding 9h 9min 19.366153s random time.
Jun 23 11:16:13 systemd[1]: apt-daily.timer: Adding 10h 34min 25.479340s random time.

/var/log/apt/history.log
Start-Date: 2017-06-23 11:15:34
Commandline: /usr/bin/unattended-upgrade
Upgrade: openvpn:amd64 (2.3.10-1ubuntu2, 2.3.10-1ubuntu2.1)
End-Date: 2017-06-23 11:15:42

A simple "service openvpn restart" or of course server reboot fixed the issue for now but this is only a workaround.

Revision history for this message
Simon Déziel (sdeziel) wrote :
Download full text (5.6 KiB)

Here's the info collected an machine that experienced the problem on June 23rd:

# grep -F 2017-06-23 /var/log/dpkg.log
2017-06-23 07:47:29 startup archives unpack
2017-06-23 07:47:29 upgrade openvpn:amd64 2.3.10-1ubuntu2 2.3.10-1ubuntu2.1
2017-06-23 07:47:29 status triggers-pending libc-bin:amd64 2.23-0ubuntu9
2017-06-23 07:47:29 status half-configured openvpn:amd64 2.3.10-1ubuntu2
2017-06-23 07:47:29 status unpacked openvpn:amd64 2.3.10-1ubuntu2
2017-06-23 07:47:29 status half-installed openvpn:amd64 2.3.10-1ubuntu2
2017-06-23 07:47:29 status triggers-pending systemd:amd64 229-4ubuntu17
2017-06-23 07:47:29 status triggers-pending ureadahead:amd64 0.100.0-19
2017-06-23 07:47:29 status half-installed openvpn:amd64 2.3.10-1ubuntu2
2017-06-23 07:47:29 status unpacked openvpn:amd64 2.3.10-1ubuntu2.1
2017-06-23 07:47:29 status unpacked openvpn:amd64 2.3.10-1ubuntu2.1
2017-06-23 07:47:29 trigproc libc-bin:amd64 2.23-0ubuntu9 <none>
2017-06-23 07:47:29 status half-configured libc-bin:amd64 2.23-0ubuntu9
2017-06-23 07:47:29 status installed libc-bin:amd64 2.23-0ubuntu9
2017-06-23 07:47:29 trigproc systemd:amd64 229-4ubuntu17 <none>
2017-06-23 07:47:29 status half-configured systemd:amd64 229-4ubuntu17
2017-06-23 07:47:30 status installed systemd:amd64 229-4ubuntu17
2017-06-23 07:47:30 trigproc ureadahead:amd64 0.100.0-19 <none>
2017-06-23 07:47:30 status half-configured ureadahead:amd64 0.100.0-19
2017-06-23 07:47:30 status installed ureadahead:amd64 0.100.0-19
2017-06-23 07:47:30 startup packages configure
2017-06-23 07:47:30 configure openvpn:amd64 2.3.10-1ubuntu2.1 <none>
2017-06-23 07:47:30 status triggers-pending libc-bin:amd64 2.23-0ubuntu9
2017-06-23 07:47:30 status unpacked openvpn:amd64 2.3.10-1ubuntu2.1
2017-06-23 07:47:30 status unpacked openvpn:amd64 2.3.10-1ubuntu2.1
2017-06-23 07:47:30 status unpacked openvpn:amd64 2.3.10-1ubuntu2.1
2017-06-23 07:47:30 status unpacked openvpn:amd64 2.3.10-1ubuntu2.1
2017-06-23 07:47:30 status unpacked openvpn:amd64 2.3.10-1ubuntu2.1
2017-06-23 07:47:30 status unpacked openvpn:amd64 2.3.10-1ubuntu2.1
2017-06-23 07:47:30 status unpacked openvpn:amd64 2.3.10-1ubuntu2.1
2017-06-23 07:47:30 status half-configured openvpn:amd64 2.3.10-1ubuntu2.1
2017-06-23 07:47:30 status installed openvpn:amd64 2.3.10-1ubuntu2.1
2017-06-23 07:47:30 trigproc libc-bin:amd64 2.23-0ubuntu9 <none>
2017-06-23 07:47:30 status half-configured libc-bin:amd64 2.23-0ubuntu9
2017-06-23 07:47:30 status installed libc-bin:amd64 2.23-0ubuntu9
2017-06-23 07:47:30 startup packages configure

/var/log/syslog:

Jun 23 07:47:30 baz ovpn-foo[31061]: event_wait : Interrupted system call (code=4)
Jun 23 07:47:30 baz ovpn-foo[31061]: /sbin/ip addr del dev tun0 192.168.176.254/25
Jun 23 07:47:30 baz ovpn-foo[31061]: SIGTERM[hard,] received, process exiting
Jun 23 07:47:30 baz ovpn-foo[6943]: OpenVPN 2.3.10 x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [EPOLL] [PKCS11] [MH] [IPv6] built on Jun 22 2017
Jun 23 07:47:30 baz ovpn-foo[6943]: library versions: OpenSSL 1.0.2g 1 Mar 2016, LZO 2.08
Jun 23 07:47:30 baz ovpn-foo[6944]: Control Channel Authentication: using '/etc/openvpn/foo/tls-auth.key' as a OpenVPN static key file
Jun 23 07:47:30 baz ovpn-foo[...

Read more...

Revision history for this message
Marius Gedminas (mgedmin) wrote :
Download full text (3.5 KiB)

Bug still there in 18.04.5 LTS. Had an unattended security upgrade of openvpn on May 5, which shut down the old ovpn-server:

    | May 05 06:14:19 fridge ovpn-server[3384]: event_wait : Interrupted system call (code=4)
    | May 05 06:14:19 fridge ovpn-server[3384]: /sbin/ip route del 10.8.0.0/24
    | May 05 06:14:19 fridge ovpn-server[3384]: openvpn_execve: unable to fork: Resource temporarily unavailable (errno=11)
    | May 05 06:14:19 fridge ovpn-server[3384]: Exiting due to fatal error

and started a new one

    | May 05 06:14:19 fridge ovpn-server[13115]: OpenVPN 2.4.4 x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [PKCS11] [MH/PKTINFO] [AEAD] built on Apr 27 2021
    ...
    | May 05 06:14:19 fridge ovpn-server[13116]: /sbin/ip link set dev tun1 up mtu 1500
    | May 05 06:14:19 fridge ovpn-server[13116]: /sbin/ip addr add dev tun1 local 10.8.0.1 peer 10.8.0.2
    | May 05 06:14:19 fridge ovpn-server[13116]: /sbin/ip route add 10.8.0.0/24 via 10.8.0.2
    | May 05 06:14:19 fridge ovpn-server[13116]: ERROR: Linux route add command failed: external program exited with error status: 2

and then clients could connect to the VPN server but did not get any network connectivity through it.

I'm wondering if there's a race between the old ovpn-server running /sbin/ip route del vs the new opvpn-server running /sbin/ip route add?

Also curiously systemctl status openvpn@server a few days later showed

    | ● <email address hidden> - OpenVPN connection to server
    | Loaded: loaded (/lib/systemd/system/openvpn@.service; indirect; vendor preset: enabled)
    | Active: active (running) since Fri 2021-04-16 07:36:38 EEST; 3 weeks 0 days ago
    | Docs: man:openvpn(8)
    | https://community.openvpn.net/openvpn/wiki/Openvpn24ManPage
    | https://community.openvpn.net/openvpn/wiki/HOWTO
    | Main PID: 13116 (openvpn)
    | Status: "Initialization Sequence Completed"
    | Tasks: 0 (limit: 4915)
    | CGroup: /<email address hidden>
    | ‣ 13116 /usr/sbin/openvpn --writepid /run/openvpn/server.pid --daemon ovpn-server --cd /etc/openvpn --config /etc/openvpn/server.conf
    |
    | May 04 19:36:22 fridge ovpn-server[3384]: laurynas2/78.58.248.51:52905 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
    | May 04 19:36:22 fridge ovpn-server[3384]: laurynas2/78.58.248.51:52905 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
    | May 04 19:36:22 fridge ovpn-server[3384]: laurynas2/78.58.248.51:52905 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, 2048 bit RSA
    | May 04 20:22:09 fridge ovpn-server[3384]: laurynas2/78.58.248.51:52905 [laurynas2] Inactivity timeout (--ping-restart), restarting
    | May 04 20:22:09 fridge ovpn-server[3384]: laurynas2/78.58.248.51:52905 SIGUSR1[soft,ping-restart] received, client-instance restarting
    | May 05 00:43:45 fridge ovpn-server[3384]: TLS Error: cannot locate HMAC in incoming packet from [AF_INET]185.200.118.51:33488
    | May 05 06:14:19 fridge ovpn-server[3384]: event_wait : Interrupted system call (code=4)
    | May 05 06:14:19 fridge ov...

Read more...

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

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