From d9682472b3204c6ccab3c19cb713086ff92da25d Mon Sep 17 00:00:00 2001
From: Mike McLean <mikem@redhat.com>
Date: May 03 2018 18:52:30 +0000
Subject: PR#777: add debug timestamp log for logs


Merges #777
https://pagure.io/koji/pull-request/777

Fixes: #776
https://pagure.io/koji/issue/776
Add timestamps to logs

---

diff --git a/builder/kojid b/builder/kojid
index f9f46d2..c2ac6c7 100755
--- a/builder/kojid
+++ b/builder/kojid
@@ -381,6 +381,7 @@ class BuildRoot(object):
             uploadpath = self.getUploadPath()
             logs = {}
 
+            ts_offsets = {}
             finished = False
             while not finished:
                 time.sleep(1)
@@ -398,10 +399,36 @@ class BuildRoot(object):
                     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(resultdir, ts_name)
+                            if os.path.exists(fpath):
+                                with open(fpath, 'rt') as ts_file:
+                                    lines = ts_file.readlines()
+                                    if lines:
+                                        last = int(lines[-1].split()[1])
+                                        ts_offsets[fname] = last
+                            else:
+                                with open(fpath, 'a') 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 open(fpath, 'rt') as ts_file:
+                                    lines = ts_file.readlines()
+                                    if lines:
+                                        last = int(lines[-1].split()[1])
+                                        ts_offsets[mocklog] = last
+                            else:
+                                with open(fpath, 'a') 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:
@@ -414,18 +441,34 @@ class BuildRoot(object):
                                 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 = file(fpath, 'r')
-                        logs[fname] = (fd, stat_info.st_ino, stat_info.st_size, fpath)
+                            fd = open(fpath, 'r')
+                        logs[fname] = (fd, stat_info.st_ino, stat_info.st_size or size, fpath)
                     except:
                         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(resultdir, '%s-ts.log' % fname)
+                            with open(fpath, 'a') as ts_file:
+                                ts_file.write('%.0f %i\n' % (time.time(), position))
+                            ts_offsets[fname] = position
                     incremental_upload(self.session, fname, fd, uploadpath, logger=self.logger)
+
             #clean up and return exit status of command
             for (fname, (fd, inode, size, fpath)) in logs.items():
-                if fd:
-                    fd.close()
+                if not fd:
+                    continue
+                if fname.endswith('-ts.log'):
+                    # finish upload of ts.log as they could've been missed in
+                    # last iteration
+                    incremental_upload(self.session, fname, fd, uploadpath, logger=self.logger)
+                fd.close()
             return status[1]
 
         else:
@@ -5667,6 +5710,7 @@ def get_options():
                 'offline_retry': True,
                 'offline_retry_interval': 120,
                 'keepalive' : True,
+                'log_timestamps': False,
                 'timeout' : None,
                 'no_ssl_verify' : False,
                 'use_fast_upload': True,
@@ -5696,7 +5740,7 @@ def get_options():
             elif name in ['offline_retry', 'use_createrepo_c',  'createrepo_skip_stat',
                           'createrepo_update', 'keepalive', 'use_fast_upload',
                           'support_rpm_source_layout', 'krb_rdns', 'krb_canon_host',
-                          'build_arch_can_fail', 'no_ssl_verify']:
+                          'build_arch_can_fail', 'no_ssl_verify', 'log_timestamps']:
                 defaults[name] = config.getboolean('kojid', name)
             elif name in ['plugin', 'plugins']:
                 defaults['plugin'] = value.split()
diff --git a/builder/kojid.conf b/builder/kojid.conf
index 1a49ebe..f22ce95 100644
--- a/builder/kojid.conf
+++ b/builder/kojid.conf
@@ -92,3 +92,8 @@ from_addr=Koji Build System <buildsys@example.com>
 
 ;if set to True, failing subtask will not automatically cancel other siblings
 ;build_arch_can_fail = False
+
+;if set to True additional logs with timestamps will get created and uploaded
+;to hub. It could be useful for debugging purposes, but creates twice as many
+;log files
+;log_timestamps = False