#413 [rpmbuild] nicer live logs
Merged a year ago by msuchy. Opened a year ago by praiskup.
copr/ praiskup/copr better-live-logs  into  master

@@ -3,38 +3,14 @@ 

  import logging

  import shutil

  import subprocess

- from threading import Timer

  

  from jinja2 import Environment, FileSystemLoader

- from ..helpers import run_cmd, locate_spec, locate_srpm, CONF_DIRS, get_mock_uniqueext

+ from ..helpers import run_cmd, locate_spec, locate_srpm, CONF_DIRS, \

+         get_mock_uniqueext, GentlyTimeoutedPopen

  

  log = logging.getLogger("__main__")

  

  

- class GentlyTimeoutedPopen(subprocess.Popen):

-     timers = []

- 

-     def __init__(self, cmd, timeout=None, **kwargs):

-         super(GentlyTimeoutedPopen, self).__init__(cmd, **kwargs)

-         if not timeout:

-             return

- 

-         def timeout_cb(me, string, signal):

-             log.error(" !! Copr timeout => sending {0}".format(string))

-             me.send_signal(signal)

- 

-         delay = timeout

-         for string, signal in [('INT', 2), ('TERM', 15), ('KILL', 9)]:

-             timer = Timer(delay, timeout_cb, [self, string, signal])

-             timer.start()

-             self.timers.append(timer)

-             delay = delay + 10

- 

-     def done(self):

-         for timer in self.timers:

-             timer.cancel()

- 

- 

  class MockBuilder(object):

      def __init__(self, task, sourcedir, resultdir, config):

          self.task_id = task.get("task_id")

@@ -89,16 +65,6 @@ 

                                 enable_net=self.enable_net, use_bootstrap_container=self.use_bootstrap_container,

                                 repos=self.repos, pkg_manager_conf=self.pkg_manager_conf)

  

-     def preexec_fn_build_stream(self):

-         if not self.logfile:

-             return

-         filter_continuing_lines = r"sed 's/.*\x0D\([^\x0a]\)/\1/g' --unbuffered"

-         tee_output = "tee -a {0}".format(self.logfile)

-         cmd = filter_continuing_lines + "|" + tee_output

-         tee = subprocess.Popen(cmd, stdin=subprocess.PIPE, shell=True)

-         os.dup2(tee.stdin.fileno(), sys.stdout.fileno())

-         os.dup2(tee.stdin.fileno(), sys.stderr.fileno())

- 

      def produce_srpm(self, spec, sources, configdir, resultdir):

          cmd = [

              "unbuffer", "/usr/bin/mock",

@@ -117,10 +83,8 @@ 

          for without_opt in self.without_opts:

              cmd += ["--without", without_opt]

  

-         log.info('Running: {0}'.format(' '.join(cmd)))

- 

          process = GentlyTimeoutedPopen(cmd, stdin=subprocess.PIPE,

-                 preexec_fn=self.preexec_fn_build_stream, timeout=self.timeout)

+                 timeout=self.timeout)

  

          try:

              process.communicate()

@@ -132,6 +96,7 @@ 

          if process.returncode != 0:

              raise RuntimeError("Build failed")

  

+ 

      def produce_rpm(self, srpm, configdir, resultdir):

          cmd = ["unbuffer", "/usr/bin/mock",

                 "--rebuild", srpm,

@@ -146,10 +111,8 @@ 

          for without_opt in self.without_opts:

              cmd += ["--without", without_opt]

  

-         log.info('Running: {0}'.format(' '.join(cmd)))

- 

          process = GentlyTimeoutedPopen(cmd, stdin=subprocess.PIPE,

-                 preexec_fn=self.preexec_fn_build_stream, timeout=self.timeout)

+                 timeout=self.timeout)

  

          try:

              process.communicate()

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

  import rpm

  import glob

  import os

+ import sys

  import re

  import shutil

  import fileinput

@@ -11,6 +12,7 @@ 

  import pprint

  import datetime

  import pipes

+ from threading import Timer

  

  try:

      from urllib.parse import urlparse

@@ -41,6 +43,10 @@ 

      log.debug("")

  

  

+ def cmd_readable(cmd):

+     return ' '.join([pipes.quote(part) for part in cmd])

+ 

+ 

  def run_cmd(cmd, cwd=".", preexec_fn=None):

      """

      Runs given command in a subprocess.

@@ -52,7 +58,7 @@ 

      :raises RuntimeError

      :returns munch.Munch(cmd, stdout, stderr, returncode)

      """

-     log.info('Running: {cmd}'.format(cmd=' '.join(cmd)))

+     log.info('Running: ' + cmd_readable(cmd))

      process = subprocess.Popen(

          cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE, cwd=cwd, preexec_fn=preexec_fn)

      try:

@@ -273,3 +279,41 @@ 

          repo_configs.append(repo_config)

  

      return repo_configs

+ 

+ 

+ def dump_live_log(logfile):

+     filter_continuing_lines = r"sed 's/.*\x0D\([^\x0a]\)/\1/g' --unbuffered"

+     tee_output = "tee -a {0}".format(pipes.quote(logfile))

+     cmd = filter_continuing_lines + "|" + tee_output

+     tee = subprocess.Popen(cmd, stdin=subprocess.PIPE, shell=True)

+     os.dup2(tee.stdin.fileno(), sys.stdout.fileno())

+     os.dup2(tee.stdin.fileno(), sys.stderr.fileno())

+ 

+ 

+ class GentlyTimeoutedPopen(subprocess.Popen):

+     timers = []

+ 

+     def __init__(self, cmd, timeout=None, **kwargs):

+         log.info('Running (timeout={to}): {cmd}'.format(

+             to=str(timeout),

+             cmd=cmd_readable(cmd),

+         ))

+ 

+         super(GentlyTimeoutedPopen, self).__init__(cmd, **kwargs)

+         if not timeout:

+             return

+ 

+         def timeout_cb(me, string, signal):

+             log.error(" !! Copr timeout => sending {0}".format(string))

+             me.send_signal(signal)

+ 

+         delay = timeout

+         for string, signal in [('INT', 2), ('TERM', 15), ('KILL', 9)]:

+             timer = Timer(delay, timeout_cb, [self, string, signal])

+             timer.start()

+             self.timers.append(timer)

+             delay = delay + 10

+ 

+     def done(self):

+         for timer in self.timers:

+             timer.cancel()

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

          self.chroot = source_json.get('chroot')

          self.inner_resultdir = source_json.get('resultdir')

          self.builddeps = source_json.get('builddeps')

+         self.timeout = source_json.get("timeout", 3600)

  

          if 'hook_data' in source_json:

              self.hook_payload_url = "{server}/tmp/{tmp}/hook_payload".format(

@@ -86,12 +87,22 @@ 

                  self.inner_workdir, self.inner_resultdir))

  

          # prepare the sources

-         helpers.run_cmd(cmd)

+         process = helpers.GentlyTimeoutedPopen(cmd, timeout=self.timeout)

+         try:

+             process.communicate()

+         except OSError as e:

+             raise RuntimeError(str(e))

+         finally:

+             process.done()

+ 

+         if process.returncode != 0:

+             raise RuntimeError("Build failed")

  

          # copy the sources out into workdir

          mock = ['mock', '-r', mock_config_file]

  

          srpm_srcdir = os.path.join(self.workdir, 'srcdir')

+ 

          helpers.run_cmd(mock + ['--copyout', inner_resultdir, srpm_srcdir])

          helpers.run_cmd(mock + ['--scrub', 'all'])

          helpers.build_srpm(srpm_srcdir, self.outdir)

file modified
+6 -3

@@ -24,7 +24,8 @@ 

  from copr_rpmbuild import providers

  from copr_rpmbuild.builders.mock import MockBuilder

  from copr_rpmbuild.helpers import read_config, extract_srpm, locate_srpm, \

-     SourceType, parse_copr_name, get_additional_repo_configs, copr_chroot_to_task_id

+     SourceType, parse_copr_name, get_additional_repo_configs, \

+     copr_chroot_to_task_id, dump_live_log

  

  try:

      from urllib.parse import urlparse, urljoin

@@ -132,8 +133,10 @@ 

      pidfile.close()

  

      # Log also to a file

-     open(config.get("main", "logfile"), 'w').close() # truncate log

-     log.addHandler(logging.FileHandler(config.get("main", "logfile")))

+     logfile = config.get("main", "logfile")

+     if logfile:

+         open(logfile, 'w').close() # truncate log

+         dump_live_log(logfile)

  

      log.info('Running: {0}'.format(" ".join(map(pipes.quote, sys.argv))))

      log.info('Version: {0}'.format(VERSION))

file modified
+1 -2

@@ -48,7 +48,7 @@ 

          self.resultdir = "/path/to/resultdir"

          self.config = configparser.RawConfigParser()

          self.config.add_section('main')

-         self.config.set('main', 'logfile', '/path/to/logfile')

+         self.config.set('main', 'logfile', '/dev/null')

  

      def test_init(self):

          builder = MockBuilder(self.task, self.sourcedir, self.resultdir, self.config)

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

                        '--uniqueext', '2',

                        '-r', 'child']

          popen_mock.assert_called_with(assert_cmd, stdin=subprocess.PIPE,

-                                       preexec_fn=builder.preexec_fn_build_stream,

                                        timeout=21600)

  

      @mock.patch('{0}.open'.format(builtins), new_callable=mock.mock_open())

  • custom method uses GentlyTimeoutedPopen to not buffer outputs
    by helpers.run_cmd(), and it is wise to have some timeout, too
  • print the debugging commands pipes.quote()'d
  • the overall live log for source methods is now processed
    through "sed && tee" pair (as already has been done in mock.py
    so far), instead of additional logger handler
  • print the debug command directly by GentlyTimeoutedPopen

rebased onto a5cb501

a year ago

CI shows us that this is non-breaking change; and nobody reacted for a few days.
I'd merge this tomorrow if there are no complaints.

Pull-Request has been merged by msuchy

a year ago