action #29304

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

Added by dasantiago over 2 years ago. Updated about 2 years ago.

Status:ResolvedStart date:12/12/2017
Priority:NormalDue date:
Assignee:dasantiago% Done:

100%

Category:Concrete Bugs
Target version:Done
Difficulty:
Duration:

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

History

#1 Updated by dasantiago over 2 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.

#2 Updated by okurz over 2 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

#3 Updated by dasantiago over 2 years ago

  • % Done changed from 0 to 100

PR submitted

#4 Updated by dasantiago over 2 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)

#5 Updated by coolo over 2 years ago

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

merged

#6 Updated by szarate about 2 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)

#7 Updated by szarate about 2 years ago

  • Target version changed from Current Sprint to Done

Also available in: Atom PDF