#777 add debug timestamp log for logs
Merged 4 years ago by mikem. Opened 4 years ago by tkopecek.
tkopecek/koji issue776  into  master

file modified
+49 -5
@@ -376,6 +376,7 @@ 

              uploadpath = self.getUploadPath()

              logs = {}

  

+             ts_offsets = {}

              finished = False

              while not finished:

                  time.sleep(1)
@@ -393,10 +394,36 @@ 

                      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:
@@ -409,18 +436,34 @@ 

                                  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:
@@ -5633,6 +5676,7 @@ 

                  'offline_retry': True,

                  'offline_retry_interval': 120,

                  'keepalive' : True,

+                 'log_timestamps': False,

                  'timeout' : None,

                  'no_ssl_verify' : False,

                  'use_fast_upload': True,
@@ -5662,7 +5706,7 @@ 

              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()

file modified
+5
@@ -92,3 +92,8 @@ 

  

  ;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

Does this make sense? I would also add a config option if we want to go this way.

I wonder about having it all in one file. It is definitely simpler, but this forces us to put the filename on each line. Seems like a lot of duplication.

Perhaps ts_offsets instead of ts_state?

Do we need the header in the file?

Should we make our granularity configurable?

The %f format for the time seems like overkill. We can never be that granular. Might be best to just use %.0f.

At some point (probably as follow-on work), we might want to add some code that can combine the timestamp data with the logs on the fly, perhaps even have the web offer that option.

3 new commits added

  • make timestamp logs configurable
  • split timestamp log to multiple files
  • wip
4 years ago

rebased onto d285c5e

4 years ago

Rebased due to merge conflict, added split logs and configuration. Also fixed some problem with multiple opening of ts.log leading to non-monotonous values.

Commit d968247 fixes this pull-request

Pull-Request has been merged by mikem

4 years ago