kerberos pre-auth fails

SSSD / sssd

A daemon to manage identity, authentication and authorization for centrally-managed systems.

https://sssd.io

GNU General Public License v3.0

609 stars 250 forks source link

kerberos pre-auth fails #5377

Closed xDFCx closed 4 years ago

xDFCx commented 4 years ago

Hello. Sorry, if this in not appropriate place for looking for help, but I dont know where else I can find it with such a problem. I'm trying to make work logon via smartcard in a samba4 domain with two level enterprise CA. My test stand consists of offline root CA (centos7-based distro RedOS), subordinate CA (RedOS), samba4 DC (RedOS), Win7 domain client, RedOS domain client. So, I already have working smartcard auth on win7 client, now I'm really stuck with linux client. I've got all needed libs installed, so I get this:

#/usr/libexec/sssd/p11_child --pre --nssdb=/etc/pki/nssdb -d 10
(Mon Oct 26 18:52:04:157147 2020) [[sssd[p11_child[28763]]]] [main] (0x0400): p11_child started.
(Mon Oct 26 18:52:04:157225 2020) [[sssd[p11_child[28763]]]] [main] (0x2000): Running in [pre-auth] mode.
(Mon Oct 26 18:52:04:157236 2020) [[sssd[p11_child[28763]]]] [main] (0x2000): Running with effective IDs: [0][0].
(Mon Oct 26 18:52:04:157245 2020) [[sssd[p11_child[28763]]]] [main] (0x2000): Running with real IDs [0][0].
(Mon Oct 26 18:52:07:257136 2020) [[sssd[p11_child[28763]]]] [do_card] (0x4000): Default Module List:
(Mon Oct 26 18:52:07:257203 2020) [[sssd[p11_child[28763]]]] [do_card] (0x4000): common name: [NSS Internal PKCS #11 Module].
(Mon Oct 26 18:52:07:257212 2020) [[sssd[p11_child[28763]]]] [do_card] (0x4000): dll name: [(null)].
(Mon Oct 26 18:52:07:257220 2020) [[sssd[p11_child[28763]]]] [do_card] (0x4000): common name: [JaCarta].
(Mon Oct 26 18:52:07:257228 2020) [[sssd[p11_child[28763]]]] [do_card] (0x4000): dll name: [/lib64/libjcPKCS11-2.so].
(Mon Oct 26 18:52:07:257236 2020) [[sssd[p11_child[28763]]]] [do_card] (0x4000): Dead Module List:
(Mon Oct 26 18:52:07:257244 2020) [[sssd[p11_child[28763]]]] [do_card] (0x4000): DB Module List:
(Mon Oct 26 18:52:07:257251 2020) [[sssd[p11_child[28763]]]] [do_card] (0x4000): common name: [NSS Internal Module].
(Mon Oct 26 18:52:07:257259 2020) [[sssd[p11_child[28763]]]] [do_card] (0x4000): dll name: [(null)].
(Mon Oct 26 18:52:07:257267 2020) [[sssd[p11_child[28763]]]] [do_card] (0x4000): common name: [Policy File].
(Mon Oct 26 18:52:07:257274 2020) [[sssd[p11_child[28763]]]] [do_card] (0x4000): dll name: [(null)].
(Mon Oct 26 18:52:07:257297 2020) [[sssd[p11_child[28763]]]] [do_card] (0x4000): Description [NSS Internal Cryptographic Services                             Mozilla Foundation                ] Manufacturer [Mozilla Foundation                  ] flags [9] removable [false] token present [true].
(Mon Oct 26 18:52:07:257311 2020) [[sssd[p11_child[28763]]]] [do_card] (0x4000): Description [NSS User Private Key and Certificate Services                   Mozilla Foundation              ] Manufacturer [Mozilla Foundation              ] flags [1] removable [false] token present [true].
(Mon Oct 26 18:52:07:257330 2020) [[sssd[p11_child[28763]]]] [do_card] (0x4000): Description [Aladdin R.D. JaCarta [SCR Interface] (000000000000) 00 00       Aladdin R.D.                    ] Manufacturer [Aladdin R.D.                    ] flags [7] removable [true] token present [true].
(Mon Oct 26 18:52:07:257339 2020) [[sssd[p11_child[28763]]]] [do_card] (0x4000): Found [jacarta] in slot [Aladdin R.D. JaCarta [SCR Interface] (000000000000) 00 00][131071] of module [2][/lib64/libjcPKCS11-2.so].
(Mon Oct 26 18:52:07:257348 2020) [[sssd[p11_child[28763]]]] [do_card] (0x4000): Token is NOT friendly.
(Mon Oct 26 18:52:07:257355 2020) [[sssd[p11_child[28763]]]] [do_card] (0x4000): Trying to switch to friendly to read certificate.
(Mon Oct 26 18:52:07:257364 2020) [[sssd[p11_child[28763]]]] [do_card] (0x4000): Login required.
(Mon Oct 26 18:52:07:257371 2020) [[sssd[p11_child[28763]]]] [do_card] (0x0020): Login required but no PIN available, continue.
(Mon Oct 26 18:52:08:280494 2020) [[sssd[p11_child[28763]]]] [do_card] (0x4000): found cert[(null)][E=user1@pki-test.local,CN=user1@pki-test.local]
(Mon Oct 26 18:52:08:280556 2020) [[sssd[p11_child[28763]]]] [do_card] (0x4000): found cert[(null)][E=user1@pki-test.local,CN=user1]
(Mon Oct 26 18:52:08:280568 2020) [[sssd[p11_child[28763]]]] [do_card] (0x4000): Filtered certificates:
(Mon Oct 26 18:52:08:280576 2020) [[sssd[p11_child[28763]]]] [do_card] (0x4000): found cert[(null)][E=user1@pki-test.local,CN=user1@pki-test.local]
(Mon Oct 26 18:52:08:280619 2020) [[sssd[p11_child[28763]]]] [do_card] (0x4000): module uri: pkcs11:library-manufacturer=Aladdin%20R.D.;library-description=JaCarta%20PKCS%2311%20module;library-version=2.4.
(Mon Oct 26 18:52:08:280637 2020) [[sssd[p11_child[28763]]]] [do_card] (0x4000): token uri: pkcs11:token=jacarta;manufacturer=Aladdin%20R.D.;serial=4E46000557304C4E;model=JaCarta%20Laser.
(Mon Oct 26 18:52:08:889249 2020) [[sssd[p11_child[28763]]]] [do_card] (0x4000): (null) /lib64/libjcPKCS11-2.so (null) jacarta (null) (null).
(Mon Oct 26 18:52:08:889336 2020) [[sssd[p11_child[28763]]]] [do_card] (0x4000): found cert[(null)][E=user1@pki-test.local,CN=user1]
(Mon Oct 26 18:52:08:889368 2020) [[sssd[p11_child[28763]]]] [do_card] (0x4000): module uri: pkcs11:library-manufacturer=Aladdin%20R.D.;library-description=JaCarta%20PKCS%2311%20module;library-version=2.4.
(Mon Oct 26 18:52:08:889386 2020) [[sssd[p11_child[28763]]]] [do_card] (0x4000): token uri: pkcs11:token=jacarta;manufacturer=Aladdin%20R.D.;serial=4E46000557304C4E;model=JaCarta%20Laser.
(Mon Oct 26 18:52:09:043029 2020) [[sssd[p11_child[28763]]]] [do_card] (0x4000): (null) /lib64/libjcPKCS11-2.so (null) jacarta (null) (null).
(Mon Oct 26 18:52:09:295720 2020) [[sssd[p11_child[28763]]]] [do_card] (0x4000): Found certificate has key id [4321].
(Mon Oct 26 18:52:09:411971 2020) [[sssd[p11_child[28763]]]] [do_card] (0x4000): uri: pkcs11:token=jacarta;manufacturer=Aladdin%20R.D.;serial=4E46000557304C4E;model=JaCarta%20Laser;library-manufacturer=Aladdin%20R.D.;library-description=JaCarta%20PKCS%2311%20module;library-version=2.4;object=-%20no%20label%20found%20-;type=cert;slot-manufacturer=Aladdin%20R.D.;slot-description=Aladdin%20R.D.%20JaCarta%20[SCR%20Interface]%20(000000000000)%2000%2000;slot-id=131071;id=%43%21.
(Mon Oct 26 18:52:09:676326 2020) [[sssd[p11_child[28763]]]] [do_card] (0x4000): Found certificate has key id [1616].
(Mon Oct 26 18:52:09:791585 2020) [[sssd[p11_child[28763]]]] [do_card] (0x4000): uri: pkcs11:token=jacarta;manufacturer=Aladdin%20R.D.;serial=4E46000557304C4E;model=JaCarta%20Laser;library-manufacturer=Aladdin%20R.D.;library-description=JaCarta%20PKCS%2311%20module;library-version=2.4;object=-%20no%20label%20found%20-;type=cert;slot-manufacturer=Aladdin%20R.D.;slot-description=Aladdin%20R.D.%20JaCarta%20[SCR%20Interface]%20(000000000000)%2000%2000;slot-id=131071;id=%16%16.
jacarta
/lib64/libjcPKCS11-2.so
4321
- no label found -
MIIE9zCCA9+gAwIBAgIUBLqY47X2y/kL1GKvge8eKPJ71uMwDQYJKoZIhvcNAQELBQAwEzERMA8GA1UEAwwIU1VCQ0EtczEwHhcNMjAxMDIzMDkyNTQxWhcNMjExMDIzMDkyNTQxWjBEMR0wGwYDVQQDDBR1c2VyMUBwa2ktdGVzdC5sb2NhbDEjMCEGCSqGSIb3DQEJARYUdXNlcjFAcGtpLXRlc3QubG9jYWwwggEiMA0GCSqGSIb3DQEBAQUAA4IBDwAwggEKAoIBAQCrsBsmWBCRMsoohaQf2rkiIfJxPE3UphvmLz+CrcAHhxiMdDbFKcNquamBafhgiDcHK5qFdBdmqpeEzABLtNmjEhheL3UuKVzSLEdWGful+ds3dxTZ+Dvl9n3d5AJ/9RGTOFGFG9TcwDIM7X4kNSeKpeEkiBRfXVr3ws4p5PpNRD4xFQQz2Br2DAEH+0EGaFlgFxwvfzvoVXzlrJn7qpanY7cIAixCJPhKtyJ6aJHqpaSr0ki2Xfkjz3a1F4TTIQBML+9+Lpi6aT0Qj3TTqzQJPXj5qK+GsnbgLc2dR2W5gI5sYsEeyNicHp1HA948L4+z8jikIov86jADv2MlqGcxAgMBAAGjggIQMIICDDAMBgNVHRMBAf8EAjAAMB8GA1UdIwQYMBaAFPMva1ihFSq06/VbLc0GK9UkKOucMGEGCCsGAQUFBwEBBFUwUzBRBggrBgEFBQcwAYZFaHR0cDovL3JlZG9zLXN1YmNhLXMxLnBraS10ZXN0LmxvY2FsOjgwODAvZWpiY2EvcHVibGljd2ViL3N0YXR1cy9vY3NwMDgGA1UdEgQxMC+CHXJlZG9zLXN1YmNhLXMxLnBraS10ZXN0LmxvY2Fsgg5yZWRvcy1zdWJjYS1zMTBFBgNVHREEPjA8gRR1c2VyMUBwa2ktdGVzdC5sb2NhbKAkBgorBgEEAYI3FAIDoBYMFHVzZXIxQHBraS10ZXN0LmxvY2FsMDMGA1UdJQQsMCoGCCsGAQUFBwMCBggrBgEFBQcDBAYKKwYBBAGCNxQCAgYIKwYBBQUHAwEwgZIGA1UdHwSBijCBhzCBhKBpoGeGZWh0dHA6Ly9yZWRvcy1zdWJjYS1zMS5wa2ktdGVzdC5sb2NhbDo4MDgwL2VqYmNhL3B1YmxpY3dlYi93ZWJkaXN0L2NlcnRkaXN0P2NtZD1jcmwmaXNzdWVyPUNOPVNVQkNBLXMxohekFTATMREwDwYDVQQDDAhTVUJDQS1zMTAdBgNVHQ4EFgQUo/VymQXXuWRguEza1uZUG3gi5WgwDgYDVR0PAQH/BAQDAgTwMA0GCSqGSIb3DQEBCwUAA4IBAQB45BbY+hfOJnULJ2o1vL+rHYYVLoP+0E3o0Nx/cyoN+ISO3ZthpqMzI5NbpeFQIDcTLCrCDMkGVkse9IDPdD62F78ajrLYXUK2sbJ/hj5r17aXKvtzD44pPgrJFHU7ABNiVwkc8UuY5CMHGmfUZ8ykR8HbIvt8pqTZe/mTblriy8X4lIvf6Dyi8j2mjNAIZYC8ZNrtQFJq22v8e1QszdUayeRuxxndXM3mpqEGWu49QUvep71zH/OahCxZpRjBYnFjLFsQv34Zlv9GQhcgEa0H+IXlxKo1C/+MGjiOSzQnyh3zeknqE3bmInCYEq/maPXvWfkqz2+8aD7BGtWkN52r
jacarta
/lib64/libjcPKCS11-2.so
1616
- no label found -
MIIE6DCCA9CgAwIBAgIUDa8QTOVB60tO5EdcZ4pfc0sYF0QwDQYJKoZIhvcNAQELBQAwEzERMA8GA1UEAwwIU1VCQ0EtczEwHhcNMjAxMDIzMTAwMjQzWhcNMjExMDIzMTAwMjQzWjA1MQ4wDAYDVQQDDAV1c2VyMTEjMCEGCSqGSIb3DQEJARYUdXNlcjFAcGtpLXRlc3QubG9jYWwwggEiMA0GCSqGSIb3DQEBAQUAA4IBDwAwggEKAoIBAQDe5rwe1+KLb8dB3Mk/AiRieGhfbgpuYk/ELT9DwPm7aVXIKG+CdendeJaoZOPtS+XzB60iQkOMfbH1quixXfHP0BY3S+JIMtI3llR49CsF4UM+lvuDC791AFC1hN2UWqRNLDLDDB3/Ux+HFmlKgGtDWxwdhY2p4auzeBd4tryeg2mVTvUxZ46Wc1bc6KczhgSY3g9kXGWiMM/vanOh5rUAlx0f6ajzq2yQr70/UvxWgVO9iiPgdBCnuLenwGt0EH8BTumQOyz29nzT0tfPNKxYrHYpo4+hBMuo1JvmF7ccfK2c+CJUxMUKxywwiTfI3ANH/Nm/gge2NtasjAgfmc1XAgMBAAGjggIQMIICDDAMBgNVHRMBAf8EAjAAMB8GA1UdIwQYMBaAFPMva1ihFSq06/VbLc0GK9UkKOucMGEGCCsGAQUFBwEBBFUwUzBRBggrBgEFBQcwAYZFaHR0cDovL3JlZG9zLXN1YmNhLXMxLnBraS10ZXN0LmxvY2FsOjgwODAvZWpiY2EvcHVibGljd2ViL3N0YXR1cy9vY3NwMDgGA1UdEgQxMC+CHXJlZG9zLXN1YmNhLXMxLnBraS10ZXN0LmxvY2Fsgg5yZWRvcy1zdWJjYS1zMTBFBgNVHREEPjA8gRR1c2VyMUBwa2ktdGVzdC5sb2NhbKAkBgorBgEEAYI3FAIDoBYMFHVzZXIxQHBraS10ZXN0LmxvY2FsMDMGA1UdJQQsMCoGCCsGAQUFBwMCBggrBgEFBQcDBAYKKwYBBAGCNxQCAgYIKwYBBQUHAwEwgZIGA1UdHwSBijCBhzCBhKBpoGeGZWh0dHA6Ly9yZWRvcy1zdWJjYS1zMS5wa2ktdGVzdC5sb2NhbDo4MDgwL2VqYmNhL3B1YmxpY3dlYi93ZWJkaXN0L2NlcnRkaXN0P2NtZD1jcmwmaXNzdWVyPUNOPVNVQkNBLXMxohekFTATMREwDwYDVQQDDAhTVUJDQS1zMTAdBgNVHQ4EFgQULuQ4OuzHMohokQWZhXlk93/41UEwDgYDVR0PAQH/BAQDAgTwMA0GCSqGSIb3DQEBCwUAA4IBAQBMxQ8lASoQGshQYTcusQub1ijNAHk4dJKw5kTSCYC0EvsjgwHczUps4HyUtZhSkGU0cUwWfVBy3gHIbwz5gC/M0M6iILim9z7vMDAUw+RZuoQoROAISN1byoUpU1n9zCYMtlnV4Q+WwTBufVwxiGez6romzA8ajQIIvmW1/VimZ3+tdpQE+F1mEyYkmLlcBvGmfdvA3aUguKDkjUBFbnCT3kg/b6cV3wnVZtAdHpo4en4JnAKR7YS8LrFOiLyg/u4i8dg1Hfh796O2tqEnRihwEJcoBDF5NejbI5kQuZbx5f6k7Uc8FCKmBTs/H1xV3UMEHm5+UOI2qzJINxFtNVSb

With theese 2 certs (and keys) on my token I can login on windows client, but on RedOS i get this:

# cat krb5_child.log
(Fri Oct 23 18:35:18:015369 2020) [[sssd[krb5_child[19536]]]] [main] (0x0400): krb5_child started.
(Fri Oct 23 18:35:18:015452 2020) [[sssd[krb5_child[19536]]]] [unpack_buffer] (0x1000): total buffer size: [148]
(Fri Oct 23 18:35:18:015467 2020) [[sssd[krb5_child[19536]]]] [unpack_buffer] (0x0100): cmd [249] uid [403801106] gid [403800513] validate [true] enterprise principal [false] offline [true] UPN [user1@PKI-TEST.LOCAL]
(Fri Oct 23 18:35:18:015476 2020) [[sssd[krb5_child[19536]]]] [unpack_buffer] (0x0100): ccname: [KEYRING:persistent:403801106] old_ccname: [KEYRING:persistent:403801106] keytab: [/etc/krb5.keytab]
(Fri Oct 23 18:35:18:015660 2020) [[sssd[krb5_child[19536]]]] [check_use_fast] (0x0100): Not using FAST.
(Fri Oct 23 18:35:18:015722 2020) [[sssd[krb5_child[19536]]]] [privileged_krb5_setup] (0x0080): Cannot open the PAC responder socket
(Fri Oct 23 18:35:18:015731 2020) [[sssd[krb5_child[19536]]]] [become_user] (0x0200): Trying to become user [403801106][403800513].
(Fri Oct 23 18:35:18:015750 2020) [[sssd[krb5_child[19536]]]] [main] (0x2000): Running as [403801106][403800513].
(Fri Oct 23 18:35:18:015762 2020) [[sssd[krb5_child[19536]]]] [become_user] (0x0200): Trying to become user [403801106][403800513].
(Fri Oct 23 18:35:18:015770 2020) [[sssd[krb5_child[19536]]]] [become_user] (0x0200): Already user [403801106].
(Fri Oct 23 18:35:18:015778 2020) [[sssd[krb5_child[19536]]]] [k5c_setup] (0x2000): Running as [403801106][403800513].
(Fri Oct 23 18:35:18:015798 2020) [[sssd[krb5_child[19536]]]] [set_lifetime_options] (0x0100): No specific renewable lifetime requested.
(Fri Oct 23 18:35:18:015806 2020) [[sssd[krb5_child[19536]]]] [set_lifetime_options] (0x0100): No specific lifetime requested.
(Fri Oct 23 18:35:18:015813 2020) [[sssd[krb5_child[19536]]]] [main] (0x0400): Will perform pre-auth
(Fri Oct 23 18:35:18:015821 2020) [[sssd[krb5_child[19536]]]] [tgt_req_child] (0x1000): Attempting to get a TGT
(Fri Oct 23 18:35:18:015829 2020) [[sssd[krb5_child[19536]]]] [get_and_save_tgt] (0x0400): Attempting kinit for realm [PKI-TEST.LOCAL]
(Fri Oct 23 18:35:18:015856 2020) [[sssd[krb5_child[19536]]]] [sss_child_krb5_trace_cb] (0x4000): [19536] 1603467318.15649: Getting initial credentials for user1@PKI-TEST.LOCAL

(Fri Oct 23 18:35:18:016148 2020) [[sssd[krb5_child[19536]]]] [sss_child_krb5_trace_cb] (0x4000): [19536] 1603467318.15651: Sending unauthenticated request

(Fri Oct 23 18:35:18:016182 2020) [[sssd[krb5_child[19536]]]] [sss_child_krb5_trace_cb] (0x4000): [19536] 1603467318.15652: Sending request (208 bytes) to PKI-TEST.LOCAL

(Fri Oct 23 18:35:18:016323 2020) [[sssd[krb5_child[19536]]]] [sss_child_krb5_trace_cb] (0x4000): [19536] 1603467318.15653: Sending DNS URI query for _kerberos.PKI-TEST.LOCAL.

(Fri Oct 23 18:35:18:017453 2020) [[sssd[krb5_child[19536]]]] [sss_child_krb5_trace_cb] (0x4000): [19536] 1603467318.15654: No URI records found

(Fri Oct 23 18:35:18:017479 2020) [[sssd[krb5_child[19536]]]] [sss_child_krb5_trace_cb] (0x4000): [19536] 1603467318.15655: Sending DNS SRV query for _kerberos._udp.PKI-TEST.LOCAL.

(Fri Oct 23 18:35:18:018387 2020) [[sssd[krb5_child[19536]]]] [sss_child_krb5_trace_cb] (0x4000): [19536] 1603467318.15656: SRV answer: 0 100 88 "redos-dc-s1.pki-test.local."

(Fri Oct 23 18:35:18:018411 2020) [[sssd[krb5_child[19536]]]] [sss_child_krb5_trace_cb] (0x4000): [19536] 1603467318.15657: Sending DNS SRV query for _kerberos._tcp.PKI-TEST.LOCAL.

(Fri Oct 23 18:35:18:019249 2020) [[sssd[krb5_child[19536]]]] [sss_child_krb5_trace_cb] (0x4000): [19536] 1603467318.15658: SRV answer: 0 100 88 "redos-dc-s1.pki-test.local."

(Fri Oct 23 18:35:18:019289 2020) [[sssd[krb5_child[19536]]]] [sss_child_krb5_trace_cb] (0x4000): [19536] 1603467318.15659: Resolving hostname redos-dc-s1.pki-test.local.

(Fri Oct 23 18:35:18:021060 2020) [[sssd[krb5_child[19536]]]] [sss_child_krb5_trace_cb] (0x4000): [19536] 1603467318.15660: Sending initial UDP request to dgram 192.168.42.10:88

(Fri Oct 23 18:35:18:023493 2020) [[sssd[krb5_child[19536]]]] [sss_child_krb5_trace_cb] (0x4000): [19536] 1603467318.15661: Received answer (276 bytes) from dgram 192.168.42.10:88

(Fri Oct 23 18:35:18:023572 2020) [[sssd[krb5_child[19536]]]] [sss_child_krb5_trace_cb] (0x4000): [19536] 1603467318.15662: Sending DNS URI query for _kerberos.PKI-TEST.LOCAL.

(Fri Oct 23 18:35:18:024359 2020) [[sssd[krb5_child[19536]]]] [sss_child_krb5_trace_cb] (0x4000): [19536] 1603467318.15663: No URI records found

(Fri Oct 23 18:35:18:024393 2020) [[sssd[krb5_child[19536]]]] [sss_child_krb5_trace_cb] (0x4000): [19536] 1603467318.15664: Sending DNS SRV query for _kerberos-master._udp.PKI-TEST.LOCAL.

(Fri Oct 23 18:35:18:025103 2020) [[sssd[krb5_child[19536]]]] [sss_child_krb5_trace_cb] (0x4000): [19536] 1603467318.15665: No SRV records found

(Fri Oct 23 18:35:18:025118 2020) [[sssd[krb5_child[19536]]]] [sss_child_krb5_trace_cb] (0x4000): [19536] 1603467318.15666: Response was not from master KDC

(Fri Oct 23 18:35:18:025162 2020) [[sssd[krb5_child[19536]]]] [sss_child_krb5_trace_cb] (0x4000): [19536] 1603467318.15667: Received error from KDC: -1765328359/Additional pre-authentication required

(Fri Oct 23 18:35:18:025222 2020) [[sssd[krb5_child[19536]]]] [sss_child_krb5_trace_cb] (0x4000): [19536] 1603467318.15670: Preauthenticating using KDC method data

(Fri Oct 23 18:35:18:025241 2020) [[sssd[krb5_child[19536]]]] [sss_child_krb5_trace_cb] (0x4000): [19536] 1603467318.15671: Processing preauth types: PA-PK-AS-REQ (16), PA-PK-AS-REP_OLD (15), PA-ENC-TIMESTAMP (2), PA-ETYPE-INFO2 (19)

(Fri Oct 23 18:35:18:025268 2020) [[sssd[krb5_child[19536]]]] [sss_child_krb5_trace_cb] (0x4000): [19536] 1603467318.15672: Selected etype info: etype aes256-cts, salt "PKI-TEST.LOCALuser1", params "\x00\x00\x10\x00"

(Fri Oct 23 18:35:18:025283 2020) [[sssd[krb5_child[19536]]]] [sss_krb5_responder] (0x4000): Got question [password].
(Fri Oct 23 18:35:18:025299 2020) [[sssd[krb5_child[19536]]]] [sss_krb5_prompter] (0x4000): sss_krb5_prompter name [(null)] banner [(null)] num_prompts [1] EINVAL.
(Fri Oct 23 18:35:18:025307 2020) [[sssd[krb5_child[19536]]]] [sss_krb5_prompter] (0x4000): Prompt [0][Password for user1@PKI-TEST.LOCAL].
(Fri Oct 23 18:35:18:025315 2020) [[sssd[krb5_child[19536]]]] [sss_krb5_prompter] (0x0020): Cannot handle password prompts.
(Fri Oct 23 18:35:18:025328 2020) [[sssd[krb5_child[19536]]]] [sss_child_krb5_trace_cb] (0x4000): [19536] 1603467318.15673: Preauth module encrypted_timestamp (2) (real) returned: -1765328254/Cannot read password

(Fri Oct 23 18:35:18:025345 2020) [[sssd[krb5_child[19536]]]] [sss_krb5_get_init_creds_password] (0x0020): 1618: [-1765328174][Pre-authentication failed: Cannot read password]
(Fri Oct 23 18:35:18:025426 2020) [[sssd[krb5_child[19536]]]] [get_and_save_tgt] (0x0400): krb5_get_init_creds_password returned [-1765328174] during pre-auth.
(Fri Oct 23 18:35:18:025438 2020) [[sssd[krb5_child[19536]]]] [k5c_send_data] (0x0200): Received error code 0
(Fri Oct 23 18:35:18:025446 2020) [[sssd[krb5_child[19536]]]] [pack_response_packet] (0x2000): response packet size: [12]
(Fri Oct 23 18:35:18:025460 2020) [[sssd[krb5_child[19536]]]] [k5c_send_data] (0x4000): Response sent.
(Fri Oct 23 18:35:18:025468 2020) [[sssd[krb5_child[19536]]]] [main] (0x0400): krb5_child completed successfully

I see that pre-auth fails on asking login and password, but it cannot be used, obviously. But why was PA-PK-AS-REP_OLD/PA-PK-AS-REQ not used? I had no PIN-code prompt. How can I debug it?

xDFCx commented 4 years ago

Looks like I forgot the important:

# cat /etc/sssd/sssd.conf
[sssd]
domains = pki-test.local
config_file_version = 2
services = nss, pam
debug_level = 10
debug_microseconds = true

[domain/pki-test.local]
enumerate = True
ad_domain = pki-test.local
krb5_realm = PKI-TEST.LOCAL
realmd_tags = manages-system joined-with-samba 
cache_credentials = True
id_provider = ad
krb5_store_password_if_offline = True
default_shell = /bin/bash
ldap_id_mapping = True
use_fully_qualified_names = False
fallback_homedir = /home/%u@%d
access_provider = ad
debug_level = 10
debug_microseconds = true

[pam]
pam_cert_auth = True
debug_level = 10
debug_microseconds = true

alexey-tikhonov commented 4 years ago

Hi,

What's the content of /etc/krb5.conf and /etc/krb5.conf.d/* ?

Does running kinit manually work for you? Like:

kinit -X X509_user_identity='PKCS11:libjcPKCS11-2.so' <username>

(You might want to prepend KRB5_TRACE=/dev/stdout before kinit to get additional debug)

xDFCx commented 4 years ago

krb5.conf

# To opt out of the system crypto-policies configuration of krb5, remove the
# symlink at /etc/krb5.conf.d/crypto-policies which will not be recreated.
includedir /etc/krb5.conf.d/

[logging]
    default = FILE:/var/log/krb5libs.log
    kdc = FILE:/var/log/krb5kdc.log
    admin_server = FILE:/var/log/kadmind.log

[libdefaults]
    dns_lookup_realm = false
    ticket_lifetime = 24h
    renew_lifetime = 7d
    forwardable = true
    rdns = false
    pkinit_anchors = /etc/pki/tls/certs/ca-bundle.crt
    spake_preauth_groups = edwards25519
    default_realm = PKI-TEST.LOCAL
    default_ccache_name = KEYRING:persistent:%{uid}

[realms]
# EXAMPLE.COM = {
#     kdc = kerberos.example.com
#     admin_server = kerberos.example.com
# }

[domain_realm]
# .example.com = EXAMPLE.COM
# example.com = EXAMPLE.COM

/etc/krb5.conf.d/

# ls /etc/krb5.conf.d/
crypto-policies
# cat /etc/krb5.conf.d/crypto-policies 
# This file is automatically generated by update-crypto-policies.
permitted_enctypes = aes256-cts-hmac-sha1-96 aes128-cts-hmac-sha1-96 des3-cbc-sha1 camellia256-cts-cmac camellia128-cts-cmac

kinit

$ KRB5_TRACE=/dev/stdout
$ kinit -X X509_user_identity='PKCS11:libjcPKCS11-2.so' user1@PKI-TEST.LOCAL
Password for user1@PKI-TEST.LOCAL: 
$ klist
Ticket cache: KEYRING:persistent:1000:1000
Default principal: user1@PKI-TEST.LOCAL

Valid starting       Expires              Service principal
27.10.2020 09:34:55  27.10.2020 19:34:55  krbtgt/PKI-TEST.LOCAL@PKI-TEST.LOCAL
    renew until 03.11.2020 09:34:49

I also tried "kinit -X X509_user_identity='PKCS11:/lib64/libjcPKCS11-2.so' user1@PKI-TEST.LOCAL" and noticed, that it waits much longer (like 30 sec) before asking password. Without absolute path to the library it prompted password in just 2 seconds.

sumit-bose commented 4 years ago

Hi,

do you have the krb5-pkinit package installed?

bye, Sumit

xDFCx commented 4 years ago

It was not installed by default or by any dependency, but I tried installing it - krb5_child.log is almost the same:

(Tue Oct 27 10:55:06:550002 2020) [[sssd[krb5_child[9196]]]] [main] (0x0400): krb5_child started.
(Tue Oct 27 10:55:06:550070 2020) [[sssd[krb5_child[9196]]]] [unpack_buffer] (0x1000): total buffer size: [148]
(Tue Oct 27 10:55:06:550091 2020) [[sssd[krb5_child[9196]]]] [unpack_buffer] (0x0100): cmd [249] uid [403801106] gid [403800513] validate [true] enterprise principal [false] offline [true] UPN [user1@PKI-TEST.LOCAL]
(Tue Oct 27 10:55:06:550102 2020) [[sssd[krb5_child[9196]]]] [unpack_buffer] (0x0100): ccname: [KEYRING:persistent:403801106] old_ccname: [KEYRING:persistent:403801106] keytab: [/etc/krb5.keytab]
(Tue Oct 27 10:55:06:550262 2020) [[sssd[krb5_child[9196]]]] [check_use_fast] (0x0100): Not using FAST.
(Tue Oct 27 10:55:06:550320 2020) [[sssd[krb5_child[9196]]]] [privileged_krb5_setup] (0x0080): Cannot open the PAC responder socket
(Tue Oct 27 10:55:06:550330 2020) [[sssd[krb5_child[9196]]]] [become_user] (0x0200): Trying to become user [403801106][403800513].
(Tue Oct 27 10:55:06:550347 2020) [[sssd[krb5_child[9196]]]] [main] (0x2000): Running as [403801106][403800513].
(Tue Oct 27 10:55:06:550360 2020) [[sssd[krb5_child[9196]]]] [become_user] (0x0200): Trying to become user [403801106][403800513].
(Tue Oct 27 10:55:06:550367 2020) [[sssd[krb5_child[9196]]]] [become_user] (0x0200): Already user [403801106].
(Tue Oct 27 10:55:06:550375 2020) [[sssd[krb5_child[9196]]]] [k5c_setup] (0x2000): Running as [403801106][403800513].
(Tue Oct 27 10:55:06:550387 2020) [[sssd[krb5_child[9196]]]] [set_lifetime_options] (0x0100): No specific renewable lifetime requested.
(Tue Oct 27 10:55:06:550395 2020) [[sssd[krb5_child[9196]]]] [set_lifetime_options] (0x0100): No specific lifetime requested.
(Tue Oct 27 10:55:06:550402 2020) [[sssd[krb5_child[9196]]]] [main] (0x0400): Will perform pre-auth
(Tue Oct 27 10:55:06:550410 2020) [[sssd[krb5_child[9196]]]] [tgt_req_child] (0x1000): Attempting to get a TGT
(Tue Oct 27 10:55:06:550417 2020) [[sssd[krb5_child[9196]]]] [get_and_save_tgt] (0x0400): Attempting kinit for realm [PKI-TEST.LOCAL]
(Tue Oct 27 10:55:06:550440 2020) [[sssd[krb5_child[9196]]]] [sss_child_krb5_trace_cb] (0x4000): [9196] 1603785306.550257: Getting initial credentials for user1@PKI-TEST.LOCAL

(Tue Oct 27 10:55:06:552480 2020) [[sssd[krb5_child[9196]]]] [sss_child_krb5_trace_cb] (0x4000): [9196] 1603785306.550259: Sending unauthenticated request

(Tue Oct 27 10:55:06:552534 2020) [[sssd[krb5_child[9196]]]] [sss_child_krb5_trace_cb] (0x4000): [9196] 1603785306.550260: Sending request (208 bytes) to PKI-TEST.LOCAL

(Tue Oct 27 10:55:06:552701 2020) [[sssd[krb5_child[9196]]]] [sss_child_krb5_trace_cb] (0x4000): [9196] 1603785306.550261: Sending DNS URI query for _kerberos.PKI-TEST.LOCAL.

(Tue Oct 27 10:55:06:553869 2020) [[sssd[krb5_child[9196]]]] [sss_child_krb5_trace_cb] (0x4000): [9196] 1603785306.550262: No URI records found

(Tue Oct 27 10:55:06:553900 2020) [[sssd[krb5_child[9196]]]] [sss_child_krb5_trace_cb] (0x4000): [9196] 1603785306.550263: Sending DNS SRV query for _kerberos._udp.PKI-TEST.LOCAL.

(Tue Oct 27 10:55:06:554416 2020) [[sssd[krb5_child[9196]]]] [sss_child_krb5_trace_cb] (0x4000): [9196] 1603785306.550264: SRV answer: 0 100 88 "redos-dc-s1.pki-test.local."

(Tue Oct 27 10:55:06:554443 2020) [[sssd[krb5_child[9196]]]] [sss_child_krb5_trace_cb] (0x4000): [9196] 1603785306.550265: Sending DNS SRV query for _kerberos._tcp.PKI-TEST.LOCAL.

(Tue Oct 27 10:55:06:554877 2020) [[sssd[krb5_child[9196]]]] [sss_child_krb5_trace_cb] (0x4000): [9196] 1603785306.550266: SRV answer: 0 100 88 "redos-dc-s1.pki-test.local."

(Tue Oct 27 10:55:06:554912 2020) [[sssd[krb5_child[9196]]]] [sss_child_krb5_trace_cb] (0x4000): [9196] 1603785306.550267: Resolving hostname redos-dc-s1.pki-test.local.

(Tue Oct 27 10:55:06:556021 2020) [[sssd[krb5_child[9196]]]] [sss_child_krb5_trace_cb] (0x4000): [9196] 1603785306.550268: Sending initial UDP request to dgram 192.168.42.10:88

(Tue Oct 27 10:55:06:558527 2020) [[sssd[krb5_child[9196]]]] [sss_child_krb5_trace_cb] (0x4000): [9196] 1603785306.550269: Received answer (277 bytes) from dgram 192.168.42.10:88

(Tue Oct 27 10:55:06:558581 2020) [[sssd[krb5_child[9196]]]] [sss_child_krb5_trace_cb] (0x4000): [9196] 1603785306.550270: Sending DNS URI query for _kerberos.PKI-TEST.LOCAL.

(Tue Oct 27 10:55:06:559113 2020) [[sssd[krb5_child[9196]]]] [sss_child_krb5_trace_cb] (0x4000): [9196] 1603785306.550271: No URI records found

(Tue Oct 27 10:55:06:559130 2020) [[sssd[krb5_child[9196]]]] [sss_child_krb5_trace_cb] (0x4000): [9196] 1603785306.550272: Sending DNS SRV query for _kerberos-master._udp.PKI-TEST.LOCAL.

(Tue Oct 27 10:55:06:559682 2020) [[sssd[krb5_child[9196]]]] [sss_child_krb5_trace_cb] (0x4000): [9196] 1603785306.550273: No SRV records found

(Tue Oct 27 10:55:06:559699 2020) [[sssd[krb5_child[9196]]]] [sss_child_krb5_trace_cb] (0x4000): [9196] 1603785306.550274: Response was not from master KDC

(Tue Oct 27 10:55:06:559730 2020) [[sssd[krb5_child[9196]]]] [sss_child_krb5_trace_cb] (0x4000): [9196] 1603785306.550275: Received error from KDC: -1765328359/Additional pre-authentication required

(Tue Oct 27 10:55:06:559772 2020) [[sssd[krb5_child[9196]]]] [sss_child_krb5_trace_cb] (0x4000): [9196] 1603785306.550278: Preauthenticating using KDC method data

(Tue Oct 27 10:55:06:559785 2020) [[sssd[krb5_child[9196]]]] [sss_child_krb5_trace_cb] (0x4000): [9196] 1603785306.550279: Processing preauth types: PA-PK-AS-REQ (16), PA-PK-AS-REP_OLD (15), PA-ENC-TIMESTAMP (2), PA-ETYPE-INFO2 (19)

(Tue Oct 27 10:55:06:559806 2020) [[sssd[krb5_child[9196]]]] [sss_child_krb5_trace_cb] (0x4000): [9196] 1603785306.550280: Selected etype info: etype aes256-cts, salt "PKI-TEST.LOCALuser1", params "\x00\x00\x10\x00"

(Tue Oct 27 10:55:06:559832 2020) [[sssd[krb5_child[9196]]]] [sss_child_krb5_trace_cb] (0x4000): [9196] 1603785306.550281: PKINIT client has no configured identity; giving up

(Tue Oct 27 10:55:06:559849 2020) [[sssd[krb5_child[9196]]]] [sss_krb5_responder] (0x4000): Got question [password].
(Tue Oct 27 10:55:06:559866 2020) [[sssd[krb5_child[9196]]]] [sss_child_krb5_trace_cb] (0x4000): [9196] 1603785306.550282: PKINIT client has no configured identity; giving up

(Tue Oct 27 10:55:06:559881 2020) [[sssd[krb5_child[9196]]]] [sss_child_krb5_trace_cb] (0x4000): [9196] 1603785306.550283: Preauth module pkinit (16) (real) returned: 22/Invalid argument

(Tue Oct 27 10:55:06:559890 2020) [[sssd[krb5_child[9196]]]] [sss_child_krb5_trace_cb] (0x4000): [9196] 1603785306.550284: PKINIT client ignoring draft 9 offer from RFC 4556 KDC

(Tue Oct 27 10:55:06:559901 2020) [[sssd[krb5_child[9196]]]] [sss_child_krb5_trace_cb] (0x4000): [9196] 1603785306.550285: Preauth module pkinit (15) (real) returned: -1765328360/Preauthentication failed

(Tue Oct 27 10:55:06:559913 2020) [[sssd[krb5_child[9196]]]] [sss_krb5_prompter] (0x4000): sss_krb5_prompter name [(null)] banner [(null)] num_prompts [1] EINVAL.
(Tue Oct 27 10:55:06:559920 2020) [[sssd[krb5_child[9196]]]] [sss_krb5_prompter] (0x4000): Prompt [0][Password for user1@PKI-TEST.LOCAL].
(Tue Oct 27 10:55:06:559929 2020) [[sssd[krb5_child[9196]]]] [sss_krb5_prompter] (0x0020): Cannot handle password prompts.
(Tue Oct 27 10:55:06:559940 2020) [[sssd[krb5_child[9196]]]] [sss_child_krb5_trace_cb] (0x4000): [9196] 1603785306.550286: Preauth module encrypted_timestamp (2) (real) returned: -1765328254/Cannot read password

(Tue Oct 27 10:55:06:559955 2020) [[sssd[krb5_child[9196]]]] [sss_krb5_get_init_creds_password] (0x0020): 1618: [-1765328174][Pre-authentication failed: Invalid argument]
(Tue Oct 27 10:55:06:560035 2020) [[sssd[krb5_child[9196]]]] [get_and_save_tgt] (0x0400): krb5_get_init_creds_password returned [-1765328174] during pre-auth.
(Tue Oct 27 10:55:06:560048 2020) [[sssd[krb5_child[9196]]]] [k5c_send_data] (0x0200): Received error code 0
(Tue Oct 27 10:55:06:560057 2020) [[sssd[krb5_child[9196]]]] [pack_response_packet] (0x2000): response packet size: [12]
(Tue Oct 27 10:55:06:560071 2020) [[sssd[krb5_child[9196]]]] [k5c_send_data] (0x4000): Response sent.
(Tue Oct 27 10:55:06:560079 2020) [[sssd[krb5_child[9196]]]] [main] (0x0400): krb5_child completed successfully

Now it is not installed. Is it required?

sumit-bose commented 4 years ago

Hi,

yes, it is required so that you have a proper Kerberos ticket at the end of the authentication.

Now the next thing to check are mapping and matching rules. By default SSSD only uses certificates with the extended key usage (EKU) 'Client Authentication' which is the case for your certificates and expects that the full certificates is stored in the userCertificate attribute in the user's LDAP entry. I guess this is not the case in your environment.

Since your certificates also have EKU 'Microsoft Smartcard Login' and a user principal stored in the subject alternative names I would assume that your Windows clients will use this principal to map the certificate to a user. To tell SSSD to do the same please add

[certmap/pki-test.local/nt_principal]
maprule = (|(userPrincipalName={subject_nt_principal})(samAccountName={subject_nt_principal.short_name}))

to sssd.conf (please see man sssd.conf and man sss-certmap for details), Please note that these rules are only available with RHEL-8. If you want to use RHEL-7 clients you have to store the certificate in the LDAP userCertificate attribute.

bye, Sumit

xDFCx commented 4 years ago

Thanks for the clarification. Now I understood, that matching will work only on rhel8 distros. BTW, is it because of SSSD version or something else? Anyway, I've got RedOS which is rhel7-based. As you said, I imported the user certificate into ldap, in pem format, hex form, into userCertificate attribute via ADUC mmc snap-in. I also use LDAP Admin tool to verify - it opens directly from ldap as a valid certificate. On my redos client I ran sss_cache -E and tried auth again, getting the same:

(Tue Oct 27 12:58:01:749631 2020) [[sssd[krb5_child[9623]]]] [main] (0x0400): krb5_child started.
(Tue Oct 27 12:58:01:749701 2020) [[sssd[krb5_child[9623]]]] [unpack_buffer] (0x1000): total buffer size: [148]
(Tue Oct 27 12:58:01:749713 2020) [[sssd[krb5_child[9623]]]] [unpack_buffer] (0x0100): cmd [249] uid [403801106] gid [403800513] validate [true] enterprise principal [false] offline [true] UPN [user1@PKI-TEST.LOCAL]
(Tue Oct 27 12:58:01:749722 2020) [[sssd[krb5_child[9623]]]] [unpack_buffer] (0x0100): ccname: [KEYRING:persistent:403801106] old_ccname: [KEYRING:persistent:403801106] keytab: [/etc/krb5.keytab]
(Tue Oct 27 12:58:01:749893 2020) [[sssd[krb5_child[9623]]]] [check_use_fast] (0x0100): Not using FAST.
(Tue Oct 27 12:58:01:749949 2020) [[sssd[krb5_child[9623]]]] [privileged_krb5_setup] (0x0080): Cannot open the PAC responder socket
(Tue Oct 27 12:58:01:749959 2020) [[sssd[krb5_child[9623]]]] [become_user] (0x0200): Trying to become user [403801106][403800513].
(Tue Oct 27 12:58:01:749988 2020) [[sssd[krb5_child[9623]]]] [main] (0x2000): Running as [403801106][403800513].
(Tue Oct 27 12:58:01:750005 2020) [[sssd[krb5_child[9623]]]] [become_user] (0x0200): Trying to become user [403801106][403800513].
(Tue Oct 27 12:58:01:750013 2020) [[sssd[krb5_child[9623]]]] [become_user] (0x0200): Already user [403801106].
(Tue Oct 27 12:58:01:750020 2020) [[sssd[krb5_child[9623]]]] [k5c_setup] (0x2000): Running as [403801106][403800513].
(Tue Oct 27 12:58:01:750033 2020) [[sssd[krb5_child[9623]]]] [set_lifetime_options] (0x0100): No specific renewable lifetime requested.
(Tue Oct 27 12:58:01:750041 2020) [[sssd[krb5_child[9623]]]] [set_lifetime_options] (0x0100): No specific lifetime requested.
(Tue Oct 27 12:58:01:750048 2020) [[sssd[krb5_child[9623]]]] [main] (0x0400): Will perform pre-auth
(Tue Oct 27 12:58:01:750056 2020) [[sssd[krb5_child[9623]]]] [tgt_req_child] (0x1000): Attempting to get a TGT
(Tue Oct 27 12:58:01:750064 2020) [[sssd[krb5_child[9623]]]] [get_and_save_tgt] (0x0400): Attempting kinit for realm [PKI-TEST.LOCAL]
(Tue Oct 27 12:58:01:750089 2020) [[sssd[krb5_child[9623]]]] [sss_child_krb5_trace_cb] (0x4000): [9623] 1603792681.749887: Getting initial credentials for user1@PKI-TEST.LOCAL

(Tue Oct 27 12:58:01:752125 2020) [[sssd[krb5_child[9623]]]] [sss_child_krb5_trace_cb] (0x4000): [9623] 1603792681.749889: Sending unauthenticated request

(Tue Oct 27 12:58:01:752169 2020) [[sssd[krb5_child[9623]]]] [sss_child_krb5_trace_cb] (0x4000): [9623] 1603792681.749890: Sending request (208 bytes) to PKI-TEST.LOCAL

(Tue Oct 27 12:58:01:752294 2020) [[sssd[krb5_child[9623]]]] [sss_child_krb5_trace_cb] (0x4000): [9623] 1603792681.749891: Sending DNS URI query for _kerberos.PKI-TEST.LOCAL.

(Tue Oct 27 12:58:01:753385 2020) [[sssd[krb5_child[9623]]]] [sss_child_krb5_trace_cb] (0x4000): [9623] 1603792681.749892: No URI records found

(Tue Oct 27 12:58:01:753416 2020) [[sssd[krb5_child[9623]]]] [sss_child_krb5_trace_cb] (0x4000): [9623] 1603792681.749893: Sending DNS SRV query for _kerberos._udp.PKI-TEST.LOCAL.

(Tue Oct 27 12:58:01:753958 2020) [[sssd[krb5_child[9623]]]] [sss_child_krb5_trace_cb] (0x4000): [9623] 1603792681.749894: SRV answer: 0 100 88 "redos-dc-s1.pki-test.local."

(Tue Oct 27 12:58:01:753975 2020) [[sssd[krb5_child[9623]]]] [sss_child_krb5_trace_cb] (0x4000): [9623] 1603792681.749895: Sending DNS SRV query for _kerberos._tcp.PKI-TEST.LOCAL.

(Tue Oct 27 12:58:01:754461 2020) [[sssd[krb5_child[9623]]]] [sss_child_krb5_trace_cb] (0x4000): [9623] 1603792681.749896: SRV answer: 0 100 88 "redos-dc-s1.pki-test.local."

(Tue Oct 27 12:58:01:754486 2020) [[sssd[krb5_child[9623]]]] [sss_child_krb5_trace_cb] (0x4000): [9623] 1603792681.749897: Resolving hostname redos-dc-s1.pki-test.local.

(Tue Oct 27 12:58:01:755830 2020) [[sssd[krb5_child[9623]]]] [sss_child_krb5_trace_cb] (0x4000): [9623] 1603792681.749898: Sending initial UDP request to dgram 192.168.42.10:88

(Tue Oct 27 12:58:01:758499 2020) [[sssd[krb5_child[9623]]]] [sss_child_krb5_trace_cb] (0x4000): [9623] 1603792681.749899: Received answer (277 bytes) from dgram 192.168.42.10:88

(Tue Oct 27 12:58:01:758549 2020) [[sssd[krb5_child[9623]]]] [sss_child_krb5_trace_cb] (0x4000): [9623] 1603792681.749900: Sending DNS URI query for _kerberos.PKI-TEST.LOCAL.

(Tue Oct 27 12:58:01:759030 2020) [[sssd[krb5_child[9623]]]] [sss_child_krb5_trace_cb] (0x4000): [9623] 1603792681.749901: No URI records found

(Tue Oct 27 12:58:01:759045 2020) [[sssd[krb5_child[9623]]]] [sss_child_krb5_trace_cb] (0x4000): [9623] 1603792681.749902: Sending DNS SRV query for _kerberos-master._udp.PKI-TEST.LOCAL.

(Tue Oct 27 12:58:01:759446 2020) [[sssd[krb5_child[9623]]]] [sss_child_krb5_trace_cb] (0x4000): [9623] 1603792681.749903: No SRV records found

(Tue Oct 27 12:58:01:759461 2020) [[sssd[krb5_child[9623]]]] [sss_child_krb5_trace_cb] (0x4000): [9623] 1603792681.749904: Response was not from master KDC

(Tue Oct 27 12:58:01:759492 2020) [[sssd[krb5_child[9623]]]] [sss_child_krb5_trace_cb] (0x4000): [9623] 1603792681.749905: Received error from KDC: -1765328359/Additional pre-authentication required

(Tue Oct 27 12:58:01:759531 2020) [[sssd[krb5_child[9623]]]] [sss_child_krb5_trace_cb] (0x4000): [9623] 1603792681.749908: Preauthenticating using KDC method data

(Tue Oct 27 12:58:01:759544 2020) [[sssd[krb5_child[9623]]]] [sss_child_krb5_trace_cb] (0x4000): [9623] 1603792681.749909: Processing preauth types: PA-PK-AS-REQ (16), PA-PK-AS-REP_OLD (15), PA-ENC-TIMESTAMP (2), PA-ETYPE-INFO2 (19)

(Tue Oct 27 12:58:01:759566 2020) [[sssd[krb5_child[9623]]]] [sss_child_krb5_trace_cb] (0x4000): [9623] 1603792681.749910: Selected etype info: etype aes256-cts, salt "PKI-TEST.LOCALuser1", params "\x00\x00\x10\x00"

(Tue Oct 27 12:58:01:759590 2020) [[sssd[krb5_child[9623]]]] [sss_child_krb5_trace_cb] (0x4000): [9623] 1603792681.749911: PKINIT client has no configured identity; giving up

(Tue Oct 27 12:58:01:759601 2020) [[sssd[krb5_child[9623]]]] [sss_krb5_responder] (0x4000): Got question [password].
(Tue Oct 27 12:58:01:759617 2020) [[sssd[krb5_child[9623]]]] [sss_child_krb5_trace_cb] (0x4000): [9623] 1603792681.749912: PKINIT client has no configured identity; giving up

(Tue Oct 27 12:58:01:759630 2020) [[sssd[krb5_child[9623]]]] [sss_child_krb5_trace_cb] (0x4000): [9623] 1603792681.749913: Preauth module pkinit (16) (real) returned: 22/Invalid argument

(Tue Oct 27 12:58:01:759640 2020) [[sssd[krb5_child[9623]]]] [sss_child_krb5_trace_cb] (0x4000): [9623] 1603792681.749914: PKINIT client ignoring draft 9 offer from RFC 4556 KDC

(Tue Oct 27 12:58:01:759650 2020) [[sssd[krb5_child[9623]]]] [sss_child_krb5_trace_cb] (0x4000): [9623] 1603792681.749915: Preauth module pkinit (15) (real) returned: -1765328360/Preauthentication failed

(Tue Oct 27 12:58:01:759662 2020) [[sssd[krb5_child[9623]]]] [sss_krb5_prompter] (0x4000): sss_krb5_prompter name [(null)] banner [(null)] num_prompts [1] EINVAL.
(Tue Oct 27 12:58:01:759670 2020) [[sssd[krb5_child[9623]]]] [sss_krb5_prompter] (0x4000): Prompt [0][Password for user1@PKI-TEST.LOCAL].
(Tue Oct 27 12:58:01:759677 2020) [[sssd[krb5_child[9623]]]] [sss_krb5_prompter] (0x0020): Cannot handle password prompts.
(Tue Oct 27 12:58:01:759689 2020) [[sssd[krb5_child[9623]]]] [sss_child_krb5_trace_cb] (0x4000): [9623] 1603792681.749916: Preauth module encrypted_timestamp (2) (real) returned: -1765328254/Cannot read password

(Tue Oct 27 12:58:01:759704 2020) [[sssd[krb5_child[9623]]]] [sss_krb5_get_init_creds_password] (0x0020): 1618: [-1765328174][Pre-authentication failed: Invalid argument]
(Tue Oct 27 12:58:01:759821 2020) [[sssd[krb5_child[9623]]]] [get_and_save_tgt] (0x0400): krb5_get_init_creds_password returned [-1765328174] during pre-auth.
(Tue Oct 27 12:58:01:759834 2020) [[sssd[krb5_child[9623]]]] [k5c_send_data] (0x0200): Received error code 0
(Tue Oct 27 12:58:01:759842 2020) [[sssd[krb5_child[9623]]]] [pack_response_packet] (0x2000): response packet size: [12]
(Tue Oct 27 12:58:01:759856 2020) [[sssd[krb5_child[9623]]]] [k5c_send_data] (0x4000): Response sent.
(Tue Oct 27 12:58:01:759864 2020) [[sssd[krb5_child[9623]]]] [main] (0x0400): krb5_child completed successfully

sumit-bose commented 4 years ago

Hi,

the certificate should be stored in a binary format, see https://sssd.io/docs/design_pages/smartcard_authentication_testing_with_ad.html#writing-the-certificate-to-ad for an example how this can be done.

To figure out why the certificate cannot be mapped to the user you have to check sssd_pam.log and the domain logs file. In the pam log file you should see that SSSD get the certificates from the Smartcard and use them to look up the matching user. During this it might be possible that the pam responder sends a request to the backend to look up the user by certificates. This request should then be found in the domain log together with the used LDAP search filters etc.

HTH

bye, Sumit

xDFCx commented 4 years ago

Ok, I readded the certificate as in sssd documentatition you mentioned (actually the result is the same). Now I'm not sure what to look for in sssd_pam.log. Something like that may be, but I still dont understand whats wrong.

(Tue Oct 27 14:32:42:020688 2020) [sssd[pam]] [cache_req_search_cache] (0x0400): CR #2: Object [user1@implicit_files] was not found in cache
(Tue Oct 27 14:32:42:020697 2020) [sssd[pam]] [cache_req_search_ncache_add_to_domain] (0x0400): CR #2: Adding [user1@implicit_files] to negative cache
(Tue Oct 27 14:32:42:020736 2020) [sssd[pam]] [is_user_local_by_name] (0x0400): User user1@implicit_files is a local user
(Tue Oct 27 14:32:42:020745 2020) [sssd[pam]] [sss_ncache_set_str] (0x0400): Adding [NCE/USER/implicit_files/user1@implicit_files] to negative cache
(Tue Oct 27 14:32:42:020760 2020) [sssd[pam]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain pki-test.local type POSIX is valid
(Tue Oct 27 14:32:42:020769 2020) [sssd[pam]] [cache_req_set_domain] (0x0400): CR #2: Using domain [pki-test.local]
(Tue Oct 27 14:32:42:020777 2020) [sssd[pam]] [cache_req_prepare_domain_data] (0x0400): CR #2: Preparing input data for domain [pki-test.local] rules
(Tue Oct 27 14:32:42:020788 2020) [sssd[pam]] [cache_req_search_send] (0x0400): CR #2: Looking up user1@pki-test.local
(Tue Oct 27 14:32:42:020796 2020) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #2: Checking negative cache for [user1@pki-test.local]
(Tue Oct 27 14:32:42:020805 2020) [sssd[pam]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/pki-test.local/user1@pki-test.local]
(Tue Oct 27 14:32:42:020813 2020) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #2: [user1@pki-test.local] is not present in negative cache
(Tue Oct 27 14:32:42:020821 2020) [sssd[pam]] [cache_req_search_dp] (0x0400): CR #2: Looking up [user1@pki-test.local] in data provider
(Tue Oct 27 14:32:42:020830 2020) [sssd[pam]] [sss_dp_get_account_send] (0x0400): Creating request for [pki-test.local][0x3][BE_REQ_INITGROUPS][name=user1@pki-test.local:-]
(Tue Oct 27 14:32:42:022912 2020) [sssd[pam]] [sbus_dispatch] (0x4000): Dispatching.
(Tue Oct 27 14:32:42:022941 2020) [sssd[pam]] [sbus_reply_check] (0x4000): D-Bus error [org.freedesktop.DBus.Error.Disconnected]: SSSD is offline
(Tue Oct 27 14:32:42:022957 2020) [sssd[pam]] [cache_req_common_process_dp_reply] (0x0040): CR #2: Could not get account info [1432158212]: SSSD is offline
(Tue Oct 27 14:32:42:022965 2020) [sssd[pam]] [cache_req_common_process_dp_reply] (0x0400): CR #2: Due to an error we will return cached data
(Tue Oct 27 14:32:42:022973 2020) [sssd[pam]] [cache_req_search_cache] (0x0400): CR #2: Looking up [user1@pki-test.local] in cache
(Tue Oct 27 14:32:42:023008 2020) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x559aa21e1210

(Tue Oct 27 14:32:42:023017 2020) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x559aa21e12e0

(Tue Oct 27 14:32:42:023026 2020) [sssd[pam]] [ldb] (0x4000): Running timer event 0x559aa21e1210 "ltdb_callback"

(Tue Oct 27 14:32:42:023108 2020) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x559aa21e12e0 "ltdb_timeout"

(Tue Oct 27 14:32:42:023118 2020) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x559aa21e1210 "ltdb_callback"

(Tue Oct 27 14:32:42:023154 2020) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x559aa21fa440

(Tue Oct 27 14:32:42:023163 2020) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x559aa21e0fe0

(Tue Oct 27 14:32:42:023171 2020) [sssd[pam]] [ldb] (0x4000): Running timer event 0x559aa21fa440 "ltdb_callback"

(Tue Oct 27 14:32:42:023195 2020) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x559aa21e0fe0 "ltdb_timeout"

(Tue Oct 27 14:32:42:023204 2020) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x559aa21fa440 "ltdb_callback"

(Tue Oct 27 14:32:42:023238 2020) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x559aa21fa3a0

(Tue Oct 27 14:32:42:023249 2020) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x559aa21fa7c0

(Tue Oct 27 14:32:42:023258 2020) [sssd[pam]] [ldb] (0x4000): Running timer event 0x559aa21fa3a0 "ltdb_callback"

(Tue Oct 27 14:32:42:023287 2020) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x559aa21ffd10

(Tue Oct 27 14:32:42:023296 2020) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x559aa21ffde0

(Tue Oct 27 14:32:42:023305 2020) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x559aa21fa7c0 "ltdb_timeout"

(Tue Oct 27 14:32:42:023320 2020) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x559aa21fa3a0 "ltdb_callback"

(Tue Oct 27 14:32:42:023329 2020) [sssd[pam]] [ldb] (0x4000): Running timer event 0x559aa21ffd10 "ltdb_callback"

(Tue Oct 27 14:32:42:023360 2020) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x559aa22007b0

(Tue Oct 27 14:32:42:023370 2020) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x559aa2200880

(Tue Oct 27 14:32:42:023379 2020) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x559aa21ffde0 "ltdb_timeout"

(Tue Oct 27 14:32:42:023387 2020) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x559aa21ffd10 "ltdb_callback"

(Tue Oct 27 14:32:42:023396 2020) [sssd[pam]] [ldb] (0x4000): Running timer event 0x559aa22007b0 "ltdb_callback"

(Tue Oct 27 14:32:42:023431 2020) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x559aa2200880 "ltdb_timeout"

(Tue Oct 27 14:32:42:023442 2020) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x559aa22007b0 "ltdb_callback"

(Tue Oct 27 14:32:42:023459 2020) [sssd[pam]] [cache_req_search_ncache_filter] (0x0400): CR #2: This request type does not support filtering result by negative cache
(Tue Oct 27 14:32:42:023467 2020) [sssd[pam]] [cache_req_search_done] (0x0400): CR #2: Returning updated object [user1@pki-test.local]
(Tue Oct 27 14:32:42:023477 2020) [sssd[pam]] [cache_req_create_and_add_result] (0x0400): CR #2: Found 3 entries in domain pki-test.local
(Tue Oct 27 14:32:42:023495 2020) [sssd[pam]] [cache_req_done] (0x0400): CR #2: Finished: Success
(Tue Oct 27 14:32:42:023506 2020) [sssd[pam]] [pd_set_primary_name] (0x0400): User's primary name is user1@pki-test.local
(Tue Oct 27 14:32:42:023516 2020) [sssd[pam]] [pam_initgr_cache_set] (0x2000): [user1] added to PAM initgroup cache
(Tue Oct 27 14:32:42:023526 2020) [sssd[pam]] [pam_dp_send_req] (0x0100): Sending request with the following data:
(Tue Oct 27 14:32:42:023534 2020) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_PREAUTH
(Tue Oct 27 14:32:42:023542 2020) [sssd[pam]] [pam_print_data] (0x0100): domain: pki-test.local
(Tue Oct 27 14:32:42:023549 2020) [sssd[pam]] [pam_print_data] (0x0100): user: user1@pki-test.local
(Tue Oct 27 14:32:42:023557 2020) [sssd[pam]] [pam_print_data] (0x0100): service: su
(Tue Oct 27 14:32:42:023564 2020) [sssd[pam]] [pam_print_data] (0x0100): tty: pts/0
(Tue Oct 27 14:32:42:023572 2020) [sssd[pam]] [pam_print_data] (0x0100): ruser: user
(Tue Oct 27 14:32:42:023579 2020) [sssd[pam]] [pam_print_data] (0x0100): rhost: not set
(Tue Oct 27 14:32:42:023586 2020) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0
(Tue Oct 27 14:32:42:023594 2020) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0
(Tue Oct 27 14:32:42:023602 2020) [sssd[pam]] [pam_print_data] (0x0100): priv: 0
(Tue Oct 27 14:32:42:023609 2020) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 10686
(Tue Oct 27 14:32:42:023617 2020) [sssd[pam]] [pam_print_data] (0x0100): logon name: user1
(Tue Oct 27 14:32:42:023624 2020) [sssd[pam]] [pam_print_data] (0x0100): flags: 0
(Tue Oct 27 14:32:42:023761 2020) [sssd[pam]] [pam_dom_forwarder] (0x0100): pam_dp_send_req returned 0
(Tue Oct 27 14:32:42:047953 2020) [sssd[pam]] [sbus_dispatch] (0x4000): Dispatching.
(Tue Oct 27 14:32:42:048335 2020) [sssd[pam]] [pam_dp_send_req_done] (0x0200): received: [9 (Службе проверки подлинности не удается загрузить сведения аутентификации)][pki-test.local]
(Tue Oct 27 14:32:42:048492 2020) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x559aa21ff450

(Tue Oct 27 14:32:42:048534 2020) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x559aa21ff520

(Tue Oct 27 14:32:42:048566 2020) [sssd[pam]] [ldb] (0x4000): Running timer event 0x559aa21ff450 "ltdb_callback"

(Tue Oct 27 14:32:42:048641 2020) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x559aa21ff520 "ltdb_timeout"

(Tue Oct 27 14:32:42:048675 2020) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x559aa21ff450 "ltdb_callback"

(Tue Oct 27 14:32:42:048749 2020) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [9]: Службе проверки подлинности не удается загрузить сведения аутентификации.
(Tue Oct 27 14:32:42:048781 2020) [sssd[pam]] [pam_reply] (0x0020): Unknown PAM call [249].
(Tue Oct 27 14:32:42:048858 2020) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x559aa21ff8d0

(Tue Oct 27 14:32:42:048893 2020) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x559aa21ff450

(Tue Oct 27 14:32:42:048924 2020) [sssd[pam]] [ldb] (0x4000): Running timer event 0x559aa21ff8d0 "ltdb_callback"

(Tue Oct 27 14:32:42:048996 2020) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x559aa21ff450 "ltdb_timeout"

(Tue Oct 27 14:32:42:049030 2020) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x559aa21ff8d0 "ltdb_callback"

(Tue Oct 27 14:32:42:049093 2020) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x559aa21fee00

(Tue Oct 27 14:32:42:049116 2020) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x559aa21fcb10

(Tue Oct 27 14:32:42:049136 2020) [sssd[pam]] [ldb] (0x4000): Running timer event 0x559aa21fee00 "ltdb_callback"

(Tue Oct 27 14:32:42:049175 2020) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x559aa21fcb10 "ltdb_timeout"

(Tue Oct 27 14:32:42:049197 2020) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x559aa21fee00 "ltdb_callback"

(Tue Oct 27 14:32:42:049227 2020) [sssd[pam]] [filter_responses] (0x0100): [pam_response_filter] not available, not fatal.
(Tue Oct 27 14:32:42:049250 2020) [sssd[pam]] [pam_reply] (0x0200): blen: 39
(Tue Oct 27 14:32:45:932950 2020) [sssd[pam]] [client_recv] (0x0200): Client disconnected!
(Tue Oct 27 14:32:45:933042 2020) [sssd[pam]] [client_close_fn] (0x2000): Terminated client [0x559aa21dfdc0][27]
(Tue Oct 27 14:32:47:025220 2020) [sssd[pam]] [pam_initgr_cache_remove] (0x2000): [user1] removed from PAM initgroup cache

krb5_child.log ldap_child.log p11_child.log sssd.log

sumit-bose commented 4 years ago

Hi,

it look like the backend is offline, i.e. cannot connect to the LDAP service of a DC. Please check the domain log for indications why the backend is offline.

Btw, I would recommend to remove enumerate = True.

bye, Sumit

xDFCx commented 4 years ago

Hi. Thats all I see in samba log connected to user1 and preauth:

[2020/10/28 10:25:31.596128,  3] ../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
  Kerberos: AS-REQ user1@PKI-TEST.LOCAL from ipv4:192.168.42.77:51204 for krbtgt/PKI-TEST.LOCAL@PKI-TEST.LOCAL
[2020/10/28 10:25:31.597420,  6] ../lib/util/util_ldb.c:60(gendb_search_v)
  gendb_search_v: DC=pki-test,DC=local NULL -> 1
[2020/10/28 10:25:31.598802,  6] ../lib/util/util_ldb.c:60(gendb_search_v)
  gendb_search_v: DC=pki-test,DC=local NULL -> 1
[2020/10/28 10:25:31.598982,  6] ../lib/util/util_ldb.c:60(gendb_search_v)
  gendb_search_v: DC=pki-test,DC=local NULL -> 1
[2020/10/28 10:25:31.599133,  3] ../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
  Kerberos: Client sent patypes: 150, 149
[2020/10/28 10:25:31.599147,  3] ../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
  Kerberos: Looking for PKINIT pa-data -- user1@PKI-TEST.LOCAL
[2020/10/28 10:25:31.599158,  3] ../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
  Kerberos: Looking for ENC-TS pa-data -- user1@PKI-TEST.LOCAL
[2020/10/28 10:25:31.599187,  3] ../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
  Kerberos: No preauth found, returning PREAUTH-REQUIRED -- user1@PKI-TEST.LOCAL

samba.log

Also a lot of DNS queries. I still don't see anything that could say me that something is wrong, And as I mentioned yesterday, kerberos and samba just can't fail working, because I've got win7 client smartcard auth working, with exactly theese certs, that are on the token now.

sumit-bose commented 4 years ago

Hi,

sorry for not being clear with 'domain log' I meant the SSSD domain log /var/log/sssd/sssd_pki-test.local. Here you should find the reason why SSSD is offline.

bye, Sumit

xDFCx commented 4 years ago

sssd_pki-test.local.log Does SSSD go offline because of this?

(Wed Oct 28 12:56:47:843126 2020) [sssd[be[pki-test.local]]] [sdap_id_op_connect_done] (0x4000): notify offline to op #1
(Wed Oct 28 12:56:47:843138 2020) [sssd[be[pki-test.local]]] [ad_subdomains_refresh_connect_done] (0x0020): Unable to connect to LDAP [11]: Ресурс временно недоступен
(Wed Oct 28 12:56:47:843152 2020) [sssd[be[pki-test.local]]] [ad_subdomains_refresh_connect_done] (0x0080): No AD server is available, cannot get the subdomain list while offline
(Wed Oct 28 12:56:47:843164 2020) [sssd[be[pki-test.local]]] [be_ptask_done] (0x0040): Task [Subdomains Refresh]: failed with [1432158212]: SSSD is offline
(Wed Oct 28 12:56:47:843173 2020) [sssd[be[pki-test.local]]] [be_ptask_schedule] (0x0400): Task [Subdomains Refresh]: scheduling task 14400 seconds from now [1603893407]
(Wed Oct 28 12:56:47:843180 2020) [sssd[be[pki-test.local]]] [sdap_id_op_connect_done] (0x4000): notify offline to op #2
(Wed Oct 28 12:56:47:843196 2020) [sssd[be[pki-test.local]]] [ad_subdomains_refresh_connect_done] (0x0020): Unable to connect to LDAP [11]: Ресурс временно недоступен
(Wed Oct 28 12:56:47:843204 2020) [sssd[be[pki-test.local]]] [ad_subdomains_refresh_connect_done] (0x0080): No AD server is available, cannot get the subdomain list while offline
(Wed Oct 28 12:56:47:843215 2020) [sssd[be[pki-test.local]]] [dp_req_done] (0x0400): DP Request [Subdomains #0]: Request handler finished [0]: Выполнено
(Wed Oct 28 12:56:47:843224 2020) [sssd[be[pki-test.local]]] [_dp_req_recv] (0x0400): DP Request [Subdomains #0]: Receiving request data.
(Wed Oct 28 12:56:47:843234 2020) [sssd[be[pki-test.local]]] [dp_req_destructor] (0x0400): DP Request [Subdomains #0]: Request removed.
(Wed Oct 28 12:56:47:843241 2020) [sssd[be[pki-test.local]]] [dp_req_destructor] (0x0400): Number of active DP request: 0
(Wed Oct 28 12:56:47:843251 2020) [sssd[be[pki-test.local]]] [dp_req_reply_std] (0x1000): DP Request [Subdomains #0]: Returning [Provider is Offline]: 1,1432158212,Offline
(Wed Oct 28 12:56:47:843302 2020) [sssd[be[pki-test.local]]] [sbus_issue_request_done] (0x0400): sssd.dataprovider.getDomains: Success
(Wed Oct 28 12:56:47:843340 2020) [sssd[be[pki-test.local]]] [sdap_id_release_conn_data] (0x4000): releasing unused connection

Then I dont get why it cannot connect to LDAP - firewalls and selinux are off on both domain controller and client. On DC samba is listening all necessary ports: Also win7 client works fine. I'm confused...

sumit-bose commented 4 years ago

Hi,

the issue happens a bit before the log snippet you have pasted. Authentication with the keytab failed.

Does

kinit -k 'REDOS-CLIENT-S1$@PKI-TEST.LOCAL'

work (please do not forget the ' around the principal)? If not please try to join the domain again or refresh the machine accoutn password and the keytab by other means.

bye, Sumit

xDFCx commented 4 years ago

Yeah, OS on this VM was reinstalled after it was joined to domain and then got the same name and joined domain again, without cleaning up previous entry in ldap. IDK what else is wrong with this VM, so i decided to set up a new one from the very beginning. Now I see, that it looks for a cert in ldap and doesn't find it. But if I look through the user's attributes in ADUC or in LDAPadmin i see this cert, the one that starts with "\30\82\04\e8\30" in userCertificate. I don't understand how could the search return 0 results. sssd_pki-test.local.log

xDFCx commented 4 years ago

Hi. I tried to copy cert hex data from the ldap request, then replace all slashes with spaces and paste it into AD. Still have 0 results in ldap search. I have no idea why. I also tried adding that mapping rule from https://github.com/SSSD/sssd/issues/5377#issuecomment-717088647 now I see this sssd_pki-test.local.log

sumit-bose commented 4 years ago

Hi,

the content of the userCertifcate attribute really has to be binary. I do not think you can add it with any copy-and-paste method. I do not know if there is a way on the windows side to properly import the binary data. I would recommend the ldapmodify way from https://sssd.io/docs/design_pages/smartcard_authentication_testing_with_ad.html#writing-the-certificate-to-ad.

In this logs with mapping rules it looks like the user way found and that you were asked for a PIN. Also it looks like the authentication was successful. The next step would be access control but this is not covered in the logs. Was the su command asking you for a PIN and was it successful in the end?

bye, Sumit

xDFCx commented 4 years ago

Ok, again, as in docs:

[root@redos-client2-s1 tmp]# /usr/libexec/sssd/p11_child --pre --nssdb=/etc/pki/nssdb | tail -1 | base64 -d > cert.der
[root@redos-client2-s1 tmp]# klist
Ticket cache: FILE:/tmp/krb5cc_0
Default principal: user1@PKI-TEST.LOCAL

Valid starting       Expires              Service principal
29.10.2020 13:30:54  29.10.2020 23:30:54  krbtgt/PKI-TEST.LOCAL@PKI-TEST.LOCAL
    renew until 05.11.2020 13:30:50
29.10.2020 13:32:20  29.10.2020 23:30:54  ldap/redos-dc-s1.pki-test.local@
    renew until 05.11.2020 13:30:50
29.10.2020 13:32:20  29.10.2020 23:30:54  ldap/redos-dc-s1.pki-test.local@PKI-TEST.LOCAL
    renew until 05.11.2020 13:30:50
[root@redos-client2-s1 tmp]# ldapsearch -Y GSSAPI -H ldap://redos-dc-s1.pki-test.local -b 'dc=pki-test,dc=local' samaccountname=user1 dn
SASL/GSSAPI authentication started
SASL username: user1@PKI-TEST.LOCAL
SASL SSF: 56
SASL data security layer installed.
# extended LDIF
#
# LDAPv3
# base <dc=pki-test,dc=local> with scope subtree
# filter: samaccountname=user1
# requesting: dn 
#

# user1, corp, pki-test.local
dn: CN=user1,OU=corp,DC=pki-test,DC=local

# search reference
ref: ldap://pki-test.local/CN=Configuration,DC=pki-test,DC=local

# search reference
ref: ldap://pki-test.local/DC=DomainDnsZones,DC=pki-test,DC=local

# search reference
ref: ldap://pki-test.local/DC=ForestDnsZones,DC=pki-test,DC=local

# search result
search: 4
result: 0 Success

# numResponses: 5
# numEntries: 1
# numReferences: 3
[root@redos-client2-s1 tmp]# cat ./user1.ldif 
dn: CN=user1,OU=corp,DC=pki-test,DC=local
changetype: modify
add: userCertificate
userCertificate:< file:cert.der
[root@redos-client2-s1 tmp]# ldapmodify -Y GSSAPI -H ldap://redos-dc-s1.pki-test.local -f user1.ldif 
SASL/GSSAPI authentication started
SASL username: user1@PKI-TEST.LOCAL
SASL SSF: 56
SASL data security layer installed.
modifying entry "CN=user1,OU=corp,DC=pki-test,DC=local"

then

[user@redos-client2-s1 ~]$ su user1
Please select a certificate by typing the corresponding number

[1]:
- no label found -
E=user1@pki-test.local,CN=user1

[2]:
- no label found -
E=user1@pki-test.local,CN=user1@pki-test.local
1
Certificate ‘1616’ selected
PIN for jacarta
su: Authentication failure

sssd_pki-test.local.log

sumit-bose commented 4 years ago

Hi,

thanks, can you add sssd_pam.log and krb5_child.log from the attempt above as well?

bye, Sumit

xDFCx commented 4 years ago

Sure krb5_child.log

sssd_pam.log

xDFCx commented 4 years ago

Tried deleting one container from token (id 4321) - generally nothing changed, I now have no prompt for cert number from token. @sumit-bose may be you have any ideas what I should try to do? P.S. sssd is version 2.0.0-8.el7

alexey-tikhonov commented 4 years ago

P.S. sssd is version 2.0.0-8.el7

Where does this package came from? IIRC CentOS 7 is based on 1.16 branch. 2.x is for CentOS 8 but this version is very old.

sumit-bose commented 4 years ago

Hi,

which version of krb5-libs and krb5-pkinit are you using? From the logs it looks like that the certificate id is not used by the pkinit plugin. Can you send the output of

KRB5_TRACE=/dev/stdout kinit -X X509_user_identity='PKCS11:module_name=/lib64/libjcPKCS11-2.so:token=jacarta:certid=1616' user1@PKI-TEST.LOCAL

for verification?

Currently there is no label assigned to the certificate on the Smartcard and in general this should not be needed but besides the certificate id the label is other way to uniquely identify a certificate and private-key pair.

Can you send the output of

p11tool --login --provider=/lib64/libjcPKCS11-2.so --list-all

you will be asked for the PIN so that certificate ids and labels on the private keys can be read as well.

bye, Sumit

xDFCx commented 4 years ago

@alexey-tikhonov RedOS 7.2 distro, centos7-based, got this version of sssd in repos.

xDFCx commented 4 years ago

@sumit-bose I've created new user and a new cert for it, so its now user2. Tested on win7 client - it allows to login, so now on linux:

[root@redos-client2-s1 sssd]# yum list installed|grep krb5
krb5-libs.x86_64                      1.16.1-24.el7            @anaconda/rawhide
krb5-pkinit.x86_64                    1.16.1-24.el7            @base            
krb5-server.x86_64                    1.16.1-24.el7            @anaconda/rawhide
krb5-workstation.x86_64               1.16.1-24.el7            @anaconda/rawhide
sssd-krb5.x86_64                      2.0.0-8.el7              @anaconda/rawhide
sssd-krb5-common.x86_64               2.0.0-8.el7              @anaconda/rawhide

[root@redos-client2-s1 sssd]# pkcs11-tool --module /lib64/libjcPKCS11-2.so -O
Using slot 0 with a present token (0x1ffff)
Certificate Object; type = X.509 cert
  label:      PKI
  ID:         7573657232

[root@redos-client2-s1 sssd]# /usr/libexec/sssd/p11_child --pre --nssdb=/etc/pki/nssdb -d 10 --debug-fd=2
(Fri Oct 30 09:55:30:215589 2020) [[sssd[p11_child[9556]]]] [main] (0x0400): p11_child started.
(Fri Oct 30 09:55:30:215650 2020) [[sssd[p11_child[9556]]]] [main] (0x2000): Running in [pre-auth] mode.
(Fri Oct 30 09:55:30:215659 2020) [[sssd[p11_child[9556]]]] [main] (0x2000): Running with effective IDs: [0][0].
(Fri Oct 30 09:55:30:215667 2020) [[sssd[p11_child[9556]]]] [main] (0x2000): Running with real IDs [0][0].
(Fri Oct 30 09:55:32:554857 2020) [[sssd[p11_child[9556]]]] [do_card] (0x4000): Default Module List:
(Fri Oct 30 09:55:32:554907 2020) [[sssd[p11_child[9556]]]] [do_card] (0x4000): common name: [NSS Internal PKCS #11 Module].
(Fri Oct 30 09:55:32:554920 2020) [[sssd[p11_child[9556]]]] [do_card] (0x4000): dll name: [(null)].
(Fri Oct 30 09:55:32:554930 2020) [[sssd[p11_child[9556]]]] [do_card] (0x4000): common name: [JaCarta].
(Fri Oct 30 09:55:32:554938 2020) [[sssd[p11_child[9556]]]] [do_card] (0x4000): dll name: [/lib64/libjcPKCS11-2.so].
(Fri Oct 30 09:55:32:554945 2020) [[sssd[p11_child[9556]]]] [do_card] (0x4000): Dead Module List:
(Fri Oct 30 09:55:32:554952 2020) [[sssd[p11_child[9556]]]] [do_card] (0x4000): DB Module List:
(Fri Oct 30 09:55:32:554962 2020) [[sssd[p11_child[9556]]]] [do_card] (0x4000): common name: [NSS Internal Module].
(Fri Oct 30 09:55:32:554969 2020) [[sssd[p11_child[9556]]]] [do_card] (0x4000): dll name: [(null)].
(Fri Oct 30 09:55:32:554976 2020) [[sssd[p11_child[9556]]]] [do_card] (0x4000): common name: [Policy File].
(Fri Oct 30 09:55:32:554983 2020) [[sssd[p11_child[9556]]]] [do_card] (0x4000): dll name: [(null)].
(Fri Oct 30 09:55:32:554993 2020) [[sssd[p11_child[9556]]]] [do_card] (0x4000): Description [NSS Internal Cryptographic Services                             Mozilla Foundation                 ] Manufacturer [Mozilla Foundation                  ] flags [9] removable [false] token present [true].
(Fri Oct 30 09:55:32:555004 2020) [[sssd[p11_child[9556]]]] [do_card] (0x4000): Description [NSS User Private Key and Certificate Services                   Mozilla Foundation              ] Manufacturer [Mozilla Foundation              ] flags [1] removable [false] token present [true].
(Fri Oct 30 09:55:32:555022 2020) [[sssd[p11_child[9556]]]] [do_card] (0x4000): Description [Aladdin R.D. JaCarta [SCR Interface] (000000000000) 00 00       Aladdin R.D.                    ] Manufacturer [Aladdin R.D.                    ] flags [7] removable [true] token present [true].
(Fri Oct 30 09:55:32:555033 2020) [[sssd[p11_child[9556]]]] [do_card] (0x4000): Found [jacarta] in slot [Aladdin R.D. JaCarta [SCR Interface] (000000000000) 00 00][131071] of module [2][/lib64/libjcPKCS11-2.so].
(Fri Oct 30 09:55:32:555041 2020) [[sssd[p11_child[9556]]]] [do_card] (0x4000): Token is NOT friendly.
(Fri Oct 30 09:55:32:555047 2020) [[sssd[p11_child[9556]]]] [do_card] (0x4000): Trying to switch to friendly to read certificate.
(Fri Oct 30 09:55:32:555055 2020) [[sssd[p11_child[9556]]]] [do_card] (0x4000): Login required.
(Fri Oct 30 09:55:32:555065 2020) [[sssd[p11_child[9556]]]] [do_card] (0x0020): Login required but no PIN available, continue.
(Fri Oct 30 09:55:32:691861 2020) [[sssd[p11_child[9556]]]] [do_card] (0x4000): Filtered certificates:
(Fri Oct 30 09:55:32:691908 2020) [[sssd[p11_child[9556]]]] [do_card] (0x4000): No certificate found.

[root@redos-client2-s1 sssd]# certutil -d /etc/pki/nssdb -L -h all

Certificate Nickname                                         Trust Attributes
                                                             SSL,S/MIME,JAR/XPI

Enter Password or Pin for "jacarta":
SUBCA-s1                                                     CT,C,C
ORCA-s1                                                      CT,C,C
[root@redos-client2-s1 sssd]# KRB5_TRACE=/dev/stdout kinit -X X509_user_identity='PKCS11:module_name=/lib64/libjcPKCS11-2.so:token=jacarta:certid=7573657232' user2@PKI-TEST.LOCAL
[9568] 1604040970.160556: Getting initial credentials for user2@PKI-TEST.LOCAL
[9568] 1604040970.160558: Sending unauthenticated request
[9568] 1604040970.160559: Sending request (208 bytes) to PKI-TEST.LOCAL
[9568] 1604040970.160560: Sending initial UDP request to dgram 192.168.42.10:88
[9568] 1604040970.160561: Received answer (277 bytes) from dgram 192.168.42.10:88
[9568] 1604040970.160562: Response was from master KDC
[9568] 1604040970.160563: Received error from KDC: -1765328359/Additional pre-authentication required
[9568] 1604040970.160566: Preauthenticating using KDC method data
[9568] 1604040970.160567: Processing preauth types: PA-PK-AS-REQ (16), PA-PK-AS-REP_OLD (15), PA-ENC-TIMESTAMP (2), PA-ETYPE-INFO2 (19)
[9568] 1604040970.160568: Selected etype info: etype aes256-cts, salt "PKI-TEST.LOCALuser2", params "\x00\x00\x10\x00"
jacarta                          PIN: 
[9568] 1604040979.84601: PKINIT client has no configured identity; giving up
[9568] 1604040979.84602: Preauth module pkinit (16) (real) returned: 22/Недопустимый аргумент
[9568] 1604040979.84603: PKINIT client ignoring draft 9 offer from RFC 4556 KDC
[9568] 1604040979.84604: Preauth module pkinit (15) (real) returned: -1765328360/Preauthentication failed
Password for user2@PKI-TEST.LOCAL: 
^C
[9568] 1604040980.962419: Preauth module encrypted_timestamp (2) (real) returned: -1765328252/Password read interrupted
kinit: Password read interrupted while getting initial credentials

[root@redos-client2-s1 tmp]# p11tool --login --provider=/lib64/libjcPKCS11-2.so --list-all
Token 'jacarta' with URL 'pkcs11:model=JaCarta%20Laser;manufacturer=Aladdin%20R.D.;serial=4E46000557304C4E;token=jacarta' requires user PIN
Enter PIN: 
Object 0:
    URL: pkcs11:model=JaCarta%20Laser;manufacturer=Aladdin%20R.D.;serial=4E46000557304C4E;token=jacarta;id=%75%73%65%72%32;object=PKI;type=cert
    Type: X.509 Certificate
    Label: PKI
    ID: 75:73:65:72:32

Object 1:
    URL: pkcs11:model=JaCarta%20Laser;manufacturer=Aladdin%20R.D.;serial=4E46000557304C4E;token=jacarta;id=%75%73%65%72%32;object=PKI;type=private
    Type: Private key
    Label: PKI
    Flags: CKA_PRIVATE; CKA_NEVER_EXTRACTABLE; CKA_SENSITIVE; 
    ID: 75:73:65:72:32

I didn't understand why p11_child now don's see new cert. Previous 2 certs for user1 were generated using pkcs11-tool (for generating keypair on the token) and openssl with pkcs11 engine loaded (to create csr), then cert was geneated on SubCA (ejbca). Now i tried to generate keypair and cert right on SubCA and export it in pfx, then import it on the token using the software, provided by the developer of token.

xDFCx commented 4 years ago

I reissued the cert for user2, now it is fine for certutil and p11_child:

[root@redos-client2-s1 ~]# certutil -d /etc/pki/nssdb -L -h all

Certificate Nickname                                         Trust Attributes
                                                             SSL,S/MIME,JAR/XPI

Enter Password or Pin for "jacarta":
SUBCA-s1                                                     CT,C,C
ORCA-s1                                                      CT,C,C
user2@pki-test.local                                         u,u,u
[root@redos-client2-s1 ~]# /usr/libexec/sssd/p11_child --pre --nssdb=/etc/pki/nssdb
jacarta
/lib64/libjcPKCS11-2.so
7B34306264303736372D373165302D343161342D393066612D6661346337333862306661637D
- no label found -
MIIE0DCCA7igAwIBAgIUVtFX2+xMgDneBWi8x7b2vLkytpMwDQYJKoZIhvcNAQELBQAwEzERMA8GA1UEAwwIU1VCQ0EtczEwHhcNMjAxMDMwMDgzNzQ0WhcNMjExMDMwMDgzNzQ0WjAdMQswCQYDVQQGEwJSVTEOMAwGA1UEAwwFdXNlcjIwggEiMA0GCSqGSIb3DQEBAQUAA4IBDwAwggEKAoIBAQCqwGFDsDrhbjeuChG9A3ZkzuMsA8D/ZicE/UYHdrVbWuMsjKwzbxvEkzOByEHOA1wds5kTxyTuBnh+fe10+gryNQcz8Q4+LUaFZDrJtH7myYU7/6zVHOO0mYJSSLOwKb0uH2TJ4hUI9H+3FvGpqpBU/FnFF9WQBWK3wUQY4garQDF91+Ng27fqQrhSRyWqdQuI2ccOBxKirCgVnIJCm/Nvs8VBMEvycIQoDoBO+jKVpnH3jym+E+TMWaZD7lTbS3mW0Ps5/nzXVhGa+QD90wt9nNogs2YKR6uWeub71+WGv1Kz3BkLvYjV6n53gHyfEAOyHN6vI6qpf5+7MqEZJ4glAgMBAAGjggIQMIICDDAMBgNVHRMBAf8EAjAAMB8GA1UdIwQYMBaAFPMva1ihFSq06/VbLc0GK9UkKOucMGEGCCsGAQUFBwEBBFUwUzBRBggrBgEFBQcwAYZFaHR0cDovL3JlZG9zLXN1YmNhLXMxLnBraS10ZXN0LmxvY2FsOjgwODAvZWpiY2EvcHVibGljd2ViL3N0YXR1cy9vY3NwMDgGA1UdEgQxMC+CHXJlZG9zLXN1YmNhLXMxLnBraS10ZXN0LmxvY2Fsgg5yZWRvcy1zdWJjYS1zMTBFBgNVHREEPjA8gRR1c2VyMkBwa2ktdGVzdC5sb2NhbKAkBgorBgEEAYI3FAIDoBYMFHVzZXIyQHBraS10ZXN0LmxvY2FsMDMGA1UdJQQsMCoGCCsGAQUFBwMCBggrBgEFBQcDBAYKKwYBBAGCNxQCAgYIKwYBBQUHAwEwgZIGA1UdHwSBijCBhzCBhKBpoGeGZWh0dHA6Ly9yZWRvcy1zdWJjYS1zMS5wa2ktdGVzdC5sb2NhbDo4MDgwL2VqYmNhL3B1YmxpY3dlYi93ZWJkaXN0L2NlcnRkaXN0P2NtZD1jcmwmaXNzdWVyPUNOPVNVQkNBLXMxohekFTATMREwDwYDVQQDDAhTVUJDQS1zMTAdBgNVHQ4EFgQUdxCO623wtRDYJcyT/laswwbHOr0wDgYDVR0PAQH/BAQDAgTwMA0GCSqGSIb3DQEBCwUAA4IBAQAO3i8Mg5QTRr92OiBHmE0GZ4aEHMIYxXa2KGqpIiZ0hThFb/SlQ8588jEI+SmI3B5vPwMXQ/t5GYzh/9OeRJLlH+MOvzYxMUmMkStwixzt9MOW9p8Wi7L0lXmziSXt0fwo5cbIdLMy3RZMoU22ag+G+CjzXa+5Xo3UT+HnDGUo31n4JJ+3fiodR9S3TjiNmtcO7JiXcNu8JNYFz5FCi5/JZQSuwSSYJ60xMJrmkNJHsxbyudOzKHIun+oRFnRbmq4K4G7w+9r6vVHrAcQdGOqIGrtrtmJIjBKn5EcAziLH76geMzog1egQFJ9xps3yG21rdAFHp/5BeN5L8dvqizEO
[root@redos-client2-s1 ~]# /usr/libexec/sssd/p11_child --pre --nssdb=/etc/pki/nssdb | tail -1 | base64 -d > user2.der
[root@redos-client2-s1 ~]# klist
Ticket cache: FILE:/tmp/krb5cc_0
Default principal: adm1@PKI-TEST.LOCAL

Valid starting       Expires              Service principal
30.10.2020 11:35:02  30.10.2020 21:35:02  krbtgt/PKI-TEST.LOCAL@PKI-TEST.LOCAL
    renew until 06.11.2020 11:35:02
30.10.2020 12:23:33  30.10.2020 21:35:02  ldap/redos-dc-s1.pki-test.local@
    renew until 06.11.2020 11:35:02
30.10.2020 12:23:33  30.10.2020 21:35:02  ldap/redos-dc-s1.pki-test.local@PKI-TEST.LOCAL
    renew until 06.11.2020 11:35:02
[root@redos-client2-s1 ~]# ldapsearch -Y GSSAPI -H ldap://redos-dc-s1.pki-test.local -b 'dc=pki-test,dc=local' samaccountname=user2 dn
SASL/GSSAPI authentication started
SASL username: adm1@PKI-TEST.LOCAL
SASL SSF: 56
SASL data security layer installed.
# extended LDIF
#
# LDAPv3
# base <dc=pki-test,dc=local> with scope subtree
# filter: samaccountname=user2
# requesting: dn 
#

# user2, corp, pki-test.local
dn: CN=user2,OU=corp,DC=pki-test,DC=local

# search reference
ref: ldap://pki-test.local/CN=Configuration,DC=pki-test,DC=local

# search reference
ref: ldap://pki-test.local/DC=DomainDnsZones,DC=pki-test,DC=local

# search reference
ref: ldap://pki-test.local/DC=ForestDnsZones,DC=pki-test,DC=local

# search result
search: 4
result: 0 Success

# numResponses: 5
# numEntries: 1
# numReferences: 3

[root@redos-client2-s1 ~]# cat user2.ldif
dn: CN=user2,OU=corp,DC=pki-test,DC=local
changetype: modify
add: userCertificate
userCertificate:< file:user2.der

[root@redos-client2-s1 ~]# ldapmodify -Y GSSAPI -H ldap://redos-dc-s1.pki-test.local -f user2.ldif
SASL/GSSAPI authentication started
SASL username: adm1@PKI-TEST.LOCAL
SASL SSF: 56
SASL data security layer installed.
modifying entry "CN=user2,OU=corp,DC=pki-test,DC=local"

[root@redos-client2-s1 sssd5]# KRB5_TRACE=/dev/stdout kinit -X X509_user_identity='PKCS11:module_name=/lib64/libjcPKCS11-2.so:token=jacarta:certid=7B34306264303736372D373165302D343161342D393066612D6661346337333862306661637D' user2@PKI-TEST.LOCAL
[10847] 1604050473.495999: Getting initial credentials for user2@PKI-TEST.LOCAL
[10847] 1604050473.496001: Sending unauthenticated request
[10847] 1604050473.496002: Sending request (208 bytes) to PKI-TEST.LOCAL
[10847] 1604050473.496003: Sending initial UDP request to dgram 192.168.42.10:88
[10847] 1604050473.496004: Received answer (277 bytes) from dgram 192.168.42.10:88
[10847] 1604050473.496005: Response was from master KDC
[10847] 1604050473.496006: Received error from KDC: -1765328359/Additional pre-authentication required
[10847] 1604050473.496009: Preauthenticating using KDC method data
[10847] 1604050473.496010: Processing preauth types: PA-PK-AS-REQ (16), PA-PK-AS-REP_OLD (15), PA-ENC-TIMESTAMP (2), PA-ETYPE-INFO2 (19)
[10847] 1604050473.496011: Selected etype info: etype aes256-cts, salt "PKI-TEST.LOCALuser2", params "\x00\x00\x10\x00"
jacarta                          PIN: 
[10847] 1604050482.522299: PKINIT client has no configured identity; giving up
[10847] 1604050482.522300: Preauth module pkinit (16) (real) returned: 22/Недопустимый аргумент
[10847] 1604050482.522301: PKINIT client ignoring draft 9 offer from RFC 4556 KDC
[10847] 1604050482.522302: Preauth module pkinit (15) (real) returned: -1765328360/Preauthentication failed
Password for user2@PKI-TEST.LOCAL: 
^C
[10847] 1604050484.172134: Preauth module encrypted_timestamp (2) (real) returned: -1765328252/Password read interrupted
kinit: Password read interrupted while getting initial credentials

but now I don't get PIN prompt:

$su user2
su: authentication failure

sssd_pam.log sssd_pki-test.local.log

xDFCx commented 4 years ago

BTW, does installed version of sssd (2.0.0-8.el7) assume that certificate mapping will work on my cento7-based distro? Or I still should use matching algorithm?

sumit-bose commented 4 years ago

Hi,

let's start with the manual kinit. Have you added the CA certificates for your CAs to /etc/pki/tls/certs/ca-bundle.crtor did you add another pkinit_anchors line to /etc/krb5.conf pointing to a file with your CA certificates in PEM format? The libkrb5 pkinit plugin must be able to verify the certificates as well and cannot read NSS databases like e.g. /etc/pki/nssdb.

Additionally I would expect that you have to add

pkinit_kdc_hostname = dns.name.of.your.dc

for all your domain controllers and

pkinit_eku_checking = none

to the [libdefaults] section of /etc/krb5.conf

After adding those please try the kinit command again and send the new KRB5_TRACE output.

It looks like you attached old log files.

bye, Sumit

xDFCx commented 4 years ago

Speaking of CA certs, you mean on the client or domain controller? On DC there is pkinit_anchors with my CA cert in KDC section of krb5.conf. On client - no, I have not seen anywhere, that this is necessary. Ok, I'll try. "pkinit_kdc_hostname" and "pkinit_eku_checking" also must be added on client, right? P.S. Sorry, I updated attached files to previous message.

xDFCx commented 4 years ago

Added my CA cert to ca-bundle.crt and those options in krb5.conf on client

[root@redos-client2-s1 sssd5]# cat /etc/krb5.conf
includedir /etc/krb5.conf.d/

[logging]
    default = FILE:/var/log/krb5libs.log
    kdc = FILE:/var/log/krb5kdc.log
    admin_server = FILE:/var/log/kadmind.log

[libdefaults]
    dns_lookup_realm = false
    ticket_lifetime = 24h
    renew_lifetime = 7d
    forwardable = true
    rdns = false
    pkinit_anchors = /etc/pki/tls/certs/ca-bundle.crt
    spake_preauth_groups = edwards25519
    default_ccache_name = FILE:/tmp/krb5cc_%{uid}
    default_realm = PKI-TEST.LOCAL
    pkinit_kdc_hostname = redos-dc-s1.pki-test.local
    pkinit_eku_checking = none

[realms]
# EXAMPLE.COM = {
#     kdc = kerberos.example.com
#     admin_server = kerberos.example.com
# }

[domain_realm]
# .example.com = EXAMPLE.COM
# example.com = EXAMPLE.COM

[root@redos-client2-s1 ~]# KRB5_TRACE=/dev/stdout kinit -X X509_user_identity='PKCS11:module_name=/lib64/libjcPKCS11-2.so:token=jacarta:certid=7B34306264303736372D373165302D343161342D393066612D6661346337333862306661637D' user2@PKI-TEST.LOCAL
[2322] 1604056228.224822: Getting initial credentials for user2@PKI-TEST.LOCAL
[2322] 1604056228.224824: Sending unauthenticated request
[2322] 1604056228.224825: Sending request (208 bytes) to PKI-TEST.LOCAL
[2322] 1604056228.224826: Sending initial UDP request to dgram 192.168.42.10:88
[2322] 1604056228.224827: Received answer (277 bytes) from dgram 192.168.42.10:88
[2322] 1604056228.224828: Response was from master KDC
[2322] 1604056228.224829: Received error from KDC: -1765328359/Additional pre-authentication required
[2322] 1604056228.224832: Preauthenticating using KDC method data
[2322] 1604056228.224833: Processing preauth types: PA-PK-AS-REQ (16), PA-PK-AS-REP_OLD (15), PA-ENC-TIMESTAMP (2), PA-ETYPE-INFO2 (19)
[2322] 1604056228.224834: Selected etype info: etype aes256-cts, salt "PKI-TEST.LOCALuser2", params "\x00\x00\x10\x00"
jacarta                          PIN: 
[2322] 1604056236.611892: PKINIT client has no configured identity; giving up
[2322] 1604056236.611893: Preauth module pkinit (16) (real) returned: 22/Недопустимый аргумент
[2322] 1604056236.611894: PKINIT client ignoring draft 9 offer from RFC 4556 KDC
[2322] 1604056236.611895: Preauth module pkinit (15) (real) returned: -1765328360/Preauthentication failed
Password for user2@PKI-TEST.LOCAL: 
^C
[2322] 1604056239.797173: Preauth module encrypted_timestamp (2) (real) returned: -1765328252/Password read interrupted
kinit: Password read interrupted while getting initial credentials

sumit-bose commented 4 years ago

Hi,

the pkinit plugin still cannot find the certificate. Since there is only one on the card can you try if

KRB5_TRACE=/dev/stdout kinit -X X509_user_identity='PKCS11:module_name=/lib64/libjcPKCS11-2.so:token=jacarta' user2@PKI-TEST.LOCAL

works any better?

Can you try to add a label to the certificate and the private key on the Smartcard and check manual kinit works better with this?

It is possible to recompile the pkinit plugin with extra debug information which might help to understand what is going wrong. Do you know there I can download the source packages for your version of RedOS?

bye, Sumit

xDFCx commented 4 years ago

@sumit-bose this command was in the listing above, https://github.com/SSSD/sssd/issues/5377#issuecomment-719491361 I'm not sure how can I add label, what tool should I use? I uploaded src rpm here https://yadi.sk/d/3nPgMwvzPEzeSA

xDFCx commented 4 years ago

Ok, looks like I cannot just assign a label to the private key or a certificate on a token, so I just created new keypair and cert, so now I have this:

[root@redos-client2-s1 ~]# pkcs11-tool --module /lib64/libjcPKCS11-2.so -Ol
Using slot 0 with a present token (0x1ffff)
Logging in to "jacarta".
Please enter User PIN: 
Public Key Object; RSA 2048 bits
  label:      user2_test3
  ID:         7573657232
  Usage:      encrypt, verify, wrap
Certificate Object; type = X.509 cert
  label:      user2_test3
  ID:         7573657232
Private Key Object; RSA 
  label:      user2_test3
  ID:         7573657232
  Usage:      decrypt, sign, unwrap
warning: PKCS11 function C_GetAttributeValue(ALWAYS_AUTHENTICATE) failed: rv = CKR_ATTRIBUTE_TYPE_INVALID (0x12)

[root@redos-client2-s1 ~]# /usr/libexec/sssd/p11_child --pre --nssdb=/etc/pki/nssdb
jacarta
/lib64/libjcPKCS11-2.so
7573657232
user2_test3
<cert skipped>

but kinit still fails using token

[root@redos-client2-s1 ~]# KRB5_TRACE=/dev/stdout kinit -X X509_user_identity='PKCS11:module_name=/lib64/libjcPKCS11-2.so:token=jacarta:certid=7573657232' user2@PKI-TEST.LOCAL
[3023] 1604067967.164159: Getting initial credentials for user2@PKI-TEST.LOCAL
[3023] 1604067967.164161: Sending unauthenticated request
[3023] 1604067967.164162: Sending request (208 bytes) to PKI-TEST.LOCAL
[3023] 1604067967.164163: Sending initial UDP request to dgram 192.168.42.10:88
[3023] 1604067967.164164: Received answer (277 bytes) from dgram 192.168.42.10:88
[3023] 1604067967.164165: Response was from master KDC
[3023] 1604067967.164166: Received error from KDC: -1765328359/Additional pre-authentication required
[3023] 1604067967.164169: Preauthenticating using KDC method data
[3023] 1604067967.164170: Processing preauth types: PA-PK-AS-REQ (16), PA-PK-AS-REP_OLD (15), PA-ENC-TIMESTAMP (2), PA-ETYPE-INFO2 (19)
[3023] 1604067967.164171: Selected etype info: etype aes256-cts, salt "PKI-TEST.LOCALuser2", params "\x00\x00\x10\x00"
jacarta                          PIN: 
[3023] 1604067976.111289: PKINIT client has no configured identity; giving up
[3023] 1604067976.111290: Preauth module pkinit (16) (real) returned: 22/Invalid argument
[3023] 1604067976.111291: PKINIT client ignoring draft 9 offer from RFC 4556 KDC
[3023] 1604067976.111292: Preauth module pkinit (15) (real) returned: -1765328360/Preauthentication failed
Password for user2@PKI-TEST.LOCAL: 
^C
[3023] 1604067978.152082: Preauth module encrypted_timestamp (2) (real) returned: -1765328252/Password read interrupted
kinit: Password read interrupted while getting initial credentials

xDFCx commented 4 years ago

Hi. On the past weekend I tried to set up new VM in tnis test environment, using pure Centos 8 distro. I was sure, that I installed all what it needed and edited all required configs, like I did on RedOS, but I get this: Does this mean, that p11_child cannot validate the user2's cert using CRL from SUBCA? If so, CRL is taken from URI in certificate CDP field or must be stored locally?

sumit-bose commented 4 years ago

Hi,

sorry for not being specific, I needed the krb5 source rpm not the SSSD source rpm. But since you have CentOS8 now it makes it easier to create a debug build.

SSSD in CentOS8 does not use NSS anymore but OpenSSL. Please try,

/usr/libexec/sssd/p11_child --pre --nssdb=/path/to/pem/file/with/CA_certificates.pem -d 10 --debug-fd=1

If you have added the CA certificates to /etc/pki/tls/certs/ca-bundle.crt you can use this file here as well. Please add

pam_cert_db_path = /etc/pki/tls/certs/ca-bundle.crt

to the [pam] section of sssd.conf as well.

bye, Sumit

xDFCx commented 4 years ago

If using /usr/libexec/sssd/p11_child --pre --nssdb=/etc/pki/tls/certs/ca-bundle.crt -d 10 --debug-fd=1 I also dont get certificate stored on token, but I'm sure that is is because of openssl doesn't aware of a library I use to access the token - /lib64/libjcPKCS11-2.so. On RedOS I had to add it to nssdb with modutil -dbdir /etc/pki/nssdb -add JaCarta -libfile /lib64/libjcPKCS11-2.so Anyway, my chief told me, that I shouldn't try using any other version of software besides that is in the distro, because of local certification laws. So I must return using RedOS, with its versions of all packages.

sumit-bose commented 4 years ago

Hi,

for CentOS8 you have to add your PKCS#11 module /lib64/libjcPKCS11-2.so to the p11-kit configuration.

Coming back to RedOS, can you send my a link to the krb5 source rpm for RedOS so that I can check how to add a patch so that you can rebuild it with extra debug output for the pkinit module.

bye, Sumit

xDFCx commented 4 years ago

Hi, sorry for being inactive last 2 days - we've tried setting up another stand, got same results. Also, we cannot provide krb5 sources from redos, but we can ask developers to provide rebuilt version, but I must know what to ask for - what package and which options. Kerberos version 1.16.1-24 (may be it is from fedora29)

xDFCx commented 4 years ago

Ok, I found this article https://k5wiki.kerberos.org/wiki/Pkinit_configuration#Debugging_Pkinit, and will try to rebuild pkinit.so with debug enabled.

sumit-bose commented 4 years ago

Hi,

sorry for the delay, I typically use a patch like the attached on to enable the extra debugging data and make them available via KRB5_TRACE.

bye, Sumit 0001-pki-debug-trace.patch.txt

xDFCx commented 4 years ago

I took kerberos5 sources from https://github.com/krb5/krb5, version 1.16.1-final and applied your patch. Now it seems like the library I've compiled and substituted the original one just doesn't work. This is with original library (I get PIN prompt):

[root@redos-client-s3 preauth]# KRB5_TRACE=/dev/stdout kinit -X X509_user_identity='PKCS11:module_name=/lib64/libjcPKCS11-2.so:token=jacarta:certid=7B64396136366430622D623933302D343663652D613730662D3333616364303866376362617D' user1@PKI.TEST
[31806] 1605012592.148747: Getting initial credentials for user1@PKI.TEST
[31806] 1605012592.148749: Sending unauthenticated request
[31806] 1605012592.148750: Sending request (196 bytes) to PKI.TEST
[31806] 1605012592.148751: Sending initial UDP request to dgram 192.168.43.21:88
[31806] 1605012592.148752: Received answer (251 bytes) from dgram 192.168.43.21:88
[31806] 1605012592.148753: Response was from master KDC
[31806] 1605012592.148754: Received error from KDC: -1765328359/Additional pre-authentication required
[31806] 1605012592.148757: Preauthenticating using KDC method data
[31806] 1605012592.148758: Processing preauth types: PA-PK-AS-REQ (16), PA-PK-AS-REP_OLD (15), PA-ENC-TIMESTAMP (2), PA-ETYPE-INFO2 (19)
[31806] 1605012592.148759: Selected etype info: etype aes256-cts, salt "PKI.TESTuser1", params "\x00\x00\x10\x00"
jacarta                          PIN: 
[31806] 1605012600.417044: PKINIT client has no configured identity; giving up
[31806] 1605012600.417045: Preauth module pkinit (16) (real) returned: 22/Недопустимый аргумент
[31806] 1605012600.417046: PKINIT client ignoring draft 9 offer from RFC 4556 KDC
[31806] 1605012600.417047: Preauth module pkinit (15) (real) returned: -1765328360/Preauthentication failed
Password for user1@PKI.TEST:
^C
[31806] 1605012601.951790: Preauth module encrypted_timestamp (2) (real) returned: -1765328252/Password read interrupted
kinit: Password read interrupted while getting initial credentials

This is with compiled library (no PIN prompt):

[root@redos-client-s3 preauth]# KRB5_TRACE=/dev/stdout kinit -X X509_user_identity='PKCS11:module_name=/lib64/libjcPKCS11-2.so:token=jacarta:certid=7B64396136366430622D623933302D343663652D613730662D3333616364303866376362617D' user1@PKI.TEST
[31821] 1605012620.328390: Getting initial credentials for user1@PKI.TEST
[31821] 1605012620.328392: Sending unauthenticated request
[31821] 1605012620.328393: Sending request (196 bytes) to PKI.TEST
[31821] 1605012620.328394: Sending initial UDP request to dgram 192.168.43.21:88
[31821] 1605012620.328395: Received answer (251 bytes) from dgram 192.168.43.21:88
[31821] 1605012620.328396: Response was from master KDC
[31821] 1605012620.328397: Received error from KDC: -1765328359/Additional pre-authentication required
[31821] 1605012620.328400: Preauthenticating using KDC method data
[31821] 1605012620.328401: Processing preauth types: PA-PK-AS-REQ (16), PA-PK-AS-REP_OLD (15), PA-ENC-TIMESTAMP (2), PA-ETYPE-INFO2 (19)
[31821] 1605012620.328402: Selected etype info: etype aes256-cts, salt "PKI.TESTuser1", params "\x00\x00\x10\x00"
Password for user1@PKI.TEST: 
^C
[31821] 1605012630.257257: Preauth module encrypted_timestamp (2) (real) returned: -1765328252/Password read interrupted
kinit: Password read interrupted while getting initial credentials

Also, when I try su user1 i get this in sssd_pam.log:

(Tue Nov 10 15:38:45:426562 2020) [sssd[pam]] [pam_reply] (0x0040): Backend cannot handle Smartcard authentication, trying local Smartcard authentication.

And then I'm becoming user1 in console. krb5_child.log ldap_child.log p11_child.log sssd_pam.log sssd_pki.test.log

sumit-bose commented 4 years ago

Hi,

it's a pity that RedOS does not provide the sources for their packages. You need special configure options to enable the build of the pkinit plugin. You said hte krb5 package might be based on Fedora, please check the Fedora-29 spec file for the needed configure options https://src.fedoraproject.org/rpms/krb5/blob/f29/f/krb5.spec#_354 .

HTH

bye, Sumit

xDFCx commented 4 years ago

Ok, I got sources from redos, patched and built them. Now in console I see this:

[root@redos-client-s3 tmp]# KRB5_TRACE=/dev/stdout kinit -X X509_user_identity='PKCS11:module_name=/lib64/libjcPKCS11-2.so:token=jacarta:certid=7B64396136366430622D623933302D343663652D613730662D3333616364303866376362617D' user1@PKI.TEST
[2510] 1605099563.380987: pkinit_init_plg_crypto: initializing openssl crypto context at 0x5615ab4bacb0

[2510] 1605099563.380988: pkinit_client_plugin_init: returning plgctx at 0x5615ab497a70

[2510] 1605099563.380989: (pkinit) received 'X509_user_identity' = 'PKCS11:module_name=/lib64/libjcPKCS11-2.so:token=jacarta:certid=7B64396136366430622D623933302D343663652D613730662D3333616364303866376362617D'

[2510] 1605099563.380990: Getting initial credentials for user1@PKI.TEST
[2510] 1605099563.380991: pkinit_init_req_crypto: returning ctx at 0x5615ab4bc360

[2510] 1605099563.380992: pkinit_init_identity_crypto: returning ctx at 0x5615ab4bc770

[2510] 1605099563.380993: pkinit_client_req_init: returning reqctx at 0x5615ab4bc450

[2510] 1605099563.380995: Sending unauthenticated request
[2510] 1605099563.380996: Sending request (196 bytes) to PKI.TEST
[2510] 1605099563.380997: Sending initial UDP request to dgram 192.168.43.21:88
[2510] 1605099563.380998: Received answer (251 bytes) from dgram 192.168.43.21:88
[2510] 1605099563.380999: Response was from master KDC
[2510] 1605099563.381000: Received error from KDC: -1765328359/Additional pre-authentication required
[2510] 1605099563.381003: Preauthenticating using KDC method data
[2510] 1605099563.381004: Processing preauth types: PA-PK-AS-REQ (16), PA-PK-AS-REP_OLD (15), PA-ENC-TIMESTAMP (2), PA-ETYPE-INFO2 (19)
[2510] 1605099563.381005: Selected etype info: etype aes256-cts, salt "PKI.TESTuser1", params "\x00\x00\x10\x00"
[2510] 1605099563.381006: pkinit_client_profile 0x5615ab496060 0x5615ab497a70 0x5615ab4bc450 0x5615ab4bc1f8

[2510] 1605099563.381007: pkinit_identity_initialize: 0x5615ab496060 0x5615ab4bc8d0 0x5615ab4bc770

[2510] 1605099563.381008: process_option_identity: processing value 'PKCS11:module_name=/lib64/libjcPKCS11-2.so:token=jacarta:certid=7B64396136366430622D623933302D343663652D613730662D3333616364303866376362617D'

[2510] 1605099563.381009: process_option_identity: idtype is PKCS11

[2510] 1605099563.381010: loading module "/lib64/libjcPKCS11-2.so"... 
[2510] 1605099563.381011: ok

[2510] 1605099565.288030: open_session: slotid 131071 token "jacarta"

[2510] 1605099565.288031: open_session: slotid 131071 (1 of 1)

[2510] 1605099565.288032: can't open pkcs11 session

[2510] 1605099565.288033: pkinit_client_prep_questions: asking question ''

[2510] 1605099565.288034: pkinit_client_prep_questions returning 0

[2510] 1605099565.288035: pkinit_client_prep_questions: asking question ''

[2510] 1605099565.288036: pkinit_client_prep_questions returning 0

[2510] 1605099565.288037: pkinit_client_process 0x5615ab496060 0x5615ab497a70 0x5615ab4bc450 0x5615ab4bc260

[2510] 1605099565.288038: processing KRB5_PADATA_PK_AS_REQ

[2510] 1605099565.288039: pkinit_client_profile 0x5615ab496060 0x5615ab497a70 0x5615ab4bc450 0x5615ab4bc1f8

[2510] 1605099565.288040: pkinit_identity_prompt: 0x5615ab496060 0x5615ab4bc8d0 0x5615ab4bc770

[2510] 1605099565.288041: loading module "/lib64/libjcPKCS11-2.so"... 
[2510] 1605099565.288042: ok

[2510] 1605099567.10789: open_session: slotid 131071 token "jacarta"

[2510] 1605099567.10790: open_session: slotid 131071 (1 of 1)

jacarta                          PIN: 
[2510] 1605099572.814174: cert 0 size 1262 id 123 idlen 38

[2510] 1605099572.814175: pkinit_cert_matching: no matching rules found in config file

[2510] 1605099572.814176: process_option_ca_crl: processing catype ANCHORS, value '/etc/pki/tls/certs/ca-bundle.crt'

[2510] 1605099572.814177: No type given for '/etc/pki/tls/certs/ca-bundle.crt'

[2510] 1605099572.814178: PKINIT client has no configured identity; giving up
[2510] 1605099572.814179: pkinit_identity_prompt returned 22 (Invalid argument)

[2510] 1605099572.814180: Preauth module pkinit (16) (real) returned: 22/Invalid argument
[2510] 1605099572.814181: pkinit_client_process 0x5615ab496060 0x5615ab497a70 0x5615ab4bc450 0x5615ab4bc260

[2510] 1605099572.814182: PKINIT client ignoring draft 9 offer from RFC 4556 KDC
[2510] 1605099572.814183: Preauth module pkinit (15) (real) returned: -1765328360/Preauthentication failed
Password for user1@PKI.TEST:
^C
[2510] 1605099575.26896: Preauth module encrypted_timestamp (2) (real) returned: -1765328252/Password read interrupted
[2510] 1605099575.26897: pkinit_client_req_fini: received reqctx at 0x5615ab4bc450

[2510] 1605099575.26898: pkinit_fini_req_crypto: freeing ctx at 0x5615ab4bc360

[2510] 1605099575.26899: pkinit_fini_identity_crypto: freeing ctx at 0x5615ab4bc770

kinit: Password read interrupted while getting initial credentials
[2510] 1605099575.26900: pkinit_client_plugin_fini: got plgctx at 0x5615ab497a70

[2510] 1605099575.26901: pkinit_fini_plg_crypto: freeing context at 0x5615ab4bacb0

Does preauth fail because of matching rules? I checked sssd.conf:

[sssd]
domains = pki.test
config_file_version = 2
services = nss, pam
debug_level = 9
debug_microseconds = True

[domain/pki.test]
enumerate = False
ad_domain = pki.test
krb5_realm = PKI.TEST
realmd_tags = manages-system joined-with-samba
cache_credentials = True
id_provider = ad
krb5_store_password_if_offline = True
default_shell = /bin/bash
ldap_id_mapping = True
ldap_user_certificate = userCertificate
use_fully_qualified_names = False
fallback_homedir = /home/%u@%d
access_provider = ad
ad_gpo_access_control = permissive
debug_level = 9
debug_microseconds = True

[pam]
pam_cert_auth = True
debug_level = 9
debug_microseconds = True

[certmap/pki-test.local/nt_principal]
maprule = (|(userPrincipalName={subject_nt_principal})(samAccountName={subject_nt_principal.short_name}))

I also checked pkinit_anchors file - CA cert is in the end of it. Still dont understand why it happens.

xDFCx commented 4 years ago

UPD: I see, that I copied [certmap/pki-test.local/nt_principal] section from previous test stand, and now domain name differs, I changed it, so it is now right. Still in sssd.log I see Section [certmap/pki.test/nt_principal] is not allowed. Check for typos.

sumit-bose commented 4 years ago

Hi,

can you try with

pkinit_anchors = FILE:/etc/pki/tls/certs/ca-bundle.crt

instead of

pkinit_anchors = /etc/pki/tls/certs/ca-bundle.crt

You can ignore the Section [certmap/pki.test/nt_principal] is not allowed. message, there is just a check missing in the config validation rules.

bye, Sumit

xDFCx commented 4 years ago

Oh, now it enumerates all certs in that file, last of them is my CA:

<...>
[3196] 1605106602.284606: cert #167: /CN=redos-ca-s3

[3196] 1605106602.284607: CMS Verification successful

[3196] 1605106602.284608: PKINIT client verified DH reply
[3196] 1605106602.284609: verify_kdc_san: No pkinit_kdc_hostname values found in config file

[3196] 1605106602.284610: crypto_retrieve_X509_sans: looking for SANs in cert = /CN=redos-dc-s3

[3196] 1605106602.284611: crypto_retrieve_X509_sans: found 2 subject alt name extension(s)

[3196] 1605106602.284612: crypto_retrieve_X509_sans: unrecognized othername oid in SAN

[3196] 1605106602.284613: verify_kdc_san: Checking pkinit sans

[3196] 1605106602.284614: verify_kdc_san: no pkinit san match found

[3196] 1605106602.284615: verify_kdc_san: no certhosts (or we wouldn't accept them anyway)

[3196] 1605106602.284616: verify_kdc_san: returning retval -1765328308, valid_san 0, need_eku_checking 1

[3196] 1605106602.284617: pkinit_as_rep_parse returning -1765328308 (KDC name mismatch)

[3196] 1605106602.284618: pkinit_as_rep_parse returned -1765328308 (KDC name mismatch)

[3196] 1605106602.284619: pkinit_client_process: returning -1765328308 (KDC name mismatch)

[3196] 1605106602.284620: Preauth module pkinit (17) (real) returned: -1765328308/KDC name mismatch
[3196] 1605106602.284621: Produced preauth for next request: (empty)
[3196] 1605106602.284622: Getting AS key, salt "PKI.TESTuser1", params "\x00\x00\x10\x00"
Password for user1@PKI.TEST:
^C
[3196] 1605106610.419348: pkinit_client_req_fini: received reqctx at 0x55a8c89f4450

[3196] 1605106610.419349: pkinit_fini_req_crypto: freeing ctx at 0x55a8c89f4360

[3196] 1605106610.419350: pkinit_fini_identity_crypto: freeing ctx at 0x55a8c89f4770

kinit: Password read interrupted while getting initial credentials
[3196] 1605106610.419351: pkinit_client_plugin_fini: got plgctx at 0x55a8c89cfa70

[3196] 1605106610.419352: pkinit_fini_plg_crypto: freeing context at 0x55a8c89f2cb0

xDFCx commented 4 years ago

Am I missing anything in certificates? SAN field? Link to certificates for this stand - https://yadi.sk/d/wW3nnNg0qVGP_w

sumit-bose commented 4 years ago

Hi,

do you still have

pkinit_kdc_hostname = redos-dc-s1.pki-test.local
pkinit_eku_checking = none

in krb5.conf? If not, please add them again. Additionally you might need

pkinit_kdc_hostname = redos-dc-s3.pki-test.local

and similar lines for all other DCs in your environment.

bye, Sumit

xDFCx commented 4 years ago

OMG it's finally working! @sumit-bose thank you soooo much! Yeah, I didn't add that line pkinit_eku_checking = none on this test stand, with it I'm able to login with domain user. I still got two questions:

Does this mean, that I have to disable EKU checking on all clients or I can modify my DC cert template to generate valid cert, containig needed fields/values?
Do I still have to put user certificate into LDAP userCertificate attribute, considering my version of sssd (2.0.0-8) and krb5 (1.16.1-24)?

sumit-bose commented 4 years ago

OMG it's finally working! @sumit-bose thank you soooo much! Yeah, I didn't add that line pkinit_eku_checking = none on this test stand, with it I'm able to login with domain user.

Hi,

thanks for your patience, glad it is working for you now.

I still got two questions:

1. Does this mean, that I have to disable EKU checking on all clients or I can modify my DC cert template to generate valid cert, containig needed fields/values?

If you create the DC certificates with the 'Kerberos Authentication' certificate template the EKU is set so that you do not have to disable the EKC checking.

Additionally this template will also add the domain name to the SAN to that you do not need pkinit_kdc_hostname lines for every DC in your environment but just pkinit_kdc_hostname = domain.name.

2. Do I still have to put user certificate into LDAP userCertificate attribute, considering my version of sssd (2.0.0-8) and krb5 (1.16.1-24)?

If you can use sssd-2.x then you can user certificate mapping and matching rules in sssd.conf. However, I would really recommend to use newer version, sssd-2.0.0 is more than 2 years old and the current version is sssd-2.4.0.

bye, Sumit