[PATCH 1/2] libkas: Consolidate and refactor error reporting of run_cmd*

[Jan Kiszka]

From: Jan Kiszka <jan.k...@siemens.com>

While run_cmd_async was dumping stderr on fail=True, run_cmd was not.
This aligns both which specifically helps debugging failing
init-build-env scripts.

It furthermore avoids duplicate reporting of the failing command,
dropping the explicit output in favor of the one via CommandExecError.

And it makes the error dump more compact. Error reports are already
clearly marked by not carrying the prefixes of kas-generated outputs.

Closes #166
Signed-off-by: Jan Kiszka <jan.k...@siemens.com>
---
kas/libkas.py | 17 +++++++++--------
1 file changed, 9 insertions(+), 8 deletions(-)

diff --git a/kas/libkas.py b/kas/libkas.py
index 89113fa..37dcb3f 100644
--- a/kas/libkas.py
+++ b/kas/libkas.py
@@ -116,6 +116,13 @@ def _filter_stderr(capture_stderr, ret, out, err=None):
return (ret, out)


+def _report_cmd_error(ret, cmd, stderr):
+ if stderr:
+ msg = f'Command execution failed, error output:\n{stderr}'
+ logging.error(msg.rstrip('\n'))
+ raise CommandExecError(cmd, ret)
+
+
async def run_cmd_async(cmd, cwd, env=None, fail=True, liveupdate=False,
capture_stderr=False):
"""
@@ -170,13 +177,7 @@ async def run_cmd_async(cmd, cwd, env=None, fail=True, liveupdate=False,
raise

if ret and fail:
- msg = f'Command "{cwd}$ {cmdstr}" failed'
- if logo.stderr:
- msg += '\n--- Error summary ---\n'
- for line in logo.stderr:
- msg += line
- logging.error(msg)
- raise CommandExecError(cmd, ret)
+ _report_cmd_error(ret, cmd, logo.stderr)

return _filter_stderr(capture_stderr, ret,
''.join(logo.stdout), ''.join(logo.stderr))
@@ -193,7 +194,7 @@ def run_cmd(cmd, cwd, env=None, fail=True, capture_stderr=False):
try:
ret = subprocess_run(cmd, env=env, cwd=cwd, stdout=PIPE, stderr=PIPE)
if ret.returncode and fail:
- raise CommandExecError(cmd, ret.returncode)
+ _report_cmd_error(ret.returncode, cmd, ret.stderr.decode('utf-8'))
except FileNotFoundError as ex:
if fail:
raise ex
--
2.51.0

[Jan Kiszka]

From: Jan Kiszka <jan.k...@siemens.com>

This allows to inspect the output of the oe/isar-init-build-env scripts
when turning on debug log-level which can be helpful for analyzing the
proper script behavior.

Closes #166
Signed-off-by: Jan Kiszka <jan.k...@siemens.com>
---

kas/libkas.py | 12 +++++++++++-
1 file changed, 11 insertions(+), 1 deletion(-)

diff --git a/kas/libkas.py b/kas/libkas.py
index 37dcb3f..29e902a 100644
--- a/kas/libkas.py
+++ b/kas/libkas.py
@@ -290,9 +290,13 @@ def get_build_environ(build_system):
raise InitBuildEnvError('Did not find any init-build-env script')

with tempfile.TemporaryDirectory() as temp_dir:
+ if logging.getLogger().getEffectiveLevel() == logging.DEBUG:
+ init_script_log = pathlib.Path(temp_dir) / '.init_script.log'
+ else:
+ init_script_log = '/dev/null'
script = f"""#!/bin/bash
set -e
- source {init_script} $1 > /dev/null
+ source {init_script} $1 > {init_script_log}
env
"""

@@ -305,6 +309,12 @@ def get_build_environ(build_system):

(_, output) = run_cmd([str(get_bb_env_file), get_context().build_dir],
cwd=init_repo.path, env=env)
+ if init_script_log != '/dev/null':
+ with open(init_script_log) as log:
+ msg = f'{init_script} output:\n'
+ for line in log.readlines():
+ msg += line
+ logging.debug(msg.rstrip('\n'))

env = {}
for line in output.splitlines():
--
2.51.0

[Felix Moessbauer]

Hi, why not simply extend the CommandExecError Exception with an
optional parameter "stderr" and set it accordingly? By that, we could
avoid the helper function and pass the error to the callers error handler.

Apart from that, the change is fine.

Felix

Siemens AG
Linux Expert Center
Friedrich-Ludwig-Bauer-Str. 3
85748 Garching, Germany

[Felix Moessbauer]

Please just use "init_script_log.is_file()", which is false for pseudo
files like /dev/null.

Felix

> + with open(init_script_log) as log:
> + msg = f'{init_script} output:\n'
> + for line in log.readlines():
> + msg += line
> + logging.debug(msg.rstrip('\n'))
>
> env = {}
> for line in output.splitlines():

--

[Jan Kiszka]

I don't see any value for this complication, specifically as it is
non-obvious on first glance.

Jan

--
Siemens AG, Foundational Technologies
Linux Expert Center

[Jan Kiszka]

Some CommandExecErrors are actually caught and converted into
TaskExecErrors or just plan error codes. In that light, we may not want
to drop the heading command name reporting. I will send a v2 for this,
just to be safe to now swallow too much.

Jan

[Jan Kiszka]

From: Jan Kiszka <jan.k...@siemens.com>

While run_cmd_async was dumping stderr on fail=True, run_cmd was not.
This aligns both which specifically helps debugging failing
init-build-env scripts.

It furthermore makes the error dump more compact. Error reports are

already clearly marked by not carrying the prefixes of kas-generated
outputs.

Closes #166
Signed-off-by: Jan Kiszka <jan.k...@siemens.com>
---

Changes in v2:
- keep the header line as CommandExecError may be caught and
differently reported in some cases
- move cmdstr generation around to avoid needless execution

kas/libkas.py | 21 ++++++++++++---------
1 file changed, 12 insertions(+), 9 deletions(-)

diff --git a/kas/libkas.py b/kas/libkas.py
index 89113fa..95afd20 100644
--- a/kas/libkas.py
+++ b/kas/libkas.py
@@ -116,6 +116,14 @@ def _filter_stderr(capture_stderr, ret, out, err=None):
return (ret, out)


+def _report_cmd_error(ret, cwd, cmd, stderr):
+ if stderr:
+ cmdstr = ' '.join(cmd)
+ msg = f'Command "{cwd}$ {cmdstr}" failed:\n{stderr}'

+ logging.error(msg.rstrip('\n'))
+ raise CommandExecError(cmd, ret)
+
+

async def run_cmd_async(cmd, cwd, env=None, fail=True, liveupdate=False,
capture_stderr=False):
"""

@@ -123,7 +131,6 @@ async def run_cmd_async(cmd, cwd, env=None, fail=True, liveupdate=False,
"""

env = env or get_context().environ
- cmdstr = ' '.join(cmd)
logging.debug('%s$ %s', cwd, cmdstr)

logo = LogOutput(liveupdate)
@@ -165,18 +172,13 @@ async def run_cmd_async(cmd, cwd, env=None, fail=True, liveupdate=False,
ret = await asyncio.shield(process.wait())
except asyncio.CancelledError:
process.terminate()
+ cmdstr = ' '.join(cmd)
logging.debug('Command "%s" cancelled', cmdstr)
await process.wait()

raise

if ret and fail:
- msg = f'Command "{cwd}$ {cmdstr}" failed'
- if logo.stderr:
- msg += '\n--- Error summary ---\n'
- for line in logo.stderr:
- msg += line
- logging.error(msg)
- raise CommandExecError(cmd, ret)

+ _report_cmd_error(ret, cwd, cmd, logo.stderr)

return _filter_stderr(capture_stderr, ret,
''.join(logo.stdout), ''.join(logo.stderr))

@@ -193,7 +195,8 @@ def run_cmd(cmd, cwd, env=None, fail=True, capture_stderr=False):

try:
ret = subprocess_run(cmd, env=env, cwd=cwd, stdout=PIPE, stderr=PIPE)
if ret.returncode and fail:
- raise CommandExecError(cmd, ret.returncode)

+ _report_cmd_error(ret.returncode, cwd, cmd,
+ ret.stderr.decode('utf-8'))

except FileNotFoundError as ex:
if fail:
raise ex
--

2.51.0

[Jan Kiszka]

From: Jan Kiszka <jan.k...@siemens.com>

While run_cmd_async was dumping stderr on fail=True, run_cmd was not.
This aligns both which specifically helps debugging failing
init-build-env scripts.

It furthermore makes the error dump more compact. Error reports are
already clearly marked by not carrying the prefixes of kas-generated
outputs.

Closes #166
Signed-off-by: Jan Kiszka <jan.k...@siemens.com>
---

Changes in v3:
- do not move cmdstr assignment around - miss one unconditional user -,
rather pass it do _report_cmd_error

kas/libkas.py | 18 ++++++++++--------
1 file changed, 10 insertions(+), 8 deletions(-)

diff --git a/kas/libkas.py b/kas/libkas.py
index 89113fa..36fc391 100644
--- a/kas/libkas.py
+++ b/kas/libkas.py
@@ -116,6 +116,13 @@ def _filter_stderr(capture_stderr, ret, out, err=None):
return (ret, out)


+def _report_cmd_error(ret, cwd, cmdstr, cmd, stderr):
+ if stderr:

+ msg = f'Command "{cwd}$ {cmdstr}" failed:\n{stderr}'
+ logging.error(msg.rstrip('\n'))
+ raise CommandExecError(cmd, ret)
+
+
async def run_cmd_async(cmd, cwd, env=None, fail=True, liveupdate=False,
capture_stderr=False):
"""

@@ -170,13 +177,7 @@ async def run_cmd_async(cmd, cwd, env=None, fail=True, liveupdate=False,

raise

if ret and fail:
- msg = f'Command "{cwd}$ {cmdstr}" failed'
- if logo.stderr:
- msg += '\n--- Error summary ---\n'
- for line in logo.stderr:
- msg += line
- logging.error(msg)
- raise CommandExecError(cmd, ret)

+ _report_cmd_error(ret, cwd, cmdstr, cmd, logo.stderr)

return _filter_stderr(capture_stderr, ret,
''.join(logo.stdout), ''.join(logo.stderr))

@@ -193,7 +194,8 @@ def run_cmd(cmd, cwd, env=None, fail=True, capture_stderr=False):

try:
ret = subprocess_run(cmd, env=env, cwd=cwd, stdout=PIPE, stderr=PIPE)
if ret.returncode and fail:
- raise CommandExecError(cmd, ret.returncode)

+ _report_cmd_error(ret.returncode, cwd, cmdstr, cmd,