[libvirt] [PATCH 0/4] virtlogd: timestamp option to prepend timestamp

Shaleen Bathla posted 4 patches 1 month, 4 weeks ago
Patches applied successfully (tree, apply log)
git fetch https://github.com/patchew-project/libvirt tags/patchew/20240229064639.1731653-1-shaleen.bathla@oracle.com
src/logging/log_daemon_config.c  |  3 ++
src/logging/log_daemon_config.h  |  1 +
src/logging/log_handler.c        | 10 +++--
src/logging/test_virtlogd.aug.in |  1 +
src/logging/virtlogd.aug         |  1 +
src/logging/virtlogd.conf        |  4 ++
src/util/virrotatingfile.c       | 69 +++++++++++++++++++++++++++++++-
src/util/virrotatingfile.h       |  3 +-
tests/virrotatingfiletest.c      | 34 ++++++++--------
9 files changed, 104 insertions(+), 22 deletions(-)
[libvirt] [PATCH 0/4] virtlogd: timestamp option to prepend timestamp
Posted by Shaleen Bathla 1 month, 4 weeks ago
Description
====================================================
Add timestamp option to virtlogd.conf
When timestamp=1, let virtlogd prepend timestamps at start of line,
i.e. append timestamp after '\n' character.
This can be a useful debugging feature to help us see timestamp along
with commands/operations run inside the VM

Previous discussion link :
https://listman.redhat.com/archives/libvir-list/2023-August/241562.html

Test
=====================================================
Set timestamp = 1 in virtlogd.conf
systemctl restart libvirtd
If VM's xml has something like :
  <devices>
    ...
    <console type='pty'>
      <log file='/var/log/libvirt/vm-serial0.log' append='on'/>
      <target type='serial' port='0'/>
    </console>
  </devices>


Sample Output of /var/log/libvirt/vm-serial0.log:
...
2024-02-22 09:36:33.898+0000 Last login: Sat Feb 10 10:48:00 on ttyS0^M
2024-02-22 09:36:33.953+0000 [root@localhost ~]# ll^H^[[K^H^[[K^M
2024-02-22 09:36:36.930+0000 [root@localhost ~]# ls^M
2024-02-22 09:36:38.224+0000 anaconda-ks.cfg  original-ks.cfg  test.py  tmp     x.txt^M
2024-02-22 09:36:38.226+0000 [root@localhost ~]# ^M
2024-02-22 09:36:40.062+0000 [root@localhost ~]# l^H^[[Kyo^M
2024-02-22 09:36:44.292+0000 -bash: yo: command not found^M
2024-02-22 09:36:44.293+0000 [root@localhost ~]#


Shaleen Bathla (4):
  logging: virtlogd: Add option to append timestamp to domain logs
  util: virrotatingfile: Introduce virRotatingFileWriterAppendTimestamp
  util: virrotatingfile: virtlogd timestamp appending logic
  tests: virrotatingfiletest: update virRotatingFileWriterAppend

 src/logging/log_daemon_config.c  |  3 ++
 src/logging/log_daemon_config.h  |  1 +
 src/logging/log_handler.c        | 10 +++--
 src/logging/test_virtlogd.aug.in |  1 +
 src/logging/virtlogd.aug         |  1 +
 src/logging/virtlogd.conf        |  4 ++
 src/util/virrotatingfile.c       | 69 +++++++++++++++++++++++++++++++-
 src/util/virrotatingfile.h       |  3 +-
 tests/virrotatingfiletest.c      | 34 ++++++++--------
 9 files changed, 104 insertions(+), 22 deletions(-)

-- 
2.39.3
_______________________________________________
Devel mailing list -- devel@lists.libvirt.org
To unsubscribe send an email to devel-leave@lists.libvirt.org
Re: [libvirt] [PATCH 0/4] virtlogd: timestamp option to prepend timestamp
Posted by Michal Prívozník 1 month, 4 weeks ago
On 2/29/24 07:46, Shaleen Bathla wrote:
> Description
> ====================================================
> Add timestamp option to virtlogd.conf
> When timestamp=1, let virtlogd prepend timestamps at start of line,
> i.e. append timestamp after '\n' character.
> This can be a useful debugging feature to help us see timestamp along
> with commands/operations run inside the VM
> 
> Previous discussion link :
> https://listman.redhat.com/archives/libvir-list/2023-August/241562.html
> 
> Test
> =====================================================
> Set timestamp = 1 in virtlogd.conf
> systemctl restart libvirtd
> If VM's xml has something like :
>   <devices>
>     ...
>     <console type='pty'>
>       <log file='/var/log/libvirt/vm-serial0.log' append='on'/>
>       <target type='serial' port='0'/>
>     </console>
>   </devices>
> 
> 
> Sample Output of /var/log/libvirt/vm-serial0.log:
> ...
> 2024-02-22 09:36:33.898+0000 Last login: Sat Feb 10 10:48:00 on ttyS0^M
> 2024-02-22 09:36:33.953+0000 [root@localhost ~]# ll^H^[[K^H^[[K^M
> 2024-02-22 09:36:36.930+0000 [root@localhost ~]# ls^M
> 2024-02-22 09:36:38.224+0000 anaconda-ks.cfg  original-ks.cfg  test.py  tmp     x.txt^M
> 2024-02-22 09:36:38.226+0000 [root@localhost ~]# ^M
> 2024-02-22 09:36:40.062+0000 [root@localhost ~]# l^H^[[Kyo^M
> 2024-02-22 09:36:44.292+0000 -bash: yo: command not found^M
> 2024-02-22 09:36:44.293+0000 [root@localhost ~]#
> 
> 
> Shaleen Bathla (4):
>   logging: virtlogd: Add option to append timestamp to domain logs
>   util: virrotatingfile: Introduce virRotatingFileWriterAppendTimestamp
>   util: virrotatingfile: virtlogd timestamp appending logic
>   tests: virrotatingfiletest: update virRotatingFileWriterAppend
> 
>  src/logging/log_daemon_config.c  |  3 ++
>  src/logging/log_daemon_config.h  |  1 +
>  src/logging/log_handler.c        | 10 +++--
>  src/logging/test_virtlogd.aug.in |  1 +
>  src/logging/virtlogd.aug         |  1 +
>  src/logging/virtlogd.conf        |  4 ++
>  src/util/virrotatingfile.c       | 69 +++++++++++++++++++++++++++++++-
>  src/util/virrotatingfile.h       |  3 +-
>  tests/virrotatingfiletest.c      | 34 ++++++++--------
>  9 files changed, 104 insertions(+), 22 deletions(-)
> 

Couple of points:

1) We require that after every single commit the code base compiles and
all tests pass. This is a non-negotiable requirement and it's because
when bisceting something, we want to be able to compile libvirt and
focus on the bug we're after. Not fight a broken build. The feature is
not required to be available from the very first commit. For large
series we often have patches that refactor something, prepare the code
base, then implement it in various areas of the code, and only as the
last commit the feature is turned on.

2) Be aware that logging code you're touching is also used for
/var/log/libvirt/qemu/$VM.log. After this series I'm seeing some weird
behavior:

# tail -n3 /var/log/libvirt/qemu/fedora.log
2024-02-29 14:48:33.785+000 2024-02-29 14:48:33.857+0000: 9562: debug :
virCommandHandshakeChild:431 : Handshake with parent is done
2024-02-29 14:48:33.857+000 char device redirected to /dev/pts/41 (label
charserial0)
2024-02-29 14:48:33.876+000

IOW, the timestamp is printed twice. Also, the log file ends with a
timestamp and no other message.

Michal
_______________________________________________
Devel mailing list -- devel@lists.libvirt.org
To unsubscribe send an email to devel-leave@lists.libvirt.org