OpenVPN PAM failed after package upgrade to 2.3.8-14.1

English Network/Internet
#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

#2

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

#3

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!