On 08/12/2016 11:06 AM, Jakub Hrozek wrote:
> On Thu, Aug 11, 2016 at 02:23:39PM +0200, Petr Cech wrote:
> > On 08/09/2016 02:49 PM, Jakub Hrozek wrote:
> > > On Tue, Aug 09, 2016 at 12:57:58PM +0200, Petr Cech wrote:
> > > > On 08/09/2016 11:26 AM, Jakub Hrozek wrote:
> > > > > On Mon, Aug 08, 2016 at 09:46:55AM +0200, Petr Cech wrote:
> > > > > > > On 08/04/2016 05:01 PM, Petr Cech wrote:
> > > > > > > > > On 08/04/2016 04:35 PM, Petr Cech wrote:
> > > > > > > > > > > Hi list,
> > > > > > > > > > >
> > > > > > > > > > > there is the first version of
patch for [1]. I need
> > > > > > > > > > > to investigate if we have the same
issue in other
> > > > > > > > > > > *_childs.
> > > > > > > > > > >
> > > > > > > > > > > I tested it with sleep() added
into ldap_child code.
> > > > > > > > > > >
> > > > > > > > > > > [1]
https://fedorahosted.org/sssd/ticket/3106
> > > > > > > > > > >
> > > > > > > > >
> > > > > > > > > I know, it is not perfect. For example 2
seconds between SIGTERM and
> > > > > > > > > SIGKILL should be constant. I will send the
second version with other
> > > > > > > > > childs, but not today.
> > > > > > > > >
> > > > > > > > > Regards
> > > > > > >
> > > > > > > Hello all,
> > > > > > >
> > > > > > > there is fixed patch set. There is only one minor
change -- constant for
> > > > > > > time between signals.
> > > > > > >
> > > > > > > Is there better name for global_ccname_file_dummy? I
did not want to break
> > > > > > > the naming... but it looks really long.
> > > > > I think this name is fine, but I would prefer to not use the
variable in
> > > > > the code, except for setting it after the temporary file is
created and
> > > > > then set the variable back to NULL after the temporary file is
renamed
> > > > > to the real one.
> > > >
> > > > Addressed.
> > > >
> > > > Thanks Jakub, it looks better. :-)
> > >
> > > OK, now I actually tested the patch and it regresses the way we handle
> > > responses, because the handler exits the process with success error
> > > code, the provider then tries to parse the child output, which is not
> > > there..
> > >
> > > I think the easiest way would be to define a return code of ldap_child
> > > that would be used in exit in the signal handler and the back end code
> > > would print a nice debug message telling the admin that the child timed
> > > out.
> >
> > Thanks Jakub,
> > improved patch set is attached.
> >
> > Regards
> >
> > --
> > Petr^4 Čech
>
> > From f84d4d2fcc7c1f2cb404a02aeea7abd12c14dd61 Mon Sep 17 00:00:00 2001
> > From: Petr Cech <pcech(a)redhat.com>
> > Date: Fri, 22 Jul 2016 14:28:54 +0200
> > Subject: [PATCH] LDAP: Fixing of removing netgroup from cache
>
> This patch is from a different set.
Sorry, the right one is attached.
> > From 1f40587cbb256bab98e8e35670ca76426b41e6b1 Mon Sep 17 00:00:00 2001
> > From: Petr Cech <pcech(a)redhat.com>
> > Date: Thu, 4 Aug 2016 16:27:40 +0200
> > Subject: [PATCH 2/3] LDAP: Adding SIGTERM signal before SIGKILL
> >
> > We add better termination of ldap_child. If ldap_child reaches
> > the timeout for termination parent sents SIGTERM signal. Child
> > has 2 seconds for removing temporary file and exit.
> > If it is not sufficient there is SIGKILL send to the child.
> >
> > Resolves:
> >
https://fedorahosted.org/sssd/ticket/3106
>
> [...]
>
> > +static void get_tgt_timeout_handler(struct tevent_context *ev,
> > + struct tevent_timer *te,
> > + struct timeval tv, void *pvt)
> > +{
> > + struct tevent_req *req = talloc_get_type(pvt, struct tevent_req);
> > + struct sdap_get_tgt_state *state = tevent_req_data(req,
> > + struct sdap_get_tgt_state);
> > + int ret;
> > +
> > + DEBUG(SSSDBG_TRACE_ALL,
> > + "timeout for sending SIGTERM to tgt child [%d]
reached.\n",
> > + state->child->pid);
> > +
> > + ret = kill(state->child->pid, SIGTERM);
> > + if (ret == -1) {
>
> Please use:
> ret = errno
> and then use ret instead of errno in the DEBUG statement to avoid
> overwriting errno if we ever change this branch in the future.
Thanks, addressed.
> > + DEBUG(SSSDBG_CRIT_FAILURE,
> > + "Sending SIGTERM failed [%d][%s].\n", errno,
strerror(errno));
> > + }
>
> > From 4ca2a6b90dd7d7ee792b0e144a4e6d432f4693a4 Mon Sep 17 00:00:00 2001
> > From: Petr Cech <pcech(a)redhat.com>
> > Date: Thu, 11 Aug 2016 14:18:15 +0200
> > Subject: [PATCH 3/3] LDAP: Adding SIGCHLD callback
> >
> > This patch adds SIGCHLD callback for ldap_child. So if timeout is
> > reached and ldap_child is terminated by handler we have debug message
> > about it.
> >
> > Resolves:
> >
https://fedorahosted.org/sssd/ticket/3106
>
> This patch does not apply for me, so I'll just comment on the diff.
I applied it on top of master. If there is some issue please tell me.
> > ---
> > src/providers/ldap/ldap_child.c | 2 +-
> > src/providers/ldap/sdap_child_helpers.c | 10 +++++++++-
> > src/util/child_common.h | 1 +
> > 3 files changed, 11 insertions(+), 2 deletions(-)
> >
> > diff --git a/src/providers/ldap/ldap_child.c b/src/providers/ldap/ldap_child.c
> > index
2edfc30ec7b4a3ff03d86ae41f086a6128451a9b..b6913fdaa4c8f87f33cc8c10f9a029d63626f279 100644
> > --- a/src/providers/ldap/ldap_child.c
> > +++ b/src/providers/ldap/ldap_child.c
> > @@ -54,7 +54,7 @@ static void sig_term_handler(int sig)
> > }
> > }
> >
> > - _exit(0);
> > + _exit(SIGNAL_EXIT_CODE);
>
> I would prefer CHILD_SIGTERM_EXIT_CODE or CHILD_TIMEOUT_EXIT_CODE
> (prefix and change the name)
Addressed. Naming is one big issue :-)
> > }
> >
> > static krb5_context krb5_error_ctx;
> > diff --git a/src/providers/ldap/sdap_child_helpers.c
b/src/providers/ldap/sdap_child_helpers.c
> > index
9f9c9b57a7ca5e1217d56ab560cc941432084df8..98b0fe777fd18fad6ffdaefc48ea156a45f4e803 100644
> > --- a/src/providers/ldap/sdap_child_helpers.c
> > +++ b/src/providers/ldap/sdap_child_helpers.c
> > @@ -69,6 +69,14 @@ static void sdap_close_fd(int *fd)
> > *fd = -1;
> > }
> >
> > +void child_callback(int child_status, struct tevent_signal *sige, void *pvt)
> > +{
> > + if (WEXITSTATUS(child_status) == SIGNAL_EXIT_CODE) {
> > + DEBUG(SSSDBG_CRIT_FAILURE,
> > + "LDAP child was terminated due to timeout\n");
> > + }
> > +}
> > +
> > static errno_t sdap_fork_child(struct tevent_context *ev,
> > struct sdap_child *child)
> > {
> > @@ -110,7 +118,7 @@ static errno_t sdap_fork_child(struct tevent_context *ev,
> > sss_fd_nonblocking(child->io->read_from_child_fd);
> > sss_fd_nonblocking(child->io->write_to_child_fd);
> >
> > - ret = child_handler_setup(ev, pid, NULL, NULL, NULL);
> > + ret = child_handler_setup(ev, pid, child_callback, NULL, NULL);
> > if (ret != EOK) {
> > goto fail;
> > }
> > diff --git a/src/util/child_common.h b/src/util/child_common.h
> > index
eb7623987238d5d9e9032b9bbbbef49188f5b1d2..e88661349a1568ffc981e0a3134f7ccea61b394e 100644
> > --- a/src/util/child_common.h
> > +++ b/src/util/child_common.h
> > @@ -36,6 +36,7 @@
> > #define CHILD_MSG_CHUNK 256
> >
> > #define SIGTERM_TO_SIGKILL_TIME 2
> > +#define SIGNAL_EXIT_CODE EINTR
>
> I'm not sure if we want to use errno constants here, I would say just
> defining our own constant is better, at least to avoid overflowing the
> maximum exit value of 255. I don't think we even have to worry about
> clashing with constants from sysexits.h, this is our internal API anyway.
I choose 7.
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.
(Fri Aug 12 15:01:05 2016) [sssd[be[ipaldap]]] [sdap_kinit_done] (0x0020): child failed
(22 [Invalid argument])
(Fri Aug 12 15:01:05 2016) [sssd[be[ipaldap]]] [sdap_cli_kinit_done] (0x0400): Cannot get
a TGT: ret [22](Invalid argument)
(Fri Aug 12 15:01:05 2016) [sssd[be[ipaldap]]] [sdap_cli_connect_recv] (0x0040): Unable to
establish connection [13]: Permission denied
(Fri Aug 12 15:01:05 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