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

[Nir Soffer]

Latest version show thread name before logger name, improving visibility.

Patches in this topic:

- https://gerrit.ovirt.org/64113 - logging: More standard logging format
  The main change, the next patches refine this change.

- https://gerrit.ovirt.org/64216 - logging: Use same log format in the tests
  Important to developers looking at failed tests logs

- https://gerrit.ovirt.org/64217 - logging: Improve log level alignment
  Improve alignment by shortening long log level names
  (e.g. WARNING -> WARN)

- https://gerrit.ovirt.org/64227 - logging: Unify SimpleLogAdapter format
  Improves vm logs

Please review.

Thanks,
Nir

On Thu, Sep 22, 2016 at 12:49 AM, Nir Soffer  wrote:
> On Wed, Sep 21, 2016 at 4:47 PM, Roman Hodain  wrote:
>>
>> Hi,
>>
>> I agree with Michal. The Thread is very important for the debugging.
>> Obviously you can highlight what you need, but still the thread is jumping
>> there and back which make is less readable. It would be ok if that would be
>> on the third place as the log level is aligned. It makes huge difference if
>> you look to the logs the entire day.
>
>
> Thanks for the comments,
>
> I agree that showing the thread before the logger may be more useful.
>
> I'll address this in the next version.
>
> Nir
>
___
Devel mailing list
Devel@ovirt.org
http://lists.ovirt.org/mailman/listinfo/devel

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

[Roman Hodain]

Hi,

I agree with Michal. The Thread is very important for the debugging.
Obviously you can highlight what you need, but still the thread is jumping
there and back which make is less readable. It would be ok if that would be
on the third place as the log level is aligned. It makes huge difference if
you look to the logs the entire day.

A part of that I do not see any issues. The spaces are Ok as long as it is
parsable. It looks like it should not be a problem.

Roman

On Wed, Sep 21, 2016 at 12:12 PM, Peter Portante 
wrote:

>
>
> On Wed, Sep 21, 2016 at 2:54 AM, Michal Skrivanek <
> michal.skriva...@redhat.com> wrote:
>
>>
>> > On 20 Sep 2016, at 19:52, Nir Soffer  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.
>
> Thanks for considering,
>
> -peter
>
>
>>
>> Thanks for the improvements!
>> michal
>>
>> >
>> > Thanks,
>> > Nir
>> > ___
>> > Devel mailing list
>> > Devel@ovirt.org
>> > http://lists.ovirt.org/mailman/listinfo/devel
>>
>> ___
>> Devel mailing list
>> Devel@ovirt.org
>> http://lists.ovirt.org/mailman/listinfo/devel
>>
>
>


-- 
Roman Hodain
Software Maintenance Engineer
Brno, The Czech Republic
Phone: +420.532294924
IRC: rhodain
___
Devel mailing list
Devel@ovirt.org
http://lists.ovirt.org/mailman/listinfo/devel

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

[Peter Portante]

On Wed, Sep 21, 2016 at 6:03 PM, Nir Soffer  wrote:
> On Wed, Sep 21, 2016 at 1:12 PM, Peter Portante  wrote:
>>
>>
>>
>> On Wed, Sep 21, 2016 at 2:54 AM, Michal Skrivanek
>>  wrote:
>>>
>>>
>>> > On 20 Sep 2016, at 19:52, Nir Soffer  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
___
Devel mailing list
Devel@ovirt.org
http://lists.ovirt.org/mailman/listinfo/devel

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

[Nir Soffer]

On Wed, Sep 21, 2016 at 1:12 PM, Peter Portante  wrote:

>
>
> On Wed, Sep 21, 2016 at 2:54 AM, Michal Skrivanek <
> michal.skriva...@redhat.com> wrote:
>
>>
>> > On 20 Sep 2016, at 19:52, Nir Soffer  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.

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.

Nir
___
Devel mailing list
Devel@ovirt.org
http://lists.ovirt.org/mailman/listinfo/devel

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

[Nir Soffer]

On Wed, Sep 21, 2016 at 4:47 PM, Roman Hodain  wrote:

> Hi,
>
> I agree with Michal. The Thread is very important for the debugging.
> Obviously you can highlight what you need, but still the thread is jumping
> there and back which make is less readable. It would be ok if that would be
> on the third place as the log level is aligned. It makes huge difference if
> you look to the logs the entire day.
>

Thanks for the comments,

I agree that showing the thread before the logger may be more useful.

I'll address this in the next version.

Nir
___
Devel mailing list
Devel@ovirt.org
http://lists.ovirt.org/mailman/listinfo/devel

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

[Peter Portante]

On Wed, Sep 21, 2016 at 2:54 AM, Michal Skrivanek <
michal.skriva...@redhat.com> wrote:

>
> > On 20 Sep 2016, at 19:52, Nir Soffer  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.

Thanks for considering,

-peter


>
> Thanks for the improvements!
> michal
>
> >
> > Thanks,
> > Nir
> > ___
> > Devel mailing list
> > Devel@ovirt.org
> > http://lists.ovirt.org/mailman/listinfo/devel
>
> ___
> Devel mailing list
> Devel@ovirt.org
> http://lists.ovirt.org/mailman/listinfo/devel
>
___
Devel mailing list
Devel@ovirt.org
http://lists.ovirt.org/mailman/listinfo/devel

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

[Michal Skrivanek]

> On 20 Sep 2016, at 19:52, Nir Soffer  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.

Thanks for the improvements!
michal

> 
> Thanks,
> Nir
> ___
> Devel mailing list
> Devel@ovirt.org
> http://lists.ovirt.org/mailman/listinfo/devel

___
Devel mailing list
Devel@ovirt.org
http://lists.ovirt.org/mailman/listinfo/devel