Project

General

Profile

Actions
Copy link

action #29304

closed

[tools][Sprint 201711.2] logging timestamp lost sub-second precision (+ longer debug lines with not much helpful content)

Added by dasantiago about 7 years ago. Updated almost 7 years ago.

Status:
Resolved
Priority:
Normal
Assignee:
dasantiago
Category:
Regressions/Crashes
Target version:
Done
Start date:
2017-12-12
Due date:
% Done:

100%

Estimated time:

Description

I deleted poo#29190 by mistake.

  • Author: okurz
  • Status: New
  • Priority: Normal
  • Assignee: dasantiago
  • Category: Concrete Bugs

* Target version: Ready

Observation

before:

06:26:04.7286 Debug: /var/lib/openqa/share/tests/opensuse/tests/console/consoletest
_setup.pm:64 called testapi::script_run
06:26:04.7286 <<< type_string(string='ps axf > /tmp/psaxf.log', max_interval=250)
06:26:05.8347 WARNING: enqueue_screenshot took 0.57 seconds - slow IO? (opencv: 0.5
2 - encoder: 0.05)
06:26:08.7880 Debug: /var/lib/openqa/share/tests/opensuse/tests/console/consoletest
_setup.pm:64 called testapi::script_run

after:

[Sun Dec 10 00:38:14 2017] [21440:debug] <<< testapi::wait_serial(timeout=30, regex
p=qr/(?^:4_rLE-\d+-)/)
[Sun Dec 10 00:38:20 2017] [21440:debug] >>> testapi::wait_serial: (?^:4_rLE-\d+-):
 ok
[Sun Dec 10 00:38:20 2017] [21440:debug] <<< testapi::upload_logs(file='/tmp/y2logs
_clone.tar.bz2')

Problem

I think the problem was introduced with https://github.com/os-autoinst/os-autoinst/pull/876 trying to harmonize the logging format among openQA and os-autoinst which is good but:

  • P1: The sub-second precision output is helpful to understand timing behaviour of tests -> should come back
  • P2: The whole string prefix "[Sun Dec 10 00:38:20 2017] [21440:debug]" is a bit long
  • P3: The mixed date/time format is not following a common standard. How about using ISO 8601
Actions
Copy link
 #1

Updated by dasantiago about 7 years ago

I deleted by mistake poo#29190.

Comments:

Issue #29190 has been updated by dasantiago.
I'll change the timestamp.

However i've some questions, regarding the precision.

According to the Mojo::Log documentation, how the logger prints to the log, is specified via a callback which contains as input parameter the time. This time however doesn't contain the micro-seconds. So i don't have the requested info.

For example:

printf "[%s.%04d] [$level] ", (POSIX::strftime "%H:%M:%S", gmtime($time)), 10000 * ($time - int($time)

will print

[16:55:42.0000] [debug]

I can however do Time::HiRes::gettimeofday, but i'm not really sure if doing this will defeat the Okurz's goal and if the information then printed will be entirely correct, as the callback invocation, might not occur immediately.

Issue #29190 has been updated by okurz.
This might mean that mojo::log is not usable for the test log output or patch mojo::log. The mojo upstream maintainer also works for SUSE ;) it's kraih

Issue #29190 has been updated by coolo.
well, the code in mojo::log is:

  push @$history, my $msg = [time, $level, @_];
  shift @$history while @$history > $max;

  $self->append($self->format->(@$msg));

And the format callback is what you overload. So the log is still pretty sync - so just ignore the time argument and calculate it yourself hires.

Actions
Copy link
 #2

Updated by okurz about 7 years ago

The output format as in http://tragicbox.suse.cz/tests/23/file/autoinst-log.txt is nice, it's ISO 8601 :) The worker output though still differs or differs now again:

[Tue Dec 12 11:29:07 2017] [debug] running on tragicbox:1 (Linux 4.4.92-31-default #1 SMP Sun Oct 22 06:56:24 UTC 2017 (1d80e8a) x86_64)
[2017-12-12T11:29:07.0440 CET] [debug] git hash in /var/lib/openqa/share/tests/sle: 2398807b14a5bc78d81646d2ad63eaa5576496b8
Actions
Copy link
 #3

Updated by dasantiago about 7 years ago

  • % Done changed from 0 to 100

PR submitted

Actions
Copy link
 #4

Updated by dasantiago about 7 years ago

  • Subject changed from logging timestamp lost sub-second precision (+ longer debug lines with not much helpful content) to [tools] logging timestamp lost sub-second precision (+ longer debug lines with not much helpful content)
Actions
Copy link
 #5

Updated by coolo about 7 years ago

  • Status changed from New to Resolved
  • Target version set to Current Sprint

merged

Actions
Copy link
 #6

Updated by szarate almost 7 years ago

  • Subject changed from [tools] logging timestamp lost sub-second precision (+ longer debug lines with not much helpful content) to [tools][Sprint 201711.2] logging timestamp lost sub-second precision (+ longer debug lines with not much helpful content)
Actions
Copy link
 #7

Updated by szarate almost 7 years ago

  • Target version changed from Current Sprint to Done
Actions
Copy link

Also available in: Atom PDF