On Fri, 2017-05-19 at 13:43 +0200, Lukas Slebodnik wrote:
> On (19/05/17 11:31), Joakim Tjernlund wrote:
> > On Fri, 2017-05-19 at 13:22 +0200, Lukas Slebodnik wrote:
> > > On (19/05/17 10:37), Joakim Tjernlund wrote:
> > > > On Thu, 2017-05-18 at 11:40 -0400, Striker Leggette wrote:
> > > > > I can understand the first unlock from waking up from sleep. For
the second, bump your debug_level in sssd.conf up to 7 and then check to see if you have
any "Got request" lines in /var/log/sssd/sssd_domain.log for the second login
attempt from the lock screen. You should be able to see if it is using cached creds or
actively trying to parse the domain server.
> > > > > Can you paste your sssd.conf also?
> > > >
> > > > I not using a VPN, local ethernet (got wifi too bu in this case eth is
connected)
> > > >
> > >
> > > And log file says there are problem with resolution of DNS names.
> > >
> > > e.g.
> > > [fo_resolve_service_done] (0x0020): Failed to resolve server
'se-dc01.infinera.com': Could not contact DNS servers
> > > [fo_resolve_service_done] (0x0020): Failed to resolve server
'se-dc02.infinera.com': Could not contact DNS servers
> > > [fo_resolve_service_done] (0x0020): Failed to resolve server
'sv-dc01.infinera.com': Could not contact DNS servers
> > > [fo_resolve_service_done] (0x0020): Failed to resolve server
'sv-dc02.infinera.com': Could not contact DNS servers
> > >
> > > Therefore sssd works in offline mode and therefore cannot renew a ticket.
> >
> > ping and nslookup work fine, I just did a new lock unlock and this is the log
from this that action.
> > I still did not get a new ticket.
> >
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [fo_resolve_service_send]
(0x0100): Trying to resolve service 'AD'
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [get_server_status]
(0x1000): Status of server 'se-dc01.infinera.com' is 'working'
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [get_port_status] (0x1000):
Port status of port 0 for server 'se-dc01.infinera.com' is 'not working'
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [get_port_status] (0x0080):
SSSD is unable to complete the full connection request, this internal status does not
necessarily indicate network port issues.
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [get_server_status]
(0x1000): Status of server 'se-dc02.infinera.com' is 'name resolved'
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [get_port_status] (0x1000):
Port status of port 0 for server 'se-dc02.infinera.com' is 'not working'
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [get_port_status] (0x0080):
SSSD is unable to complete the full connection request, this internal status does not
necessarily indicate network port issues.
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [get_server_status]
(0x1000): Status of server 'sv-dc01.infinera.com' is 'name resolved'
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [get_port_status] (0x1000):
Port status of port 0 for server 'sv-dc01.infinera.com' is 'not working'
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [get_port_status] (0x0080):
SSSD is unable to complete the full connection request, this internal status does not
necessarily indicate network port issues.
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [get_server_status]
(0x1000): Status of server 'sv-dc02.infinera.com' is 'name not resolved'
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [get_port_status] (0x1000):
Port status of port 0 for server 'sv-dc02.infinera.com' is 'neutral'
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [get_server_status]
(0x1000): Status of server 'sv-dc02.infinera.com' is 'name not resolved'
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]]
[resolv_gethostbyname_files_send] (0x0100): Trying to resolve A record of
'sv-dc02.infinera.com' in files
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [set_server_common_status]
(0x0100): Marking server 'sv-dc02.infinera.com' as 'resolving name'
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]]
[resolv_gethostbyname_files_send] (0x0100): Trying to resolve AAAA record of
'sv-dc02.infinera.com' in files
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [resolv_gethostbyname_next]
(0x0200): No more address families to retry
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]]
[resolv_gethostbyname_dns_query] (0x0100): Trying to resolve A record of
'sv-dc02.infinera.com' in DNS
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]]
[resolv_gethostbyname_dns_parse] (0x1000): Parsing an A reply
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [request_watch_destructor]
(0x0400): Deleting request watch
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [set_server_common_status]
(0x0100): Marking server 'sv-dc02.infinera.com' as 'name resolved'
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [be_resolve_server_process]
(0x0200): Found address for server
sv-dc02.infinera.com: [10.100.98.22] TTL 3600
>
> looks like name was properly resolved here
>
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [ad_resolve_callback]
(0x0100): Constructed uri 'ldap://sv-dc02.infinera.com'
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [ad_resolve_callback]
(0x0100): Constructed GC uri 'ldap://sv-dc02.infinera.com'
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]]
[be_primary_server_timeout_activate] (0x0400): The primary server reconnection is already
scheduled
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [sss_domain_get_state]
(0x1000): Domain
infinera.com is Active
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [write_pipe_handler]
(0x0400): All data has been sent!
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]]
[delayed_online_authentication_callback] (0x0200): Backend is online, starting delayed
online authentication.
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [authenticate_stored_users]
(0x0020): User [jocke(a)infinera.com] is still logged in, trying online authentication.
>
> SSSD tried to authenticate online here.
>
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [child_sig_handler]
(0x1000): Waiting for child [15431].
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [child_sig_handler]
(0x0100): child [15431] finished successfully.
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [krb5_auth_queue_send]
(0x1000): Request [0xefd900] successfully added to wait queue of user
[jocke(a)infinera.com].
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [read_pipe_handler]
(0x0400): EOF received, client finished
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [fo_set_port_status]
(0x0100): Marking port 0 of server 'sv-dc02.infinera.com' as 'not
working'
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [fo_set_port_status]
(0x0400): Marking port 0 of duplicate server 'sv-dc02.infinera.com' as 'not
working'
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [fo_resolve_service_send]
(0x0100): Trying to resolve service 'AD'
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [get_server_status]
(0x1000): Status of server 'se-dc01.infinera.com' is 'working'
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [get_port_status] (0x1000):
Port status of port 0 for server 'se-dc01.infinera.com' is 'not working'
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [get_port_status] (0x0080):
SSSD is unable to complete the full connection request, this internal status does not
necessarily indicate network port issues.
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [get_server_status]
(0x1000): Status of server 'se-dc02.infinera.com' is 'name resolved'
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [get_port_status] (0x1000):
Port status of port 0 for server 'se-dc02.infinera.com' is 'not working'
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [get_port_status] (0x0080):
SSSD is unable to complete the full connection request, this internal status does not
necessarily indicate network port issues.
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [get_server_status]
(0x1000): Status of server 'sv-dc01.infinera.com' is 'name resolved'
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [get_port_status] (0x1000):
Port status of port 0 for server 'sv-dc01.infinera.com' is 'not working'
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [get_port_status] (0x0080):
SSSD is unable to complete the full connection request, this internal status does not
necessarily indicate network port issues.
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [get_server_status]
(0x1000): Status of server 'sv-dc02.infinera.com' is 'name resolved'
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [get_port_status] (0x1000):
Port status of port 0 for server 'sv-dc02.infinera.com' is 'not working'
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [get_port_status] (0x0080):
SSSD is unable to complete the full connection request, this internal status does not
necessarily indicate network port issues.
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [fo_resolve_service_send]
(0x0020): No available servers for service 'AD'
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [be_resolve_server_done]
(0x1000): Server resolution failed: [5]: Input/output error
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [be_mark_dom_offline]
(0x1000): Marking back end offline
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [be_ptask_enable] (0x0400):
Task [Check if online (periodic)]: enabling task
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [be_ptask_schedule]
(0x0400): Task [Check if online (periodic)]: scheduling task 81 seconds from now
[1495193169]
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [be_run_offline_cb]
(0x0080): Going offline. Running callbacks.
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [write_pipe_handler]
(0x0400): All data has been sent!
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [read_pipe_handler]
(0x0400): EOF received, client finished
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [parse_krb5_child_response]
(0x0020): message too short.
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [krb5_auth_done] (0x0040):
Could not parse child response [22]: Invalid argument
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [krb5_auth_queue_done]
(0x0040): krb5_auth_recv failed with: 22
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [renew_tgt_done] (0x0020):
krb5_auth request failed.
> > (Fri May 19 13:24:48 2017) [sssd[be[infinera.com]]] [renew_tgt_done] (0x0200):
Giving back pam data.
>
> But renew failed and sssd went offline.
>
> Could you truncate sssd log file (truncate -s 0 /var/log/sssd/*)
> Then try to reproduce one more time and provide not only domain log file but
> also *child log files.
Did that but I did not get a child log file at all.
If you can see debug messages from following functions
write_pipe_handler
read_pipe_handler
parse_krb5_child_response
Then krb5_child was executed. And there will be non-empty file
/var/log/sssd/krb5_child.log.
> Attachments or pastebin are usually better
> then direct inclusion of log into mail.
Sure, will attach next time