From f2182b84235aa504f4dd5f23695eadef49271899 Mon Sep 17 00:00:00 2001 From: Jan Kaluza Date: Nov 08 2017 07:10:11 +0000 Subject: Add BaseHandler.set_context to set the current context of a handler and use it to mark builds as failed in case of traceback. --- diff --git a/freshmaker/consumer.py b/freshmaker/consumer.py index 1b30181..80c8450 100644 --- a/freshmaker/consumer.py +++ b/freshmaker/consumer.py @@ -147,8 +147,8 @@ class FreshmakerConsumer(fedmsg.consumers.FedmsgConsumer): try: further_work = handler.handle(msg) or [] except Exception: - msg = 'Could not process message handler. See the traceback.' - log.exception(msg) + err = 'Could not process message handler. See the traceback.' + log.exception(err) log.debug("Done with %s" % idx) diff --git a/freshmaker/handlers/__init__.py b/freshmaker/handlers/__init__.py index 5e08df6..6d499aa 100644 --- a/freshmaker/handlers/__init__.py +++ b/freshmaker/handlers/__init__.py @@ -24,6 +24,7 @@ import abc import json import re +from functools import wraps from freshmaker import conf, log, db, models from freshmaker.kojiservice import koji_service, parse_NVR @@ -32,19 +33,116 @@ from freshmaker.models import ArtifactBuildState from freshmaker.types import ArtifactType from freshmaker.models import ArtifactBuild, Event from freshmaker.utils import krb_context, get_rebuilt_nvr -from freshmaker.errors import UnprocessableEntity +from freshmaker.errors import UnprocessableEntity, ProgrammingError from freshmaker.odcsclient import ODCS from freshmaker.odcsclient import AuthMech from freshmaker.odcsclient import COMPOSE_STATES +def fail_event_on_handler_exception(func): + """ + Decorator which marks the models.Event associated with handler by + BaseHandler.set_context() as FAILED in case the `func` raises an + exception. + + The exception is re-raised by this decorator once its finished. + """ + @wraps(func) + def decorator(handler, *args, **kwargs): + try: + return func(handler, *args, **kwargs) + except Exception as e: + err = 'Could not process message handler. See the traceback.' + log.exception(err) + + # In case the exception interrupted the database transaction, + # rollback it. + db.session.rollback() + + # Mark the event as failed. + db_event_id = handler.current_db_event_id + db_event = db.session.query(Event).filter_by( + id=db_event_id).first() + if db_event: + db_event.builds_transition( + ArtifactBuildState.FAILED.value, "Handling of " + "event failed with traceback: %s" % (str(e))) + db.session.commit() + raise + return decorator + + +def fail_artifact_build_on_handler_exception(func): + """ + Decorator which marks the models.ArtifactBuild associated with handler by + BaseHandler.set_context() as FAILED in case the `func` raises an + exception. + + The exception is re-raised by this decorator once its finished. + """ + @wraps(func) + def decorator(handler, *args, **kwargs): + try: + return func(handler, *args, **kwargs) + except Exception as e: + err = 'Could not process message handler. See the traceback.' + log.exception(err) + + # In case the exception interrupted the database transaction, + # rollback it. + db.session.rollback() + + # Mark the event as failed. + build_id = handler.current_db_artifact_build_id + build = db.session.query(ArtifactBuild).filter_by( + id=build_id).first() + if build: + build.transition( + ArtifactBuildState.FAILED.value, "Handling of " + "build failed with traceback: %s" % (str(e))) + db.session.commit() + raise + return decorator + + class BaseHandler(object): """ Abstract base class for event handlers. """ __metaclass__ = abc.ABCMeta + def __init__(self): + self._db_event_id = None + self._db_artifact_build_id = None + + @property + def current_db_event_id(self): + return self._db_event_id + + @property + def current_db_artifact_build_id(self): + return self._db_artifact_build_id + + def set_context(self, db_object): + """ + Sets the current context of a handler. This method accepts models.Event + or models.ArtifactBuild. + + Whenever the handler handles particular event or artifact build, it + must set the context, so in case of a failure, the event or artifact + build can be marked as FAILED by a consumer class. + """ + if type(db_object) == Event: + self._db_event_id = db_object.id + self._db_artifact_build_id = None + elif type(db_object) == ArtifactBuild: + self._db_event_id = db_object.event.id + self._db_artifact_build_id = db_object.id + else: + raise ProgrammingError( + "Unsupported context type passed to BaseHandler.set_context()") + @abc.abstractmethod def can_handle(self, event): """ @@ -190,6 +288,7 @@ class ContainerBuildHandler(BaseHandler): koji_parent_build=koji_parent_build, scratch=conf.koji_container_scratch_build) + @fail_artifact_build_on_handler_exception def build_image_artifact_build(self, build, repo_urls=[]): """ Submits ArtifactBuild of 'image' type to Koji. @@ -296,6 +395,7 @@ class ContainerBuildHandler(BaseHandler): dep_on=None).all() for build in builds: + self.set_context(build) repo_urls = self.get_repo_urls(db_event, build) build.build_id = self.build_image_artifact_build(build, repo_urls) if build.build_id: @@ -308,3 +408,5 @@ class ContainerBuildHandler(BaseHandler): "Error while building container image in Koji.") db.session.add(build) db.session.commit() + + self.set_context(db_event) diff --git a/freshmaker/handlers/brew/container_task_state_change.py b/freshmaker/handlers/brew/container_task_state_change.py index efb153c..79b2987 100644 --- a/freshmaker/handlers/brew/container_task_state_change.py +++ b/freshmaker/handlers/brew/container_task_state_change.py @@ -23,7 +23,8 @@ from freshmaker import log from freshmaker import db from freshmaker.events import BrewContainerTaskStateChangeEvent from freshmaker.models import ArtifactBuild -from freshmaker.handlers import ContainerBuildHandler +from freshmaker.handlers import ( + ContainerBuildHandler, fail_event_on_handler_exception) from freshmaker.types import ArtifactType, ArtifactBuildState @@ -35,6 +36,7 @@ class BrewContainerTaskStateChangeHandler(ContainerBuildHandler): def can_handle(self, event): return isinstance(event, BrewContainerTaskStateChangeEvent) + @fail_event_on_handler_exception def handle(self, event): """ When build container task state changed in brew, update build state in db and @@ -47,6 +49,7 @@ class BrewContainerTaskStateChangeHandler(ContainerBuildHandler): found_build = db.session.query(ArtifactBuild).filter_by(type=ArtifactType.IMAGE.value, build_id=build_id).first() if found_build is not None: + self.set_context(found_build) # update build state in db if event.new_state == 'CLOSED': found_build.transition( @@ -64,6 +67,7 @@ class BrewContainerTaskStateChangeHandler(ContainerBuildHandler): state=ArtifactBuildState.PLANNED.value, dep_on=found_build).all() for build in planned_builds: + self.set_context(build) repo_urls = self.get_repo_urls(found_build.event, build) log.info("Build %r depends on build %r" % (build, found_build)) build.build_id = self.build_image_artifact_build(build, repo_urls) diff --git a/freshmaker/handlers/errata/errata_advisory_rpms_signed.py b/freshmaker/handlers/errata/errata_advisory_rpms_signed.py index b4acea1..d536a47 100644 --- a/freshmaker/handlers/errata/errata_advisory_rpms_signed.py +++ b/freshmaker/handlers/errata/errata_advisory_rpms_signed.py @@ -29,7 +29,7 @@ from freshmaker import conf, db, log from freshmaker import messaging from freshmaker.events import ErrataAdvisoryRPMsSignedEvent from freshmaker.events import ODCSComposeStateChangeEvent -from freshmaker.handlers import BaseHandler +from freshmaker.handlers import BaseHandler, fail_event_on_handler_exception from freshmaker.kojiservice import koji_service from freshmaker.lightblue import LightBlue from freshmaker.pulp import Pulp @@ -58,6 +58,7 @@ class ErrataAdvisoryRPMsSignedHandler(BaseHandler): def can_handle(self, event): return isinstance(event, ErrataAdvisoryRPMsSignedEvent) + @fail_event_on_handler_exception def handle(self, event): """ Rebuilds all Docker images which contain packages from the Errata @@ -77,6 +78,7 @@ class ErrataAdvisoryRPMsSignedHandler(BaseHandler): db.session, event.msg_id, event.search_key, event.__class__, released=False) db.session.commit() + self.set_context(db_event) # Get and record all images to rebuild based on the current # ErrataAdvisoryRPMsSignedEvent event. diff --git a/freshmaker/handlers/errata/errata_advisory_state_changed.py b/freshmaker/handlers/errata/errata_advisory_state_changed.py index 880dad0..cc51a47 100644 --- a/freshmaker/handlers/errata/errata_advisory_state_changed.py +++ b/freshmaker/handlers/errata/errata_advisory_state_changed.py @@ -23,7 +23,7 @@ from freshmaker import db, conf, log from freshmaker.events import ( ErrataAdvisoryStateChangedEvent, ErrataAdvisoryRPMsSignedEvent) from freshmaker.models import Event, EVENT_TYPES -from freshmaker.handlers import BaseHandler +from freshmaker.handlers import BaseHandler, fail_event_on_handler_exception from freshmaker.errata import Errata @@ -43,6 +43,7 @@ class ErrataAdvisoryStateChangedHandler(BaseHandler): def can_handle(self, event): return isinstance(event, ErrataAdvisoryStateChangedEvent) + @fail_event_on_handler_exception def mark_as_released(self, errata_id): """ Marks the Errata advisory with `errata_id` ID as "released", so it @@ -57,6 +58,8 @@ class ErrataAdvisoryStateChangedHandler(BaseHandler): "Freshmaker db.", errata_id) return [] + self.set_context(db_event) + db_event.released = True db.session.commit() log.info("Errata advisory %d is now marked as released", errata_id) diff --git a/freshmaker/handlers/koji/task_state_change.py b/freshmaker/handlers/koji/task_state_change.py index 1bfe470..ea2c1af 100644 --- a/freshmaker/handlers/koji/task_state_change.py +++ b/freshmaker/handlers/koji/task_state_change.py @@ -21,7 +21,7 @@ from freshmaker import log, db, models from freshmaker.types import ArtifactType, ArtifactBuildState -from freshmaker.handlers import BaseHandler +from freshmaker.handlers import BaseHandler, fail_event_on_handler_exception from freshmaker.events import KojiTaskStateChangeEvent @@ -34,6 +34,7 @@ class KojiTaskStateChangeHandler(BaseHandler): return False + @fail_event_on_handler_exception def handle(self, event): task_id = event.task_id task_state = event.task_state @@ -45,6 +46,7 @@ class KojiTaskStateChangeHandler(BaseHandler): raise RuntimeError("Found duplicate image build '%s' in db" % task_id) if len(builds) == 1: build = builds.pop() + self.set_context(build) if task_state in ['CLOSED', 'FAILED']: log.info("Image build '%s' state changed in koji, updating it in db.", task_id) if task_state == 'CLOSED': diff --git a/freshmaker/handlers/mbs/module_state_change.py b/freshmaker/handlers/mbs/module_state_change.py index d3a181d..5ec896b 100644 --- a/freshmaker/handlers/mbs/module_state_change.py +++ b/freshmaker/handlers/mbs/module_state_change.py @@ -25,7 +25,7 @@ from freshmaker import log, conf, utils, db, models from freshmaker.types import ArtifactType, ArtifactBuildState from freshmaker.mbs import MBS from freshmaker.pdc import PDC -from freshmaker.handlers import BaseHandler +from freshmaker.handlers import BaseHandler, fail_event_on_handler_exception from freshmaker.events import MBSModuleStateChangeEvent @@ -38,6 +38,7 @@ class MBSModuleStateChangeHandler(BaseHandler): return False + @fail_event_on_handler_exception def handle(self, event): """ Update build state in db when module state changed in MBS and the @@ -59,6 +60,7 @@ class MBSModuleStateChangeHandler(BaseHandler): if len(builds) == 1: # we can find this build in DB module_build = builds.pop() + self.set_context(module_build) if build_state in [MBS.BUILD_STATES['ready'], MBS.BUILD_STATES['failed']]: log.info("Module build '%s' state changed in MBS, updating it in db.", build_id) if build_state == MBS.BUILD_STATES['ready']: diff --git a/freshmaker/handlers/odcs/compose_state_change.py b/freshmaker/handlers/odcs/compose_state_change.py index a8e083e..4d3f35a 100644 --- a/freshmaker/handlers/odcs/compose_state_change.py +++ b/freshmaker/handlers/odcs/compose_state_change.py @@ -23,7 +23,8 @@ from freshmaker import db from freshmaker.models import Event -from freshmaker.handlers import ContainerBuildHandler +from freshmaker.handlers import ( + ContainerBuildHandler, fail_event_on_handler_exception) from freshmaker.events import ODCSComposeStateChangeEvent from odcs.common.types import COMPOSE_STATES @@ -39,8 +40,10 @@ class ComposeStateChangeHandler(ContainerBuildHandler): return False return event.compose['state'] == COMPOSE_STATES['done'] + @fail_event_on_handler_exception def handle(self, event): errata_signed_events = db.session.query(Event).filter( Event.compose_id == event.compose['id']).all() - for event in errata_signed_events: - self._build_first_batch(event) + for db_event in errata_signed_events: + self.set_context(db_event) + self._build_first_batch(db_event) diff --git a/tests/test_brew_container_task_state_change_handler.py b/tests/test_brew_container_task_state_change_handler.py index 6cae225..1ceb349 100644 --- a/tests/test_brew_container_task_state_change_handler.py +++ b/tests/test_brew_container_task_state_change_handler.py @@ -64,7 +64,8 @@ class TestBrewContainerTaskStateChangeHandler(helpers.FreshmakerTestCase): @mock.patch('freshmaker.handlers.ContainerBuildHandler.build_image_artifact_build') @mock.patch('freshmaker.handlers.ContainerBuildHandler.get_repo_urls') - def test_build_containers_when_dependency_container_is_built(self, repo_urls, build_image): + @mock.patch('freshmaker.handlers.ContainerBuildHandler.set_context') + def test_build_containers_when_dependency_container_is_built(self, set_context, repo_urls, build_image): """ Tests when dependency container is built, rebuild containers depend on it. """ @@ -89,6 +90,9 @@ class TestBrewContainerTaskStateChangeHandler(helpers.FreshmakerTestCase): mock.call(build_2, ['url']), ]) + set_context.assert_has_calls([ + mock.call(build_0), mock.call(build_1), mock.call(build_2)]) + self.assertEqual(build_0.build_id, 1) self.assertEqual(build_1.build_id, 2) self.assertEqual(build_2.build_id, 3) diff --git a/tests/test_consumer.py b/tests/test_consumer.py index eb07adf..0fa5e1e 100644 --- a/tests/test_consumer.py +++ b/tests/test_consumer.py @@ -25,6 +25,10 @@ import unittest import freshmaker from freshmaker.events import BrewSignRPMEvent +from freshmaker.models import Event, ArtifactBuild +from freshmaker import db +from freshmaker.types import ArtifactBuildState +from freshmaker.handlers import fail_event_on_handler_exception class ConsumerBaseTest(unittest.TestCase): @@ -35,9 +39,34 @@ class ConsumerBaseTest(unittest.TestCase): hub.config['freshmakerconsumer'] = True return freshmaker.consumer.FreshmakerConsumer(hub) + def _module_state_change_msg(self, state=None): + msg = {'body': { + "msg_id": "2017-7afcb214-cf82-4130-92d2-22f45cf59cf7", + "topic": "org.fedoraproject.prod.mbs.module.state.change", + "signature": "qRZ6oXBpKD/q8BTjBNa4MREkAPxT+KzI8Oret+TSKazGq/6gk0uuprdFpkfBXLR5dd4XDoh3NQWp\nyC74VYTDVqJR7IsEaqHtrv01x1qoguU/IRWnzrkGwqXm+Es4W0QZjHisBIRRZ4ywYBG+DtWuskvy\n6/5Mc3dXaUBcm5TnT0c=\n", + "msg": { + "state": 5, + "id": 70, + "state_name": state or "ready" + } + }} + + return msg + class ConsumerTest(ConsumerBaseTest): + def setUp(self): + db.session.remove() + db.drop_all() + db.create_all() + db.session.commit() + + def tearDown(self): + db.session.remove() + db.drop_all() + db.session.commit() + @mock.patch("freshmaker.handlers.mbs.module_state_change.MBSModuleStateChangeHandler.handle") @mock.patch("freshmaker.consumer.get_global_consumer") def test_consumer_processing_message(self, global_consumer, handle): @@ -48,19 +77,9 @@ class ConsumerTest(ConsumerBaseTest): """ consumer = self._create_consumer() global_consumer.return_value = consumer - - msg = {'body': { - "msg_id": "2017-7afcb214-cf82-4130-92d2-22f45cf59cf7", - "topic": "org.fedoraproject.prod.mbs.module.state.change", - "signature": "qRZ6oXBpKD/q8BTjBNa4MREkAPxT+KzI8Oret+TSKazGq/6gk0uuprdFpkfBXLR5dd4XDoh3NQWp\nyC74VYTDVqJR7IsEaqHtrv01x1qoguU/IRWnzrkGwqXm+Es4W0QZjHisBIRRZ4ywYBG+DtWuskvy\n6/5Mc3dXaUBcm5TnT0c=\n", - "msg": { - "state": 5, - "id": 70, - "state_name": "ready" - } - }} - handle.return_value = [freshmaker.events.TestingEvent("ModuleBuilt handled")] + + msg = self._module_state_change_msg() consumer.consume(msg) event = consumer.incoming.get() @@ -78,6 +97,36 @@ class ConsumerTest(ConsumerBaseTest): for topic in topics: self.assertIn(mock.call(topic, callback), consumer.hub.subscribe.call_args_list) + @mock.patch("freshmaker.handlers.mbs.module_state_change.MBSModuleStateChangeHandler.handle", + autospec=True) + @mock.patch("freshmaker.consumer.get_global_consumer") + def test_consumer_mark_event_as_failed_on_exception( + self, global_consumer, handle): + """ + Tests that Consumer.consume marks the DB Event as failed in case there + is an error in a handler. + """ + consumer = self._create_consumer() + global_consumer.return_value = consumer + + @fail_event_on_handler_exception + def mocked_handle(cls, msg): + event = Event.get_or_create(db.session, "msg_id", "msg_id", 0) + ArtifactBuild.create(db.session, event, "foo", 0) + db.session.commit() + cls.set_context(event) + raise ValueError("Expected exception") + + handle.side_effect = mocked_handle + + msg = self._module_state_change_msg() + consumer.consume(msg) + + db_event = Event.get(db.session, "msg_id") + for build in db_event.builds: + self.assertEqual(build.state, ArtifactBuildState.FAILED.value) + self.assertTrue(build.state_reason, "Failed with traceback") + class ParseBrewSignRPMEventTest(ConsumerBaseTest): diff --git a/tests/test_errata_advisory_state_changed.py b/tests/test_errata_advisory_state_changed.py index 9af81ad..c63d217 100644 --- a/tests/test_errata_advisory_state_changed.py +++ b/tests/test_errata_advisory_state_changed.py @@ -114,6 +114,7 @@ class TestAllowBuild(unittest.TestCase): handler.handle(event) record_images.assert_not_called() + self.assertEqual(handler.current_db_event_id, None) @patch("freshmaker.handlers.errata.ErrataAdvisoryRPMsSignedHandler." "_find_images_to_rebuild", return_value=[]) @@ -130,6 +131,7 @@ class TestAllowBuild(unittest.TestCase): handler.handle(event) record_images.assert_called_once() + self.assertEqual(handler.current_db_event_id, 1) @patch("freshmaker.handlers.errata.ErrataAdvisoryRPMsSignedHandler." "_find_images_to_rebuild", return_value=[]) diff --git a/tests/test_handler.py b/tests/test_handler.py index 05b4cf6..52815d3 100644 --- a/tests/test_handler.py +++ b/tests/test_handler.py @@ -33,7 +33,7 @@ from freshmaker.handlers import ContainerBuildHandler from freshmaker.models import ArtifactBuild from freshmaker.models import ArtifactBuildState from freshmaker.models import Event -from freshmaker.errors import UnprocessableEntity +from freshmaker.errors import UnprocessableEntity, ProgrammingError from freshmaker.types import ArtifactType @@ -97,6 +97,47 @@ class TestKrbContextPreparedForBuildContainer(TestCase): ) +class TestContext(TestCase): + """Test setting context of handler""" + + def setUp(self): + db.session.remove() + db.drop_all() + db.create_all() + db.session.commit() + + def tearDown(self): + db.session.remove() + db.drop_all() + db.session.commit() + + def test_context_event(self): + db_event = Event.get_or_create( + db.session, "msg1", "current_event", ErrataAdvisoryRPMsSignedEvent) + db.session.commit() + handler = MyHandler() + handler.set_context(db_event) + + self.assertEqual(handler.current_db_event_id, db_event.id) + self.assertEqual(handler.current_db_artifact_build_id, None) + + def test_context_artifact_build(self): + db_event = Event.get_or_create( + db.session, "msg1", "current_event", ErrataAdvisoryRPMsSignedEvent) + build = ArtifactBuild.create(db.session, db_event, "parent1-1-4", + "image") + db.session.commit() + handler = MyHandler() + handler.set_context(build) + + self.assertEqual(handler.current_db_event_id, db_event.id) + self.assertEqual(handler.current_db_artifact_build_id, build.id) + + def test_context_unknown(self): + handler = MyHandler() + self.assertRaises(ProgrammingError, handler.set_context, "something") + + class AnyStringWith(str): def __eq__(self, other): return self in other @@ -126,11 +167,14 @@ class TestBuildFirstBatch(TestCase): db.session, "msg1", "current_event", ErrataAdvisoryRPMsSignedEvent, released=False) self.db_event.compose_id = 3 + p1 = ArtifactBuild.create(db.session, self.db_event, "parent1-1-4", "image", state=ArtifactBuildState.PLANNED.value, original_nvr="parent1-1-4") p1.build_args = build_args + self.p1 = p1 + b = ArtifactBuild.create(db.session, self.db_event, "parent1_child1", "image", state=ArtifactBuildState.PLANNED.value, @@ -258,3 +302,39 @@ class TestBuildFirstBatch(TestCase): handler.allow_build(ArtifactType.IMAGE, name=container["name"], branch=container["branch"]) + + @patch('freshmaker.handlers.ODCS') + @patch('koji.ClientSession') + @patch('freshmaker.utils.krbContext') + def test_build_first_batch_exception(self, krb, ClientSession, ODCS): + """ + Tests that only PLANNED images without a parent are submitted to + build system. + """ + + def _fake_get_compose(compose_id): + return { + "id": compose_id, + "result_repo": "http://localhost/composes/latest-odcs-%d-1/compose/Temporary" % compose_id, + "result_repofile": "http://localhost/composes/latest-odcs-%d-1/compose/Temporary/odcs-%s.repo" % (compose_id, compose_id), + "source": "f26", + "source_type": 1, + "state": 2, + "state_name": "done", + } + + ODCS.return_value.get_compose = _fake_get_compose + + def mock_buildContainer(*args, **kwargs): + raise ValueError("Expected exception") + + mock_session = ClientSession.return_value + mock_session.buildContainer.side_effect = mock_buildContainer + + handler = MyHandler() + self.assertRaises(ValueError, handler._build_first_batch, self.db_event) + + db.session.refresh(self.p1) + self.assertEqual(self.p1.state, ArtifactBuildState.FAILED.value) + self.assertTrue(self.p1.state_reason.startswith( + "Handling of build failed with traceback")) diff --git a/tests/test_odcs_compose_state_change.py b/tests/test_odcs_compose_state_change.py index 3b8173f..63dde15 100644 --- a/tests/test_odcs_compose_state_change.py +++ b/tests/test_odcs_compose_state_change.py @@ -71,7 +71,8 @@ class TestComposeStateChangeHandler(unittest.TestCase): self.assertFalse(can_handle) @patch('freshmaker.handlers.ContainerBuildHandler._build_first_batch') - def test_start_to_build(self, build_first_batch): + @patch('freshmaker.handlers.ContainerBuildHandler.set_context') + def test_start_to_build(self, set_context, build_first_batch): event = ODCSComposeStateChangeEvent( 'msg-id', {'id': 1, 'state': 'done'} ) @@ -81,3 +82,8 @@ class TestComposeStateChangeHandler(unittest.TestCase): call(self.adv_signed_event1), call(self.adv_signed_event2), ]) + + set_context.assert_has_calls([ + call(self.adv_signed_event1), + call(self.adv_signed_event2) + ])