copr / copr

Clone

#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

file modified
+5 -42 

@@ -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()

file modified
+45 -1 

@@ -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()

file modified
+12 -1 

@@ -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.

+1

Pull-Request has been merged by msuchy
a year ago
Changes Summary 5
+5 -42
file changed
rpmbuild/copr_rpmbuild/builders/mock.py
+45 -1
file changed
rpmbuild/copr_rpmbuild/helpers.py
+12 -1
file changed
rpmbuild/copr_rpmbuild/providers/custom.py
+6 -3
file changed
rpmbuild/main.py
+1 -2
file changed
rpmbuild/tests/test_mock.py
Powered by Pagure 5.7.9
Documentation • File an Issue • About • SSH Hostkey/Fingerprint
© 2014-2019 Red Hat, Inc. and others.