[PATCH] Fix startup race condition causing backend restarts

[Stephen Gallagher]

When the backends start up, the monitor was immediately sending a
getIdentity request. However, as we've added more processing to
the initialization routines over time, we started introducing
latency between when we open the connection and when we're able to
process requests on that connection.

I've updated the monitor to check for NoReply as an error message
and queue the getIdentity check for retries until the service
answers or one wallclock second (literally, ten tries at 10ms
each) has passed.

[Martin Nagy]

On Fri, 07 Aug 2009 13:59:49 -0400, Stephen Gallagher
 wrote:
> When the backends start up, the monitor was immediately sending a
> getIdentity request. However, as we've added more processing to
> the initialization routines over time, we started introducing
> latency between when we open the connection and when we're able to
> process requests on that connection.
>
> I've updated the monitor to check for NoReply as an error message
> and queue the getIdentity check for retries until the service
> answers or one wallclock second (literally, ten tries at 10ms
> each) has passed.

Hi Steven, the patch looks good to me. Ack.
I do have some minor suggestions though, apply them at your own
discretion.
> static void identity_check(DBusPendingCall *pending, void *data)
> @@ -1862,8 +1886,11 @@ static void identity_check(DBusPendingCall *pending, void *data)
>      DBusError dbus_error;
>      dbus_uint16_t svc_ver;
>      char *svc_name;
> const char *error_name;
> dbus_bool_t ret;
> int type;
> struct timeval tv;
> struct tevent_timer *te;

I would put these two variables closer to where they are needed (marked
below).

[snip]
>    error_name = dbus_message_get_error_name(reply);
>    if (strcmp(error_name, DBUS_ERROR_NO_REPLY) == 0) {

Put the 'tv' and 'te' variable declarations here.
>        /* Queue up another try in 10ms */
>        fake_svc->restarts++;
>        gettimeofday(&tv, NULL);
>        tv.tv_usec += 1000;
>        te = tevent_add_timer(fake_svc->mt_ctx->ev, fake_svc, tv,
>                              do_identity_check, fake_svc);
>        if (te == NULL) {
>            DEBUG(0, ("Failed to add do_identity_check event for [%s]!\n",
>                      fake_svc->name));
>            sbus_disconnect(conn_ctx);
>            return;
>        }
>        DEBUG(3, ("getIdentity reported NoReply. Retrying.\n"));

Move this debug statement right at the beginning of the if() body.

Martin

[Stephen Gallagher]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On 08/10/2009 03:38 AM, Martin Nagy wrote:
> On Fri, 07 Aug 2009 13:59:49 -0400, Stephen Gallagher
>  wrote:
> > When the backends start up, the monitor was immediately sending a
> > getIdentity request. However, as we've added more processing to
> > the initialization routines over time, we started introducing
> > latency between when we open the connection and when we're able to
> > process requests on that connection.
> >
> > I've updated the monitor to check for NoReply as an error message
> > and queue the getIdentity check for retries until the service
> > answers or one wallclock second (literally, ten tries at 10ms
> > each) has passed.
>
> Hi Steven, the patch looks good to me. Ack.
> I do have some minor suggestions though, apply them at your own
> discretion.
> > static void identity_check(DBusPendingCall *pending, void *data)
> > @@ -1862,8 +1886,11 @@ static void identity_check(DBusPendingCall *pending, void *data)
> >      DBusError dbus_error;
> >      dbus_uint16_t svc_ver;
> >      char *svc_name;
> > const char *error_name;
> > dbus_bool_t ret;
> > int type;
> > struct timeval tv;
> > struct tevent_timer *te;
>
> I would put these two variables closer to where they are needed (marked
> below).
>
> [snip]
> >    error_name = dbus_message_get_error_name(reply);
> >    if (strcmp(error_name, DBUS_ERROR_NO_REPLY) == 0) {
>
> Put the 'tv' and 'te' variable declarations here.

I generally would, but the coding style within the SSSD prefers
declaration at the top of the function. If I have misunderstood our
coding style here, someone please tell me.
> >        /* Queue up another try in 10ms */
> >        fake_svc->restarts++;
> >        gettimeofday(&tv, NULL);
> >        tv.tv_usec += 1000;
> >        te = tevent_add_timer(fake_svc->mt_ctx->ev, fake_svc, tv,
> >                              do_identity_check, fake_svc);
> >        if (te == NULL) {
> >            DEBUG(0, ("Failed to add do_identity_check event for [%s]!\n",
> >                      fake_svc->name));
> >            sbus_disconnect(conn_ctx);
> >            return;
> >        }
> >        DEBUG(3, ("getIdentity reported NoReply. Retrying.\n"));
>
> Move this debug statement right at the beginning of the if() body.
>
> Martin

I put this at the end because it is only true if tevent_add_timer()
succeeded here. (Otherwise we are not retrying, we've just failed).

Thank you for the review.

- -- 
Stephen Gallagher
RHCE 804006346421761

Looking to carve out IT costs?
www.redhat.com/carveoutcosts/
> -----BEGIN PGP SIGNATURE-----
> Version: GnuPG v1.4.9 (GNU/Linux)
> Comment: Using GnuPG with Fedora - http://enigmail.mozdev.org/
>
> iEYEARECAAYFAkp/+9YACgkQeiVVYja6o6PJKwCgizu18ymzsbeqPMmwiSWf9h5W
> qzcAnRqIhjWzJTfoO7jwVr04HNS3MceQ
> =4VfB
> -----END PGP SIGNATURE-----

[Martin Nagy]

On Mon, 10 Aug 2009 06:52:11 -0400, Stephen Gallagher
 wrote:
> -----BEGIN PGP SIGNED MESSAGE-----
> Hash: SHA1
>
> On 08/10/2009 03:38 AM, Martin Nagy wrote:
> > On Fri, 07 Aug 2009 13:59:49 -0400, Stephen Gallagher
> >  wrote:
> > > When the backends start up, the monitor was immediately sending a
> > > getIdentity request. However, as we've added more processing to
> > > the initialization routines over time, we started introducing
> > > latency between when we open the connection and when we're able to
> > > process requests on that connection.
> > >
> > > I've updated the monitor to check for NoReply as an error message
> > > and queue the getIdentity check for retries until the service
> > > answers or one wallclock second (literally, ten tries at 10ms
> > > each) has passed.
> >
> > Hi Steven, the patch looks good to me. Ack.
> > I do have some minor suggestions though, apply them at your own
> > discretion.
> > > static void identity_check(DBusPendingCall *pending, void *data)
> > > @@ -1862,8 +1886,11 @@ static void identity_check(DBusPendingCall *pending, void *data)
> > >      DBusError dbus_error;
> > >      dbus_uint16_t svc_ver;
> > >      char *svc_name;
> > > const char *error_name;
> > > dbus_bool_t ret;
> > > int type;
> > > struct timeval tv;
> > > struct tevent_timer *te;
> >
> > I would put these two variables closer to where they are needed (marked
> > below).
> >
> > [snip]
> > >    error_name = dbus_message_get_error_name(reply);
> > >    if (strcmp(error_name, DBUS_ERROR_NO_REPLY) == 0) {
> >
> > Put the 'tv' and 'te' variable declarations here.
>
> I generally would, but the coding style within the SSSD prefers
> declaration at the top of the function. If I have misunderstood our
> coding style here, someone please tell me.

You're right. I will send an email proposing to change this in the
coding style.
> > >        /* Queue up another try in 10ms */
> > >        fake_svc->restarts++;
> > >        gettimeofday(&tv, NULL);
> > >        tv.tv_usec += 1000;
> > >        te = tevent_add_timer(fake_svc->mt_ctx->ev, fake_svc, tv,
> > >                              do_identity_check, fake_svc);
> > >        if (te == NULL) {
> > >            DEBUG(0, ("Failed to add do_identity_check event for [%s]!\n",
> > >                      fake_svc->name));
> > >            sbus_disconnect(conn_ctx);
> > >            return;
> > >        }
> > >        DEBUG(3, ("getIdentity reported NoReply. Retrying.\n"));
> >
> > Move this debug statement right at the beginning of the if() body.
> >
> > Martin
>
> I put this at the end because it is only true if tevent_add_timer()
> succeeded here. (Otherwise we are not retrying, we've just failed).

Hm, my thinking here was that if te == NULL, the error message would be
out of context. But now that I look at it, you explicitly mention that
you are adding a do_identity_check event, so I guess both ways are
correct.

Martin

[Dmitri Pal]

Martin Nagy wrote:
> On Mon, 10 Aug 2009 06:52:11 -0400, Stephen Gallagher
>  wrote:
> > -----BEGIN PGP SIGNED MESSAGE-----
> > Hash: SHA1
> >
> > On 08/10/2009 03:38 AM, Martin Nagy wrote:
> > > On Fri, 07 Aug 2009 13:59:49 -0400, Stephen Gallagher
> > >  wrote:
> > > > When the backends start up, the monitor was immediately sending a
> > > > getIdentity request. However, as we've added more processing to
> > > > the initialization routines over time, we started introducing
> > > > latency between when we open the connection and when we're able to
> > > > process requests on that connection.
> > > >
> > > > I've updated the monitor to check for NoReply as an error message
> > > > and queue the getIdentity check for retries until the service
> > > > answers or one wallclock second (literally, ten tries at 10ms
> > > > each) has passed.
> > >
> > > Hi Steven, the patch looks good to me. Ack.
> > > I do have some minor suggestions though, apply them at your own
> > > discretion.
> > > > static void identity_check(DBusPendingCall *pending, void *data)
> > > > @@ -1862,8 +1886,11 @@ static void identity_check(DBusPendingCall *pending, void *data)
> > > >      DBusError dbus_error;
> > > >      dbus_uint16_t svc_ver;
> > > >      char *svc_name;
> > > > const char *error_name;
> > > > dbus_bool_t ret;
> > > > int type;
> > > > struct timeval tv;
> > > > struct tevent_timer *te;
> > >
> > > I would put these two variables closer to where they are needed (marked
> > > below).
> > >
> > > [snip]
> > > >    error_name = dbus_message_get_error_name(reply);
> > > >    if (strcmp(error_name, DBUS_ERROR_NO_REPLY) == 0) {
> > >
> > > Put the 'tv' and 'te' variable declarations here.
> >
> > I generally would, but the coding style within the SSSD prefers
> > declaration at the top of the function. If I have misunderstood our
> > coding style here, someone please tell me.
>
> You're right. I will send an email proposing to change this in the
> coding style.

I am not against the change in general but I suggest we do not do it now.
This is a significant change to the way the code is structured or can be
structured.
Changing it now IMO is too late. It might make more harm than good.

[Stephen Gallagher]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On 08/10/2009 08:36 AM, Dmitri Pal wrote:
> Martin Nagy wrote:
> > On Mon, 10 Aug 2009 06:52:11 -0400, Stephen Gallagher
> >  wrote:
> > > -----BEGIN PGP SIGNED MESSAGE-----
> > > Hash: SHA1
> > >
> > > On 08/10/2009 03:38 AM, Martin Nagy wrote:
> > > > On Fri, 07 Aug 2009 13:59:49 -0400, Stephen Gallagher
> > > >  wrote:
> > > > > When the backends start up, the monitor was immediately sending a
> > > > > getIdentity request. However, as we've added more processing to
> > > > > the initialization routines over time, we started introducing
> > > > > latency between when we open the connection and when we're able to
> > > > > process requests on that connection.
> > > > >
> > > > > I've updated the monitor to check for NoReply as an error message
> > > > > and queue the getIdentity check for retries until the service
> > > > > answers or one wallclock second (literally, ten tries at 10ms
> > > > > each) has passed.
> > > >
> > > > Hi Steven, the patch looks good to me. Ack.
> > > > I do have some minor suggestions though, apply them at your own
> > > > discretion.
> > > > > static void identity_check(DBusPendingCall *pending, void *data)
> > > > > @@ -1862,8 +1886,11 @@ static void identity_check(DBusPendingCall *pending, void *data)
> > > > >      DBusError dbus_error;
> > > > >      dbus_uint16_t svc_ver;
> > > > >      char *svc_name;
> > > > > const char *error_name;
> > > > > dbus_bool_t ret;
> > > > > int type;
> > > > > struct timeval tv;
> > > > > struct tevent_timer *te;
> > > >
> > > > I would put these two variables closer to where they are needed (marked
> > > > below).
> > > >
> > > > [snip]
> > > > >    error_name = dbus_message_get_error_name(reply);
> > > > >    if (strcmp(error_name, DBUS_ERROR_NO_REPLY) == 0) {
> > > >
> > > > Put the 'tv' and 'te' variable declarations here.
> > >
> > > I generally would, but the coding style within the SSSD prefers
> > > declaration at the top of the function. If I have misunderstood our
> > > coding style here, someone please tell me.
> >
> > You're right. I will send an email proposing to change this in the
> > coding style.
>
> I am not against the change in general but I suggest we do not do it now.
> This is a significant change to the way the code is structured or can be
> structured.
> Changing it now IMO is too late. It might make more harm than good.

We're not proposing to go through the code and change what is already
done. We're proposing that, going forward, we start doing it a new way.
> sssd-devel mailing list
> [e-mail]
> https://fedorahosted.org/mailman/listinfo/sssd-devel

- -- 
Stephen Gallagher
RHCE 804006346421761

Looking to carve out IT costs?
www.redhat.com/carveoutcosts/
> -----BEGIN PGP SIGNATURE-----
> Version: GnuPG v1.4.9 (GNU/Linux)
> Comment: Using GnuPG with Fedora - http://enigmail.mozdev.org/
>
> iEYEARECAAYFAkqAGcoACgkQeiVVYja6o6PFNQCeNEO0sKFcWAnDEOYcKJ/idoxk
> M3cAnjR3HPDPEVtZSMVPlav8xuefv3Vd
> =Dk1G
> -----END PGP SIGNATURE-----

[Dmitri Pal]

Stephen Gallagher wrote:
> On 08/10/2009 08:36 AM, Dmitri Pal wrote:
> > Martin Nagy wrote:
> > > On Mon, 10 Aug 2009 06:52:11 -0400, Stephen Gallagher
> > >  wrote:
> > > > -----BEGIN PGP SIGNED MESSAGE-----
> > > > Hash: SHA1
> > > >
> > > > On 08/10/2009 03:38 AM, Martin Nagy wrote:
> > > > > On Fri, 07 Aug 2009 13:59:49 -0400, Stephen Gallagher
> > > > >  wrote:
> > > > > > When the backends start up, the monitor was immediately sending a
> > > > > > getIdentity request. However, as we've added more processing to
> > > > > > the initialization routines over time, we started introducing
> > > > > > latency between when we open the connection and when we're able to
> > > > > > process requests on that connection.
> > > > > >
> > > > > > I've updated the monitor to check for NoReply as an error message
> > > > > > and queue the getIdentity check for retries until the service
> > > > > > answers or one wallclock second (literally, ten tries at 10ms
> > > > > > each) has passed.
> > > > >
> > > > > Hi Steven, the patch looks good to me. Ack.
> > > > > I do have some minor suggestions though, apply them at your own
> > > > > discretion.
> > > > > > static void identity_check(DBusPendingCall *pending, void *data)
> > > > > > @@ -1862,8 +1886,11 @@ static void
>
> identity_check(DBusPendingCall *pending, void *data)
> > > > > >  DBusError dbus_error;
> > > > > >  dbus_uint16_t svc_ver;
> > > > > >  char *svc_name;
> > > > > > const char *error_name;
> > > > > > dbus_bool_t ret;
> > > > > > int type;
> > > > > > struct timeval tv;
> > > > > > struct tevent_timer *te;
> > > > >
> > > > > I would put these two variables closer to where they are needed
>
> (marked
> > > > > below).
> > > > >
> > > > > [snip]
> > > > > >    error_name = dbus_message_get_error_name(reply);
> > > > > >    if (strcmp(error_name, DBUS_ERROR_NO_REPLY) == 0) {
> > > > >
> > > > > Put the 'tv' and 'te' variable declarations here.
> > > >
> > > > I generally would, but the coding style within the SSSD prefers
> > > > declaration at the top of the function. If I have misunderstood our
> > > > coding style here, someone please tell me.
> > >
> > > You're right. I will send an email proposing to change this in the
> > > coding style.
> >
> > I am not against the change in general but I suggest we do not do it
>
> now.
> > This is a significant change to the way the code is structured or can be
> > structured.
> > Changing it now IMO is too late. It might make more harm than good.
>
> We're not proposing to go through the code and change what is already
> done. We're proposing that, going forward, we start doing it a new way.

Which will make the code harder to read since the styles will be mixed.
> > sssd-devel mailing list
> > [e-mail]
> > https://fedorahosted.org/mailman/listinfo/sssd-devel

_______________________________________________
sssd-devel mailing list
[e-mail]
https://fedorahosted.org/mailman/listinfo/sssd-devel

[Martin Nagy]

Dmitri Pal wrote:
> Stephen Gallagher wrote:
> > On 08/10/2009 08:36 AM, Dmitri Pal wrote:
> > > Martin Nagy wrote:
> > > > On Mon, 10 Aug 2009 06:52:11 -0400, Stephen Gallagher
> > > >  wrote:
> > > > > -----BEGIN PGP SIGNED MESSAGE-----
> > > > > Hash: SHA1
> > > > >
> > > > > On 08/10/2009 03:38 AM, Martin Nagy wrote:
> > > > > > On Fri, 07 Aug 2009 13:59:49 -0400, Stephen Gallagher
> > > > > >  wrote:
> > > > > >
> > > > > > > When the backends start up, the monitor was immediately sending a
> > > > > > > getIdentity request. However, as we've added more processing to
> > > > > > > the initialization routines over time, we started introducing
> > > > > > > latency between when we open the connection and when we're able to
> > > > > > > process requests on that connection.
> > > > > > >
> > > > > > > I've updated the monitor to check for NoReply as an error message
> > > > > > > and queue the getIdentity check for retries until the service
> > > > > > > answers or one wallclock second (literally, ten tries at 10ms
> > > > > > > each) has passed.
> > > > > > >         
> > > > > > Hi Steven, the patch looks good to me. Ack.
> > > > > > I do have some minor suggestions though, apply them at your own
> > > > > > discretion.
> > > > > >
> > > > > > >  static void identity_check(DBusPendingCall *pending, void *data)
> > > > > > > @@ -1862,8 +1886,11 @@ static void
> >
> > identity_check(DBusPendingCall *pending, void *data)
> > > > > > >      DBusError dbus_error;
> > > > > > >      dbus_uint16_t svc_ver;
> > > > > > >      char *svc_name;
> > > > > > > +    const char *error_name;
> > > > > > >      dbus_bool_t ret;
> > > > > > >      int type;
> > > > > > > +    struct timeval tv;
> > > > > > > +    struct tevent_timer *te;
> > > > > > >         
> > > > > > I would put these two variables closer to where they are needed
> >
> > (marked
> > > > > > below).
> > > > > >
> > > > > > [snip]
> > > > > >
> > > > > > > +        error_name = dbus_message_get_error_name(reply);
> > > > > > > +        if (strcmp(error_name, DBUS_ERROR_NO_REPLY) == 0) {
> > > > > > >         
> > > > > > Put the 'tv' and 'te' variable declarations here.
> > > > >
> > > > > I generally would, but the coding style within the SSSD prefers
> > > > > declaration at the top of the function. If I have misunderstood our
> > > > > coding style here, someone please tell me.
> > > >
> > > > You're right. I will send an email proposing to change this in the
> > > > coding style.
> > >
> > > I am not against the change in general but I suggest we do not do it
> >
> > now.
> > > This is a significant change to the way the code is structured or can be
> > > structured.
> > > Changing it now IMO is too late. It might make more harm than good.
> >
> > We're not proposing to go through the code and change what is already
> > done. We're proposing that, going forward, we start doing it a new way.
>
> Which will make the code harder to read since the styles will be mixed.

I think this really is not a question of style. I'd vote for removing
the paragraph from the coding style and not mention it at all. This
should just be left for the programmers discretion. And I don't think
that mixing would have such a profound negative impact that it would not
be worth it. It shouldn't be a dogma you have to follow, but it
certainly helps if you'd need 10 variables in a longer function -- such
a code simply isn't readable.

Martin

[Simo Sorce]

On Fri, 2009-08-07 at 13:59 -0400, Stephen Gallagher wrote:
> When the backends start up, the monitor was immediately sending a
> getIdentity request. However, as we've added more processing to
> the initialization routines over time, we started introducing
> latency between when we open the connection and when we're able to
> process requests on that connection.
>
> I've updated the monitor to check for NoReply as an error message
> and queue the getIdentity check for retries until the service
> answers or one wallclock second (literally, ten tries at 10ms
> each) has passed.

After a brief discussion on IRC, we decided to change the way the client
identify instead of adding this hack on top.
I will send a patch shortly.

Simo.