On Thu, Jun 04, 2020 at 11:47:36AM -0400, Abhijit Tikekar wrote:
> Hi all,
>
> We recently started having issues with some SSSD clients that are
> connecting to RODC. They were all working fine when suddenly all
> authentications started getting following
>
> sshd[4487]: pam_sss(sshd:auth): received for user firstname.lastname: 4
> (System error)
>
> Being a RODC, keytab was created manually on a writable DC using setspn &
> ktpass and then integrated on the system using ktutil. Things were fine
> until last week when it stopped working on all such systems. We are not
> able to identify if the issue is on the system side or AD. Network side
> looks good and all required ports are open between client and Server. Host
> can also resolve RODC via DNS. Even other utilities such as ldapsearch,
> getent, id etc retrieve the results just fine. It is only the main login
> process that fails. Attaching parts of logs generated with debug level 10.
>
> It would be great if someone can review these and point us in the right
> direction.
>
> *sssd_domain.log*
>
> (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [dp_attach_req] (0x0400):
> Number of active DP request: 1
> (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [sdap_id_op_connect_step]
> (0x4000): beginning to connect
> (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [fo_resolve_service_send]
> (0x0100): Trying to resolve service 'AD'
> (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [get_server_status]
> (0x1000): Status of server 'RODC.x.y.local' is 'name resolved'
> (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [get_port_status]
> (0x1000): Port status of port 0 for server 'RODC.x.y.local' is 'not working'
> (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [get_port_status]
> (0x0080): SSSD is unable to complete the full connection request, this
> internal status does not necessarily indicate network port issues.
> (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [fo_resolve_service_send]
> (0x0020): No available servers for service 'AD'
> (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [be_resolve_server_done]
> (0x1000): Server resolution failed: [5]: Input/output error
> (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [sdap_id_op_connect_done]
> (0x0020): Failed to connect, going offline (5 [Input/output error])
> (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [be_mark_offline]
> (0x2000): Going offline!
> (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [be_mark_offline]
> (0x2000): Enable check_if_online_ptask.
> (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [be_ptask_enable]
> (0x0080): Task [Check if online (periodic)]: already enabled
> (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [be_run_offline_cb]
> (0x4000): Flag indicates that offline callback were already called.
> (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [sdap_id_op_connect_done]
> (0x4000): notify offline to op #1
> (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]]
> [ad_subdomains_refresh_connect_done] (0x0020): Unable to connect to LDAP
> [11]: Resource temporarily unavailable
> (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]]
> [ad_subdomains_refresh_connect_done] (0x0080): No AD server is available,
> cannot get the subdomain list while offline
> (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [dp_req_done] (0x0400): DP
> Request [Subdomains #2]: Request handler finished [0]: Success
> (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [_dp_req_recv] (0x0400):
> DP Request [Subdomains #2]: Receiving request data.
> (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]]
> [dp_req_reply_list_success] (0x0400): DP Request [Subdomains #2]: Finished.
> Success.
> (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [dp_req_reply_std]
> (0x1000): DP Request [Subdomains #2]: Returning [Provider is Offline]:
> 1,1432158212,Offline
> (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]]
> [dp_table_value_destructor] (0x0400): Removing [8:8:0000:<ALL>] from reply
> table
> (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [dp_req_destructor]
> (0x0400): DP Request [Subdomains #2]: Request removed.
> (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [dp_req_destructor]
> (0x0400): Number of active DP request: 0
> (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]]
> [sdap_id_release_conn_data] (0x4000): releasing unused connection
> (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [sbus_dispatch] (0x4000):
> dbus conn: 0x55c31927bed0
> (Tue May 26 23:10:52 2020) [sssd[be[x.y.local]]] [be_ptask_offline_cb]
> (0x0400): Back end is offline
>
> *ldap_child.log*
>
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [main] (0x0400):
> ldap_child started.
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [main] (0x2000):
> context initialized
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [unpack_buffer]
> (0x1000): total buffer size: 73
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [unpack_buffer]
> (0x1000): realm_str size: 14
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [unpack_buffer]
> (0x1000): got realm_str: x.y.local
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [unpack_buffer]
> (0x1000): princ_str size: 35
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [unpack_buffer]
> (0x1000): got princ_str: host/dmz_host.x.y.local
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [unpack_buffer]
> (0x1000): keytab_name size: 0
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [unpack_buffer]
> (0x1000): lifetime: 86400
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [unpack_buffer]
> (0x0200): Will run as [0][0].
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]]
> [privileged_krb5_setup] (0x2000): Kerberos context initialized
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [main] (0x2000):
> Kerberos context initialized
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [become_user]
> (0x0200): Trying to become user [0][0].
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [become_user]
> (0x0200): Already user [0].
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [main] (0x2000):
> Running as [0][0].
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [main] (0x2000):
> getting TGT sync
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]]
> [ldap_child_get_tgt_sync] (0x2000): got realm_name: [x.y.local]
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]]
> [ldap_child_get_tgt_sync] (0x0100): Principal name is:
> [host/dmz_host.x.y.local@x.y.local]
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]]
> [ldap_child_get_tgt_sync] (0x0100): Using keytab [MEMORY:/etc/krb5.keytab]
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]]
> [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529555: Getting
> initial credentials for host/dmz_host.x.y.local@x.y.local
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]]
> [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529556: Looked up
> etypes in keytab: rc4-hmac, rc4-hmac, rc4-hmac
^^^^^^^^^^^^^^^^^^^^^^^^^^^^
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]]
> [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529558: Sending
> unauthenticated request
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]]
> [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529559: Sending
> request (227 bytes) to x.y.local
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]]
> [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529560: Sending
> initial UDP request to dgram x.x.x.x:88
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]]
> [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529561: Received
> answer (220 bytes) from dgram x.x.x.x:88
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]]
> [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529562: Response was
> from master KDC
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]]
> [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529563: Received
> error from KDC: -1765328359/Additional pre-authentication required
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]]
> [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529566:
> Preauthenticating using KDC method data
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]]
> [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529567: Processing
> preauth types: PA-PK-AS-REQ (16), PA-PK-AS-REP_OLD (15), PA-ETYPE-INFO2
> (19), PA-ENC-TIMESTAMP (2)
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]]
> [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529568: Selected
> etype info: etype rc4-hmac, salt "", params ""
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]]
> [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529569: Retrieving
> host/dmz_host.x.y.local@x.y.local from MEMORY:/etc/krb5.keytab (vno 0,
> enctype rc4-hmac) with result: 0/Success
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]]
> [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529570: AS key
> obtained for encrypted timestamp: rc4-hmac/D7FD
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]]
> [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529572: Encrypted
> timestamp (for 1590549052.518887): plain
> 301AA011180F32303230303532373033313035325AA105020307EAE7, encrypted
> 5B0813887E05A9BDC49D2BA37EEC1C61CC0E6A51212B5A29DB1AA6F319E5C11BD6E9F9D843A3E4E5ED511C932BAFAB13B7995E39
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]]
> [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529573: Preauth
> module encrypted_timestamp (2) (real) returned: 0/Success
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]]
> [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529574: Produced
> preauth for next request: PA-ENC-TIMESTAMP (2)
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]]
> [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529575: Sending
> request (303 bytes) to x.y.local
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]]
> [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529576: Sending
> initial UDP request to dgram x.x.x.x:88
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]]
> [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529577: Received
> answer (100 bytes) from dgram x.x.x.x:88
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]]
> [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529578: Response was
> from master KDC
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]]
> [sss_child_krb5_trace_cb] (0x4000): [12599] 1590549052.529579: Received
> error from KDC: -1765328370/KDC has no support for encryption type
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]]
> [ldap_child_get_tgt_sync] (0x0010): Failed to init credentials: KDC has no
> support for encryption type
Hi,
it looks like the keytab only has keys with rc4 and the AD DC does not
like those keys anymore. Is there a chance that there was a change on
the AD side recently which enforces AES keys? Can you try to get a new
keytab with AES keys?
bye,
Sumit
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]]
> [unique_filename_destructor] (0x2000): Unlinking
> [/var/lib/sss/db/ccache_x.y.local_AosPub]
> (Tue May 26 23:10:52 2020) [[sssd[ldap_child[12599]]]] [main] (0x0020):
> ldap_child_get_tgt_sync failed.
>
> *krb5_child.log*
>
>
> (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [main] (0x0400):
> krb5_child started.
> (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [unpack_buffer]
> (0x1000): total buffer size: [171]
> (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [unpack_buffer]
> (0x0100): cmd [241] uid [xxxxxxxxx] gid [yyyyyyyyy] validate [false]
> enterprise principal [false] offline [true] UPN
> [firstname.lastname@x.y.local]
> (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [unpack_buffer]
> (0x0100): ccname: [KEYRING:persistent:xxxxxxxxx] old_ccname:
> [KEYRING:persistent:xxxxxxxxx] keytab: [/etc/krb5.keytab]
> (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [check_use_fast]
> (0x0100): Not using FAST.
> (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [switch_creds]
> (0x0200): Switch user to [xxxxxxxxx][yyyyyyyyy].
> (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]]
> [sss_krb5_cc_verify_ccache] (0x2000): TGT not found or expired.
> (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [switch_creds]
> (0x0200): Switch user to [0][0].
> (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]]
> [k5c_check_old_ccache] (0x4000): Ccache_file is
> [KEYRING:persistent:xxxxxxxxx] and is not active and TGT is valid.
> (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]]
> [privileged_krb5_setup] (0x0080): Cannot open the PAC responder socket
> (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [become_user]
> (0x0200): Trying to become user [xxxxxxxxx][yyyyyyyyy].
> (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [main] (0x2000):
> Running as [xxxxxxxxx][yyyyyyyyy].
> (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [become_user]
> (0x0200): Trying to become user [xxxxxxxxx][yyyyyyyyy].
> (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [become_user]
> (0x0200): Already user [xxxxxxxxx].
> (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [k5c_setup]
> (0x2000): Running as [xxxxxxxxx][yyyyyyyyy].
> (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]]
> [set_lifetime_options] (0x0100): No specific renewable lifetime requested.
> (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]]
> [set_lifetime_options] (0x0100): No specific lifetime requested.
> (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [main] (0x0400):
> Will perform offline auth
> (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]]
> [create_empty_ccache] (0x1000): Existing ccache still valid, reusing
> (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [k5c_send_data]
> (0x0200): Received error code 0
> (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]]
> [pack_response_packet] (0x2000): response packet size: [52]
> (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [k5c_send_data]
> (0x4000): Response sent.
> (Tue May 26 23:11:06 2020) [[sssd[krb5_child[12603]]]] [main] (0x0400):
> krb5_child completed successfully
>
> *sssd_pam.log*
>
> (Tue May 26 23:11:06 2020) [sssd[pam]] [get_client_cred] (0x4000): Client
> creds: euid[0] egid[0] pid[12602].
> (Tue May 26 23:11:06 2020) [sssd[pam]] [setup_client_idle_timer] (0x4000):
> Idle timer re-set for client [0x562762f1f590][19]
> (Tue May 26 23:11:06 2020) [sssd[pam]] [accept_fd_handler] (0x0400): Client
> connected to privileged pipe!
> (Tue May 26 23:11:06 2020) [sssd[pam]] [sss_cmd_get_version] (0x0200):
> Received client version [3].
> (Tue May 26 23:11:06 2020) [sssd[pam]] [sss_cmd_get_version] (0x0200):
> Offered version [3].
> (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_cmd_authenticate] (0x0100):
> entering pam_cmd_authenticate
> (Tue May 26 23:11:06 2020) [sssd[pam]] [sss_parse_name_for_domains]
> (0x0200): name 'firstname.lastname' matched without domain, user is
> firstname.lastname
> (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): command:
> SSS_PAM_AUTHENTICATE
> (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): domain:
> not set
> (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): user:
> firstname.lastname
> (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): service:
> sshd
> (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh
> (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): ruser:
> not set
> (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): rhost:
> remote_host.x.y.local
> (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): authtok
> type: 1
> (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100):
> newauthtok type: 0
> (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
> (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): cli_pid:
> 12602
> (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): logon
> name: firstname.lastname
> (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_initgr_check_timeout] (0x4000):
> User [firstname.lastname] not found in PAM cache.
> (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_set_plugin] (0x2000): CR
> #0: Setting "Initgroups by name" plugin
> (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_send] (0x0400): CR #0:
> New request 'Initgroups by name'
> (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_process_input] (0x0400):
> CR #0: Parsing input name [firstname.lastname]
> (Tue May 26 23:11:06 2020) [sssd[pam]] [sss_parse_name_for_domains]
> (0x0200): name 'firstname.lastname' matched without domain, user is
> firstname.lastname
> (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_set_name] (0x0400): CR
> #0: Setting name [firstname.lastname]
> (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_select_domains] (0x0400):
> CR #0: Performing a multi-domain search
> (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_search_domains] (0x0400):
> CR #0: Search will bypass the cache and check the data provider
> (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_validate_domain_type]
> (0x2000): Request type POSIX-only for domain x.y.local type POSIX is valid
> (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_set_domain] (0x0400): CR
> #0: Using domain [x.y.local]
> (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_prepare_domain_data]
> (0x0400): CR #0: Preparing input data for domain [x.y.local] rules
> (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_search_send] (0x0400): CR
> #0: Looking up firstname.lastname@x.y.local
> (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_search_ncache] (0x0400):
> CR #0: Checking negative cache for [firstname.lastname@x.y.local]
> (Tue May 26 23:11:06 2020) [sssd[pam]] [sss_ncache_check_str] (0x2000):
> Checking negative cache for [NCE/USER/x.y.local/firstname.lastname@x.y.local
> ]
> (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_search_ncache] (0x0400):
> CR #0: [firstname.lastname@x.y.local] is not present in negative cache
> (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_search_dp] (0x0400): CR
> #0: Looking up [firstname.lastname@x.y.local] in data provider
> (Tue May 26 23:11:06 2020) [sssd[pam]] [sss_dp_issue_request] (0x0400):
> Issuing request for [0x5627622d5930:3:firstname.lastname@x.y.local
> @x.y.local]
> (Tue May 26 23:11:06 2020) [sssd[pam]] [sss_dp_get_account_msg] (0x0400):
> Creating request for
> [x.y.local][0x3][BE_REQ_INITGROUPS][name=firstname.lastname@x.y.local:-]
> (Tue May 26 23:11:06 2020) [sssd[pam]] [sbus_add_timeout] (0x2000):
> 0x562762f19c90
> (Tue May 26 23:11:06 2020) [sssd[pam]] [sss_dp_internal_get_send] (0x0400):
> Entering request [0x5627622d5930:3:firstname.lastname@x.y.local@x.y.local]
> (Tue May 26 23:11:06 2020) [sssd[pam]] [sbus_remove_timeout] (0x2000):
> 0x562762f19c90
> (Tue May 26 23:11:06 2020) [sssd[pam]] [sbus_dispatch] (0x4000): dbus conn:
> 0x562762f17990
> (Tue May 26 23:11:06 2020) [sssd[pam]] [sbus_dispatch] (0x4000):
> Dispatching.
> (Tue May 26 23:11:06 2020) [sssd[pam]] [sss_dp_get_reply] (0x0010): The
> Data Provider returned an error
> [org.freedesktop.sssd.Error.DataProvider.Offline]
> (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_common_dp_recv] (0x0040):
> CR #0: Data Provider Error: 3, 5, Failed to get reply from Data Provider
> (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_common_dp_recv] (0x0400):
> CR #0: Due to an error we will return cached data
> (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_search_cache] (0x0400):
> CR #0: Looking up [firstname.lastname@x.y.local] in cache
> (Tue May 26 23:11:06 2020) [sssd[pam]] [ldb] (0x4000): Added timed event
> "ltdb_callback": 0x562762f294a0
> ...
> ...
> (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_search_ncache_filter]
> (0x0400): CR #0: This request type does not support filtering result by
> negative cache
> (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_search_done] (0x0400): CR
> #0: Returning updated object [firstname.lastname@x.y.local]
> (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_create_and_add_result]
> (0x0400): CR #0: Found 15 entries in domain x.y.local
> (Tue May 26 23:11:06 2020) [sssd[pam]] [sss_dp_req_destructor] (0x0400):
> Deleting request: [0x5627622d5930:3:firstname.lastname@x.y.local@x.y.local]
> (Tue May 26 23:11:06 2020) [sssd[pam]] [cache_req_done] (0x0400): CR #0:
> Finished: Success
> (Tue May 26 23:11:06 2020) [sssd[pam]] [pd_set_primary_name] (0x0400):
> User's primary name is firstname.lastname@x.y.local
> (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_initgr_cache_set] (0x2000):
> [firstname.lastname] added to PAM initgroup cache
> (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_dp_send_req] (0x0100): Sending
> request with the following data:
> (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): command:
> SSS_PAM_AUTHENTICATE
> (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): domain:
> x.y.local
> (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): user:
> firstname.lastname@x.y.local
> (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): service:
> sshd
> (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh
> (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): ruser:
> not set
> (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): rhost:
> remote_host.x.y.local
> (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): authtok
> type: 1
> (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100):
> newauthtok type: 0
> (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): priv: 1
> (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): cli_pid:
> 12602
> (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_print_data] (0x0100): logon
> name: firstname.lastname
> (Tue May 26 23:11:06 2020) [sssd[pam]] [sbus_add_timeout] (0x2000):
> 0x562762f19c90
> (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_dom_forwarder] (0x0100):
> pam_dp_send_req returned 0
> (Tue May 26 23:11:06 2020) [sssd[pam]] [sbus_remove_timeout] (0x2000):
> 0x562762f19c90
> (Tue May 26 23:11:06 2020) [sssd[pam]] [sbus_dispatch] (0x4000): dbus conn:
> 0x562762f17990
> (Tue May 26 23:11:06 2020) [sssd[pam]] [sbus_dispatch] (0x4000):
> Dispatching.
> (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_dp_process_reply] (0x0200):
> received: [4 (System error)][x.y.local]
> (Tue May 26 23:11:06 2020) [sssd[pam]] [ldb] (0x4000): Added timed event
> "ltdb_callback": 0x562762f3be60
> ...
> ...
> (Tue May 26 23:11:06 2020) [sssd[pam]] [filter_responses] (0x0100):
> [pam_response_filter] not available, not fatal.
> (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_reply] (0x0200): blen: 79
> (Tue May 26 23:11:06 2020) [sssd[pam]] [pam_reply] (0x0200): Returning [4]:
> System error to the client
> (Tue May 26 23:11:08 2020) [sssd[pam]] [client_recv] (0x0200): Client
> disconnected!
> (Tue May 26 23:11:08 2020) [sssd[pam]] [client_close_fn] (0x2000):
> Terminated client [0x562762f1f590][19]
> (Tue May 26 23:11:11 2020) [sssd[pam]] [pam_initgr_cache_remove] (0x2000):
> [firstname.lastname] removed from PAM initgroup cache
>
>
> Thanks,
>
> ~ Abhi
> _______________________________________________
> sssd-users mailing list -- sssd-users@lists.fedorahosted.org
> To unsubscribe send an email to sssd-users-le...@lists.fedorahosted.org
> Fedora Code of Conduct:
> https://docs.fedoraproject.org/en-US/project/code-of-conduct/
> List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines
> List Archives:
> https://lists.fedorahosted.org/archives/list/sssd-users@lists.fedorahosted.org
_______________________________________________
sssd-users mailing list -- sssd-users@lists.fedorahosted.org
To unsubscribe send an email to sssd-users-le...@lists.fedorahosted.org
Fedora Code of Conduct:
https://docs.fedoraproject.org/en-US/project/code-of-conduct/
List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines
List Archives:
https://lists.fedorahosted.org/archives/list/sssd-users@lists.fedorahosted.org
