From d285c5e19f95c1c4ddc51ed794b7cb32f00a2952 Mon Sep 17 00:00:00 2001 From: Tomas Kopecek 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 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 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 ;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