Closed FlorinAndrei closed 6 years ago
If everything is owned by root
then you shouldn't use no_strict_owner
, but that's not the problem here.
If you're not getting any log message from the PAM module then I'd say it was never successfully invoked.
If the code is actually running it's failing without logging anything. Are you sure that you're reading all logs? It's probably not enough to read the openvpn output or logs, but you'll also need to check /var/log/auth.log
or similar.
What if you put in return PAM_SUCCESS
as the first line in the google_authenticator
function? That would prove that it's successfully loading the .so
file.
What if you put in return PAM_SUCCESS as the first line in the google_authenticator function? That would prove that it's successfully loading the .so file.
So that works just fine:
Mon Apr 9 18:58:15 2018 vpn:41163 PLUGIN_CALL: POST /usr/lib/openvpn/openvpn-plugin-auth-pam.so/PLUGIN_AUTH_USER_PASS_VERIFY status=0
Mon Apr 9 18:58:15 2018 vpn:41163 TLS: Username/Password authentication succeeded for username 'florin'
I've replaced it back with the original Google PAM module and tried again. This time I'm logging like this (so I'm forcing logging to a file):
log openvpn-multi.log
verb 6
And this is what I get in the log file:
AUTH-PAM: BACKGROUND: received command code: 0
AUTH-PAM: BACKGROUND: USER: florin
AUTH-PAM: BACKGROUND: my_conv[0] query='Verification code: ' style=2
AUTH-PAM: BACKGROUND: user 'florin' failed to authenticate: Authentication failure
Mon Apr 9 19:15:23 2018 us=790144 vpn:36242 PLUGIN_CALL: POST /usr/lib/openvpn/openvpn-plugin-auth-pam.so/PLUGIN_AUTH_USER_PASS_VERIFY status=1
Mon Apr 9 19:15:23 2018 us=790160 vpn:36242 PLUGIN_CALL: plugin function PLUGIN_AUTH_USER_PASS_VERIFY failed with status 1: /usr/lib/openvpn/openvpn-plugin-auth-pam.so
Mon Apr 9 19:15:23 2018 us=790181 vpn:36242 TLS Auth Error: Auth Username/Password verification failed for peer
Everything else is UDP and TLS and seems unrelated.
Is this how debug logging is supposed to look like with the Google Auth PAM module?
None of those log lines come from google authenticator.
It's likely not going to show up in openvpn-multi.log
, but more likely in /var/log/auth.log
or some other syslog-based logfile.
I'm not sure what's the facility/priority combo used by the plugin, but on this Ubuntu 16.04 instance its debug messages were not logged anywhere. I had to do this to capture the debug from the plugin:
# cat /etc/rsyslog.d/10-everything.conf
*.* /var/log/everything.log
This is what I see now:
Apr 9 23:32:00 vpn openvpn(pam_google_authenticator)[3137]: debug: start of google_authenticator for "florin"
Apr 9 23:32:00 vpn openvpn(pam_google_authenticator)[3137]: debug: Secret file permissions are 0600. Allowed permissions are 0600
Apr 9 23:32:00 vpn openvpn(pam_google_authenticator)[3137]: debug: "/etc/openvpn/google-auth-users/florin" read
Apr 9 23:32:00 vpn openvpn(pam_google_authenticator)[3137]: debug: shared secret in "/etc/openvpn/google-auth-users/florin" processed
Apr 9 23:32:00 vpn openvpn(pam_google_authenticator)[3137]: Invalid verification code for florin
Apr 9 23:32:00 vpn openvpn(pam_google_authenticator)[3137]: debug: "/etc/openvpn/google-auth-users/florin" written
Time is synchronized, ntpd is running and is synced to upstream.
Another strange thing I've noticed is that the initial permissions for the file are 0600, but after the authentication attempt it's changed to 0400. No idea how that happens.
Were you ever asked for a verification code? If so, what did the prompt look like?
Permissions: allowed permissions is 0600, ideal is 0400. So that's what's set when the file is very carefully updated.
I use Tunnelblick. I get the regular username / password prompt.
In the username field I enter the user account name that you see in the logs quoted above.
In the password field, I enter the PIN generated with Google Authenticator on Android; the GA profile was created from the ASCII art image generated by the google-authenticator CLI utility on the VPN instance.
Oh, you enter it as password? Then to be clear you were not asked for a verification code.
Sounds like this client doesn't support asking for additional authentication tokens, and that you have to configure the PAM module to extract the OTP from the supplied password instead.
Try adding the use_first_pass
option to the PAM module. Possibly one of the other options try_first_pass / use_first_pass / forward_pass
would help. See the README for more details that might help.
Others have commented that they made it work with Tunnelblick:
https://github.com/Tunnelblick/Tunnelblick/issues/383
I had a similar setup a while ago, where the verification code and the password were concatenated, and were entered together in the password field in Tunnelblick - except I was using Yubikey instead of Google Auth.
So it seems like it should work. After all, that's what the forward_pass
option is for. I believe the Yubikey module behaves like the Google Auth module with the forward_pass
option enabled.
Another thing I've noticed:
When the QR code is generated, the CLI utility prints this message:
Your verification code is XXXXXX
But that code never matches anything I could get from the Google Auth app in Android. Even if I do everything as fast as I can within 30 seconds, I long-press the new entry in the app, copy the code to the clipboard and paste it in another app, it never matches what's printed by the CLI utility.
I've tried to generate the new entry in the Android app in three different ways (scan QR, click the URL, and copy/paste the secret key) and the result is always the same. I get a new entry in the app, the verification code never matches what's printed in the terminal, and the thing just doesn't work.
# cat /etc/pam.d/openvpn
auth required /usr/local/lib/security/pam_google_authenticator.so secret=/etc/openvpn/google-auth-users/${USER} user=root no_strict_owner echo_verification_code debug forward_pass
auth required pam_radius_auth.so debug use_first_pass
account required pam_permit.so debug
# pamtester openvpn florin authenticate
Password & verification code: XXXXXXXXXX
pamtester: Authentication failure
At the prompt above, I enter the password stored in Radius, concatenated with the Google Auth code.
# tail /var/log/everything.log
Apr 10 18:35:33 vpn openvpn(pam_google_authenticator)[8028]: debug: start of google_authenticator for "florin"
Apr 10 18:35:33 vpn openvpn(pam_google_authenticator)[8028]: debug: Secret file permissions are 0400. Allowed permissions are 0600
Apr 10 18:35:33 vpn openvpn(pam_google_authenticator)[8028]: debug: "/etc/openvpn/google-auth-users/florin" read
Apr 10 18:35:33 vpn openvpn(pam_google_authenticator)[8028]: debug: shared secret in "/etc/openvpn/google-auth-users/florin" processed
Apr 10 18:35:41 vpn openvpn(pam_google_authenticator)[8028]: debug: no scratch code used from "/etc/openvpn/google-auth-users/florin"
Apr 10 18:35:41 vpn openvpn(pam_google_authenticator)[8028]: debug: no scratch code used from "/etc/openvpn/google-auth-users/florin"
Apr 10 18:35:41 vpn openvpn(pam_google_authenticator)[8028]: Invalid verification code for florin
Apr 10 18:35:41 vpn pamtester[8028]: pam_radius_auth: Got user name florin
Apr 10 18:35:41 vpn pamtester[8028]: pam_radius_auth: authentication failed
I don't even see anything in the FreeRadius log - either the request is not even sent to it, or it's too mangled to be processed.
But pamtester works fine if I configure /etc/pam.d/openvpn
to only use Radius.
To me, this seems to indicate that something is wrong with the Google Auth module itself.
EDIT: Confirmed. I've configured pam.d to only use the Google Auth module, no Radius, and pamtester fails:
root@vpn:~# pamtester openvpn florin authenticate
Verification code: 980252
pamtester: Authentication failure
root@vpn:~# tail /var/log/everything.log
Apr 10 18:49:01 vpn openvpn(pam_google_authenticator)[8128]: debug: start of google_authenticator for "florin"
Apr 10 18:49:01 vpn openvpn(pam_google_authenticator)[8128]: debug: Secret file permissions are 0400. Allowed permissions are 0600
Apr 10 18:49:01 vpn openvpn(pam_google_authenticator)[8128]: debug: "/etc/openvpn/google-auth-users/florin" read
Apr 10 18:49:01 vpn openvpn(pam_google_authenticator)[8128]: debug: shared secret in "/etc/openvpn/google-auth-users/florin" processed
Apr 10 18:49:14 vpn openvpn(pam_google_authenticator)[8128]: debug: no scratch code used from "/etc/openvpn/google-auth-users/florin"
Apr 10 18:49:14 vpn openvpn(pam_google_authenticator)[8128]: Invalid verification code for florin
Is the echo_verification_code
option supposed to send the code to the logs via debug? It doesn't seem to do anything.
Strange. Works for me.
$ cat /etc/pam.d/blaha
auth required /usr/local/lib/security/pam_google_authenticator.so no_strict_owner echo_verification_code debug forward_pass
account required pam_permit.so debug
$ sudo pamtester blaha thomas authenticate
Password & verification code: blaha123321
pamtester: successfully authenticated
I added this to line 1794 of src/pam_google_authenticator.c
:
log_message(LOG_INFO, pamh, "Code: %d", code);
And it prints out the code as expected.
Is the time set correctly on your server and phone? Check again.
Is the
echo_verification_code
option supposed to send the code to the logs via debug? It doesn't seem to do anything.
No, it affects if the password is echoed as you are entering it. If that's a GUI then that's a no-op. Does affect the behaviour of pamtester
though.
Making progress. I was actually missing the .la file from my pam_google_authenticator installation, that's why it kept failing. 😞 Now it works with pamtester:
Apr 11 11:31:18 vpn openvpn(pam_google_authenticator)[21911]: debug: start of google_authenticator for "florin"
Apr 11 11:31:18 vpn openvpn(pam_google_authenticator)[21911]: debug: Secret file permissions are 0400. Allowed permissions are 0600
Apr 11 11:31:18 vpn openvpn(pam_google_authenticator)[21911]: debug: "/etc/openvpn/google-auth-users/florin" read
Apr 11 11:31:18 vpn openvpn(pam_google_authenticator)[21911]: debug: shared secret in "/etc/openvpn/google-auth-users/florin" processed
Apr 11 11:31:35 vpn openvpn(pam_google_authenticator)[21911]: debug: no scratch code used from "/etc/openvpn/google-auth-users/florin"
Apr 11 11:31:35 vpn openvpn(pam_google_authenticator)[21911]: Accepted google_authenticator for florin
Apr 11 11:31:35 vpn openvpn(pam_google_authenticator)[21911]: debug: "/etc/openvpn/google-auth-users/florin" written
Apr 11 11:31:35 vpn pamtester[21911]: pam_radius_auth: Got user name florin
Apr 11 11:31:35 vpn pamtester[21911]: pam_radius_auth: Got password 1234
Apr 11 11:31:35 vpn pamtester[21911]: pam_radius_auth: Sending RADIUS request code 1
Apr 11 11:31:35 vpn pamtester[21911]: pam_radius_auth: DEBUG: getservbyname(radius, udp) returned 35300480.
Apr 11 11:31:35 vpn pamtester[21911]: pam_radius_auth: Got RADIUS response code 2
Apr 11 11:31:35 vpn pamtester[21911]: pam_radius_auth: authentication succeeded
However, it keeps failing with openvpn, using the exact same /etc/pam.d/openvpn
configuration. I've tried both Tunnelblick and Viscosity as clients.
Apr 11 11:41:49 vpn openvpn(pam_google_authenticator)[22925]: debug: start of google_authenticator for "florin"
Apr 11 11:41:49 vpn openvpn(pam_google_authenticator)[22925]: debug: Secret file permissions are 0400. Allowed permissions are 0600
Apr 11 11:41:49 vpn openvpn(pam_google_authenticator)[22925]: debug: "/etc/openvpn/google-auth-users/florin" read
Apr 11 11:41:49 vpn openvpn(pam_google_authenticator)[22925]: debug: shared secret in "/etc/openvpn/google-auth-users/florin" processed
Apr 11 11:41:49 vpn openvpn(pam_google_authenticator)[22925]: Invalid verification code for florin
Apr 11 11:41:49 vpn openvpn(pam_google_authenticator)[22925]: debug: "/etc/openvpn/google-auth-users/florin" written
Apr 11 11:41:49 vpn openvpn[22925]: pam_radius_auth: Got user name florin
Apr 11 11:41:49 vpn openvpn[22925]: pam_radius_auth: authentication failed
Like I said put in that log_message
line and see what the PAM module thinks is the OTP.
Or try having both use_first_pass
and forward_pass
.
log_message
in the 1794 region of the code is not even executed when I run openvpn. Something fails before that and the code doesn't even try to run that line.
When I run pamtester then the 1794 line is executed just fine.
I've added another log_message
at 1713 (trying to log pw
but I'm probably not doing it right) and that one at least does get executed every time no matter what (with both pamtester and openvpn). So whatever goes wrong is between 1713 and 1794.
Using both use_first_pass
and forward_pass
doesn't work at all - pamtester fails, openvpn fails.
Dunno. Add logging down the different paths to see where it goes.
It takes the invalid
code branch in the 1700s region of the code, then hits continue
. Never makes it past that point.
if (pw_len < expected_len ||
// Verification are six digits starting with '0'..'9',
// scratch codes are eight digits starting with '1'..'9'
(ch = pw[pw_len - expected_len]) > '9' ||
ch < (expected_len == 8 ? '1' : '0')) {
invalid:
explicit_bzero(pw, pw_len);
free(pw);
pw = NULL;
continue;
}
Please tell me exactly what debug lines to insert in that area (I don't write C and can't spend too much time figuring it out), then I will re-run it and send you the results.
Did you add a log message saying what the OTP is? is it "mypasswordhere123456"?
I did this:
if (pw_len < expected_len ||
// Verification are six digits starting with '0'..'9',
// scratch codes are eight digits starting with '1'..'9'
(ch = pw[pw_len - expected_len]) > '9' ||
ch < (expected_len == 8 ? '1' : '0')) {
invalid:
log_message(LOG_INFO, pamh, "line 1739");
log_message(LOG_INFO, pamh, "pw: %s", pw);
explicit_bzero(pw, pw_len);
free(pw);
pw = NULL;
continue;
}
And it's printing this:
May 1 11:44:27 vpn openvpn(pam_google_authenticator)[8914]: line 1714
May 1 11:44:27 vpn openvpn(pam_google_authenticator)[8914]: line 1731
May 1 11:44:27 vpn openvpn(pam_google_authenticator)[8914]: line 1739
May 1 11:44:27 vpn openvpn(pam_google_authenticator)[8914]: pw: florin
May 1 11:44:27 vpn openvpn(pam_google_authenticator)[8914]: line 1714
May 1 11:44:27 vpn openvpn(pam_google_authenticator)[8914]: line 1731
May 1 11:44:27 vpn openvpn(pam_google_authenticator)[8914]: line 1739
May 1 11:44:27 vpn openvpn(pam_google_authenticator)[8914]: pw: florin
May 1 11:44:27 vpn openvpn(pam_google_authenticator)[8914]: Invalid verification code for florin
May 1 11:44:27 vpn openvpn(pam_google_authenticator)[8914]: debug: "/etc/openvpn/google-auth-users/florin" written
May 1 11:44:27 vpn openvpn[8914]: pam_radius_auth: Got user name florin
May 1 11:44:27 vpn openvpn[8914]: pam_radius_auth: authentication failed
Seems like it's printing my username where it should print the password + code.
log the password just before 1783 (memset(pw + pw_len - expected_len, 0, expected_len);
)
No, it doesn't make it that far. It gets stuck in the 1765 - 1775 block which is right above it.
if (pw_len < expected_len ||
// Verification are six digits starting with '0'..'9',
// scratch codes are eight digits starting with '1'..'9'
(ch = pw[pw_len - expected_len]) > '9' ||
ch < (expected_len == 8 ? '1' : '0')) {
invalid:
explicit_bzero(pw, pw_len);
free(pw);
pw = NULL;
continue;
}
There's something weird with the way the authentication parameters (username, pass + code, etc) are received by the module. The problem happens way before that, I think.
Maybe the stuff is handed down the wrong way by OpenVPN. Maybe the PAM module gets confused by something.
Observation: I am using the 1.05 release. If you want me to switch to the current master branch instead, let me know.
Are you sure that it doesn't get to there? It jumps backwards to the invalid:
label.
If it doesn't get to the memset
on 1783 and you entered both password and OTP, but the log line you added only shows the password, then I have absolutely no idea. That doesn't seem possible, since that's where the password is altered. If it's been altered and not there, then I don't know.
I am using the 1.05 release from the Releases link on this GitHub project. The diff is this - literally just one line changed:
# diff -U 30 google-authenticator-libpam-1.05/src/pam_google_authenticator.c google-authenticator-libpam-1.05-new/src/pam_google_authenticator.c
--- google-authenticator-libpam-1.05/src/pam_google_authenticator.c 2017-12-04 06:12:46.000000000 -0800
+++ google-authenticator-libpam-1.05-new/src/pam_google_authenticator.c 2018-05-03 11:39:13.199353808 -0700
@@ -1717,60 +1717,61 @@
const int expected_len = mode & 1 ? 8 : 6;
char ch;
// Full OpenSSH "bad password" is "\b\n\r\177INCORRECT", capped
// to original password length.
if (pw_len > 0 && pw[0] == '\b') {
log_message(LOG_INFO, pamh,
"Dummy password supplied by PAM."
" Did OpenSSH 'PermitRootLogin <anything but yes>' or some"
" other config block this login?");
}
if (pw_len < expected_len ||
// Verification are six digits starting with '0'..'9',
// scratch codes are eight digits starting with '1'..'9'
(ch = pw[pw_len - expected_len]) > '9' ||
ch < (expected_len == 8 ? '1' : '0')) {
invalid:
explicit_bzero(pw, pw_len);
free(pw);
pw = NULL;
continue;
}
char *endptr;
errno = 0;
const long l = strtol(pw + pw_len - expected_len, &endptr, 10);
if (errno || l < 0 || *endptr) {
goto invalid;
}
const int code = (int)l;
+ log_message(LOG_INFO, pamh, "pw: %s", pw);
memset(pw + pw_len - expected_len, 0, expected_len);
if ((mode == 2 || mode == 3) && !params.forward_pass) {
// We are explicitly configured so that we don't try to share
// the password with any other stacked PAM module. We must
// therefore verify that the user entered just the verification
// code, but no password.
if (*pw) {
goto invalid;
}
}
// Only if we actually have a secret will we try to verify the code
// In all other cases will we just remain at PAM_AUTH_ERR
if (secret) {
// Check all possible types of verification codes.
switch (check_scratch_codes(pamh, ¶ms, secret_filename, &updated, buf, code)) {
case 1:
if (hotp_counter > 0) {
switch (check_counterbased_code(pamh, secret_filename, &updated,
&buf, secret, secretLen, code,
hotp_counter,
&must_advance_counter)) {
case 0:
rc = PAM_SUCCESS;
break;
case 1:
goto invalid;
default:
break;
I've pulled the latest master branch from github. The diff with the log line is this:
# git diff
diff --git a/src/pam_google_authenticator.c b/src/pam_google_authenticator.c
index a5f9a1d..9680ae1 100644
--- a/src/pam_google_authenticator.c
+++ b/src/pam_google_authenticator.c
@@ -1780,6 +1780,7 @@ static int google_authenticator(pam_handle_t *pamh,
goto invalid;
}
const int code = (int)l;
+ log_message(LOG_INFO, pamh, "pw: %s", pw);
memset(pw + pw_len - expected_len, 0, expected_len);
if ((mode == 2 || mode == 3) && !params.forward_pass) {
It does not log anything. It does not get to that line - or, if it does, the failure is such that nothing is shown in the logs. I would expect to see something like:
May 14 17:21:23 vpn openvpn(pam_google_authenticator)[5222]: pw: 1234291434
At least the pw:
prefix should be printed out. But no, with openvpn nothing like that happens.
PROBLEM SOLVED!!!
Turns out, in the OpenVPN server config file you need to invoke the PAM module like this:
plugin /usr/lib/openvpn/plugins/openvpn-plugin-auth-pam.so "openvpn login USERNAME password PASSWORD"
Just specifying the service name after the plugin file is not enough. You also have to tell it how to answer the queries from the PAM stack. Otherwise it won't hand off the user/pass information to the PAM stack in the correct format.
Now everything works. The "password" is actually a concatenated string, made of the fixed PIN (handed off to Radius) plus the code from the GAuth app (handed off to google-authenticator-libpam). I've tested wrong PIN (and then Radius fails), and wrong code (and then GAuth fails). When both PIN and code are correct, authentication returns success.
Sorry for all this trouble, and thank you for all your help. I just wish I read the openvpn-plugin-auth-pam.so documentation earlier.
Awesome! Thanks for following up with the explanation.
pam keeps reporting that error Dec 19 16:46:16 ip-172-16-100-124 openvpn(pam_google_authenticator)[8922]: Invalid verification code using this configuration on etc/pam.d/openvpn
account required pam_unix.so account required pam_permit.so auth requisite pam_google_authenticator.so secret=/etc/openvpn/google-authenticator/${USER} user=gauth forward_pass auth required pam_unix.so use_first_pass and openvpn server plugin /usr/lib64/openvpn/plugin/lib/openvpn-auth-pam.so openvpn on client auth-user-pass
info about package version
yum info google-authenticator Loaded plugins: priorities, update-motd, upgrade-helper Installed Packages Name : google-authenticator Arch : x86_64 Version : 1.0 Release : 1.2.amzn1 Size : 63 k Repo : installed From repo : amzn-main Summary : One-time passcode support using open standards URL : http://code.google.com/p/google-authenticator/ License : ASL 2.0 Description : The Google Authenticator package contains a pluggable authentication : module (PAM) which allows login using one-time passcodes conforming to : the open standards developed by the Initiative for Open Authentication : (OATH) (which is unrelated to OAuth). : : Passcode generators are available (separately) for several mobile : platforms. : : These implementations support the HMAC-Based One-time Password (HOTP) : algorithm specified in RFC 4226 and the Time-based One-time Password : (TOTP) algorithm currently in draft.
Available Packages Name : google-authenticator Arch : i686 Version : 1.0 Release : 1.2.amzn1 Size : 31 k Repo : amzn-main/latest Summary : One-time passcode support using open standards URL : http://code.google.com/p/google-authenticator/ License : ASL 2.0 Description : The Google Authenticator package contains a pluggable authentication : module (PAM) which allows login using one-time passcodes conforming to : the open standards developed by the Initiative for Open Authentication : (OATH) (which is unrelated to OAuth). : : Passcode generators are available (separately) for several mobile : platforms. : : These implementations support the HMAC-Based One-time Password (HOTP) : algorithm specified in RFC 4226 and the Time-based One-time Password : (TOTP) algorithm currently in draft.
Ubuntu 16.04 openvpn 2.3.10
On server:
On client:
Running openvpn like this:
Various configs:
I get this error:
NTP is installed everywhere.
I've tried initially the very old Google Auth package that comes with Ubuntu. Didn't work. Now I've compiled it from the latest source release. Same result.
I'm not even sure how to even start troubleshooting.
openvpn authenticates just fine with FreeRadius if I comment out the Google Auth part and I enable the Radius part instead.
Eventually I want to be able to use a PIN (sent to Radius) and an OTP (sent to Google Auth), but for now I can't make Google Auth work alone; in the current tests I only enter the OTP as the password.
The
debug
option passed topam_google_authenticator.so
doesn't seem to make any difference. I get the same messages with or without it.