pfSense

Hello,

Do you see this same behavior in 23.05?

Can not reproduce on 23.05.1
23.05.1-RELEASE (amd64)
built on Wed Jun 28 03:57:27 UTC 2023
FreeBSD 14.0-CURRENT

I just checked my 23.05 box and I see 5 of these runaways. I guess we'll need to update to 23.05.1 to test that...

I'm not sure that the Operation timed out log is related because the existence of the log means that the authentication process completes and the script returns, hence fcgicli should exit. The truss output seems to indicate that fcgicli is waiting on openvpn.auth-user.php to finish which implies the issue is with the .php file. I did manage to reproduce this issue once (unfortunately I did not have any debugging output applied); as expected no output was returned from openvpn.attributes.php. I also noticed the following in the OpenVPN logs rather than in the system logs (reversed):

Oct 11 14:08:17     openvpn     81755     /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - -> 172.25.1.1 - Restarting packages.
Oct 11 14:08:17     openvpn     81755     /rc.newwanip: rc.newwanip called with empty interface.
Oct 11 14:08:17     openvpn     81755     /rc.newwanip: rc.newwanip: on (IP address: 172.25.1.1) (interface: []) (real interface: ovpns1).
Oct 11 14:08:17     openvpn     81755     /rc.newwanip: rc.newwanip: Info: starting on ovpns1. 

1. Disabling Duplicate Connection in the OpenVPN server config, or
2. Renaming /etc/inc/openvpn.attributes.php to /etc/inc/openvpn.attributes.php.bak (used for Cisco-AVPair rules)
3. Apply the following patch to omit openlog() ShowHide

   diff --git a/src/etc/inc/openvpn.auth-user.php b/src/etc/inc/openvpn.auth-user.php
   index 436c4e1bf6..b587d96ca3 100644
   --- a/src/etc/inc/openvpn.auth-user.php
   +++ b/src/etc/inc/openvpn.auth-user.php
   @@ -34,7 +34,7 @@ require_once("auth.inc");
    require_once("interfaces.inc");
   
    /* setup syslog logging */
   -openlog("openvpn", LOG_ODELAY, LOG_AUTH);
   +//openlog("openvpn", LOG_ODELAY, LOG_AUTH);
   
    global $common_name, $username, $dev, $untrusted_port;
   
   @@ -61,10 +61,10 @@ if (!$username) {
        syslog(LOG_ERR, "invalid user authentication environment");
        if (isset($_GET['username'])) {
            echo "FAILED";
   -        closelog();
   +        //closelog();
            return;
        } else {
   -        closelog();
   +        //closelog();
            return (-1);
        }
    }
   @@ -78,10 +78,10 @@ if (($strictusercn === true) && (mb_strtolower($common_name) !== mb_strtolower($
        syslog(LOG_WARNING, "Username does not match certificate common name (\"{$username}\" != \"{$common_name}\"), access denied.");
        if (isset($_GET['username'])) {
            echo "FAILED";
   -        closelog();
   +        //closelog();
            return;
        } else {
   -        closelog();
   +        //closelog();
            return (1);
        }
    }
   @@ -90,10 +90,10 @@ if (!is_array($authmodes)) {
        syslog(LOG_WARNING, "No authentication server has been selected to authenticate against. Denying authentication for user {$username}");
        if (isset($_GET['username'])) {
            echo "FAILED";
   -        closelog();
   +        //closelog();
            return;
        } else {
   -        closelog();
   +        //closelog();
            return (1);
        }
    }
   @@ -120,10 +120,10 @@ if ($authenticated == false) {
        syslog(LOG_WARNING, "user '{$username}' could not authenticate.");
        if (isset($_GET['username'])) {
            echo "FAILED";
   -        closelog();
   +        //closelog();
            return;
        } else {
   -        closelog();
   +        //closelog();
            return (-1);
        }
    }
   @@ -159,7 +159,7 @@ if (!empty($content)) {
    }
   
    syslog(LOG_NOTICE, "user '{$username}' authenticated");
   -closelog();
   +//closelog();
   
    if (isset($_GET['username'])) {
        echo "OK";
   
   

Duplicate Connection was already disabled (multiple connections from the same user are not allowed - check box not checked.

I moved /etc/inc/openvpn.attributes.php out of the way.

Just had a re-occurrence, so I will now apply the patch.

The patch fixed the issue on a firewall with the same symptoms. There were no side effects after applying the patch.

23.05.1-RELEASE (amd64)
built on Wed Jun 28 03:57:27 UTC 2023
FreeBSD 14.0-CURRENT

Preferably we can get more testing/feedback on this. Given the inconsistent nature of the issue, it may simply be the issue has not appeared yet.

Just had another reproducer. However, this time it did not appear to the associated with the auth timeout message initially reported, but a different variant:

Oct 27 10:04:22 PLUGIN_CALL: POST /usr/local/lib/openvpn/plugins/openvpn-plugin-auth-script.so/PLUGIN_AUTH_USER_PASS_VERIFY status=2
Oct 27 10:04:22 TLS: Username/Password authentication deferred for username 'USER'
...
Oct 27 10:05:18 PUSH: Received control message: 'PUSH_REQUEST'
Oct 27 10:05:34 Delayed exit in 5 seconds
Oct 27 10:05:34 SENT CONTROL [UNDEF]: 'AUTH_FAILED' (status=1)
Oct 27 10:05:34 SENT CONTROL [akialoa.cora.nwra.com]: 'AUTH_FAILED' (status=1)

Orion Poplawski wrote in #note-8:

Just had another reproducer. However, this time it did not appear to the associated with the auth timeout message initially reported, but a different variant:

[...]
Although now that I check I see that the "Duplicate Connection" box is checked on this particular VPN configuration, so I need to disable that now. Sigh

Is that with the patch applied?

Marcos M wrote in #note-9:

Orion Poplawski wrote in #note-8:

Just had another reproducer. However, this time it did not appear to the associated with the auth timeout message initially reported, but a different variant:

[...]
Although now that I check I see that the "Duplicate Connection" box is checked on this particular VPN configuration, so I need to disable that now. Sigh

Is that with the patch applied?

Yes - patch applied and /etc/inc/openvpn.attributes.php moved out of the way.

In that case, it seems more likely that the issue is with fcgicli. Given this issue seems to have appeared in 23.01, it may be due to reintroducing the use of fcgicli here:
https://github.com/pfsense/pfsense/commit/758ee42ae096fee8436efc89f2c9bcc4ae7ea23d

Please try the following patch to use php-cgi instead (updated): ShowHide

diff --git a/src/usr/local/sbin/ovpn_auth_verify b/src/usr/local/sbin/ovpn_auth_verify
index 2bc39d3c0f..ea43f72a5b 100755
--- a/src/usr/local/sbin/ovpn_auth_verify
+++ b/src/usr/local/sbin/ovpn_auth_verify
@@ -25,7 +25,7 @@ if [ "$1" = "tls" ]; then
     do
         eval serial="\$tls_serial_${check_depth}" 
         if [ -n "$serial" ]; then
-            RESULT=$(/usr/local/sbin/fcgicli -f /etc/inc/openvpn.tls-verify.php -d "servercn=$2&depth=$3&certdepth=$4&certsubject=$5&serial=$serial&config=$config")
+            RESULT=$(/usr/local/bin/php-cgi -q -f /etc/inc/openvpn.tls-verify.php "servercn=$2&depth=$3&certdepth=$4&certsubject=$5&serial=$serial&config=$config")
             if [ "${RESULT}" = "FAILED" ]; then
                 exit 1
             fi
@@ -36,7 +36,7 @@ else
     # Base64 and urlEncode usernames and passwords
     password=$(echo -n "${password}" | openssl enc -base64 | sed -e 's_=_%3D_g;s_+_%2B_g;s_/_%2F_g')
     username=$(echo -n "${username}" | openssl enc -base64 | sed -e 's_=_%3D_g;s_+_%2B_g;s_/_%2F_g')
-    RESULT=$(/usr/local/sbin/fcgicli -f /etc/inc/openvpn.auth-user.php -d "username=$username&password=$password&cn=$common_name&strictcn=$3&authcfg=$2&modeid=$4&nas_port=$5")
+    RESULT=$(/usr/local/bin/php-cgi -q -f /etc/inc/openvpn.auth-user.php "username=$username&password=$password&cn=$common_name&strictcn=$3&authcfg=$2&modeid=$4&nas_port=$5")
 fi

 if [ "${RESULT}" = "OK" ]; then
diff --git a/src/usr/local/sbin/ovpn_auth_verify_async b/src/usr/local/sbin/ovpn_auth_verify_async
index fec42c36ba..78190296f2 100755
--- a/src/usr/local/sbin/ovpn_auth_verify_async
+++ b/src/usr/local/sbin/ovpn_auth_verify_async
@@ -35,7 +35,7 @@
 # nas_port          - $5

 # ---------- Command Definitions
-fcgicli="/usr/local/sbin/fcgicli" 
+phpcgi="/usr/local/bin/php-cgi" 
 openssl="/usr/bin/openssl" 
 sed="/usr/bin/sed" 
 auth_user_php="/etc/inc/openvpn.auth-user.php" 
@@ -66,7 +66,7 @@ auth_server_1="cn=${common_name}&strictcn=${strictcn}&authcfg=${authcfg}&dev=${d
 auth_server_2="modeid=${modeid}&nas_port=${nas_port}" 
 auth_args="${auth_credentials}&${auth_server_1}&${auth_server_2}" 

-result=$("${fcgicli}" -f "${auth_user_php}" -d "${auth_args}")
+result=$("${phpcgi}" -f "${auth_user_php}" "${auth_args}")

 # ---------- Write the Result

The patched version of ovpn_auth_verify seems to work okay, but if I patch ovpn_auth_verify_async I get auth failures:

SENT CONTROL [UNDEF]: 'AUTH_FAILED' (status=1)

not much else in the log to know why.

FWIW - still present in 2.7.2 and 23.09.1.

Orion Poplawski wrote in #note-13:

FWIW - still present in 2.7.2 and 23.09.1.

Does the patch from #note-11 work around the issue? It should avoid the auth failure now.

As I noted, patching ovpn_auth_verify_async gave me auth failures. I could try it again an see if that is still the case. Or just patch ovpn_auth_verify, but I wasn't sure if patching just that was sufficient.

I updated the patch which should deal with the auth failure.

Okay, I have that applied and working now. And I don't seem to see a runaway with a simple auth failure. We'll see if anything else triggers it. Thanks.

I don't have a test instance at the moment, but I've thought about spinning one up for quite a while. I'll see what I can do. Thanks for taking a look at this - it sounds promising.

What version(s) are you currently running and encountering this? Perhaps a test build of fcgicli would be appropriate.

pfSense 2.7.2 and pfSense Plus 23.09.1