From 35b4d045617c042cd829673a54fa4e4d8aab8b19 Mon Sep 17 00:00:00 2001 From: Tomas Kopecek Date: Wed, 3 Jan 2018 17:34:07 +0100 Subject: [PATCH 1/3] add debug timestamp log for logs Fixes: https://pagure.io/koji/issue/776 --- builder/kojid | 21 +++++++++++++++++++++ 1 file changed, 21 insertions(+) diff --git a/builder/kojid b/builder/kojid index f9f46d2a..d2bb79b3 100755 --- a/builder/kojid +++ b/builder/kojid @@ -381,6 +381,8 @@ class BuildRoot(object): uploadpath = self.getUploadPath() logs = {} + ts_file = None + ts_state = {} finished = False while not finished: time.sleep(1) @@ -388,6 +390,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: @@ -421,7 +427,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 78ba6ef12ea382f1efec07a0a37e4321d928a26d Mon Sep 17 00:00:00 2001 From: Tomas Kopecek Date: Wed, 7 Feb 2018 16:30:54 +0100 Subject: [PATCH 2/3] split timestamp log tu multiple files --- builder/kojid | 63 ++++++++++++++++++++++++++++++++++----------------- 1 file changed, 42 insertions(+), 21 deletions(-) diff --git a/builder/kojid b/builder/kojid index d2bb79b3..a57a3951 100755 --- a/builder/kojid +++ b/builder/kojid @@ -381,8 +381,7 @@ class BuildRoot(object): uploadpath = self.getUploadPath() logs = {} - ts_file = None - ts_state = {} + ts_offsets = {} finished = False while not finished: time.sleep(1) @@ -390,10 +389,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: @@ -404,10 +399,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: @@ -420,33 +440,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 5882904aea758e85db8e3d8dfa1ee06feca84118 Mon Sep 17 00:00:00 2001 From: Tomas Kopecek Date: Thu, 8 Feb 2018 13:32:56 +0100 Subject: [PATCH 3/3] make timestamp logs configurable --- builder/kojid | 36 +++++++++++++++++++----------------- builder/kojid.conf | 5 +++++ 2 files changed, 24 insertions(+), 17 deletions(-) diff --git a/builder/kojid b/builder/kojid index a57a3951..c2ac6c71 100755 --- a/builder/kojid +++ b/builder/kojid @@ -399,7 +399,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): @@ -416,18 +416,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: @@ -447,7 +448,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() @@ -464,8 +465,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] @@ -5709,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, @@ -5738,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 1a49ebe4..f22ce950 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