On Fri, Aug 12, 2016 at 03:41:26PM +0200, Petr Cech wrote:
On 08/12/2016 03:07 PM, Jakub Hrozek wrote:
> > Logs now look like:
> > >
> > > [root@albireo sssd]# grep 'child' sssd_ipa.cygnus.dev.log
> > > [child_handler_setup] (0x2000): Setting up signal handler up for pid
[18835]
> > > [child_handler_setup] (0x2000): Signal handler set up for pid [18835]
> > > [set_tgt_child_timeout] (0x0400): Setting 6 seconds timeout for tgt child
> > >
> > > (6 seconds later)
> > >
> > > [get_tgt_timeout_handler] (0x4000): timeout for sending SIGTERM to tgt
child
> > > [18835] reached.
> > > [get_tgt_timeout_handler] (0x0400): Setting 2 seconds timeout for sending
> > > SIGKILL to tgt child
> > > [sdap_get_tgt_recv] (0x0020): Cannot parse child response: [22][Invalid
> > > argument]
> > > [sdap_kinit_done] (0x0020): child failed (22 [Invalid argument])
> > > [child_sig_handler] (0x1000): Waiting for child [18835].
> > > [child_sig_handler] (0x0020): child [18835] failed with status [7].
> > > [child_callback] (0x0020): LDAP child was terminated due to timeout
> I'm sorry, but these patches still don't fix the issue I was seeing.
> Before the patches, when I timed out the child process, I saw:
> (Fri Aug 12 14:54:24 2016) [[sssd[ldap_child[31721]]]] [ldap_child_get_tgt_sync]
(0x0100): Principal name is: [host/client.ipa.test(a)IPA.TEST]
> (Fri Aug 12 14:54:24 2016) [[sssd[ldap_child[31721]]]] [ldap_child_get_tgt_sync]
(0x0100): Using keytab [MEMORY:/etc/krb5.keytab]
> (Fri Aug 12 14:54:30 2016) [sssd[be[ipaldap]]] [get_tgt_timeout_handler] (0x4000):
timeout for tgt child [31721] reached.
> (Fri Aug 12 14:54:30 2016) [sssd[be[ipaldap]]] [sdap_kinit_done] (0x0080):
Communication with KDC timed out, trying the next one
> (Fri Aug 12 14:54:30 2016) [sssd[be[ipaldap]]] [_be_fo_set_port_status] (0x8000):
Setting status: PORT_NOT_WORKING. Called from:
/sssd/src/providers/ldap/sdap_async_connection.c: sdap_kinit_done: 1207
> (Fri Aug 12 14:54:30 2016) [sssd[be[ipaldap]]] [fo_set_port_status] (0x0100):
Marking port 0 of server 'unidirect.ipa.test' as 'not working'
> (Fri Aug 12 14:54:30 2016) [sssd[be[ipaldap]]] [fo_set_port_status] (0x0400):
Marking port 0 of duplicate server 'unidirect.ipa.test' as 'not working'
> (Fri Aug 12 14:54:30 2016) [sssd[be[ipaldap]]] [sdap_kinit_next_kdc] (0x1000):
Resolving next KDC for service KERBEROS
> (Fri Aug 12 14:54:30 2016) [sssd[be[ipaldap]]] [fo_resolve_service_send] (0x0100):
Trying to resolve service 'KERBEROS'
> (Fri Aug 12 14:54:30 2016) [sssd[be[ipaldap]]] [get_server_status] (0x1000): Status
of server 'unidirect.ipa.test' is 'name resolved'
> (Fri Aug 12 14:54:30 2016) [sssd[be[ipaldap]]] [get_port_status] (0x1000): Port
status of port 0 for server 'unidirect.ipa.test' is 'not working'
> (Fri Aug 12 14:54:30 2016) [sssd[be[ipaldap]]] [fo_resolve_service_send] (0x0020):
No available servers for service 'KERBEROS'
> (Fri Aug 12 14:54:30 2016) [sssd[be[ipaldap]]] [be_resolve_server_done] (0x1000):
Server resolution failed: [5]: Input/output error
> (Fri Aug 12 14:54:30 2016) [sssd[be[ipaldap]]] [sdap_cli_kinit_done] (0x0400):
Cannot get a TGT: ret [1432158228](Network I/O Error)
> (Fri Aug 12 14:54:30 2016) [sssd[be[ipaldap]]] [sdap_cli_connect_recv] (0x0040):
Unable to establish connection [13]: Permission denied
> (Fri Aug 12 14:54:30 2016) [sssd[be[ipaldap]]] [_be_fo_set_port_status] (0x8000):
Setting status: PORT_NOT_WORKING. Called from:
/sssd/src/providers/ldap/sdap_async_connection.c: sdap_cli_connect_recv: 2048
>
> After the patch, I see:
> (Fri Aug 12 15:01:05 2016) [sssd[be[ipaldap]]] [get_tgt_timeout_handler] (0x4000):
timeout for sending SIGTERM to tgt child [17291] reached.
> (Fri Aug 12 15:01:05 2016) [sssd[be[ipaldap]]] [get_tgt_timeout_handler] (0x0400):
Setting 2 seconds timeout for sending SIGKILL to tgt child
> (Fri Aug 12 15:01:05 2016) [[sssd[ldap_child[17291]]]] [sig_term_handler] (0x0010):
Received signal [Terminated] [15], shutting down
> (Fri Aug 12 15:01:05 2016) [sssd[be[ipaldap]]] [read_pipe_handler] (0x0400): EOF
received, client finished
> (Fri Aug 12 15:01:05 2016) [sssd[be[ipaldap]]] [sdap_get_tgt_recv] (0x0020): Cannot
parse child response: [22][Invalid argument]
> here ---^
>
> This is the part I don't like, we try to read the response from the child's
> pipe and fail with a bad error message. I thought this was because with
> the preivous patch, we exit the child with zero, but I guess this was not
> the case.. Anyway, we still should fix this, the message would be really
> confusing to admins.
Hi Jakub,
I know I had the same
'Cannot parse child response: [22][Invalid argument]'
in my logs too, see my last mail above.
Some lines after it I have new message
'[child_callback] (0x0020): LDAP child was terminated due to timeout'
I understand that it is not satisfying. The main purpose of this patch was
deleting temporary files if timeout reached. And this is IMO solved I think.
It is true that we have big effort to have understandable logs.
Yesterday I looked deeper at mechanism how signals, child handler and all
such stuff works in ldap_child case. I wasn't able to tell to
sdap_get_tgt_recv() that the state is changed and we shouldn't parse the
answer.
If I understand handler stuff right I need introduce in ldap_child handler
whole mechanism like in src/providers/be_dyndns.c
The mechanism is calling the child_handler_setup() with all parameters which
means rewrite sdap_child_helpers in appropriate manner.
I think it would be enough to pass the tevent_req to the
child_callback() and cancel it with tevent_req_error(req, ETIMEDOUT)
The problem is that with the current patches, the whole request is
marked as 'succeeded', that's why the _recv() function tries to parse
the response. If you look at sdap_get_tgt_recv(), if the request is
marked as failure, the processing aborts in TEVENT_REQ_RETURN_ON_ERROR..
>
> Maybe there is simpler way please tell me if. But if this ticket is urgent
> (removing of temporary files) we could push it and solve logs (I mean
> rewrite handler mechanism) in next ticket.
>
> Regards
>
> --
> Petr^4 Čech
> _______________________________________________
> sssd-devel mailing list
> sssd-devel(a)lists.fedorahosted.org
>
https://lists.fedorahosted.org/admin/lists/sssd-devel@lists.fedorahosted.org