Ask Your Question

Revision history [back]

click to hide/show revision 1
initial version

Interpretation of sssd logs

I have been struggling to get active directory users to authenticate on Fedora 27. Would someone please assist in diagnosing the following sssd log. I am particularly curious about the 'wrong authtok' line. The log shows an attempt to 'su' to an AD user.

[sssd[be[mydomain.co.uk]]] [dp_get_account_info_handler] (0x0200): Got request for [0x3][BE_REQ_INITGROUPS][name=hugh@mydomain.co.uk] [sssd[be[mydomain.co.uk]]] [sss_domain_get_state] (0x1000): Domain mydomain.co.uk is Active [sssd[be[mydomain.co.uk]]] [dp_attach_req] (0x0400): DP Request [Initgroups #8]: New request. Flags [0x0001]. [sssd[be[mydomain.co.uk]]] [dp_attach_req] (0x0400): Number of active DP request: 1 [sssd[be[mydomain.co.uk]]] [sss_domain_get_state] (0x1000): Domain mydomain.co.uk is Active [sssd[be[mydomain.co.uk]]] [_dp_req_recv] (0x0400): DP Request [Initgroups #8]: Receiving request data. [sssd[be[mydomain.co.uk]]] [dp_req_reply_gen_error] (0x0080): DP Request [Initgroups #8]: Finished. Backend is currently offline. [sssd[be[mydomain.co.uk]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:3::mydomain.co.uk:name=hugh@mydomain.co.uk] from reply table [sssd[be[mydomain.co.uk]]] [dp_req_destructor] (0x0400): DP Request [Initgroups #8]: Request removed. [sssd[be[mydomain.co.uk]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 [sssd[be[mydomain.co.uk]]] [dp_pam_handler] (0x0100): Got request with the following data [sssd[be[mydomain.co.uk]]] [pam_print_data] (0x0100): command: SSS_PAM_AUTHENTICATE [sssd[be[mydomain.co.uk]]] [pam_print_data] (0x0100): domain: mydomain.co.uk [sssd[be[mydomain.co.uk]]] [pam_print_data] (0x0100): user: hugh@mydomain.co.uk [sssd[be[mydomain.co.uk]]] [pam_print_data] (0x0100): service: su [sssd[be[mydomain.co.uk]]] [pam_print_data] (0x0100): tty: pts/2 [sssd[be[mydomain.co.uk]]] [pam_print_data] (0x0100): ruser: hjadmin [sssd[be[mydomain.co.uk]]] [pam_print_data] (0x0100): rhost: [sssd[be[mydomain.co.uk]]] [pam_print_data] (0x0100): authtok type: 1 [sssd[be[mydomain.co.uk]]] [pam_print_data] (0x0100): newauthtok type: 0 [sssd[be[mydomain.co.uk]]] [pam_print_data] (0x0100): priv: 0 [sssd[be[mydomain.co.uk]]] [pam_print_data] (0x0100): cli_pid: 364 [sssd[be[mydomain.co.uk]]] [pam_print_data] (0x0100): logon name: not set [sssd[be[mydomain.co.uk]]] [dp_attach_req] (0x0400): DP Request [PAM Authenticate #9]: New request. Flags [0000]. [sssd[be[mydomain.co.uk]]] [dp_attach_req] (0x0400): Number of active DP request: 1 [sssd[be[mydomain.co.uk]]] [sss_domain_get_state] (0x1000): Domain mydomain.co.uk is Active [sssd[be[mydomain.co.uk]]] [krb5_auth_queue_send] (0x1000): Wait queue of user [hugh@mydomain.co.uk] is empty, running request [0x563536126c40] immediately. [sssd[be[mydomain.co.uk]]] [krb5_auth_send] (0x0100): Home directory for user [hugh@mydomain.co.uk] not known. [sssd[be[mydomain.co.uk]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'AD' [sssd[be[mydomain.co.uk]]] [get_server_status] (0x1000): Status of server 'queeg.mydomain.co.uk' is 'name resolved' [sssd[be[mydomain.co.uk]]] [get_port_status] (0x1000): Port status of port 389 for server 'queeg.mydomain.co.uk' is 'not working' [sssd[be[mydomain.co.uk]]] [get_port_status] (0x0080): SSSD is unable to complete the full connection request, this internal status does not necessarily indicate network port issues. [sssd[be[mydomain.co.uk]]] [get_port_status] (0x0100): Resetting the status of port 389 for server 'queeg.mydomain.co.uk' [sssd[be[mydomain.co.uk]]] [resolve_srv_send] (0x0200): The status of SRV lookup is resolved [sssd[be[mydomain.co.uk]]] [get_server_status] (0x1000): Status of server 'queeg.mydomain.co.uk' is 'name resolved' [sssd[be[mydomain.co.uk]]] [be_resolve_server_process] (0x1000): Saving the first resolved server [sssd[be[mydomain.co.uk]]] [be_resolve_server_process] (0x0200): Found address for server queeg.mydomain.co.uk: [10.9.8.16] TTL 900 [sssd[be[mydomain.co.uk]]] [ad_resolve_callback] (0x0100): Constructed uri 'ldap://queeg.mydomain.co.uk' [sssd[be[mydomain.co.uk]]] [ad_resolve_callback] (0x0100): Constructed GC uri 'ldap://queeg.mydomain.co.uk' [sssd[be[mydomain.co.uk]]] [write_pipe_handler] (0x0400): All data has been sent! [sssd[be[mydomain.co.uk]]] [child_sig_handler] (0x1000): Waiting for child [382]. [sssd[be[mydomain.co.uk]]] [child_sig_handler] (0x0100): child [382] finished successfully. [sssd[be[mydomain.co.uk]]] [read_pipe_handler] (0x0400): EOF received, client finished [sssd[be[mydomain.co.uk]]] [parse_krb5_child_response] (0x1000): child response [0][3][46]. [sssd[be[mydomain.co.uk]]] [fo_set_port_status] (0x0100): Marking port 389 of server 'queeg.mydomain.co.uk' as 'working' [sssd[be[mydomain.co.uk]]] [set_server_common_status] (0x0100): Marking server 'queeg.mydomain.co.uk' as 'working' [sssd[be[mydomain.co.uk]]] [fo_set_port_status] (0x0400): Marking port 389 of duplicate server 'queeg.mydomain.co.uk' as 'working' [sssd[be[mydomain.co.uk]]] [sysdb_set_entry_attr] (0x0200): Entry [name=hugh@mydomain.co.uk,cn=users,cn=mydomain.co.uk,cn=sysdb] has set [ts_cache] attrs. [sssd[be[mydomain.co.uk]]] [check_for_combined_2fa_password] (0x1000): Wrong authtok type. [sssd[be[mydomain.co.uk]]] [sysdb_cache_auth] (0x0100): Authentication failed. [sssd[be[mydomain.co.uk]]] [sysdb_set_entry_attr] (0x0200): Entry [name=hugh@mydomain.co.uk,cn=users,cn=mydomain.co.uk,cn=sysdb] has set [cache, ts_cache] attrs. [sssd[be[mydomain.co.uk]]] [krb5_auth_cache_creds] (0x0020): Offline authentication failed [sssd[be[mydomain.co.uk]]] [check_wait_queue] (0x1000): Wait queue for user [hugh@mydomain.co.uk] is empty. [sssd[be[mydomain.co.uk]]] [krb5_auth_queue_done] (0x1000): krb5_auth_queue request [0x563536126c40] done. [sssd[be[mydomain.co.uk]]] [dp_req_done] (0x0400): DP Request [PAM Authenticate #9]: Request handler finished [0]: Success [sssd[be[mydomain.co.uk]]] [_dp_req_recv] (0x0400): DP Request [PAM Authenticate #9]: Receiving request data. [sssd[be[mydomain.co.uk]]] [dp_req_destructor] (0x0400): DP Request [PAM Authenticate #9]: Request removed. [sssd[be[mydomain.co.uk]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 [sssd[be[mydomain.co.uk]]] [dp_method_enabled] (0x0400): Target selinux is not configured [sssd[be[mydomain.co.uk]]] [dp_pam_reply] (0x1000): DP Request [PAM Authenticate #9]: Sending result [7][mydomain.co.uk]

Interpretation of sssd logs

I have been struggling to get active directory users to authenticate on Fedora 27. Would someone please assist in diagnosing the following sssd log. I am particularly curious about the 'wrong authtok' line. The log shows an attempt to 'su' to an AD user.

[sssd[be[mydomain.co.uk]]] [dp_get_account_info_handler] (0x0200): Got request for [0x3][BE_REQ_INITGROUPS][name=hugh@mydomain.co.uk] [sssd[be[mydomain.co.uk]]] [sss_domain_get_state] (0x1000): Domain mydomain.co.uk is Active [sssd[be[mydomain.co.uk]]] [dp_attach_req] (0x0400): DP Request [Initgroups #8]: New request. Flags [0x0001]. [sssd[be[mydomain.co.uk]]] [dp_attach_req] (0x0400): Number of active DP request: 1 [sssd[be[mydomain.co.uk]]] [sss_domain_get_state] (0x1000): Domain mydomain.co.uk is Active [sssd[be[mydomain.co.uk]]] [_dp_req_recv] (0x0400): DP Request [Initgroups #8]: Receiving request data. [sssd[be[mydomain.co.uk]]] [dp_req_reply_gen_error] (0x0080): DP Request [Initgroups #8]: Finished. Backend is currently offline. [sssd[be[mydomain.co.uk]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:3::mydomain.co.uk:name=hugh@mydomain.co.uk] from reply table [sssd[be[mydomain.co.uk]]] [dp_req_destructor] (0x0400): DP Request [Initgroups #8]: Request removed. [sssd[be[mydomain.co.uk]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 [sssd[be[mydomain.co.uk]]] [dp_pam_handler] (0x0100): Got request with the following data [sssd[be[mydomain.co.uk]]] [pam_print_data] (0x0100): command: SSS_PAM_AUTHENTICATE [sssd[be[mydomain.co.uk]]] [pam_print_data] (0x0100): domain: mydomain.co.uk [sssd[be[mydomain.co.uk]]] [pam_print_data] (0x0100): user: hugh@mydomain.co.uk [sssd[be[mydomain.co.uk]]] [pam_print_data] (0x0100): service: su [sssd[be[mydomain.co.uk]]] [pam_print_data] (0x0100): tty: pts/2 [sssd[be[mydomain.co.uk]]] [pam_print_data] (0x0100): ruser: hjadmin [sssd[be[mydomain.co.uk]]] [pam_print_data] (0x0100): rhost: [sssd[be[mydomain.co.uk]]] [pam_print_data] (0x0100): authtok type: 1 [sssd[be[mydomain.co.uk]]] [pam_print_data] (0x0100): newauthtok type: 0 [sssd[be[mydomain.co.uk]]] [pam_print_data] (0x0100): priv: 0 [sssd[be[mydomain.co.uk]]] [pam_print_data] (0x0100): cli_pid: 364 [sssd[be[mydomain.co.uk]]] [pam_print_data] (0x0100): logon name: not set [sssd[be[mydomain.co.uk]]] [dp_attach_req] (0x0400): DP Request [PAM Authenticate #9]: New request. Flags [0000]. [sssd[be[mydomain.co.uk]]] [dp_attach_req] (0x0400): Number of active DP request: 1 [sssd[be[mydomain.co.uk]]] [sss_domain_get_state] (0x1000): Domain mydomain.co.uk is Active [sssd[be[mydomain.co.uk]]] [krb5_auth_queue_send] (0x1000): Wait queue of user [hugh@mydomain.co.uk] is empty, running request [0x563536126c40] immediately. [sssd[be[mydomain.co.uk]]] [krb5_auth_send] (0x0100): Home directory for user [hugh@mydomain.co.uk] not known. [sssd[be[mydomain.co.uk]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'AD' [sssd[be[mydomain.co.uk]]] [get_server_status] (0x1000): Status of server 'queeg.mydomain.co.uk' is 'name resolved' [sssd[be[mydomain.co.uk]]] [get_port_status] (0x1000): Port status of port 389 for server 'queeg.mydomain.co.uk' is 'not working' [sssd[be[mydomain.co.uk]]] [get_port_status] (0x0080): SSSD is unable to complete the full connection request, this internal status does not necessarily indicate network port issues. [sssd[be[mydomain.co.uk]]] [get_port_status] (0x0100): Resetting the status of port 389 for server 'queeg.mydomain.co.uk' [sssd[be[mydomain.co.uk]]] [resolve_srv_send] (0x0200): The status of SRV lookup is resolved [sssd[be[mydomain.co.uk]]] [get_server_status] (0x1000): Status of server 'queeg.mydomain.co.uk' is 'name resolved' [sssd[be[mydomain.co.uk]]] [be_resolve_server_process] (0x1000): Saving the first resolved server [sssd[be[mydomain.co.uk]]] [be_resolve_server_process] (0x0200): Found address for server queeg.mydomain.co.uk: [10.9.8.16] TTL 900 [sssd[be[mydomain.co.uk]]] [ad_resolve_callback] (0x0100): Constructed uri 'ldap://queeg.mydomain.co.uk' [sssd[be[mydomain.co.uk]]] [ad_resolve_callback] (0x0100): Constructed GC uri 'ldap://queeg.mydomain.co.uk' [sssd[be[mydomain.co.uk]]] [write_pipe_handler] (0x0400): All data has been sent! [sssd[be[mydomain.co.uk]]] [child_sig_handler] (0x1000): Waiting for child [382]. [sssd[be[mydomain.co.uk]]] [child_sig_handler] (0x0100): child [382] finished successfully. [sssd[be[mydomain.co.uk]]] [read_pipe_handler] (0x0400): EOF received, client finished [sssd[be[mydomain.co.uk]]] [parse_krb5_child_response] (0x1000): child response [0][3][46]. [sssd[be[mydomain.co.uk]]] [fo_set_port_status] (0x0100): Marking port 389 of server 'queeg.mydomain.co.uk' as 'working' [sssd[be[mydomain.co.uk]]] [set_server_common_status] (0x0100): Marking server 'queeg.mydomain.co.uk' as 'working' [sssd[be[mydomain.co.uk]]] [fo_set_port_status] (0x0400): Marking port 389 of duplicate server 'queeg.mydomain.co.uk' as 'working' [sssd[be[mydomain.co.uk]]] [sysdb_set_entry_attr] (0x0200): Entry [name=hugh@mydomain.co.uk,cn=users,cn=mydomain.co.uk,cn=sysdb] has set [ts_cache] attrs. [sssd[be[mydomain.co.uk]]] [check_for_combined_2fa_password] (0x1000): Wrong authtok type. [sssd[be[mydomain.co.uk]]] [sysdb_cache_auth] (0x0100): Authentication failed. [sssd[be[mydomain.co.uk]]] [sysdb_set_entry_attr] (0x0200): Entry [name=hugh@mydomain.co.uk,cn=users,cn=mydomain.co.uk,cn=sysdb] has set [cache, ts_cache] attrs. [sssd[be[mydomain.co.uk]]] [krb5_auth_cache_creds] (0x0020): Offline authentication failed [sssd[be[mydomain.co.uk]]] [check_wait_queue] (0x1000): Wait queue for user [hugh@mydomain.co.uk] is empty. [sssd[be[mydomain.co.uk]]] [krb5_auth_queue_done] (0x1000): krb5_auth_queue request [0x563536126c40] done. [sssd[be[mydomain.co.uk]]] [dp_req_done] (0x0400): DP Request [PAM Authenticate #9]: Request handler finished [0]: Success [sssd[be[mydomain.co.uk]]] [_dp_req_recv] (0x0400): DP Request [PAM Authenticate #9]: Receiving request data. [sssd[be[mydomain.co.uk]]] [dp_req_destructor] (0x0400): DP Request [PAM Authenticate #9]: Request removed. [sssd[be[mydomain.co.uk]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 [sssd[be[mydomain.co.uk]]] [dp_method_enabled] (0x0400): Target selinux is not configured [sssd[be[mydomain.co.uk]]] [dp_pam_reply] (0x1000): DP Request [PAM Authenticate #9]: Sending result [7][mydomain.co.uk]

click to hide/show revision 3
No.3 Revision

Interpretation of sssd logs

I have been struggling to get active directory users to authenticate on Fedora 27. Would someone please assist in diagnosing the following sssd log. I am particularly curious about the 'wrong authtok' line. The log shows an attempt to 'su' to an AD user.

[dp_get_account_info_handler]

>[dp_get_account_info_handler] (0x0200): Got request for [0x3][BE_REQ_INITGROUPS][name=hugh@mydomain.co.uk]
  [sss_domain_get_state] >[sss_domain_get_state] (0x1000): Domain mydomain.co.uk is Active
  [dp_attach_req] >[dp_attach_req] (0x0400): DP Request [Initgroups #8]: New request. Flags [0x0001].
  [dp_attach_req] >[dp_attach_req] (0x0400): Number of active DP request: 1
  [sss_domain_get_state] >[sss_domain_get_state] (0x1000): Domain mydomain.co.uk is Active
  [_dp_req_recv] >[_dp_req_recv] (0x0400): DP Request [Initgroups #8]: Receiving request data.
  [dp_req_reply_gen_error] >[dp_req_reply_gen_error] (0x0080): DP Request [Initgroups #8]: Finished. Backend is currently offline.
  [dp_table_value_destructor] >[dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:3::mydomain.co.uk:name=hugh@mydomain.co.uk] from reply table
  [dp_req_destructor] >[dp_req_destructor] (0x0400): DP Request [Initgroups #8]: Request removed.
  [dp_req_destructor] >[dp_req_destructor] (0x0400): Number of active DP request: 0
  [dp_pam_handler] >[dp_pam_handler] (0x0100): Got request with the following data
  [pam_print_data] >[pam_print_data] (0x0100): command: SSS_PAM_AUTHENTICATE
  [pam_print_data] >[pam_print_data] (0x0100): domain: mydomain.co.uk
  [pam_print_data] >[pam_print_data] (0x0100): user: hugh@mydomain.co.uk
  [pam_print_data] >[pam_print_data] (0x0100): service: su
  [pam_print_data] >[pam_print_data] (0x0100): tty: pts/2
  [pam_print_data] >[pam_print_data] (0x0100): ruser: hjadmin
  [pam_print_data] >[pam_print_data] (0x0100): rhost:
  [pam_print_data] >[pam_print_data] (0x0100): authtok type: 1
  [pam_print_data] >[pam_print_data] (0x0100): newauthtok type: 0
  [pam_print_data] >[pam_print_data] (0x0100): priv: 0
  [pam_print_data] >[pam_print_data] (0x0100): cli_pid: 364
  [pam_print_data] >[pam_print_data] (0x0100): logon name: not set
  [dp_attach_req] >[dp_attach_req] (0x0400): DP Request [PAM Authenticate #9]: New request. Flags [0000].
  [dp_attach_req] >[dp_attach_req] (0x0400): Number of active DP request: 1
  [sss_domain_get_state] >[sss_domain_get_state] (0x1000): Domain mydomain.co.uk is Active
  [krb5_auth_queue_send] >[krb5_auth_queue_send] (0x1000): Wait queue of user [hugh@mydomain.co.uk] is empty, running request [0x563536126c40] immediately.
  [krb5_auth_send] >[krb5_auth_send] (0x0100): Home directory for user [hugh@mydomain.co.uk] not known.
  [fo_resolve_service_send] >[fo_resolve_service_send] (0x0100): Trying to resolve service 'AD'
  [get_server_status] >[get_server_status] (0x1000): Status of server 'queeg.mydomain.co.uk' is 'name resolved'
  [get_port_status] >[get_port_status] (0x1000): Port status of port 389 for server 'queeg.mydomain.co.uk' is 'not working'
  [get_port_status] >[get_port_status] (0x0080): SSSD is unable to complete the full connection request, this internal status does not necessarily indicate network port issues.
  [get_port_status] >[get_port_status] (0x0100): Resetting the status of port 389 for server 'queeg.mydomain.co.uk'
  [resolve_srv_send] >[resolve_srv_send] (0x0200): The status of SRV lookup is resolved
  [get_server_status] >[get_server_status] (0x1000): Status of server 'queeg.mydomain.co.uk' is 'name resolved'
  [be_resolve_server_process] >[be_resolve_server_process] (0x1000): Saving the first resolved server
  [be_resolve_server_process] >[be_resolve_server_process] (0x0200): Found address for server queeg.mydomain.co.uk: [10.9.8.16] TTL 900
  [ad_resolve_callback] >[ad_resolve_callback] (0x0100): Constructed uri 'ldap://queeg.mydomain.co.uk'
  [ad_resolve_callback] >[ad_resolve_callback] (0x0100): Constructed GC uri 'ldap://queeg.mydomain.co.uk'
  [write_pipe_handler] >[write_pipe_handler] (0x0400): All data has been sent!
  [child_sig_handler] >[child_sig_handler] (0x1000): Waiting for child [382].
  [child_sig_handler] >[child_sig_handler] (0x0100): child [382] finished successfully.
  [read_pipe_handler] >[read_pipe_handler] (0x0400): EOF received, client finished
  [parse_krb5_child_response] >[parse_krb5_child_response] (0x1000): child response [0][3][46].
  [fo_set_port_status] >[fo_set_port_status] (0x0100): Marking port 389 of server 'queeg.mydomain.co.uk' as 'working'
  [set_server_common_status] >[set_server_common_status] (0x0100): Marking server 'queeg.mydomain.co.uk' as 'working'
  [fo_set_port_status] >[fo_set_port_status] (0x0400): Marking port 389 of duplicate server 'queeg.mydomain.co.uk' as 'working'
  [sysdb_set_entry_attr] >[sysdb_set_entry_attr] (0x0200): Entry [name=hugh@mydomain.co.uk,cn=users,cn=mydomain.co.uk,cn=sysdb] has set [ts_cache] attrs.
  [check_for_combined_2fa_password] >[check_for_combined_2fa_password] (0x1000): Wrong authtok type.
  [sysdb_cache_auth] >[sysdb_cache_auth] (0x0100): Authentication failed.
  [sysdb_set_entry_attr] >[sysdb_set_entry_attr] (0x0200): Entry [name=hugh@mydomain.co.uk,cn=users,cn=mydomain.co.uk,cn=sysdb] has set [cache, ts_cache] attrs.
  [krb5_auth_cache_creds] >[krb5_auth_cache_creds] (0x0020): Offline authentication failed
  [check_wait_queue] >[check_wait_queue] (0x1000): Wait queue for user [hugh@mydomain.co.uk] is empty.
  [krb5_auth_queue_done] >[krb5_auth_queue_done] (0x1000): krb5_auth_queue request [0x563536126c40] done.
  [dp_req_done] >[dp_req_done] (0x0400): DP Request [PAM Authenticate #9]: Request handler finished [0]: Success
  [_dp_req_recv] >[_dp_req_recv] (0x0400): DP Request [PAM Authenticate #9]: Receiving request data.
  [dp_req_destructor] >[dp_req_destructor] (0x0400): DP Request [PAM Authenticate #9]: Request removed.
  [dp_req_destructor] >[dp_req_destructor] (0x0400): Number of active DP request: 0
  [dp_method_enabled] >[dp_method_enabled] (0x0400): Target selinux is not configured
  [dp_pam_reply] >[dp_pam_reply] (0x1000): DP Request [PAM Authenticate #9]: Sending result [7][mydomain.co.uk]

[7][mydomain.co.uk]