[Freeipa-users] unable to authenticate using freeipa client

Tue Mar 15 05:25:06 UTC 2016

For the error in the krb5_child.log
(Tue Mar 15 04:35:51 2016) [[sssd[krb5_child[13708]]]]
[sss_child_krb5_trace_cb] (0x4000): [13708] 1458016551.87210: Received
error from KDC: -1765328359/Additional pre-authentication required

I deleted the sssd cache as well as the /tmp/krb5* and restarted sssd ,
still the issue persists.

Another error that I see is in /var/log/secure

Mar 14 21:35:51 ip-1-1-1-1 sshd[13705]: pam_unix(sshd:auth): authentication
failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=127.0.0.1
user=q-tempuser
Mar 14 21:35:51 ip-1-1-1-1 sshd[13705]: pam_sss(sshd:auth): authentication
failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=127.0.0.1
user=q-tempuser
Mar 14 21:35:51 ip-1-1-1-1 sshd[13705]: pam_sss(sshd:auth): received for
user q-tempuser: 4 (System error)

I have "UsePAM yes" and "GSSAPIAuthentication yes" in sshd_config.

so not sure whats causing this..

I tried uninstalling and installing back the client as well but did not
help..

Anything else that I might be missing out..

Thanks,
Rakesh

On Mon, Mar 14, 2016 at 5:50 PM, Rakesh Rajasekharan <
rakesh.rajasekharan at gmail.com> wrote:

> I set up freeipa in my environment and works perfectly.
>
> But just on one host , I am not able to authenticate. I get a permission
> denied eror.
>
> The sssd version I have is 1.12
>
> the krb5_child log does point to some error,
> krb5_child.log
> (Mon Mar 14 12:02:27 2016) [[sssd[krb5_child[11862]]]] [unpack_buffer]
> (0x2000): No old ccache
> (Mon Mar 14 12:02:27 2016) [[sssd[krb5_child[11862]]]] [unpack_buffer]
> (0x0100): ccname: [FILE:/tmp/krb5cc_5102_XXXXXX] old_ccname: [not set]
> keytab: [/etc/krb5.keytab]
> (Mon Mar 14 12:02:27 2016) [[sssd[krb5_child[11862]]]]
> [k5c_precreate_ccache] (0x4000): Recreating ccache
> (Mon Mar 14 12:02:27 2016) [[sssd[krb5_child[11862]]]] [k5c_setup_fast]
> (0x0100): SSSD_KRB5_FAST_PRINCIPAL is set to [host/1.1.1.1 at TEST.COM]
> (Mon Mar 14 12:02:27 2016) [[sssd[krb5_child[11862]]]]
> [find_principal_in_keytab] (0x4000): Trying to find principal host/
> 1.1.1.1 at TEST.COM in keytab.
> (Mon Mar 14 12:02:27 2016) [[sssd[krb5_child[11862]]]] [match_principal]
> (0x1000): Principal matched to the sample (host/1.1.1.1 at TEST.COM).
> (Mon Mar 14 12:02:27 2016) [[sssd[krb5_child[11862]]]] [get_tgt_times]
> (0x1000): FAST ccache must be recreated
> (Mon Mar 14 12:02:27 2016) [[sssd[krb5_child[11864]]]] [become_user]
> (0x0200): Trying to become user [0][0].
> (Mon Mar 14 12:02:27 2016) [[sssd[krb5_child[11864]]]] [become_user]
> (0x0200): Already user [0].
> (Mon Mar 14 12:02:27 2016) [[sssd[krb5_child[11864]]]] [check_fast_ccache]
> (0x2000): Running as [0][0].
> (Mon Mar 14 12:02:27 2016) [[sssd[krb5_child[11864]]]]
> [set_canonicalize_option] (0x0100): SSSD_KRB5_CANONICALIZE is set to [true]
> (Mon Mar 14 12:02:28 2016) [[sssd[krb5_child[11864]]]] [create_ccache]
> (0x4000): Initializing ccache of type [FILE]
> (Mon Mar 14 12:02:28 2016) [[sssd[krb5_child[11862]]]] [check_fast_ccache]
> (0x0200): FAST TGT was successfully recreated!
> (Mon Mar 14 12:02:28 2016) [[sssd[krb5_child[11862]]]] [become_user]
> (0x0200): Trying to become user [5102][701].
> (Mon Mar 14 12:02:28 2016) [[sssd[krb5_child[11862]]]] [main] (0x2000):
> Running as [5102][701].
> (Mon Mar 14 12:02:28 2016) [[sssd[krb5_child[11862]]]] [k5c_setup]
> (0x2000): Running as [5102][701].
> (Mon Mar 14 12:02:28 2016) [[sssd[krb5_child[11862]]]]
> [set_lifetime_options] (0x0100): Cannot read [SSSD_KRB5_RENEWABLE_LIFETIME]
> from environment.
> (Mon Mar 14 12:02:28 2016) [[sssd[krb5_child[11862]]]]
> [set_lifetime_options] (0x0100): Cannot read [SSSD_KRB5_LIFETIME] from
> environment.
> (Mon Mar 14 12:02:28 2016) [[sssd[krb5_child[11862]]]]
> [set_canonicalize_option] (0x0100): SSSD_KRB5_CANONICALIZE is set to [true]
> (Mon Mar 14 12:02:28 2016) [[sssd[krb5_child[11862]]]] [main] (0x0400):
> Will perform online auth
> (Mon Mar 14 12:02:28 2016) [[sssd[krb5_child[11862]]]] [tgt_req_child]
> (0x1000): Attempting to get a TGT
> (Mon Mar 14 12:02:28 2016) [[sssd[krb5_child[11862]]]] [get_and_save_tgt]
> (0x0400): Attempting kinit for realm [TEST.COM]
> (Mon Mar 14 12:02:28 2016) [[sssd[krb5_child[11862]]]]
> [sss_child_krb5_trace_cb] (0x4000): [11862] 1457956948.18425: Getting
> initial credentials for q-tempuser at TEST.COM
>
> (Mon Mar 14 12:02:28 2016) [[sssd[krb5_child[11862]]]]
> [sss_child_krb5_trace_cb] (0x4000): [11862] 1457956948.18471: FAST armor
> ccache: MEMORY:/var/lib/sss/db/fast_ccache_TEST.COM
>
> (Mon Mar 14 12:02:28 2016) [[sssd[krb5_child[11862]]]]
> [sss_child_krb5_trace_cb] (0x4000): [11862] 1457956948.18502: Retrieving
> host/1.1.1.1 at TEST.COM -> krb5_ccache_conf_data/fast_avail/krbtgt\/TEST.COM
> \@TEST.COM at X-CACHECONF: from MEMORY:/var/lib/sss/db/fast_ccache_TEST.COM
> with result: -1765328243/Matching credential not found
>
> (Mon Mar 14 12:02:28 2016) [[sssd[krb5_child[11862]]]]
> [sss_child_krb5_trace_cb] (0x4000): [11862] 1457956948.18545: Sending
> request (189 bytes) to TEST.COM
>
> (Mon Mar 14 12:02:28 2016) [[sssd[krb5_child[11862]]]]
> [sss_child_krb5_trace_cb] (0x4000): [11862] 1457956948.187.36: Initiating
> TCP connection to stre
> (END)
>
>
> And here are the contents from sssd_domain.log
> sssd_test.com
> (Mon Mar 14 11:57:12 2016) [sssd[be[test.com]]] [pam_print_data]
> (0x0100): domain: test.com
> (Mon Mar 14 11:57:12 2016) [sssd[be[test.com]]] [pam_print_data]
> (0x0100): user: q-tempuser
> (Mon Mar 14 11:57:12 2016) [sssd[be[test.com]]] [pam_print_data]
> (0x0100): service: sshd
> (Mon Mar 14 11:57:12 2016) [sssd[be[test.com]]] [pam_print_data]
> (0x0100): tty: ssh
> (Mon Mar 14 11:57:12 2016) [sssd[be[test.com]]] [pam_print_data]
> (0x0100): ruser:
> (Mon Mar 14 11:57:12 2016) [sssd[be[test.com]]] [pam_print_data]
> (0x0100): rhost: 127.0.0.1
> (Mon Mar 14 11:57:12 2016) [sssd[be[test.com]]] [pam_print_data]
> (0x0100): authtok type: 1
> (Mon Mar 14 11:57:12 2016) [sssd[be[test.com]]] [pam_print_data]
> (0x0100): newauthtok type: 0
> (Mon Mar 14 11:57:12 2016) [sssd[be[test.com]]] [pam_print_data]
> (0x0100): priv: 1
> (Mon Mar 14 11:57:12 2016) [sssd[be[test.com]]] [pam_print_data]
> (0x0100): cli_pid: 11794
> (Mon Mar 14 11:57:12 2016) [sssd[be[test.com]]] [pam_print_data]
> (0x0100): logon name: not set
> (Mon Mar 14 11:57:12 2016) [sssd[be[test.com]]] [ldb] (0x4000): Added
> timed event "ltdb_callback": 0x69e690
>
> (Mon Mar 14 11:57:12 2016) [sssd[be[test.com]]] [ldb] (0x4000): Added
> timed event "ltdb_timeout": 0x69e7b0
>
> (Mon Mar 14 11:57:12 2016) [sssd[be[test.com]]] [ldb] (0x4000): Running
> timer event 0x69e690 "ltdb_callback"
>
> (Mon Mar 14 11:57:12 2016) [sssd[be[test.com]]] [ldb] (0x4000):
> Destroying timer event 0x69e7b0 "ltdb_timeout"
>
> (Mon Mar 14 11:57:12 2016) [sssd[be[test.com]]] [ldb] (0x4000): Ending
> timer event 0x69e690 "ltdb_callback"
>
> (Mon Mar 14 11:57:12 2016) [sssd[be[test.com]]]
> [krb5_auth_prepare_ccache_name] (0x1000): No ccache file for user
> [q-tempuser] found.
> (Mon Mar 14 11:57:12 2016) [sssd[be[test.com]]] [fo_resolve_service_send]
> (0x0100): Trying to resolve service 'IPA'
> (Mon Mar 14 11:57:12 2016) [sssd[be[test.com]]] [get_server_status]
> (0x1000): Status of server 'ipa-test-master.test.com' is 'working'
> (Mon Mar 14 11:57:12 2016) [sssd[be[test.com]]] [get_port_status]
> (0x1000): Port status of port 0 for server 'ipa-test-master.test.com' is
> 'working'
> (Mon Mar 14 11:57:12 2016) [sssd[be[test.com]]]
> [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 6
> seconds
> (Mon Mar 14 11:57:12 2016) [sssd[be[test.com]]] [get_server_status]
> (0x1000): Status of server 'ipa-test-master.test.com' is 'working'
> (Mon Mar 14 11:57:12 2016) [sssd[be[test.com]]]
> [be_resolve_server_process] (0x1000): Saving the first resolved server
> (Mon Mar 14 11:57:12 2016) [sssd[be[test.com]]]
> [be_resolve_server_process] (0x0200): Found address for server
> ipa-test-master.test.com: [10.1.6.56] TTL 183
> (Mon Mar 14 11:57:12 2016) [sssd[be[test.com]]] [child_handler_setup]
> (0x2000): Setting up signal handler up for pid [11797]
> (Mon Mar 14 11:57:12 2016) [sssd[be[test.com]]] [child_handler_setup]
> (0x2000): Signal handler set up for pid [11797]
> (Mon Mar 14 11:57:12 2016) [sssd[be[test.com]]] [write_pipe_handler]
> (0x0400): All data has been sent!
> (Mon Mar 14 11:57:12 2016) [sssd[be[test.com]]] [child_sig_handler]
> (0x1000): Waiting for child [11797].
> (Mon Mar 14 11:57:12 2016) [sssd[be[test.com]]] [child_sig_handler]
> (0x0100): child [11797] finished successfully.
> (Mon Mar 14 11:57:12 2016) [sssd[be[test.com]]] [read_pipe_handler]
> (0x0400): EOF received, client finished
> (Mon Mar 14 11:57:12 2016) [sssd[be[test.com]]]
> [parse_krb5_child_response] (0x1000): child response [1432158209][6][8].
> (Mon Mar 14 11:57:12 2016) [sssd[be[test.com]]] [be_pam_handler_callback]
> (0x0100): Backend returned: (0, 4, <NULL>) [Success]
> (Mon Mar 14 11:57:12 2016) [sssd[be[test.com]]] [be_pam_handler_callback]
> (0x0100): Sending result [4][test.com]
> (Mon Mar 14 11:57:12 2016) [sssd[be[test.com]]] [be_pam_handler_callback]
> (0x0100): Sent result [4][test.com]
> (Mon Mar 14 11:57:15 2016) [sssd[be[test.com]]] [sbus_dispatch] (0x4000):
> dbus conn: 0x678710
> (Mon Mar 14 11:57:15 2016) [sssd[be[test.com]]] [sbus_dispatch] (0x4000):
> Dispatching.
> (Mon Mar 14 11:57:15 2016) [sssd[be[test.com]]] [sbus_message_handler]
> (0x4000): Received SBUS method [ping]
> (Mon Mar 14 11:57:15 2016) [sssd[be[test.com]]] [sbus_get_sender_id_send]
> (0x2000): Not a sysbus message, quit
> (Mon Mar 14 11:57:15 2016) [sssd[be[test.com]]]
> [sbus_handler_got_caller_id] (0x4000): Received SBUS method [ping]
>
>
> Not sure what could be wrong here, I think thisused to work fine earlier .
>
>
> Thanks,
> Rakesh
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://listman.redhat.com/archives/freeipa-users/attachments/20160315/c6f56388/attachment.htm>