From 81b3ad9898f75f23965c0f268f4f23ee0e31b435 Mon Sep 17 00:00:00 2001 From: Jan Kaluza Date: Dec 15 2017 11:28:41 +0000 Subject: Improve the logging related to Errata advisories handling. --- diff --git a/freshmaker/consumer.py b/freshmaker/consumer.py index e373f3b..46568f5 100644 --- a/freshmaker/consumer.py +++ b/freshmaker/consumer.py @@ -76,7 +76,6 @@ class FreshmakerConsumer(fedmsg.consumers.FedmsgConsumer): if conf.messaging == 'fedmsg': # If this is a faked internal message, don't bother. if isinstance(message, events.BaseEvent): - log.info("Skipping crypto validation for %r" % message) return # Otherwise, if it is a real message from the network, pass it # through crypto validation. @@ -94,8 +93,8 @@ class FreshmakerConsumer(fedmsg.consumers.FedmsgConsumer): msg = self.get_abstracted_msg(message['body']) if not msg: - # Logging is done in get_abstracted_msg, because we know - # the msg_id there... + # We do not log here anything, because it would create lot of + # useless messages in the logs. return # Primary work is done here. @@ -133,12 +132,7 @@ class FreshmakerConsumer(fedmsg.consumers.FedmsgConsumer): 'Received message does not contain "msg_id" or "message-id": ' '%r' % (message)) - msg = events.BaseEvent.from_fedmsg(message['topic'], message) - if not msg: - log.debug("No BaseEvent subclass defined for message with id %s", - message["msg_id"]) - - return msg + return events.BaseEvent.from_fedmsg(message['topic'], message) def process_event(self, msg): log.debug('Received a message with an ID of "{0}" and of type "{1}"' diff --git a/freshmaker/handlers/__init__.py b/freshmaker/handlers/__init__.py index 941d4d1..948ffed 100644 --- a/freshmaker/handlers/__init__.py +++ b/freshmaker/handlers/__init__.py @@ -117,6 +117,43 @@ class BaseHandler(object): def __init__(self): self._db_event_id = None self._db_artifact_build_id = None + self._log_prefix = "" + + def _log(self, log_fnc, msg, *args, **kwargs): + """ + Logs the message `msg` using `log_fnc`, passing msg, *args and **kwargs + to it. + + :param log_fnc: log.info, log.error, log.warn, ... + :param str msg: Message to log (first argument passed to log_fnc). + :param *args: Args passed to log_fnc. + :param **kwargs: Kwargs passed to log_fnc. + """ + return log_fnc("%s%s" % (self._log_prefix, msg), *args, **kwargs) + + def log_debug(self, msg, *args, **kwargs): + """ + Wraps log.info, prefixes the message with a context of this handler. + """ + return self._log(log.debug, msg, *args, **kwargs) + + def log_info(self, msg, *args, **kwargs): + """ + Wraps log.info, prefixes the message with a context of this handler. + """ + return self._log(log.info, msg, *args, **kwargs) + + def log_warn(self, msg, *args, **kwargs): + """ + Wraps log.warn, prefixes the message with a context of this handler. + """ + return self._log(log.warn, msg, *args, **kwargs) + + def log_error(self, msg, *args, **kwargs): + """ + Wraps log.error, prefixes the message with a context of this handler. + """ + return self._log(log.error, msg, *args, **kwargs) @property def current_db_event_id(self): @@ -142,9 +179,11 @@ class BaseHandler(object): if type(db_object) == Event: self._db_event_id = db_object.id self._db_artifact_build_id = None + self._log_prefix = "%s: " % str(db_object) elif type(db_object) == ArtifactBuild: self._db_event_id = db_object.event.id self._db_artifact_build_id = db_object.id + self._log_prefix = "%s: " % str(db_object.event) else: raise ProgrammingError( "Unsupported context type passed to BaseHandler.set_context()") diff --git a/freshmaker/handlers/errata/errata_advisory_rpms_signed.py b/freshmaker/handlers/errata/errata_advisory_rpms_signed.py index 6140436..799bb4b 100644 --- a/freshmaker/handlers/errata/errata_advisory_rpms_signed.py +++ b/freshmaker/handlers/errata/errata_advisory_rpms_signed.py @@ -84,7 +84,7 @@ class ErrataAdvisoryRPMsSignedHandler(ContainerBuildHandler): "to trigger rebuilds.".format(event.errata_id)) db_event.transition(EventState.SKIPPED, msg) db.session.commit() - log.info(msg) + self.log_info(msg) return [] # Get and record all images to rebuild based on the current @@ -95,7 +95,7 @@ class ErrataAdvisoryRPMsSignedHandler(ContainerBuildHandler): if not builds: msg = 'No container images to rebuild for advisory %r' % event.errata_name - log.info(msg) + self.log_info(msg) db_event.transition(EventState.SKIPPED, msg) db.session.commit() return [] @@ -109,9 +109,10 @@ class ErrataAdvisoryRPMsSignedHandler(ContainerBuildHandler): # Generate the ODCS compose with RPMs from the current advisory. repo_urls = self._prepare_yum_repos_for_rebuilds( db_event, event, builds) - log.info("Following repositories will be used for the rebuild:") + self.log_info( + "Following repositories will be used for the rebuild:") for url in repo_urls: - log.info(" - %s", url) + self.log_info(" - %s", url) # Log what we are going to rebuild self._check_images_to_rebuild(db_event, builds) @@ -141,8 +142,8 @@ class ErrataAdvisoryRPMsSignedHandler(ContainerBuildHandler): :rtype: dict :return: Fake odcs.new_compose dict. """ - log.info("DRY RUN: Calling fake odcs.new_compose with args: %r", - (compose_source, tag, packages)) + self.log_info("DRY RUN: Calling fake odcs.new_compose with args: %r", + (compose_source, tag, packages)) # Generate the new_compose dict. ErrataAdvisoryRPMsSignedHandler._FAKE_COMPOSE_ID += 1 @@ -155,7 +156,7 @@ class ErrataAdvisoryRPMsSignedHandler(ContainerBuildHandler): # Generate and inject the ODCSComposeStateChangeEvent event. event = ODCSComposeStateChangeEvent( "fake_compose_msg", new_compose) - log.info("Injecting fake event: %r", event) + self.log_info("Injecting fake event: %r", event) work_queue_put(event) return new_compose @@ -182,7 +183,7 @@ class ErrataAdvisoryRPMsSignedHandler(ContainerBuildHandler): while prev_builds_count != len(builds): prev_builds_count = len(builds) extra_events = self._find_events_to_include(db_event, builds) - log.info("Extra events: %r", extra_events) + self.log_info("Extra events: %r", extra_events) for ev in extra_events: if ev in seen_extra_events: continue @@ -230,9 +231,9 @@ class ErrataAdvisoryRPMsSignedHandler(ContainerBuildHandler): % (builds, errata_id)) return - log.info('Generate new compose for rebuild: ' - 'source: %s, source type: %s, packages: %s', - compose_source, 'tag', packages) + self.log_info('Generating new compose for rebuild: ' + 'source: %s, source type: %s, packages: %s', + compose_source, 'tag', packages) odcs = ODCS(conf.odcs_server_url, auth_mech=AuthMech.Kerberos, verify_ssl=conf.odcs_verify_ssl) @@ -266,8 +267,8 @@ class ErrataAdvisoryRPMsSignedHandler(ContainerBuildHandler): :rtype: dict :return: ODCS compose dictionary. """ - log.info('Generating new PULP type compose for content_sets: %r', - content_sets) + self.log_info('Generating new PULP type compose for content_sets: %r', + content_sets) odcs = ODCS(conf.odcs_server_url, auth_mech=AuthMech.Kerberos, verify_ssl=conf.odcs_verify_ssl) @@ -291,7 +292,8 @@ class ErrataAdvisoryRPMsSignedHandler(ContainerBuildHandler): return True elif ret["state_name"] == "failed": return False - log.info("Waiting for Pulp compose to finish: %r", ret) + self.log_info("Waiting for Pulp compose to finish: %r", + ret) raise Exception("ODCS compose not finished.") done = wait_for_compose(new_compose["id"]) @@ -348,30 +350,30 @@ class ErrataAdvisoryRPMsSignedHandler(ContainerBuildHandler): latest=True, package=koji.parse_NVR(nvr)['name']) if latest_build and latest_build[0]['nvr'] == nvr: - log.info("Package %r is latest version in tag %r, " - "will use this tag", nvr, tag) + self.log_info("Package %r is latest version in tag %r, " + "will use this tag", nvr, tag) return tag elif not latest_build: - log.info("Could not find package %r in tag %r, " - "skipping this tag", nvr, tag) + self.log_info("Could not find package %r in tag %r, " + "skipping this tag", nvr, tag) else: - log.info("Package %r is not he latest in the tag %r (" - "latest is %r), skipping this tag", nvr, tag, - latest_build[0]['nvr']) + self.log_info("Package %r is not he latest in the tag %r (" + "latest is %r), skipping this tag", + nvr, tag, latest_build[0]['nvr']) def _check_images_to_rebuild(self, db_event, builds): """ - Checks the images to rebuild and logs them using log.info(...). + Checks the images to rebuild and logs them using self.log_info(...). :param Event db_event: Database Event associated with images. :param builds dict: list of docker images to build as returned by _find_images_to_rebuild(...). """ - log.info('Found docker images to rebuild in following order:') + self.log_info('Found container images to rebuild in following order:') batch = 0 printed = [] while (len(printed) != len(builds.values()) or len(printed) != len(db_event.builds)): - log.info(' Batch %d:', batch) + self.log_info(' Batch %d:', batch) old_printed_count = len(printed) for build in builds.values(): # Print build only if: @@ -387,8 +389,9 @@ class ErrataAdvisoryRPMsSignedHandler(ContainerBuildHandler): args = json.loads(build.build_args) based_on = "based on %s" % args["parent"] \ if args["parent"] else "base image" - log.info(' - %s#%s (%s)' % - (args["repository"], args["commit"], based_on)) + self.log_info( + ' - %s#%s (%s)' % + (args["repository"], args["commit"], based_on)) printed.append(build.original_nvr) # Nothing has been printed, that means the dependencies between @@ -398,12 +401,12 @@ class ErrataAdvisoryRPMsSignedHandler(ContainerBuildHandler): db_event.builds_transition( ArtifactBuildState.FAILED.value, "No image to be built in batch %d." % (batch)) - log.error("Dumping the builds:") + self.log_error("Dumping the builds:") for build in builds.values(): - log.error(" %r", build.original_nvr) - log.error("Printed ones:") + self.log_error(" %r", build.original_nvr) + self.log_error("Printed ones:") for p in printed: - log.error(" %r", p) + self.log_error(" %r", p) break batch += 1 @@ -458,10 +461,10 @@ class ErrataAdvisoryRPMsSignedHandler(ContainerBuildHandler): for image in batch: nvr = image["brew"]["build"] if nvr in builds: - log.debug("Skipping recording build %s, " - "it is already in db", nvr) + self.log_debug("Skipping recording build %s, " + "it is already in db", nvr) continue - log.debug("Recording %s", nvr) + self.log_debug("Recording %s", nvr) parent_nvr = image["parent"]["brew"]["build"] \ if image["parent"] else None dep_on = builds[parent_nvr] if parent_nvr in builds else None @@ -527,8 +530,8 @@ class ErrataAdvisoryRPMsSignedHandler(ContainerBuildHandler): if not self.event.manual and not self.allow_build( ArtifactType.IMAGE, image_name=image_name): - log.info("Skipping rebuild of image %s, not allowed by " - "configuration", image_name) + self.log_info("Skipping rebuild of image %s, not allowed by " + "configuration", image_name) return True return False @@ -555,7 +558,8 @@ class ErrataAdvisoryRPMsSignedHandler(ContainerBuildHandler): password=conf.pulp_password) content_sets = pulp.get_content_set_by_repo_ids(pulp_repo_ids) - log.info('RPM will end up within content sets %s', content_sets) + self.log_info('RPMs from advisory ends up in following content sets: ' + '%s', content_sets) # Query images from LightBlue by signed RPM's srpm name and found # content sets @@ -570,13 +574,17 @@ class ErrataAdvisoryRPMsSignedHandler(ContainerBuildHandler): # Container images builds end with ".tar.gz", so do not treat # them as RPMs here. if not nvr.endswith(".tar.gz"): + self.log_info( + "Going to find all the container images to rebuild as " + "result of %s update.", nvr) srpm_name = self._find_build_srpm_name(nvr) batches = lb.find_images_to_rebuild( srpm_name, content_sets, filter_fnc=self._filter_out_not_allowed_builds) yield batches else: - log.info("Skipping unsupported Errata build type: %s.", nvr) + self.log_info("Skipping unsupported Errata build type: " + "%s.", nvr) def _find_build_srpm_name(self, build_nvr): """Find srpm name from a build""" diff --git a/freshmaker/kojiservice.py b/freshmaker/kojiservice.py index bcd96df..a02889c 100644 --- a/freshmaker/kojiservice.py +++ b/freshmaker/kojiservice.py @@ -154,17 +154,14 @@ class KojiService(object): return task_id def get_build_rpms(self, build_nvr, arches=None): - log.info("get_build_rpms %r", build_nvr) build_info = self.session.getBuild(build_nvr) return self.session.listRPMs(buildID=build_info['id'], arches=arches) def get_build(self, build_nvr): - log.info("get_build %r", build_nvr) return self.session.getBuild(build_nvr) def get_task_request(self, task_id): - log.info("get_task_request %r", task_id) return self.session.getTaskRequest(task_id) diff --git a/freshmaker/models.py b/freshmaker/models.py index ca567b6..f88cf00 100644 --- a/freshmaker/models.py +++ b/freshmaker/models.py @@ -288,6 +288,13 @@ class Event(FreshmakerBase): def __repr__(self): return "" % (self.message_id, self.event_type, self.search_key) + def __str__(self): + if self.event_type_id in INVERSE_EVENT_TYPES: + type_name = INVERSE_EVENT_TYPES[self.event_type_id].__name__ + else: + type_name = "UnknownEventType %d" % self.event_type_id + return "<%s, search_key=%s>" % (type_name, self.search_key) + def json(self): event_url = get_url_for('event', id=self.id) db.session.add(self) diff --git a/freshmaker/parsers/brew/task_state_change.py b/freshmaker/parsers/brew/task_state_change.py index ebecc97..05f63da 100644 --- a/freshmaker/parsers/brew/task_state_change.py +++ b/freshmaker/parsers/brew/task_state_change.py @@ -21,7 +21,6 @@ import re -from freshmaker import log from freshmaker.parsers import BaseParser from freshmaker.events import BrewContainerTaskStateChangeEvent @@ -56,6 +55,3 @@ class BrewTaskStateChangeParser(BaseParser): m = re.match(r".*/(?P[^#]*)", git_url) container = m.group('container') return BrewContainerTaskStateChangeEvent(msg_id, container, branch, target, task_id, old_state, new_state) - else: - log.debug("brew.task.closed or brew.task.failed of %s task_method " - "is not handled yet.", task_method) diff --git a/tests/test_errata_advisory_state_changed.py b/tests/test_errata_advisory_state_changed.py index 101c881..78c0cd2 100644 --- a/tests/test_errata_advisory_state_changed.py +++ b/tests/test_errata_advisory_state_changed.py @@ -33,7 +33,7 @@ from freshmaker.events import ErrataAdvisoryStateChangedEvent from freshmaker.errata import ErrataAdvisory from freshmaker import conf, db, events -from freshmaker.models import Event, ArtifactBuild +from freshmaker.models import Event, ArtifactBuild, EVENT_TYPES from freshmaker.types import ArtifactBuildState, ArtifactType, EventState @@ -363,7 +363,8 @@ class TestCheckImagesToRebuild(unittest.TestCase): "odcs_pulp_compose_id": 15, }) - self.ev = Event.create(db.session, 'msg-id', '123', 100) + self.ev = Event.create(db.session, 'msg-id', '123', + EVENT_TYPES[ErrataAdvisoryRPMsSignedEvent]) self.b1 = ArtifactBuild.create( db.session, self.ev, "parent", "image", state=ArtifactBuildState.PLANNED, @@ -389,6 +390,7 @@ class TestCheckImagesToRebuild(unittest.TestCase): } handler = ErrataAdvisoryRPMsSignedHandler() + handler.set_context(self.ev) handler._check_images_to_rebuild(self.ev, builds) # Check that the images have proper data in proper db columns. @@ -404,6 +406,7 @@ class TestCheckImagesToRebuild(unittest.TestCase): } handler = ErrataAdvisoryRPMsSignedHandler() + handler.set_context(self.ev) handler._check_images_to_rebuild(self.ev, builds) # Check that the images have proper data in proper db columns. @@ -419,6 +422,7 @@ class TestCheckImagesToRebuild(unittest.TestCase): } handler = ErrataAdvisoryRPMsSignedHandler() + handler.set_context(self.ev) handler._check_images_to_rebuild(self.ev, builds) # Check that the images have proper data in proper db columns. diff --git a/tests/test_models.py b/tests/test_models.py index 9a38421..9a96785 100644 --- a/tests/test_models.py +++ b/tests/test_models.py @@ -167,3 +167,13 @@ class TestModels(unittest.TestCase): # No state means only COMPLETE should be returned ret = Event.get_unreleased(db.session, states=[EventState.SKIPPED]) self.assertEqual(ret, [event3]) + + def test_str(self): + event = Event.create(db.session, "test_msg_id1", "test", + events.TestingEvent) + self.assertEqual(str(event), "") + + def test_str_unknown_event_type(self): + event = Event.create(db.session, "test_msg_id1", "test", 1024) + self.assertEqual( + str(event), "")