[tools][Sprint 201711.2] logging timestamp lost sub-second precision (+ longer debug lines with not much helpful content)
I deleted poo#29190 by mistake.
- Author: okurz
- Status: New
- Priority: Normal
- Assignee: dasantiago
- Category: Concrete Bugs
* Target version: Ready¶
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
[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')
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
#1 Updated by dasantiago over 2 years ago
I deleted by mistake poo#29190.
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.
printf "[%s.%04d] [$level] ", (POSIX::strftime "%H:%M:%S", gmtime($time)), 10000 * ($time - int($time)
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