Old users cannot login to new freeIPA client machine

[Sam Bell]

I have a small FreeIPA setup and user login works ok on the client systems. Recently, I wanted to add a new machine as a client.
I loaded Fedora 33 on the machine and installed freeipa-client. Installation seems to be ok and I can see all users with find-user
on the client system. However, when existing users try to log in into the new client machine via ssh, it shows the error permission denied. 
These users can login to old client machines and server (to check) without any problems. To debug the problem, I created new user accounts
 and they seem to log in with all client machines (old + new) without any trouble. DNS for the machines are set through hosts file.

I don't have deep knowledge about this stuff but after reading some online threads here are few things I tried:
1. Updated to server (Fedora) to latest packages.
2. Made sure new client machine is chrony/ntp synchronized with server.
3. Tried enabling pre-authentication for old user on server.
4. kinit admin; ipa user-find --all lists all freeipa users on new client machine.
5. Set debug_level  of sssd to 9.

Checking krb5_child.log shows:
For old users with failed authentication:
[sss_krb5_prompter] (0x4000): sss_krb5_prompter name [(null)] banner [(null)] num_prompts [1] EINVAL.
[sss_krb5_prompter] (0x4000): Prompt [0][Password for [e-mail]].
[krb5_child[2789]] [sss_krb5_prompter] (0x0020): Cannot handle password prompts.
[sss_child_krb5_trace_cb] (0x4000): [2789] 1615347264.001283: Preauth module spake (151) (real) returned: -1765328254/Cannot read password

For newly created users, these logs are bit more detailed and in general, show success of authentication.

I am not sure which part to focus on to debug this problem.
Any help/suggestions are appreciated.
Thank you.

[Sumit Bose]

On Wed, Mar 10, 2021 at 03:48:34AM -0000, Sam Bell via FreeIPA-users wrote:
> I have a small FreeIPA setup and user login works ok on the client systems. Recently, I wanted to add a new machine as a client.
> I loaded Fedora 33 on the machine and installed freeipa-client. Installation seems to be ok and I can see all users with find-user
> on the client system. However, when existing users try to log in into the new client machine via ssh, it shows the error permission denied. 
> These users can login to old client machines and server (to check) without any problems. To debug the problem, I created new user accounts
>  and they seem to log in with all client machines (old + new) without any trouble. DNS for the machines are set through hosts file.
>
> I don't have deep knowledge about this stuff but after reading some online threads here are few things I tried:
> Updated to server (Fedora) to latest packages.
> Made sure new client machine is chrony/ntp synchronized with server.
> Tried enabling pre-authentication for old user on server.
> kinit admin; ipa user-find --all lists all freeipa users on new client machine.
> Set debug_level  of sssd to 9.
>
> Checking krb5_child.log shows:
> For old users with failed authentication:
> [sss_krb5_prompter] (0x4000): sss_krb5_prompter name [(null)] banner [(null)] num_prompts [1] EINVAL.
> [sss_krb5_prompter] (0x4000): Prompt [0][Password for [e-mail]].
> [krb5_child[2789]] [sss_krb5_prompter] (0x0020): Cannot handle password prompts.
> [sss_child_krb5_trace_cb] (0x4000): [2789] 1615347264.001283: Preauth module spake (151) (real) returned: -1765328254/Cannot read password

Hi,

the above output only contains some details for debugging but typically
does not indicate an issue. Can you send the full krb5_child.log?

bye,
Sumit
> For newly created users, these logs are bit more detailed and in general, show success of authentication.
>
> I am not sure which part to focus on to debug this problem.
> Any help/suggestions are appreciated.
> Thank you.
>
> FreeIPA-users mailing list -- [e-mail]
> To unsubscribe send an email to [e-mail]
> Fedora Code of Conduct: https://docs.fedoraproject.org/en-US/project/code-of-conduct/
> List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines
> List Archives: https://lists.fedorahosted.org/archives/list/[e-mail]...
> Do not reply to spam on the list, report it: https://pagure.io/fedora-infrastructure

[Sam Bell]

Thanks for the reply.
Following are the details:
Server ip: 192.168.0.245
Client : 192.168.0.248
krb5_child.log content:
(2021-03-10 15:47:06): [krb5_child[3066]] [main] (0x0400): krb5_child started.
(2021-03-10 15:47:06): [krb5_child[3066]] [unpack_buffer] (0x1000): total buffer size: [96]
(2021-03-10 15:47:06): [krb5_child[3066]] [unpack_buffer] (0x0100): cmd [249] uid [365400011] gid [365400011] validate [true] enterprise principal [false] offline [false] UPN [[e-mail]]
(2021-03-10 15:47:06): [krb5_child[3066]] [unpack_buffer] (0x2000): No old ccache
(2021-03-10 15:47:06): [krb5_child[3066]] [unpack_buffer] (0x0100): ccname: [KCM:] old_ccname: [not set] keytab: [/etc/krb5.keytab]
(2021-03-10 15:47:06): [krb5_child[3066]] [k5c_setup_fast] (0x0100): Fast principal is set to [host/[e-mail]]
(2021-03-10 15:47:06): [krb5_child[3066]] [find_principal_in_keytab] (0x4000): Trying to find principal host/[e-mail] in keytab.
(2021-03-10 15:47:06): [krb5_child[3066]] [match_principal] (0x1000): Principal matched to the sample (host/[e-mail]).
(2021-03-10 15:47:06): [krb5_child[3066]] [check_fast_ccache] (0x0200): FAST TGT is still valid.
(2021-03-10 15:47:06): [krb5_child[3066]] [become_user] (0x0200): Trying to become user [365400011][365400011].
(2021-03-10 15:47:06): [krb5_child[3066]] [main] (0x2000): Running as [365400011][365400011].
(2021-03-10 15:47:06): [krb5_child[3066]] [set_lifetime_options] (0x0100): No specific renewable lifetime requested.
(2021-03-10 15:47:06): [krb5_child[3066]] [set_lifetime_options] (0x0100): No specific lifetime requested.
(2021-03-10 15:47:06): [krb5_child[3066]] [set_canonicalize_option] (0x0100): Canonicalization is set to [true]
(2021-03-10 15:47:06): [krb5_child[3066]] [main] (0x0400): Will perform pre-auth
(2021-03-10 15:47:06): [krb5_child[3066]] [tgt_req_child] (0x1000): Attempting to get a TGT
(2021-03-10 15:47:06): [krb5_child[3066]] [get_and_save_tgt] (0x0400): Attempting kinit for realm [FREEIPA.LAB]
(2021-03-10 15:47:06): [krb5_child[3066]] [sss_child_krb5_trace_cb] (0x4000): [3066] 1615358826.830679: Getting initial credentials for [e-mail]

(2021-03-10 15:47:06): [krb5_child[3066]] [sss_child_krb5_trace_cb] (0x4000): [3066] 1615358826.830680: FAST armor ccache: MEMORY:/var/lib/sss/db/fast_ccache_FREEIPA.LAB

(2021-03-10 15:47:06): [krb5_child[3066]] [sss_child_krb5_trace_cb] (0x4000): [3066] 1615358826.830681: Retrieving host/[e-mail] -> krb5_ccache_conf_data/fast_avail/krbtgt/[e-mail]@X-CACHECONF: from MEMORY:/var/lib/sss/db/fast_ccache_FREEIPA.LAB with result: -1765328243/Matching credential not found

(2021-03-10 15:47:06): [krb5_child[3066]] [sss_child_krb5_trace_cb] (0x4000): [3066] 1615358826.830683: Sending unauthenticated request

(2021-03-10 15:47:06): [krb5_child[3066]] [sss_child_krb5_trace_cb] (0x4000): [3066] 1615358826.830684: Sending request (180 bytes) to FREEIPA.LAB

(2021-03-10 15:47:06): [krb5_child[3066]] [sss_child_krb5_trace_cb] (0x4000): [3066] 1615358826.830685: Initiating TCP connection to stream 192.168.0.245:88

(2021-03-10 15:47:06): [krb5_child[3066]] [sss_child_krb5_trace_cb] (0x4000): [3066] 1615358826.830686: Sending TCP request to stream 192.168.0.245:88

(2021-03-10 15:47:06): [krb5_child[3066]] [sss_child_krb5_trace_cb] (0x4000): [3066] 1615358826.830687: Received answer (505 bytes) from stream 192.168.0.245:88

(2021-03-10 15:47:06): [krb5_child[3066]] [sss_child_krb5_trace_cb] (0x4000): [3066] 1615358826.830688: Terminating TCP connection to stream 192.168.0.245:88

(2021-03-10 15:47:06): [krb5_child[3066]] [sss_child_krb5_trace_cb] (0x4000): [3066] 1615358826.830689: Response was from master KDC

(2021-03-10 15:47:06): [krb5_child[3066]] [sss_child_krb5_trace_cb] (0x4000): [3066] 1615358826.830690: Received error from KDC: -1765328359/Additional pre-authentication required

(2021-03-10 15:47:06): [krb5_child[3066]] [sss_child_krb5_trace_cb] (0x4000): [3066] 1615358826.830691: Upgrading to FAST due to presence of PA_FX_FAST in reply

(2021-03-10 15:47:06): [krb5_child[3066]] [sss_child_krb5_trace_cb] (0x4000): [3066] 1615358826.830692: FAST armor ccache: MEMORY:/var/lib/sss/db/fast_ccache_FREEIPA.LAB

(2021-03-10 15:47:06): [krb5_child[3066]] [sss_child_krb5_trace_cb] (0x4000): [3066] 1615358826.830693: Retrieving host/[e-mail] -> krb5_ccache_conf_data/fast_avail/krbtgt/[e-mail]@X-CACHECONF: from MEMORY:/var/lib/sss/db/fast_ccache_FREEIPA.LAB with result: -1765328243/Matching credential not found

(2021-03-10 15:47:06): [krb5_child[3066]] [sss_child_krb5_trace_cb] (0x4000): [3066] 1615358826.830694: Getting credentials host/[e-mail] -> krbtgt/[e-mail] using ccache MEMORY:/var/lib/sss/db/fast_ccache_FREEIPA.LAB

(2021-03-10 15:47:06): [krb5_child[3066]] [sss_child_krb5_trace_cb] (0x4000): [3066] 1615358826.830695: Retrieving host/[e-mail] -> krbtgt/[e-mail] from MEMORY:/var/lib/sss/db/fast_ccache_FREEIPA.LAB with result: 0/Success

(2021-03-10 15:47:06): [krb5_child[3066]] [sss_child_krb5_trace_cb] (0x4000): [3066] 1615358826.830696: Armor ccache sesion key: aes256-cts/DFBC

(2021-03-10 15:47:06): [krb5_child[3066]] [sss_child_krb5_trace_cb] (0x4000): [3066] 1615358826.830698: Creating authenticator for host/[e-mail] -> krbtgt/[e-mail], seqnum 0, subkey aes256-cts/FC48, session key aes256-cts/DFBC

(2021-03-10 15:47:06): [krb5_child[3066]] [sss_child_krb5_trace_cb] (0x4000): [3066] 1615358826.830700: FAST armor key: aes256-cts/4167

(2021-03-10 15:47:06): [krb5_child[3066]] [sss_child_krb5_trace_cb] (0x4000): [3066] 1615358826.830702: Sending unauthenticated request

(2021-03-10 15:47:06): [krb5_child[3066]] [sss_child_krb5_trace_cb] (0x4000): [3066] 1615358826.830703: Encoding request body and padata into FAST request

(2021-03-10 15:47:06): [krb5_child[3066]] [sss_child_krb5_trace_cb] (0x4000): [3066] 1615358826.830704: Sending request (1133 bytes) to FREEIPA.LAB

(2021-03-10 15:47:06): [krb5_child[3066]] [sss_child_krb5_trace_cb] (0x4000): [3066] 1615358826.830705: Initiating TCP connection to stream 192.168.0.245:88

(2021-03-10 15:47:06): [krb5_child[3066]] [sss_child_krb5_trace_cb] (0x4000): [3066] 1615358826.830706: Sending TCP request to stream 192.168.0.245:88

(2021-03-10 15:47:06): [krb5_child[3066]] [sss_child_krb5_trace_cb] (0x4000): [3066] 1615358826.830707: Received answer (768 bytes) from stream 192.168.0.245:88

(2021-03-10 15:47:06): [krb5_child[3066]] [sss_child_krb5_trace_cb] (0x4000): [3066] 1615358826.830708: Terminating TCP connection to stream 192.168.0.245:88

(2021-03-10 15:47:06): [krb5_child[3066]] [sss_child_krb5_trace_cb] (0x4000): [3066] 1615358826.830709: Response was from master KDC

(2021-03-10 15:47:06): [krb5_child[3066]] [sss_child_krb5_trace_cb] (0x4000): [3066] 1615358826.830710: Received error from KDC: -1765328359/Additional pre-authentication required

(2021-03-10 15:47:06): [krb5_child[3066]] [sss_child_krb5_trace_cb] (0x4000): [3066] 1615358826.830711: Decoding FAST response

(2021-03-10 15:47:06): [krb5_child[3066]] [sss_child_krb5_trace_cb] (0x4000): [3066] 1615358826.830714: Preauthenticating using KDC method data

(2021-03-10 15:47:06): [krb5_child[3066]] [sss_child_krb5_trace_cb] (0x4000): [3066] 1615358826.830715: Processing preauth types: PA-PK-AS-REQ (16), PA-FX-FAST (136), PA-ETYPE-INFO2 (19), PA-PKINIT-KX (147), PA-SPAKE (151), PA-ENCRYPTED-CHALLENGE (138), PA_AS_FRESHNESS (150), PA-FX-COOKIE (133), PA-FX-ERROR (137)

(2021-03-10 15:47:06): [krb5_child[3066]] [sss_child_krb5_trace_cb] (0x4000): [3066] 1615358826.830716: Selected etype info: etype aes256-cts, salt "Sb(P5NjuP@EJHY.h", params ""

(2021-03-10 15:47:06): [krb5_child[3066]] [sss_child_krb5_trace_cb] (0x4000): [3066] 1615358826.830717: Received cookie: MIT1\x00\x00\x00\x01\xff\xc5\xca\x15\xfe`\x8c\x8fm\xf1\x0d\x15F\xd0\xd1P\x9a:_\xdcgt\x84\x81w\x1c?4\xe8\x98{c\x18\x18|\xf2m\x03\xcf\xe7\x99\xcb$\xca\x9d\x97("\xb4vv\xdc\xa8\xfd\x80\xb5\xf7,\xdc\x04|\xd1\x0d\x82o\xc1\xf3.\xda\x1e\xde)\xed\xac\xbe\xe7\xc1b\xf3\xa9\x9ae\xfeJwcn\x0e:\x99\xb4>_\xcd\xb6y\xb1\xf7\x8f\x86W\xb9\x19\x15\xf4J\x17\x8b9\xf8\x99\x03\xa9\xa0~>p\xa4W\xaf\xbe\x99\x8d\xf9\xf6\xb5\x03\xb2+\xef

(2021-03-10 15:47:06): [krb5_child[3066]] [sss_krb5_responder] (0x4000): Got question [password].
(2021-03-10 15:47:06): [krb5_child[3066]] [sss_child_krb5_trace_cb] (0x4000): [3066] 1615358826.830718: SPAKE challenge received with group 1, pubkey 8F4EF911F1D3D626C6264A1CBC6D22E52B7AE72424F505CE1B400189A2D21ED7

(2021-03-10 15:47:06): [krb5_child[3066]] [sss_krb5_prompter] (0x4000): sss_krb5_prompter name [(null)] banner [(null)] num_prompts [1] EINVAL.
(2021-03-10 15:47:06): [krb5_child[3066]] [sss_krb5_prompter] (0x4000): Prompt [0][Password for [e-mail]].
(2021-03-10 15:47:06): [krb5_child[3066]] [sss_krb5_prompter] (0x0020): Cannot handle password prompts.
(2021-03-10 15:47:06): [krb5_child[3066]] [sss_child_krb5_trace_cb] (0x4000): [3066] 1615358826.830719: Preauth module spake (151) (real) returned: -1765328254/Cannot read password

(2021-03-10 15:47:06): [krb5_child[3066]] [sss_krb5_prompter] (0x4000): sss_krb5_prompter name [(null)] banner [(null)] num_prompts [1] EINVAL.
(2021-03-10 15:47:06): [krb5_child[3066]] [sss_krb5_prompter] (0x4000): Prompt [0][Password for [e-mail]].
(2021-03-10 15:47:06): [krb5_child[3066]] [sss_krb5_prompter] (0x0020): Cannot handle password prompts.
(2021-03-10 15:47:06): [krb5_child[3066]] [sss_child_krb5_trace_cb] (0x4000): [3066] 1615358826.830720: Preauth module encrypted_challenge (138) (real) returned: -1765328254/Cannot read password

(2021-03-10 15:47:06): [krb5_child[3066]] [get_and_save_tgt] (0x0400): krb5_get_init_creds_password returned [-1765328174] during pre-auth.
(2021-03-10 15:47:06): [krb5_child[3066]] [k5c_send_data] (0x0200): Received error code 0
(2021-03-10 15:47:06): [krb5_child[3066]] [pack_response_packet] (0x2000): response packet size: [12]
(2021-03-10 15:47:06): [krb5_child[3066]] [k5c_send_data] (0x4000): Response sent.
(2021-03-10 15:47:06): [krb5_child[3066]] [main] (0x0400): krb5_child completed successfully
(2021-03-10 15:47:12): [krb5_child[3067]] [main] (0x0400): krb5_child started.
(2021-03-10 15:47:12): [krb5_child[3067]] [unpack_buffer] (0x1000): total buffer size: [109]
(2021-03-10 15:47:12): [krb5_child[3067]] [unpack_buffer] (0x0100): cmd [241] uid [365400011] gid [365400011] validate [true] enterprise principal [false] offline [false] UPN [[e-mail]]
(2021-03-10 15:47:12): [krb5_child[3067]] [unpack_buffer] (0x2000): No old ccache
(2021-03-10 15:47:12): [krb5_child[3067]] [unpack_buffer] (0x0100): ccname: [KCM:] old_ccname: [not set] keytab: [/etc/krb5.keytab]
(2021-03-10 15:47:12): [krb5_child[3067]] [k5c_precreate_ccache] (0x4000): Recreating ccache
(2021-03-10 15:47:12): [krb5_child[3067]] [k5c_setup_fast] (0x0100): Fast principal is set to [host/[e-mail]]
(2021-03-10 15:47:12): [krb5_child[3067]] [find_principal_in_keytab] (0x4000): Trying to find principal host/[e-mail] in keytab.
(2021-03-10 15:47:12): [krb5_child[3067]] [match_principal] (0x1000): Principal matched to the sample (host/[e-mail]).
(2021-03-10 15:47:12): [krb5_child[3067]] [check_fast_ccache] (0x0200): FAST TGT is still valid.
(2021-03-10 15:47:12): [krb5_child[3067]] [become_user] (0x0200): Trying to become user [365400011][365400011].
(2021-03-10 15:47:12): [krb5_child[3067]] [main] (0x2000): Running as [365400011][365400011].
(2021-03-10 15:47:12): [krb5_child[3067]] [set_lifetime_options] (0x0100): No specific renewable lifetime requested.
(2021-03-10 15:47:12): [krb5_child[3067]] [set_lifetime_options] (0x0100): No specific lifetime requested.
(2021-03-10 15:47:12): [krb5_child[3067]] [set_canonicalize_option] (0x0100): Canonicalization is set to [true]
(2021-03-10 15:47:12): [krb5_child[3067]] [main] (0x0400): Will perform online auth
(2021-03-10 15:47:12): [krb5_child[3067]] [tgt_req_child] (0x1000): Attempting to get a TGT
(2021-03-10 15:47:12): [krb5_child[3067]] [get_and_save_tgt] (0x0400): Attempting kinit for realm [FREEIPA.LAB]
(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436798: Getting initial credentials for [e-mail]

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436799: FAST armor ccache: MEMORY:/var/lib/sss/db/fast_ccache_FREEIPA.LAB

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436800: Retrieving host/[e-mail] -> krb5_ccache_conf_data/fast_avail/krbtgt/[e-mail]@X-CACHECONF: from MEMORY:/var/lib/sss/db/fast_ccache_FREEIPA.LAB with result: -1765328243/Matching credential not found

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436802: Sending unauthenticated request

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436803: Sending request (180 bytes) to FREEIPA.LAB

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436804: Initiating TCP connection to stream 192.168.0.245:88

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436805: Sending TCP request to stream 192.168.0.245:88

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436806: Received answer (505 bytes) from stream 192.168.0.245:88

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436807: Terminating TCP connection to stream 192.168.0.245:88

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436808: Response was from master KDC

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436809: Received error from KDC: -1765328359/Additional pre-authentication required

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436810: Upgrading to FAST due to presence of PA_FX_FAST in reply

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436811: FAST armor ccache: MEMORY:/var/lib/sss/db/fast_ccache_FREEIPA.LAB

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436812: Retrieving host/[e-mail] -> krb5_ccache_conf_data/fast_avail/krbtgt/[e-mail]@X-CACHECONF: from MEMORY:/var/lib/sss/db/fast_ccache_FREEIPA.LAB with result: -1765328243/Matching credential not found

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436813: Getting credentials host/[e-mail] -> krbtgt/[e-mail] using ccache MEMORY:/var/lib/sss/db/fast_ccache_FREEIPA.LAB

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436814: Retrieving host/[e-mail] -> krbtgt/[e-mail] from MEMORY:/var/lib/sss/db/fast_ccache_FREEIPA.LAB with result: 0/Success

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436815: Armor ccache sesion key: aes256-cts/DFBC

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436817: Creating authenticator for host/[e-mail] -> krbtgt/[e-mail], seqnum 0, subkey aes256-cts/81B3, session key aes256-cts/DFBC

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436819: FAST armor key: aes256-cts/7BD4

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436821: Sending unauthenticated request

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436822: Encoding request body and padata into FAST request

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436823: Sending request (1133 bytes) to FREEIPA.LAB

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436824: Initiating TCP connection to stream 192.168.0.245:88

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436825: Sending TCP request to stream 192.168.0.245:88

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436826: Received answer (768 bytes) from stream 192.168.0.245:88

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436827: Terminating TCP connection to stream 192.168.0.245:88

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436828: Response was from master KDC

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436829: Received error from KDC: -1765328359/Additional pre-authentication required

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436830: Decoding FAST response

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436833: Preauthenticating using KDC method data

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436834: Processing preauth types: PA-PK-AS-REQ (16), PA-FX-FAST (136), PA-ETYPE-INFO2 (19), PA-PKINIT-KX (147), PA-SPAKE (151), PA-ENCRYPTED-CHALLENGE (138), PA_AS_FRESHNESS (150), PA-FX-COOKIE (133), PA-FX-ERROR (137)

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436835: Selected etype info: etype aes256-cts, salt "Sb(P5NjuP@EJHY.h", params ""

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436836: Received cookie: MIT1\x00\x00\x00\x01$\x89\xe5\xdeM\x0c\xb9\xbf4\xb9]\x02\xbf\xeb{B\xd5\xec\x94u\xd7\x17\xa6W\x88\x02Q$\xea\xd8\xbcW\xcbuCe\x0d!\x07\xc8\xd4S\xc4\xa0v\xa0B\x01s\x8ax\x98\x0e\x0b\x0a\x86=\xf6,\xe5\xcf2\x1a\xee\x81zw\xcb\xd6\xbe\x90E\xe4M\xeac%{\x0e\xbf\xeb\x0f\x08_B\x0e\x8d\xc7\xf6O\x13kP\xde\x97\x12Q\xd3K\x11\x91\xbd\xc4c\xe1\xc2rN\x9dF\x1et _\x97\x13\xe9T\xcd\xb1dq\xc6?\xd2KWI\xcd

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_krb5_responder] (0x4000): Got question [password].
(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436837: SPAKE challenge received with group 1, pubkey B1A9EF557490B82926C709104562B7909C90B6D048029750F6B6BACE2CBD5330

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436838: SPAKE key generated with pubkey 84DDE37EADDB0AA67C31779625F3BF1F9F303AC2D05C6CD70D02F0E12AC00BE8

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436839: SPAKE algorithm result: E9B4976DA979CDE31FCD41F5CC95F4D1A4E396C3D7E20616E8429F5FD5280FAD

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436840: SPAKE final transcript hash: C1D6EB57E4845C6CCA389D4574854A0169B510EEFE72E400F9523C187EB1AE98

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436841: Sending SPAKE response

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436842: Preauth module spake (151) (real) returned: 0/Success

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436843: Produced preauth for next request: PA-FX-COOKIE (133), PA-SPAKE (151)

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436844: Encoding request body and padata into FAST request

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436845: Sending request (1395 bytes) to FREEIPA.LAB

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436846: Initiating TCP connection to stream 192.168.0.245:88

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436847: Sending TCP request to stream 192.168.0.245:88

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436848: Received answer (768 bytes) from stream 192.168.0.245:88

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436849: Terminating TCP connection to stream 192.168.0.245:88

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436850: Response was from master KDC

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436851: Received error from KDC: -1765328360/Preauthentication failed

(2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436852: Decoding FAST response

(2021-03-10 15:47:12): [krb5_child[3067]] [get_and_save_tgt] (0x0020): 1704: [-1765328360][Preauthentication failed]
(2021-03-10 15:47:12): [krb5_child[3067]] [map_krb5_error] (0x0020): 1833: [-1765328360][Preauthentication failed]
(2021-03-10 15:47:12): [krb5_child[3067]] [k5c_send_data] (0x0200): Received error code 1432158222
(2021-03-10 15:47:12): [krb5_child[3067]] [pack_response_packet] (0x2000): response packet size: [4]
(2021-03-10 15:47:12): [krb5_child[3067]] [k5c_send_data] (0x4000): Response sent.
(2021-03-10 15:47:12): [krb5_child[3067]] [main] (0x0400): krb5_child completed successfully
(2021-03-10 15:47:14): [krb5_child[3069]] [main] (0x0400): krb5_child started.
(2021-03-10 15:47:14): [krb5_child[3069]] [unpack_buffer] (0x1000): total buffer size: [96]
(2021-03-10 15:47:14): [krb5_child[3069]] [unpack_buffer] (0x0100): cmd [249] uid [365400011] gid [365400011] validate [true] enterprise principal [false] offline [false] UPN [[e-mail]]
(2021-03-10 15:47:14): [krb5_child[3069]] [unpack_buffer] (0x2000): No old ccache
(2021-03-10 15:47:14): [krb5_child[3069]] [unpack_buffer] (0x0100): ccname: [KCM:] old_ccname: [not set] keytab: [/etc/krb5.keytab]
(2021-03-10 15:47:14): [krb5_child[3069]] [k5c_setup_fast] (0x0100): Fast principal is set to [host/[e-mail]]
(2021-03-10 15:47:14): [krb5_child[3069]] [find_principal_in_keytab] (0x4000): Trying to find principal host/[e-mail] in keytab.
(2021-03-10 15:47:14): [krb5_child[3069]] [match_principal] (0x1000): Principal matched to the sample (host/[e-mail]).
(2021-03-10 15:47:14): [krb5_child[3069]] [check_fast_ccache] (0x0200): FAST TGT is still valid.
(2021-03-10 15:47:14): [krb5_child[3069]] [become_user] (0x0200): Trying to become user [365400011][365400011].
(2021-03-10 15:47:14): [krb5_child[3069]] [main] (0x2000): Running as [365400011][365400011].
(2021-03-10 15:47:14): [krb5_child[3069]] [set_lifetime_options] (0x0100): No specific renewable lifetime requested.
(2021-03-10 15:47:14): [krb5_child[3069]] [set_lifetime_options] (0x0100): No specific lifetime requested.
(2021-03-10 15:47:14): [krb5_child[3069]] [set_canonicalize_option] (0x0100): Canonicalization is set to [true]
(2021-03-10 15:47:14): [krb5_child[3069]] [main] (0x0400): Will perform pre-auth
(2021-03-10 15:47:14): [krb5_child[3069]] [tgt_req_child] (0x1000): Attempting to get a TGT
(2021-03-10 15:47:14): [krb5_child[3069]] [get_and_save_tgt] (0x0400): Attempting kinit for realm [FREEIPA.LAB]
(2021-03-10 15:47:14): [krb5_child[3069]] [sss_child_krb5_trace_cb] (0x4000): [3069] 1615358834.778703: Getting initial credentials for [e-mail]

(2021-03-10 15:47:14): [krb5_child[3069]] [sss_child_krb5_trace_cb] (0x4000): [3069] 1615358834.778704: FAST armor ccache: MEMORY:/var/lib/sss/db/fast_ccache_FREEIPA.LAB

(2021-03-10 15:47:14): [krb5_child[3069]] [sss_child_krb5_trace_cb] (0x4000): [3069] 1615358834.778705: Retrieving host/[e-mail] -> krb5_ccache_conf_data/fast_avail/krbtgt/[e-mail]@X-CACHECONF: from MEMORY:/var/lib/sss/db/fast_ccache_FREEIPA.LAB with result: -1765328243/Matching credential not found

(2021-03-10 15:47:14): [krb5_child[3069]] [sss_child_krb5_trace_cb] (0x4000): [3069] 1615358834.778707: Sending unauthenticated request

(2021-03-10 15:47:14): [krb5_child[3069]] [sss_child_krb5_trace_cb] (0x4000): [3069] 1615358834.778708: Sending request (180 bytes) to FREEIPA.LAB

(2021-03-10 15:47:14): [krb5_child[3069]] [sss_child_krb5_trace_cb] (0x4000): [3069] 1615358834.778709: Initiating TCP connection to stream 192.168.0.245:88

(2021-03-10 15:47:14): [krb5_child[3069]] [sss_child_krb5_trace_cb] (0x4000): [3069] 1615358834.778710: Sending TCP request to stream 192.168.0.245:88

(2021-03-10 15:47:14): [krb5_child[3069]] [sss_child_krb5_trace_cb] (0x4000): [3069] 1615358834.778711: Received answer (505 bytes) from stream 192.168.0.245:88

(2021-03-10 15:47:14): [krb5_child[3069]] [sss_child_krb5_trace_cb] (0x4000): [3069] 1615358834.778712: Terminating TCP connection to stream 192.168.0.245:88

(2021-03-10 15:47:14): [krb5_child[3069]] [sss_child_krb5_trace_cb] (0x4000): [3069] 1615358834.778713: Response was from master KDC

(2021-03-10 15:47:14): [krb5_child[3069]] [sss_child_krb5_trace_cb] (0x4000): [3069] 1615358834.778714: Received error from KDC: -1765328359/Additional pre-authentication required

(2021-03-10 15:47:14): [krb5_child[3069]] [sss_child_krb5_trace_cb] (0x4000): [3069] 1615358834.778715: Upgrading to FAST due to presence of PA_FX_FAST in reply

(2021-03-10 15:47:14): [krb5_child[3069]] [sss_child_krb5_trace_cb] (0x4000): [3069] 1615358834.778716: FAST armor ccache: MEMORY:/var/lib/sss/db/fast_ccache_FREEIPA.LAB

(2021-03-10 15:47:14): [krb5_child[3069]] [sss_child_krb5_trace_cb] (0x4000): [3069] 1615358834.778717: Retrieving host/[e-mail] -> krb5_ccache_conf_data/fast_avail/krbtgt/[e-mail]@X-CACHECONF: from MEMORY:/var/lib/sss/db/fast_ccache_FREEIPA.LAB with result: -1765328243/Matching credential not found

(2021-03-10 15:47:14): [krb5_child[3069]] [sss_child_krb5_trace_cb] (0x4000): [3069] 1615358834.778718: Getting credentials host/[e-mail] -> krbtgt/[e-mail] using ccache MEMORY:/var/lib/sss/db/fast_ccache_FREEIPA.LAB

(2021-03-10 15:47:14): [krb5_child[3069]] [sss_child_krb5_trace_cb] (0x4000): [3069] 1615358834.778719: Retrieving host/[e-mail] -> krbtgt/[e-mail] from MEMORY:/var/lib/sss/db/fast_ccache_FREEIPA.LAB with result: 0/Success

(2021-03-10 15:47:14): [krb5_child[3069]] [sss_child_krb5_trace_cb] (0x4000): [3069] 1615358834.778720: Armor ccache sesion key: aes256-cts/DFBC

(2021-03-10 15:47:14): [krb5_child[3069]] [sss_child_krb5_trace_cb] (0x4000): [3069] 1615358834.778722: Creating authenticator for host/[e-mail] -> krbtgt/[e-mail], seqnum 0, subkey aes256-cts/106F, session key aes256-cts/DFBC

(2021-03-10 15:47:14): [krb5_child[3069]] [sss_child_krb5_trace_cb] (0x4000): [3069] 1615358834.778724: FAST armor key: aes256-cts/F35A

(2021-03-10 15:47:14): [krb5_child[3069]] [sss_child_krb5_trace_cb] (0x4000): [3069] 1615358834.778726: Sending unauthenticated request

(2021-03-10 15:47:14): [krb5_child[3069]] [sss_child_krb5_trace_cb] (0x4000): [3069] 1615358834.778727: Encoding request body and padata into FAST request

(2021-03-10 15:47:14): [krb5_child[3069]] [sss_child_krb5_trace_cb] (0x4000): [3069] 1615358834.778728: Sending request (1133 bytes) to FREEIPA.LAB

(2021-03-10 15:47:14): [krb5_child[3069]] [sss_child_krb5_trace_cb] (0x4000): [3069] 1615358834.778729: Initiating TCP connection to stream 192.168.0.245:88

(2021-03-10 15:47:14): [krb5_child[3069]] [sss_child_krb5_trace_cb] (0x4000): [3069] 1615358834.778730: Sending TCP request to stream 192.168.0.245:88

(2021-03-10 15:47:14): [krb5_child[3069]] [sss_child_krb5_trace_cb] (0x4000): [3069] 1615358834.778731: Received answer (768 bytes) from stream 192.168.0.245:88

(2021-03-10 15:47:14): [krb5_child[3069]] [sss_child_krb5_trace_cb] (0x4000): [3069] 1615358834.778732: Terminating TCP connection to stream 192.168.0.245:88

(2021-03-10 15:47:14): [krb5_child[3069]] [sss_child_krb5_trace_cb] (0x4000): [3069] 1615358834.778733: Response was from master KDC

(2021-03-10 15:47:14): [krb5_child[3069]] [sss_child_krb5_trace_cb] (0x4000): [3069] 1615358834.778734: Received error from KDC: -1765328359/Additional pre-authentication required

(2021-03-10 15:47:14): [krb5_child[3069]] [sss_child_krb5_trace_cb] (0x4000): [3069] 1615358834.778735: Decoding FAST response

(2021-03-10 15:47:14): [krb5_child[3069]] [sss_child_krb5_trace_cb] (0x4000): [3069] 1615358834.778738: Preauthenticating using KDC method data

(2021-03-10 15:47:14): [krb5_child[3069]] [sss_child_krb5_trace_cb] (0x4000): [3069] 1615358834.778739: Processing preauth types: PA-PK-AS-REQ (16), PA-FX-FAST (136), PA-ETYPE-INFO2 (19), PA-PKINIT-KX (147), PA-SPAKE (151), PA-ENCRYPTED-CHALLENGE (138), PA_AS_FRESHNESS (150), PA-FX-COOKIE (133), PA-FX-ERROR (137)

(2021-03-10 15:47:14): [krb5_child[3069]] [sss_child_krb5_trace_cb] (0x4000): [3069] 1615358834.778740: Selected etype info: etype aes256-cts, salt "Sb(P5NjuP@EJHY.h", params ""

(2021-03-10 15:47:14): [krb5_child[3069]] [sss_child_krb5_trace_cb] (0x4000): [3069] 1615358834.778741: Received cookie: MIT1\x00\x00\x00\x01\xb1\x92\xca\x09\xdc\xb4\x87\xad\x81\x87\xbb\xb9\xb1aDR\x18\xdf\xc8\xca_\xc6\xe6\xa6y!\xe7\xb9\xc4\x844\xa3k\xe5~\xb3\xce\xd0\xcb\xd3u\x996u\x91\x06v\x9f\x8d\x02\x10\xfa\x96B\x89V\xb9\x92\x09lae\xf1\x9a8\x0b\xd4\xf3^\xc2\x1a\x17\xb2\xc4\x19j]\xdc\xdd\xfc\xf7bs\x0cd\x8d\xf8\xe8\xa2\xba\x838\x7f\xcf\xad\x87\x13\xeb\xadW+U\x7f\xe8\x83ko\xb3\x95\xe8\xb3x\xd1\x10\xc2\x91\xe8B-\x8c]&\xbc.\xad\xf9\xfd\x1c\xb0,

(2021-03-10 15:47:14): [krb5_child[3069]] [sss_krb5_responder] (0x4000): Got question [password].
(2021-03-10 15:47:14): [krb5_child[3069]] [sss_child_krb5_trace_cb] (0x4000): [3069] 1615358834.778742: SPAKE challenge received with group 1, pubkey D763432BF5C15DE6D4CEA2F2FF97E0A2B766EEA6B1A275C5B44F19A590E8ACFC

(2021-03-10 15:47:14): [krb5_child[3069]] [sss_krb5_prompter] (0x4000): sss_krb5_prompter name [(null)] banner [(null)] num_prompts [1] EINVAL.
(2021-03-10 15:47:14): [krb5_child[3069]] [sss_krb5_prompter] (0x4000): Prompt [0][Password for [e-mail]].
(2021-03-10 15:47:14): [krb5_child[3069]] [sss_krb5_prompter] (0x0020): Cannot handle password prompts.
(2021-03-10 15:47:14): [krb5_child[3069]] [sss_child_krb5_trace_cb] (0x4000): [3069] 1615358834.778743: Preauth module spake (151) (real) returned: -1765328254/Cannot read password

(2021-03-10 15:47:14): [krb5_child[3069]] [sss_krb5_prompter] (0x4000): sss_krb5_prompter name [(null)] banner [(null)] num_prompts [1] EINVAL.
(2021-03-10 15:47:14): [krb5_child[3069]] [sss_krb5_prompter] (0x4000): Prompt [0][Password for [e-mail]].
(2021-03-10 15:47:14): [krb5_child[3069]] [sss_krb5_prompter] (0x0020): Cannot handle password prompts.
(2021-03-10 15:47:14): [krb5_child[3069]] [sss_child_krb5_trace_cb] (0x4000): [3069] 1615358834.778744: Preauth module encrypted_challenge (138) (real) returned: -1765328254/Cannot read password

(2021-03-10 15:47:14): [krb5_child[3069]] [get_and_save_tgt] (0x0400): krb5_get_init_creds_password returned [-1765328174] during pre-auth.
(2021-03-10 15:47:14): [krb5_child[3069]] [k5c_send_data] (0x0200): Received error code 0
(2021-03-10 15:47:14): [krb5_child[3069]] [pack_response_packet] (0x2000): response packet size: [12]
(2021-03-10 15:47:14): [krb5_child[3069]] [k5c_send_data] (0x4000): Response sent.
(2021-03-10 15:47:14): [krb5_child[3069]] [main] (0x0400): krb5_child completed successfully
(2021-03-10 15:47:20): [krb5_child[3070]] [main] (0x0400): krb5_child started.
(2021-03-10 15:47:20): [krb5_child[3070]] [unpack_buffer] (0x1000): total buffer size: [109]
(2021-03-10 15:47:20): [krb5_child[3070]] [unpack_buffer] (0x0100): cmd [241] uid [365400011] gid [365400011] validate [true] enterprise principal [false] offline [false] UPN [[e-mail]]
(2021-03-10 15:47:20): [krb5_child[3070]] [unpack_buffer] (0x2000): No old ccache
(2021-03-10 15:47:20): [krb5_child[3070]] [unpack_buffer] (0x0100): ccname: [KCM:] old_ccname: [not set] keytab: [/etc/krb5.keytab]
(2021-03-10 15:47:20): [krb5_child[3070]] [k5c_precreate_ccache] (0x4000): Recreating ccache
(2021-03-10 15:47:20): [krb5_child[3070]] [k5c_setup_fast] (0x0100): Fast principal is set to [host/[e-mail]]
(2021-03-10 15:47:20): [krb5_child[3070]] [find_principal_in_keytab] (0x4000): Trying to find principal host/[e-mail] in keytab.
(2021-03-10 15:47:20): [krb5_child[3070]] [match_principal] (0x1000): Principal matched to the sample (host/[e-mail]).
(2021-03-10 15:47:20): [krb5_child[3070]] [check_fast_ccache] (0x0200): FAST TGT is still valid.
(2021-03-10 15:47:20): [krb5_child[3070]] [become_user] (0x0200): Trying to become user [365400011][365400011].
(2021-03-10 15:47:20): [krb5_child[3070]] [main] (0x2000): Running as [365400011][365400011].
(2021-03-10 15:47:20): [krb5_child[3070]] [set_lifetime_options] (0x0100): No specific renewable lifetime requested.
(2021-03-10 15:47:20): [krb5_child[3070]] [set_lifetime_options] (0x0100): No specific lifetime requested.
(2021-03-10 15:47:20): [krb5_child[3070]] [set_canonicalize_option] (0x0100): Canonicalization is set to [true]
(2021-03-10 15:47:20): [krb5_child[3070]] [main] (0x0400): Will perform online auth
(2021-03-10 15:47:20): [krb5_child[3070]] [tgt_req_child] (0x1000): Attempting to get a TGT
(2021-03-10 15:47:20): [krb5_child[3070]] [get_and_save_tgt] (0x0400): Attempting kinit for realm [FREEIPA.LAB]
(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246680: Getting initial credentials for [e-mail]

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246681: FAST armor ccache: MEMORY:/var/lib/sss/db/fast_ccache_FREEIPA.LAB

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246682: Retrieving host/[e-mail] -> krb5_ccache_conf_data/fast_avail/krbtgt/[e-mail]@X-CACHECONF: from MEMORY:/var/lib/sss/db/fast_ccache_FREEIPA.LAB with result: -1765328243/Matching credential not found

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246684: Sending unauthenticated request

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246685: Sending request (180 bytes) to FREEIPA.LAB

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246686: Initiating TCP connection to stream 192.168.0.245:88

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246687: Sending TCP request to stream 192.168.0.245:88

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246688: Received answer (505 bytes) from stream 192.168.0.245:88

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246689: Terminating TCP connection to stream 192.168.0.245:88

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246690: Response was from master KDC

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246691: Received error from KDC: -1765328359/Additional pre-authentication required

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246692: Upgrading to FAST due to presence of PA_FX_FAST in reply

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246693: FAST armor ccache: MEMORY:/var/lib/sss/db/fast_ccache_FREEIPA.LAB

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246694: Retrieving host/[e-mail] -> krb5_ccache_conf_data/fast_avail/krbtgt/[e-mail]@X-CACHECONF: from MEMORY:/var/lib/sss/db/fast_ccache_FREEIPA.LAB with result: -1765328243/Matching credential not found

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246695: Getting credentials host/[e-mail] -> krbtgt/[e-mail] using ccache MEMORY:/var/lib/sss/db/fast_ccache_FREEIPA.LAB

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246696: Retrieving host/[e-mail] -> krbtgt/[e-mail] from MEMORY:/var/lib/sss/db/fast_ccache_FREEIPA.LAB with result: 0/Success

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246697: Armor ccache sesion key: aes256-cts/DFBC

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246699: Creating authenticator for host/[e-mail] -> krbtgt/[e-mail], seqnum 0, subkey aes256-cts/2B7B, session key aes256-cts/DFBC

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246701: FAST armor key: aes256-cts/F6C9

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246703: Sending unauthenticated request

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246704: Encoding request body and padata into FAST request

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246705: Sending request (1133 bytes) to FREEIPA.LAB

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246706: Initiating TCP connection to stream 192.168.0.245:88

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246707: Sending TCP request to stream 192.168.0.245:88

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246708: Received answer (768 bytes) from stream 192.168.0.245:88

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246709: Terminating TCP connection to stream 192.168.0.245:88

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246710: Response was from master KDC

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246711: Received error from KDC: -1765328359/Additional pre-authentication required

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246712: Decoding FAST response

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246715: Preauthenticating using KDC method data

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246716: Processing preauth types: PA-PK-AS-REQ (16), PA-FX-FAST (136), PA-ETYPE-INFO2 (19), PA-PKINIT-KX (147), PA-SPAKE (151), PA-ENCRYPTED-CHALLENGE (138), PA_AS_FRESHNESS (150), PA-FX-COOKIE (133), PA-FX-ERROR (137)

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246717: Selected etype info: etype aes256-cts, salt "Sb(P5NjuP@EJHY.h", params ""

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246718: Received cookie: MIT1\x00\x00\x00\x01R\x8f%5\x9a\xc5\x0f\xe8\x8d,\x00\x8e\xccH\xe2\xe8\xfd\xb2<R\xb5bl\xfb\x1eF0_\xfd[.\x10D\xc7k\x81\xb5\x88Pk49\xabc/a\x9b\xd3Hq\xec\x0ae\xa0\x0d\xec\x0eQv=2\x85\xdcO\x95\xab\xb21m\x0a\xd8\x03\x15\xe5\xd6\xc1\xa3\xbb\xe9\x1b\xaa\x15\xec%\xef($\x0dC\xff\x02\xc3\x1bK\x9c|\xbbg_\xa8\x96\x97\x9bD\x05\xc9\x8e\xe6\xd3\xfaOs\xf4D\xc5V\xa6\xb2qgo\xa8\xbc\xb9\x81h3\x1bf(

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_krb5_responder] (0x4000): Got question [password].
(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246719: SPAKE challenge received with group 1, pubkey AAD03D5937C55BE7DEAE0239FF154C2E19C9C778A7B91D73BC0BE7D3F156A5B4

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246720: SPAKE key generated with pubkey 91280D73F8E8C97C6E05341B344089C66590FFE0AA24666C480D655C191DA2F9

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246721: SPAKE algorithm result: 3DB17C68FCAAE00B4E8B625FB16D9DF013539A5B8FE952D4615789080790678F

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246722: SPAKE final transcript hash: F0059A861616C1A99C1CFAB9D8B2935622314685DBA8E026E0B3656184300C04

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246723: Sending SPAKE response

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246724: Preauth module spake (151) (real) returned: 0/Success

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246725: Produced preauth for next request: PA-FX-COOKIE (133), PA-SPAKE (151)

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246726: Encoding request body and padata into FAST request

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246727: Sending request (1395 bytes) to FREEIPA.LAB

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246728: Initiating TCP connection to stream 192.168.0.245:88

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246729: Sending TCP request to stream 192.168.0.245:88

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246730: Received answer (768 bytes) from stream 192.168.0.245:88

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246731: Terminating TCP connection to stream 192.168.0.245:88

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246732: Response was from master KDC

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246733: Received error from KDC: -1765328360/Preauthentication failed

(2021-03-10 15:47:20): [krb5_child[3070]] [sss_child_krb5_trace_cb] (0x4000): [3070] 1615358840.246734: Decoding FAST response

(2021-03-10 15:47:20): [krb5_child[3070]] [get_and_save_tgt] (0x0020): 1704: [-1765328360][Preauthentication failed]
(2021-03-10 15:47:20): [krb5_child[3070]] [map_krb5_error] (0x0020): 1833: [-1765328360][Preauthentication failed]
(2021-03-10 15:47:20): [krb5_child[3070]] [k5c_send_data] (0x0200): Received error code 1432158222
(2021-03-10 15:47:20): [krb5_child[3070]] [pack_response_packet] (0x2000): response packet size: [4]
(2021-03-10 15:47:20): [krb5_child[3070]] [k5c_send_data] (0x4000): Response sent.
(2021-03-10 15:47:20): [krb5_child[3070]] [main] (0x0400): krb5_child completed successfully
(2021-03-10 15:47:22): [krb5_child[3072]] [main] (0x0400): krb5_child started.
(2021-03-10 15:47:22): [krb5_child[3072]] [unpack_buffer] (0x1000): total buffer size: [96]
(2021-03-10 15:47:22): [krb5_child[3072]] [unpack_buffer] (0x0100): cmd [249] uid [365400011] gid [365400011] validate [true] enterprise principal [false] offline [false] UPN [[e-mail]]
(2021-03-10 15:47:22): [krb5_child[3072]] [unpack_buffer] (0x2000): No old ccache
(2021-03-10 15:47:22): [krb5_child[3072]] [unpack_buffer] (0x0100): ccname: [KCM:] old_ccname: [not set] keytab: [/etc/krb5.keytab]
(2021-03-10 15:47:22): [krb5_child[3072]] [k5c_setup_fast] (0x0100): Fast principal is set to [host/[e-mail]]
(2021-03-10 15:47:22): [krb5_child[3072]] [find_principal_in_keytab] (0x4000): Trying to find principal host/[e-mail] in keytab.
(2021-03-10 15:47:22): [krb5_child[3072]] [match_principal] (0x1000): Principal matched to the sample (host/[e-mail]).
(2021-03-10 15:47:22): [krb5_child[3072]] [check_fast_ccache] (0x0200): FAST TGT is still valid.
(2021-03-10 15:47:22): [krb5_child[3072]] [become_user] (0x0200): Trying to become user [365400011][365400011].
(2021-03-10 15:47:22): [krb5_child[3072]] [main] (0x2000): Running as [365400011][365400011].
(2021-03-10 15:47:22): [krb5_child[3072]] [set_lifetime_options] (0x0100): No specific renewable lifetime requested.
(2021-03-10 15:47:22): [krb5_child[3072]] [set_lifetime_options] (0x0100): No specific lifetime requested.
(2021-03-10 15:47:22): [krb5_child[3072]] [set_canonicalize_option] (0x0100): Canonicalization is set to [true]
(2021-03-10 15:47:22): [krb5_child[3072]] [main] (0x0400): Will perform pre-auth
(2021-03-10 15:47:22): [krb5_child[3072]] [tgt_req_child] (0x1000): Attempting to get a TGT
(2021-03-10 15:47:22): [krb5_child[3072]] [get_and_save_tgt] (0x0400): Attempting kinit for realm [FREEIPA.LAB]
(2021-03-10 15:47:22): [krb5_child[3072]] [sss_child_krb5_trace_cb] (0x4000): [3072] 1615358842.024736: Getting initial credentials for [e-mail]

(2021-03-10 15:47:22): [krb5_child[3072]] [sss_child_krb5_trace_cb] (0x4000): [3072] 1615358842.024737: FAST armor ccache: MEMORY:/var/lib/sss/db/fast_ccache_FREEIPA.LAB

(2021-03-10 15:47:22): [krb5_child[3072]] [sss_child_krb5_trace_cb] (0x4000): [3072] 1615358842.024738: Retrieving host/[e-mail] -> krb5_ccache_conf_data/fast_avail/krbtgt/[e-mail]@X-CACHECONF: from MEMORY:/var/lib/sss/db/fast_ccache_FREEIPA.LAB with result: -1765328243/Matching credential not found

(2021-03-10 15:47:22): [krb5_child[3072]] [sss_child_krb5_trace_cb] (0x4000): [3072] 1615358842.024740: Sending unauthenticated request

(2021-03-10 15:47:22): [krb5_child[3072]] [sss_child_krb5_trace_cb] (0x4000): [3072] 1615358842.024741: Sending request (180 bytes) to FREEIPA.LAB

(2021-03-10 15:47:22): [krb5_child[3072]] [sss_child_krb5_trace_cb] (0x4000): [3072] 1615358842.024742: Initiating TCP connection to stream 192.168.0.245:88

(2021-03-10 15:47:22): [krb5_child[3072]] [sss_child_krb5_trace_cb] (0x4000): [3072] 1615358842.024743: Sending TCP request to stream 192.168.0.245:88

(2021-03-10 15:47:22): [krb5_child[3072]] [sss_child_krb5_trace_cb] (0x4000): [3072] 1615358842.024744: Received answer (504 bytes) from stream 192.168.0.245:88

(2021-03-10 15:47:22): [krb5_child[3072]] [sss_child_krb5_trace_cb] (0x4000): [3072] 1615358842.024745: Terminating TCP connection to stream 192.168.0.245:88

(2021-03-10 15:47:22): [krb5_child[3072]] [sss_child_krb5_trace_cb] (0x4000): [3072] 1615358842.024746: Response was from master KDC

(2021-03-10 15:47:22): [krb5_child[3072]] [sss_child_krb5_trace_cb] (0x4000): [3072] 1615358842.024747: Received error from KDC: -1765328359/Additional pre-authentication required

(2021-03-10 15:47:22): [krb5_child[3072]] [sss_child_krb5_trace_cb] (0x4000): [3072] 1615358842.024748: Upgrading to FAST due to presence of PA_FX_FAST in reply

(2021-03-10 15:47:22): [krb5_child[3072]] [sss_child_krb5_trace_cb] (0x4000): [3072] 1615358842.024749: FAST armor ccache: MEMORY:/var/lib/sss/db/fast_ccache_FREEIPA.LAB

(2021-03-10 15:47:22): [krb5_child[3072]] [sss_child_krb5_trace_cb] (0x4000): [3072] 1615358842.024750: Retrieving host/[e-mail] -> krb5_ccache_conf_data/fast_avail/krbtgt/[e-mail]@X-CACHECONF: from MEMORY:/var/lib/sss/db/fast_ccache_FREEIPA.LAB with result: -1765328243/Matching credential not found

(2021-03-10 15:47:22): [krb5_child[3072]] [sss_child_krb5_trace_cb] (0x4000): [3072] 1615358842.024751: Getting credentials host/[e-mail] -> krbtgt/[e-mail] using ccache MEMORY:/var/lib/sss/db/fast_ccache_FREEIPA.LAB

(2021-03-10 15:47:22): [krb5_child[3072]] [sss_child_krb5_trace_cb] (0x4000): [3072] 1615358842.024752: Retrieving host/[e-mail] -> krbtgt/[e-mail] from MEMORY:/var/lib/sss/db/fast_ccache_FREEIPA.LAB with result: 0/Success

(2021-03-10 15:47:22): [krb5_child[3072]] [sss_child_krb5_trace_cb] (0x4000): [3072] 1615358842.024753: Armor ccache sesion key: aes256-cts/DFBC

(2021-03-10 15:47:22): [krb5_child[3072]] [sss_child_krb5_trace_cb] (0x4000): [3072] 1615358842.024755: Creating authenticator for host/[e-mail] -> krbtgt/[e-mail], seqnum 0, subkey aes256-cts/BFF8, session key aes256-cts/DFBC

(2021-03-10 15:47:22): [krb5_child[3072]] [sss_child_krb5_trace_cb] (0x4000): [3072] 1615358842.024757: FAST armor key: aes256-cts/9C25

(2021-03-10 15:47:22): [krb5_child[3072]] [sss_child_krb5_trace_cb] (0x4000): [3072] 1615358842.024759: Sending unauthenticated request

(2021-03-10 15:47:22): [krb5_child[3072]] [sss_child_krb5_trace_cb] (0x4000): [3072] 1615358842.024760: Encoding request body and padata into FAST request

(2021-03-10 15:47:22): [krb5_child[3072]] [sss_child_krb5_trace_cb] (0x4000): [3072] 1615358842.024761: Sending request (1132 bytes) to FREEIPA.LAB

(2021-03-10 15:47:22): [krb5_child[3072]] [sss_child_krb5_trace_cb] (0x4000): [3072] 1615358842.024762: Initiating TCP connection to stream 192.168.0.245:88

(2021-03-10 15:47:22): [krb5_child[3072]] [sss_child_krb5_trace_cb] (0x4000): [3072] 1615358842.024763: Sending TCP request to stream 192.168.0.245:88

(2021-03-10 15:47:22): [krb5_child[3072]] [sss_child_krb5_trace_cb] (0x4000): [3072] 1615358842.024764: Received answer (766 bytes) from stream 192.168.0.245:88

(2021-03-10 15:47:22): [krb5_child[3072]] [sss_child_krb5_trace_cb] (0x4000): [3072] 1615358842.024765: Terminating TCP connection to stream 192.168.0.245:88

(2021-03-10 15:47:22): [krb5_child[3072]] [sss_child_krb5_trace_cb] (0x4000): [3072] 1615358842.024766: Response was from master KDC

(2021-03-10 15:47:22): [krb5_child[3072]] [sss_child_krb5_trace_cb] (0x4000): [3072] 1615358842.024767: Received error from KDC: -1765328359/Additional pre-authentication required

(2021-03-10 15:47:22): [krb5_child[3072]] [sss_child_krb5_trace_cb] (0x4000): [3072] 1615358842.024768: Decoding FAST response

(2021-03-10 15:47:22): [krb5_child[3072]] [sss_child_krb5_trace_cb] (0x4000): [3072] 1615358842.024771: Preauthenticating using KDC method data

(2021-03-10 15:47:22): [krb5_child[3072]] [sss_child_krb5_trace_cb] (0x4000): [3072] 1615358842.024772: Processing preauth types: PA-PK-AS-REQ (16), PA-FX-FAST (136), PA-ETYPE-INFO2 (19), PA-PKINIT-KX (147), PA-SPAKE (151), PA-ENCRYPTED-CHALLENGE (138), PA_AS_FRESHNESS (150), PA-FX-COOKIE (133), PA-FX-ERROR (137)

(2021-03-10 15:47:22): [krb5_child[3072]] [sss_child_krb5_trace_cb] (0x4000): [3072] 1615358842.024773: Selected etype info: etype aes256-cts, salt "Sb(P5NjuP@EJHY.h", params ""

(2021-03-10 15:47:22): [krb5_child[3072]] [sss_child_krb5_trace_cb] (0x4000): [3072] 1615358842.024774: Received cookie: MIT1\x00\x00\x00\x01\xc9-\xcb)Nd\xad\xb5\xb82)\xcek!x\x9c|\xde\xe0+Y\xe7$9\xda89\xdeN$\xf1\xfe:\xca\xa6\xab\x07}\x08\xbdlc\x1a\xda\x13\x8d\x9fb\x97\xcf\xa6\x1c4\x82\xc3\xa1u\xc1\x05\xc3\xe1=\xbe\xd5K\x98\x01\xfbm\xd4\xf3S\xcc\xb5e.\x131\xda\xfd\x04\x19oA\xc8 \xa1\x10\xbb\xe0\xd0\x82\xf0/?\x89\xb9\xbe\xd8\xe4\xa9]\x88)\x12\xf6\xfc\x0f\x1f\x05G\x0b\x8c6\x0773\xe7\xb4\xa7W\x04\x1a\x1a\x1b\xaf\x91[\x18\xe6

(2021-03-10 15:47:22): [krb5_child[3072]] [sss_krb5_responder] (0x4000): Got question [password].
(2021-03-10 15:47:22): [krb5_child[3072]] [sss_child_krb5_trace_cb] (0x4000): [3072] 1615358842.024775: SPAKE challenge received with group 1, pubkey E310505029EFD651CC7E33DAF052940519E287C12EE8ABFFA5A67C95E86BE8A2

(2021-03-10 15:47:22): [krb5_child[3072]] [sss_krb5_prompter] (0x4000): sss_krb5_prompter name [(null)] banner [(null)] num_prompts [1] EINVAL.
(2021-03-10 15:47:22): [krb5_child[3072]] [sss_krb5_prompter] (0x4000): Prompt [0][Password for [e-mail]].
(2021-03-10 15:47:22): [krb5_child[3072]] [sss_krb5_prompter] (0x0020): Cannot handle password prompts.
(2021-03-10 15:47:22): [krb5_child[3072]] [sss_child_krb5_trace_cb] (0x4000): [3072] 1615358842.024776: Preauth module spake (151) (real) returned: -1765328254/Cannot read password

(2021-03-10 15:47:22): [krb5_child[3072]] [sss_krb5_prompter] (0x4000): sss_krb5_prompter name [(null)] banner [(null)] num_prompts [1] EINVAL.
(2021-03-10 15:47:22): [krb5_child[3072]] [sss_krb5_prompter] (0x4000): Prompt [0][Password for [e-mail]].
(2021-03-10 15:47:22): [krb5_child[3072]] [sss_krb5_prompter] (0x0020): Cannot handle password prompts.
(2021-03-10 15:47:22): [krb5_child[3072]] [sss_child_krb5_trace_cb] (0x4000): [3072] 1615358842.024777: Preauth module encrypted_challenge (138) (real) returned: -1765328254/Cannot read password

(2021-03-10 15:47:22): [krb5_child[3072]] [get_and_save_tgt] (0x0400): krb5_get_init_creds_password returned [-1765328174] during pre-auth.
(2021-03-10 15:47:22): [krb5_child[3072]] [k5c_send_data] (0x0200): Received error code 0
(2021-03-10 15:47:22): [krb5_child[3072]] [pack_response_packet] (0x2000): response packet size: [12]
(2021-03-10 15:47:22): [krb5_child[3072]] [k5c_send_data] (0x4000): Response sent.
(2021-03-10 15:47:22): [krb5_child[3072]] [main] (0x0400): krb5_child completed successfully

[Sumit Bose]

On Wed, Mar 10, 2021 at 07:06:34AM -0000, Sam Bell via FreeIPA-users wrote:
> Thanks for the reply.
> Following are the details:
> Server ip: 192.168.0.245
> Client : 192.168.0.248
> krb5_child.log content:

...
> (2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436837: SPAKE challenge received with group 1, pubkey B1A9EF557490B82926C709104562B7909C90B6D048029750F6B6BACE2CBD5330
>
> (2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436838: SPAKE key generated with pubkey 84DDE37EADDB0AA67C31779625F3BF1F9F303AC2D05C6CD70D02F0E12AC00BE8
>
> (2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436839: SPAKE algorithm result: E9B4976DA979CDE31FCD41F5CC95F4D1A4E396C3D7E20616E8429F5FD5280FAD
>
> (2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436840: SPAKE final transcript hash: C1D6EB57E4845C6CCA389D4574854A0169B510EEFE72E400F9523C187EB1AE98
>
> (2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436841: Sending SPAKE response
>
> (2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436842: Preauth module spake (151) (real) returned: 0/Success
>
> (2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436843: Produced preauth for next request: PA-FX-COOKIE (133), PA-SPAKE (151)
>
> (2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436844: Encoding request body and padata into FAST request
>
> (2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436845: Sending request (1395 bytes) to FREEIPA.LAB
>
> (2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436846: Initiating TCP connection to stream 192.168.0.245:88
>
> (2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436847: Sending TCP request to stream 192.168.0.245:88
>
> (2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436848: Received answer (768 bytes) from stream 192.168.0.245:88
>
> (2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436849: Terminating TCP connection to stream 192.168.0.245:88
>
> (2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436850: Response was from master KDC
>
> (2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436851: Received error from KDC: -1765328360/Preauthentication failed
>
> (2021-03-10 15:47:12): [krb5_child[3067]] [sss_child_krb5_trace_cb] (0x4000): [3067] 1615358832.436852: Decoding FAST response
>
> (2021-03-10 15:47:12): [krb5_child[3067]] [get_and_save_tgt] (0x0020): 1704: [-1765328360][Preauthentication failed]
> (2021-03-10 15:47:12): [krb5_child[3067]] [map_krb5_error] (0x0020): 1833: [-1765328360][Preauthentication failed]
> (2021-03-10 15:47:12): [krb5_child[3067]] [k5c_send_data] (0x0200): Received error code 1432158222
> (2021-03-10 15:47:12): [krb5_child[3067]] [pack_response_packet] (0x2000): response packet size: [4]
> (2021-03-10 15:47:12): [krb5_child[3067]] [k5c_send_data] (0x4000): Response sent.
> (2021-03-10 15:47:12): [krb5_child[3067]] [main] (0x0400): krb5_child completed successfully

Hi,

'Preauthentication failed' is returned by the KDC and typically
indicates a wrong password. Since it works with the older IPA client I
expect that the password should work. Can you check in the krb5kdc.log
in the FreeIPA server what messages are logged at the same time?

bye,
Sumit

[Sam Bell]

Yeah the password is right. 
On a separate note, on the client machine I had login problem on both Ubuntu(installed before)
and Fedora. So the problem could be with server.

For pre-authentication I used following commands:
# kadmin.local
kadmin.local: modprinc +requires_preauth testuser
Principal "[e-mail]" modified.

Server: xpsserver.freeipa.lab (fedora)
freeipa-server version: 4.9.2 (4.fc32)

client: mu3090x1.freeipa.lab
freeipa-client version: 4.9.2 (4.fc33)

Here's the log from krb5kdc.log from the server:

Mar 10 15:47:06 xpsserver.freeipa.lab krb5kdc[1225](info): AS_REQ (6 etypes {aes256-cts-hmac-sha1-96(18), aes256-cts-hmac-sha384-192(20), camellia256-cts-cmac(26), aes128-cts-hmac-sha1-96(17), aes128-cts-hmac-sha256-128(19), camellia128-cts-cmac(25)}) 192.168.0.248: NEEDED_PREAUTH: [e-mail] for krbtgt/[e-mail], Additional pre-authentication required
Mar 10 15:47:06 xpsserver.freeipa.lab krb5kdc[1225](info): closing down fd 11
Mar 10 15:47:06 xpsserver.freeipa.lab krb5kdc[1223](info): AS_REQ (6 etypes {aes256-cts-hmac-sha1-96(18), aes256-cts-hmac-sha384-192(20), camellia256-cts-cmac(26), aes128-cts-hmac-sha1-96(17), aes128-cts-hmac-sha256-128(19), camellia128-cts-cmac(25)}) 192.168.0.248: NEEDED_PREAUTH: [e-mail] for krbtgt/[e-mail], Additional pre-authentication required
Mar 10 15:47:06 xpsserver.freeipa.lab krb5kdc[1223](info): closing down fd 11
Mar 10 15:47:12 xpsserver.freeipa.lab krb5kdc[1223](info): AS_REQ (6 etypes {aes256-cts-hmac-sha1-96(18), aes256-cts-hmac-sha384-192(20), camellia256-cts-cmac(26), aes128-cts-hmac-sha1-96(17), aes128-cts-hmac-sha256-128(19), camellia128-cts-cmac(25)}) 192.168.0.248: NEEDED_PREAUTH: [e-mail] for krbtgt/[e-mail], Additional pre-authentication required
Mar 10 15:47:12 xpsserver.freeipa.lab krb5kdc[1223](info): closing down fd 11
Mar 10 15:47:12 xpsserver.freeipa.lab krb5kdc[1225](info): AS_REQ (6 etypes {aes256-cts-hmac-sha1-96(18), aes256-cts-hmac-sha384-192(20), camellia256-cts-cmac(26), aes128-cts-hmac-sha1-96(17), aes128-cts-hmac-sha256-128(19), camellia128-cts-cmac(25)}) 192.168.0.248: NEEDED_PREAUTH: [e-mail] for krbtgt/[e-mail], Additional pre-authentication required
Mar 10 15:47:12 xpsserver.freeipa.lab krb5kdc[1225](info): closing down fd 11
Mar 10 15:47:12 xpsserver.freeipa.lab krb5kdc[1220](info): preauth (spake) verify failure: Preauthentication failed
Mar 10 15:47:12 xpsserver.freeipa.lab krb5kdc[1220](info): AS_REQ (6 etypes {aes256-cts-hmac-sha1-96(18), aes256-cts-hmac-sha384-192(20), camellia256-cts-cmac(26), aes128-cts-hmac-sha1-96(17), aes128-cts-hmac-sha256-128(19), camellia128-cts-cmac(25)}) 192.168.0.248: PREAUTH_FAILED: [e-mail] for krbtgt/[e-mail], Preauthentication failed
Mar 10 15:47:12 xpsserver.freeipa.lab krb5kdc[1220](info): closing down fd 11
Mar 10 15:47:14 xpsserver.freeipa.lab krb5kdc[1219](info): AS_REQ (6 etypes {aes256-cts-hmac-sha1-96(18), aes256-cts-hmac-sha384-192(20), camellia256-cts-cmac(26), aes128-cts-hmac-sha1-96(17), aes128-cts-hmac-sha256-128(19), camellia128-cts-cmac(25)}) 192.168.0.248: NEEDED_PREAUTH: [e-mail] for krbtgt/[e-mail], Additional pre-authentication required
Mar 10 15:47:14 xpsserver.freeipa.lab krb5kdc[1219](info): closing down fd 11
Mar 10 15:47:14 xpsserver.freeipa.lab krb5kdc[1222](info): AS_REQ (6 etypes {aes256-cts-hmac-sha1-96(18), aes256-cts-hmac-sha384-192(20), camellia256-cts-cmac(26), aes128-cts-hmac-sha1-96(17), aes128-cts-hmac-sha256-128(19), camellia128-cts-cmac(25)}) 192.168.0.248: NEEDED_PREAUTH: [e-mail] for krbtgt/[e-mail], Additional pre-authentication required
Mar 10 15:47:14 xpsserver.freeipa.lab krb5kdc[1222](info): closing down fd 11
Mar 10 15:47:20 xpsserver.freeipa.lab krb5kdc[1220](info): AS_REQ (6 etypes {aes256-cts-hmac-sha1-96(18), aes256-cts-hmac-sha384-192(20), camellia256-cts-cmac(26), aes128-cts-hmac-sha1-96(17), aes128-cts-hmac-sha256-128(19), camellia128-cts-cmac(25)}) 192.168.0.248: NEEDED_PREAUTH: [e-mail] for krbtgt/[e-mail], Additional pre-authentication required
Mar 10 15:47:20 xpsserver.freeipa.lab krb5kdc[1220](info): closing down fd 11
Mar 10 15:47:20 xpsserver.freeipa.lab krb5kdc[1220](info): AS_REQ (6 etypes {aes256-cts-hmac-sha1-96(18), aes256-cts-hmac-sha384-192(20), camellia256-cts-cmac(26), aes128-cts-hmac-sha1-96(17), aes128-cts-hmac-sha256-128(19), camellia128-cts-cmac(25)}) 192.168.0.248: NEEDED_PREAUTH: [e-mail] for krbtgt/[e-mail], Additional pre-authentication required
Mar 10 15:47:20 xpsserver.freeipa.lab krb5kdc[1220](info): closing down fd 11
Mar 10 15:47:20 xpsserver.freeipa.lab krb5kdc[1225](info): preauth (spake) verify failure: Preauthentication failed
Mar 10 15:47:20 xpsserver.freeipa.lab krb5kdc[1225](info): AS_REQ (6 etypes {aes256-cts-hmac-sha1-96(18), aes256-cts-hmac-sha384-192(20), camellia256-cts-cmac(26), aes128-cts-hmac-sha1-96(17), aes128-cts-hmac-sha256-128(19), camellia128-cts-cmac(25)}) 192.168.0.248: PREAUTH_FAILED: [e-mail] for krbtgt/[e-mail], Preauthentication failed
Mar 10 15:47:20 xpsserver.freeipa.lab krb5kdc[1225](info): closing down fd 11
Mar 10 15:47:22 xpsserver.freeipa.lab krb5kdc[1225](info): AS_REQ (6 etypes {aes256-cts-hmac-sha1-96(18), aes256-cts-hmac-sha384-192(20), camellia256-cts-cmac(26), aes128-cts-hmac-sha1-96(17), aes128-cts-hmac-sha256-128(19), camellia128-cts-cmac(25)}) 192.168.0.248: NEEDED_PREAUTH: [e-mail] for krbtgt/[e-mail], Additional pre-authentication required
Mar 10 15:47:22 xpsserver.freeipa.lab krb5kdc[1225](info): closing down fd 11
Mar 10 15:47:22 xpsserver.freeipa.lab krb5kdc[1225](info): AS_REQ (6 etypes {aes256-cts-hmac-sha1-96(18), aes256-cts-hmac-sha384-192(20), camellia256-cts-cmac(26), aes128-cts-hmac-sha1-96(17), aes128-cts-hmac-sha256-128(19), camellia128-cts-cmac(25)}) 192.168.0.248: NEEDED_PREAUTH: [e-mail] for krbtgt/[e-mail], Additional pre-authentication required
Mar 10 15:47:22 xpsserver.freeipa.lab krb5kdc[1225](info): closing down fd 11

[Alexander Bokovoy]

On ke, 10 maalis 2021, Sam Bell via FreeIPA-users wrote:
> Yeah the password is right.
> On a separate note, on the client machine I had login problem on both Ubuntu(installed before)
> and Fedora. So the problem could be with server.
>
> For pre-authentication I used following commands:
> # kadmin.local
> kadmin.local: modprinc +requires_preauth testuser
> Principal "[e-mail]" modified.

Why did you do this step?

All IPA users are using preauthentication by default, there is no need
to operate on low level Kerberos principals and no need to use kadmin at
all.

[Sam Bell]

Thanks for the comment. 
I did it after checking the logs showing pre-authentication error. While searching online, I found this 
thread (https://sssd-users.fedorahosted.narkive.com/JkDs5m3z/sssd-authentication-fai...). However, it doesn't help, as you mentioned it is done by default.

[Sumit Bose]

On Wed, Mar 10, 2021 at 12:05:27PM -0000, Sam Bell via FreeIPA-users wrote:
> Yeah the password is right. 
> On a separate note, on the client machine I had login problem on both Ubuntu(installed before)
> and Fedora. So the problem could be with server.
>
> For pre-authentication I used following commands:
> # kadmin.local
> kadmin.local: modprinc +requires_preauth testuser
> Principal "[e-mail]" modified.
>
> Server: xpsserver.freeipa.lab (fedora)
> freeipa-server version: 4.9.2 (4.fc32)
>
> client: mu3090x1.freeipa.lab
> freeipa-client version: 4.9.2 (4.fc33)
>
> Here's the log from krb5kdc.log from the server:

w..
> Mar 10 15:47:12 xpsserver.freeipa.lab krb5kdc[1220](info): preauth (spake) verify failure: Preauthentication failed
> Mar 10 15:47:12 xpsserver.freeipa.lab krb5kdc[1220](info): AS_REQ (6 etypes {aes256-cts-hmac-sha1-96(18), aes256-cts-hmac-sha384-192(20), camellia256-cts-cmac(26), aes128-cts-hmac-sha1-96(17), aes128-cts-hmac-sha256-128(19), camellia128-cts-cmac(25)}) 192.168.0.248: PREAUTH_FAILED: [e-mail] for krbtgt/[e-mail], Preauthentication failed

Hi,

it looks like the failure is related to spake pre-authentication. This
would explain why it worked on older clients because they most probably
do not support spake. Since you said that new users work I wonder if
changing/resetting the old user's password would help as well?

bye,
Sumit

[Sam Bell]

Thanks for the suggestion.
I tried changing the password of one of the old user. It didn't help and the issue is still there.
I can login to server(ver. 4.9.2) and older clients with the changed password, but not to the new client machine.
The older clients are actually not that old. They run Ubuntu Server 20.01, installed less than a year
ago and I updated the freeipa-client to 4.8.6 few months ago.

I forgot to mention earlier, I had also created a replication server for redundancy. However, that machine is down
temporarily for last few days. I am not sure it helps in anyway.

[Sam Bell]

In addition, I am attaching the krb5kdc log for successful authentication on older client machine:

Mar 11 11:11:07 xpsserver.freeipa.lab krb5kdc[1225](info): AS_REQ (8 etypes {aes256-cts-hmac-sha1-96(18), aes128-cts-hmac-sha1-96(17), aes256-cts-hmac-sha384-192(20), aes128-cts-hmac-sha256-128(19), UNSUPPORTED:des3-hmac-sha1(16), DEPRECATED:arcfour-hmac(23), camellia128-cts-cmac(25), camellia256-cts-cmac(26)}) 192.168.0.244: NEEDED_PREAUTH: host/[e-mail] for krbtgt/[e-mail], Additional pre-authentication required
Mar 11 11:11:07 xpsserver.freeipa.lab krb5kdc[1225](info): closing down fd 11
Mar 11 11:11:07 xpsserver.freeipa.lab krb5kdc[1225](info): AS_REQ (8 etypes {aes256-cts-hmac-sha1-96(18), aes128-cts-hmac-sha1-96(17), aes256-cts-hmac-sha384-192(20), aes128-cts-hmac-sha256-128(19), UNSUPPORTED:des3-hmac-sha1(16), DEPRECATED:arcfour-hmac(23), camellia128-cts-cmac(25), camellia256-cts-cmac(26)}) 192.168.0.244: ISSUE: authtime 1615428667, etypes {rep=aes256-cts-hmac-sha1-96(18), tkt=aes256-cts-hmac-sha1-96(18), ses=aes256-cts-hmac-sha1-96(18)}, host/[e-mail] for krbtgt/[e-mail]
Mar 11 11:11:07 xpsserver.freeipa.lab krb5kdc[1225](info): closing down fd 11
Mar 11 11:11:07 xpsserver.freeipa.lab krb5kdc[1225](info): AS_REQ (8 etypes {aes256-cts-hmac-sha1-96(18), aes128-cts-hmac-sha1-96(17), aes256-cts-hmac-sha384-192(20), aes128-cts-hmac-sha256-128(19), UNSUPPORTED:des3-hmac-sha1(16), DEPRECATED:arcfour-hmac(23), camellia128-cts-cmac(25), camellia256-cts-cmac(26)}) 192.168.0.244: NEEDED_PREAUTH: [e-mail] for krbtgt/[e-mail], Additional pre-authentication required
Mar 11 11:11:07 xpsserver.freeipa.lab krb5kdc[1225](info): closing down fd 11
Mar 11 11:11:07 xpsserver.freeipa.lab krb5kdc[1225](info): AS_REQ (8 etypes {aes256-cts-hmac-sha1-96(18), aes128-cts-hmac-sha1-96(17), aes256-cts-hmac-sha384-192(20), aes128-cts-hmac-sha256-128(19), UNSUPPORTED:des3-hmac-sha1(16), DEPRECATED:arcfour-hmac(23), camellia128-cts-cmac(25), camellia256-cts-cmac(26)}) 192.168.0.244: NEEDED_PREAUTH: [e-mail] for krbtgt/[e-mail], Additional pre-authentication required
Mar 11 11:11:07 xpsserver.freeipa.lab krb5kdc[1225](info): closing down fd 11
Mar 11 11:11:07 xpsserver.freeipa.lab krb5kdc[1225](info): AS_REQ (8 etypes {aes256-cts-hmac-sha1-96(18), aes128-cts-hmac-sha1-96(17), aes256-cts-hmac-sha384-192(20), aes128-cts-hmac-sha256-128(19), UNSUPPORTED:des3-hmac-sha1(16), DEPRECATED:arcfour-hmac(23), camellia128-cts-cmac(25), camellia256-cts-cmac(26)}) 192.168.0.244: ISSUE: authtime 1615428667, etypes {rep=aes256-cts-hmac-sha1-96(18), tkt=aes256-cts-hmac-sha1-96(18), ses=aes256-cts-hmac-sha1-96(18)}, [e-mail] for krbtgt/[e-mail]
Mar 11 11:11:07 xpsserver.freeipa.lab krb5kdc[1225](info): closing down fd 11
Mar 11 11:11:07 xpsserver.freeipa.lab krb5kdc[1225](info): TGS_REQ (8 etypes {aes256-cts-hmac-sha1-96(18), aes128-cts-hmac-sha1-96(17), aes256-cts-hmac-sha384-192(20), aes128-cts-hmac-sha256-128(19), UNSUPPORTED:des3-hmac-sha1(16), DEPRECATED:arcfour-hmac(23), camellia128-cts-cmac(25), camellia256-cts-cmac(26)}) 192.168.0.244: ISSUE: authtime 1615428667, etypes {rep=aes256-cts-hmac-sha1-96(18), tkt=aes256-cts-hmac-sha1-96(18), ses=aes256-cts-hmac-sha1-96(18)}, [e-mail] for host/[e-mail]
Mar 11 11:11:07 xpsserver.freeipa.lab krb5kdc[1225](info): closing down fd 11