[PATCH] oe_syslog.py: Handle syslogd/klogd restart race

[PATCH] oe_syslog.py: Handle syslogd/klogd restart race

[Jon Mason]

syslogd and klogd can occasionally take too long to restart, which
causes tests to fail by starting before the log daemons are ready.  To
work around this problem, poll for up to 30 seconds on the processes to
verify the old ones are killed and the new ones are up and running.

[YOCTO #13379]

Signed-off-by: Jon Mason <jdmason@kudzu.us>
---
 meta/lib/oeqa/runtime/cases/oe_syslog.py | 37 ++++++++++++++++++++++++
 1 file changed, 37 insertions(+)

diff --git a/meta/lib/oeqa/runtime/cases/oe_syslog.py b/meta/lib/oeqa/runtime/cases/oe_syslog.py
index 0f5f9f43ca..3270a0fc88 100644
--- a/meta/lib/oeqa/runtime/cases/oe_syslog.py
+++ b/meta/lib/oeqa/runtime/cases/oe_syslog.py
@@ -50,9 +50,46 @@ class SyslogTestConfig(OERuntimeTestCase):
     @skipIfDataVar('VIRTUAL-RUNTIME_init_manager', 'systemd',
                    'Not appropiate for systemd image')
     def test_syslog_startup_config(self):
+        status, syslogd_pid = self.target.run('pidof syslogd')
+        status, klogd_pid = self.target.run('pidof klogd')
+
         cmd = 'echo "LOGFILE=/var/log/test" >> /etc/syslog-startup.conf'
         self.target.run(cmd)
         status, output = self.target.run('/etc/init.d/syslog restart')
+
+        # Error, most likely a race between shutting down and starting up
+        if status:
+            import time
+            timeout = time.time() + 30
+
+            while time.time() < timeout:
+                time.sleep(1)
+                # Verify the old ones are no longer running
+                status, output = self.target.run('kill -0 %s' %syslogd_pid)
+                if not status:
+                    self.logger.debug("old syslogd is running")
+                    continue
+
+                status, output = self.target.run('kill -0 %s' %klogd_pid)
+                if not status:
+                    self.logger.debug("old klogd is running")
+                    continue
+
+                # Verify the new ones are running
+                status, new_syslogd_pid = self.target.run('pidof syslogd')
+                if status:
+                    self.logger.debug("new syslogd is not running")
+                    continue
+
+                status, new_klogd_pid = self.target.run('pidof klogd')
+                if status:
+                    self.logger.debug("new syslogd is not running")
+                    continue
+
+                # Everything is fine now, so keep running
+                status = 0
+                break
+
         msg = ('Could not restart syslog service. Status and output:'
                ' %s and %s' % (status,output))
         self.assertEqual(status, 0, msg)
-- 
2.21.0

Re: [PATCH] oe_syslog.py: Handle syslogd/klogd restart race

[Richard Purdie]

On Fri, 2019-06-21 at 11:42 -0400, Jon Mason wrote:
> syslogd and klogd can occasionally take too long to restart, which
> causes tests to fail by starting before the log daemons are ready.  To
> work around this problem, poll for up to 30 seconds on the processes to
> verify the old ones are killed and the new ones are up and running.
> 
> [YOCTO #13379]
> 
> Signed-off-by: Jon Mason <jdmason@kudzu.us>
> ---
>  meta/lib/oeqa/runtime/cases/oe_syslog.py | 37 ++++++++++++++++++++++++
>  1 file changed, 37 insertions(+)
> 
> diff --git a/meta/lib/oeqa/runtime/cases/oe_syslog.py b/meta/lib/oeqa/runtime/cases/oe_syslog.py
> index 0f5f9f43ca..3270a0fc88 100644
> --- a/meta/lib/oeqa/runtime/cases/oe_syslog.py
> +++ b/meta/lib/oeqa/runtime/cases/oe_syslog.py
> @@ -50,9 +50,46 @@ class SyslogTestConfig(OERuntimeTestCase):
>      @skipIfDataVar('VIRTUAL-RUNTIME_init_manager', 'systemd',
>                     'Not appropiate for systemd image')
>      def test_syslog_startup_config(self):
> +        status, syslogd_pid = self.target.run('pidof syslogd')
> +        status, klogd_pid = self.target.run('pidof klogd')
> +
>          cmd = 'echo "LOGFILE=/var/log/test" >> /etc/syslog-startup.conf'
>          self.target.run(cmd)
>          status, output = self.target.run('/etc/init.d/syslog restart')
> +
> +        # Error, most likely a race between shutting down and starting up
> +        if status:
> +            import time
> +            timeout = time.time() + 30
> +
> +            while time.time() < timeout:
> +                time.sleep(1)
> +                # Verify the old ones are no longer running
> +                status, output = self.target.run('kill -0 %s' %syslogd_pid)
> +                if not status:
> +                    self.logger.debug("old syslogd is running")
> +                    continue
> +
> +                status, output = self.target.run('kill -0 %s' %klogd_pid)
> +                if not status:
> +                    self.logger.debug("old klogd is running")
> +                    continue
> +
> +                # Verify the new ones are running
> +                status, new_syslogd_pid = self.target.run('pidof syslogd')
> +                if status:
> +                    self.logger.debug("new syslogd is not running")
> +                    continue
> +
> +                status, new_klogd_pid = self.target.run('pidof klogd')
> +                if status:
> +                    self.logger.debug("new syslogd is not running")
> +                    continue
> +
> +                # Everything is fine now, so keep running
> +                status = 0
> +                break
> +
>          msg = ('Could not restart syslog service. Status and output:'
>                 ' %s and %s' % (status,output))
>          self.assertEqual(status, 0, msg)

Thanks, I think this is reasonable however I think we may need to make
the above a function and then call it from other places in the tests in
that file.

test_syslog_restart should check it did restart using the above

test_syslog_startup_config does a second restart which we should also
check?

Out of interest were you able to see error codes being returned in
status in your tests?

Cheers,

Richard

Re: [PATCH] oe_syslog.py: Handle syslogd/klogd restart race

[Jon Mason]

On Fri, Jun 21, 2019 at 12:14 PM Richard Purdie
<richard.purdie@linuxfoundation.org> wrote:
>
> On Fri, 2019-06-21 at 11:42 -0400, Jon Mason wrote:
> > syslogd and klogd can occasionally take too long to restart, which
> > causes tests to fail by starting before the log daemons are ready.  To
> > work around this problem, poll for up to 30 seconds on the processes to
> > verify the old ones are killed and the new ones are up and running.
> >
> > [YOCTO #13379]
> >
> > Signed-off-by: Jon Mason <jdmason@kudzu.us>
> > ---
> >  meta/lib/oeqa/runtime/cases/oe_syslog.py | 37 ++++++++++++++++++++++++
> >  1 file changed, 37 insertions(+)
> >
> > diff --git a/meta/lib/oeqa/runtime/cases/oe_syslog.py b/meta/lib/oeqa/runtime/cases/oe_syslog.py
> > index 0f5f9f43ca..3270a0fc88 100644
> > --- a/meta/lib/oeqa/runtime/cases/oe_syslog.py
> > +++ b/meta/lib/oeqa/runtime/cases/oe_syslog.py
> > @@ -50,9 +50,46 @@ class SyslogTestConfig(OERuntimeTestCase):
> >      @skipIfDataVar('VIRTUAL-RUNTIME_init_manager', 'systemd',
> >                     'Not appropiate for systemd image')
> >      def test_syslog_startup_config(self):
> > +        status, syslogd_pid = self.target.run('pidof syslogd')
> > +        status, klogd_pid = self.target.run('pidof klogd')
> > +
> >          cmd = 'echo "LOGFILE=/var/log/test" >> /etc/syslog-startup.conf'
> >          self.target.run(cmd)
> >          status, output = self.target.run('/etc/init.d/syslog restart')
> > +
> > +        # Error, most likely a race between shutting down and starting up
> > +        if status:
> > +            import time
> > +            timeout = time.time() + 30
> > +
> > +            while time.time() < timeout:
> > +                time.sleep(1)
> > +                # Verify the old ones are no longer running
> > +                status, output = self.target.run('kill -0 %s' %syslogd_pid)
> > +                if not status:
> > +                    self.logger.debug("old syslogd is running")
> > +                    continue
> > +
> > +                status, output = self.target.run('kill -0 %s' %klogd_pid)
> > +                if not status:
> > +                    self.logger.debug("old klogd is running")
> > +                    continue
> > +
> > +                # Verify the new ones are running
> > +                status, new_syslogd_pid = self.target.run('pidof syslogd')
> > +                if status:
> > +                    self.logger.debug("new syslogd is not running")
> > +                    continue
> > +
> > +                status, new_klogd_pid = self.target.run('pidof klogd')
> > +                if status:
> > +                    self.logger.debug("new syslogd is not running")
> > +                    continue
> > +
> > +                # Everything is fine now, so keep running
> > +                status = 0
> > +                break
> > +
> >          msg = ('Could not restart syslog service. Status and output:'
> >                 ' %s and %s' % (status,output))
> >          self.assertEqual(status, 0, msg)
>
> Thanks, I think this is reasonable however I think we may need to make
> the above a function and then call it from other places in the tests in
> that file.
>
> test_syslog_restart should check it did restart using the above
>
> test_syslog_startup_config does a second restart which we should also
> check?

Seems reasonable.  I'll crank out v2 shortly.

> Out of interest were you able to see error codes being returned in
> status in your tests?

I used code to force every error path during development, but not that
the testcase will fail.  So, your question did cause me to notice a
bug in the code when verifying that the old ones are no longer
running.  That should return 0 if still running, which wouldn't cause
the assert outside of the loop.  So, I'll need to tweak this there.
v2 will have this fix as well.

Thanks,
Jon

>
> Cheers,
>
> Richard
>

Re: [PATCH] oe_syslog.py: Handle syslogd/klogd restart race

[richard.purdie]

On Fri, 2019-06-21 at 12:39 -0400, Jon Mason wrote:
> On Fri, Jun 21, 2019 at 12:14 PM Richard Purdie
> <richard.purdie@linuxfoundation.org> wrote:
> > On Fri, 2019-06-21 at 11:42 -0400, Jon Mason wrote:
> > > 
> > Thanks, I think this is reasonable however I think we may need to
> > make
> > the above a function and then call it from other places in the
> > tests in
> > that file.
> > 
> > test_syslog_restart should check it did restart using the above
> > 
> > test_syslog_startup_config does a second restart which we should
> > also
> > check?
> 
> Seems reasonable.  I'll crank out v2 shortly.
> 
> > Out of interest were you able to see error codes being returned in
> > status in your tests?
> 
> I used code to force every error path during development, but not
> that
> the testcase will fail.  So, your question did cause me to notice a
> bug in the code when verifying that the old ones are no longer
> running.  That should return 0 if still running, which wouldn't cause
> the assert outside of the loop.  So, I'll need to tweak this there.
> v2 will have this fix as well.

The reason I ask is that its far from clear that busybox's starts-stop-
daemon would notice if the daemon didn't restart so I don't think we
can reliably trust status to be set correctly.

Is there any reason we can't run these checks regardless of status?

I realise there is slightly more overhead but it might give us more
chance of fixing all the races?

Cheers,

Richard

Re: [PATCH] oe_syslog.py: Handle syslogd/klogd restart race

[Jon Mason]

On Fri, Jun 21, 2019 at 12:58 PM <richard.purdie@linuxfoundation.org> wrote:
>
> On Fri, 2019-06-21 at 12:39 -0400, Jon Mason wrote:
> > On Fri, Jun 21, 2019 at 12:14 PM Richard Purdie
> > <richard.purdie@linuxfoundation.org> wrote:
> > > On Fri, 2019-06-21 at 11:42 -0400, Jon Mason wrote:
> > > >
> > > Thanks, I think this is reasonable however I think we may need to
> > > make
> > > the above a function and then call it from other places in the
> > > tests in
> > > that file.
> > >
> > > test_syslog_restart should check it did restart using the above
> > >
> > > test_syslog_startup_config does a second restart which we should
> > > also
> > > check?
> >
> > Seems reasonable.  I'll crank out v2 shortly.
> >
> > > Out of interest were you able to see error codes being returned in
> > > status in your tests?
> >
> > I used code to force every error path during development, but not
> > that
> > the testcase will fail.  So, your question did cause me to notice a
> > bug in the code when verifying that the old ones are no longer
> > running.  That should return 0 if still running, which wouldn't cause
> > the assert outside of the loop.  So, I'll need to tweak this there.
> > v2 will have this fix as well.
>
> The reason I ask is that its far from clear that busybox's starts-stop-
> daemon would notice if the daemon didn't restart so I don't think we
> can reliably trust status to be set correctly.
>
> Is there any reason we can't run these checks regardless of status?

The current code logic would work regardless of whether it failed or
not.  I we can run it every time, and it would not hurt anything.

> I realise there is slightly more overhead but it might give us more
> chance of fixing all the races?

4 extra function calls would almost be statistical noise.  I'll code
it up to do the check every time regardless and add it for each
syslogd/klogd call.

>
> Cheers,
>
> Richard
>

Re: [PATCH] oe_syslog.py: Handle syslogd/klogd restart race

[Jon Mason]

On Fri, Jun 21, 2019 at 1:44 PM Jon Mason <jdmason@kudzu.us> wrote:
>
> On Fri, Jun 21, 2019 at 12:58 PM <richard.purdie@linuxfoundation.org> wrote:
> >
> > On Fri, 2019-06-21 at 12:39 -0400, Jon Mason wrote:
> > > On Fri, Jun 21, 2019 at 12:14 PM Richard Purdie
> > > <richard.purdie@linuxfoundation.org> wrote:
> > > > On Fri, 2019-06-21 at 11:42 -0400, Jon Mason wrote:
> > > > >
> > > > Thanks, I think this is reasonable however I think we may need to
> > > > make
> > > > the above a function and then call it from other places in the
> > > > tests in
> > > > that file.
> > > >
> > > > test_syslog_restart should check it did restart using the above
> > > >
> > > > test_syslog_startup_config does a second restart which we should
> > > > also
> > > > check?
> > >
> > > Seems reasonable.  I'll crank out v2 shortly.
> > >
> > > > Out of interest were you able to see error codes being returned in
> > > > status in your tests?
> > >
> > > I used code to force every error path during development, but not
> > > that
> > > the testcase will fail.  So, your question did cause me to notice a
> > > bug in the code when verifying that the old ones are no longer
> > > running.  That should return 0 if still running, which wouldn't cause
> > > the assert outside of the loop.  So, I'll need to tweak this there.
> > > v2 will have this fix as well.
> >
> > The reason I ask is that its far from clear that busybox's starts-stop-
> > daemon would notice if the daemon didn't restart so I don't think we
> > can reliably trust status to be set correctly.
> >
> > Is there any reason we can't run these checks regardless of status?
>
> The current code logic would work regardless of whether it failed or
> not.  I we can run it every time, and it would not hurt anything.
>
> > I realise there is slightly more overhead but it might give us more
> > chance of fixing all the races?
>
> 4 extra function calls would almost be statistical noise.  I'll code
> it up to do the check every time regardless and add it for each
> syslogd/klogd call.

A timed run of testimage on a Cortex A57x4 system (with KVM enabled)
went from ~1m21s (1m23s, 1m22s,1m20s) to ~1m23s (1m22s, 1m25s, 1m24s).
Without KVM enabled, it went from 20m6s to 20m56s. It's possible with
a larger sample size that they would converge even more, but I think
this is sufficient to show it's not a deal breaker to run it every
time.

Thanks,
Jon


>
> >
> > Cheers,
> >
> > Richard
> >

Re: [PATCH] oe_syslog.py: Handle syslogd/klogd restart race

[richard.purdie]

On Fri, 2019-06-21 at 15:26 -0400, Jon Mason wrote:
> On Fri, Jun 21, 2019 at 1:44 PM Jon Mason <jdmason@kudzu.us> wrote:
> > On Fri, Jun 21, 2019 at 12:58 PM <
> > richard.purdie@linuxfoundation.org> wrote:
> > > 
> > > I realise there is slightly more overhead but it might give us
> > > more
> > > chance of fixing all the races?
> > 
> > 4 extra function calls would almost be statistical noise.  I'll
> > code
> > it up to do the check every time regardless and add it for each
> > syslogd/klogd call.
> 
> A timed run of testimage on a Cortex A57x4 system (with KVM enabled)
> went from ~1m21s (1m23s, 1m22s,1m20s) to ~1m23s (1m22s, 1m25s,
> 1m24s).
> Without KVM enabled, it went from 20m6s to 20m56s. It's possible with
> a larger sample size that they would converge even more, but I think
> this is sufficient to show it's not a deal breaker to run it every
> time.

Sound good to me, thanks! :)

Cheers,

Richard