[ovirt-devel] [VDSM] Improving vdsm logging format

[Peter Portante]

On Wed, Sep 21, 2016 at 6:03 PM, Nir Soffer <nsoffer at redhat.com> wrote:
> On Wed, Sep 21, 2016 at 1:12 PM, Peter Portante <pportant at redhat.com> wrote:
>>
>>
>>
>> On Wed, Sep 21, 2016 at 2:54 AM, Michal Skrivanek
>> <michal.skrivanek at redhat.com> wrote:
>>>
>>>
>>> > On 20 Sep 2016, at 19:52, Nir Soffer <nsoffer at redhat.com> wrote:
>>> >
>>> > Hi all,
>>> >
>>> > We are reviewing patches for improving vdsm log format.
>>> >
>>> > The goal is to have more standard logging format, similar to engine
>>> > logs and other logs in the ovirt project, to make it easier to debug
>>> > and support the system.
>>> >
>>> > We know that this change will break tools people wrote to parse vdsm
>>> > logs (I wrote couple), but we find vdsm log format too painful to work
>>> > with, and we hope this is be useful in the long term.
>>> >
>>> > Please review.
>>> > https://gerrit.ovirt.org/#/q/topic:log-format
>>>
>>> Hi Nir,
>>> typically for concise changes reviewing a single patch is way easier than
>>> whole topic. I know vdsm developers prefer it that way, but please do
>>> realize it is harder for “external” people to comprehend and you get less
>>> feedback.
>>> I see example of the new format mentioned in one commit message as a link
>>> to pastebin. I suppose including a single line example in the commit message
>>> itself is a bit more persistent
>>>
>>> Just two notes - big -1 on moving the thread id further down the line.
>>> Typically this is the only thing with some continuity, making it the most
>>> important thing to see. Putting it at a fixed aligned position somewhere at
>>> the beginning of the line would help a lot.
>>> Do we switch to UTC timestamp or still want to use local time? It does
>>> make it a bit hard to correlate with libvirt and qemu.
>>
>>
>> Lurker chiming in here ...
>>
>> Using UTC is really important when correlating across multiple systems.
>> All of the boxes we run in production we have placed in UTC to help us
>> correlate events across our environment. We had no end of frustrations when
>> we could not find ANY logs to debug a problem due to a timezone shift.
>>
>> And keep in mind, the one reviewing events in time may not be in the same
>> timezone as well, so the original timezone information will often get
>> converted to the local timezone of that reviewer.
>
>
> I agree that using UTC is better then local time - if other logs on the
> system would use the same timezone.
>
> Currently /var/log/messages and /var/log/sanlock are the most important
> logs for me, and both are using local time. Using different time for vdsm
> will make it harder debug.

At least for /var/log/messages, rsyslog upstream now supports that
independently of the current systems timezone, see
https://github.com/rsyslog/rsyslog/commit/0ab2ba2ff2a20c2b8333259a31bb71ba4f77f5aa

Perhaps just whole system on UTC is better for most cases.

>
> Libvirt log is pretty useless now when we disabled debug logs,
> and qemu logs are even worse, mostly without any timestamps.
>
> I suggest to file a bug to switch system to use UTC by default,
> or to have an easy way to choose the logs timezone globally.
>
> To make it easier to correlate between engine and vdsm logs, we need
> to introduce back the correlation id that was removed from vdsm
> in 3.5, when we switched to jsonrpc.

That would be a powerful piece of metadata to have.

-peter

>
> Nir