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 over 6 years ago. Updated about 6 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

Also available in: Atom PDF