2FA authentication (password + otp) does not work on Ubuntu18, Debian 10, and Centos7 distributions. 2FA authentication on Ubuntu16 is working
1.Install freeipa-client 2.Register host on freeipa-server 3.Enable 2FA for installed host 3. Try to connet via SSH by user who pass+otp enabled on server side
Permission denied, please try again
"sucssesful enter"
freeipa-server-4.8.3-1.fc31.x86_64 freeipa-client-4.8.3-1.fc31.x86_64 package ipa-server is not installed package ipa-client is not installed 389-ds-base-1.4.2.4-2.fc31.x86_64 pki-ca-10.7.3-3.fc31.noarch krb5-server-1.17-45.fc31.x86_64 on Fedora30
There is a part of log of krb5kcd Dec 05 18:07:51 ipx.sample.net krb5kdc24799: closing down fd 11 Dec 05 18:07:51 ipx.sample.net krb5kdc24799: AS_REQ (7 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), DEPRECATED:arcfour-hmac(23), camellia128-cts-cmac(25), camellia256-cts-cmac(26)}) 46.101.254.17: NEEDED_PREAUTH: shaman@sample.NET for krbtgt/sample.NET@sample.NET, Additional pre-authentication required Dec 05 18:07:51 ipx.sample.net krb5kdc24799: closing down fd 11 Dec 05 18:07:51 ipx.sample.net krb5kdc24799: AS_REQ (7 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), DEPRECATED:arcfour-hmac(23), camellia128-cts-cmac(25), camellia256-cts-cmac(26)}) 46.101.254.17: NEEDED_PREAUTH: shaman@sample.NET for krbtgt/sample.NET@sample.NET, Additional pre-authentication required Dec 05 18:07:51 ipx.sample.net krb5kdc24799: closing down fd 11 Dec 05 18:07:51 ipx.sample.net krb5kdc24799: AS_REQ (7 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), DEPRECATED:arcfour-hmac(23), camellia128-cts-cmac(25), camellia256-cts-cmac(26)}) 46.101.254.17: NEEDED_PREAUTH: shaman@sample.NET for krbtgt/sample.NET@sample.NET, Additional pre-authentication required Dec 05 18:07:51 ipx.sample.net krb5kdc24799: closing down fd 11 Dec 05 18:07:51 ipx.sample.net krb5kdc24799: preauth (spake) verify failure: Preauthentication failed Dec 05 18:07:51 ipx.sample.net krb5kdc24799: AS_REQ (7 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), DEPRECATED:arcfour-hmac(23), camellia128-cts-cmac(25), camellia256-cts-cmac(26)}) 46.101.254.17: PREAUTH_FAILED: shaman@sample.NET for krbtgt/sample.NET@sample.NET, Preauthentication failed Dec 05 18:07:51 ipx.sample.net krb5kdc24799: closing down fd 11
Hi,
can you set debug_level = 9 to the [domain/...] section of sssd.conf on the IPA client, restart SSSD, try 2FA again and then send the krb5_child.log from /var/log/sssd ?
debug_level = 9
[domain/...]
sssd.conf
krb5_child.log
/var/log/sssd
Does the user has enabled both 2fa and password on the IPA server?
2fa
password
Which kind of prompt do you see with ssh, First Factor and Second Factor or just Password?
First Factor
Second Factor
Password
How does the sshd PAM configuration (/etc/pam.d/sshd ?) looks like?
bye, Sumit
I reproduced it only with SSH access when SSSD is unable to supply a password to a krb5 prompter. It works fine with gdm where a prompter is able to provide two separate answers and it also works with SSH with Keyboard-Interactive.
To me this strongly suggests it is a bug in SSSD.
Hi, can you set debug_level = 9 to the [domain/...] section of sssd.conf on the IPA client, restart SSSD, try 2FA again and then send the krb5_child.log from /var/log/sssd ?
krb5_child.log:
(Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [main] (0x0400): krb5_child started. (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [unpack_buffer] (0x1000): total buffer size: [167] (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [unpack_buffer] (0x0100): cmd [241] uid [1372800004] gid [1372800000] validate [true] enterprise principal [false] offline [false] UPN [bkakym@EXAMPLE.COM] (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [unpack_buffer] (0x0100): ccname: [KEYRING:persistent:1372800004] old_ccname: [KEYRING:persistent:1372800004] keytab: [/etc/krb5.keytab]</span>. (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [switch_creds] (0x0200): Switch user to [1372800004][1372800000]. (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [switch_creds] (0x0200): Switch user to [0][0]. (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [k5c_check_old_ccache] (0x4000): Ccache_file is [KEYRING:persistent:1372800004] and is not active and TGT is valid. (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [k5c_precreate_ccache] (0x4000): Recreating ccache (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [k5c_setup_fast] (0x0100): Fast principal is set to [host/testipa18.example.com@EXAMPLE.COM] (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [find_principal_in_keytab] (0x4000): Trying to find principal host/testipa18.example.com@EXAMPLE.COM in keytab. (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [match_principal] (0x1000): Principal matched to the sample (host/testipa18.example.com@EXAMPLE.COM). (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [check_fast_ccache] (0x0200): FAST TGT is still valid. (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [become_user] (0x0200): Trying to become user [1372800004][1372800000]. (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [main] (0x2000): Running as [1372800004][1372800000]. (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [k5c_setup] (0x2000): Running as [1372800004][1372800000]. (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [set_lifetime_options] (0x0100): No specific renewable lifetime requested. (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [set_lifetime_options] (0x0100): No specific lifetime requested. (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [set_canonicalize_option] (0x0100): Canonicalization is set to [true] (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [main] (0x0400): Will perform online auth (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [tgt_req_child] (0x1000): Attempting to get a TGT (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [get_and_save_tgt] (0x0400): Attempting kinit for realm [EXAMPLE.COM] (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526532: Getting initial credentials for bkakym@EXAMPLE.COM (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526533: FAST armor ccache: MEMORY:/var/lib/sss/db/fast_ccache_EXAMPLE.COM (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526534: Retrieving host/testipa18example.com@EXAMPLE.COM -> krb5_ccache_conf_data/fast_avail/krbtgt\/EXAMPLE.COM\@EXAMPLE.COM@X-CACHECONF: from MEMORY:/var/lib/sss/db/fast_ccache_EXAMPLE.COM with result: -1765328243/Matching credential not found (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526536: Sending unauthenticated request (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526537: Sending request (178 bytes) to EXAMPLE.COM (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526538: Initiating TCP connection to stream 46.101.254.17:88 (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526539: Sending TCP request to stream 46.101.254.17:88 (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526540: Received answer (480 bytes) from stream 46.101.254.17:88 (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526541: Terminating TCP connection to stream 46.101.254.17:88 (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526542: Response was from master KDC (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526543: Received error from KDC: -1765328359/Additional pre-authentication required (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526544: Upgrading to FAST due to presence of PA_FX_FAST in reply (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526545: FAST armor ccache: MEMORY:/var/lib/sss/db/fast_ccache_EXAMPLE.COM (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526546: Retrieving host/testipa18.EXAMPLE.COM@EXAMPLE.COM -> krb5_ccache_conf_data/fast_avail/krbtgt\/EXAMPLE.COM\@EXAMPLE.COM@X-CACHECONF: from MEMORY:/var/lib/sss/db/fast_ccache_EXAMPLE.COM with result: -1765328243/Matching credential not found (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526547: Getting credentials host/testipa18.example.com@EXAMPLE.COM -> krbtgt/EXAMPLE.COM@EXAMPLE.COM using ccache MEMORY:/var/lib/sss/db/fast_ccache_EXAMPLE.COM (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526548: Retrieving host/testipa18.example.com@EXAMPLE.COM -> krbtgt/EXAMPLE.COM@EXAMPLE.COM from MEMORY:/var/lib/sss/db/fast_ccache_EXAMPLE.COM with result: 0/Success (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526549: Armor ccache sesion key: aes256-cts/8BEC (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526551: Creating authenticator for host/testipa18.example.com@EXAMPLE.COM -> krbtgt/EXAMPLE.COM@EXAMPLE.COM, seqnum 0, subkey aes256-cts/E5AC, session key aes256-cts/8BEC (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526553: FAST armor key: aes256-cts/6728 (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526555: Sending unauthenticated request (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526556: Encoding request body and padata into FAST request (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526557: Sending request (1041 bytes) to EXAMPLE.COM (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526558: Initiating TCP connection to stream 46.101.254.17:88 (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526559: Sending TCP request to stream 46.101.254.17:88 (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526560: Received answer (813 bytes) from stream 46.101.254.17:88 (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526561: Terminating TCP connection to stream 46.101.254.17:88 (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526562: Response was from master KDC (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526563: Received error from KDC: -1765328359/Additional pre-authentication required (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526564: Decoding FAST response (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526567: Preauthenticating using KDC method data (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526568: Processing preauth types: 16, 136, 19, 147, 141, 151, 138, 133, 137 (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526569: Selected etype info: etype aes256-cts, salt "[u>@J.iG+"8/EN4+", params "" (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526570: Received cookie: MIT1\x00\x00\x00\x01\x18\x8f\xd3\xb4\xf8\xf6x\xce\x02b\xa0\xee\x9c\x0a\x16\x0b\x99\xde\xa5\x17\xd9%)\xb0S?J\xeb\xc8s\xf1\xa8\xf7\xb7\xb4\xdc\xfb\xd5\x97e\xcd\xa3\x9d\xf3\xf8fxK\x02\xc9\xff\xde\x7f\x00\x95-6\xf8\xa4BT/\x9d7\x12\xd9`\xa8\xbfT\x89\x04\xfa\x0e\xef\x87\xf3zp\x97\x95\xac\xb6Vv%~~\x88 \x9c$\xc0\x83j\xffVn\xa7\xeb\x88\xaf\xff\xd8\x7fB9A\x89\xcb\xc1\xe6\xa0\xc6\xe3\xb6s\xfe\xb8q\x8a\xf5\xd5`\x93iwS\x16Y (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_krb5_responder] (0x4000): Got question [otp]. (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_krb5_responder] (0x4000): Got question [password]. (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_krb5_prompter] (0x4000): sss_krb5_prompter name [(null)] banner [(null)] num_prompts [1] EINVAL. (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_krb5_prompter] (0x4000): Prompt [0][Enter OTP Token Value]. (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_krb5_prompter] (0x0020): Cannot handle password prompts. (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526571: Preauth module otp (141) (real) returned: -1765328254/Cannot read password (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526573: Preauth module encrypted_challenge (138) (real) returned: 0/Success (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526574: Produced preauth for next request: 133, 138 (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526575: Encoding request body and padata into FAST request (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526576: Sending request (1280 bytes) to EXAMPLE.COM (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526577: Initiating TCP connection to stream 46.101.254.17:88 (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526578: Sending TCP request to stream 46.101.254.17:88 (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526579: Received answer (813 bytes) from stream 46.101.254.17:88 (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526580: Terminating TCP connection to stream 46.101.254.17:88 (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526581: Response was from master KDC (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526582: Received error from KDC: -1765328360/Preauthentication failed (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526583: Decoding FAST response (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526586: Preauthenticating using KDC method data (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526587: Processing preauth types: 16, 136, 19, 147, 141, 151, 138, 133, 137 (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526588: Selected etype info: etype aes256-cts, salt "[u>@J.iG+"8/EN4+", params "" (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_child_krb5_trace_cb] (0x4000): [656] 1575988048.526589: Received cookie: MIT1\x00\x00\x00\x01\xce\x8c\x9f$#\xe8\xe2\x03\x91\xcf\xaf\x92\xec\xa9.\xecP\xba\xe3\x95\xb5\xfb\x91\xd2\x0c\x95be\x80\xbdO2\xa0!C\xbc\xe2\xfcWM\xc5q\x80\xcbv\xb8\x90\x92=\xbb\xe3wI\xc4G\xfa\x10\x9e\xaa\xe1o7,i\x07\xf2e\xdf\xc3\xed\xa5A0\xf2\xd3F\x96\xbc,*\xbd\xde\xf2\x1e\xf1\xc8}q\x1b\x13\x0e<\x1a\x06\xcb\xdd\xe9\x03~\x0e\xb2\xd8\x8f[\xe3\xa8\x9e.AK\xe9\x85FX\xc1y\x18\x9cs\x15\xd9@\xb6 \x0d\x19\xde]\x09\xba (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [sss_krb5_responder] (0x4000): Got question [otp]. (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [get_and_save_tgt] (0x0020): 1695: [-1765328360][Preauthentication failed] (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [map_krb5_error] (0x0020): 1808: [-1765328360][Preauthentication failed] (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [k5c_send_data] (0x0200): Received error code 1432158221 (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [pack_response_packet] (0x2000): response packet size: [12] (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [k5c_send_data] (0x4000): Response sent. (Tue Dec 10 14:27:28 2019) [[sssd[krb5_child[656]]]] [main] (0x0400): krb5_child completed successfully
Yes, user has them enabled on IPA server
Just password
# PAM configuration for the Secure Shell service # Standard Un*x authentication. @include common-auth # Disallow non-root logins when /etc/nologin exists. account required pam_nologin.so # Uncomment and edit /etc/security/access.conf if you need to set complex # access limits that are hard to express in sshd_config. # account required pam_access.so # Standard Un*x authorization. @include common-account # SELinux needs to be the first session rule. This ensures that any # lingering context has been cleared. Without this it is possible that a # module could execute code in the wrong domain. session [success=ok ignore=ignore module_unknown=ignore default=bad] pam_selinux.so close # Set the loginuid process attribute. session required pam_loginuid.so # Create a new session keyring. session optional pam_keyinit.so force revoke # Standard Un*x session setup and teardown. @include common-session # Print the message of the day upon successful login. # This includes a dynamically generated part from /run/motd.dynamic # and a static (admin-editable) part from /etc/motd. session optional pam_motd.so motd=/run/motd.dynamic session optional pam_motd.so noupdate # Print the status of the user's mailbox upon successful login. session optional pam_mail.so standard noenv # [1] # Set up user limits from /etc/security/limits.conf. session required pam_limits.so # Read environment variables from /etc/environment and # /etc/security/pam_env.conf. session required pam_env.so # [1] # In Debian 4.0 (etch), locale-related environment variables were moved to # /etc/default/locale, so read that as well. session required pam_env.so user_readenv=1 envfile=/etc/default/locale # SELinux needs to intervene at login time to ensure that the process starts # in the proper default security context. Only sessions which are intended # to run in the user's context should be run after this. session [success=ok ignore=ignore module_unknown=ignore default=bad] pam_selinux.so open # Standard Un*x password updating. @include common-password
thanks for the details.
I assume it you only enter the password (first factor) without adding to OTP-token value at the ssh password prompt, authentication is successful and you can log in?
Since you enabled both 'otp' and 'password' on the IPA server for the user, both should be possible. But from the Kerberos perspective both are handled differently and since we try to avoid try-and-error authentication with SSSD we need to know if the user just entered just the password or both factors. For this SSSD in general will prompt for both factors separately and the second prompt will indicate that the second factor can be skipped.
But ssh is a bit special here because it has to be told explicitly the forward the PAM conversation to the client by allowing ChallengeResponseAuthentication on the service side. On the client side it must be enabled as well and I heard that KbdInteractiveAuthentication might be needed as well. With this setting you should see the separate prompts for the first and second factor as well.
ChallengeResponseAuthentication
KbdInteractiveAuthentication
HTH
Hi
I cheked configuration on all ssh servers wich I use for authentification testing. ChallengeResponseAuthentication is enabled on them.
I try to connect via ssh to each of them with option KbdInteractiveAuthentication and without it - result was the same - access denied.
After this l check authentication through pamtester the result is the same and given logs are from such checks
root@debian10-ipa-test:/home/shaman# pamtester -v login shaman authenticate pamtester: invoking pam_start(login, shaman, ...) pamtester: performing operation - authenticate Password: pamtester: Authentication failure
There are more some logs:
krb5_child.log from Ubuntu16 server(here authentification is sucsesseful) :
(Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [main] (0x0400): krb5_child started. (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [unpack_buffer] (0x1000): total buffer size: [163] (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [unpack_buffer] (0x0100): cmd [241] uid [1372800004] gid [1372800000] validate [true] enterprise principal [false] offline [false] UPN [bkakym@EXAMPLE.COM] (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [unpack_buffer] (0x0100): ccname: [KEYRING:persistent:1372800004] old_ccname: [KEYRING:persistent:1372800004] keytab: [/etc/krb5.keytab] (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [switch_creds] (0x0200): Switch user to [1372800004][1372800000]. (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [switch_creds] (0x0200): Switch user to [0][0]. (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [k5c_check_old_ccache] (0x4000): Ccache_file is [KEYRING:persistent:1372800004] and is not active and TGT is valid. (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [k5c_precreate_ccache] (0x4000): Recreating ccache (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [k5c_setup_fast] (0x0100): SSSD_KRB5_FAST_PRINCIPAL is set to [host/testipa16.example.com@EXAMPLE.COM] (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [find_principal_in_keytab] (0x4000): Trying to find principal host/testipa16.example.com@EXAMPLE.COM in keytab. (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [match_principal] (0x1000): Principal matched to the sample (host/testipa16.example.com@EXAMPLE.COM). (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [check_fast_ccache] (0x0200): FAST TGT is still valid. (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [become_user] (0x0200): Trying to become user [1372800004][1372800000]. (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [main] (0x2000): Running as [1372800004][1372800000]. (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [k5c_setup] (0x2000): Running as [1372800004][1372800000]. (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [set_lifetime_options] (0x0100): Cannot read [SSSD_KRB5_RENEWABLE_LIFETIME] from environment. (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [set_lifetime_options] (0x0100): Cannot read [SSSD_KRB5_LIFETIME] from environment. (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [set_canonicalize_option] (0x0100): SSSD_KRB5_CANONICALIZE is set to [true] (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [main] (0x0400): Will perform online auth (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [tgt_req_child] (0x1000): Attempting to get a TGT (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [get_and_save_tgt] (0x0400): Attempting kinit for realm [EXAMPLE.COM] (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.118998: Getting initial credentials for bkakym@EXAMPLE.COM (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.119050: FAST armor ccache: MEMORY:/var/lib/sss/db/fast_ccache_EXAMPLE.COM (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.119081: Retrieving host/testipa16.example.com@EXAMPLE.COM -> krb5_ccache_conf_data/fast_avail/krbtgt\/EXAMPLE.COM\@EXAMPLE.COM@X-CACHECONF: from MEMORY:/var/lib/sss/db/fast_ccache_EXAMPLE.COM with result: -1765328243/Matching credential not found (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.119120: Sending request (172 bytes) to EXAMPLE.COM (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.119273: Initiating TCP connection to stream 46.101.254.17:88 (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.151536: Sending TCP request to stream 46.101.254.17:88 (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.189078: Received answer (480 bytes) from stream 46.101.254.17:88 (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.189146: Terminating TCP connection to stream 46.101.254.17:88 (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.189219: Response was from master KDC (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.189244: Received error from KDC: -1765328359/Additional pre-authentication required (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.189262: Upgrading to FAST due to presence of PA_FX_FAST in reply (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.189274: Restarting to upgrade to FAST (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.189288: FAST armor ccache: MEMORY:/var/lib/sss/db/fast_ccache_EXAMPLE.COM (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.189313: Retrieving host/testipa16.example.com@EXAMPLE.COM -> krb5_ccache_conf_data/fast_avail/krbtgt\/EXAMPLE.COM\@EXAMPLE.COM@X-CACHECONF: from MEMORY:/var/lib/sss/db/fast_ccache_EXAMPLE.COM with result: -1765328243/Matching credential not found (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.189327: Upgrading to FAST due to presence of PA_FX_FAST in reply (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.189339: FAST armor ccache: MEMORY:/var/lib/sss/db/fast_ccache_EXAMPLE.COM (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.189358: Retrieving host/testipa16.example.com@EXAMPLE.COM -> krb5_ccache_conf_data/fast_avail/krbtgt\/EXAMPLE.COM\@EXAMPLE.COM@X-CACHECONF: from MEMORY:/var/lib/sss/db/fast_ccache_EXAMPLE.COM with result: -1765328243/Matching credential not found (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.189374: Getting credentials host/testipa16.example.com@EXAMPLE.COM -> krbtgt/EXAMPLE.COM@EXAMPLE.COM using ccache MEMORY:/var/lib/sss/db/fast_ccache_EXAMPLE.COM (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.189404: Retrieving host/testipa16.example.com@EXAMPLE.COM -> krbtgt/EXAMPLE.COM@EXAMPLE.COM from MEMORY:/var/lib/sss/db/fast_ccache_EXAMPLE.COM with result: 0/Success (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.189434: Armor ccache sesion key: aes256-cts/D76C (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.189467: Creating authenticator for host/testipa16.example.com@EXAMPLE.COM-> krbtgt/EXAMPLE.COM@EXAMPLE.COM, seqnum 0, subkey aes256-cts/7BC8, session key aes256-cts/D76C (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.189530: FAST armor key: aes256-cts/1C32 (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.189557: Encoding request body and padata into FAST request (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.189614: Sending request (1029 bytes) to EXAMPLE.COM (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.189655: Initiating TCP connection to stream 46.101.254.17:88 (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.221667: Sending TCP request to stream 46.101.254.17:88 (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.261228: Received answer (813 bytes) from stream 46.101.254.17:88 (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.261275: Terminating TCP connection to stream 46.101.254.17:88 (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.261328: Response was from master KDC (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.261353: Received error from KDC: -1765328359/Additional pre-authentication required (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.261367: Decoding FAST response (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.261425: Processing preauth types: 16, 136, 19, 147, 141, 151, 138, 133, 137 (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.261445: Selected etype info: etype aes256-cts, salt "[u>@J.iG+"8/EN4+", params "" (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.261470: Received cookie: MIT1\x00\x00\x00\x01\xe0.\xc7\xdd\x958uR\x0f\xce\xbfD."\x8f^\xdb,\x9e2\x11\xf7\xe9WtM\x9b\x80,\xf9\xc91[\xa3\x90*\x0aY|Z\xbc-t\xf18\xcc\x8b\xd8\xd5\xf8\xfe\xae\x0ee-\xa4\x04a\x97D\xa3\x90\xe0\x83\x9fI\x8e\x9dD\x8a\x84f\xa9\xdb\x957o\xb7\xf8\xae\x8f1x\x09x\x09+\x8b-\xc4v\x95\x81"\xe4\x14\x0a\xbe\xe1e\xae\x045\xfad\xe2H\x94\xbc\x09\xcd&\xa3\x89\x8a\xb5W\x12T|C\x8197q\xac\xec"Dt (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.261533: Preauth module otp (141) (real) returned: 0/Success (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.261551: Produced preauth for next request: 133, 142 (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.261563: Encoding request body and padata into FAST request (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.261619: Sending request (1311 bytes) to EXAMPLE.COM (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.261658: Initiating TCP connection to stream 46.101.254.17:88 (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.293140: Sending TCP request to stream 46.101.254.17:88 (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.469374: Received answer (1046 bytes) from stream 46.101.254.17:88 (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.469405: Terminating TCP connection to stream 46.101.254.17:88 (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.469457: Response was from master KDC (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.469480: Decoding FAST response (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.469527: Processing preauth types: (empty) (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.469544: Produced preauth for next request: (empty) (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.469559: AS key determined by preauth: aes256-cts/1C32 (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.469586: FAST reply key: aes256-cts/1164 (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.469620: Decrypted AS reply; session key is: aes256-cts/357B (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.469652: FAST negotiation: available (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_krb5_expire_callback_func] (0x2000): exp_time: [6947624] (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [validate_tgt] (0x2000): Found keytab entry with the realm of the credential. (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.469716: Retrieving host/testipa16.example.com@EXAMPLE.COM from MEMORY:/etc/krb5.keytab (vno 0, enctype 0) with result: 0/Success (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.469731: Resolving unique ccache of type MEMORY (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.469746: Initializing MEMORY:dR5V6Wc with default princ bkakym@EXAMPLE.COM (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.469761: Storing bkakym@EXAMPLE.COM -> krbtgt/EXAMPLE.COM@EXAMPLE.COM in MEMORY:dR5V6Wc (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.469779: Getting credentials bkakym@EXAMPLE.COM -> host/testipa16.example.com@EXAMPLE.COM using ccache MEMORY:dR5V6Wc (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.469802: Retrieving bkakym@EXAMPLE.COM -> host/testipa16.example.com@EXAMPLE.COM from MEMORY:dR5V6Wc with result: -1765328243/Matching credential not found (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.469823: Retrieving bkakym@EXAMPLE.COM -> krbtgt/EXAMPLE.COM@EXAMPLE.COM from MEMORY:dR5V6Wc with result: 0/Success (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.469837: Starting with TGT for client realm: bkakym@EXAMPLE.COM -> krbtgt/EXAMPLE.COM@EXAMPLE.COM (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.469850: Requesting tickets for host/testipa16.example.com@EXAMPLE.COM, referrals on (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.469869: Generated subkey for TGS request: aes256-cts/0883 (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.469900: etypes requested in TGS request: aes256-cts, aes128-cts, des3-cbc-sha1, rc4-hmac, camellia128-cts, camellia256-cts (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.469948: Encoding request body and padata into FAST request (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.469998: Sending request (1070 bytes) to EXAMPLE.COM (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.470037: Initiating TCP connection to stream 46.101.254.17:88 (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.501363: Sending TCP request to stream 46.101.254.17:88 (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.540829: Received answer (987 bytes) from stream 46.101.254.17:88 (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.540858: Terminating TCP connection to stream 46.101.254.17:88 (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.540910: Response was from master KDC (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.540933: Decoding FAST response (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.540992: FAST reply key: aes256-cts/9285 (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.541037: TGS reply is for bkakym@EXAMPLE.COM -> host/testipa16.example.com@EXAMPLE.COM with session key aes256-cts/8A39 (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.541074: TGS request result: 0/Success (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.541091: Received creds for desired service host/testipa16.example.com@EXAMPLE.COM (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.541106: Storing bkakym@EXAMPLE.COM -> host/testipa16.example.com@EXAMPLE.COM in MEMORY:dR5V6Wc (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.541132: Creating authenticator for bkakym@EXAMPLE.COM -> host/testipa16.example.com@EXAMPLE.COM, seqnum 0, subkey (null), session key aes256-cts/8A39 (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.541185: Retrieving host/testipa16.example.com@EXAMPLE.COM from MEMORY:/etc/krb5.keytab (vno 1, enctype aes256-cts) with result: 0/Success (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.541225: Decrypted AP-REQ with specified server principal host/testipa16.example.com@EXAMPLE.COM: aes256-cts/00DD (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.541244: AP-REQ ticket: bkakym@EXAMPLE.COM -> host/testipa16.example.com@EXAMPLE.COM, session key aes256-cts/8A39 (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.541406: Negotiated enctype based on authenticator: aes256-cts (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.541430: Initializing MEMORY:rd_req2 with default princ bkakym@EXAMPLE.COM (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.541446: Storing bkakym@EXAMPLE.COM -> host/testipa16.example.com@EXAMPLE.COM in MEMORY:rd_req2 (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.541464: Destroying ccache MEMORY:dR5V6Wc (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [validate_tgt] (0x0400): TGT verified using key for [host/testipa16.example.com@EXAMPLE.COM]. (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_child_krb5_trace_cb] (0x4000): [7920] 1576324892.541495: Destroying ccache MEMORY:rd_req2 (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_get_ccache_name_for_principal] (0x4000): Location: [KEYRING:persistent:1372800004] (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [sss_get_ccache_name_for_principal] (0x4000): tmp_ccname: [KEYRING:persistent:1372800004:krb_ccache_14zn2VD] (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [create_ccache] (0x4000): Initializing ccache of type [KEYRING] (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [create_ccache] (0x4000): CC supports switch (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [create_ccache] (0x4000): returning: 0 (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [safe_remove_old_ccache_file] (0x0400): New and old ccache file are the same, none will be deleted. (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [k5c_send_data] (0x0200): Received error code 0 (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [pack_response_packet] (0x2000): response packet size: [147] (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [k5c_send_data] (0x4000): Response sent. (Sat Dec 14 12:01:32 2019) [[sssd[krb5_child[7920]]]] [main] (0x0400): krb5_child completed successfully
Here is the krb5_child.log from Ubuntu18 server(here authentification is unsucsesseful) :
(Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [main] (0x0400): krb5_child started. (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [unpack_buffer] (0x1000): total buffer size: [138] (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [unpack_buffer] (0x0100): cmd [241] uid [1372800004] gid [1372800000] validate [true] enterprise principal [false] offline [false] UPN [bkakym@EXAMPLE.COM] (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [unpack_buffer] (0x2000): No old ccache (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [unpack_buffer] (0x0100): ccname: [KEYRING:persistent:1372800004] old_ccname: [not set] keytab: [/etc/krb5.keytab] (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [k5c_precreate_ccache] (0x4000): Recreating ccache (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [k5c_setup_fast] (0x0100): Fast principal is set to [host/testipa18.example.com@EXAMPLE.COM] (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [find_principal_in_keytab] (0x4000): Trying to find principal host/testipa18.example.com@EXAMPLE.COM in keytab. (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [match_principal] (0x1000): Principal matched to the sample (host/testipa18.example.com@EXAMPLE.COM). (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [check_fast_ccache] (0x0200): FAST TGT is still valid. (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [become_user] (0x0200): Trying to become user [1372800004][1372800000]. (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [main] (0x2000): Running as [1372800004][1372800000]. (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [k5c_setup] (0x2000): Running as [1372800004][1372800000]. (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [set_lifetime_options] (0x0100): No specific renewable lifetime requested. (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [set_lifetime_options] (0x0100): No specific lifetime requested. (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [set_canonicalize_option] (0x0100): Canonicalization is set to [true] (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [main] (0x0400): Will perform online auth (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [tgt_req_child] (0x1000): Attempting to get a TGT (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [get_and_save_tgt] (0x0400): Attempting kinit for realm [EXAMPLE.COM] (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134384: Getting initial credentials for bkakym@EXAMPLE.COM (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134385: FAST armor ccache: MEMORY:/var/lib/sss/db/fast_ccache_EXAMPLE.COM (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134386: Retrieving host/testipa18.example.com@EXAMPLE.COM -> krb5_ccache_conf_data/fast_avail/krbtgt\/EXAMPLE.COM\@EXAMPLE.COM@X-CACHECONF: from MEMORY:/var/lib/sss/db/fast_ccache_EXAMPLE.COM with result: -1765328243/Matching credential not found (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134388: Sending unauthenticated request (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134389: Sending request (178 bytes) to EXAMPLE.COM (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134390: Initiating TCP connection to stream 46.101.254.17:88 (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134391: Sending TCP request to stream 46.101.254.17:88 (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134392: Received answer (480 bytes) from stream 46.101.254.17:88 (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134393: Terminating TCP connection to stream 46.101.254.17:88 (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134394: Response was from master KDC (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134395: Received error from KDC: -1765328359/Additional pre-authentication required (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134396: Upgrading to FAST due to presence of PA_FX_FAST in reply (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134397: FAST armor ccache: MEMORY:/var/lib/sss/db/fast_ccache_EXAMPLE.COM (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134398: Retrieving host/testipa18.example.com@EXAMPLE.COM -> krb5_ccache_conf_data/fast_avail/krbtgt\/EXAMPLE.COM\@EXAMPLE.COM@X-CACHECONF: from MEMORY:/var/lib/sss/db/fast_ccache_EXAMPLE.COM with result: -1765328243/Matching credential not found (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134399: Getting credentials host/testipa18.example.com@EXAMPLE.COM -> krbtgt/EXAMPLE.COM@EXAMPLE.COM using ccache MEMORY:/var/lib/sss/db/fast_ccache_EXAMPLE.COM (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134400: Retrieving host/testipa18.example.com@EXAMPLE.COM -> krbtgt/EXAMPLE.COM@EXAMPLE.COM from MEMORY:/var/lib/sss/db/fast_ccache_EXAMPLE.COM with result: 0/Success (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134401: Armor ccache sesion key: aes256-cts/8704 (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134403: Creating authenticator for host/testipa18.example.com@EXAMPLE.COM -> krbtgt/EXAMPLE.COM@EXAMPLE.COM, seqnum 0, subkey aes256-cts/56C8, session key aes256-cts/8704 (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134405: FAST armor key: aes256-cts/5409 (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134407: Sending unauthenticated request (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134408: Encoding request body and padata into FAST request (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134409: Sending request (1041 bytes) to EXAMPLE.COM (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134410: Initiating TCP connection to stream 46.101.254.17:88 (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134411: Sending TCP request to stream 46.101.254.17:88 (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134412: Received answer (813 bytes) from stream 46.101.254.17:88 (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134413: Terminating TCP connection to stream 46.101.254.17:88 (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134414: Response was from master KDC (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134415: Received error from KDC: -1765328359/Additional pre-authentication required (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134416: Decoding FAST response (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134419: Preauthenticating using KDC method data (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134420: Processing preauth types: 16, 136, 19, 147, 141, 151, 138, 133, 137 (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134421: Selected etype info: etype aes256-cts, salt "[u>@J.iG+"8/EN4+", params "" (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134422: Received cookie: MIT1\x00\x00\x00\x01\x8f"\xd8\x90Qw\x8d\x95z\xd2\x9eG\xa3\x94\xc8\xcd\xf9\xd5"e\xef^fg\x8et\xc3\xd04\x10\x05\xc5\x84\x0c\x02\xad\xcb\xc1\xd8\xfe\x83I`Do\xb7+^\xd2b\x86\xcd\xa24\xc0\x01\xc2\xecR\x14\xab>-E\x10\x99\xc3\xe7\xf2E\xb9\xa1\xae\x14\x9e\\x16\x12F5\x9cgj{Q\xaeJT\x1f\x11yv\xe5^\x89(m\x7f\xe4%\x11gi\x9f\x1b\xb1\x92\xa4(\x1bt\x0e2cf\x8c\x06.\x97\xd5\x1f\xb5 \xde\x0a{D\xaf~< (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_krb5_responder] (0x4000): Got question [otp]. (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_krb5_responder] (0x4000): Got question [password]. (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_krb5_prompter] (0x4000): sss_krb5_prompter name [(null)] banner [(null)] num_prompts [1] EINVAL. (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_krb5_prompter] (0x4000): Prompt [0][Enter OTP Token Value]. (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_krb5_prompter] (0x0020): Cannot handle password prompts. (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134423: Preauth module otp (141) (real) returned: -1765328254/Cannot read password (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134425: Preauth module encrypted_challenge (138) (real) returned: 0/Success (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134426: Produced preauth for next request: 133, 138 (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134427: Encoding request body and padata into FAST request (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134428: Sending request (1280 bytes) to EXAMPLE.COM (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134429: Initiating TCP connection to stream 46.101.254.17:88 (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134430: Sending TCP request to stream 46.101.254.17:88 (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134431: Received answer (813 bytes) from stream 46.101.254.17:88 (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134432: Terminating TCP connection to stream 46.101.254.17:88 (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134433: Response was from master KDC (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134434: Received error from KDC: -1765328360/Preauthentication failed (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134435: Decoding FAST response (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134438: Preauthenticating using KDC method data (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134439: Processing preauth types: 16, 136, 19, 147, 141, 151, 138, 133, 137 (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134440: Selected etype info: etype aes256-cts, salt "[u>@J.iG+"8/EN4+", params "" (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_child_krb5_trace_cb] (0x4000): [17941] 1576324931.134441: Received cookie: MIT1\x00\x00\x00\x01H\xe9\x9aV\xf2\x87\xc8\x126\x83+y\xcd\x9c\xdaR;\xfd\xf3\x95\xbc\x04\xec\xd1\x92\xa8\xf3\xfaJ\xbdmk\xe6\xcd7\xe4\x8a\xfd|B\xc46\x19\xdb\x96m\x14\x9aOI\x03}\x0c\xc3\xf5\xa2ZT\x17\xe2_\xd0\x10\xe2\xd9\x95FLf\x9d\xc1WX\xdf\xebQ\x92o-MXE\xd6\xf8\xc1\xa1\xd3\xa4)\xd2\x94\xf9d\xa9\xa93"1\xee~\xea\x87\x13\x9a \xe9upE\xc6\x0bq\x06\xd7\xba\x19\xee\xc9Jx\xb2pb!f;\xcaU\x91\x8e (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [sss_krb5_responder] (0x4000): Got question [otp]. (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [get_and_save_tgt] (0x0020): 1695: [-1765328360][Preauthentication failed] (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [map_krb5_error] (0x0020): 1808: [-1765328360][Preauthentication failed] (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [k5c_send_data] (0x0200): Received error code 1432158221 (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [pack_response_packet] (0x2000): response packet size: [12] (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [k5c_send_data] (0x4000): Response sent. (Sat Dec 14 12:02:11 2019) [[sssd[krb5_child[17941]]]] [main] (0x0400): krb5_child completed successfully
Here is the /var/log/sss/sssd_domain.log from Debian10(here authentification is unsucsesseful)
/var/log/sss/sssd_domain.log
(Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x3][BE_REQ_INITGROUPS][name=shaman@example.com] (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [dp_attach_req] (0x0400): DP Request [Initgroups #2515]: New request. Flags [0x0001]. (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [sdap_get_initgr_next_base] (0x0400): Searching for users with base [cn=accounts,dc=obltelecom,dc=net] (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(uid=shaman)(objectclass=posixAccount)(&(uidNumber=*)(!(uidNumber=0))))][cn=accounts,dc=obltelecom,dc=net]. (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [sdap_save_user] (0x0400): Save user (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [sdap_get_primary_name] (0x0400): Processing object shaman (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [sdap_save_user] (0x0400): Processing user shaman@example.com (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [sdap_save_user] (0x0400): Adding original memberOf attributes to [shaman@example.com]. (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [sdap_save_user] (0x0400): Adding user principal [shaman@EXAMPLE.COM] to attributes of [shaman@example.com]. (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [sdap_save_user] (0x0400): Storing info for user shaman@example.com (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [sysdb_set_entry_attr] (0x0200): Entry [name=shaman@example.com,cn=users,cn=example.com,cn=sysdb] has set [ts_cache] attrs. (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [sdap_get_primary_name] (0x0400): Processing object shaman (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [sdap_has_deref_support] (0x0400): The server supports deref method OpenLDAP (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [sdap_x_deref_search_send] (0x0400): Dereferencing entry [uid=shaman,cn=users,cn=accounts,dc=obltelecom,dc=net] using OpenLDAP deref (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [sdap_get_generic_ext_send] (0x0400): WARNING: Disabling paging because scope is set to base. (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [no filter][uid=shaman,cn=users,cn=accounts,dc=obltelecom,dc=net]. (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [sdap_x_deref_parse_entry] (0x0400): Got deref control (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [sdap_x_deref_parse_entry] (0x0400): All deref results from a single control parsed (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [sdap_get_primary_name] (0x0400): Processing object admins (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [sdap_get_primary_name] (0x0400): Processing object ipausers (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [sdap_get_initgr_done] (0x0400): Primary group already cached, nothing to do. (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaOverrideAnchor)(ipaAnchorUUID=:IPA:example.com:29e1d212-1677-11ea-bf2b-fa4293121f76))][cn=Default Trust View,cn=views,cn=accounts,dc=obltelecom,dc=net]. (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [dp_req_done] (0x0400): DP Request [Initgroups #2515]: Request handler finished [0]: Success (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [_dp_req_recv] (0x0400): DP Request [Initgroups #2515]: Receiving request data. (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [sysdb_set_entry_attr] (0x0200): Entry [name=shaman@example.com,cn=users,cn=example.com,cn=sysdb] has set [ts_cache] attrs. (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [dp_req_initgr_pp_nss_notify] (0x0400): Ordering NSS responder to update memory cache (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [dp_req_reply_list_success] (0x0400): DP Request [Initgroups #2515]: Finished. Success. (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:3::example.com:name=shaman@example.com] from reply table (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [dp_req_destructor] (0x0400): DP Request [Initgroups #2515]: Request removed. (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [dp_pam_handler] (0x0100): Got request with the following data (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [pam_print_data] (0x0100): command: SSS_PAM_AUTHENTICATE (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [pam_print_data] (0x0100): domain: example.com (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [pam_print_data] (0x0100): user: shaman@example.com (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [pam_print_data] (0x0100): service: login (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [pam_print_data] (0x0100): tty: (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [pam_print_data] (0x0100): ruser: (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [pam_print_data] (0x0100): rhost: (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [pam_print_data] (0x0100): authtok type: 1 (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [pam_print_data] (0x0100): newauthtok type: 0 (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [pam_print_data] (0x0100): priv: 1 (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [pam_print_data] (0x0100): cli_pid: 2518 (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [pam_print_data] (0x0100): logon name: not set (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [dp_attach_req] (0x0400): DP Request [PAM Authenticate #2516]: New request. Flags [0000]. (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA' (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [be_resolve_server_process] (0x0200): Found address for server ipx.example.com: [46.101.254.17] TTL 600 (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [ipa_resolve_callback] (0x0400): Constructed uri 'ldap://ipx.example.com' (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [write_pipe_handler] (0x0400): All data has been sent! (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [read_pipe_handler] (0x0400): EOF received, client finished (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(cn=ipaConfig)(objectClass=ipaGuiConfig))][cn=etc,dc=obltelecom,dc=net]. (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [child_sig_handler] (0x0100): child [2519] finished successfully. (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [dp_req_done] (0x0400): DP Request [PAM Authenticate #2516]: Request handler finished [0]: Success (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [_dp_req_recv] (0x0400): DP Request [PAM Authenticate #2516]: Receiving request data. (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [dp_req_destructor] (0x0400): DP Request [PAM Authenticate #2516]: Request removed. (Sat Dec 14 14:22:26 2019) [sssd[be[example.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0
Here is the /var/log/krb5kdc.log on freeipa server then authentification is unsucsesseful
/var/log/krb5kdc.log
Dec 14 14:22:26 ipx.example.com krb5kdc[24799](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), DEPRECATED:des3-hmac-sha1(16), DEPRECATED:arcfour-hmac(23), camellia128-cts-cmac(25), camellia256-cts-cmac(26)}) 167.172.191.192: NEEDED_PREAUTH: shaman@EXAMPLE.COM for krbtgt/EXAMPLE.COM@EXAMPLE.COM, Additional pre-authentication required Dec 14 14:22:26 ipx.example.com krb5kdc[24799](info): closing down fd 11 Dec 14 14:22:26 ipx.example.com krb5kdc[24799](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), DEPRECATED:des3-hmac-sha1(16), DEPRECATED:arcfour-hmac(23), camellia128-cts-cmac(25), camellia256-cts-cmac(26)}) 167.172.191.192: NEEDED_PREAUTH: shaman@EXAMPLE.COM for krbtgt/EXAMPLE.COM@EXAMPLE.COM, Additional pre-authentication required Dec 14 14:22:26 ipx.example.com krb5kdc[24799](info): closing down fd 11 Dec 14 14:22:26 ipx.example.com krb5kdc[24799](info): preauth (spake) verify failure: Preauthentication failed Dec 14 14:22:26 ipx.example.com krb5kdc[24799](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), DEPRECATED:des3-hmac-sha1(16), DEPRECATED:arcfour-hmac(23), camellia128-cts-cmac(25), camellia256-cts-cmac(26)}) 167.172.191.192: PREAUTH_FAILED: shaman@EXAMPLE.COM for krbtgt/EXAMPLE.COM@EXAMPLE.COM, Preauthentication failed Dec 14 14:22:26 ipx.example.com krb5kdc[24799](info): closing down fd 11
Tell me please if I can give you an additional info. Thank.
Are there any updates on this issue? Perhaps the problem is in SSSD? If you need additional info - tell me, I`ll try to help. The solution of the issue is needed.
Thanks.
Can you try freeipa 4.8.4-2.fc31 (in updates-testing)? It should have this fixed by way of https://github.com/freeipa/freeipa/pull/4015
We tried the version as you asked:
Installed Packages Name : freeipa-server Version : 4.8.4 Release : 2.fc31 Architecture : x86_64 Size : 1.1 M Source : freeipa-4.8.4-2.fc31.src.rpm Repository : @System From repo : updates-testing Summary : The IPA authentication server URL : http://www.freeipa.org/ License : GPLv3+
But result is the same as before - Authentication failure.
since you have enable both 'otp' and 'password' for the user the fix in 4.8.4 might be not what you needed.
Do I understand correctly that although ChallengeResponseAuthentication is enabled the ssh command still only asks for a password? Can you send the verbose output of the ssh command
ssh -v -v -v user@remote.host
Hi, since you have enable both 'otp' and 'password' for the user the fix in 4.8.4 might be not what you needed. Do I understand correctly that although ChallengeResponseAuthentication is enabled the ssh command still only asks for a password? Can you send the verbose output of the ssh command ssh -v -v -v user@remote.host bye, Sumit
Hi, since you have enable both 'otp' and 'password' for the user the fix in 4.8.4 might be not what you needed. Do I understand correctly that although ChallengeResponseAuthentication is enabled the ssh command still only asks for a password? Can you send the verbose output of the ssh command ssh -v -v -v user@remote.host
HI,
We encounter an error not only with ssh authentication - we also checking authentication via pamtester And result is the same - Authentication failure. Errors in logs are the same for both type of checks
can you run pamtester with strace like e.g.
strace -s 1024 -f -o /tmp/pamtester.out pamtester -v login shaman authenticate
and send /tmp/pamtester.out and all log files from /var/log/sssd in a zip or tar.gz file?
<img alt="freeipa_auth_issue.zip" src="/freeipa/issue/raw/files/4623c282970a5acbfee6278dc14101797b2f9808a774a64cdd95db1d8e6f9419-freeipa_auth_issue.zip" />
Hi.
Here are the files you requested.
Thank you for the logs.
I'm sorry I didn't realize this earlier but you might have to change you PAM configuration.
Since only SSSD knows about the different authentication types pam_sss.so must prompt the user for credentials. In you case it looks like pam_unix.so asks the use and pam_unix. so can only ask for a password and pam_sss.so treats forwarded credentials from other PAM modules as password.
The relevant part of the PAM configuration in Fedora or RHEL looks like:
...... auth [default=1 ignore=ignore success=ok] pam_succeed_if.so uid >= 1000 quiet auth [default=1 ignore=ignore success=ok] pam_localuser.so auth sufficient pam_unix.so nullok try_first_pass auth requisite pam_succeed_if.so uid >= 1000 quiet_success auth sufficient pam_sss.so forward_pass auth required pam_deny.so
The pam_succeed_if.so makes sure unknown users where the uid cannot be determined are handled by pam_unix, then pam_localuser skips pam_unix for non-local users, i.e. users handled by SSSD get their prompt from pam_sss and not from pam_unix.
Can you try to add a similar block to your /etc/pam.d/common-auth and check if pamtester now asks for First and Second Factor?
We have changed PAM configuration according to your recommendation. Pamtester cheks became successful.
ssh became successful to.
Thank you, it`s working!
Metadata Update from @bkakakym: - Issue close_status updated to: fixed - Issue status updated to: Closed (was: Open)
Login to comment on this ticket.