Thanks for the review! Some comments below.
On 13.10.25 19:00, Thomas Lamprecht wrote:
Am 02.10.25 um 18:28 schrieb Laurențiu Leahu-Vlăducu:
This helps correlate our debug logs with other log files for
easier debugging when making API calls.
Signed-off-by: Laurențiu Leahu-Vlăducu <[email protected]>
---
src/PVE/APIServer/AnyEvent.pm | 4 +++-
1 file changed, 3 insertions(+), 1 deletion(-)
diff --git a/src/PVE/APIServer/AnyEvent.pm b/src/PVE/APIServer/AnyEvent.pm
index 59bc184..cdc82b2 100644
--- a/src/PVE/APIServer/AnyEvent.pm
+++ b/src/PVE/APIServer/AnyEvent.pm
@@ -76,7 +76,9 @@ sub dprint {
my ($pkg, $pkgfile, $line, $sub) = caller(1);
$sub =~ s/^(?:.+::)+//;
- print "worker[$$]: $pkg +$line: $sub: $message\n";
+ my ($secs, $microsecs) = gettimeofday();
+ my $timestr = strftime("%F %T", localtime($secs)) . sprintf(".%06d",
$microsecs);
+ print "$timestr | worker[$$]: $pkg +$line: $sub: $message\n";
would not include the " |" part as it's not really standardized format,
a simple space should be enough (closer to like e.g. journalctl prints).
Sure, I can send a v2 that removes it, if you wish.
And FWIW, I benchmarked this, i.e. the gettimeofday and strftime calls
separate and together:
elapsed[gettimeofday+strftime,1000000]: 5.730306 s => 5.730306 us/loop
elapsed[strftime, 1000000]: 5.532132 s => 5.532132 us/loop
elapsed[gettimeofday, 1000000]: 100.645 ms => 100.645 ns/loop
So FWIW, this is not really cheap and adds ~5.7 µs delay on every print.
I did not check whether this is due to localtime() or strftime(), but my
feeling says it's most probably the latter. I agree that this is quite a
performance difference. On the other hand, this code only gets executed
when the debug output is enabled (e.g. pveproxy start --debug), and in
that case, timestamps are probably useful anyway.
I originally had the idea of including the UTC offset as well, but since
I needed to split the call to strftime (due to strftime not supporting
subseconds), I decided against calling it twice for this exact reason.
It IMO would be slightly nicer to split the debug option into debug and
foreground options in PVE::Daemon so that one can enable debug output
without running in foreground, as then a simple systemd service override [0]
could be used to allow the debug logs to land in the journal, which already
got efficient and precise time stamping available.
I really like this idea. This is also useful for getting logs from
customers, as the current solution needs something like:
pveproxy start --debug | tee /tmp/pveproxy.log
Not that the current solution using "tee" hard to use (it's not), but
using the journal adds some convenience indeed, and allows showing the
logs later, if needed.
Also, for the sake of completeness, I want to state that in my current
case, logging was needed for events that happened very quickly, during a
TLS handshake. For this, subsecond precision is necessary. Thankfully,
the journal also supports microsecond precision, by calling journalctl
with -o short-precise or -o short-iso-precise. Using the journal would
thus still cover this use case.
But not sure if it helps the rather limited integrators in your case that
this patch originated from, so if you think it's worth it I can apply this
as is for now.
[0]:
# /etc/systemd/system/pveproxy.service.d/override.conf
[Service]
ExecStart=
ExecStart=/usr/bin/pveproxy start --debug
Since debug logs might be very noisy, I agree that we should only write
debug logs to the journal only if --debug is enabled, to prevent the
journal from growing unnecessarily and/or delete older logs.
}
sub log_request {
In the end, I agree that additionally adding a --foreground option would
be nice. Still, I think I could still do this as an additional, separate
patch, because in case --foreground is enabled, my current patch would
still provide timestamps, which would be useful anyway. What do you think?
I could either:
- send a v2 removing | from the print statements, or
- send a patch adding --foreground right away
_______________________________________________
pve-devel mailing list
[email protected]
https://lists.proxmox.com/cgi-bin/mailman/listinfo/pve-devel
