[libvirt] [PATCH 0/4] virtlogd: timestamp option to prepend timestamp
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
In virtlogd.conf, introduce a new timestamp option. When set to 1, timestamp is appended after \n in serial console logs. Signed-off-by: Shaleen Bathla <shaleen.bathla@oracle.com> --- src/logging/log_daemon_config.c | 3 +++ src/logging/log_daemon_config.h | 1 + src/logging/test_virtlogd.aug.in | 1 + src/logging/virtlogd.aug | 1 + src/logging/virtlogd.conf | 4 ++++ 5 files changed, 10 insertions(+) diff --git a/src/logging/log_daemon_config.c b/src/logging/log_daemon_config.c index 248bd927d3f0..278e4c0a7832 100644 --- a/src/logging/log_daemon_config.c +++ b/src/logging/log_daemon_config.c @@ -62,6 +62,7 @@ virLogDaemonConfigNew(bool privileged G_GNUC_UNUSED) data->max_size = 1024 * 1024 * 2; data->max_backups = 3; data->max_age_days = 0; + data->timestamp = 0; return data; } @@ -101,6 +102,8 @@ virLogDaemonConfigLoadOptions(virLogDaemonConfig *data, return -1; if (virConfGetValueString(conf, "log_root", &data->log_root) < 0) return -1; + if (virConfGetValueBool(conf, "timestamp", &data->timestamp) < 0) + return -1; if (!data->log_root) data->log_root = g_strdup(DEFAULT_LOG_ROOT); diff --git a/src/logging/log_daemon_config.h b/src/logging/log_daemon_config.h index 43922feedf6e..8fe3ac460cb8 100644 --- a/src/logging/log_daemon_config.h +++ b/src/logging/log_daemon_config.h @@ -36,6 +36,7 @@ struct _virLogDaemonConfig { char *log_root; size_t max_age_days; + bool timestamp; }; diff --git a/src/logging/test_virtlogd.aug.in b/src/logging/test_virtlogd.aug.in index 8dfad3950608..dfae4fff15fd 100644 --- a/src/logging/test_virtlogd.aug.in +++ b/src/logging/test_virtlogd.aug.in @@ -11,3 +11,4 @@ module Test_virtlogd = { "max_backups" = "3" } { "max_age_days" = "0" } { "log_root" = "/var/log/libvirt" } + { "timestamp" = "0" } diff --git a/src/logging/virtlogd.aug b/src/logging/virtlogd.aug index bdf61dea6eb5..a1e5c09bbb04 100644 --- a/src/logging/virtlogd.aug +++ b/src/logging/virtlogd.aug @@ -33,6 +33,7 @@ module Virtlogd = | int_entry "max_backups" | int_entry "max_age_days" | str_entry "log_root" + | bool_entry "timestamp" (* Each entry in the config is one of the following three ... *) let entry = logging_entry diff --git a/src/logging/virtlogd.conf b/src/logging/virtlogd.conf index 5214e96121a1..2c45f3da2e3d 100644 --- a/src/logging/virtlogd.conf +++ b/src/logging/virtlogd.conf @@ -115,3 +115,7 @@ # WARNING: all files under this location potentially can be GC-ed. See the # warning for max_age_days. #log_root = "/var/log/libvirt" + +# Append timestamp to serial console logs after every '\n' character +# Defaults to 0 i.e. turned off +#timestamp = 0 -- 2.39.3
virRotatingFileWriterAppendTimestamp function appends timestamp to a file. Signed-off-by: Shaleen Bathla <shaleen.bathla@oracle.com> --- src/util/virrotatingfile.c | 35 +++++++++++++++++++++++++++++++++++ 1 file changed, 35 insertions(+) diff --git a/src/util/virrotatingfile.c b/src/util/virrotatingfile.c index b02a88c4b08d..2a44c9bf93e3 100644 --- a/src/util/virrotatingfile.c +++ b/src/util/virrotatingfile.c @@ -30,6 +30,7 @@ #include "virerror.h" #include "virfile.h" #include "virlog.h" +#include "virtime.h" VIR_LOG_INIT("util.rotatingfile"); @@ -406,6 +407,40 @@ virRotatingFileWriterRollover(virRotatingFileWriter *file) } +/** + * virRotatingFileWriterAppendTimestamp: + * @file: the file context + * + * Append current timestamp with a trailing ' ' char to @file + * + * Returns 0 on success and -1 on error + */ +static ssize_t +virRotatingFileWriterAppendTimestamp(virRotatingFileWriter* file) +{ + char* timestamp = NULL; + size_t len = 0; + + if (!(timestamp = virTimeStringNow())) { + g_free(timestamp); + return -1; + } + + len = VIR_TIME_STRING_BUFLEN; + timestamp = g_realloc(timestamp, len+1); + timestamp[len-1] = ' '; + timestamp[len] = '\0'; + + if (virRotatingFileWriterAppend(file, timestamp, len) != len) { + g_free(timestamp); + return -1; + } + + g_free(timestamp); + return 0; +} + + /** * virRotatingFileWriterAppend: * @file: the file context -- 2.39.3
On 2/29/24 07:46, Shaleen Bathla wrote:
virRotatingFileWriterAppendTimestamp function appends timestamp to a file.
Signed-off-by: Shaleen Bathla <shaleen.bathla@oracle.com> --- src/util/virrotatingfile.c | 35 +++++++++++++++++++++++++++++++++++ 1 file changed, 35 insertions(+)
diff --git a/src/util/virrotatingfile.c b/src/util/virrotatingfile.c index b02a88c4b08d..2a44c9bf93e3 100644 --- a/src/util/virrotatingfile.c +++ b/src/util/virrotatingfile.c @@ -30,6 +30,7 @@ #include "virerror.h" #include "virfile.h" #include "virlog.h" +#include "virtime.h"
VIR_LOG_INIT("util.rotatingfile");
@@ -406,6 +407,40 @@ virRotatingFileWriterRollover(virRotatingFileWriter *file) }
+/** + * virRotatingFileWriterAppendTimestamp: + * @file: the file context + * + * Append current timestamp with a trailing ' ' char to @file + * + * Returns 0 on success and -1 on error + */ +static ssize_t +virRotatingFileWriterAppendTimestamp(virRotatingFileWriter* file) +{ + char* timestamp = NULL; + size_t len = 0; + + if (!(timestamp = virTimeStringNow())) { + g_free(timestamp); + return -1; + } + + len = VIR_TIME_STRING_BUFLEN; + timestamp = g_realloc(timestamp, len+1); + timestamp[len-1] = ' '; + timestamp[len] = '\0';
Firstly, to avoid having to call g_free() everywhere you can declare the variable like this: g_autofree char *timestamp = NULL; but in this specific case, when we know how long the string is going to be (and that it's relatively short), might as well allocate the buffer on the stack: char timestamp[VIR_TIME_STRING_BUFLEN + 1] = { 0 }; and then call virTimeStringNowRaw() instead. This avoid necessary g_realloc.
+ + if (virRotatingFileWriterAppend(file, timestamp, len) != len) {
So eventually, virRotatingFileWriterAppend() would call virRotatingFileWriterAppendTimestamp() which would then call virRotatingFileWriterAppend() again? I wonder whether the timestamp can't be prepended to the string caller wants to write in virRotatingFileWriterAppend(). Michal
Make use of timestamp option in virtlogd config and append timestamp to domain event logs after every '\n' character. Signed-off-by: Shaleen Bathla <shaleen.bathla@oracle.com> --- src/logging/log_handler.c | 10 +++++++--- src/util/virrotatingfile.c | 36 ++++++++++++++++++++++++++++++++++-- src/util/virrotatingfile.h | 3 ++- 3 files changed, 43 insertions(+), 6 deletions(-) diff --git a/src/logging/log_handler.c b/src/logging/log_handler.c index 71517bbbe5ff..9be338d92ca1 100644 --- a/src/logging/log_handler.c +++ b/src/logging/log_handler.c @@ -116,6 +116,7 @@ virLogHandlerDomainLogFileEvent(int watch, virLogHandlerLogFile *logfile; char buf[1024]; ssize_t len; + bool timestamp = false; virObjectLock(handler); logfile = virLogHandlerGetLogFileFromWatch(handler, watch); @@ -130,6 +131,9 @@ virLogHandlerDomainLogFileEvent(int watch, goto cleanup; } + if (handler->config && handler->config->timestamp) + timestamp = true; + reread: len = read(fd, buf, sizeof(buf)); if (len < 0) { @@ -143,7 +147,7 @@ virLogHandlerDomainLogFileEvent(int watch, goto error; } - if (virRotatingFileWriterAppend(logfile->file, buf, len) != len) + if (virRotatingFileWriterAppend(logfile->file, buf, len, timestamp) != len) goto error; cleanup: @@ -440,7 +444,7 @@ virLogHandlerDomainLogFileDrain(virLogHandlerLogFile *file) return; } - if (virRotatingFileWriterAppend(file->file, buf, len) != len) + if (virRotatingFileWriterAppend(file->file, buf, len, 0) != len) return; } } @@ -568,7 +572,7 @@ virLogHandlerDomainAppendLogFile(virLogHandler *handler, writer = newwriter; } - if (virRotatingFileWriterAppend(writer, message, strlen(message)) < 0) + if (virRotatingFileWriterAppend(writer, message, strlen(message), 0) < 0) goto cleanup; ret = 0; diff --git a/src/util/virrotatingfile.c b/src/util/virrotatingfile.c index 2a44c9bf93e3..5443e850721b 100644 --- a/src/util/virrotatingfile.c +++ b/src/util/virrotatingfile.c @@ -431,7 +431,7 @@ virRotatingFileWriterAppendTimestamp(virRotatingFileWriter* file) timestamp[len-1] = ' '; timestamp[len] = '\0'; - if (virRotatingFileWriterAppend(file, timestamp, len) != len) { + if (virRotatingFileWriterAppend(file, timestamp, len, 0) != len) { g_free(timestamp); return -1; } @@ -446,6 +446,7 @@ virRotatingFileWriterAppendTimestamp(virRotatingFileWriter* file) * @file: the file context * @buf: the data buffer * @len: the number of bytes in @buf + * @timestamp: append timestamp config option * * Append the data in @buf to the file, performing rollover * of the files if their size would exceed the limit @@ -455,10 +456,12 @@ virRotatingFileWriterAppendTimestamp(virRotatingFileWriter* file) ssize_t virRotatingFileWriterAppend(virRotatingFileWriter *file, const char *buf, - size_t len) + size_t len, + bool timestamp) { ssize_t ret = 0; size_t i; + while (len) { size_t towrite = len; bool forceRollover = false; @@ -488,6 +491,35 @@ virRotatingFileWriterAppend(virRotatingFileWriter *file, } } + if (timestamp && towrite) { + int last_nl = -1; + for (i = 0; i < towrite; i++) { + if (buf[i] == '\n') { + if (safewrite(file->entry->fd, buf+last_nl+1, i-last_nl) != i-last_nl) { + virReportSystemError(errno, + _("Unable to write to file %1$s"), + file->basepath); + return -1; + } + if (virRotatingFileWriterAppendTimestamp(file) != 0) { + virReportSystemError(errno, + _("Unable to write to file %1$s"), + file->basepath); + return -1; + } + last_nl = i; + } + } + + last_nl++; + buf += last_nl; + len -= last_nl; + ret += last_nl; + file->entry->pos += last_nl; + file->entry->len += last_nl; + towrite -= last_nl; + } + if (towrite) { if (safewrite(file->entry->fd, buf, towrite) != towrite) { virReportSystemError(errno, diff --git a/src/util/virrotatingfile.h b/src/util/virrotatingfile.h index 1ed8838e7df2..388774bc3913 100644 --- a/src/util/virrotatingfile.h +++ b/src/util/virrotatingfile.h @@ -43,7 +43,8 @@ off_t virRotatingFileWriterGetOffset(virRotatingFileWriter *file); ssize_t virRotatingFileWriterAppend(virRotatingFileWriter *file, const char *buf, - size_t len); + size_t len, + bool timestamp); int virRotatingFileReaderSeek(virRotatingFileReader *file, ino_t inode, -- 2.39.3
update virRotatingFileWriterAppend calls by adding timestamp parameter Signed-off-by: Shaleen Bathla <shaleen.bathla@oracle.com> --- tests/virrotatingfiletest.c | 34 +++++++++++++++++----------------- 1 file changed, 17 insertions(+), 17 deletions(-) diff --git a/tests/virrotatingfiletest.c b/tests/virrotatingfiletest.c index ede65848ea54..5ba7235c13da 100644 --- a/tests/virrotatingfiletest.c +++ b/tests/virrotatingfiletest.c @@ -188,7 +188,7 @@ static int testRotatingFileWriterNew(const void *data G_GNUC_UNUSED) memset(buf, 0x5e, sizeof(buf)); - virRotatingFileWriterAppend(file, buf, sizeof(buf)); + virRotatingFileWriterAppend(file, buf, sizeof(buf), 0); if (testRotatingFileWriterAssertFileSizes(sizeof(buf), (off_t)-1, @@ -231,7 +231,7 @@ static int testRotatingFileWriterAppend(const void *data G_GNUC_UNUSED) memset(buf, 0x5e, sizeof(buf)); - virRotatingFileWriterAppend(file, buf, sizeof(buf)); + virRotatingFileWriterAppend(file, buf, sizeof(buf), 0); if (testRotatingFileWriterAssertFileSizes(1024, (off_t)-1, @@ -274,7 +274,7 @@ static int testRotatingFileWriterTruncate(const void *data G_GNUC_UNUSED) memset(buf, 0x5e, sizeof(buf)); - virRotatingFileWriterAppend(file, buf, sizeof(buf)); + virRotatingFileWriterAppend(file, buf, sizeof(buf), 0); if (testRotatingFileWriterAssertFileSizes(512, (off_t)-1, @@ -317,7 +317,7 @@ static int testRotatingFileWriterRolloverNone(const void *data G_GNUC_UNUSED) memset(buf, 0x5e, sizeof(buf)); - virRotatingFileWriterAppend(file, buf, sizeof(buf)); + virRotatingFileWriterAppend(file, buf, sizeof(buf), 0); if (testRotatingFileWriterAssertFileSizes(112, (off_t)-1, @@ -360,9 +360,9 @@ static int testRotatingFileWriterRolloverOne(const void *data G_GNUC_UNUSED) memset(buf, 0x5e, sizeof(buf)); - virRotatingFileWriterAppend(file, buf, sizeof(buf)); - virRotatingFileWriterAppend(file, buf, sizeof(buf)); - virRotatingFileWriterAppend(file, buf, sizeof(buf)); + virRotatingFileWriterAppend(file, buf, sizeof(buf), 0); + virRotatingFileWriterAppend(file, buf, sizeof(buf), 0); + virRotatingFileWriterAppend(file, buf, sizeof(buf), 0); if (testRotatingFileWriterAssertFileSizes(512, 1024, @@ -405,7 +405,7 @@ static int testRotatingFileWriterRolloverAppend(const void *data G_GNUC_UNUSED) memset(buf, 0x5e, sizeof(buf)); - virRotatingFileWriterAppend(file, buf, sizeof(buf)); + virRotatingFileWriterAppend(file, buf, sizeof(buf), 0); if (testRotatingFileWriterAssertFileSizes(256, 1024, @@ -448,13 +448,13 @@ static int testRotatingFileWriterRolloverMany(const void *data G_GNUC_UNUSED) memset(buf, 0x5e, sizeof(buf)); - virRotatingFileWriterAppend(file, buf, sizeof(buf)); - virRotatingFileWriterAppend(file, buf, sizeof(buf)); - virRotatingFileWriterAppend(file, buf, sizeof(buf)); - virRotatingFileWriterAppend(file, buf, sizeof(buf)); - virRotatingFileWriterAppend(file, buf, sizeof(buf)); - virRotatingFileWriterAppend(file, buf, sizeof(buf)); - virRotatingFileWriterAppend(file, buf, sizeof(buf)); + virRotatingFileWriterAppend(file, buf, sizeof(buf), 0); + virRotatingFileWriterAppend(file, buf, sizeof(buf), 0); + virRotatingFileWriterAppend(file, buf, sizeof(buf), 0); + virRotatingFileWriterAppend(file, buf, sizeof(buf), 0); + virRotatingFileWriterAppend(file, buf, sizeof(buf), 0); + virRotatingFileWriterAppend(file, buf, sizeof(buf), 0); + virRotatingFileWriterAppend(file, buf, sizeof(buf), 0); if (testRotatingFileWriterAssertFileSizes(512, 1024, @@ -496,7 +496,7 @@ static int testRotatingFileWriterRolloverLineBreak(const void *data G_GNUC_UNUSE (off_t)-1) < 0) goto cleanup; - virRotatingFileWriterAppend(file, buf, strlen(buf)); + virRotatingFileWriterAppend(file, buf, strlen(buf), 0); if (testRotatingFileWriterAssertFileSizes(59, 144, @@ -538,7 +538,7 @@ static int testRotatingFileWriterLargeFile(const void *data G_GNUC_UNUSED) (off_t)-1) < 0) goto cleanup; - virRotatingFileWriterAppend(file, buf, strlen(buf)); + virRotatingFileWriterAppend(file, buf, strlen(buf), 0); if (testRotatingFileWriterAssertFileSizes(103, 200, -- 2.39.3
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
participants (2)
-
Michal Prívozník -
Shaleen Bathla