PR#721: Fixup copr-rpmbuild logging - copr/copr

		`@@ -5,6 +5,7 @@`
		`import multiprocessing`
		`import pipes`
		`import glob`
		`+ import errno`
		`from setproctitle import setproctitle`

		`from ..exceptions import MockRemoteError, CoprWorkerError, VmError, CoprBackendSrpmError`
		`@@ -158,10 +159,10 @@`
		`self.mark_running(job)`

		`# setup our target dir locally`
		`- if not os.path.exists(job.chroot_dir):`
		`- try:`
		`- os.makedirs(job.chroot_dir)`
		`- except (OSError, IOError):`
		`+ try:`
		`+ os.makedirs(job.chroot_dir)`
		`+ except OSError as e:`
		`+ if e.errno != errno.EEXIST:`
		`self.log.exception("Could not make results dir for job: %s",`
		`job.chroot_dir)`
		`failed = True`
		`@@ -202,6 +203,7 @@`

		`mr.check_build_success() # raises if build didn't succeed`
		`mr.download_results()`
		`+ mr.cleanup_builder()`

		`except MockRemoteError as e:`
		`# record and break`
		`@@ -209,7 +211,9 @@`
		`"Error during the build, host=%s, build_id=%s, chroot=%s",`
		`self.vm.vm_ip, job.build_id, job.chroot)`
		`failed = True`
		`- mr.download_results()`
		`+ mr.download_results(can_fail=True)`
		`+ # the builder is stil believed to work`
		`+ mr.cleanup_builder()`

		`except SSHConnectionError as err:`
		`self.log.exception(`

backend/backend/mockremote/__init__.py

file modified

+6 -1

		`@@ -288,10 +288,12 @@`
		`except BuilderError as error:`
		`raise MockRemoteError("Build {} failed".format(self.job))`

		`- def download_results(self):`
		`+ def download_results(self, can_fail=False):`
		`try:`
		`self.builder.download_results(self.job.results_dir)`
		`except Exception as err:`
		`+ if not can_fail:`
		`+ raise MockRemoteError("Can not download build results")`
		`self.log.exception(err)`

		`def mark_dir_with_build_id(self):`
		`@@ -310,3 +312,6 @@`

		`except Exception as error:`
		`self.log.exception("Failed to mark build {} with build_id".format(error))`
		`+`
		`+ def cleanup_builder(self):`
		`+ self.builder.cleanup_after_build()`

backend/backend/mockremote/builder.py

file modified

		`@@ -153,6 +153,11 @@`
		`def reattach(self):`
		`self.attach_to_build()`

		`+ def cleanup_after_build(self):`
		`+ self.log.info("Removing pid file")`
		`+ cmd = '/bin/rm -f /var/lib/copr-rpmbuild/pid'`
		`+ self.conn.run_expensive(cmd)`
		`+`
		`def rsync_call(self, source_path, target_path):`
		`# TODO: sshcmd.py uses pre-allocated socket, use it here, too`
		`ensure_dir_exists(target_path, self.log)`

rpmbuild/copr_rpmbuild/builders/mock.py

file modified

-2

		`@@ -25,10 +25,8 @@`
		`self.sourcedir = sourcedir`
		`self.resultdir = resultdir`
		`self.config = config`
		`- self.logfile = self.config.get("main", "logfile")`

		`def run(self):`
		`- open(self.logfile, 'w').close() # truncate logfile`
		`configdir = os.path.join(self.resultdir, "configs")`
		`self.prepare_configs(configdir)`

rpmbuild/copr_rpmbuild/helpers.py

file modified

+14 -7

		`@@ -236,13 +236,20 @@`
		`return ownername, projectname`


		`- 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())`
		`+ def dump_live_log(filename):`
		`+ sed = subprocess.Popen(`
		`+ ['sed', r"s/.*\x0D\([^\x0a]\)/\1/g", '--unbuffered'],`
		`+ stdin=subprocess.PIPE,`
		`+ stdout=subprocess.PIPE,`
		`+ )`
		`+`
		`+ tee = subprocess.Popen(`
		`+ ['tee', '-a', filename],`
		`+ stdin=sed.stdout`
		`+ )`
		`+`
		`+ os.dup2(sed.stdin.fileno(), sys.stdout.fileno())`
		`+ os.dup2(sed.stdin.fileno(), sys.stderr.fileno())`


		`class GentlyTimeoutedPopen(subprocess.Popen):`

rpmbuild/main.py

file modified

+45 -31

		`@@ -2,7 +2,6 @@`

		`import re`
		`import os`
		`- import fcntl`
		`import sys`
		`import argparse`
		`import requests`
		`@@ -15,6 +14,9 @@`
		`import stat`
		`import pipes`
		`import pkg_resources`
		`+ import errno`
		`+ import daemon`
		`+ import time`

		`try:`
		`from simplejson.scanner import JSONDecodeError`
		`@@ -30,39 +32,44 @@`

		`log = logging.getLogger(__name__)`
		`log.setLevel(logging.INFO)`
		`- log.addHandler(logging.StreamHandler(sys.stdout))`
		`+ log.addHandler(logging.StreamHandler(sys.stderr))`

		`try:`
		`VERSION = pkg_resources.require('copr-rpmbuild')[0].version`
		`except pkg_resources.DistributionNotFound:`
		`VERSION = 'git'`

		`- def daemonize():`
		`+`
		`+ def daemonize(pidfilename):`
		`try:`
		`pid = os.fork()`
		`except OSError as e:`
		`- self.log.error("Unable to fork, errno: {0}".format(e.errno))`
		`+ log.error("Unable to fork, errno: {0}".format(e.errno))`
		`sys.exit(1)`

		`if pid != 0:`
		`- log.info(pid)`
		`- os._exit(0)`
		`-`
		`- process_id = os.setsid()`
		`- if process_id == -1:`
		`+ # wait till child writes the PID into pidfile`
		`+ start = time.time()`
		`+ while time.time() - start < 10:`
		`+ # try-except not needed, pidfilename always exists`
		`+ with open(pidfilename, 'r') as pidfile:`
		`+ content = pidfile.read()`
		`+ if content.endswith("\n"):`
		`+ sys.stdout.write(content)`
		`+ sys.exit(0)`
		`+ time.sleep(0.1)`
		`+ log.error("Unable to wait for PID")`
		`sys.exit(1)`

		`- devnull_fd = os.open('/dev/null', os.O_RDWR)`
		`- os.dup2(devnull_fd, 0)`
		`- os.dup2(devnull_fd, 1)`
		`- os.dup2(devnull_fd, 2)`
		`- os.close(devnull_fd)`
		`+ c = daemon.DaemonContext()`
		`+ c.open()`


		`def get_parser():`
		`shared_parser = argparse.ArgumentParser(add_help=False)`
		`shared_parser.add_argument("-d", "--detached", default=False, action="store_true",`
		`- help="Run build in background. Log into /var/lib/copr-rpmbuild/main.log.")`
		`+ help="Run build in background. Log into /var/lib/copr-rpmbuild/main.log. "`
		`+ "Print PID of the background process.")`
		`shared_parser.add_argument("-v", "--verbose", action="count",`
		`help="Print debugging information.")`
		`shared_parser.add_argument("-r", "--chroot",`
		`@@ -117,15 +124,28 @@`
		`if args.verbose:`
		`log.setLevel(logging.DEBUG)`

		`+ # Create the pidfile`
		`+ pidfilename = config.get("main", "pidfile")`
		`+ try:`
		`+ os.open(pidfilename, os.O_CREAT \| os.O_WRONLY \| os.O_EXCL)`
		`+ except OSError as e:`
		`+ if e.errno == errno.EEXIST:`
		`+ log.error("Either another build is running, or the file "`
		`+ "'{0}' is forgotten".format(pidfilename))`
		`+ sys.exit(1)`
		`+ raise(e)`
		`+`
		`+ # Switch to background, if requested`
		`if args.detached:`
		`- daemonize()`
		`+ daemonize(pidfilename)`

		`- # Write pid`
		`- pidfile = open(config.get("main", "pidfile"), "w")`
		`- pidfile.write(str(os.getpid()))`
		`- pidfile.close()`
		`+ # Let the main process (if --detached) know ASAP what is our PID. Note that`
		`+ # the info is also used by copr-backend when re-attaching to running builds`
		`+ # after 'systemctl restart'.`
		`+ with open(pidfilename, 'w') as pidfile:`
		`+ pidfile.write("{0}\n".format(os.getpid()))`

		`- # Log also to a file`
		`+ # Redirect stderr to stdout, and then copy stdout to logfile`
		`logfile = config.get("main", "logfile")`
		`if logfile:`
		`open(logfile, 'w').close() # truncate log`
		`@@ -134,10 +154,7 @@`
		`log.info('Running: {0}'.format(" ".join(map(pipes.quote, sys.argv))))`
		`log.info('Version: {0}'.format(VERSION))`

		`- # Allow only one instance`
		`- lockfd = os.open(config.get("main", "lockfile"), os.O_RDWR \| os.O_CREAT)`
		`try:`
		`- fcntl.lockf(lockfd, fcntl.LOCK_EX, 1)`
		`init(args, config)`

		`if args.dump_configs:`
		`@@ -148,15 +165,12 @@`
		`action = build_rpm`

		`action(args, config)`
		`- except (RuntimeError, OSError):`
		`- log.exception("")`
		`+ except RuntimeError as e:`
		`+ log.exception(e)`
		`sys.exit(1)`
		`- except: # Programmer's mistake`
		`- log.exception("")`
		`+ except Exception as e: # Programmer's mistake`
		`+ log.exception(e)`
		`sys.exit(1)`
		`- finally:`
		`- fcntl.lockf(lockfd, fcntl.LOCK_UN, 1)`
		`- os.close(lockfd)`


		`def init(args, config):`