[PATCH 2/6] only control log-level via arg if not running under pytest

[Felix Moessbauer]

The pytest test executor has its own mechanism to set the log level
which directly integrates with the logging module. Currently this does
not work, because we explicitly set the log level. We restore this
functionality by not setting it if running under pytest.

Signed-off-by: Felix Moessbauer <felix.mo...@siemens.com>
---
kas/kas.py | 5 +++--
1 file changed, 3 insertions(+), 2 deletions(-)

diff --git a/kas/kas.py b/kas/kas.py
index 9440e34b1..635247401 100644
--- a/kas/kas.py
+++ b/kas/kas.py
@@ -63,7 +63,8 @@ def create_logger():
Setup the logging environment
"""
log = logging.getLogger() # root logger
- log.setLevel(DEFAULT_LOG_LEVEL.upper())
+ if not is_pytest():
+ log.setLevel(DEFAULT_LOG_LEVEL.upper())
format_str = '%(asctime)s - %(levelname)-8s - %(message)s'
date_format = '%Y-%m-%d %H:%M:%S'
if HAVE_COLORLOG and os.isatty(2):
@@ -185,7 +186,7 @@ def kas(argv):
parser = kas_get_argparser()
args = parser.parse_args(argv)

- if args.log_level:
+ if not is_pytest() and args.log_level:
logging.getLogger().setLevel(args.log_level.upper())

logging.info('%s %s started', os.path.basename(sys.argv[0]), __version__)
--
2.51.0

[Felix Moessbauer]

As discovered in [1], we currently do not correctly detect some errors
during repo fetching. While fixing this, I further noticed the following:

- incorrect assumption about return codes (fetch_async reports errors
via return codes, but no one ever checked these)
- the interaction with the event loop is not correct, as transitive
exceptions might be thrown in a shutdown context (detected by adding
a fetch-fail test). Note, that this was hidden by testing the
cancellation either on small tests with single tasks, or manually via
CTRL-C which transitively cancels all tasks.

This series fixes all this, by first improving the debugging under pytest,
then fixing the event loop inconsistencies and finally fixing the reported
bug. A nice side effect is, that now kas returns much more quickly in case
one of its tasks raises. Before that, all tasks were still run to
completion if an exception occurred.

PS: Did I already mention, that event loops in Python are hell?

[1] https://github.com/siemens/kas/issues/168

Best regards,
Felix

Felix Moessbauer (6):
refactor: add function to check if running under pytest
only control log-level via arg if not running under pytest
fix: do not raise on task exceptions in shutdown cleanup
fix: cancel pending tasks on exception
fix(repos): raise on fetching errors
test: add test for failed fetching of repos

kas/kas.py | 23 ++++++++++++++++++-----
kas/libkas.py | 14 +++++++++++++-
kas/repos.py | 20 ++++++++++++++------
tests/test_commands.py | 10 ++++++++++
4 files changed, 55 insertions(+), 12 deletions(-)

--
2.51.0

[Felix Moessbauer]

When shutting down the event loop, we are already in a termination
context. In this context, we must not raise any exceptions to not
interact with the event loop again. Otherwise the eventloop is not shut
down properly leading to exceptions thrown in non-raisable contexts.

Handling these exceptions is anyways not needed, as the root cause for
the cancellation (an exception) is already handled in the main execution
of the event loop.

Fixes: f4beea37f ("graceful cancellation of external commands")

Signed-off-by: Felix Moessbauer <felix.mo...@siemens.com>
---

kas/kas.py | 9 +++++++--
1 file changed, 7 insertions(+), 2 deletions(-)

diff --git a/kas/kas.py b/kas/kas.py
index 635247401..8244c8c21 100644
--- a/kas/kas.py
+++ b/kas/kas.py
@@ -117,10 +117,15 @@ def termination():

def shutdown_loop(loop):
"""
- Waits for completion of the event loop
+ Waits for completion of the event loop but ignores any exceptions.
+ The tasks are either already cancelled or will be transitively
+ cancelled shortly. As this is the final cleanup, we cannot check for
+ exceptions as these might lead in an unclosed event loops.
"""
pending = asyncio.all_tasks(loop)
- loop.run_until_complete(asyncio.gather(*pending))
+ if len(pending):
+ logging.debug("Cleanup %d remaining tasks", len(pending))
+ loop.run_until_complete(asyncio.gather(*pending, return_exceptions=True))
loop.close()


--
2.51.0

[Felix Moessbauer]

We currently only warn in case the fetching fails. However, we must not
continue as otherwise kas assumes the repo is up-to-date and passes
incorrect data to downstream consumers (like dump, lock). Before the
introduction of the dump / lock command, this was merely an annoyance as
the checkout did not match the upstream state. With the consumers, it is
a bug.

While changing this, we also remove all error-code returns in that
function which never have been checked for anyways.

Fixes: daf0abab5 ("Initial public release")
Closes: #168

Signed-off-by: Felix Moessbauer <felix.mo...@siemens.com>
---

kas/repos.py | 20 ++++++++++++++------
1 file changed, 14 insertions(+), 6 deletions(-)

diff --git a/kas/repos.py b/kas/repos.py
index 187f94305..c40158582 100644
--- a/kas/repos.py
+++ b/kas/repos.py
@@ -83,6 +83,14 @@ class PatchApplyError(KasUserError):
super().__init__(msg)


+class RepoFetchError(KasUserError):
+ """
+ An error occurred during repo fetching
+ """
+ def __init__(self, repo, output):
+ super().__init__(f'Fetching of repo: "{repo.name}" failed: {output}')
+
+
class Repo:
"""
Represents a repository in the kas configuration.
@@ -361,9 +369,8 @@ class RepoImpl(Repo):
"""
Starts asynchronous repository fetch.
"""
-
if self.operations_disabled:
- return 0
+ return

refdir = get_context().kas_repo_ref_dir
sdir = os.path.join(refdir, self.qualified_name) if refdir else None
@@ -404,7 +411,7 @@ class RepoImpl(Repo):
# take what came out of clone and stick to that forever
if self.commit is None and self.tag is None and self.branch is None \
and self.refspec is None:
- return 0
+ return

if not get_context().update:
# Do commit/tag/branch/refspec exist in the current repository?
@@ -424,9 +431,9 @@ class RepoImpl(Repo):
(_, output) = await run_cmd_async(
self.branch_contains_ref(), cwd=self.path, fail=False)
if output.strip():
- return retc
+ return
else:
- return retc
+ return

# Try to fetch if commit/tag/branch/refspec is missing or if --update
# argument was passed
@@ -436,9 +443,10 @@ class RepoImpl(Repo):
if retc:
logging.warning('Could not update repository %s: %s',
self.name, output)
+ raise RepoFetchError(self, output)
else:
logging.info('Repository %s updated', self.name)
- return 0
+ return

def checkout(self):
"""
--
2.51.0

[Felix Moessbauer]

In case one task raises an exception that is not ignore-handled, we must
cancel all other tasks as well. Otherwise it takes quite long until the
overall execution finishes.

Fixes: f4beea37f ("graceful cancellation of external commands")

Signed-off-by: Felix Moessbauer <felix.mo...@siemens.com>
---

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

diff --git a/kas/libkas.py b/kas/libkas.py
index ee587eb04..801134f42 100644
--- a/kas/libkas.py
+++ b/kas/libkas.py
@@ -178,7 +178,11 @@ async def run_cmd_async(cmd, cwd, env=None, fail=True, liveupdate=False,
await asyncio.gather(*[asyncio.shield(t) for t in tasks])
ret = await asyncio.shield(process.wait())
except asyncio.CancelledError:
- process.terminate()
+ try:
+ process.terminate()
+ except ProcessLookupError:
+ # Process already exited between the cancel and us reaching here.
+ pass
logging.debug('Command "%s" cancelled', cmdstr)
await process.wait()
raise
@@ -244,7 +248,11 @@ def repos_fetch(repos):
try:
loop.run_until_complete(asyncio.gather(*tasks))
except CommandExecError as e:
+ [t.cancel() for t in tasks]
raise TaskExecError('fetch repos', e.ret_code)
+ except KasUserError:
+ [t.cancel() for t in tasks]
+ raise


def repos_apply_patches(repos):
@@ -264,7 +272,11 @@ def repos_apply_patches(repos):
try:
loop.run_until_complete(asyncio.gather(*tasks))
except CommandExecError as e:
+ [t.cancel() for t in tasks]
raise TaskExecError('apply patches', e.ret_code)
+ except KasUserError:
+ [t.cancel() for t in tasks]
+ raise


def get_buildtools_dir():
--
2.51.0

[Felix Moessbauer]

We currently only test the good case of fetching repos, however we also
need to test the error path. We add a check for that as well by mocking
the fetch_cmd implementation of a GitRepo.

Signed-off-by: Felix Moessbauer <felix.mo...@siemens.com>
---

tests/test_commands.py | 10 ++++++++++
1 file changed, 10 insertions(+)

diff --git a/tests/test_commands.py b/tests/test_commands.py
index cfc0a6b99..d269b8131 100644
--- a/tests/test_commands.py
+++ b/tests/test_commands.py
@@ -31,6 +31,7 @@ import pytest
from kas import kas
from kas.libkas import TaskExecError, KasUserError, run_cmd
from kas.attestation import file_digest_slow
+from kas.repos import RepoFetchError


@pytest.mark.dirsfromenv
@@ -82,6 +83,15 @@ def test_checkout(monkeykas, tmpdir):
assert not (kas_bd / 'downloads').exists()
assert not (kas_bd / 'sstate-cache').exists()

+ # test re-fetching
+ kas.kas(['checkout', '--update', 'test.yml'])
+
+ with monkeykas.context() as mc:
+ from kas.repos import GitRepo
+ mc.setattr(GitRepo, "fetch_cmd", lambda _: ["false"])
+ with pytest.raises(RepoFetchError):
+ kas.kas(['checkout', '--update', 'test.yml'])
+

def test_invalid_checkout(monkeykas, tmpdir, capsys):
tdir = str(tmpdir / 'test_commands')
--
2.51.0

[Jan Kiszka]

On 01.10.25 12:21, Felix Moessbauer wrote:
> We currently only warn in case the fetching fails. However, we must not
> continue as otherwise kas assumes the repo is up-to-date and passes
> incorrect data to downstream consumers (like dump, lock). Before the
> introduction of the dump / lock command, this was merely an annoyance as
> the checkout did not match the upstream state. With the consumers, it is
> a bug.
>
> While changing this, we also remove all error-code returns in that
> function which never have been checked for anyways.

Please split this off.

Then the warning above is no longer a warning - it's now an error.

> else:
> logging.info('Repository %s updated', self.name)
> - return 0
> + return

No longer needed statement then.

>
> def checkout(self):
> """

Jan

--
Siemens AG, Foundational Technologies
Linux Expert Center

[Jan Kiszka]

On 01.10.25 12:20, Felix Moessbauer wrote:
> In case one task raises an exception that is not ignore-handled, we must
> cancel all other tasks as well. Otherwise it takes quite long until the
> overall execution finishes.
>
> Fixes: f4beea37f ("graceful cancellation of external commands")

Strictly spoken, this here is an optimization... anyway.

Jan

[Jan Kiszka]

On 01.10.25 12:20, Felix Moessbauer wrote:

Patch 3 and 4 already applied, thanks.

Jan

[Felix Moessbauer]

Changes since v1:

- rebased onto next
- replace pytest specifics in kas with monkeypatch
- split repo fetch fix from unrelated return code cleanup
- adapt checkout test to changes needed after 021e961be

As discovered in [1], we currently do not correctly detect some errors
during repo fetching. While fixing this, I further noticed the following:

- incorrect assumption about return codes (fetch_async reports errors
via return codes, but no one ever checked these)
- the interaction with the event loop is not correct, as transitive
exceptions might be thrown in a shutdown context (detected by adding
a fetch-fail test). Note, that this was hidden by testing the
cancellation either on small tests with single tasks, or manually via
CTRL-C which transitively cancels all tasks.

This series fixes all this, by first improving the debugging under pytest,
then fixing the event loop inconsistencies and finally fixing the reported
bug. A nice side effect is, that now kas returns much more quickly in case
one of its tasks raises. Before that, all tasks were still run to
completion if an exception occurred.

PS: Did I already mention, that event loops in Python are hell?

[1] https://github.com/siemens/kas/issues/168

Best regards,
Felix

Felix Moessbauer (6):

refactor: move registration of signal handlers to function
refactor: move setting of log level to function
refactor: use monkeypatch to patch global kas logic
refactor(repo): remove useless return codes

fix(repos): raise on fetching errors
test: add test for failed fetching of repos

kas/kas.py | 27 ++++++++++++++++++++-------
kas/repos.py | 22 +++++++++++++++-------
tests/conftest.py | 23 +++++++++++++++++++++++
tests/test_commands.py | 16 ++++++++++++++++
4 files changed, 74 insertions(+), 14 deletions(-)

--
2.51.0

[Felix Moessbauer]

By that, we can later monkey patch this function to avoid pytest
specific code in the official deployment.

Signed-off-by: Felix Moessbauer <felix.mo...@siemens.com>
---

kas/kas.py | 17 ++++++++++++-----
1 file changed, 12 insertions(+), 5 deletions(-)

diff --git a/kas/kas.py b/kas/kas.py
index 1598ae582..fc129ee45 100644
--- a/kas/kas.py
+++ b/kas/kas.py
@@ -85,6 +85,17 @@ def cleanup_logger():
logging.root.removeHandler(handler)


+def register_signal_handlers(loop):
+ """
+ Register the signal handlers which should be handled by the
+ event loop. Implemented as function to monkey-patch it out in tests.
+ """
+ loop.add_signal_handler(signal.SIGTERM, interruption)
+ # don't overwrite pytest's signal handler
+ if "PYTEST_CURRENT_TEST" not in os.environ:
+ loop.add_signal_handler(signal.SIGINT, interruption)
+
+
def interruption():
"""
Gracefully cancel all tasks in the event loop
@@ -190,11 +201,7 @@ def kas(argv):

loop = asyncio.new_event_loop()
asyncio.set_event_loop(loop)
-
- loop.add_signal_handler(signal.SIGTERM, interruption)
- # don't overwrite pytest's signal handler
- if "PYTEST_CURRENT_TEST" not in os.environ:
- loop.add_signal_handler(signal.SIGINT, interruption)
+ register_signal_handlers(loop)

try:
plugin_class = plugins.get(args.cmd)
--
2.51.0

[Felix Moessbauer]

By that, we can later patch it out when running under pytest.

The pytest test executor has its own mechanism to set the log level
which directly integrates with the logging module. Currently this does
not work, because we explicitly set the log level.

Signed-off-by: Felix Moessbauer <felix.mo...@siemens.com>
---

kas/kas.py | 12 ++++++++++--
1 file changed, 10 insertions(+), 2 deletions(-)

diff --git a/kas/kas.py b/kas/kas.py
index fc129ee45..3fbd89a39 100644
--- a/kas/kas.py
+++ b/kas/kas.py
@@ -56,7 +56,7 @@ def create_logger():

Setup the logging environment
"""
log = logging.getLogger() # root logger
- log.setLevel(DEFAULT_LOG_LEVEL.upper())

+ set_global_loglevel(DEFAULT_LOG_LEVEL.upper())

format_str = '%(asctime)s - %(levelname)-8s - %(message)s'
date_format = '%Y-%m-%d %H:%M:%S'
if HAVE_COLORLOG and os.isatty(2):

@@ -85,6 +85,14 @@ def cleanup_logger():
logging.root.removeHandler(handler)


+def set_global_loglevel(level):
+ """
+ Configure the global log level.
+ Implemented as function to monkey-patch it out in tests.
+ """
+ logging.getLogger().setLevel(level)
+
+
def register_signal_handlers(loop):

"""
Register the signal handlers which should be handled by the

@@ -195,7 +203,7 @@ def kas(argv):
args = parser.parse_args(argv)

if args.log_level:
- logging.getLogger().setLevel(args.log_level.upper())
+ set_global_loglevel(args.log_level.upper())

[Felix Moessbauer]

kas changes some logic globally for the whole program, which interferes
with the execution of pytest. Instead of letting kas detect that it is
running under pytest, we use monkeypatch to patch the related functions.

By that, we do not need to have pytest specific code in kas.

Signed-off-by: Felix Moessbauer <felix.mo...@siemens.com>
---

kas/kas.py | 4 +---
tests/conftest.py | 23 +++++++++++++++++++++++
2 files changed, 24 insertions(+), 3 deletions(-)

diff --git a/kas/kas.py b/kas/kas.py
index 3fbd89a39..d83c93ec1 100644
--- a/kas/kas.py
+++ b/kas/kas.py
@@ -99,9 +99,7 @@ def register_signal_handlers(loop):
event loop. Implemented as function to monkey-patch it out in tests.

"""
loop.add_signal_handler(signal.SIGTERM, interruption)
- # don't overwrite pytest's signal handler
- if "PYTEST_CURRENT_TEST" not in os.environ:
- loop.add_signal_handler(signal.SIGINT, interruption)

+ loop.add_signal_handler(signal.SIGINT, interruption)


def interruption():
diff --git a/tests/conftest.py b/tests/conftest.py
index 5fd4e3efe..4092d5112 100644
--- a/tests/conftest.py
+++ b/tests/conftest.py
@@ -20,12 +20,15 @@
# OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE
# SOFTWARE.

+import signal
import pytest
import os
import subprocess
import shutil
from pathlib import Path

+from kas import kas
+
ENVVARS_KAS = [
'KAS_WORK_DIR',
'KAS_BUILD_DIR',
@@ -83,6 +86,26 @@ def pytest_generate_tests(metafunc):
indirect=True)


+...@pytest.fixture(autouse=True)
+def prepare_kas_for_tests(monkeypatch):
+ """
+ Patch-out some global logic kas modifies. The strategy is as
+ following: kas implements the problematic parts as dedicated
+ functions which we monkeypatch here.
+ """
+ def _register_signal_handlers(loop):
+ loop.add_signal_handler(signal.SIGTERM, kas.interruption)
+ # do not handle signal.SIGINT
+
+ def _set_global_loglevel(level):
+ # do not set global log level as this is handled by pytest
+ pass
+
+ monkeypatch.setattr(kas, "register_signal_handlers",
+ _register_signal_handlers)
+ monkeypatch.setattr(kas, "set_global_loglevel", _set_global_loglevel)
+
+
@pytest.fixture()
def monkeykas(request, monkeypatch, tmpdir):
def get_kas_work_dir():
--
2.51.0

[Felix Moessbauer]

The fetch_async function returns the underlying command return codes to
the caller. However, the caller has never checked for these. As the
error checking is anyways based on exceptions, we just remove the return
codes.

Signed-off-by: Felix Moessbauer <felix.mo...@siemens.com>
---

kas/repos.py | 9 ++++-----
1 file changed, 4 insertions(+), 5 deletions(-)

diff --git a/kas/repos.py b/kas/repos.py
index 4b6ff440f..d2b92d08e 100644
--- a/kas/repos.py
+++ b/kas/repos.py
@@ -363,7 +363,7 @@ class RepoImpl(Repo):

"""

if self.operations_disabled:
- return 0
+ return

refdir = get_context().kas_repo_ref_dir
sdir = os.path.join(refdir, self.qualified_name) if refdir else None

@@ -404,7 +404,7 @@ class RepoImpl(Repo):

# take what came out of clone and stick to that forever
if self.commit is None and self.tag is None and self.branch is None \
and self.refspec is None:
- return 0
+ return

# check if we already have the commit. On update, check as well in case
# the commit is fixed, hence the repo must not be updated anyways
@@ -427,9 +427,9 @@ class RepoImpl(Repo):

(_, output) = await run_cmd_async(
self.branch_contains_ref(), cwd=self.path, fail=False)
if output.strip():
- return retc
+ return
else:
- return retc
+ return

# Try to fetch if commit/tag/branch/refspec is missing or if --update
# argument was passed

@@ -441,7 +441,6 @@ class RepoImpl(Repo):
self.name, output)

else:
logging.info('Repository %s updated', self.name)
- return 0

def checkout(self):
"""
--
2.51.0

[Felix Moessbauer]

We currently only warn in case the fetching fails. However, we must not
continue as otherwise kas assumes the repo is up-to-date and passes
incorrect data to downstream consumers (like dump, lock). Before the
introduction of the dump / lock command, this was merely an annoyance as
the checkout did not match the upstream state. With the consumers, it is
a bug.

Fixes: daf0abab5 ("Initial public release")
Closes: #168

Signed-off-by: Felix Moessbauer <felix.mo...@siemens.com>
---

kas/repos.py | 13 +++++++++++--
1 file changed, 11 insertions(+), 2 deletions(-)

diff --git a/kas/repos.py b/kas/repos.py
index d2b92d08e..a8ea458f9 100644
--- a/kas/repos.py
+++ b/kas/repos.py

@@ -83,6 +83,14 @@ class PatchApplyError(KasUserError):
super().__init__(msg)


+class RepoFetchError(KasUserError):
+ """
+ An error occurred during repo fetching
+ """
+ def __init__(self, repo, output):
+ super().__init__(f'Fetching of repo: "{repo.name}" failed: {output}')
+
+
class Repo:
"""
Represents a repository in the kas configuration.

@@ -437,8 +445,9 @@ class RepoImpl(Repo):
cwd=self.path,
fail=False)
if retc:
- logging.warning('Could not update repository %s: %s',
- self.name, output)
+ logging.error('Could not update repository %s: %s',
+ self.name, output)
+ raise RepoFetchError(self, output)

else:
logging.info('Repository %s updated', self.name)

--
2.51.0

[Felix Moessbauer]

We currently only test the good case of fetching repos, however we also
need to test the error path. We add a check for that as well by mocking

the fetch_cmd implementation of a GitRepo. We further need to remove the
commit, as otherwise the short-circuit implementation added in 021e961be
skips the fetching.

Signed-off-by: Felix Moessbauer <felix.mo...@siemens.com>
---

tests/test_commands.py | 16 ++++++++++++++++
1 file changed, 16 insertions(+)

diff --git a/tests/test_commands.py b/tests/test_commands.py
index cfc0a6b99..13386c727 100644

--- a/tests/test_commands.py
+++ b/tests/test_commands.py
@@ -31,6 +31,7 @@ import pytest
from kas import kas
from kas.libkas import TaskExecError, KasUserError, run_cmd
from kas.attestation import file_digest_slow
+from kas.repos import RepoFetchError


@pytest.mark.dirsfromenv

@@ -82,6 +83,21 @@ def test_checkout(monkeykas, tmpdir):

assert not (kas_bd / 'downloads').exists()
assert not (kas_bd / 'sstate-cache').exists()

+ # test re-fetching (remove commit as nothing is fetched otherwise)
+ with open('test.yml', 'r') as f:
+ yml = yaml.safe_load(f)
+ with open('test-no-commit.yml', 'w') as f:
+ del yml['repos']['kas_1.1']['commit']
+ yml['repos']['kas_1.1']['branch'] = 'master'
+ yaml.safe_dump(yml, f)
+ kas.kas(['checkout', '--update', 'test-no-commit.yml'])

+
+ with monkeykas.context() as mc:
+ from kas.repos import GitRepo
+ mc.setattr(GitRepo, "fetch_cmd", lambda _: ["false"])
+ with pytest.raises(RepoFetchError):

+ kas.kas(['checkout', '--update', 'test-no-commit.yml'])

[Jan Kiszka]

Thanks, applied.