From d285c5e19f95c1c4ddc51ed794b7cb32f00a2952 Mon Sep 17 00:00:00 2001
From: Tomas Kopecek <tkopecek@redhat.com>
Date: Feb 08 2018 12:34:51 +0000
Subject: [PATCH 1/3] add debug timestamp log for logs


Fixes: https://pagure.io/koji/issue/776

---

diff --git a/builder/kojid b/builder/kojid
index 26fbc6e..dc99e0c 100755
--- a/builder/kojid
+++ b/builder/kojid
@@ -376,6 +376,8 @@ class BuildRoot(object):
             uploadpath = self.getUploadPath()
             logs = {}
 
+            ts_file = None
+            ts_state = {}
             finished = False
             while not finished:
                 time.sleep(1)
@@ -383,6 +385,10 @@ class BuildRoot(object):
                 if status[0] != 0:
                     finished = True
 
+                if ts_file is None and os.path.exists(resultdir):
+                    ts_file = open(os.path.join(resultdir, 'ts.log'), 'wt')
+                    ts_file.write('filename,timestamp,offset\n')
+
                 try:
                     results = os.listdir(resultdir)
                 except OSError:
@@ -416,7 +422,22 @@ class BuildRoot(object):
                         self.logger.error(''.join(traceback.format_exception(*sys.exc_info())))
                         continue
 
+                    if ts_file and fname != 'ts.log':
+                        # race condition against incremental_upload's tell,
+                        # but with enough precision for ts.log purposes
+                        position = fd.tell()
+                        ts_state.setdefault(fname, 0)
+                        if ts_state[fname] < position:
+                            ts_file.write('%s %f %i\n' % (fname, time.time(), position))
+                            ts_state[fname] = position
                     incremental_upload(self.session, fname, fd, uploadpath, logger=self.logger)
+
+            # flush ts.log as it could be changed during previous iteration
+            # but not uploaded.
+            if ts_file:
+                ts_file.close()
+                incremental_upload(self.session, 'ts.log', logs['ts.log'][0], uploadpath, logger=self.logger)
+
             #clean up and return exit status of command
             for (fname, (fd, inode, size, fpath)) in logs.items():
                 if fd:

From 4e8fc3c038c332bf809b23f6fd31744dd1f58529 Mon Sep 17 00:00:00 2001
From: Tomas Kopecek <tkopecek@redhat.com>
Date: Feb 08 2018 12:36:13 +0000
Subject: [PATCH 2/3] split timestamp log tu multiple files


---

diff --git a/builder/kojid b/builder/kojid
index dc99e0c..8b34203 100755
--- a/builder/kojid
+++ b/builder/kojid
@@ -376,8 +376,7 @@ class BuildRoot(object):
             uploadpath = self.getUploadPath()
             logs = {}
 
-            ts_file = None
-            ts_state = {}
+            ts_offsets = {}
             finished = False
             while not finished:
                 time.sleep(1)
@@ -385,10 +384,6 @@ class BuildRoot(object):
                 if status[0] != 0:
                     finished = True
 
-                if ts_file is None and os.path.exists(resultdir):
-                    ts_file = open(os.path.join(resultdir, 'ts.log'), 'wt')
-                    ts_file.write('filename,timestamp,offset\n')
-
                 try:
                     results = os.listdir(resultdir)
                 except OSError:
@@ -399,10 +394,35 @@ 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 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)
+                        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:
@@ -415,33 +435,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 ts_file and fname != 'ts.log':
+                    if not fname.endswith('-ts.log'):
                         # race condition against incremental_upload's tell,
                         # but with enough precision for ts.log purposes
                         position = fd.tell()
-                        ts_state.setdefault(fname, 0)
-                        if ts_state[fname] < position:
-                            ts_file.write('%s %f %i\n' % (fname, time.time(), position))
-                            ts_state[fname] = position
+                        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)
 
-            # flush ts.log as it could be changed during previous iteration
-            # but not uploaded.
-            if ts_file:
-                ts_file.close()
-                incremental_upload(self.session, 'ts.log', logs['ts.log'][0], 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'):
+                    # flush ts.log as it could be changed during previous iteration
+                    # but not uploaded.
+                    incremental_upload(self.session, fname, fd, uploadpath, logger=self.logger)
+                fd.close()
             return status[1]
 
         else:

From 34e54cce03666a5541f558de754d0f5c5fb0f3ba Mon Sep 17 00:00:00 2001
From: Tomas Kopecek <tkopecek@redhat.com>
Date: Feb 08 2018 12:36:27 +0000
Subject: [PATCH 3/3] make timestamp logs configurable


---

diff --git a/builder/kojid b/builder/kojid
index 8b34203..37d08fc 100755
--- a/builder/kojid
+++ b/builder/kojid
@@ -394,7 +394,7 @@ 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 not fname.endswith('-ts.log'):
+                        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):
@@ -411,18 +411,19 @@ class BuildRoot(object):
                     fpath = os.path.join(workdir, mocklog)
                     if os.path.exists(fpath):
                         logs[mocklog] = (None, None, 0, fpath)
-                        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)
+                        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:
@@ -442,7 +443,7 @@ class BuildRoot(object):
                         self.logger.error(''.join(traceback.format_exception(*sys.exc_info())))
                         continue
 
-                    if not fname.endswith('-ts.log'):
+                    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()
@@ -459,8 +460,8 @@ class BuildRoot(object):
                 if not fd:
                     continue
                 if fname.endswith('-ts.log'):
-                    # flush ts.log as it could be changed during previous iteration
-                    # but not uploaded.
+                    # 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]
@@ -5675,6 +5676,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,
@@ -5704,7 +5706,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

