12:39 p.m.
Configuration:
FreeIPA and FreeRADIUS : Fedora 34 on host ipa.example.com with ip 192.168.1.139 (Proxmox
LXC Container)
privacyIDEA: Debian 10 on host mfa.example.com with ip 192.168.1.136 (Proxmox LXC
Container)
yum info freeipa-server
Version : 4.9.6
yum info freeradius
Version : 3.0.21
pip show privacyidea
Name: privacyIDEA
Version: 3.5.1
The connection between FreeRADIUS and privacyIDEA is configured with the perl module
privacyidea_radius.pm
# ipa user-show otp_test
Principal name: otp_test(a)EXAMPLE.COM
User authentication types: radius, otp
RADIUS proxy configuration: privacyidea
Password: True
Kerberos keys available: True
# ipa user-show ipa_test
Principal name: ipa_test(a)EXAMPLE.COM
User authentication types: password
Password: True
Kerberos keys available: True
# ipa radiusproxy-show privacyidea
RADIUS proxy server name: privacyidea
Server: 192.168.1.139
Problem:
It is not possible to login with user otp_test when the policy in privacyIDEA is set to
'otppin = userstore'.
Test:
[ipa_test@ipa ~]$ su otp_test
First Factor: <password>
Second Factor: <otp>
su: Authentication failure
If I set the privacyIDEA policy to 'otppin = tokenpin' and set the pin =
<password> login works.
So I think that in general authentication with privacyIDEA works.
The problem is that privacyIDEA can not check the password against the FreeIPA LDAP as you
can see in the privacyidea.log file.
In the krb5kdc.log you can see 'preauth (otp) verify failure: Generic
preauthentication failure'
Can anybody help me to fix that?
Here are parts of the logs:
/var/log/privacyidea/privacyidea.log
------------------------------------
[2021-09-22 05:27:03,157][5358][139872937498368][INFO][privacyidea.lib.crypto:821]
initializing HSM class: <class
'privacyidea.lib.security.default.DefaultSecurityModule'>
[2021-09-22 05:27:03,158][5358][139872937498368][INFO][privacyidea.lib.crypto:260]
Initialized HSM object {'obj':
<privacyidea.lib.security.default.DefaultSecurityModule object at 0x7f36a43b48d0>}
[2021-09-22 05:27:03,486][5358][139872937498368][INFO][privacyidea.lib.user:233] user
'otp_test' found in resolver 'FreeIPA'
[2021-09-22 05:27:03,486][5358][139872937498368][INFO][privacyidea.lib.user:234] userid
resolved to '69820e7e-1872-11ec-b5e7-8ae8999d4764'
[2021-09-22 05:27:03,492][5358][139872937498368][INFO][privacyidea.lib.pooling:119]
Created a new engine registry: <privacyidea.lib.pooling.NullEngineRegistry object at
0x7f369fa787b8>
[2021-09-22 05:27:03,557][5358][139872937498368][INFO][privacyidea.lib.tokens.vasco:56]
PI_VASCO_LIBRARY option is not set, functionality disabled
[2021-09-22 05:27:03,566][5358][139872937498368][INFO][privacyidea.lib.user:360] User
'otp_test' from realm 'example.com' tries to authenticate
[2021-09-22
05:27:03,576][5358][139872937498368][WARNING][privacyidea.lib.resolvers.LDAPIdResolver:354]
failed to check password for
'69820e7e-1872-11ec-b5e7-8ae8999d4764'/'uid=otp_test,cn=users,cn=accounts,dc=nottebrok,dc=net':
Exception('Wrong credentials')
[2021-09-22 05:27:03,577][5358][139872937498368][INFO][privacyidea.lib.user:371] user
User(login='otp_test', realm='example.com', resolver='FreeIPA')
failed to authenticate.
/var/log/radius/radius.log
--------------------------
Wed Sep 22 05:27:01 2021 : Info: rlm_perl: Config File /etc/privacyidea/rlm_perl.ini
found!
Wed Sep 22 05:27:01 2021 : Info: rlm_perl: Debugging config: true
Wed Sep 22 05:27:01 2021 : Info: rlm_perl: Default URL
https://mfa.example.com/validate/check
Wed Sep 22 05:27:01 2021 : Info: rlm_perl: Looking for config for auth-type Perl
Wed Sep 22 05:27:01 2021 : rlm_perl: RAD_REQUEST: User-Password =
<password><otp>
Wed Sep 22 05:27:01 2021 : rlm_perl: RAD_REQUEST: Packet-Src-IP-Address = 192.168.1.139
Wed Sep 22 05:27:01 2021 : rlm_perl: RAD_REQUEST: NAS-Identifier = ipa.example.com
Wed Sep 22 05:27:01 2021 : rlm_perl: RAD_REQUEST: Service-Type = Authenticate-Only
Wed Sep 22 05:27:01 2021 : rlm_perl: RAD_REQUEST: User-Name = otp_test
Wed Sep 22 05:27:01 2021 : Info: rlm_perl: Password encoding guessed: ascii
Wed Sep 22 05:27:01 2021 : Info: rlm_perl: Setting client IP to 192.168.1.139.
Wed Sep 22 05:27:01 2021 : Info: rlm_perl: Auth-Type: Perl
Wed Sep 22 05:27:01 2021 : Info: rlm_perl: url: https://mfa.example.com/validate/check
Wed Sep 22 05:27:01 2021 : Info: rlm_perl: user sent to privacyidea: otp_test
Wed Sep 22 05:27:01 2021 : Info: rlm_perl: realm sent to privacyidea:
Wed Sep 22 05:27:01 2021 : Info: rlm_perl: resolver sent to privacyidea:
Wed Sep 22 05:27:01 2021 : Info: rlm_perl: client sent to privacyidea: 192.168.1.139
Wed Sep 22 05:27:01 2021 : Info: rlm_perl: state sent to privacyidea:
Wed Sep 22 05:27:01 2021 : rlm_perl: urlparam client = 192.168.1.139
Wed Sep 22 05:27:01 2021 : rlm_perl: urlparam pass = <password><otp>
Wed Sep 22 05:27:01 2021 : rlm_perl: urlparam user = otp_test
Wed Sep 22 05:27:01 2021 : Info: rlm_perl: Request timeout: 10
Wed Sep 22 05:27:01 2021 : Info: rlm_perl: Not verifying SSL certificate!
Wed Sep 22 05:27:03 2021 : Info: rlm_perl: elapsed time for privacyidea call: 2.298527
Wed Sep 22 05:27:03 2021 : rlm_perl: Content {"detail": {"message":
"wrong otp pin", "threadid": 139872937498368}, "id": 1,
"jsonrpc": "2.0", "result": {"status": true,
"value": false}, "time": 1632288423.7560399, "version":
"privacyIDEA 3.5.1", "versionnumber": "3.5.1",
"signature":
"rsa_sha256_pss:a4ea05ca498b36c09137d1f492bc882109adfc8a7fb3a185fb4b8638255dd2539659897591afdffd99b6cdd1bb5c5741f63f2037abdc85c5bafae669a97f1e7cbc76f26da70139651e796e60550d9410c7f7c6cab8f3581cbb6f676683da9a1c4659ec2f30187d18c25297dda2a61e06085ee4265606670377040247e19bb58ca0f04aca71cf30b198376eaf263503228176ec249dccb82036e987d190c6108fddadebd250deb2c19995b7dbeeb8ed2d233066389c871e99c76d85ef908009448c5af2ca7d0605852720bdb9ade99b58711593c9b9f92a2ca45aa351d0d33c721df9417d464aaf9052cdce99440d851ea6f9940de8576df4023974866cc5fb16"}
Wed Sep 22 05:27:03 2021 : Info: rlm_perl: privacyIDEA Result status is true!
Wed Sep 22 05:27:03 2021 : Info: rlm_perl: privacyIDEA access denied for otp_test
realm=''
Wed Sep 22 05:27:03 2021 : Info: rlm_perl: return RLM_MODULE_REJECT
/var/log/dirsrv/slapd-NOTTEBROK-NET/access
------------------------------------------
[22/Sep/2021:05:27:01.564080274 +0000] conn=3895 op=2 RESULT err=0 tag=101 nentries=1
wtime=0.000049870 optime=0.000150998 etime=0.000199231
[22/Sep/2021:05:27:01.564323730 +0000] conn=3895 op=3 SRCH
base="cn=privacyidea,cn=radiusproxy,dc=nottebrok,dc=net" scope=0
filter="(objectClass=*)" attrs="ipatokenRadiusServer ipatokenRadiusSecret
ipatokenRadiusTimeout ipatokenRadiusRetries ipatokenUserMapAttribute"
[22/Sep/2021:05:27:01.564421567 +0000] conn=3895 op=3 RESULT err=0 tag=101 nentries=1
wtime=0.000041954 optime=0.000099034 etime=0.000139513
[22/Sep/2021:05:27:01.566557293 +0000] conn=3892 op=11 SRCH
base="cn=ipservices,cn=accounts,dc=nottebrok,dc=net" scope=2
filter="(&(cn=radius)(ipServiceProtocol=udp)(objectClass=ipService))"
attrs="objectClass cn ipServicePort ipServiceProtocol entryusn"
[22/Sep/2021:05:27:01.566712813 +0000] conn=3892 op=11 RESULT err=0 tag=101 nentries=0
wtime=0.000084750 optime=0.000157349 etime=0.000240250
[22/Sep/2021:05:27:03.246250221 +0000] conn=3897 fd=121 slot=121 connection from
192.168.1.136 to 192.168.1.139
[22/Sep/2021:05:27:03.246571254 +0000] conn=3897 op=-1 fd=121 closed error - B1
[22/Sep/2021:05:27:03.246630909 +0000] conn=3898 fd=126 slot=126 connection from
192.168.1.136 to 192.168.1.139
[22/Sep/2021:05:27:03.246931986 +0000] conn=3898 op=0 EXT
oid="1.3.6.1.4.1.1466.20037" name="start_tls_plugin"
[22/Sep/2021:05:27:03.246975107 +0000] conn=3898 op=0 RESULT err=0 tag=120 nentries=0
wtime=0.000135107 optime=0.000048051 etime=0.000181367
[22/Sep/2021:05:27:03.250916223 +0000] conn=3898 TLS1.2 128-bit AES-GCM
[22/Sep/2021:05:27:03.251829337 +0000] conn=3898 op=1 BIND
dn="uid=privacyidea-bind,cn=sysaccounts,cn=etc,dc=nottebrok,dc=net" method=128
version=3
[22/Sep/2021:05:27:03.252339317 +0000] conn=3898 op=1 RESULT err=0 tag=97 nentries=0
wtime=0.004225141 optime=0.000524375 etime=0.004747290
dn="uid=privacyidea-bind,cn=sysaccounts,cn=etc,dc=nottebrok,dc=net"
[22/Sep/2021:05:27:03.253292531 +0000] conn=3898 op=2 SRCH base="" scope=0
filter="(objectClass=*)" attrs="subschemaSubentry +"
[22/Sep/2021:05:27:03.254751970 +0000] conn=3898 op=2 RESULT err=0 tag=101 nentries=1
wtime=0.000091257 optime=0.001461035 etime=0.001549672
[22/Sep/2021:05:27:03.256597869 +0000] conn=3898 op=3 SRCH base="cn=schema"
scope=0 filter="(objectClass=subschema)" attrs="objectClasses
attributeTypes ldapSyntaxes matchingRules matchingRuleUse dITContentRules
dITStructureRules nameForms createTimestamp modifyTimestamp * + aci"
[22/Sep/2021:05:27:03.351666572 +0000] conn=3898 op=3 RESULT err=0 tag=101 nentries=1
wtime=0.000120956 optime=0.095069951 etime=0.095184874
[22/Sep/2021:05:27:03.484292759 +0000] conn=3898 op=4 SRCH
base="cn=users,cn=accounts,dc=nottebrok,dc=net" scope=2
filter="(&(uid=*)(objectClass=inetOrgPerson)(uid=otp_test))"
attrs="telephoneNumber mobile mail sn givenName gecos uid ipaUniqueID"
[22/Sep/2021:05:27:03.485807992 +0000] conn=3898 op=4 RESULT err=0 tag=101 nentries=1
wtime=0.000140279 optime=0.001516926 etime=0.001653375 notes=U details="Partially
Unindexed Filter"
[22/Sep/2021:05:27:03.564155920 +0000] conn=3898 op=5 SRCH
base="cn=users,cn=accounts,dc=nottebrok,dc=net" scope=2
filter="(&(uid=*)(objectClass=inetOrgPerson)(ipaUniqueID=69820e7e-1872-11ec-b5e7-8ae8999d4764))"
attrs="telephoneNumber mobile mail sn givenName gecos uid"
[22/Sep/2021:05:27:03.565628714 +0000] conn=3898 op=5 RESULT err=0 tag=101 nentries=1
wtime=0.000138785 optime=0.001475478 etime=0.001609564 notes=U details="Partially
Unindexed Filter"
[22/Sep/2021:05:27:03.568418557 +0000] conn=3898 op=6 SRCH
base="cn=users,cn=accounts,dc=nottebrok,dc=net" scope=2
filter="(&(uid=*)(objectClass=inetOrgPerson)(ipaUniqueID=69820e7e-1872-11ec-b5e7-8ae8999d4764))"
attrs="telephoneNumber mobile mail sn givenName gecos uid"
[22/Sep/2021:05:27:03.569936263 +0000] conn=3898 op=6 RESULT err=0 tag=101 nentries=1
wtime=0.000139985 optime=0.001520723 etime=0.001656185 notes=U details="Partially
Unindexed Filter"
[22/Sep/2021:05:27:03.570551770 +0000] conn=3899 fd=121 slot=121 connection from
192.168.1.136 to 192.168.1.139
[22/Sep/2021:05:27:03.570832412 +0000] conn=3899 op=-1 fd=121 closed error - B1
[22/Sep/2021:05:27:03.570894957 +0000] conn=3900 fd=127 slot=127 connection from
192.168.1.136 to 192.168.1.139
[22/Sep/2021:05:27:03.571225293 +0000] conn=3900 op=0 EXT
oid="1.3.6.1.4.1.1466.20037" name="start_tls_plugin"
[22/Sep/2021:05:27:03.571270580 +0000] conn=3900 op=0 RESULT err=0 tag=120 nentries=0
wtime=0.000153969 optime=0.000047853 etime=0.000200296
[22/Sep/2021:05:27:03.574890946 +0000] conn=3900 TLS1.2 128-bit AES-GCM
[22/Sep/2021:05:27:03.575569529 +0000] conn=3900 op=1 BIND
dn="uid=otp_test,cn=users,cn=accounts,dc=nottebrok,dc=net" method=128 version=3
[22/Sep/2021:05:27:03.576077489 +0000] conn=3900 op=1 RESULT err=49 tag=97 nentries=0
wtime=0.003805205 optime=0.000518648 etime=0.004320920
[22/Sep/2021:05:27:04.869258275 +0000] conn=3029 op=13493 MOD
dn="uid=otp_test,cn=users,cn=accounts,dc=nottebrok,dc=net"
[22/Sep/2021:05:27:04.939090470 +0000] conn=3029 op=13493 RESULT err=0 tag=103 nentries=0
wtime=0.000077276 optime=0.069837500 etime=0.069910794
[22/Sep/2021:05:27:04.940438540 +0000] conn=3890 op=36 SRCH
base="cn=etc,dc=nottebrok,dc=net" scope=2
filter="(&(cn=ipaConfig)(objectClass=ipaGuiConfig))"
attrs="ipaMigrationEnabled ipaSELinuxUserMapDefault ipaSELinuxUserMapOrder"
[22/Sep/2021:05:27:04.940991039 +0000] conn=3890 op=36 RESULT err=0 tag=101 nentries=1
wtime=0.000166940 optime=0.000555022 etime=0.000718249
/var/log/krb5kdc.log
--------------------
Sep 22 05:27:01 ipa krb5kdc[8615](info): AS_REQ (8 etypes {aes256-cts-hmac-sha1-96(18),
aes128-cts-hmac-sha1-96(17), aes256-cts-hmac-sha384-192(20),
aes128-cts-hmac-sha256-128(19), UNSUPPORTED:des3-hmac-sha1(16),
DEPRECATED:arcfour-hmac(23), camellia128-cts-cmac(25), camellia256-cts-cmac(26)})
192.168.1.129: NEEDED_PREAUTH: otp_test(a)EXAMPLE.COM for krbtgt/EXAMPLE.COM(a)EXAMPLE.COM,
Additional pre-authentication required
Sep 22 05:27:01 ipa krb5kdc[8615](info): closing down fd 11
Sep 22 05:27:01 ipa krb5kdc[8615](info): AS_REQ (8 etypes {aes256-cts-hmac-sha1-96(18),
aes128-cts-hmac-sha1-96(17), aes256-cts-hmac-sha384-192(20),
aes128-cts-hmac-sha256-128(19), UNSUPPORTED:des3-hmac-sha1(16),
DEPRECATED:arcfour-hmac(23), camellia128-cts-cmac(25), camellia256-cts-cmac(26)})
192.168.1.129: NEEDED_PREAUTH: otp_test(a)EXAMPLE.COM for krbtgt/EXAMPLE.COM(a)EXAMPLE.COM,
Additional pre-authentication required
Sep 22 05:27:01 ipa krb5kdc[8615](info): closing down fd 11
Sep 22 05:27:04 ipa krb5kdc[8615](info): preauth (otp) verify failure: Generic
preauthentication failure
Sep 22 05:27:04 ipa krb5kdc[8615](info): AS_REQ (8 etypes {aes256-cts-hmac-sha1-96(18),
aes128-cts-hmac-sha1-96(17), aes256-cts-hmac-sha384-192(20),
aes128-cts-hmac-sha256-128(19), UNSUPPORTED:des3-hmac-sha1(16),
DEPRECATED:arcfour-hmac(23), camellia128-cts-cmac(25), camellia256-cts-cmac(26)})
192.168.1.129: PREAUTH_FAILED: otp_test(a)EXAMPLE.COM for krbtgt/EXAMPLE.COM(a)EXAMPLE.COM,
Preauthentication failed
Sep 22 05:27:04 ipa krb5kdc[8615](info): closing down fd 11