Actions
action #29304
closed[tools][Sprint 201711.2] logging timestamp lost sub-second precision (+ longer debug lines with not much helpful content)
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