OpenVPN PAM failed after package upgrade to 2.3.8-14.1

Hello,
I’m using OpenVPN with PAM-Radius for authentication with a free radius server. The configuration was functioning very well from many years until upgrading “openvpn” and “openvpn-auth-pam-plugin” packages from 2.3.8-7.1 to 2.3.8-14.1.

Before migration, the authentication logs were like that:
For PAM:


2018-01-21T20:53:39.686912+01:00 gate openvpn[16979]: pam_radius_auth: Got user name toto
2018-01-21T20:53:39.688240+01:00 gate openvpn[16979]: pam_radius_auth: ignore last_pass, force_prompt set
2018-01-21T20:53:39.689730+01:00 gate openvpn[16979]: pam_radius_auth: Sending RADIUS request code 1
2018-01-21T20:53:40.503547+01:00 gate openvpn[16979]: pam_radius_auth: Got RADIUS response code 2
2018-01-21T20:53:40.504966+01:00 gate openvpn[16979]: pam_radius_auth: authentication succeeded

For openvpn:

Sun Jan 21 19:53:39 2018 us=678984 xx.xx.xx.123:55949 PLUGIN_CALL: PRE type=PLUGIN_AUTH_USER_PASS_VERIFY
Sun Jan 21 19:53:39 2018 us=679435 xx.xx.xx.123:55949 ARGV[0] = '/usr/lib64/openvpn/plugins/openvpn-plugin-auth-pam.so'
Sun Jan 21 19:53:39 2018 us=679656 xx.xx.xx.123:55949 ENVP[0] = 'auth_control_file=/tmp/openvpn_acf_0bd7ec8a1471ba18505bb4a145a8e085.tmp'
Sun Jan 21 19:53:39 2018 us=679912 xx.xx.xx.123:55949 ENVP[1] = 'untrusted_port=55949'
Sun Jan 21 19:53:39 2018 us=680228 xx.xx.xx.123:55949 ENVP[2] = 'untrusted_ip=xx.xx.xx.123'
Sun Jan 21 19:53:39 2018 us=680524 xx.xx.xx.123:55949 ENVP[4] = 'username=toto'
Sun Jan 21 19:53:39 2018 us=680730 xx.xx.xx.123:55949 ENVP[5] = 'remote_port_1=1194'
Sun Jan 21 19:53:39 2018 us=680934 xx.xx.xx.123:55949 ENVP[6] = 'local_port_1=1194'
Sun Jan 21 19:53:39 2018 us=681180 xx.xx.xx.123:55949 ENVP[7] = 'local_1=172.xx.xx.10'
Sun Jan 21 19:53:39 2018 us=681238 xx.xx.xx.123:55949 ENVP[8] = 'proto_1=tcp-server'
Sun Jan 21 19:53:39 2018 us=681293 xx.xx.xx.123:55949 ENVP[9] = 'daemon_pid=16978'
Sun Jan 21 19:53:39 2018 us=681348 xx.xx.xx.123:55949 ENVP[10] = 'daemon_start_time=1516562606'
Sun Jan 21 19:53:39 2018 us=681403 xx.xx.xx.123:55949 ENVP[11] = 'daemon_log_redirect=1'
Sun Jan 21 19:53:39 2018 us=681458 xx.xx.xx.123:55949 ENVP[12] = 'daemon=1'
Sun Jan 21 19:53:39 2018 us=681514 xx.xx.xx.123:55949 ENVP[13] = 'verb=7'
Sun Jan 21 19:53:39 2018 us=681569 xx.xx.xx.123:55949 ENVP[14] = 'config=/etc/openvpn/server.conf'
Sun Jan 21 19:53:39 2018 us=681624 xx.xx.xx.123:55949 ENVP[15] = 'ifconfig_local=172.xx.xx.1'
Sun Jan 21 19:53:39 2018 us=681680 xx.xx.xx.123:55949 ENVP[16] = 'ifconfig_remote=172.xx.xx.2'
Sun Jan 21 19:53:39 2018 us=681734 xx.xx.xx.123:55949 ENVP[17] = 'route_net_gateway=172.xx.xx.1'
Sun Jan 21 19:53:39 2018 us=681790 xx.xx.xx.123:55949 ENVP[18] = 'route_vpn_gateway=172.xx.xx.2'
Sun Jan 21 19:53:39 2018 us=681845 xx.xx.xx.123:55949 ENVP[19] = 'route_network_1=172.xx.xx.0'
Sun Jan 21 19:53:39 2018 us=681900 xx.xx.xx.123:55949 ENVP[20] = 'route_netmask_1=255.255.255.0'
Sun Jan 21 19:53:39 2018 us=681955 xx.xx.xx.123:55949 ENVP[21] = 'route_gateway_1=172.xx.xx.2'
Sun Jan 21 19:53:39 2018 us=682030 xx.xx.xx.123:55949 ENVP[22] = 'script_context=init'
Sun Jan 21 19:53:39 2018 us=682084 xx.xx.xx.123:55949 ENVP[23] = 'tun_mtu=1500'
Sun Jan 21 19:53:39 2018 us=682139 xx.xx.xx.123:55949 ENVP[24] = 'link_mtu=1560'
Sun Jan 21 19:53:39 2018 us=682194 xx.xx.xx.123:55949 ENVP[25] = 'dev=tun0'
Sun Jan 21 19:53:39 2018 us=682249 xx.xx.xx.123:55949 ENVP[26] = 'dev_type=tun'
Sun Jan 21 19:53:39 2018 us=682303 xx.xx.xx.123:55949 ENVP[27] = 'redirect_gateway=0'
AUTH-PAM: BACKGROUND: received command code: 0
AUTH-PAM: BACKGROUND: USER: toto
AUTH-PAM: BACKGROUND: my_conv[0] query='Password: ' style=1
Sun Jan 21 19:53:40 2018 us=506179 xx.xx.xx.123:55949 PLUGIN_CALL: POST /usr/lib64/openvpn/plugins/openvpn-plugin-auth-pam.so/PLUGIN_AUTH_USER_PASS_VERIFY status=0

The authentication was successful!

After migration, the logs were like thst:

For PAM, authentication is successful:

2018-01-21T21:08:22.092628+01:00 gate openvpn[2012]: pam_radius_auth: Got user name toto
2018-01-21T21:08:22.094812+01:00 gate openvpn[2012]: pam_radius_auth: ignore last_pass, force_prompt set
2018-01-21T21:08:22.095359+01:00 gate openvpn[2012]: pam_radius_auth: Sending RADIUS request code 1
2018-01-21T21:08:22.903171+01:00 gate openvpn[2012]: pam_radius_auth: Got RADIUS response code 2
2018-01-21T21:08:22.903662+01:00 gate openvpn[2012]: pam_radius_auth: authentication succeeded

In openvpn logs, the authentication is deferred and faild for the vpn client:

Sun Jan 21 20:08:22 2018 us=80462 xx.xx.xx.123:55992 PLUGIN_CALL: PRE type=PLUGIN_AUTH_USER_PASS_VERIFY
Sun Jan 21 20:08:22 2018 us=80812 xx.xx.xx.123:55992 ARGV[0] = '/usr/lib64/openvpn/plugins/openvpn-plugin-auth-pam.so'
Sun Jan 21 20:08:22 2018 us=81088 xx.xx.xx.123:55992 ENVP[0] = 'auth_control_file=/tmp/openvpn_acf_966ba26d91745497856172751c0195c7.tmp'
Sun Jan 21 20:08:22 2018 us=81477 xx.xx.xx.123:55992 ENVP[1] = 'untrusted_port=55992'
Sun Jan 21 20:08:22 2018 us=81570 xx.xx.xx.123:55992 ENVP[2] = 'untrusted_ip=xx.xx.xx.123'
Sun Jan 21 20:08:22 2018 us=81643 xx.xx.xx.123:55992 ENVP[4] = 'username=toto'
Sun Jan 21 20:08:22 2018 us=81713 xx.xx.xx.123:55992 ENVP[5] = 'remote_port_1=1194'
Sun Jan 21 20:08:22 2018 us=81782 xx.xx.xx.123:55992 ENVP[6] = 'local_port_1=1194'
Sun Jan 21 20:08:22 2018 us=81958 xx.xx.xx.123:55992 ENVP[7] = 'local_1=172.xx.xx.10'
Sun Jan 21 20:08:22 2018 us=82032 xx.xx.xx.123:55992 ENVP[8] = 'proto_1=tcp-server'
Sun Jan 21 20:08:22 2018 us=82102 xx.xx.xx.123:55992 ENVP[9] = 'daemon_pid=2011'
Sun Jan 21 20:08:22 2018 us=82169 xx.xx.xx.123:55992 ENVP[10] = 'daemon_start_time=1516548242'
Sun Jan 21 20:08:22 2018 us=82236 xx.xx.xx.123:55992 ENVP[11] = 'daemon_log_redirect=1'
Sun Jan 21 20:08:22 2018 us=82302 xx.xx.xx.123:55992 ENVP[12] = 'daemon=1'
Sun Jan 21 20:08:22 2018 us=82369 xx.xx.xx.123:55992 ENVP[13] = 'verb=9'
Sun Jan 21 20:08:22 2018 us=82435 xx.xx.xx.123:55992 ENVP[14] = 'config=/etc/openvpn/server.conf'
Sun Jan 21 20:08:22 2018 us=82503 xx.xx.xx.123:55992 ENVP[15] = 'ifconfig_local=172.xx.xx.1'
Sun Jan 21 20:08:22 2018 us=82569 xx.xx.xx.123:55992 ENVP[16] = 'ifconfig_remote=172.xx.xx.2'
Sun Jan 21 20:08:22 2018 us=82635 xx.xx.xx.123:55992 ENVP[17] = 'route_net_gateway=172.xx.xx.1'
Sun Jan 21 20:08:22 2018 us=82702 xx.xx.xx.123:55992 ENVP[18] = 'route_vpn_gateway=172.xx.xx.2'
Sun Jan 21 20:08:22 2018 us=82769 xx.xx.xx.123:55992 ENVP[19] = 'route_network_1=172.xx.xx.0'
Sun Jan 21 20:08:22 2018 us=82836 xx.xx.xx.123:55992 ENVP[20] = 'route_netmask_1=255.255.255.0'
Sun Jan 21 20:08:22 2018 us=82912 xx.xx.xx.123:55992 ENVP[21] = 'route_gateway_1=172.xx.xx.2'
Sun Jan 21 20:08:22 2018 us=82979 xx.xx.xx.123:55992 ENVP[22] = 'script_context=init'
Sun Jan 21 20:08:22 2018 us=83045 xx.xx.xx.123:55992 ENVP[23] = 'tun_mtu=1500'
Sun Jan 21 20:08:22 2018 us=83111 xx.xx.xx.123:55992 ENVP[24] = 'link_mtu=1560'
Sun Jan 21 20:08:22 2018 us=83178 xx.xx.xx.123:55992 ENVP[25] = 'dev=tun0'
Sun Jan 21 20:08:22 2018 us=83245 xx.xx.xx.123:55992 ENVP[26] = 'dev_type=tun'
Sun Jan 21 20:08:22 2018 us=83311 xx.xx.xx.123:55992 ENVP[27] = 'redirect_gateway=0'
AUTH-PAM: BACKGROUND: received command code: 2
AUTH-PAM: BACKGROUND: USER: toto
OPENVPN_PLUGIN_AUTH_USER_PASS_VERIFY
Sun Jan 21 20:08:22 2018 us=84047 xx.xx.xx.123:55992 PLUGIN_CALL: POST /usr/lib64/openvpn/plugins/openvpn-plugin-auth-pam.so/PLUGIN_AUTH_USER_PASS_VERIFY status=2
Sun Jan 21 20:08:22 2018 us=84168 xx.xx.xx.123:55992 TLS: Username/Password authentication deferred for username 'toto' [CN SET]

I notice the following in the Changelog of openvpn:

2017-04-20 - ndas@suse.de - Preform deferred authentication in the background to not cause main daemon processing delays when the underlying pam mechanism (e.g. ldap) needs longer to response (bsc#959511). + 0001-preform-deferred-authentication-in-the-background.patch]

Can this change be the cause of the issue?
How can we make pam-radius working with the last openvpn packages?

Thanks for your help!

Best regards

My guess is that if there is an issue with new openvpn package versions,
In these waning days of 42.2, it won’t be addressed.

I strongly recommend upgrading to 42.3, and if that doesn’t address whatever the issue might have been to post again.

TSU

I upgraded to 42.3 with the same result, not working with the same messages on logs.

I reported the issue in bugzilla https://bugzilla.opensuse.org/show_bug.cgi?id=1077729
Thanks for your replay!