#1703 set up build_log handler on each module state change handler
Opened 3 years ago by mikem. Modified 3 years ago
mikem/fm-orchestrator logging-fixes  into  master

@@ -6,7 +6,6 @@ 

  import hashlib

  from io import open

  from itertools import chain

- import logging

  import json

  import os

  import pkg_resources
@@ -28,8 +27,6 @@ 

  from module_build_service.common.utils import load_mmd, mmd_to_str, to_text_type

  from module_build_service.scheduler.db_session import db_session

  

- logging.basicConfig(level=logging.DEBUG)

- 

  

  def strip_suffixes(s, suffixes):

      """

@@ -8,7 +8,6 @@ 

  import hashlib

  from itertools import chain

  import locale

- import logging

  import os

  import random

  import string
@@ -34,8 +33,6 @@ 

  from module_build_service.scheduler.db_session import db_session

  from module_build_service.scheduler.reuse import get_reusable_components, get_reusable_module

  

- logging.basicConfig(level=logging.DEBUG)

- 

  

  @contextlib.contextmanager

  def set_locale(*args, **kwargs):

@@ -1,7 +1,6 @@ 

  # -*- coding: utf-8 -*-

  # SPDX-License-Identifier: MIT

  from __future__ import absolute_import

- import logging

  import os

  import pipes

  import re
@@ -29,8 +28,6 @@ 

  from module_build_service.scheduler import events

  from module_build_service.scheduler.db_session import db_session

  

- logging.basicConfig(level=logging.DEBUG)

- 

  

  def detect_arch():

      """

@@ -3,7 +3,6 @@ 

  from __future__ import absolute_import

  import errno

  import hashlib

- import logging

  import inspect

  from multiprocessing.dummy import Pool as ThreadPool

  import os
@@ -17,9 +16,6 @@ 

  from module_build_service.common.errors import ValidationError, ProgrammingError

  

  

- logging.basicConfig(level=logging.DEBUG)

- 

- 

  def find_srpm(cod):

      for f in os.listdir(cod):

          if f.endswith(".src.rpm"):

@@ -65,6 +65,22 @@ 

          logging.FileHandler.emit(self, record)

  

  

+ class ModuleBuildLogsContext(object):

+     """This context manager adds a logging handler for the build log"""

+ 

+     def __init__(self, build_logs, db_session, build):

+         self.build_logs = build_logs

+         self.db_session = db_session

+         self.build = build

+ 

+     def __enter__(self):

+         self.build_logs.start(self.db_session, self.build)

+ 

+     def __exit__(self, exc_type, exc_val, traceback):

+         self.build_logs.stop(self.build)

+         return False  # don't eat exceptions

+ 

+ 

  class ModuleBuildLogs(object):

      """

      Manages ModuleBuildFileHandler logging handlers.
@@ -131,6 +147,10 @@ 

          log.removeHandler(handler)

          del self.handlers[build.id]

  

+     def handle(self, db_session, build):

+         """Returns a context manager that will start and stop the build log handler"""

+         return ModuleBuildLogsContext(self, db_session, build)

+ 

  

  class MBSLogger:

      def __init__(self):

@@ -3,7 +3,6 @@ 

  """ Handlers for koji component build events on the message bus. """

  

  from __future__ import absolute_import

- import logging

  

  import koji

  
@@ -15,8 +14,6 @@ 

  from module_build_service.scheduler.batches import continue_batch_build

  from module_build_service.scheduler.db_session import db_session

  

- logging.basicConfig(level=logging.DEBUG)

- 

  

  @celery_app.task

  @events.mbs_event_handler

@@ -4,7 +4,6 @@ 

  

  from __future__ import absolute_import

  from datetime import datetime

- import logging

  import os

  

  import koji
@@ -34,8 +33,6 @@ 

  from module_build_service.scheduler.submit import format_mmd, get_module_srpm_overrides

  from module_build_service.scheduler.ursine import handle_stream_collision_modules

  

- logging.basicConfig(level=logging.DEBUG)

- 

  

  def get_artifact_from_srpm(srpm_path):

      return os.path.basename(srpm_path).replace(".src.rpm", "")
@@ -56,49 +53,50 @@ 

      """

      build = models.ModuleBuild.get_by_id(db_session, module_build_id)

  

-     if build.state != module_build_state:

-         log.warning(

-             "Note that retrieved module state %r doesn't match message module state %r",

-             build.state, module_build_state,

-         )

-         # This is ok.. it's a race condition we can ignore.

-         pass

+     with build_logs.handle(db_session, build):

  

-     if build.koji_tag:

-         builder = GenericBuilder.create_from_module(db_session, build, conf)

+         if build.state != module_build_state:

+             log.warning(

+                 "Note that retrieved module state %r doesn't match message module state %r",

+                 build.state, module_build_state,

+             )

+             # This is ok.. it's a race condition we can ignore.

+             pass

  

-         if build.new_repo_task_id:

-             builder.cancel_build(build.new_repo_task_id)

+         if build.koji_tag:

+             builder = GenericBuilder.create_from_module(db_session, build, conf)

  

-         for component in (c for c in build.component_builds if c.is_unbuilt):

-             if component.task_id:

-                 builder.cancel_build(component.task_id)

-             component.state = koji.BUILD_STATES["FAILED"]

-             component.state_reason = build.state_reason

-             db_session.add(component)

+             if build.new_repo_task_id:

+                 builder.cancel_build(build.new_repo_task_id)

  

-         # Tell the external buildsystem to wrap up

-         builder.finalize(succeeded=False)

-     else:

-         # Do not overwrite state_reason set by Frontend if any.

-         if not build.state_reason:

-             reason = "Missing koji tag. Assuming previously failed module lookup."

-             log.error(reason)

-             build.transition(

-                 db_session, conf,

-                 state=models.BUILD_STATES["failed"],

-                 state_reason=reason, failure_type="infra")

-             db_session.commit()

-             return

+             for component in (c for c in build.component_builds if c.is_unbuilt):

+                 if component.task_id:

+                     builder.cancel_build(component.task_id)

+                 component.state = koji.BUILD_STATES["FAILED"]

+                 component.state_reason = build.state_reason

+                 db_session.add(component)

  

-     # Don't transition it again if it's already been transitioned

-     if build.state != models.BUILD_STATES["failed"]:

-         build.transition(

-             db_session, conf, state=models.BUILD_STATES["failed"], failure_type="user")

+             # Tell the external buildsystem to wrap up

+             builder.finalize(succeeded=False)

+         else:

+             # Do not overwrite state_reason set by Frontend if any.

+             if not build.state_reason:

+                 reason = "Missing koji tag. Assuming previously failed module lookup."

+                 log.error(reason)

+                 build.transition(

+                     db_session, conf,

+                     state=models.BUILD_STATES["failed"],

+                     state_reason=reason, failure_type="infra")

+                 db_session.commit()

+                 return

+ 

+         # Don't transition it again if it's already been transitioned

+         if build.state != models.BUILD_STATES["failed"]:

+             build.transition(

+                 db_session, conf, state=models.BUILD_STATES["failed"], failure_type="user")

  

      db_session.commit()

  

-     build_logs.stop(build)

      GenericBuilder.clear_cache(build)

  

  
@@ -118,26 +116,26 @@ 

      :param int module_build_state: the module build state.

      """

      build = models.ModuleBuild.get_by_id(db_session, module_build_id)

-     if build.state != module_build_state:

-         log.warning(

-             "Note that retrieved module state %r doesn't match message module state %r",

-             build.state, module_build_state,

-         )

-         # This is ok.. it's a race condition we can ignore.

-         pass

- 

-     # Scratch builds stay in 'done' state

-     if not build.scratch:

-         if greenwave is None or greenwave.check_gating(build):

-             build.transition(db_session, conf, state=models.BUILD_STATES["ready"])

-         else:

-             build.state_reason = "Gating failed"

-             if greenwave.error_occurred:

-                 build.state_reason += " (Error occured while querying Greenwave)"

-             build.time_modified = datetime.utcnow()

-         db_session.commit()

+     with build_logs.handle(db_session, build):

+         if build.state != module_build_state:

+             log.warning(

+                 "Note that retrieved module state %r doesn't match message module state %r",

+                 build.state, module_build_state,

+             )

+             # This is ok.. it's a race condition we can ignore.

+             pass

+ 

+         # Scratch builds stay in 'done' state

+         if not build.scratch:

+             if greenwave is None or greenwave.check_gating(build):

+                 build.transition(db_session, conf, state=models.BUILD_STATES["ready"])

+             else:

+                 build.state_reason = "Gating failed"

+                 if greenwave.error_occurred:

+                     build.state_reason += " (Error occured while querying Greenwave)"

+                 build.time_modified = datetime.utcnow()

+             db_session.commit()

  

-     build_logs.stop(build)

      GenericBuilder.clear_cache(build)

  

  
@@ -172,74 +170,74 @@ 

              os.makedirs(mock_resultsdir)

          build_logs.build_logs_dir = mock_resultsdir

  

-     build_logs.start(db_session, build)

-     log.info("Start to handle %s which is in init state.", build.mmd().get_nsvc())

- 

-     error_msg = ""

-     failure_reason = "unspec"

-     try:

-         mmd = build.mmd()

-         record_module_build_arches(mmd, build)

-         arches = [arch.name for arch in build.arches]

-         defaults_added = add_default_modules(mmd)

- 

-         # Get map of packages that have SRPM overrides

-         srpm_overrides = get_module_srpm_overrides(build)

-         # Format the modulemd by putting in defaults and replacing streams that

-         # are branches with commit hashes

-         format_mmd(mmd, build.scmurl, build, db_session, srpm_overrides)

-         record_component_builds(mmd, build)

- 

-         # The ursine.handle_stream_collision_modules is Koji specific.

-         # It is also run only when Ursa Prime is not enabled for the base

-         # module (`if not defaults_added`).

-         if conf.system in ["koji", "test"] and not defaults_added:

-             handle_stream_collision_modules(mmd)

- 

-         # Sets xmd["mbs"]["ursine_rpms"] with RPMs from the buildrequired base modules which

-         # conflict with the RPMs from other buildrequired modules. This is done to prefer modular

-         # RPMs over base module RPMs even if their NVR is lower.

-         if conf.system in ("koji", "test"):

-             handle_collisions_with_base_module_rpms(mmd, arches)

+     with build_logs.handle(db_session, build):

+         log.info("Start to handle %s which is in init state.", build.mmd().get_nsvc())

+ 

+         error_msg = ""

+         failure_reason = "unspec"

+         try:

+             mmd = build.mmd()

+             record_module_build_arches(mmd, build)

+             arches = [arch.name for arch in build.arches]

+             defaults_added = add_default_modules(mmd)

+ 

+             # Get map of packages that have SRPM overrides

+             srpm_overrides = get_module_srpm_overrides(build)

+             # Format the modulemd by putting in defaults and replacing streams that

+             # are branches with commit hashes

+             format_mmd(mmd, build.scmurl, build, db_session, srpm_overrides)

+             record_component_builds(mmd, build)

+ 

+             # The ursine.handle_stream_collision_modules is Koji specific.

+             # It is also run only when Ursa Prime is not enabled for the base

+             # module (`if not defaults_added`).

+             if conf.system in ["koji", "test"] and not defaults_added:

+                 handle_stream_collision_modules(mmd)

+ 

+             # Sets xmd["mbs"]["ursine_rpms"] with RPMs from the buildrequired base modules which

+             # conflict with the RPMs from other buildrequired modules. This is done to prefer

+             # modular RPMs over base module RPMs even if their NVR is lower.

+             if conf.system in ("koji", "test"):

+                 handle_collisions_with_base_module_rpms(mmd, arches)

+             else:

+                 log.warning(

+                     "The necessary conflicts could not be generated due to RHBZ#1693683. "

+                     "Some RPMs from the base modules (%s) may end up being used over modular RPMs. "

+                     "This may result in different behavior than a production build.",

+                     ", ".join(conf.base_module_names)

+                 )

+ 

+             mmd = record_filtered_rpms(mmd)

+             build.modulemd = mmd_to_str(mmd)

+             build.transition(db_session, conf, models.BUILD_STATES["wait"])

+         # Catch custom exceptions that we can expose to the user

+         except (UnprocessableEntity, Forbidden, ValidationError, RuntimeError) as e:

+             log.exception(str(e))

+             error_msg = str(e)

+             failure_reason = "user"

+         except (xmlrpclib.ProtocolError, koji.GenericError) as e:

+             log.exception(str(e))

+             error_msg = 'Koji communication error: "{0}"'.format(str(e))

+             failure_reason = "infra"

+         except Exception as e:

+             log.exception(str(e))

+             error_msg = "An unknown error occurred while validating the modulemd"

+             failure_reason = "user"

          else:

-             log.warning(

-                 "The necessary conflicts could not be generated due to RHBZ#1693683. "

-                 "Some RPMs from the base modules (%s) may end up being used over modular RPMs. "

-                 "This may result in different behavior than a production build.",

-                 ", ".join(conf.base_module_names)

-             )

- 

-         mmd = record_filtered_rpms(mmd)

-         build.modulemd = mmd_to_str(mmd)

-         build.transition(db_session, conf, models.BUILD_STATES["wait"])

-     # Catch custom exceptions that we can expose to the user

-     except (UnprocessableEntity, Forbidden, ValidationError, RuntimeError) as e:

-         log.exception(str(e))

-         error_msg = str(e)

-         failure_reason = "user"

-     except (xmlrpclib.ProtocolError, koji.GenericError) as e:

-         log.exception(str(e))

-         error_msg = 'Koji communication error: "{0}"'.format(str(e))

-         failure_reason = "infra"

-     except Exception as e:

-         log.exception(str(e))

-         error_msg = "An unknown error occurred while validating the modulemd"

-         failure_reason = "user"

-     else:

-         db_session.add(build)

-         db_session.commit()

-     finally:

-         if error_msg:

-             # Rollback changes underway

-             db_session.rollback()

-             build.transition(

-                 db_session,

-                 conf,

-                 models.BUILD_STATES["failed"],

-                 state_reason=error_msg,

-                 failure_type=failure_reason,

-             )

+             db_session.add(build)

              db_session.commit()

+         finally:

+             if error_msg:

+                 # Rollback changes underway

+                 db_session.rollback()

+                 build.transition(

+                     db_session,

+                     conf,

+                     models.BUILD_STATES["failed"],

+                     state_reason=error_msg,

+                     failure_type=failure_reason,

+                 )

+                 db_session.commit()

  

  

  def generate_module_build_koji_tag(build):
@@ -341,147 +339,153 @@ 

      """

      build = models.ModuleBuild.get_by_id(db_session, module_build_id)

  

-     log.info("Found build=%r from message" % build)

-     log.debug("%r", build.modulemd)

+     with build_logs.handle(db_session, build):

+ 

+         log.info("Found build=%r from message" % build)

+         log.debug("%r", build.modulemd)

+ 

+         if build.state != module_build_state:

+             log.warning(

+                 "Note that retrieved module state %r doesn't match message module state %r",

+                 build.state, module_build_state,

+             )

+             # This is ok.. it's a race condition we can ignore.

+             pass

+ 

+         try:

+             build_deps = get_module_build_dependencies(build)

+         except ValueError:

+             reason = "Failed to get module info from MBS. Max retries reached."

+             log.exception(reason)

+             build.transition(

+                 db_session, conf,

+                 state=models.BUILD_STATES["failed"],

+                 state_reason=reason, failure_type="infra")

+             db_session.commit()

+             raise

+ 

+         tag = generate_module_build_koji_tag(build)

+         log.debug("Found tag=%s for module %r" % (tag, build))

+         # Hang on to this information for later.  We need to know which build is

+         # associated with which koji tag, so that when their repos are regenerated

+         # in koji we can figure out which for which module build that event is

+         # relevant.

+         log.debug("Assigning koji tag=%s to module build" % tag)

+         build.koji_tag = tag

+ 

+         if build.scratch:

+             log.debug(

+                 "Assigning Content Generator build koji tag is skipped for scratch module build.")

+         elif conf.koji_cg_tag_build:

+             cg_build_koji_tag = get_content_generator_build_koji_tag(build_deps)

+             log.debug(

+                 "Assigning Content Generator build koji tag=%s to module build", cg_build_koji_tag)

+             build.cg_build_koji_tag = cg_build_koji_tag

+         else:

+             log.debug(

+                 "It is disabled to tag module build during importing into Koji by Content"

+                 "Generator.")

+             log.debug("Skip to assign Content Generator build koji tag to module build.")

+ 

+         builder = GenericBuilder.create_from_module(db_session, build, conf)

  

-     if build.state != module_build_state:

-         log.warning(

-             "Note that retrieved module state %r doesn't match message module state %r",

-             build.state, module_build_state,

-         )

-         # This is ok.. it's a race condition we can ignore.

-         pass

- 

-     try:

-         build_deps = get_module_build_dependencies(build)

-     except ValueError:

-         reason = "Failed to get module info from MBS. Max retries reached."

-         log.exception(reason)

-         build.transition(

-             db_session, conf,

-             state=models.BUILD_STATES["failed"],

-             state_reason=reason, failure_type="infra")

-         db_session.commit()

-         raise

- 

-     tag = generate_module_build_koji_tag(build)

-     log.debug("Found tag=%s for module %r" % (tag, build))

-     # Hang on to this information for later.  We need to know which build is

-     # associated with which koji tag, so that when their repos are regenerated

-     # in koji we can figure out which for which module build that event is

-     # relevant.

-     log.debug("Assigning koji tag=%s to module build" % tag)

-     build.koji_tag = tag

- 

-     if build.scratch:

-         log.debug(

-             "Assigning Content Generator build koji tag is skipped for scratch module build.")

-     elif conf.koji_cg_tag_build:

-         cg_build_koji_tag = get_content_generator_build_koji_tag(build_deps)

-         log.debug(

-             "Assigning Content Generator build koji tag=%s to module build", cg_build_koji_tag)

-         build.cg_build_koji_tag = cg_build_koji_tag

-     else:

          log.debug(

-             "It is disabled to tag module build during importing into Koji by Content Generator.")

-         log.debug("Skip to assign Content Generator build koji tag to module build.")

- 

-     builder = GenericBuilder.create_from_module(db_session, build, conf)

- 

-     log.debug(

-         "Adding dependencies %s into buildroot for module %s:%s:%s",

-         build_deps.keys(), build.name, build.stream, build.version,

-     )

-     try:

-         builder.buildroot_add_repos(build_deps)

-     except SystemError as e:

-         reason = "Failed to add dependencies to buildroot: %s" % e

-         log.exception(reason)

-         build.transition(

-             db_session, conf,

-             state=models.BUILD_STATES["failed"],

-             state_reason=reason, failure_type="infra")

-         db_session.commit()

-         raise

+             "Adding dependencies %s into buildroot for module %s:%s:%s",

+             build_deps.keys(), build.name, build.stream, build.version,

+         )

+         try:

+             builder.buildroot_add_repos(build_deps)

+         except SystemError as e:

+             reason = "Failed to add dependencies to buildroot: %s" % e

+             log.exception(reason)

+             build.transition(

+                 db_session, conf,

+                 state=models.BUILD_STATES["failed"],

+                 state_reason=reason, failure_type="infra")

+             db_session.commit()

+             raise

  

-     if not build.component_builds:

-         log.info("There are no components in module %r, skipping build" % build)

-         build.transition(db_session, conf, state=models.BUILD_STATES["build"])

-         db_session.add(build)

-         db_session.commit()

-         # Return a KojiRepoChange message so that the build can be transitioned to done

-         # in the repos handler

-         from module_build_service.scheduler.handlers.repos import done as repos_done_handler

-         events.scheduler.add(repos_done_handler, ("fake_msg", builder.module_build_tag["name"]))

-         return

+         if not build.component_builds:

+             log.info("There are no components in module %r, skipping build" % build)

+             build.transition(db_session, conf, state=models.BUILD_STATES["build"])

+             db_session.add(build)

+             db_session.commit()

+             # Return a KojiRepoChange message so that the build can be transitioned to done

+             # in the repos handler

+             from module_build_service.scheduler.handlers.repos import done as repos_done_handler

+             events.scheduler.add(repos_done_handler, ("fake_msg", builder.module_build_tag["name"]))

+             return

  

-     # If all components in module build will be reused, we don't have to build

-     # module-build-macros, because there won't be any build done.

-     if attempt_to_reuse_all_components(builder, build):

-         log.info("All components have been reused for module %r, skipping build" % build)

-         build.transition(db_session, conf, state=models.BUILD_STATES["build"])

-         db_session.add(build)

+         # If all components in module build will be reused, we don't have to build

+         # module-build-macros, because there won't be any build done.

+         if attempt_to_reuse_all_components(builder, build):

+             log.info("All components have been reused for module %r, skipping build" % build)

+             build.transition(db_session, conf, state=models.BUILD_STATES["build"])

+             db_session.add(build)

+             db_session.commit()

+             return []

+ 

+         log.debug("Starting build batch 1")

+         build.batch = 1

          db_session.commit()

-         return []

  

-     log.debug("Starting build batch 1")

-     build.batch = 1

-     db_session.commit()

+         artifact_name = "module-build-macros"

+ 

+         component_build = models.ComponentBuild.from_component_name(db_session, artifact_name,

+                                                                     build.id)

+         srpm = builder.get_disttag_srpm(

+             disttag=".%s" % get_rpm_release(db_session, build),

+             module_build=build)

+         if not component_build:

+             component_build = models.ComponentBuild(

+                 module_id=build.id,

+                 package=artifact_name,

+                 format="rpms",

+                 scmurl=srpm,

+                 batch=1,

+                 build_time_only=True,

+             )

+             db_session.add(component_build)

+             # Commit and refresh so that the SQLAlchemy relationships are available

+             db_session.commit()

+             db_session.refresh(component_build)

+             recovered = builder.recover_orphaned_artifact(component_build)

+             if recovered:

+                 log.info("Found an existing module-build-macros build")

+             # There was no existing artifact found, so lets submit the build instead

+             else:

+                 task_id, state, reason, nvr = builder.build(artifact_name=artifact_name,

+                                                             source=srpm)

+                 component_build.task_id = task_id

+                 component_build.state = state

+                 component_build.reason = reason

+                 component_build.nvr = nvr

+         elif not component_build.is_completed:

+             # It's possible that the build succeeded in the builder but some other step failed which

+             # caused module-build-macros to be marked as failed in MBS, so check to see if it exists

+             # first

+             recovered = builder.recover_orphaned_artifact(component_build)

+             if recovered:

+                 log.info("Found an existing module-build-macros build")

+             else:

+                 task_id, state, reason, nvr = builder.build(artifact_name=artifact_name,

+                                                             source=srpm)

+                 component_build.task_id = task_id

+                 component_build.state = state

+                 component_build.reason = reason

+                 component_build.nvr = nvr

  

-     artifact_name = "module-build-macros"

- 

-     component_build = models.ComponentBuild.from_component_name(db_session, artifact_name, build.id)

-     srpm = builder.get_disttag_srpm(

-         disttag=".%s" % get_rpm_release(db_session, build),

-         module_build=build)

-     if not component_build:

-         component_build = models.ComponentBuild(

-             module_id=build.id,

-             package=artifact_name,

-             format="rpms",

-             scmurl=srpm,

-             batch=1,

-             build_time_only=True,

-         )

          db_session.add(component_build)

-         # Commit and refresh so that the SQLAlchemy relationships are available

+         build.transition(db_session, conf, state=models.BUILD_STATES["build"])

+         db_session.add(build)

          db_session.commit()

-         db_session.refresh(component_build)

-         recovered = builder.recover_orphaned_artifact(component_build)

-         if recovered:

-             log.info("Found an existing module-build-macros build")

-         # There was no existing artifact found, so lets submit the build instead

-         else:

-             task_id, state, reason, nvr = builder.build(artifact_name=artifact_name, source=srpm)

-             component_build.task_id = task_id

-             component_build.state = state

-             component_build.reason = reason

-             component_build.nvr = nvr

-     elif not component_build.is_completed:

-         # It's possible that the build succeeded in the builder but some other step failed which

-         # caused module-build-macros to be marked as failed in MBS, so check to see if it exists

-         # first

-         recovered = builder.recover_orphaned_artifact(component_build)

-         if recovered:

-             log.info("Found an existing module-build-macros build")

-         else:

-             task_id, state, reason, nvr = builder.build(artifact_name=artifact_name, source=srpm)

-             component_build.task_id = task_id

-             component_build.state = state

-             component_build.reason = reason

-             component_build.nvr = nvr

- 

-     db_session.add(component_build)

-     build.transition(db_session, conf, state=models.BUILD_STATES["build"])

-     db_session.add(build)

-     db_session.commit()

  

-     # We always have to regenerate the repository.

-     if conf.system == "koji":

-         log.info("Regenerating the repository")

-         task_id = builder.koji_session.newRepo(builder.module_build_tag["name"])

-         build.new_repo_task_id = task_id

-         db_session.commit()

-     else:

-         from module_build_service.scheduler.handlers.repos import done as repos_done_handler

-         events.scheduler.add(repos_done_handler, ("fake_msg", builder.module_build_tag["name"]))

+         # We always have to regenerate the repository.

+         if conf.system == "koji":

+             log.info("Regenerating the repository")

+             task_id = builder.koji_session.newRepo(builder.module_build_tag["name"])

+             build.new_repo_task_id = task_id

+             db_session.commit()

+         else:

+             from module_build_service.scheduler.handlers.repos import done as repos_done_handler

+             events.scheduler.add(repos_done_handler, ("fake_msg", builder.module_build_tag["name"]))

@@ -4,7 +4,6 @@ 

  

  from __future__ import absolute_import

  from datetime import datetime

- import logging

  

  from module_build_service.builder import GenericBuilder

  from module_build_service.common import conf, log, models
@@ -12,8 +11,6 @@ 

  from module_build_service.scheduler.batches import start_next_batch_build

  from module_build_service.scheduler.db_session import db_session

  

- logging.basicConfig(level=logging.DEBUG)

- 

  

  @celery_app.task

  @events.mbs_event_handler

@@ -3,7 +3,6 @@ 

  """ Handlers for repo change events on the message bus. """

  

  from __future__ import absolute_import

- import logging

  

  import koji

  
@@ -12,8 +11,6 @@ 

  from module_build_service.scheduler import celery_app, events

  from module_build_service.scheduler.db_session import db_session

  

- logging.basicConfig(level=logging.DEBUG)

- 

  

  @celery_app.task

  @events.mbs_event_handler

Build 845949d FAILED!
Rebase or make new commits to rebuild.

Changes LGTM, but should there be a test in tests/test_common/test_logger.py for the new handler?

The patch doesn't really address the way that this was designed to work - see the handling of MBSConsumer.current_module_build_id between scheduler/consumer.pyand common/logger.py.

I'm thinking the problem here is celery -
* that the actual handler is run via celery, so setting and unsetting the current_module_build_id doesn't work
* that different tasks can be run on different machines? (I'm not very clear on the usage of celery) so that setup/teardown work actually can't be done globally because the same machine might not see the first message for the module / subsequent work for the module / the module finishing?

Does per-module log files make sense in the celery case, or would it be better to log everything to standard log facilities in that case to permit log aggregation rather than having to hunt for multiple per-module log files?

Does this patch properly handle the way additional tasks are added during the execution of the module handlers and executed afterwards by mbs_event_handler()? Not all work is done directly within the function sin module_build_service/scheduler/handlers/modules.py.

Perhaps it would make sense to centralize whatever handling we want here in the mbs_event_handler() decorator itself in some fashion? Perhaps by making module_build_id a kwarg for all such decorated functions? (That would also fix the "Local builds: fix logging to the module build log file" commit from https://pagure.io/fm-orchestrator/pull-request/1658.)

that different tasks can be run on different machines?

Not in practice, at least for now.

One of the problems that celery introduced is that the handlers are in different processes, where there was a single daemon before.

Does per-module log files make sense in the celery case

I think celery makes it harder, but per-module log files make sense in the design. We need a record of the build process for a given build. It shouldn't require logging into the backend to see build logs.

Does this patch properly handle the way additional tasks are added during the execution of the module handlers and executed afterwards by mbs_event_handler()?

Ah, good point. I had thought a bit about that, but I hadn't thought it all the way through. The start/stop looked safe to nest because of the self.handlers index, but I see now that the most inner stop is going to stop the logging before the outer ones are finished.

Perhaps it would make sense to centralize whatever handling we want here in the mbs_event_handler() decorator itself in some fashion?

I thought about using a decorator, but it seemed like there were cases where we didn't have the module info at the very beginning. Still, maybe this could be a better approach. I do like that it is more systematic.

that different tasks can be run on different machines?

Not in practice, at least for now.

One of the problems that celery introduced is that the handlers are in different processes, where there was a single daemon before.

Ah, OK, so multiple processes, but a single machine. In that case, opening the log file at the outermost layer of handler and then closing it at the end likely is the best approach. Since the logs are flushed at the end of every write, it probably will mostly even handle multiple processes running handlers for a module at the time.

I think celery makes it harder, but per-module log files make sense in the design. We need a record of the build process for a given build. It shouldn't require logging into the backend to see build logs.

Yeah, better visibility into the workings of MBS is a plus.

For local builds, I have a change pending (but not in a PR, since the PR's it depends on have not been reviewed.)

https://pagure.io/fork/otaylor/fm-orchestrator/c/ffdb96e89cfad3e67d1029dbfdef41525de9a0e2?branch=local-build-logging

that buffers up everything from the beginning of the build and replays it into the module build log once the directory has been created, making the module build log more useful, since it then includes things like module stream resolution.

That would be hard to generalize to the server/multi-process case, unfortunately.

Perhaps it would make sense to centralize whatever handling we want here in the mbs_event_handler() decorator itself in some fashion?

I thought about using a decorator, but it seemed like there were cases where we didn't have the module info at the very beginning. Still, maybe this could be a better approach. I do like that it is more systematic.

I'm just self-interestedly trying to avoid re-indentation and patch conflicts ;-)

I don't see anything in your patch that looks particularly problematic in terms of switching to a decorator - there is some code for setting up logging for local builds that might need to be pulled out of the module init() handler, but that should be doable.

I think the main thing is to make sure that all the handlers are logging this way, and to remove current_module_build_id if that's no longer being used.

Like Brendan, I wonder if some tests can be added. Logging code paths are not the easiest to test, but they are also pretty fragile and easily broken.