[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 at 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 {