OpenVPN 2.7.1: server log lines intermittently miss per-client prefix (<username>/udp4:IP:PORT)

[zasim87]

Description:
After upgrading our OpenVPN community server from 2.6.x to 2.7.1 on Oracle Linux 9, the server log format in journald became inconsistent. Some log lines include the per-client prefix (e.g. /udp4::), but other lines related to the same connection are logged without that prefix (sometimes only udp4::, sometimes no client prefix at all). This breaks downstream log parsing/correlation (ELK), which previously relied on the client prefix being present.

Observed examples:

Expected (old behavior / sometimes still happens):

Apr 08 10:24:08 vmname.example.com openvpn-c-full_route2[661919]: username/udp4:<ip>:7003 PLUGIN_CALL: POST /usr/lib64/openvpn/plugin/lib/openvpn-auth-radius.so/PLUGIN_CLIENT_CO>
Apr 08 10:24:09 vmname.example.com openvpn-c-full_route2[661919]: username/udp4:<ip>:7003 PUSH: Received control message: 'PUSH_REQUEST'
Apr 08 10:24:09 vmname.example.com openvpn-c-full_route2[661919]: username/udp4:<ip>:7003 OPTIONS IMPORT: reading client specific options from: /tmp/openvpn_cc_59791663c61230542>
Apr 08 10:24:09 vmname.example.com openvpn-c-full_route2[661919]: username/udp4:<ip>:7003 MULTI: Learn: <ip> -> username/udp4:<ip>:7003
Apr 08 10:24:09 vmname.example.com openvpn-c-full_route2[661919]: username/udp4:<ip>:7003 MULTI: primary virtual IP for username/udp4:<ip>:7003: <ip>
Apr 08 10:24:09 vmname.example.com openvpn-c-full_route2[661919]: username/udp4:<ip>:7003 SENT CONTROL [username]: 'PUSH_REPLY,route ...
Apr 08 10:24:09 vmname.example.com openvpn-c-full_route2[661919]: username/udp4:<ip>:7003 SENT CONTROL [username]: 'PUSH_REPLY,route ...
Apr 08 10:24:09 vmname.example.com openvpn-c-full_route2[661919]: username/udp4:<ip>:7003 SENT CONTROL [username]: 'PUSH_REPLY,dhcp-option DNS ...

Actual (intermittent, even for same user on different connections):

Apr 08 06:45:22 vmname.example.com openvpn-c-full_route2[661919]: username/udp4:<ip>:6015 MULTI_sva: pool returned IPv4=<ip>, IPv6=(Not enabled)
Apr 08 06:45:22 vmname.example.com openvpn-c-full_route2[661919]: username/udp4:<ip>:6015 PLUGIN_CALL: POST /usr/lib64/openvpn/plugin/lib/openvpn-auth-radius.so/PLUGIN_CLIENT_CO>
Apr 08 06:45:22 vmname.example.com openvpn-c-full_route2[661919]: OPTIONS IMPORT: reading client specific options from: /tmp/openvpn_cc_2e90ada77c438c5d5b03b74e21d1e02.tmp
Apr 08 06:45:22 vmname.example.com openvpn-c-full_route2[661919]: MULTI: Learn: <ip> -> username/udp4:<ip>:6015
Apr 08 06:45:22 vmname.example.com openvpn-c-full_route2[661919]: MULTI: primary virtual IP for username/udp4:<ip>:6015: <ip>
Apr 08 06:45:22 vmname.example.com openvpn-c-full_route2[661919]: SENT CONTROL [username]: 'PUSH_REPLY,route ...
Apr 08 06:45:22 vmname.example.com openvpn-c-full_route2[661919]: SENT CONTROL [username]: 'PUSH_REPLY,route ...
Apr 08 06:45:22 vmname.example.com openvpn-c-full_route2[661919]: SENT CONTROL [username]: 'PUSH_REPLY,dhcp-option DNS ...

Environment:

• OS: Oracle Linux Server 9 (x86_64)
• OpenVPN: OpenVPN 2.7.1 x86_64-redhat-linux-gnu [...] [DCO]
• Logging:
  • syslog openvpn-<office_code>-
  • verb 3
  • logs are collected from journalctl (journald)

Note that SENT CONTROL and OPTIONS IMPORT can appear without the per-client prefix.

Expected Behavior:
The log prefix should consistently include the username/ip:port identifier if the user is authenticated, similar to version 2.6.

Question / request: Is this an intended logging change in 2.7.x, or a regression/bug where some messages are logged outside the per-client context?

[cron2]

Prefix handling had a number of bugs related to DCO (events unrelated to a particular user logged with that user's prefix), so we "changed things". It's possible we broke something, but that was unintentional - the end goal is that everything that is clearly related to a particular client instance should be logged with that prefix, and everything that is "generic" (like, DCO events, or MULTI cleanup things) are not. So, regression, and apologies for that.

It's possible that there are DCO events that reset the prefix but that are not logged due to --verb not high enough. This would certainly be my area of suspicion.

Without having looked into the commits in detail, it could be one of those

commit 531fef4
Author: Antonio Quartulli antonio@mandelbit.com
Date: Thu Sep 11 22:12:16 2025 +0200

dco: add standard mi prefix handling to multi_process_incoming_dco()

commit 9e9ba09
Author: Gianmarco De Gregori gianmarco@mandelbit.com
Date: Tue Sep 2 13:59:49 2025 +0200

dco: avoid printing mi prefix on debug messages

or maybe not...

gert