* [pve-devel] [PATCH pve-http-server] AnyEvent: add timestamps to debug logs @ 2025-10-02 16:28 Laurențiu Leahu-Vlăducu 2025-10-13 17:01 ` Thomas Lamprecht 2025-10-21 14:15 ` [pve-devel] superseded: " Laurențiu Leahu-Vlăducu 0 siblings, 2 replies; 4+ messages in thread From: Laurențiu Leahu-Vlăducu @ 2025-10-02 16:28 UTC (permalink / raw) To: pve-devel 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 ^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: [pve-devel] [PATCH pve-http-server] AnyEvent: add timestamps to debug logs 2025-10-02 16:28 [pve-devel] [PATCH pve-http-server] AnyEvent: add timestamps to debug logs Laurențiu Leahu-Vlăducu @ 2025-10-13 17:01 ` Thomas Lamprecht 2025-10-14 9:49 ` Laurențiu Leahu-Vlăducu 2025-10-21 14:15 ` [pve-devel] superseded: " Laurențiu Leahu-Vlăducu 1 sibling, 1 reply; 4+ messages in thread From: Thomas Lamprecht @ 2025-10-13 17:01 UTC (permalink / raw) To: Proxmox VE development discussion, Laurențiu Leahu-Vlăducu 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 ^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: [pve-devel] [PATCH pve-http-server] AnyEvent: add timestamps to debug logs 2025-10-13 17:01 ` Thomas Lamprecht @ 2025-10-14 9:49 ` Laurențiu Leahu-Vlăducu 0 siblings, 0 replies; 4+ messages in thread From: Laurențiu Leahu-Vlăducu @ 2025-10-14 9:49 UTC (permalink / raw) To: Thomas Lamprecht, Proxmox VE development discussion 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 ^ permalink raw reply [flat|nested] 4+ messages in thread
* [pve-devel] superseded: [PATCH pve-http-server] AnyEvent: add timestamps to debug logs 2025-10-02 16:28 [pve-devel] [PATCH pve-http-server] AnyEvent: add timestamps to debug logs Laurențiu Leahu-Vlăducu 2025-10-13 17:01 ` Thomas Lamprecht @ 2025-10-21 14:15 ` Laurențiu Leahu-Vlăducu 1 sibling, 0 replies; 4+ messages in thread From: Laurențiu Leahu-Vlăducu @ 2025-10-21 14:15 UTC (permalink / raw) To: Proxmox VE development discussion Superseded-by: https://lore.proxmox.com/pve-devel/20251021141030.185691-1-l.leahu-vladucu@proxmox.com/T/#u On 02.10.25 18:28, Laurențiu Leahu-Vlăducu wrote: > 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 { _______________________________________________ pve-devel mailing list pve-devel@lists.proxmox.com https://lists.proxmox.com/cgi-bin/mailman/listinfo/pve-devel ^ permalink raw reply [flat|nested] 4+ messages in thread
end of thread, other threads:[~2025-10-21 14:15 UTC | newest] Thread overview: 4+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2025-10-02 16:28 [pve-devel] [PATCH pve-http-server] AnyEvent: add timestamps to debug logs Laurențiu Leahu-Vlăducu 2025-10-13 17:01 ` Thomas Lamprecht 2025-10-14 9:49 ` Laurențiu Leahu-Vlăducu 2025-10-21 14:15 ` [pve-devel] superseded: " Laurențiu Leahu-Vlăducu
This is an external index of several public inboxes, see mirroring instructions on how to clone and mirror all data and code used by this external index.