[pve-devel] [PATCH pve-http-server v2] 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. This might ease debugging
in our enterprise support and forum, or for external developers
who need to debug Proxmox VE.

This patch does add some delay when printing debug logs (pointed out
by Thomas):

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

However, this only happens when printing debug logs, in which case
it is often expected that software might be slightly slower.

Signed-off-by: Laurențiu Leahu-Vlăducu <l.leahu-vladucu at proxmox.com>
Tested-by: Thomas Lamprecht <t.lamprecht at proxmox.com>
Reviewed-by: Thomas Lamprecht <t.lamprecht at proxmox.com>
---

Changes since v1:
* the separator '|' is no longer used after the timestamp
* improved commit message
* added Thomas' T-b and R-b 


 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..24b298d 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