[pve-devel] [PATCH pve-http-server] AnyEvent: add timestamps to debug logs

[pve-devel] [PATCH pve-http-server] AnyEvent: add timestamps to debug logs

[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 <l.leahu-vladucu@proxmox.com>
---
 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";
 }
 
 sub log_request {
-- 
2.47.3



_______________________________________________
pve-devel mailing list
pve-devel@lists.proxmox.com
https://lists.proxmox.com/cgi-bin/mailman/listinfo/pve-devel

Re: [pve-devel] [PATCH pve-http-server] AnyEvent: add timestamps to debug logs

[Thomas Lamprecht]

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 <l.leahu-vladucu@proxmox.com>
> ---
>  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).

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.

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.

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


>  }
>  
>  sub log_request {


_______________________________________________
pve-devel mailing list
pve-devel@lists.proxmox.com
https://lists.proxmox.com/cgi-bin/mailman/listinfo/pve-devel

Re: [pve-devel] [PATCH pve-http-server] AnyEvent: add timestamps to debug logs

[Laurențiu Leahu-Vlăducu]

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 <l.leahu-vladucu@proxmox.com>
>> ---
>>   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
pve-devel@lists.proxmox.com
https://lists.proxmox.com/cgi-bin/mailman/listinfo/pve-devel