[PATCH] process: Flush server stdout/stderr before reporting failure

[PATCH] process: Flush server stdout/stderr before reporting failure

[Jan Kiszka]

We need to print exceptions and flush output channels before telling the
client that the server failed. Otherwise the daemon log file may still
be empty when the client opens it for printing.

This fixes error reporting when the output is redirected to a pipe, e.g.
"bitbake target | cat" with a syntax error in a recipes or config file.
That's specifically annoying when bitbake is under the control of a
frontend process such as kas.

Signed-off-by: Jan Kiszka <jan.kiszka@siemens.com>
---
 lib/bb/server/process.py | 7 ++++++-
 1 file changed, 6 insertions(+), 1 deletion(-)

diff --git a/lib/bb/server/process.py b/lib/bb/server/process.py
index 9e5e709f..bcc4eb40 100644
--- a/lib/bb/server/process.py
+++ b/lib/bb/server/process.py
@@ -29,6 +29,7 @@ import array
 import os
 import sys
 import time
+import traceback
 import select
 import socket
 import subprocess
@@ -435,7 +436,11 @@ class BitBakeServer(object):
         try:
             self.cooker = bb.cooker.BBCooker(self.configuration, self.featureset)
             writer.send("ready")
-        except:
+        except (Exception, SystemExit) as e:
+            if type(e) != SystemExit:
+                traceback.print_exc()
+            sys.stdout.flush()
+            sys.stderr.flush()
             writer.send("fail")
             raise
         finally:
-- 
2.16.4

Re: [PATCH] process: Flush server stdout/stderr before reporting failure

[Richard Purdie]

On Sun, 2018-09-02 at 10:43 +0200, Jan Kiszka wrote:
> We need to print exceptions and flush output channels before telling
> the
> client that the server failed. Otherwise the daemon log file may
> still
> be empty when the client opens it for printing.
> 
> This fixes error reporting when the output is redirected to a pipe,
> e.g.
> "bitbake target | cat" with a syntax error in a recipes or config
> file.
> That's specifically annoying when bitbake is under the control of a
> frontend process such as kas.

Hi,

Could you check if this was already fixed by:

http://git.yoctoproject.org/cgit.cgi/poky/commit/?id=cbe2d3cb0af6c7a5cd368e7dc489960a13648bd0

?

I really want to get these flushes as close to the source of the
problems as we can.

Cheers,

Richard

Re: [PATCH] process: Flush server stdout/stderr before reporting failure

[Richard Purdie]

On Tue, 2018-09-04 at 13:15 +0100, Richard Purdie wrote:
> On Sun, 2018-09-02 at 10:43 +0200, Jan Kiszka wrote:
> > We need to print exceptions and flush output channels before
> > telling
> > the
> > client that the server failed. Otherwise the daemon log file may
> > still
> > be empty when the client opens it for printing.
> > 
> > This fixes error reporting when the output is redirected to a pipe,
> > e.g.
> > "bitbake target | cat" with a syntax error in a recipes or config
> > file.
> > That's specifically annoying when bitbake is under the control of a
> > frontend process such as kas.
> 
> Hi,
> 
> Could you check if this was already fixed by:
> 
> http://git.yoctoproject.org/cgit.cgi/poky/commit/?id=cbe2d3cb0af6c7a5
> cd368e7dc489960a13648bd0
> 
> ?
> 
> I really want to get these flushes as close to the source of the
> problems as we can.

Looking at the code further, I suspect we should simply be doing:

        writer = ConnectionWriter(self.readypipein)
        self.cooker = bb.cooker.BBCooker(self.configuration, self.featureset)
        writer.send("ready")
        os.close(self.readypipein)
        server.cooker = self.cooker

with no exception handling. The ready pipe would then get closed by the
os._exit() in daemonize which is after the flush. It simplifies the
code as an added bonus...

Cheers,

Richard

Re: [PATCH] process: Flush server stdout/stderr before reporting failure

[Jan Kiszka]

On 2018-09-04 14:34, Richard Purdie wrote:
> On Tue, 2018-09-04 at 13:15 +0100, Richard Purdie wrote:
>> On Sun, 2018-09-02 at 10:43 +0200, Jan Kiszka wrote:
>>> We need to print exceptions and flush output channels before
>>> telling
>>> the
>>> client that the server failed. Otherwise the daemon log file may
>>> still
>>> be empty when the client opens it for printing.
>>>
>>> This fixes error reporting when the output is redirected to a pipe,
>>> e.g.
>>> "bitbake target | cat" with a syntax error in a recipes or config
>>> file.
>>> That's specifically annoying when bitbake is under the control of a
>>> frontend process such as kas.
>>
>> Hi,
>>
>> Could you check if this was already fixed by:
>>
>> http://git.yoctoproject.org/cgit.cgi/poky/commit/?id=cbe2d3cb0af6c7a5
>> cd368e7dc489960a13648bd0

Looks similar on first glance, but it only partly helps with exceptions. 
We get from

$ bitbake | cat
ERROR: Unable to start bitbake server

to

$ bitbake | cat
ERROR: Unable to start bitbake server
ERROR: Server log for this session (/work/build/bitbake-cookerdaemon.log):
--- Starting bitbake server pid 149 at 2018-09-04 13:02:15.144583 ---

while it should have

$ bitbake
ERROR: Unable to start bitbake server
ERROR: Last 10 lines of server log for this session 
(/work/build/bitbake-cookerdaemon.log):
Traceback (most recent call last):
   File "/work/isar/bitbake/lib/bb/daemonize.py", line 77, in createDaemon
     function()
   File "/work/isar/bitbake/lib/bb/server/process.py", line 433, in 
_startServer
     self.cooker = bb.cooker.BBCooker(self.configuration, self.featureset)
   File "/work/isar/bitbake/lib/bb/cooker.py", line 178, in __init__
     self.configwatcher = pyinotify.WatchManager()
   File "/work/isar/bitbake/lib/pyinotify.py", line 1764, in __init__
     raise OSError(err % self._inotify_wrapper.str_errno())
OSError: Cannot initialize new instance of inotify, Errno=Too many open 
files (EMFILE)

>>
>> ?
>>
>> I really want to get these flushes as close to the source of the
>> problems as we can.
> 
> Looking at the code further, I suspect we should simply be doing:
> 
>          writer = ConnectionWriter(self.readypipein)
>          self.cooker = bb.cooker.BBCooker(self.configuration, self.featureset)
>          writer.send("ready")
>          os.close(self.readypipein)
>          server.cooker = self.cooker
> 
> with no exception handling. The ready pipe would then get closed by the
> os._exit() in daemonize which is after the flush. It simplifies the
> code as an added bonus...

Tried that, but it does not work that way, it just hangs.

As I wrote, the test case is trivial: just direct the output of bitbake 
into a pipe (bitbake | cat).

Jan

Re: [PATCH] process: Flush server stdout/stderr before reporting failure

[richard.purdie]

On Tue, 2018-09-04 at 15:09 +0200, Jan Kiszka wrote:
> Looks similar on first glance, but it only partly helps with
> exceptions. 
> We get from
> 
> $ bitbake | cat
> ERROR: Unable to start bitbake server
> 
> to
> 
> $ bitbake | cat
> ERROR: Unable to start bitbake server
> ERROR: Server log for this session (/work/build/bitbake-
> cookerdaemon.log):
> --- Starting bitbake server pid 149 at 2018-09-04 13:02:15.144583 ---
> 
> while it should have
> 
> $ bitbake
> ERROR: Unable to start bitbake server
> ERROR: Last 10 lines of server log for this session 
> (/work/build/bitbake-cookerdaemon.log):
> Traceback (most recent call last):
>    File "/work/isar/bitbake/lib/bb/daemonize.py", line 77, in
> createDaemon
>      function()
>    File "/work/isar/bitbake/lib/bb/server/process.py", line 433, in 
> _startServer
>      self.cooker = bb.cooker.BBCooker(self.configuration,
> self.featureset)
>    File "/work/isar/bitbake/lib/bb/cooker.py", line 178, in __init__
>      self.configwatcher = pyinotify.WatchManager()
>    File "/work/isar/bitbake/lib/pyinotify.py", line 1764, in __init__
>      raise OSError(err % self._inotify_wrapper.str_errno())
> OSError: Cannot initialize new instance of inotify, Errno=Too many
> open 
> files (EMFILE)

The more I looked into this the more problems I found. I've put this in
for some testing which should address the issues:

http://git.yoctoproject.org/cgit.cgi/poky/commit/?h=master-next&id=dae574dd680f4f9db0b1447266742fa127963842

Cheers,

Richard

Re: [PATCH] process: Flush server stdout/stderr before reporting failure

[Jan Kiszka]

On 2018-09-05 02:14, richard.purdie@linuxfoundation.org wrote:
> On Tue, 2018-09-04 at 15:09 +0200, Jan Kiszka wrote:
>> Looks similar on first glance, but it only partly helps with
>> exceptions.
>> We get from
>>
>> $ bitbake | cat
>> ERROR: Unable to start bitbake server
>>
>> to
>>
>> $ bitbake | cat
>> ERROR: Unable to start bitbake server
>> ERROR: Server log for this session (/work/build/bitbake-
>> cookerdaemon.log):
>> --- Starting bitbake server pid 149 at 2018-09-04 13:02:15.144583 ---
>>
>> while it should have
>>
>> $ bitbake
>> ERROR: Unable to start bitbake server
>> ERROR: Last 10 lines of server log for this session
>> (/work/build/bitbake-cookerdaemon.log):
>> Traceback (most recent call last):
>>     File "/work/isar/bitbake/lib/bb/daemonize.py", line 77, in
>> createDaemon
>>       function()
>>     File "/work/isar/bitbake/lib/bb/server/process.py", line 433, in
>> _startServer
>>       self.cooker = bb.cooker.BBCooker(self.configuration,
>> self.featureset)
>>     File "/work/isar/bitbake/lib/bb/cooker.py", line 178, in __init__
>>       self.configwatcher = pyinotify.WatchManager()
>>     File "/work/isar/bitbake/lib/pyinotify.py", line 1764, in __init__
>>       raise OSError(err % self._inotify_wrapper.str_errno())
>> OSError: Cannot initialize new instance of inotify, Errno=Too many
>> open
>> files (EMFILE)
> 
> The more I looked into this the more problems I found. I've put this in
> for some testing which should address the issues:
> 
> http://git.yoctoproject.org/cgit.cgi/poky/commit/?h=master-next&id=dae574dd680f4f9db0b1447266742fa127963842
> 

Yep, it does here as well!

Thanks,
Jan

-- 
Siemens AG, Corporate Technology, CT RDA IOT SES-DE
Corporate Competence Center Embedded Linux