Pam_Yubico returns OTP was bad (BAD_OTP) but I can test the token successfully in the PrivacyIDEAUI

Hey PrivacyIDEA community

So I am evaluating privacyIDEA to superseed the yubikey validation server for all our data centers.

So I used a working (it worked against our existing yubico validation servver) /etc/pam.d/sshd that uses pam_yubico and instead of our old validation server I pointed it to my privacyIDEA instance.

The PAM module does make a web request to my privacyIDEA endpoint which one can see from the entry in the /var/log/apache2/ssl_access.log:

x.x.x.x - - [30/Sep/2022:14:59:22 +0200] 200 “GET /wsapi/2.0/verify HTTP/1.1” 78 “-” “ykclient/2.15”

The status code is 200 which according the yubico doc means the API request was formed correctly at least:

Response
If the verification server has successfully processed your request (even if the reponse is not a successful verification), it will return an HTTP status of 200 OK with a text/plain body.
OTP validation protocol (yubico.com)

When I try to use 2FA with my Yubikey my PAM log shows the following:

[…/pam_yubico.c:parse_cfg(759)] called.
[…/pam_yubico.c:parse_cfg(760)] flags 1 argc 13
[…/pam_yubico.c:parse_cfg(762)] argv[0]=mode=client
[…/pam_yubico.c:parse_cfg(762)] argv[1]=capath=/etc/ssl/certs/
[…/pam_yubico.c:parse_cfg(762)] argv[2]=debug
[…/pam_yubico.c:parse_cfg(762)] argv[3]=debug_file=/var/run/pam-debug.log
[…/pam_yubico.c:parse_cfg(762)] argv[4]=ldap_uri=ldaps://ldap.com
[…/pam_yubico.c:parse_cfg(762)] argv[5]=ldapdn=ou=Menschen,dc=Welt
[…/pam_yubico.c:parse_cfg(762)] argv[6]=urllist=https://privacyIDEA.com/wsapi/2.0/verify
[…/pam_yubico.c:parse_cfg(762)] argv[7]=id=CLIENT_ID # this is an INT
[…/pam_yubico.c:parse_cfg(762)] argv[8]=key=API_KEY # this is an API KEY
[…/pam_yubico.c:parse_cfg(762)] argv[9]=user_attr=uid
[…/pam_yubico.c:parse_cfg(762)] argv[10]=yubi_attr=yubiKeyId
[…/pam_yubico.c:parse_cfg(762)] argv[11]=ldap_cacertfile=/etc/ssl/certs/comCAFILE.pem
[…/pam_yubico.c:parse_cfg(762)] argv[12]=token_id_length=12
[…/pam_yubico.c:parse_cfg(763)] id=CLIENT_ID
[…/pam_yubico.c:parse_cfg(764)] key=API_KEY
[…/pam_yubico.c:parse_cfg(765)] debug=1
[…/pam_yubico.c:parse_cfg(766)] alwaysok=0
[…/pam_yubico.c:parse_cfg(767)] verbose_otp=0
[…/pam_yubico.c:parse_cfg(768)] try_first_pass=0
[…/pam_yubico.c:parse_cfg(769)] use_first_pass=0
[…/pam_yubico.c:parse_cfg(770)] authfile=(null)
[…/pam_yubico.c:parse_cfg(771)] ldapserver=(null)
[…/pam_yubico.c:parse_cfg(772)] ldap_uri=ldaps://ldap.com
[…/pam_yubico.c:parse_cfg(773)] ldap_bind_user=(null)
[…/pam_yubico.c:parse_cfg(774)] ldap_bind_password=(null)
[…/pam_yubico.c:parse_cfg(775)] ldap_filter=(null)
[…/pam_yubico.c:parse_cfg(776)] ldap_cacertfile=/etc/ssl/certs/comCAFILE.pem
[…/pam_yubico.c:parse_cfg(777)] ldapdn=ou=Menschen,dc=Welt
[…/pam_yubico.c:parse_cfg(778)] user_attr=uid
[…/pam_yubico.c:parse_cfg(779)] yubi_attr=yubiKeyId
[…/pam_yubico.c:parse_cfg(780)] yubi_attr_prefix=(null)
[…/pam_yubico.c:parse_cfg(781)] url=(null)
[…/pam_yubico.c:parse_cfg(782)] urllist=https://privacyidea.com/wsapi/2.0/verify
[…/pam_yubico.c:parse_cfg(783)] capath=/etc/ssl/certs/
[…/pam_yubico.c:parse_cfg(784)] cainfo=(null)
[…/pam_yubico.c:parse_cfg(785)] proxy=(null)
[…/pam_yubico.c:parse_cfg(786)] token_id_length=12
[…/pam_yubico.c:parse_cfg(787)] mode=client
[…/pam_yubico.c:parse_cfg(788)] chalresp_path=(null)
[…/pam_yubico.c:pam_sm_authenticate(819)] pam_yubico version: 2.23
[…/pam_yubico.c:pam_sm_authenticate(834)] get user returned: dummyuser
[…/pam_yubico.c:pam_sm_authenticate(985)] conv returned 44 bytes
[…/pam_yubico.c:pam_sm_authenticate(1003)] Skipping first 0 bytes. Length is 44, token_id set to 12 and token OTP always 32.
[…/pam_yubico.c:pam_sm_authenticate(1010)] OTP: 44 bytes TOKEN here ID: public id of Yubikey
[…/pam_yubico.c:pam_sm_authenticate(1040)] ykclient return value (1): Yubikey OTP was bad (BAD_OTP)
[…/pam_yubico.c:pam_sm_authenticate(1041)] ykclient url used: https://privacyidea.com/wsapi/2.0/verify?id=1&nonce=NONCE&otp=OTP=1&h=HMAC_SIGNATURE
[…/pam_yubico.c:pam_sm_authenticate(1109)] done. [Authentication failure]

I tried reproducing it with the ykclient utility with debug mode:

[root@privacyidea]:/etc/ssl/certs# ykclient --url ‘https://privacyidea.com/wsapi/2.0/verify’ --ca ‘/etc/ssl/certs’ --apikey ‘API_KEY’ CLIENT_ID OTP_TOKEN --debug
Input:
validation URL: https://privacyidea.com/wsapi/2.0/verify
CA Path: /etc/ssl/certs
client id: CLIENT_ID
token: OTP_TOKEN
api key: API_KEY
Response from: https://privacyidea.com/wsapi/2.0/verify?id=1&nonce=NONCE&otp=OTP&timestamp=1&h=HMAC_SIGNATURE
Verification output (1): Yubikey OTP was bad (BAD_OTP)
otp: (null)
nonce: (null)
t: 2022-09-30T13:26:51Z0446
timestamp: (null)
sessioncounter: (null)
sessionuse: (null)
sl: (null)
status: BAD_OTP

Same result. But the odd thing is that I can enter the same Yubico OTP in the privacyIDEA frontend and test the token and it is successfull:
image

I did configure the privacyidea server without TLS for debugging after that (port 80) and ran a tcpdump. I wanted to see what happens internally if I press the Test Token command. What I learned that it uses the generic REST API endpoint: /validate/check and not wsapi/2.0/verify.

So I am confused what I am doing wrong that it works for the new API but not for the backwards compatible API.

What could be the problem is that my PAM config:

auth required pam_yubico.so
mode=client
capath=/etc/ssl/certs/
debug
debug_file=/var/run/pam-debug.log
ldap_uri=ldaps://ldap.com
ldapdn=ou=Menschen,dc=Welt
urllist=https://privacyidea.com/wsapi/2.0/verify
id=CLIENT_ID
key=API_KEY
user_attr=uid
yubi_attr=
ldap_cacertfile=/etc/ssl/certs/comCaChain.pem
token_id_length=12

Uses yubi_attr to lookup the yubiKeyId which in our company is just the public identifier of the Yubikey. But in the privacyIDEA GUI I see * yubikey.tokenid: e8ab88cb1fbb which is of course different. Maybe this is causing the issue. I will investigate

I think this does not make sense. Because the ykclient utility does not have this information and it does not prompt for it either so it should not be relevant the yubikey.tokenid.

Take a look at the audit log and the authentication request. It might give you some insight, what and how the pam_yubico is trying to authenticate.

I did enable the audit log but for me it was not clear why the request still fails. I switched to the privacyIDEA pam library and there the same Yubikey OTP works flawlessly.

So, I am a bit at loss why the wsapi/2.0/verify endpoint returns invalid TOKEN, when the new one returns success.

Because I can also use the same token with our current yubikey validation server and it works just fine (by using pam_yubico and pointing to our old validation server).

So, it seems to be that the wsapi/2.0/verify endpoint is not working properly. Is this endpoint still under active development?

For us it does not matter because using the new API endpoint is better anyways. We can use the same endpoint for TOTP and yubikey OTP which is great.

The /wsapi/2.0/verify endpoint mimmick the behaviour of the yubico server.
We do not use it actively. It should™ work.
The only reason, privacyIDEA has this endpoint is, that there are clients out there (like pam_yubico), that expect this very endpoint.

However, we always used the endpoint /validate/check - if possible I recommend to use this one.

1 Like