"Wrong OTP" issue running in VM?

Stephen_Daniel · May 3, 2023, 4:56pm

Hello,

long time lurker, first time poster, been doing an eval on PrivacyIdea for about a week now and I’m sort of at my wits end.

Installation: Ubuntu packages on a VM running 20.06.4
Database: whatever is default with the packages… Sooo SQL?
Version: 3.8
Webserver: Apache

pi.cfg

import logging
# The realm, where users are allowed to login as administrators
SUPERUSER_REALM = ['super']
# Your database
#SQLALCHEMY_DATABASE_URI = 'sqlite:////etc/privacyidea/data.sqlite'
# This is used to encrypt the auth_token
#SECRET_KEY = 't0p s3cr3t'
# This is used to encrypt the admin passwords
#PI_PEPPER = "Never know..."
# This is used to encrypt the token data and token passwords
PI_ENCFILE = '/etc/privacyidea/enckey'
# This is used to sign the audit log
# This is the dummy base class
#PI_AUDIT_MODULE = 'privacyidea.lib.auditmodules.base'
# This is the default
#PI_AUDIT_MODULE = 'privacyidea.lib.auditmodules.sqlaudit'
# This is used to sign the audit log
PI_AUDIT_KEY_PRIVATE = '/etc/privacyidea/private.pem'
PI_AUDIT_KEY_PUBLIC = '/etc/privacyidea/public.pem'
PI_AUDIT_SQL_TRUNCATE = True
# The Class for managing the SQL connection pool
PI_ENGINE_REGISTRY_CLASS = "shared"
PI_AUDIT_POOL_SIZE = 20

PI_LOGFILE = '/var/log/privacyidea/privacyidea.log'
PI_LOGLEVEL = 10
PI_PEPPER = 'X_X'
SECRET_KEY = 'BLehh'
SQLALCHEMY_DATABASE_URI = 'mysql+pymysql://pi:fMz3t2xn_Kb2@localhost/pi?charset=utf8'

I have imported some Token2 OTPC-N classic TOTP Display cards (one of that model to be exact) via their generated seeds.

Long story short I am constantly getting errors on simply just testing the tokens with or without a pin… even with or without an assigned user.

I had made sure to have the VM sync time with my host and even configured some local NTP services to make sure there is no time issues.

I suppose the first question is if you can test out hardware tokens without any applied policy on the server, and if that is the case for me do I need a minimum policy config applied to simply just test this function?

I am honestly leaning more towards this than the linOTP atm, and if this requires a sort of “one off” support consultation I am fine to get that going as well.

Thanks

Stephen_Daniel · May 3, 2023, 5:01pm

here’s the log report and no worries if there are any keys inside, this is simply a eval instance and the associated token is a tester bought specifically for evals.

log output

cornelinux · May 4, 2023, 3:55am

Welcome to privacyIDEA.

(note: Your logfile is not accessable. Also take care to only paste the relevant part. Noone is eager to parse through thousand lines of logs)

With TOTP there are several degrees of freedom. If you are aware of these it is quite easy to debug.

correct time and offset
hash algorithm and seed length
time step
otp length

The mentioned card looks like a customized Feitian EPD card or a smartdisplayer card. The spec mention the details.

correct time and offset

You checked with NTP. You could also enroll smartphone totp app and thus verify that the server has the same time like the smartphone and thus probably the correct time and verify that totp basically words.

In regards to the offset you need to be aware of, that the hardware token has a cheap quartz clock and is very likely wrong. So you should try to “resync” the token or increase the time window of the token.

used hash

HMAC-SHA1 is usually OK. Some vendors think they need to do SHA256… The seed lenght should correspond the the hash algo. However, exceptions have been reported in the wild.

time step

Ensure that it is either 30 or 60 seconds.

otp length

Well, you see this directly.

Stephen_Daniel · May 4, 2023, 3:56pm

Cornelinux!

Thank you for the reply.

it would appear that my debug log triggered pastebin’s security features… (understandably so).

but what I would assume is the part of the log (set to DEBUG) is this part here…

where I attempt to test the token and the the OTP only.

this

section of log

[2023-05-04 11:48:13,513][6495][140680363525888][DEBUG][privacyidea.lib.token:181] Entering get_tokens_paginate with arguments () and keywords {'serial': '86270590145510', 'realm': None, 'page': 1, 'user': User(login='user', realm='test', resolver='myusers'), 'assigned': None, 'psize': 15, 'active': None, 'sortby': 'serial', 'sortdir': 'asc', 'tokentype': None, 'resolver': None, 'description': None, 'userid': None, 'allowed_realms': None, 'tokeninfo': None, 'rollout_state': None, 'hidden_tokeninfo': []}
[2023-05-04 11:48:13,520][6495][140680363525888][DEBUG][privacyidea.lib.token:181] Entering create_tokenclass_object with arguments (<<class 'privacyidea.models.Token'> {"'_sa_instance_state'": '<sqlalchemy.orm.state.InstanceState object at 0x7ff29f605940>', "'id'": '6', "'otplen'": '6', "'count'": '0', "'pin_hash'": "'$argon2id$v=19$m=65536,t=9,p=4$L4UwRggBQMgZw3iPkZIy5g$06t/mKPyPyvksaehv5dZwwlqQA8Jm7uMImlslmYDs1c'", "'count_window'": '10', "'key_enc'": "'82249232d56b8c9bcf3833c50147588aee8b2f35caddd337ef7eebd9706f3a3702d4dbfa049f4a78df0045b88e97b1b1590a02fe2f9a693cc97d62be55036e65'", "'sync_window'": '1000', "'description'": "'Token2'", "'key_iv'": "'8c00949e8cf6d955bbd049fc5c099656'", "'user_pin_iv'": "''", "'rollout_state'": "''", "'serial'": "'86270590145510'", "'maxfail'": '10', "'so_pin'": "''", "'tokentype'": "'totp'", "'active'": 'True', "'so_pin_iv'": "''", "'revoked'": 'False', "'user_pin'": "''", "'pin_seed'": "''", "'locked'": 'False', "'failcount'": '4'}>,) and keywords {}
[2023-05-04 11:48:13,520][6495][140680363525888][DEBUG][privacyidea.lib.tokens.totptoken:181] Entering __init__ with arguments (<<class 'privacyidea.lib.tokens.totptoken.TotpTokenClass'> {}>, <<class 'privacyidea.models.Token'> {"'_sa_instance_state'": '<sqlalchemy.orm.state.InstanceState object at 0x7ff29f605940>', "'id'": '6', "'otplen'": '6', "'count'": '0', "'pin_hash'": "'$argon2id$v=19$m=65536,t=9,p=4$L4UwRggBQMgZw3iPkZIy5g$06t/mKPyPyvksaehv5dZwwlqQA8Jm7uMImlslmYDs1c'", "'count_window'": '10', "'key_enc'": "'82249232d56b8c9bcf3833c50147588aee8b2f35caddd337ef7eebd9706f3a3702d4dbfa049f4a78df0045b88e97b1b1590a02fe2f9a693cc97d62be55036e65'", "'sync_window'": '1000', "'description'": "'Token2'", "'key_iv'": "'8c00949e8cf6d955bbd049fc5c099656'", "'user_pin_iv'": "''", "'rollout_state'": "''", "'serial'": "'86270590145510'", "'maxfail'": '10', "'so_pin'": "''", "'tokentype'": "'totp'", "'active'": 'True', "'so_pin_iv'": "''", "'revoked'": 'False', "'user_pin'": "''", "'pin_seed'": "''", "'locked'": 'False', "'failcount'": '4'}>) and keywords {}
[2023-05-04 11:48:13,521][6495][140680363525888][DEBUG][privacyidea.lib.tokenclass:181] Entering __init__ with arguments (<<class 'privacyidea.lib.tokens.totptoken.TotpTokenClass'> {}>, <<class 'privacyidea.models.Token'> {"'_sa_instance_state'": '<sqlalchemy.orm.state.InstanceState object at 0x7ff29f605940>', "'id'": '6', "'otplen'": '6', "'count'": '0', "'pin_hash'": "'$argon2id$v=19$m=65536,t=9,p=4$L4UwRggBQMgZw3iPkZIy5g$06t/mKPyPyvksaehv5dZwwlqQA8Jm7uMImlslmYDs1c'", "'count_window'": '10', "'key_enc'": "'82249232d56b8c9bcf3833c50147588aee8b2f35caddd337ef7eebd9706f3a3702d4dbfa049f4a78df0045b88e97b1b1590a02fe2f9a693cc97d62be55036e65'", "'sync_window'": '1000', "'description'": "'Token2'", "'key_iv'": "'8c00949e8cf6d955bbd049fc5c099656'", "'user_pin_iv'": "''", "'rollout_state'": "''", "'serial'": "'86270590145510'", "'maxfail'": '10', "'so_pin'": "''", "'tokentype'": "'totp'", "'active'": 'True', "'so_pin_iv'": "''", "'revoked'": 'False', "'user_pin'": "''", "'pin_seed'": "''", "'locked'": 'False', "'failcount'": '4'}>) and keywords {}
[2023-05-04 11:48:13,521][6495][140680363525888][DEBUG][privacyidea.lib.tokenclass:194] Exiting __init__ with result None
[2023-05-04 11:48:13,521][6495][140680363525888][DEBUG][privacyidea.lib.tokens.totptoken:194] Exiting __init__ with result None
[2023-05-04 11:48:13,521][6495][140680363525888][DEBUG][privacyidea.lib.token:194] Exiting create_tokenclass_object with result <<class 'privacyidea.lib.tokens.totptoken.TotpTokenClass'> {"'token'": '<<class \'privacyidea.models.Token\'> {"\'_sa_instance_state\'": \'<sqlalchemy.orm.state.InstanceState object at 0x7ff29f605940>\', "\'id\'": \'6\', "\'otplen\'": \'6\', "\'count\'": \'0\', "\'pin_hash\'": "\'$argon2id$v=19$m=65536,t=9,p=4$L4UwRggBQMgZw3iPkZIy5g$06t/mKPyPyvksaehv5dZwwlqQA8Jm7uMImlslmYDs1c\'", "\'count_window\'": \'10\', "\'key_enc\'": "\'82249232d56b8c9bcf3833c50147588aee8b2f35caddd337ef7eebd9706f3a3702d4dbfa049f4a78df0045b88e97b1b1590a02fe2f9a693cc97d62be55036e65\'", "\'sync_window\'": \'1000\', "\'description\'": "\'Token2\'", "\'key_iv\'": "\'8c00949e8cf6d955bbd049fc5c099656\'", "\'user_pin_iv\'": "\'\'", "\'rollout_state\'": "\'\'", "\'serial\'": "\'86270590145510\'", "\'maxfail\'": \'10\', "\'so_pin\'": "\'\'", "\'tokentype\'": "\'totp\'", "\'active\'": \'True\', "\'so_pin_iv\'": "\'\'", "\'revoked\'": \'False\', "\'user_pin\'": "\'\'", "\'pin_seed\'": "\'\'", "\'locked\'": \'False\', "\'failcount\'": \'4\'}>', "'type'": "'totp'", "'init_details'": '{}', "'auth_details'": '{}', "'hKeyRequired'": 'True'}>
[2023-05-04 11:48:13,522][6495][140680363525888][DEBUG][privacyidea.models:181] Entering get with arguments (<<class 'privacyidea.models.Token'> {"'_sa_instance_state'": '<sqlalchemy.orm.state.InstanceState object at 0x7ff29f605940>', "'id'": '6', "'otplen'": '6', "'count'": '0', "'pin_hash'": "'$argon2id$v=19$m=65536,t=9,p=4$L4UwRggBQMgZw3iPkZIy5g$06t/mKPyPyvksaehv5dZwwlqQA8Jm7uMImlslmYDs1c'", "'count_window'": '10', "'key_enc'": "'82249232d56b8c9bcf3833c50147588aee8b2f35caddd337ef7eebd9706f3a3702d4dbfa049f4a78df0045b88e97b1b1590a02fe2f9a693cc97d62be55036e65'", "'sync_window'": '1000', "'description'": "'Token2'", "'key_iv'": "'8c00949e8cf6d955bbd049fc5c099656'", "'user_pin_iv'": "''", "'rollout_state'": "''", "'serial'": "'86270590145510'", "'maxfail'": '10', "'so_pin'": "''", "'tokentype'": "'totp'", "'active'": 'True', "'so_pin_iv'": "''", "'revoked'": 'False', "'user_pin'": "''", "'pin_seed'": "''", "'locked'": 'False', "'failcount'": '4'}>,) and keywords {}
[2023-05-04 11:48:13,522][6495][140680363525888][DEBUG][privacyidea.models:181] Entering get_vars with arguments (<<class 'privacyidea.models.Token'> {"'_sa_instance_state'": '<sqlalchemy.orm.state.InstanceState object at 0x7ff29f605940>', "'id'": '6', "'otplen'": '6', "'count'": '0', "'pin_hash'": "'$argon2id$v=19$m=65536,t=9,p=4$L4UwRggBQMgZw3iPkZIy5g$06t/mKPyPyvksaehv5dZwwlqQA8Jm7uMImlslmYDs1c'", "'count_window'": '10', "'key_enc'": "'82249232d56b8c9bcf3833c50147588aee8b2f35caddd337ef7eebd9706f3a3702d4dbfa049f4a78df0045b88e97b1b1590a02fe2f9a693cc97d62be55036e65'", "'sync_window'": '1000', "'description'": "'Token2'", "'key_iv'": "'8c00949e8cf6d955bbd049fc5c099656'", "'user_pin_iv'": "''", "'rollout_state'": "''", "'serial'": "'86270590145510'", "'maxfail'": '10', "'so_pin'": "''", "'tokentype'": "'totp'", "'active'": 'True', "'so_pin_iv'": "''", "'revoked'": 'False', "'user_pin'": "''", "'pin_seed'": "''", "'locked'": 'False', "'failcount'": '4'}>,) and keywords {'save': False}
[2023-05-04 11:48:13,522][6495][140680363525888][DEBUG][privacyidea.models:560] get_vars()
[2023-05-04 11:48:13,527][6495][140680363525888][DEBUG][privacyidea.models:194] Exiting get_vars with result {'id': 6, 'description': 'Token2', 'serial': '86270590145510', 'tokentype': 'totp', 'info': {'count_auth': '21', 'hashlib': 'sha1', 'timeShift': '0.0', 'timeStep': '30', 'timeWindow': '180', 'tokenkind': 'hardware'}, 'resolver': 'myusers', 'user_id': '1000', 'otplen': 6, 'maxfail': 10, 'active': True, 'revoked': False, 'locked': False, 'failcount': 4, 'count': 0, 'count_window': 10, 'sync_window': 1000, 'rollout_state': '', 'realms': ['test'], 'tokengroup': []}
[2023-05-04 11:48:13,527][6495][140680363525888][DEBUG][privacyidea.models:194] Exiting get with result {'id': 6, 'description': 'Token2', 'serial': '86270590145510', 'tokentype': 'totp', 'info': {'count_auth': '21', 'hashlib': 'sha1', 'timeShift': '0.0', 'timeStep': '30', 'timeWindow': '180', 'tokenkind': 'hardware'}, 'resolver': 'myusers', 'user_id': '1000', 'otplen': 6, 'maxfail': 10, 'active': True, 'revoked': False, 'locked': False, 'failcount': 4, 'count': 0, 'count_window': 10, 'sync_window': 1000, 'rollout_state': '', 'realms': ['test'], 'tokengroup': []}
[2023-05-04 11:48:13,529][6495][140680363525888][DEBUG][privacyidea.lib.user:181] Entering get_username with arguments ('1000', 'myusers') and keywords {}
[2023-05-04 11:48:13,529][6495][140680363525888][DEBUG][privacyidea.lib.config:181] Entering get_from_config with arguments ('UserCacheExpiration', '0') and keywords {}
[2023-05-04 11:48:13,529][6495][140680363525888][DEBUG][privacyidea.lib.config:194] Exiting get_from_config with result 0
[2023-05-04 11:48:13,529][6495][140680363525888][DEBUG][privacyidea.lib.resolver:181] Entering get_resolver_object with arguments ('myusers',) and keywords {}
[2023-05-04 11:48:13,529][6495][140680363525888][DEBUG][privacyidea.lib.resolver:181] Entering get_resolver_list with arguments () and keywords {'filter_resolver_name': 'myusers'}
[2023-05-04 11:48:13,530][6495][140680363525888][DEBUG][privacyidea.lib.resolver:196] Exiting get_resolver_list with result HIDDEN
[2023-05-04 11:48:13,530][6495][140680363525888][DEBUG][privacyidea.lib.resolver:194] Exiting get_resolver_object with result <privacyidea.lib.resolvers.PasswdIdResolver.IdResolver object at 0x7ff2a4a1e490>
[2023-05-04 11:48:13,530][6495][140680363525888][DEBUG][privacyidea.lib.user:194] Exiting get_username with result user
[2023-05-04 11:48:13,530][6495][140680363525888][DEBUG][privacyidea.lib.user:181] Entering __init__ with arguments (User(login='', realm='', resolver=''),) and keywords {'login': 'user', 'resolver': 'myusers', 'realm': 'test'}
[2023-05-04 11:48:13,530][6495][140680363525888][DEBUG][privacyidea.lib.config:181] Entering get_from_config with arguments ('UserCacheExpiration', '0') and keywords {}
[2023-05-04 11:48:13,530][6495][140680363525888][DEBUG][privacyidea.lib.config:194] Exiting get_from_config with result 0
[2023-05-04 11:48:13,530][6495][140680363525888][DEBUG][privacyidea.lib.resolver:181] Entering get_resolver_object with arguments ('myusers',) and keywords {}
[2023-05-04 11:48:13,530][6495][140680363525888][DEBUG][privacyidea.lib.resolver:181] Entering get_resolver_list with arguments () and keywords {'filter_resolver_name': 'myusers'}
[2023-05-04 11:48:13,531][6495][140680363525888][DEBUG][privacyidea.lib.resolver:196] Exiting get_resolver_list with result HIDDEN
[2023-05-04 11:48:13,531][6495][140680363525888][DEBUG][privacyidea.lib.resolver:194] Exiting get_resolver_object with result <privacyidea.lib.resolvers.PasswdIdResolver.IdResolver object at 0x7ff2a4a1e490>
[2023-05-04 11:48:13,531][6495][140680363525888][DEBUG][privacyidea.lib.resolver:181] Entering get_resolver_list with arguments () and keywords {'filter_resolver_name': 'myusers'}
[2023-05-04 11:48:13,531][6495][140680363525888][DEBUG][privacyidea.lib.resolver:196] Exiting get_resolver_list with result HIDDEN
[2023-05-04 11:48:13,531][6495][140680363525888][DEBUG][privacyidea.lib.user:194] Exiting __init__ with result None
[2023-05-04 11:48:13,531][6495][140680363525888][DEBUG][privacyidea.lib.resolver:181] Entering get_resolver_object with arguments ('myusers',) and keywords {}
[2023-05-04 11:48:13,531][6495][140680363525888][DEBUG][privacyidea.lib.resolver:181] Entering get_resolver_list with arguments () and keywords {'filter_resolver_name': 'myusers'}
[2023-05-04 11:48:13,531][6495][140680363525888][DEBUG][privacyidea.lib.resolver:196] Exiting get_resolver_list with result HIDDEN
[2023-05-04 11:48:13,532][6495][140680363525888][DEBUG][privacyidea.lib.resolver:194] Exiting get_resolver_object with result <privacyidea.lib.resolvers.PasswdIdResolver.IdResolver object at 0x7ff2a4a1e490>
[2023-05-04 11:48:13,532][6495][140680363525888][DEBUG][privacyidea.lib.token:194] Exiting get_tokens_paginate with result {'tokens': [{'id': 6, 'description': 'Token2', 'serial': '86270590145510', 'tokentype': 'totp', 'info': {'count_auth': '21', 'hashlib': 'sha1', 'timeShift': '0.0', 'timeStep': '30', 'timeWindow': '180', 'tokenkind': 'hardware'}, 'resolver': 'myusers', 'user_id': '1000', 'otplen': 6, 'maxfail': 10, 'active': True, 'revoked': False, 'locked': False, 'failcount': 4, 'count': 0, 'count_window': 10, 'sync_window': 1000, 'rollout_state': '', 'realms': ['test'], 'tokengroup': [], 'username': 'user', 'user_realm': 'test', 'user_editable': False}], 'prev': None, 'next': None, 'current': 1, 'count': 1}
[2023-05-04 11:48:13,532][6495][140680363525888][DEBUG][privacyidea.lib.auditmodules.base:181] Entering log with arguments (<privacyidea.lib.auditmodules.sqlaudit.Audit object at 0x7ff29f668e80>, {'success': True}) and keywords {}
[2023-05-04 11:48:13,532][6495][140680363525888][DEBUG][privacyidea.lib.auditmodules.base:194] Exiting log with result None
[2023-05-04 11:48:13,534][6495][140680363525888][DEBUG][privacyidea.api.token:194] Exiting list_api with result <PiResponseClass 674 bytes [200 OK]>
[2023-05-04 11:48:13,571][6495][140680363525888][DEBUG][privacyidea.api.lib.utils:286] Update params in request GET https://192.168.4.165/token/ with values.
[2023-05-04 11:48:13,600][6495][140680363525888][DEBUG][privacyidea.api.before_after:102] End handling of request '/token/?serial=86270590145510'

is this just the result of the web UI thinking it’s failing? that last few lines tell me that the check was successful?

also confirmed that my google authenticator app works fine.

Thanks again.

Stephen_Daniel · May 4, 2023, 5:56pm

okay, after an hour or so obsessing over the logs… I found that my issue was how the tokens were imported to begin with.

I was importing a PSKC XML format at first from the token2 website.

long story short I had multiple seeds generated for all the options they had listed. apparently everytime I tried importing the “PrivacyIdea CSV” I noticed the file was empty. up until just now when I got a new CSV from token2 generated. (this time distributed via a password zip… I know).

after importing the cards now work just fine -_-

I appreciate the time you gave to this issue so far.

now onto keycloak integration…

Cheers