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

[PATCH v2] 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 | 54 +++++++++++++++++++++---
 1 file changed, 48 insertions(+), 6 deletions(-)

diff --git a/meta/lib/oeqa/runtime/cases/oe_syslog.py b/meta/lib/oeqa/runtime/cases/oe_syslog.py
index 0f5f9f43ca..480aadedf9 100644
--- a/meta/lib/oeqa/runtime/cases/oe_syslog.py
+++ b/meta/lib/oeqa/runtime/cases/oe_syslog.py
@@ -6,6 +6,7 @@ from oeqa.runtime.case import OERuntimeTestCase
 from oeqa.core.decorator.depends import OETestDepends
 from oeqa.core.decorator.data import skipIfDataVar
 from oeqa.runtime.decorator.package import OEHasPackage
+import time
 
 class SyslogTest(OERuntimeTestCase):
 
@@ -21,6 +22,49 @@ class SyslogTest(OERuntimeTestCase):
 
 class SyslogTestConfig(OERuntimeTestCase):
 
+    def test_syslog_restart_sanity(self):
+        status, syslogd_pid = self.target.run('pidof syslogd')
+        status, klogd_pid = self.target.run('pidof klogd')
+
+        status, output = self.target.run('/etc/init.d/syslog restart')
+
+        # Always check for an error, most likely a race between shutting down and starting up
+        timeout = time.time() + 30
+
+        while time.time() < timeout:
+            # Verify the old ones are no longer running
+            status, err_output = self.target.run('kill -0 %s' %syslogd_pid)
+            if not status:
+                self.logger.debug("old syslogd is running")
+                status = 1
+                continue
+
+            status, err_output = self.target.run('kill -0 %s' %klogd_pid)
+            if not status:
+                self.logger.debug("old klogd is running")
+                status = 1
+                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)
+
+
     @OETestDepends(['oe_syslog.SyslogTest.test_syslog_running'])
     def test_syslog_logger(self):
         status, output = self.target.run('logger foobar')
@@ -40,7 +84,7 @@ class SyslogTestConfig(OERuntimeTestCase):
     @OETestDepends(['oe_syslog.SyslogTest.test_syslog_running'])
     def test_syslog_restart(self):
         if "systemd" != self.tc.td.get("VIRTUAL-RUNTIME_init_manager", ""):
-            (_, _) = self.target.run('/etc/init.d/syslog restart')
+            self.test_syslog_restart_sanity()
         else:
             (_, _) = self.target.run('systemctl restart syslog.service')
 
@@ -52,10 +96,8 @@ class SyslogTestConfig(OERuntimeTestCase):
     def test_syslog_startup_config(self):
         cmd = 'echo "LOGFILE=/var/log/test" >> /etc/syslog-startup.conf'
         self.target.run(cmd)
-        status, output = self.target.run('/etc/init.d/syslog restart')
-        msg = ('Could not restart syslog service. Status and output:'
-               ' %s and %s' % (status,output))
-        self.assertEqual(status, 0, msg)
+
+        self.test_syslog_restart_sanity()
 
         cmd = 'logger foobar && grep foobar /var/log/test'
         status,output = self.target.run(cmd)
@@ -64,4 +106,4 @@ class SyslogTestConfig(OERuntimeTestCase):
 
         cmd = "sed -i 's#LOGFILE=/var/log/test##' /etc/syslog-startup.conf"
         self.target.run(cmd)
-        self.target.run('/etc/init.d/syslog restart')
+        self.test_syslog_restart_sanity()
-- 
2.21.0

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

[Richard Purdie]

On Fri, 2019-06-21 at 15:27 -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 | 54 +++++++++++++++++++++-
> --
>  1 file changed, 48 insertions(+), 6 deletions(-)

This looks good, thanks. Testing found a small issue:

https://autobuilder.yoctoproject.org/typhoon/#/builders/61/builds/733

(and many other similar failures)

It looks like its trying to run these tests on core-image-minimal which
doesn't have an ssh server and only gets tested over serial.

The tests need to be skipped there too, so there is some markup missing
from one of the tests as a quick guess.

Hopefully easy to reproduce and fix.

Cheers,

Richard

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

[Richard Purdie]

On Fri, 2019-06-21 at 15:27 -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 | 54 +++++++++++++++++++++---
>  1 file changed, 48 insertions(+), 6 deletions(-)
> 
> diff --git a/meta/lib/oeqa/runtime/cases/oe_syslog.py b/meta/lib/oeqa/runtime/cases/oe_syslog.py
> index 0f5f9f43ca..480aadedf9 100644
> --- a/meta/lib/oeqa/runtime/cases/oe_syslog.py
> +++ b/meta/lib/oeqa/runtime/cases/oe_syslog.py
> @@ -6,6 +6,7 @@ from oeqa.runtime.case import OERuntimeTestCase
>  from oeqa.core.decorator.depends import OETestDepends
>  from oeqa.core.decorator.data import skipIfDataVar
>  from oeqa.runtime.decorator.package import OEHasPackage
> +import time
>  
>  class SyslogTest(OERuntimeTestCase):
>  
> @@ -21,6 +22,49 @@ class SyslogTest(OERuntimeTestCase):
>  
>  class SyslogTestConfig(OERuntimeTestCase):
>  
> +    def test_syslog_restart_sanity(self):
> +        status, syslogd_pid = self.target.run('pidof syslogd')
> +        status, klogd_pid = self.target.run('pidof klogd')

FWIW by calling this test_, it will be run as a standalone test. This
may have two issues:

a) it won't work on a systemd image
b) its missing dependency markup (is syslog running?) that the other
tests have

Unless we really want it as a standalone test (I think there is a
similar one already), the fix may be just to rename it something other
than starting with test_.

Cheers,

Richard

> +        status, output = self.target.run('/etc/init.d/syslog restart')
> +
> +        # Always check for an error, most likely a race between shutting down and starting up
> +        timeout = time.time() + 30
> +
> 

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

[Richard Purdie]

On Sat, 2019-06-22 at 09:08 +0100, Richard Purdie wrote:
> On Fri, 2019-06-21 at 15:27 -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 | 54
> > +++++++++++++++++++++---
> >  1 file changed, 48 insertions(+), 6 deletions(-)
> > 
> > diff --git a/meta/lib/oeqa/runtime/cases/oe_syslog.py
> > b/meta/lib/oeqa/runtime/cases/oe_syslog.py
> > index 0f5f9f43ca..480aadedf9 100644
> > --- a/meta/lib/oeqa/runtime/cases/oe_syslog.py
> > +++ b/meta/lib/oeqa/runtime/cases/oe_syslog.py
> > @@ -6,6 +6,7 @@ from oeqa.runtime.case import OERuntimeTestCase
> >  from oeqa.core.decorator.depends import OETestDepends
> >  from oeqa.core.decorator.data import skipIfDataVar
> >  from oeqa.runtime.decorator.package import OEHasPackage
> > +import time
> >  
> >  class SyslogTest(OERuntimeTestCase):
> >  
> > @@ -21,6 +22,49 @@ class SyslogTest(OERuntimeTestCase):
> >  
> >  class SyslogTestConfig(OERuntimeTestCase):
> >  
> > +    def test_syslog_restart_sanity(self):
> > +        status, syslogd_pid = self.target.run('pidof syslogd')
> > +        status, klogd_pid = self.target.run('pidof klogd')
> 
> FWIW by calling this test_, it will be run as a standalone test. This
> may have two issues:
> 
> a) it won't work on a systemd image
> b) its missing dependency markup (is syslog running?) that the other
> tests have
> 
> Unless we really want it as a standalone test (I think there is a
> similar one already), the fix may be just to rename it something
> other
> than starting with test_.

Sorry for all the replies, just realised I could quickly test a rename
of the function so I've done that in -next.

Cheers,

Richard

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

[Richard Purdie]

On Sat, 2019-06-22 at 09:12 +0100, Richard Purdie wrote:
> On Sat, 2019-06-22 at 09:08 +0100, Richard Purdie wrote:
> > On Fri, 2019-06-21 at 15:27 -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 | 54
> > > +++++++++++++++++++++---
> > >  1 file changed, 48 insertions(+), 6 deletions(-)
> > > 
> > > diff --git a/meta/lib/oeqa/runtime/cases/oe_syslog.py
> > > b/meta/lib/oeqa/runtime/cases/oe_syslog.py
> > > index 0f5f9f43ca..480aadedf9 100644
> > > --- a/meta/lib/oeqa/runtime/cases/oe_syslog.py
> > > +++ b/meta/lib/oeqa/runtime/cases/oe_syslog.py
> > > @@ -6,6 +6,7 @@ from oeqa.runtime.case import OERuntimeTestCase
> > >  from oeqa.core.decorator.depends import OETestDepends
> > >  from oeqa.core.decorator.data import skipIfDataVar
> > >  from oeqa.runtime.decorator.package import OEHasPackage
> > > +import time
> > >  
> > >  class SyslogTest(OERuntimeTestCase):
> > >  
> > > @@ -21,6 +22,49 @@ class SyslogTest(OERuntimeTestCase):
> > >  
> > >  class SyslogTestConfig(OERuntimeTestCase):
> > >  
> > > +    def test_syslog_restart_sanity(self):
> > > +        status, syslogd_pid = self.target.run('pidof syslogd')
> > > +        status, klogd_pid = self.target.run('pidof klogd')
> > 
> > FWIW by calling this test_, it will be run as a standalone test.
> > This
> > may have two issues:
> > 
> > a) it won't work on a systemd image
> > b) its missing dependency markup (is syslog running?) that the
> > other
> > tests have
> > 
> > Unless we really want it as a standalone test (I think there is a
> > similar one already), the fix may be just to rename it something
> > other
> > than starting with test_.
> 
> Sorry for all the replies, just realised I could quickly test a
> rename
> of the function so I've done that in -next.

Looks better but still some syslog problem related to core-image-full-
cmdline:

https://autobuilder.yoctoproject.org/typhoon/#/builders/83/builds/231

I think that has a different syslog provider which may be affecting the
test somehow.

Cheers,

Richard

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

[Jon Mason]

On Sat, Jun 22, 2019 at 4:08 AM Richard Purdie
<richard.purdie@linuxfoundation.org> wrote:
>
> On Fri, 2019-06-21 at 15:27 -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 | 54 +++++++++++++++++++++---
> >  1 file changed, 48 insertions(+), 6 deletions(-)
> >
> > diff --git a/meta/lib/oeqa/runtime/cases/oe_syslog.py b/meta/lib/oeqa/runtime/cases/oe_syslog.py
> > index 0f5f9f43ca..480aadedf9 100644
> > --- a/meta/lib/oeqa/runtime/cases/oe_syslog.py
> > +++ b/meta/lib/oeqa/runtime/cases/oe_syslog.py
> > @@ -6,6 +6,7 @@ from oeqa.runtime.case import OERuntimeTestCase
> >  from oeqa.core.decorator.depends import OETestDepends
> >  from oeqa.core.decorator.data import skipIfDataVar
> >  from oeqa.runtime.decorator.package import OEHasPackage
> > +import time
> >
> >  class SyslogTest(OERuntimeTestCase):
> >
> > @@ -21,6 +22,49 @@ class SyslogTest(OERuntimeTestCase):
> >
> >  class SyslogTestConfig(OERuntimeTestCase):
> >
> > +    def test_syslog_restart_sanity(self):
> > +        status, syslogd_pid = self.target.run('pidof syslogd')
> > +        status, klogd_pid = self.target.run('pidof klogd')
>
> FWIW by calling this test_, it will be run as a standalone test. This
> may have two issues:
>
> a) it won't work on a systemd image

I didn't know that was something desired.  I can modify it to try and
cover that use case, as it does make sense to try and cover all of
them.

> b) its missing dependency markup (is syslog running?) that the other
> tests have

I assumed that the dependencies on the calling functions would filter
down.  I'll add a similar limit as the other functions present.

> Unless we really want it as a standalone test (I think there is a
> similar one already), the fix may be just to rename it something other
> than starting with test_.

I can change that.

>
> Cheers,
>
> Richard
>
> > +        status, output = self.target.run('/etc/init.d/syslog restart')
> > +
> > +        # Always check for an error, most likely a race between shutting down and starting up
> > +        timeout = time.time() + 30
> > +
> >
>