Authentication ldap

Mohammed · July 21, 2022, 3:43pm

I have configured two-factor authentication using ldap. It was working fine until yesterday and i could’t figure out the RC of this issue. I added the debug log and i hope someone could help


[2022-07-21 17:20:54,400][17670][140108103038720][DEBUG][privacyidea.lib.config:72] The singleton <class 'privacyidea.lib.config.ConfigClass'> already exists.
[2022-07-21 17:20:54,403][17670][140108103038720][DEBUG][privacyidea.api.lib.utils:245] Can not get param: No JSON object could be decoded
[2022-07-21 17:20:54,404][17670][140108103038720][DEBUG][privacyidea.lib.user:185] Entering get_user_from_param with arguments ({'realm': u'', 'user': u'', 'pass': u''},) and keywords {}
[2022-07-21 17:20:54,404][17670][140108103038720][DEBUG][privacyidea.lib.config:185] Entering get_from_config with arguments ('splitAtSign',) and keywords {'default': False, 'return_bool': True}
[2022-07-21 17:20:54,404][17670][140108103038720][DEBUG][privacyidea.lib.config:72] The singleton <class 'privacyidea.lib.config.ConfigClass'> already exists.
[2022-07-21 17:20:54,406][17670][140108103038720][DEBUG][privacyidea.lib.config:197] Exiting get_from_config with result True
[2022-07-21 17:20:54,406][17670][140108103038720][DEBUG][privacyidea.lib.user:185] Entering split_user with arguments (u'',) and keywords {}
[2022-07-21 17:20:54,406][17670][140108103038720][DEBUG][privacyidea.lib.user:197] Exiting split_user with result (u'', '')
[2022-07-21 17:20:54,406][17670][140108103038720][DEBUG][privacyidea.lib.realm:185] Entering get_default_realm with arguments () and keywords {}
[2022-07-21 17:20:54,406][17670][140108103038720][DEBUG][privacyidea.lib.config:72] The singleton <class 'privacyidea.lib.config.ConfigClass'> already exists.
[2022-07-21 17:20:54,408][17670][140108103038720][DEBUG][privacyidea.lib.realm:197] Exiting get_default_realm with result com1
[2022-07-21 17:20:54,409][17670][140108103038720][DEBUG][privacyidea.lib.user:185] Entering User with arguments () and keywords {'login': u'', 'realm': u'com1', 'resolver': None}
[2022-07-21 17:20:54,409][17670][140108103038720][DEBUG][privacyidea.lib.config:185] Entering get_from_config with arguments ('UserCacheExpiration', '0') and keywords {}
[2022-07-21 17:20:54,409][17670][140108103038720][DEBUG][privacyidea.lib.config:72] The singleton <class 'privacyidea.lib.config.ConfigClass'> already exists.
[2022-07-21 17:20:54,411][17670][140108103038720][DEBUG][privacyidea.lib.config:197] Exiting get_from_config with result 0
[2022-07-21 17:20:54,411][17670][140108103038720][DEBUG][privacyidea.lib.user:185] Entering get_ordererd_resolvers with arguments (User(login=u'', realm=u'com1', resolver=''),) and keywords {}
[2022-07-21 17:20:54,411][17670][140108103038720][DEBUG][privacyidea.lib.realm:185] Entering get_realms with arguments (u'com1',) and keywords {}
[2022-07-21 17:20:54,411][17670][140108103038720][DEBUG][privacyidea.lib.config:72] The singleton <class 'privacyidea.lib.config.ConfigClass'> already exists.
[2022-07-21 17:20:54,413][17670][140108103038720][DEBUG][privacyidea.lib.realm:197] Exiting get_realms with result {u'com1': {'default': True, 'option': u'', 'resolver': [{'priority': 1L, 'type': u'ldapresolver', 'name': u'COM1'}]}}
[2022-07-21 17:20:54,413][17670][140108103038720][DEBUG][privacyidea.lib.user:197] Exiting get_ordererd_resolvers with result [u'COM1']
[2022-07-21 17:20:54,414][17670][140108103038720][DEBUG][privacyidea.lib.resolver:185] Entering get_resolver_object with arguments (u'COM1',) and keywords {}
[2022-07-21 17:20:54,414][17670][140108103038720][DEBUG][privacyidea.lib.resolver:185] Entering get_resolver_list with arguments () and keywords {'filter_resolver_name': u'COM1'}
[2022-07-21 17:20:54,414][17670][140108103038720][DEBUG][privacyidea.lib.config:72] The singleton <class 'privacyidea.lib.config.ConfigClass'> already exists.
[2022-07-21 17:20:54,416][17670][140108103038720][DEBUG][privacyidea.lib.resolver:199] Exiting get_resolver_list with result HIDDEN
[2022-07-21 17:20:54,416][17670][140108103038720][DEBUG][privacyidea.lib.config:185] Entering get_resolver_list with arguments () and keywords {}
[2022-07-21 17:20:54,416][17670][140108103038720][DEBUG][privacyidea.lib.config:549] None
[2022-07-21 17:20:54,416][17670][140108103038720][DEBUG][privacyidea.lib.config:197] Exiting get_resolver_list with result set(['privacyidea.lib.resolvers.PasswdIdResolver', 'privacyidea.lib.resolvers.SCIMIdResolver', 'privacyidea.lib.resolvers.SQLIdResolver', 'privacyidea.lib.resolvers.LDAPIdResolver'])
[2022-07-21 17:20:54,416][17670][140108103038720][DEBUG][privacyidea.lib.config:682] using the module list: set(['privacyidea.lib.resolvers.PasswdIdResolver', 'privacyidea.lib.resolvers.SCIMIdResolver', 'privacyidea.lib.resolvers.SQLIdResolver', 'privacyidea.lib.resolvers.LDAPIdResolver'])
[2022-07-21 17:20:54,416][17670][140108103038720][DEBUG][privacyidea.lib.config:690] import module: privacyidea.lib.resolvers.PasswdIdResolver
[2022-07-21 17:20:54,416][17670][140108103038720][DEBUG][privacyidea.lib.config:690] import module: privacyidea.lib.resolvers.SCIMIdResolver
[2022-07-21 17:20:54,416][17670][140108103038720][DEBUG][privacyidea.lib.config:690] import module: privacyidea.lib.resolvers.SQLIdResolver
[2022-07-21 17:20:54,416][17670][140108103038720][DEBUG][privacyidea.lib.config:690] import module: privacyidea.lib.resolvers.LDAPIdResolver
[2022-07-21 17:20:54,417][17670][140108103038720][DEBUG][privacyidea.lib.config:503] module: <module 'privacyidea.lib.resolvers.PasswdIdResolver' from '/opt/privacyIDEA/lib/python2.7/site-packages/privacyidea/lib/resolvers/PasswdIdResolver.pyc'>
[2022-07-21 17:20:54,417][17670][140108103038720][DEBUG][privacyidea.lib.config:503] module: <module 'privacyidea.lib.resolvers.SCIMIdResolver' from '/opt/privacyIDEA/lib/python2.7/site-packages/privacyidea/lib/resolvers/SCIMIdResolver.pyc'>
[2022-07-21 17:20:54,417][17670][140108103038720][DEBUG][privacyidea.lib.config:503] module: <module 'privacyidea.lib.resolvers.SQLIdResolver' from '/opt/privacyIDEA/lib/python2.7/site-packages/privacyidea/lib/resolvers/SQLIdResolver.pyc'>
[2022-07-21 17:20:54,417][17670][140108103038720][DEBUG][privacyidea.lib.config:503] module: <module 'privacyidea.lib.resolvers.LDAPIdResolver' from '/opt/privacyIDEA/lib/python2.7/site-packages/privacyidea/lib/resolvers/LDAPIdResolver.pyc'>
[2022-07-21 17:20:54,417][17670][140108103038720][DEBUG][privacyidea.lib.resolver:185] Entering get_resolver_config with arguments (u'COM1',) and keywords {}
[2022-07-21 17:20:54,417][17670][140108103038720][DEBUG][privacyidea.lib.resolver:185] Entering get_resolver_list with arguments () and keywords {'filter_resolver_name': u'COM1'}
[2022-07-21 17:20:54,417][17670][140108103038720][DEBUG][privacyidea.lib.config:72] The singleton <class 'privacyidea.lib.config.ConfigClass'> already exists.
[2022-07-21 17:20:54,419][17670][140108103038720][DEBUG][privacyidea.lib.resolver:199] Exiting get_resolver_list with result HIDDEN
[2022-07-21 17:20:54,419][17670][140108103038720][DEBUG][privacyidea.lib.resolver:199] Exiting get_resolver_config with result HIDDEN
[2022-07-21 17:20:54,421][17670][140108103038720][DEBUG][privacyidea.lib.resolvers.LDAPIdResolver:141] Get LDAP schema info: 'SCHEMA'
[2022-07-21 17:20:54,421][17670][140108103038720][DEBUG][privacyidea.lib.resolver:197] Exiting get_resolver_object with result <privacyidea.lib.resolvers.LDAPIdResolver.IdResolver object at 0x7f6d56d04450>
[2022-07-21 17:20:54,422][17670][140108103038720][DEBUG][privacyidea.lib.resolvers.LDAPIdResolver:783] Added ldap.com1.nl, None, False to server pool.
[2022-07-21 17:20:54,651][17670][140108103038720][DEBUG][privacyidea.lib.resolvers.LDAPIdResolver:539] login name filter: u'uid='
[2022-07-21 17:20:54,651][17670][140108103038720][DEBUG][privacyidea.lib.resolvers.LDAPIdResolver:547] Searching user u'' in LDAP.
[2022-07-21 17:20:54,655][17670][140108103038720][INFO][privacyidea.lib.user:230] user u'' found in resolver u'COM1'
[2022-07-21 17:20:54,655][17670][140108103038720][INFO][privacyidea.lib.user:231] userid resolved to u'uid=,ou=com1,dc=com1,dc=nl' 
[2022-07-21 17:20:54,655][17670][140108103038720][DEBUG][privacyidea.lib.resolver:185] Entering get_resolver_object with arguments (u'COM1',) and keywords {}
[2022-07-21 17:20:54,655][17670][140108103038720][DEBUG][privacyidea.lib.resolver:185] Entering get_resolver_list with arguments () and keywords {'filter_resolver_name': u'COM1'}
[2022-07-21 17:20:54,655][17670][140108103038720][DEBUG][privacyidea.lib.config:72] The singleton <class 'privacyidea.lib.config.ConfigClass'> already exists.
[2022-07-21 17:20:54,658][17670][140108103038720][DEBUG][privacyidea.lib.resolver:199] Exiting get_resolver_list with result HIDDEN
[2022-07-21 17:20:54,658][17670][140108103038720][DEBUG][privacyidea.lib.config:185] Entering get_resolver_list with arguments () and keywords {}
[2022-07-21 17:20:54,658][17670][140108103038720][DEBUG][privacyidea.lib.config:549] None
[2022-07-21 17:20:54,658][17670][140108103038720][DEBUG][privacyidea.lib.config:197] Exiting get_resolver_list with result set(['privacyidea.lib.resolvers.PasswdIdResolver', 'privacyidea.lib.resolvers.SCIMIdResolver', 'privacyidea.lib.resolvers.SQLIdResolver', 'privacyidea.lib.resolvers.LDAPIdResolver'])
[2022-07-21 17:20:54,658][17670][140108103038720][DEBUG][privacyidea.lib.config:682] using the module list: set(['privacyidea.lib.resolvers.PasswdIdResolver', 'privacyidea.lib.resolvers.SCIMIdResolver', 'privacyidea.lib.resolvers.SQLIdResolver', 'privacyidea.lib.resolvers.LDAPIdResolver'])
[2022-07-21 17:20:54,658][17670][140108103038720][DEBUG][privacyidea.lib.config:690] import module: privacyidea.lib.resolvers.PasswdIdResolver
[2022-07-21 17:20:54,658][17670][140108103038720][DEBUG][privacyidea.lib.config:690] import module: privacyidea.lib.resolvers.SCIMIdResolver
[2022-07-21 17:20:54,658][17670][140108103038720][DEBUG][privacyidea.lib.config:690] import module: privacyidea.lib.resolvers.SQLIdResolver
[2022-07-21 17:20:54,658][17670][140108103038720][DEBUG][privacyidea.lib.config:690] import module: privacyidea.lib.resolvers.LDAPIdResolver
[2022-07-21 17:20:54,658][17670][140108103038720][DEBUG][privacyidea.lib.config:503] module: <module 'privacyidea.lib.resolvers.PasswdIdResolver' from '/opt/privacyIDEA/lib/python2.7/site-packages/privacyidea/lib/resolvers/PasswdIdResolver.pyc'>
[2022-07-21 17:20:54,659][17670][140108103038720][DEBUG][privacyidea.lib.config:503] module: <module 'privacyidea.lib.resolvers.SCIMIdResolver' from '/opt/privacyIDEA/lib/python2.7/site-packages/privacyidea/lib/resolvers/SCIMIdResolver.pyc'>
[2022-07-21 17:20:54,659][17670][140108103038720][DEBUG][privacyidea.lib.config:503] module: <module 'privacyidea.lib.resolvers.SQLIdResolver' from '/opt/privacyIDEA/lib/python2.7/site-packages/privacyidea/lib/resolvers/SQLIdResolver.pyc'>
[2022-07-21 17:20:54,659][17670][140108103038720][DEBUG][privacyidea.lib.config:503] module: <module 'privacyidea.lib.resolvers.LDAPIdResolver' from '/opt/privacyIDEA/lib/python2.7/site-packages/privacyidea/lib/resolvers/LDAPIdResolver.pyc'>
[2022-07-21 17:20:54,659][17670][140108103038720][DEBUG][privacyidea.lib.resolver:197] Exiting get_resolver_object with result <privacyidea.lib.resolvers.LDAPIdResolver.IdResolver object at 0x7f6d56d04450>
[2022-07-21 17:20:54,659][17670][140108103038720][DEBUG][privacyidea.lib.resolvers.LDAPIdResolver:205] Reading u'' from cache for 'getUserId'
[2022-07-21 17:20:54,659][17670][140108103038720][DEBUG][privacyidea.lib.resolver:185] Entering get_resolver_list with arguments () and keywords {'filter_resolver_name': u'COM1'}
[2022-07-21 17:20:54,659][17670][140108103038720][DEBUG][privacyidea.lib.config:72] The singleton <class 'privacyidea.lib.config.ConfigClass'> already exists.
[2022-07-21 17:20:54,662][17670][140108103038720][DEBUG][privacyidea.lib.resolver:199] Exiting get_resolver_list with result HIDDEN
[2022-07-21 17:20:54,662][17670][140108103038720][DEBUG][privacyidea.lib.user:197] Exiting User with result <.COM1@com1>
[2022-07-21 17:20:54,662][17670][140108103038720][DEBUG][privacyidea.lib.user:197] Exiting get_user_from_param with result <.COM1@com1>
[2022-07-21 17:20:54,662][17670][140108103038720][DEBUG][privacyidea.lib.config:72] The singleton <class 'privacyidea.lib.policy.PolicyClass'> already exists.
[2022-07-21 17:20:54,664][17670][140108103038720][DEBUG][privacyidea.lib.audit:185] Entering getAudit with arguments (<Config {'JSON_AS_ASCII': True, 'PI_HSM': 'default', 'PI_LOGFILE': '/var/log/privacyidea/privacyidea.log', 'pi_hsm': {'obj': <privacyidea.lib.security.default.DefaultSecurityModule object at 0x7f6d572e6510>}, 'PI_AUDIT_KEY_PUBLIC': '/etc/privacyidea/public.pem', 'SQLALCHEMY_POOL_RECYCLE': None, 'SQLALCHEMY_ECHO': False, 'PI_PEPPER': "q%X7j=T%q+PGtE'&", 'SQLALCHEMY_TRACK_MODIFICATIONS': True, 'PI_AUDIT_SQL_TRUNCATE': True, 'SQLALCHEMY_POOL_TIMEOUT': None, 'SQLALCHEMY_RECORD_QUERIES': None, 'PI_ENCFILE': '/etc/privacyidea/enckey', 'SESSION_COOKIE_DOMAIN': None, 'SESSION_COOKIE_NAME': 'session', 'pi_token_types': ['registration', 'hotp', 'pw', 'spass', 'paper', 'sms', 'email', 'sshkey', 'radius', 'yubico', 'motp', 'daplug', 'vasco', 'remote', 'certificate', 'tiqr', 'ocra', '4eyes', 'totp', 'u2f', 'yubikey', 'question'], 'PI_EXTERNAL_LINKS': True, 'SQLALCHEMY_NATIVE_UNICODE': None, 'MAX_CONTENT_LENGTH': None, 'PERMANENT_SESSION_LIFETIME': datetime.timedelta(31), 'SQLALCHEMY_POOL_SIZE': None, 'SQLALCHEMY_MAX_OVERFLOW': None, 'TRAP_HTTP_EXCEPTIONS': False, 'PRESERVE_CONTEXT_ON_EXCEPTION': None, 'SESSION_COOKIE_PATH': None, 'SQLALCHEMY_DATABASE_URI': 'mysql://privacyidea:-Gm6/(c3.;Kg8@2fa.db.com1.local/privacyidea?ssl_key=/etc/privacyidea-ldap-proxy/ssl/client-key.pem&ssl_cert=/etc/privacyidea-ldap-proxy/ssl/client-cert.pem', 'LOGGER_NAME': 'privacyidea.app', 'SECRET_KEY': 'L>Ph=Q\\ZhfLB8nV4', 'APPLICATION_ROOT': None, 'SERVER_NAME': None, 'BABEL_DEFAULT_LOCALE': 'en', 'PREFERRED_URL_SCHEME': 'http', 'TESTING': False, 'BABEL_DEFAULT_TIMEZONE': 'UTC', 'PI_VASCO_LIBRARY': None, 'USE_X_SENDFILE': False, 'PI_AUDIT_MODULE': 'privacyidea.lib.auditmodules.sqlaudit', 'SESSION_COOKIE_SECURE': False, 'SQLALCHEMY_BINDS': None, 'DEBUG': False, 'SQLALCHEMY_COMMIT_ON_TEARDOWN': False, 'CACHE_TYPE': 'simple', 'JSONIFY_PRETTYPRINT_REGULAR': True, 'PROPAGATE_EXCEPTIONS': None, 'PI_LOGLEVEL': 10, 'TRAP_BAD_REQUEST_ERRORS': False, 'JSON_SORT_KEYS': True, 'SESSION_COOKIE_HTTPONLY': True, 'SEND_FILE_MAX_AGE_DEFAULT': 43200, 'PI_AUDIT_KEY_PRIVATE': '/etc/privacyidea/private.pem', 'SUPERUSER_REALM': ['super', 'administrators']}>,) and keywords {}
[2022-07-21 17:20:54,664][17670][140108103038720][DEBUG][privacyidea.lib.audit:185] Entering getAuditClass with arguments ('privacyidea.lib.auditmodules.sqlaudit', 'Audit') and keywords {}
[2022-07-21 17:20:54,665][17670][140108103038720][DEBUG][privacyidea.lib.audit:76] klass: <class 'privacyidea.lib.auditmodules.sqlaudit.Audit'>
[2022-07-21 17:20:54,665][17670][140108103038720][DEBUG][privacyidea.lib.audit:197] Exiting getAuditClass with result <class 'privacyidea.lib.auditmodules.sqlaudit.Audit'>
[2022-07-21 17:20:54,665][17670][140108103038720][DEBUG][privacyidea.lib.auditmodules.sqlaudit:92] using the connect string mysql://privacyidea:-Gm6/(c3.;Kg8@2fa.db.com1.local/privacyidea?ssl_key=/etc/privacyidea-ldap-proxy/ssl/client-key.pem&ssl_cert=/etc/privacyidea-ldap-proxy/ssl/client-cert.pem
[2022-07-21 17:20:54,665][17670][140108103038720][DEBUG][privacyidea.lib.auditmodules.sqlaudit:99] Using SQL pool_size of 20
[2022-07-21 17:20:54,666][17670][140108103038720][DEBUG][privacyidea.lib.audit:197] Exiting getAudit with result <privacyidea.lib.auditmodules.sqlaudit.Audit object at 0x7f6d56f551d0>
[2022-07-21 17:20:54,668][17670][140108103038720][DEBUG][privacyidea.lib.config:185] Entering get_from_config with arguments ('OverrideAuthorizationClient',) and keywords {}
[2022-07-21 17:20:54,668][17670][140108103038720][DEBUG][privacyidea.lib.config:72] The singleton <class 'privacyidea.lib.config.ConfigClass'> already exists.
[2022-07-21 17:20:54,670][17670][140108103038720][DEBUG][privacyidea.lib.config:197] Exiting get_from_config with result 127.0.0.1, 172.31.51.118
[2022-07-21 17:20:54,671][17670][140108103038720][DEBUG][privacyidea.lib.policy:185] Entering get_action_values with arguments (<privacyidea.lib.policy.PolicyClass object at 0x7f6d57005550>, 'setrealm') and keywords {'scope': 'authorization', 'client': '127.0.0.1', 'realm': u'com1', 'user': u''}
[2022-07-21 17:20:54,671][17670][140108103038720][DEBUG][privacyidea.lib.policy:185] Entering get_policies with arguments (<privacyidea.lib.policy.PolicyClass object at 0x7f6d57005550>,) and keywords {'realm': u'com1', 'active': True, 'client': '127.0.0.1', 'user': u'', 'resolver': None, 'action': 'setrealm', 'scope': 'authorization', 'adminrealm': None}
[2022-07-21 17:20:54,671][17670][140108103038720][DEBUG][privacyidea.lib.policy:481] Policies after matching time: [{'time': u'', 'user': [], 'resolver': [u'COM1'], 'active': True, 'adminrealm': [], 'condition': 0L, 'realm': [u'com1'], 'name': u'GUI', 'client': [], 'check_all_resolvers': False, 'action': {u'hide_welcome_info': True, u'logout_time': u'300'}, 'scope': u'webui'}, {'time': u'', 'user': [], 'resolver': [u'COM1'], 'active': False, 'adminrealm': [], 'condition': 0L, 'realm': [u'com1'], 'name': u'2FA', 'client': [u'127.0.0.1', u'172.31.51.113', u'172.31.51.114'], 'check_all_resolvers': False, 'action': {u'otppin': u'userstore'}, 'scope': u'authentication'}, {'time': u'', 'user': [], 'resolver': [u'COM1'], 'active': True, 'adminrealm': [], 'condition': 0L, 'realm': [u'com1'], 'name': u'Users', 'client': [], 'check_all_resolvers': True, 'action': {u'reset': True, u'enable': True, u'revoke': True, u'totp_hashlib': u'sha1', u'totp_force_server_generate': True, u'totp_timestep': u'30', u'userlist': True, u'auditlog': True, u'totp_otplen': u'6', u'disable': True, u'resync': True, u'unassign': True, u'enrollTOTP': True, u'assign': True, u'delete': True}, 'scope': u'user'}, {'time': u'', 'user': [], 'resolver': [u'COM1'], 'active': True, 'adminrealm': [], 'condition': 0L, 'realm': [u'com1'], 'name': u'Enroll', 'client': [], 'check_all_resolvers': False, 'action': {u'max_token_per_user': u'2', u'tokenissuer': u'COM1', u'tokenlabel': u'<u>', u'u2f_no_verify_certificate': True}, 'scope': u'enrollment'}, {'time': u'', 'user': [], 'resolver': [u'COM1'], 'active': False, 'adminrealm': [], 'condition': 0L, 'realm': [u'com1'], 'name': u'selfservice_Auth', 'client': [u'172.31.51.134', u'172.31.51.118'], 'check_all_resolvers': False, 'action': {u'otppin': u'tokenpin'}, 'scope': u'authentication'}, {'time': u'', 'user': [], 'resolver': [], 'active': True, 'adminrealm': [], 'condition': 0L, 'realm': [], 'name': u'tmp', 'client': [], 'check_all_resolvers': True, 'action': {u'otppin': u'userstore'}, 'scope': u'authentication'}]
[2022-07-21 17:20:54,671][17670][140108103038720][DEBUG][privacyidea.lib.policy:491] Policies after matching active: [{'time': u'', 'user': [], 'resolver': [u'COM1'], 'active': True, 'adminrealm': [], 'condition': 0L, 'realm': [u'com1'], 'name': u'GUI', 'client': [], 'check_all_resolvers': False, 'action': {u'hide_welcome_info': True, u'logout_time': u'300'}, 'scope': u'webui'}, {'time': u'', 'user': [], 'resolver': [u'COM1'], 'active': True, 'adminrealm': [], 'condition': 0L, 'realm': [u'com1'], 'name': u'Users', 'client': [], 'check_all_resolvers': True, 'action': {u'reset': True, u'enable': True, u'revoke': True, u'totp_hashlib': u'sha1', u'totp_force_server_generate': True, u'totp_timestep': u'30', u'userlist': True, u'auditlog': True, u'totp_otplen': u'6', u'disable': True, u'resync': True, u'unassign': True, u'enrollTOTP': True, u'assign': True, u'delete': True}, 'scope': u'user'}, {'time': u'', 'user': [], 'resolver': [u'COM1'], 'active': True, 'adminrealm': [], 'condition': 0L, 'realm': [u'com1'], 'name': u'Enroll', 'client': [], 'check_all_resolvers': False, 'action': {u'max_token_per_user': u'2', u'tokenissuer': u'COM1', u'tokenlabel': u'<u>', u'u2f_no_verify_certificate': True}, 'scope': u'enrollment'}, {'time': u'', 'user': [], 'resolver': [], 'active': True, 'adminrealm': [], 'condition': 0L, 'realm': [], 'name': u'tmp', 'client': [], 'check_all_resolvers': True, 'action': {u'otppin': u'userstore'}, 'scope': u'authentication'}]
[2022-07-21 17:20:54,671][17670][140108103038720][DEBUG][privacyidea.lib.policy:491] Policies after matching scope: []
[2022-07-21 17:20:54,671][17670][140108103038720][DEBUG][privacyidea.lib.policy:515] Policies after matching action: []
[2022-07-21 17:20:54,671][17670][140108103038720][DEBUG][privacyidea.lib.policy:515] Policies after matching user: []
[2022-07-21 17:20:54,671][17670][140108103038720][DEBUG][privacyidea.lib.policy:515] Policies after matching realm: []
[2022-07-21 17:20:54,672][17670][140108103038720][DEBUG][privacyidea.lib.policy:587] Policies after matching client
[2022-07-21 17:20:54,672][17670][140108103038720][DEBUG][privacyidea.lib.policy:197] Exiting get_policies with result []
[2022-07-21 17:20:54,672][17670][140108103038720][DEBUG][privacyidea.lib.policy:197] Exiting get_action_values with result []
[2022-07-21 17:20:54,672][17670][140108103038720][DEBUG][privacyidea.lib.policy:185] Entering get_action_values with arguments (<privacyidea.lib.policy.PolicyClass object at 0x7f6d57005550>, 'mangle') and keywords {'scope': 'authentication', 'client': '127.0.0.1', 'realm': u'com1', 'user': u''}
[2022-07-21 17:20:54,672][17670][140108103038720][DEBUG][privacyidea.lib.policy:185] Entering get_policies with arguments (<privacyidea.lib.policy.PolicyClass object at 0x7f6d57005550>,) and keywords {'realm': u'com1', 'active': True, 'client': '127.0.0.1', 'user': u'', 'resolver': None, 'action': 'mangle', 'scope': 'authentication', 'adminrealm': None}
[2022-07-21 17:20:54,672][17670][140108103038720][DEBUG][privacyidea.lib.policy:481] Policies after matching time: [{'time': u'', 'user': [], 'resolver': [u'COM1'], 'active': True, 'adminrealm': [], 'condition': 0L, 'realm': [u'com1'], 'name': u'GUI', 'client': [], 'check_all_resolvers': False, 'action': {u'hide_welcome_info': True, u'logout_time': u'300'}, 'scope': u'webui'}, {'time': u'', 'user': [], 'resolver': [u'COM1'], 'active': False, 'adminrealm': [], 'condition': 0L, 'realm': [u'com1'], 'name': u'2FA', 'client': [u'127.0.0.1', u'172.31.51.113', u'172.31.51.114'], 'check_all_resolvers': False, 'action': {u'otppin': u'userstore'}, 'scope': u'authentication'}, {'time': u'', 'user': [], 'resolver': [u'COM1'], 'active': True, 'adminrealm': [], 'condition': 0L, 'realm': [u'com1'], 'name': u'Users', 'client': [], 'check_all_resolvers': True, 'action': {u'reset': True, u'enable': True, u'revoke': True, u'totp_hashlib': u'sha1', u'totp_force_server_generate': True, u'totp_timestep': u'30', u'userlist': True, u'auditlog': True, u'totp_otplen': u'6', u'disable': True, u'resync': True, u'unassign': True, u'enrollTOTP': True, u'assign': True, u'delete': True}, 'scope': u'user'}, {'time': u'', 'user': [], 'resolver': [u'COM1'], 'active': True, 'adminrealm': [], 'condition': 0L, 'realm': [u'com1'], 'name': u'Enroll', 'client': [], 'check_all_resolvers': False, 'action': {u'max_token_per_user': u'2', u'tokenissuer': u'COM1', u'tokenlabel': u'<u>', u'u2f_no_verify_certificate': True}, 'scope': u'enrollment'}, {'time': u'', 'user': [], 'resolver': [u'COM1'], 'active': False, 'adminrealm': [], 'condition': 0L, 'realm': [u'com1'], 'name': u'selfservice_Auth', 'client': [u'172.31.51.134', u'172.31.51.118'], 'check_all_resolvers': False, 'action': {u'otppin': u'tokenpin'}, 'scope': u'authentication'}, {'time': u'', 'user': [], 'resolver': [], 'active': True, 'adminrealm': [], 'condition': 0L, 'realm': [], 'name': u'tmp', 'client': [], 'check_all_resolvers': True, 'action': {u'otppin': u'userstore'}, 'scope': u'authentication'}]
[2022-07-21 17:20:54,672][17670][140108103038720][DEBUG][privacyidea.lib.policy:491] Policies after matching active: [{'time': u'', 'user': [], 'resolver': [u'COM1'], 'active': True, 'adminrealm': [], 'condition': 0L, 'realm': [u'com1'], 'name': u'GUI', 'client': [], 'check_all_resolvers': False, 'action': {u'hide_welcome_info': True, u'logout_time': u'300'}, 'scope': u'webui'}, {'time': u'', 'user': [], 'resolver': [u'COM1'], 'active': True, 'adminrealm': [], 'condition': 0L, 'realm': [u'com1'], 'name': u'Users', 'client': [], 'check_all_resolvers': True, 'action': {u'reset': True, u'enable': True, u'revoke': True, u'totp_hashlib': u'sha1', u'totp_force_server_generate': True, u'totp_timestep': u'30', u'userlist': True, u'auditlog': True, u'totp_otplen': u'6', u'disable': True, u'resync': True, u'unassign': True, u'enrollTOTP': True, u'assign': True, u'delete': True}, 'scope': u'user'}, {'time': u'', 'user': [], 'resolver': [u'COM1'], 'active': True, 'adminrealm': [], 'condition': 0L, 'realm': [u'com1'], 'name': u'Enroll', 'client': [], 'check_all_resolvers': False, 'action': {u'max_token_per_user': u'2', u'tokenissuer': u'COM1', u'tokenlabel': u'<u>', u'u2f_no_verify_certificate': True}, 'scope': u'enrollment'}, {'time': u'', 'user': [], 'resolver': [], 'active': True, 'adminrealm': [], 'condition': 0L, 'realm': [], 'name': u'tmp', 'client': [], 'check_all_resolvers': True, 'action': {u'otppin': u'userstore'}, 'scope': u'authentication'}]
[2022-07-21 17:20:54,672][17670][140108103038720][DEBUG][privacyidea.lib.policy:491] Policies after matching scope: [{'time': u'', 'user': [], 'resolver': [], 'active': True, 'adminrealm': [], 'condition': 0L, 'realm': [], 'name': u'tmp', 'client': [], 'check_all_resolvers': True, 'action': {u'otppin': u'userstore'}, 'scope': u'authentication'}]
[2022-07-21 17:20:54,672][17670][140108103038720][DEBUG][privacyidea.lib.policy:515] Policies after matching action: []
[2022-07-21 17:20:54,672][17670][140108103038720][DEBUG][privacyidea.lib.policy:515] Policies after matching user: []
[2022-07-21 17:20:54,672][17670][140108103038720][DEBUG][privacyidea.lib.policy:515] Policies after matching realm: []
[2022-07-21 17:20:54,672][17670][140108103038720][DEBUG][privacyidea.lib.policy:587] Policies after matching client
[2022-07-21 17:20:54,673][17670][140108103038720][DEBUG][privacyidea.lib.policy:197] Exiting get_policies with result []
[2022-07-21 17:20:54,673][17670][140108103038720][DEBUG][privacyidea.lib.policy:197] Exiting get_action_values with result []
[2022-07-21 17:20:54,673][17670][140108103038720][DEBUG][privacyidea.lib.clientapplication:185] Entering save_clientapplication with arguments ('127.0.0.1', 'privacyIDEA-LDAP-Proxy') and keywords {}
[2022-07-21 17:20:54,681][17670][140108103038720][DEBUG][privacyidea.lib.clientapplication:197] Exiting save_clientapplication with result 57
[2022-07-21 17:20:54,688][17670][140108103038720][DEBUG][privacyidea.lib.token:185] Entering get_tokens with arguments () and keywords {'assigned': True, 'active': True, 'count': True}
[2022-07-21 17:20:54,694][17670][140108103038720][DEBUG][privacyidea.lib.token:197] Exiting get_tokens with result 51
[2022-07-21 17:20:54,694][17670][140108103038720][ERROR][privacyidea.app:1423] Exception on /validate/check [POST]
Traceback (most recent call last):
  File "/opt/privacyIDEA/lib/python2.7/site-packages/flask/app.py", line 1817, in wsgi_app
    response = self.full_dispatch_request()
  File "/opt/privacyIDEA/lib/python2.7/site-packages/flask/app.py", line 1477, in full_dispatch_request
    rv = self.handle_user_exception(e)
  File "/opt/privacyIDEA/lib/python2.7/site-packages/flask/app.py", line 1381, in handle_user_exception
    reraise(exc_type, exc_value, tb)
  File "/opt/privacyIDEA/lib/python2.7/site-packages/flask/app.py", line 1475, in full_dispatch_request
    rv = self.dispatch_request()
  File "/opt/privacyIDEA/lib/python2.7/site-packages/flask/app.py", line 1461, in dispatch_request
    return self.view_functions[rule.endpoint](**req.view_args)
  File "/opt/privacyIDEA/lib/python2.7/site-packages/privacyidea/api/lib/postpolicy.py", line 102, in policy_wrapper
    response = wrapped_function(*args, **kwds)
  File "/opt/privacyIDEA/lib/python2.7/site-packages/privacyidea/api/lib/postpolicy.py", line 102, in policy_wrapper
    response = wrapped_function(*args, **kwds)
  File "/opt/privacyIDEA/lib/python2.7/site-packages/privacyidea/api/lib/postpolicy.py", line 102, in policy_wrapper
    response = wrapped_function(*args, **kwds)
  File "/opt/privacyIDEA/lib/python2.7/site-packages/privacyidea/api/lib/postpolicy.py", line 102, in policy_wrapper
    response = wrapped_function(*args, **kwds)
  File "/opt/privacyIDEA/lib/python2.7/site-packages/privacyidea/api/lib/postpolicy.py", line 102, in policy_wrapper
    response = wrapped_function(*args, **kwds)
  File "/opt/privacyIDEA/lib/python2.7/site-packages/privacyidea/api/lib/postpolicy.py", line 102, in policy_wrapper
    response = wrapped_function(*args, **kwds)
  File "/opt/privacyIDEA/lib/python2.7/site-packages/privacyidea/api/lib/postpolicy.py", line 102, in policy_wrapper
    response = wrapped_function(*args, **kwds)
  File "/opt/privacyIDEA/lib/python2.7/site-packages/privacyidea/api/lib/postpolicy.py", line 102, in policy_wrapper
    response = wrapped_function(*args, **kwds)
  File "/opt/privacyIDEA/lib/python2.7/site-packages/privacyidea/api/lib/postpolicy.py", line 102, in policy_wrapper
    response = wrapped_function(*args, **kwds)
  File "/opt/privacyIDEA/lib/python2.7/site-packages/privacyidea/api/lib/prepolicy.py", line 120, in policy_wrapper
    return wrapped_function(*args, **kwds)
  File "/opt/privacyIDEA/lib/python2.7/site-packages/privacyidea/api/lib/prepolicy.py", line 120, in policy_wrapper
    return wrapped_function(*args, **kwds)
  File "/opt/privacyIDEA/lib/python2.7/site-packages/privacyidea/api/lib/prepolicy.py", line 120, in policy_wrapper
    return wrapped_function(*args, **kwds)
  File "/opt/privacyIDEA/lib/python2.7/site-packages/privacyidea/lib/decorators.py", line 91, in check_user_or_serial_in_request_wrapper
    f_result = func(*args, **kwds)
  File "/opt/privacyIDEA/lib/python2.7/site-packages/privacyidea/lib/subscriptions.py", line 330, in check_subscription_wrapper
    check_subscription(application)
  File "/opt/privacyIDEA/lib/python2.7/site-packages/privacyidea/lib/subscriptions.py", line 242, in check_subscription
    application=application)
SubscriptionError: SubscriptionError('No subscription for your client.', application=privacyIDEA-LDAP-Proxy)
[2022-07-21 17:20:54,780][17670][140108103038720][DEBUG][privacyidea.api.lib.utils:245] Can not get param: No JSON object could be decoded

cornelinux · July 21, 2022, 6:30pm

Take a look at the last line of your log and the traceback/exception.

Congrats — you are using the LDAP Proxy.

Mohammed · July 22, 2022, 8:08am

Hi cornel,

Yes , i’m using LDAP proxy and i’m getting this error:

Jul 22 09:51:09 web2.com1.nl twistd[17716]: 2022-07-22T09:51:09+0200 [twisted.internet.endpoints.OneShotFactory#info] Starting factory <twisted.internet.endpoints.OneShotFactory instance at 0x7fa040850b48>
Jul 22 09:51:09 web2.com1.nl twistd[17716]: 2022-07-22T09:51:09+0200 [twisted.internet.endpoints.OneShotFactory#info] Starting factory <twisted.internet.endpoints.OneShotFactory instance at 0x7fa03e4d5050>
Jul 22 09:51:09 web2.com1.nl twistd[17716]: 2022-07-22T09:51:09+0200 [pi_ldapproxy.proxy#info] Client has disconnected already, closing connection to LDAP backend …
Jul 22 09:51:09 web2.com1.nl twistd[17716]: 2022-07-22T09:51:09+0200 [twisted.internet.endpoints.OneShotFactory#info] Stopping factory <twisted.internet.endpoints.OneShotFactory instance at 0x7fa03e4d5050>
Jul 22 09:51:09 web2.com1.nl twistd[17716]: 2022-07-22T09:51:09+0200 [pi_ldapproxy.proxy#info] Client has disconnected already, closing connection to LDAP backend …
Jul 22 09:51:09 web2.com1.nl twistd[17716]: 2022-07-22T09:51:09+0200 [twisted.internet.endpoints.OneShotFactory#info] Stopping factory <twisted.internet.endpoints.OneShotFactory instance at 0x7fa040850b48>
Jul 22 09:51:21 web2.com1.nl twistd[17716]: 2022-07-22T09:51:21+0200 [twisted.internet.endpoints.OneShotFactory#info] Starting factory <twisted.internet.endpoints.OneShotFactory instance at 0x7fa03d34bf80>
Jul 22 09:51:21 web2.com1.nl twistd[17716]: 2022-07-22T09:51:21+0200 [pi_ldapproxy.proxy#info] BindRequest for ‘uid=mohammed.abdirahman,ou=com1,dc=com1,dc=nl’ received …
Jul 22 09:51:21 web2.com1.nl twistd[17716]: 2022-07-22T09:51:21+0200 [twisted.internet.endpoints.OneShotFactory#info] Starting factory <twisted.internet.endpoints.OneShotFactory instance at 0x7fa03e48a050>
Jul 22 09:51:21 web2.com1.nl twistd[17716]: 2022-07-22T09:51:21+0200 [pi_ldapproxy.proxy#info] Resolved ‘uid=mohammed.abdirahman,ou=com1,dc=com1,dc=nl’ to ‘mohammed.abdirahman’@‘’ (‘’)
Jul 22 09:51:21 web2.com1.nl twistd[17716]: 2022-07-22T09:51:21+0200 [twisted.web.client._HTTP11ClientFactory#info] Starting factory <twisted.web.client._HTTP11ClientFactory instance at 0x7fa03d3672d8>
Jul 22 09:51:21 web2.com1.nl twistd[17716]: 2022-07-22T09:51:21+0200 [twisted.internet.endpoints.OneShotFactory#info] Stopping factory <twisted.internet.endpoints.OneShotFactory instance at 0x7fa03e48a050>
Jul 22 09:51:22 web2.com1.nl twistd[17716]: 2022-07-22T09:51:22+0200 [pi_ldapproxy.proxy#info] Sending BindResponse “invalid credentials”: Failed to authenticate. Wrong HTTP response (500)

And this is my LDAP proxy config:

[privacyidea]
instance = https://127.0.0.1
verify = False

[ldap-backend]
endpoint = tls:host=172.31.0.245:port=636:trustRoots=/etc/privacyidea-ldap-proxy/pems
use-tls = False
test-connection = True

[service-account]
dn = xxxx
password = xxx

[ldap-proxy]
endpoint = ssl:port=636:privateKey=/etc/privacyidea-ldap-proxy/ssl/server.key:certKey=/etc/privacyidea-ldap-proxy/ssl/server.crt
passthrough-binds = xxxx
bind-service-account = false
allow-search = yes
allow-connection-reuse = yes
ignore-search-result-references = false
forward-anonymous-binds = yes

[user-mapping]
strategy = lookup
attribute = cn

[realm-mapping]
strategy = static
realm =

[bind-cache]
enabled = false
timeout = 3

[app-cache]
enabled = false

I think LDAP authentication is not working because for some reason privacyIDEA is not sending users bind requests to the ldap server

This is my LDAP resolver config

server URI: ldaps://ldap.com1.nl
Verify TLS: NO
Base: ou=com1,dc=com1,dc=nl
scope subtree
bind type simple
Size 500
cache timeout 30s
Skip timeout 30s
timeout 5s
retry rounds 2
Loginname Attribute: uid
Search Filter: (uid=*)(objectClass=person)
Attribute mapping: {“Firstname”:“givenName”,“Lastname”:“sn”}
UID Type
No anonymous referral chasing: not checked
No retrieval of schema information: not checked

test LDAP resolver show this result:
Your LDAP config seems to be OK, 19 user objects found.

We are using Pprivacyidea for more than 4 years and it was so stable. I have’t made any changes, suddenly LDAP authentication with OTP stop working.