Hi Guys,
I’m having a problem that Is driving me crazy.
My current environment is :
VPN Firewall ( PALO Alto ) -> Freeradius ( part of Privacy ID3a) - > Privacy ID3a.
I’m running Ubuntu 16, and got the packages from the PPA repo.
My current user resolver is using LDAP. I also have 2 policies assigned:
1- Authentication policy: { “reset_all_user_tokens”: true, “otppin”: “userstore” }
2- webui { “default_tokentype”: “totp”, “tokenwizard”: true }
I’m having a very weird problem.
When I try to connect to the VPN, using my AD password followed by the OTP ( have tried HOTP and TOTP), the authentication fails, then If I try to retype the PASS+NEW OTP the authentication is successfully done.
I’m 100% sure that the OTP code is correct.
By checking the logs I got some useful information:
[WARNING][privacyidea.lib.tokens.totptoken:327] a previous OTP value was used again! former tokencounter: 50142381, presented counter 5014238
By checking the audit logs I can see:
9/1/17 13:59:41 POST /validate/check success: 1 matching 1 tokens
Then just a second later :
9/1/17 13:59:42 POST /validate/check success:0 wrong otp value. previous otp used again
As you can see, 1 second is not enough time to any user interaction.
I’ve enabled the debug mode, please find the sequence of events below:
[2017-09-01 14:10:59,726][1796][140669225772928][DEBUG][privacyidea.lib.resolver:197] Exiting get_resolver_object with result [2017-09-01 14:10:59,729][1796][140669225772928][DEBUG][privacyidea.lib.resolvers.LDAPIdResolver:692] Added SERVERXXXXXXXXX, None, False to server pool. [2017-09-01 14:10:59,730][1796][140669225772928][DEBUG][privacyidea.lib.resolvers.LDAPIdResolver:692] Added SERVERXXXXXXXXX, None, False to server pool. [2017-09-01 14:10:59,730][1796][140669225772928][DEBUG][privacyidea.lib.resolvers.LDAPIdResolver:232] Authtype: u'Simple' [2017-09-01 14:10:59,730][1796][140669225772928][DEBUG][privacyidea.lib.resolvers.LDAPIdResolver:233] user : u'CN=NAME ,OU=IT_Infrastructure,OU=XX,OU=Users,OU=Managed,DC=XX,DC=XXXXXX' [2017-09-01 14:10:59,732][1796][140669225772928][DEBUG][privacyidea.lib.resolvers.LDAPIdResolver:1061] Doing start_tls [2017-09-01 14:10:59,744][1796][140669225772928][DEBUG][privacyidea.lib.resolvers.LDAPIdResolver:246] bind result: True [2017-09-01 14:10:59,744][1796][140669225772928][DEBUG][privacyidea.lib.resolvers.LDAPIdResolver:249] bind seems successful. [2017-09-01 14:10:59,745][1796][140669225772928][DEBUG][privacyidea.lib.resolvers.LDAPIdResolver:251] unbind successful. [2017-09-01 14:10:59,745][1796][140669225772928][DEBUG][privacyidea.lib.user:357] Successfully authenticated user User(login=u'XXXXX', realm=u'XXXXX', resolver=u'XXXXXX'). [2017-09-01 14:10:59,745][1796][140669225772928][DEBUG][privacyidea.lib.user:197] Exiting check_password with result XXXXXX@XXXXX [2017-09-01 14:10:59,745][1796][140669225772928][DEBUG][privacyidea.models:185] Entering get_otpkey with arguments (< {"'active'": 'True', "'count_window'": '10', "'key_enc'": "u'2f761aae9910d73b6acf0d08f8e3245b572b9090012cd5ba28eb58c2ad428994d13d197662175109bf95d59d9ba33949d4c58a0d5d3a418c066d2bcfd4d7bfc739adae474dd53df16dc66be36d71e2c3f306ce73229085e402cbf9f0c5b75b17'", "'pin_hash'": "u''", "'so_pin'": "u''", "'user_id'": "u'fe32db86-fdf9-4e10-b156-56970ff18a9d'", "'otplen'": '6', "'so_pin_iv'": "u''", "'serial'": "u'TOTP0000ED13'", "'revoked'": 'False', "'locked'": 'False', "'maxfail'": '5', "'realm_list'": '[]', "'count'": '50142381', "'pin_seed'": "u''", "'sync_window'": '1000', "'description'": "u''", "'resolver_type'": "u'ldapresolver'", "'user_pin_iv'": "u''", "'user_pin'": "u''", "'rollout_state'": "u''", "'failcount'": '0', "'_sa_instance_state'": '', "'id'": '11', "'resolver'": "u'XXXXXXX'", "'key_iv'": "u'd31ecaef21031d55a82063224dae1e3a'", "'tokentype'": "u'totp'"}>,) and keywords {} [2017-09-01 14:10:59,746][1796][140669225772928][DEBUG][privacyidea.models:197] Exiting get_otpkey with result [2017-09-01 14:10:59,749][1796][140669225772928][DEBUG][privacyidea.lib.tokens.HMAC:185] Entering checkOtp with arguments (, u'755782', 6) and keywords {'symetric': True} [2017-09-01 14:10:59,749][1796][140669225772928][DEBUG][privacyidea.lib.tokens.HMAC:145] OTP range counter: 50142375 - 50142387 [2017-09-01 14:10:59,749][1796][140669225772928][DEBUG][privacyidea.lib.crypto:185] Entering decrypt with arguments ('/v\x1a\xae\x99\x10\xd7;j\xcf\r\x08\xf8\xe3$[W+\x90\x90\x01,\xd5\xba(\xebX\xc2\xadB\x89\x94\xd1=\x19vb\x17Q\t\xbf\x95\xd5\x9d\x9b\xa39I\xd4\xc5\x8a\r]:A\x8c\x06m+\xcf\xd4\xd7\xbf\xc79\xad\xaeGM\xd5=\xf1m\xc6k\xe3mq\xe2\xc3\xf3\x06\xces"\x90\x85\xe4\x02\xcb\xf9\xf0\xc5\xb7[\x17', '\xd3\x1e\xca\xef!\x03\x1dU\xa8 c"M\xae\x1e:') and keywords {} [2017-09-01 14:10:59,749][1796][140669225772928][DEBUG][privacyidea.lib.crypto:199] Exiting decrypt with result HIDDEN [2017-09-01 14:10:59,750][1796][140669225772928][DEBUG][privacyidea.lib.tokens.HMAC:197] Exiting checkOtp with result 50142381 [2017-09-01 14:10:59,750][1796][140669225772928][WARNING][privacyidea.lib.tokens.totptoken:327] a previous OTP value was used again! former tokencounter: 50142381, presented counter 50142381
I’ve also tried to enable the PIN and change the auth policy parameter called otppin from userstore to tokenpin. It has exactly the same behaviour. - First attempt fails, second attempt works
Does anyone here experienced something like this ?
Thank you very much
Renato