SSSD / sssd

#3191 Not able to log in locally, although ssh login works just fine
Closed: Invalid Opened by jshim10.

Closed: Invalid
Reopen Issue

I got error4 - unhandled exception according to the troubleshooting page.
SSH login works just as fine. Do I have to manage differently for local pam_module?
here's my /var/log/sssd/sssd_pam.log

(Mon Sep 19 15:02:45 2016) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): name 'user' matched without domain, user is user
(Mon Sep 19 15:02:45 2016) [sssd[pam]] [pam_print_data] (0x0100): command: PAM_AUTHENTICATE
(Mon Sep 19 15:02:45 2016) [sssd[pam]] [pam_print_data] (0x0100): domain: not set
(Mon Sep 19 15:02:45 2016) [sssd[pam]] [pam_print_data] (0x0100): user: user
(Mon Sep 19 15:02:45 2016) [sssd[pam]] [pam_print_data] (0x0100): service: login
(Mon Sep 19 15:02:45 2016) [sssd[pam]] [pam_print_data] (0x0100): tty: tty1
(Mon Sep 19 15:02:45 2016) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set
(Mon Sep 19 15:02:45 2016) [sssd[pam]] [pam_print_data] (0x0100): rhost: not set
(Mon Sep 19 15:02:45 2016) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 1
(Mon Sep 19 15:02:45 2016) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0
(Mon Sep 19 15:02:45 2016) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
(Mon Sep 19 15:02:45 2016) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 752
(Mon Sep 19 15:02:45 2016) [sssd[pam]] [pam_print_data] (0x0100): logon name: user
(Mon Sep 19 15:02:45 2016) [sssd[pam]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/ad.udomain.edu/user]
(Mon Sep 19 15:02:45 2016) [sssd[pam]] [pam_initgr_check_timeout] (0x4000): User [user] not found in PAM cache.
(Mon Sep 19 15:02:45 2016) [sssd[pam]] [sss_dp_issue_request] (0x0400): Issuing request for [0x7f6de99ee090:3:user@ad.udomain.edu]
(Mon Sep 19 15:02:45 2016) [sssd[pam]] [sss_dp_get_account_msg] (0x0400): Creating request for [ad.udomain.edu][3][1][name=user]
(Mon Sep 19 15:02:45 2016) [sssd[pam]] [sbus_add_timeout] (0x2000): 0x7f6deb2d8b10
(Mon Sep 19 15:02:45 2016) [sssd[pam]] [sss_dp_internal_get_send] (0x0400): Entering request [0x7f6de99ee090:3:user@ad.udomain.edu]
(Mon Sep 19 15:02:46 2016) [sssd[pam]] [sbus_remove_timeout] (0x2000): 0x7f6deb2d8b10
(Mon Sep 19 15:02:46 2016) [sssd[pam]] [sbus_dispatch] (0x4000): dbus conn: 0x7f6deb2d4e00
(Mon Sep 19 15:02:46 2016) [sssd[pam]] [sbus_dispatch] (0x4000): Dispatching.
(Mon Sep 19 15:02:46 2016) [sssd[pam]] [sss_dp_get_reply] (0x1000): Got reply from Data Provider - DP error code: 0 errno: 0 error message: Success (Success)
(Mon Sep 19 15:02:46 2016) [sssd[pam]] [pam_check_user_search] (0x0100): Requesting info for [user@ad.udomain.edu]
(Mon Sep 19 15:02:46 2016) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f6deb2d6670

(Mon Sep 19 15:02:46 2016) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f6deb2de5b0

(Mon Sep 19 15:02:46 2016) [sssd[pam]] [ldb] (0x4000): Running timer event 0x7f6deb2d6670 "ltdb_callback"

(Mon Sep 19 15:02:46 2016) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x7f6deb2de5b0 "ltdb_timeout"

(Mon Sep 19 15:02:46 2016) [sssd[pam]] [ldb] (0x4000): Ending timer event 0x7f6deb2d6670 "ltdb_callback"
(Mon Sep 19 15:02:46 2016) [sssd[pam]] [pam_check_user_search] (0x0400): Returning info for user [user@ad.udomain.edu]
(Mon Sep 19 15:02:46 2016) [sssd[pam]] [pam_initgr_cache_set] (0x2000): [user] added to PAM initgroup cache
(Mon Sep 19 15:02:46 2016) [sssd[pam]] [pam_dp_send_req] (0x0100): Sending request with the following data:
(Mon Sep 19 15:02:46 2016) [sssd[pam]] [pam_print_data] (0x0100): command: PAM_AUTHENTICATE
(Mon Sep 19 15:02:46 2016) [sssd[pam]] [pam_print_data] (0x0100): domain: ad.udomain.edu
(Mon Sep 19 15:02:46 2016) [sssd[pam]] [pam_print_data] (0x0100): user: user
(Mon Sep 19 15:02:46 2016) [sssd[pam]] [pam_print_data] (0x0100): service: login
(Mon Sep 19 15:02:46 2016) [sssd[pam]] [pam_print_data] (0x0100): tty: tty1
(Mon Sep 19 15:02:46 2016) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set
(Mon Sep 19 15:02:46 2016) [sssd[pam]] [pam_print_data] (0x0100): rhost: not set
(Mon Sep 19 15:02:46 2016) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 1
(Mon Sep 19 15:02:46 2016) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0
(Mon Sep 19 15:02:46 2016) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
(Mon Sep 19 15:02:46 2016) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 752
(Mon Sep 19 15:02:46 2016) [sssd[pam]] [pam_print_data] (0x0100): logon name: user
(Mon Sep 19 15:02:46 2016) [sssd[pam]] [sbus_add_timeout] (0x2000): 0x7f6deb2d1790
(Mon Sep 19 15:02:46 2016) [sssd[pam]] [pam_dom_forwarder] (0x0100): pam_dp_send_req returned 0
(Mon Sep 19 15:02:46 2016) [sssd[pam]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x7f6de99ee090:3:user@ad.udomain.edu]
(Mon Sep 19 15:02:46 2016) [sssd[pam]] [sbus_remove_timeout] (0x2000): 0x7f6deb2d1790
(Mon Sep 19 15:02:46 2016) [sssd[pam]] [sbus_dispatch] (0x4000): dbus conn: 0x7f6deb2d4e00
(Mon Sep 19 15:02:46 2016) [sssd[pam]] [sbus_dispatch] (0x4000): Dispatching.
(Mon Sep 19 15:02:46 2016) [sssd[pam]] [pam_dp_process_reply] (0x0200): received: [4 (System error)][ad.udomain.edu]
(Mon Sep 19 15:02:46 2016) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [4]: System error.
(Mon Sep 19 15:02:46 2016) [sssd[pam]] [pam_reply] (0x0200): blen: 33
(Mon Sep 19 15:02:46 2016) [sssd[pam]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f6deb2d13f0][19]
(Mon Sep 19 15:02:51 2016) [sssd[pam]] [pam_initgr_cache_remove] (0x2000): [user] removed from PAM initgroup cache
(Mon Sep 19 15:02:53 2016) [sssd[pam]] [sbus_dispatch] (0x4000): dbus conn: 0x7f6deb2cb4b0
(Mon Sep 19 15:02:53 2016) [sssd[pam]] [sbus_dispatch] (0x4000): Dispatching.

Please also add the domain log..

/var/log/sssd/sssd_pam.log
sssd_pam.log

Did I attach right file?

Replying to [comment:1 jhrozek]:

Please also add the domain log..

You did, but we'll need to krb5_child.log as well to proceed:

(Mon Sep 19 15:02:46 2016) [sssd[be[ad.uillinois.edu]]] [child_sig_handler] (0x0100): child [2551] finished successfully.
(Mon Sep 19 15:02:46 2016) [sssd[be[ad.uillinois.edu]]] [read_pipe_handler] (0x0400): EOF received, client finished
(Mon Sep 19 15:02:46 2016) [sssd[be[ad.uillinois.edu]]] [check_wait_queue] (0x1000): Wait queue for user [jshim10] is empty.
(Mon Sep 19 15:02:46 2016) [sssd[be[ad.uillinois.edu]]] [krb5_auth_queue_done] (0x1000): krb5_auth_queue request [0x7f316ef9f4e0] done.
(Mon Sep 19 15:02:46 2016) [sssd[be[ad.uillinois.edu]]] [be_pam_handler_callback] (0x0100): Backend returned: (0, 4, <NULL>) [Success (System error)]
(Mon Sep 19 15:02:46 2016) [sssd[be[ad.uillinois.edu]]] [be_pam_handler_callback] (0x0100): Sending result [4][ad.uillinois.edu]
(Mon Sep 19 15:02:46 2016) [sssd[be[ad.uillinois.edu]]] [be_pam_handler_callback] (0x0100): Sent result [4][ad.uillinois.edu]

Well, the log says the proper KDC for that user cannot be found:

(Mon Sep 19 15:02:46 2016) [[sssd[krb5_child[2551]]]] [get_and_save_tgt] (0x0020): 1234: [-1765328230][Cannot find KDC for realm "illinois.edu"]
(Mon Sep 19 15:02:46 2016) [[sssd[krb5_child[2551]]]] [map_krb5_error] (0x0020): 1303: [-1765328230][Cannot find KDC for realm "illinois.edu"]

I would recommend to take a look at what UPN attribute this user has in AD. I suspect it ends with illinois.edu. And I suspect if you listen for DNS traffic while the user tries to log in, libkrb5 will try to look KDCs in the illinois.edu realm..

Does kinit for this user work?

I have checked that krb5 uses userPrincipalName as default for finding kdc.
We have changed UPN from default to illinois.edu for some other reason.
Is there way that we can set default domain from using userPrincipalName to something else?
We're thinking of creating a new field in our database system which contains kdc domain.
But this might be difficult since we have too many users in our database..
Any other suggestions?

Replying to [comment:4 jhrozek]:

Well, the log says the proper KDC for that user cannot be found:
{{{
(Mon Sep 19 15:02:46 2016) [[sssd[krb5_child[2551]]]] [get_and_save_tgt] (0x0020): 1234: [-1765328230][Cannot find KDC for realm "illinois.edu"]
(Mon Sep 19 15:02:46 2016) [[sssd[krb5_child[2551]]]] [map_krb5_error] (0x0020): 1303: [-1765328230][Cannot find KDC for realm "illinois.edu"]
}}}

I would recommend to take a look at what UPN attribute this user has in AD. I suspect it ends with illinois.edu. And I suspect if you listen for DNS traffic while the user tries to log in, libkrb5 will try to look KDCs in the illinois.edu realm..

Does kinit for this user work?

there is a hack: set ldap_user_principal to an attribute that doesn't exist, like:

ldap_user_principal = nosuchattr

then sssd will derive its own fallback UPN from the realm.

Works! thanks

Replying to [comment:6 jhrozek]:

there is a hack: set ldap_user_principal to an attribute that doesn't exist, like:
{{{
ldap_user_principal = nosuchattr
}}}
then sssd will derive its own fallback UPN from the realm.

Great, then I don't think there is a bug.

resolution: => worksforme
status: new => closed

Metadata Update from @jshim10:
- Issue set to the milestone: NEEDS_TRIAGE

SSSD is moving from Pagure to Github. This means that new issues and pull requests
will be accepted only in SSSD's github repository.

This issue has been cloned to Github and is available here:
- https://github.com/SSSD/sssd/issues/4224

If you want to receive further updates on the issue, please navigate to the github issue
and click on subscribe button.

Thank you for understanding. We apologize for all inconvenience.
Metadata
None
None
None
None
Normal
defect
SSSD
1.14.1
0
0
0
None
0
0
0
Static archive. pagure.io was sunset in 2026; this is a read-only snapshot.
Red Hat Logo

Fedora is sponsored by Red Hat. Learn more about the relationship between Red Hat and Fedora »

© Red Hat, Inc. and others.