[VDSM] Improving vdsm logging format
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 Thanks, Nir
On 20 Sep 2016, at 19:52, Nir Soffer <nsoffer@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. Thanks for the improvements! michal
Thanks, Nir _______________________________________________ Devel mailing list Devel@ovirt.org http://lists.ovirt.org/mailman/listinfo/devel
On Wed, Sep 21, 2016 at 2:54 AM, Michal Skrivanek < michal.skrivanek@redhat.com> wrote:
On 20 Sep 2016, at 19:52, Nir Soffer <nsoffer@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. 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
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 <pportant@redhat.com> wrote:
On Wed, Sep 21, 2016 at 2:54 AM, Michal Skrivanek < michal.skrivanek@redhat.com> wrote:
On 20 Sep 2016, at 19:52, Nir Soffer <nsoffer@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.
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
On Wed, Sep 21, 2016 at 4:47 PM, Roman Hodain <rhodain@redhat.com> 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
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 <nsoffer@redhat.com> wrote:
On Wed, Sep 21, 2016 at 4:47 PM, Roman Hodain <rhodain@redhat.com> 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
On Wed, Sep 21, 2016 at 1:12 PM, Peter Portante <pportant@redhat.com> wrote:
On Wed, Sep 21, 2016 at 2:54 AM, Michal Skrivanek < michal.skrivanek@redhat.com> wrote:
On 20 Sep 2016, at 19:52, Nir Soffer <nsoffer@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. 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
On Wed, Sep 21, 2016 at 6:03 PM, Nir Soffer <nsoffer@redhat.com> wrote:
On Wed, Sep 21, 2016 at 1:12 PM, Peter Portante <pportant@redhat.com> wrote:
On Wed, Sep 21, 2016 at 2:54 AM, Michal Skrivanek <michal.skrivanek@redhat.com> wrote:
On 20 Sep 2016, at 19:52, Nir Soffer <nsoffer@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/0ab2ba2ff2a20c2b8333259a31bb71ba4f... 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
participants (4)
-
Michal Skrivanek -
Nir Soffer -
Peter Portante -
Roman Hodain