From 60b71020f0e5acd3edcf68a0f25793ed0719ce65 Mon Sep 17 00:00:00 2001
From: Mike McLean <mikem@redhat.com>
Date: Mar 13 2024 09:09:15 +0000
Subject: split out buildroot log watching logic


---

diff --git a/builder/kojid b/builder/kojid
index 1f8cf34..767a0c0 100755
--- a/builder/kojid
+++ b/builder/kojid
@@ -24,6 +24,7 @@
 from __future__ import absolute_import, division
 
 import copy
+import errno
 import filecmp
 import glob
 import grp
@@ -471,99 +472,21 @@ class BuildRoot(object):
         mocklog = 'mock_output.log'
         pid = os.fork()
         if pid:
-            resultdir = self.resultdir()
-            logs = {}
+            log_patterns = ['%s/*.log' % self.resultdir()]
+            if workdir:
+                log_patterns.append('%s/%s' % (workdir, mocklog))
+            logs = BuildRootLogs(self, log_patterns, with_ts=self.options.log_timestamps)
 
-            ts_offsets = {}
             finished = False
             while not finished:
                 time.sleep(1)
                 status = os.waitpid(pid, os.WNOHANG)
                 if status[0] != 0:
                     finished = True
-
-                try:
-                    results = os.listdir(resultdir)
-                except OSError:
-                    # will happen when mock hasn't created the resultdir yet
-                    results = []
-
-                for fname in results:
-                    if fname.endswith('.log') and fname not in logs:
-                        fpath = os.path.join(resultdir, fname)
-                        logs[fname] = (None, None, 0, fpath)
-                        if self.options.log_timestamps and not fname.endswith('-ts.log'):
-                            ts_name = '%s-ts.log' % fname
-                            fpath = os.path.join(workdir, ts_name)
-                            if os.path.exists(fpath):
-                                with koji._open_text_file(fpath) as ts_file:
-                                    lines = ts_file.readlines()
-                                    if lines:
-                                        last = int(lines[-1].split()[1])
-                                        ts_offsets[fname] = last
-                            else:
-                                with koji._open_text_file(fpath, 'at') as ts_file:
-                                    ts_file.write('%.0f 0\n' % time.time())
-                            logs[ts_name] = (None, None, 0, fpath)
-                if workdir and mocklog not in logs:
-                    fpath = os.path.join(workdir, mocklog)
-                    if os.path.exists(fpath):
-                        logs[mocklog] = (None, None, 0, fpath)
-                        if self.options.log_timestamps:
-                            ts_name = '%s-ts.log' % mocklog
-                            fpath = os.path.join(workdir, ts_name)
-                            if os.path.exists(fpath):
-                                with koji._open_text_file(fpath) as ts_file:
-                                    lines = ts_file.readlines()
-                                    if lines:
-                                        last = int(lines[-1].split()[1])
-                                        ts_offsets[mocklog] = last
-                            else:
-                                with koji._open_text_file(fpath, 'at') as ts_file:
-                                    ts_file.write('%.0f 0\n' % time.time())
-                            logs[ts_name] = (None, None, 0, fpath)
-
-                for (fname, (fd, inode, size, fpath)) in logs.items():
-                    try:
-                        stat_info = os.stat(fpath)
-                        if not fd or stat_info.st_ino != inode or stat_info.st_size < size:
-                            # either a file we haven't opened before, or mock replaced a file we
-                            # had open with a new file and is writing to it, or truncated the file
-                            # we're reading, but our fd is pointing to the previous location in the
-                            # old file
-                            if fd:
-                                self.logger.info('Rereading %s, inode: %s -> %s, size: %s -> %s' %
-                                                 (fpath, inode, stat_info.st_ino, size,
-                                                  stat_info.st_size))
-                                fd.close()
-                            fd = open(fpath, 'rb')
-                        logs[fname] = (fd, stat_info.st_ino, stat_info.st_size or size, fpath)
-                    except Exception:
-                        self.logger.error("Error reading mock log: %s", fpath)
-                        self.logger.error(''.join(traceback.format_exception(*sys.exc_info())))
-                        continue
-
-                    if self.options.log_timestamps and not fname.endswith('-ts.log'):
-                        # race condition against incremental_upload's tell,
-                        # but with enough precision for ts.log purposes
-                        position = fd.tell()
-                        ts_offsets.setdefault(fname, 0)
-                        if ts_offsets[fname] < position:
-                            fpath = os.path.join(workdir, '%s-ts.log' % fname)
-                            with koji._open_text_file(fpath, 'at') as ts_file:
-                                ts_file.write('%.0f %i\n' % (time.time(), position))
-                            ts_offsets[fname] = position
-                    self.incremental_log(fname, fd)
+                logs.sync_logs()
 
             # clean up and return exit status of command
-            for (fname, (fd, inode, size, fpath)) in logs.items():
-                if not fd:
-                    continue
-                if fname.endswith('-ts.log'):
-                    # finish upload of ts.log as they could've been missed in
-                    # last iteration
-                    self.incremental_log(fname, fd)
-                fd.close()
+            logs.close_logs()
             return status[1]
 
         else:
@@ -1008,6 +931,163 @@ class BuildRoot(object):
         self.session.host.setBuildRootState(self.id, 'EXPIRED')
 
 
+class BuildRootLogs(object):
+
+    "Track the logs generated during a mock run"
+
+    def __init__(self, broot, patterns, with_ts=False):
+        self.broot = broot
+        self.patterns = patterns
+        self.with_ts = with_ts
+
+        self.loginfo = {}
+        self.ts_logs = {}
+        self.ignored = set()
+        self.names = {}
+        self.logger = broot.logger
+        self.workdir = getattr(broot, 'workdir', None)
+        if with_ts and self.workdir is None:
+            self.logger.error('No workdir defined -- disabling log timestamps')
+            self.with_ts = False
+
+    def match_logs(self):
+        matches = []
+        seen = set()
+        for pattern in self.patterns:
+            self.logger.debug('Looking for logs matching %r', pattern)
+            m = glob.glob(pattern)
+            self.logger.debug('Matches: %r', m)
+            for path in m:
+                if path not in seen:
+                    matches.append(path)
+        return matches
+
+    def add_log(self, path):
+        if path in self.loginfo or path in self.ignored:
+            return
+        if path.endswith('-ts.log'):
+            self.logger.error('ignoring stray ts log: %s', path)
+            self.ignored.add(path)
+            return
+
+        # pick a unique name for upload if there is overlap
+        fname = os.path.basename(path)
+        if fname in self.names:
+            base, ext = os.path.splitext(fname)
+            for n in range(99):
+                fname = '%s.DUP%02i%s' % (base, n, ext)
+                if fname not in self.names:
+                    self.logger.debug('Using log name alias %s for %s', fname, path)
+                    break
+            else:
+                self.logger.error('Unable to find unique log name for %s', path)
+                self.ignored.add(path)
+                return
+
+        info = {'name': fname, 'path': path}
+        self.names[fname] = info
+        self.loginfo[path] = info
+        self.logger.debug('Watching buildroot log: %r', info)
+
+        if self.with_ts:
+            self.add_ts_log(info)
+
+    def add_ts_log(self, info):
+        ts_name = '%(name)s-ts.log' % info
+        ts_path = os.path.join(self.workdir, ts_name)
+
+        offset = 0
+        if os.path.exists(ts_path):
+            # XXX should this even happen?
+            # read last offset from existing ts file
+            with koji._open_text_file(ts_path) as ts_file:
+                lines = ts_file.readlines()
+                if lines:
+                    offset = int(lines[-1].split()[1])
+        else:
+            # initialize ts file at zero
+            with koji._open_text_file(ts_path, 'at') as ts_file:
+                ts_file.write('%.0f 0\n' % time.time())
+
+        info['offset'] = offset
+        info['ts_log'] = ts_path
+        self.ts_logs[ts_path] = {'name': ts_name, 'path': ts_path, 'ts': True}
+        self.logger.debug('Watching timestamp log: %r', info)
+
+    def get_logs(self):
+        for info in self.loginfo.values():
+            yield info
+        for info in self.ts_logs.values():
+            yield info
+
+    def sync_logs(self):
+        paths = self.match_logs()
+
+        for fpath in paths:
+            if fpath not in self.loginfo:
+                self.add_log(fpath)
+
+        for info in self.get_logs():
+            # note that the ts logs are listed last
+            try:
+                self.sync_log(info)
+            except OSError:
+                self.logger.error("Error reading mock log: %(path)s", info)
+                self.logger.error(''.join(traceback.format_exception(*sys.exc_info())))
+                continue
+
+    def sync_log(self, info):
+        fpath = info['path']
+        try:
+            st = os.stat(fpath)
+        except OSError as e:
+            if e.errno == errno.ENOENT:
+                if info.get('missing'):
+                    # we've already noted this, don't spam the logs
+                    return
+                self.logger.error('Log disappeared: %(path)s', info)
+                info['missing'] = True
+                return
+            raise
+        if info.get('missing'):
+            self.logger.error('Log re-appeared: %(path)s', info)
+            del info['missing']
+        fd = info.get('fd')
+        if fd is None:
+            # freshly added, we need to open it
+            fd = open(fpath, 'rb')
+            info['fd'] = fd
+        last_st = info.get('st')
+        if last_st:
+            if st.st_ino != last_st.st_ino or st.st_size < last_st.st_size:
+                # file appears to have been rewritten or truncated
+                self.logger.info('Rereading %s, inode: %s -> %s, size: %s -> %s',
+                                 fpath, last_st.st_ino, st.st_ino, last_st.st_size, st.st_size)
+                fd.close()
+                fd = open(fpath, 'rb')
+                info['fd'] = fd
+        info['st'] = st
+
+        self.broot.incremental_log(info['name'], fd)
+
+        ts_log = info.get('ts_log')
+        if ts_log and self.with_ts:
+            # race condition against incremental_upload's tell,
+            # but with enough precision for ts.log purposes
+            position = fd.tell()
+            info.setdefault('offset', 0)
+            if info['offset'] < position:
+                with koji._open_text_file(ts_log, 'at') as ts_log:
+                    ts_log.write('%.0f %i\n' % (time.time(), position))
+                info['offset'] = position
+
+    def close_logs(self):
+        for info in self.get_logs():
+            fd = info.get('fd')
+            if fd:
+                fd.close()
+
+
 class ChainBuildTask(BaseTaskHandler):
 
     Methods = ['chainbuild']
diff --git a/tests/test_builder/test_buildroot_logs.py b/tests/test_builder/test_buildroot_logs.py
new file mode 100644
index 0000000..a78d916
--- /dev/null
+++ b/tests/test_builder/test_buildroot_logs.py
@@ -0,0 +1,194 @@
+from __future__ import absolute_import
+import logging
+import mock
+import os
+import shutil
+import tempfile
+import unittest
+
+import koji.daemon
+import koji
+
+from .loadkojid import kojid
+
+
+class TestBuildRootLogs(unittest.TestCase):
+
+    def setUp(self):
+        self.broot = mock.MagicMock()
+        self.broot.logger = logging.getLogger("koji.build.buildroot")
+        self.broot.incremental_log.side_effect = self.my_incremental_log
+        self.offsets = {}
+        self.contents = {}
+        self.session = mock.MagicMock()
+        self.tempdir = tempfile.mkdtemp()
+
+    def tearDown(self):
+        shutil.rmtree(self.tempdir)
+        mock.patch.stopall()
+
+    def my_incremental_log(self, fname, fd):
+        self.offsets.setdefault(fname, []).append(fd.tell())
+        self.contents.setdefault(fname, []).append(fd.read())
+
+    def test_simple(self):
+        patterns = ['%s/*.log' % self.tempdir]
+        mylogs = ['%s/test-%02i.log' % (self.tempdir, i) for i in range(4)]
+        for fn in mylogs:
+            with open(fn, 'wt') as fo:
+                fo.write('hello\n')
+        notlogs = ['%s/test-%02i.rpm' % (self.tempdir, i) for i in range(4)]
+        for fn in notlogs:
+            with open(fn, 'wt') as fo:
+                fo.write('this is not a log')
+
+        logs = kojid.BuildRootLogs(self.broot, patterns)
+
+        # first sync
+        logs.sync_logs()
+        self.assertEqual(logs.ts_logs, {})
+        self.assertEqual(sorted(logs.loginfo.keys()), mylogs)
+        self.assertEqual(len(self.broot.incremental_log.mock_calls), 4)
+
+        # sync again, no file changes
+        self.broot.reset_mock()
+        logs.sync_logs()
+        self.assertEqual(logs.ts_logs, {})
+        self.assertEqual(sorted(logs.loginfo.keys()), mylogs)
+        self.assertEqual(len(self.broot.incremental_log.mock_calls), 4)
+
+        # new file
+        mylogs.append('%s/test-new-file.log' % self.tempdir)
+        with open(mylogs[-1], 'wt') as fo:
+            fo.write('hello')
+        self.broot.reset_mock()
+        logs.sync_logs()
+        self.assertEqual(logs.ts_logs, {})
+        self.assertEqual(sorted(logs.loginfo.keys()), mylogs)
+        self.assertEqual(len(self.broot.incremental_log.mock_calls), 5)
+
+        logs.close_logs()
+
+    def test_timestamp(self):
+        patterns = ['%s/*.log' % self.tempdir]
+        mylog = '%s/test.log' % (self.tempdir)
+        with open(mylog, 'wt') as fo:
+            fo.write('hello\n')
+        workdir = '%s/work' % self.tempdir
+        os.makedirs(workdir)
+        self.broot.workdir = workdir
+
+        logs = kojid.BuildRootLogs(self.broot, patterns, with_ts=True)
+
+        # first sync
+        with mock.patch('time.time', return_value=100):
+            logs.sync_logs()
+        self.assertEqual(sorted(logs.loginfo.keys()), [mylog])
+        ts_log = '%s/test.log-ts.log' % workdir
+        self.assertEqual(sorted(logs.ts_logs.keys()), [ts_log])
+        self.assertEqual(len(self.broot.incremental_log.mock_calls), 2)
+
+        # sync again with file update
+        self.broot.reset_mock()
+        with open(mylog, 'at') as fo:
+            fo.write('hello\n')
+        with mock.patch('time.time', return_value=200):
+            logs.sync_logs()
+
+        logs.close_logs()
+
+        with open(ts_log, 'rt') as fo:
+            contents = fo.read()
+        self.assertEqual(contents, '100 0\n100 6\n200 12\n')
+
+
+    def test_truncate(self):
+        patterns = ['%s/*.log' % self.tempdir]
+        mylog = '%s/test.log' % (self.tempdir)
+        with open(mylog, 'wt') as fo:
+            fo.write('hello\n')
+
+        logs = kojid.BuildRootLogs(self.broot, patterns)
+
+        # first sync
+        logs.sync_logs()
+        self.assertEqual(sorted(logs.loginfo.keys()), [mylog])
+
+        # truncate and rsync again
+        with open(mylog, 'wt') as fo:
+            pass
+        logs.sync_logs()
+
+        # append and sync again
+        with open(mylog, 'at') as fo:
+            fo.write('...\n')
+        logs.sync_logs()
+
+        self.assertEqual(self.contents['test.log'], [b'hello\n', b'', b'...\n'])
+
+    def test_log_disappears(self):
+        patterns = ['%s/*.log' % self.tempdir]
+        mylog = '%s/test.log' % (self.tempdir)
+        with open(mylog, 'wt') as fo:
+            fo.write('hello\n')
+
+        logs = kojid.BuildRootLogs(self.broot, patterns)
+
+        # first sync
+        logs.sync_logs()
+        self.assertEqual(sorted(logs.loginfo.keys()), [mylog])
+
+        # delete and sync again
+        os.unlink(mylog)
+        logs.sync_logs()
+
+        self.assertEqual(self.contents['test.log'], [b'hello\n'])
+
+        # and again
+        logs.sync_logs()
+        self.assertEqual(self.contents['test.log'], [b'hello\n'])
+
+        # re-create and sync
+        with open(mylog, 'wt') as fo:
+            fo.write('world\n')
+        logs.sync_logs()
+
+        self.assertEqual(self.contents['test.log'], [b'hello\n', b'world\n'])
+
+    def test_no_workdir(self):
+        patterns = ['%s/*.log' % self.tempdir]
+
+        self.broot.workdir = None
+        logs = kojid.BuildRootLogs(self.broot, patterns, with_ts=True)
+        self.assertEqual(logs.with_ts, False)
+
+    def test_name_overlap(self):
+        mylog = '%s/test.log' % (self.tempdir)
+        os.mkdir('%s/dup' % self.tempdir)
+        mydup = '%s/dup/test.log' % (self.tempdir)
+        for fn in mylog, mydup:
+            with open(fn, 'wt') as fo:
+                fo.write('hello\n')
+        patterns = [
+            '%s/*.log' % self.tempdir,
+            '%s/*/*.log' % self.tempdir,
+        ]
+
+        logs = kojid.BuildRootLogs(self.broot, patterns)
+
+        # first sync
+        logs.sync_logs()
+        self.assertEqual(sorted(logs.loginfo.keys()), [mydup, mylog])
+        self.assertEqual(logs.loginfo[mylog]['name'], 'test.log')
+        self.assertEqual(logs.loginfo[mydup]['name'], 'test.DUP00.log')
+
+    def test_stray_ts_log(self):
+        logs = kojid.BuildRootLogs(self.broot, [])
+        stray = '%s/test.log-ts.log' % (self.tempdir)
+        logs.add_log(stray)
+        if stray not in logs.ignored:
+            raise Exception('stray log not ignored')
+        if stray in logs.loginfo:
+            raise Exception('stray log not ignored')
+
+