From cd792ef67c9902422362dfc4b1f4bf2d4a19c817 Mon Sep 17 00:00:00 2001 From: Peter Bieringer Date: Thu, 11 Dec 2025 08:39:53 +0100 Subject: [PATCH 1/3] add selection of XML query flags to request status log line --- radicale/app/__init__.py | 16 ++++++++++++++-- 1 file changed, 14 insertions(+), 2 deletions(-) diff --git a/radicale/app/__init__.py b/radicale/app/__init__.py index 63fe561e..d96de77f 100644 --- a/radicale/app/__init__.py +++ b/radicale/app/__init__.py @@ -275,10 +275,22 @@ class Application(ApplicationPartDelete, ApplicationPartHead, time_delta_seconds = (time_end - time_begin).total_seconds() status_text = "%d %s" % ( status, client.responses.get(status, "Unknown")) + flags = [] + if xml_request is not None: + if "" in xml_request: + flags.append("sync-token") + if "" in xml_request: + flags.append("getctag") + if flags: + flags_text = " (" + " ".join(flags) + ")" + else: + flags_text = "" if answer is not None: - logger.info("%s response status for %r%s in %.3f seconds %s %s bytes: %s", + logger.info("%s response status for %r%s in %.3f seconds %s %s bytes%s: %s", request_method, unsafe_path, depthinfo, - (time_end - time_begin).total_seconds(), content_encoding, str(len(answer)), status_text) + (time_end - time_begin).total_seconds(), content_encoding, str(len(answer)), + flags_text, + status_text) else: logger.info("%s response status for %r%s in %.3f seconds: %s", request_method, unsafe_path, depthinfo, From 225555caa0c3ea2a8dfe242b6c91fa4d92c2c6d6 Mon Sep 17 00:00:00 2001 From: Peter Bieringer Date: Thu, 11 Dec 2025 08:41:03 +0100 Subject: [PATCH 2/3] add support for timing analysis based on logged flags --- contrib/logwatch/radicale | 64 ++++++++++++++++++++++++++++++--------- 1 file changed, 50 insertions(+), 14 deletions(-) diff --git a/contrib/logwatch/radicale b/contrib/logwatch/radicale index 024be3c1..03ffbc48 100644 --- a/contrib/logwatch/radicale +++ b/contrib/logwatch/radicale @@ -80,6 +80,28 @@ sub MaxLength($) { return $length; } +sub ConvertTokens($) { + my %tokens_h; + # unique + foreach my $token (split(" ", $_[0])) { + $tokens_h{$token} = 1; + } + # map tokens + my @result_a; + if (defined $tokens_h{"sync-token"}) { + push @result_a, "ST"; + } + if (defined $tokens_h{"getctag"}) { + push @result_a, "GCT"; + } + # TODO: add potential others which causing long duration + $result = ""; + if (scalar(@result_a) > 0) { + $result = ":F=" . join(",", @result_a); + } + return $result; +} + while (defined($ThisLine = )) { # count loglevel if ( $ThisLine =~ /\[(DEBUG|INFO|WARNING|ERROR|CRITICAL)\] /o ) { @@ -109,6 +131,16 @@ while (defined($ThisLine = )) { $req .= ":R=" . $4; ResponseTimesMinMaxSum($req, $1) if ($Detail >= 10); ResponseSizesMinMaxSum($req, $2, $3) if ($Detail >= 10); + } elsif ( $ThisLine =~ / \S+ response status for .* with depth '(\d)' in ([0-9.]+) seconds (\S+) (\d+) bytes \((.*)\): (\d+)/o ) { + $req .= ":D=" . $1 . ":R=" . $6; + $reqWithFlags = $req . ConvertTokens($5); + ResponseTimesMinMaxSum($reqWithFlags, $2) if ($Detail >= 10); + ResponseSizesMinMaxSum($req, $3, $4) if ($Detail >= 10); + } elsif ( $ThisLine =~ / \S+ response status for .* in ([0-9.]+) seconds (\S+) (\d+) bytes \((.*)\): (\d+)/o ) { + $req .= ":R=" . $5; + $reqWithFlags = $req . ConvertTokens($4); + ResponseTimesMinMaxSum($reqWithFlags, $1) if ($Detail >= 10); + ResponseSizesMinMaxSum($req, $2, $3) if ($Detail >= 10); } $Responses{$req}++; } @@ -192,14 +224,15 @@ if (keys %Requests) { if (keys %Responses) { $sum = Sum(\%Responses); + $length = MaxLength(\%Responses); print "\n**Response result counters ((D= R=)**\n"; - printf "%-18s | %7s | %5s |\n", "Response", "cnt", "ratio"; - print "-" x38 . "\n"; + printf "%-" . $length . "s | %7s | %5s |\n", "Response", "cnt", "ratio"; + print "-" x($length + 20) . "\n"; foreach my $req (sort keys %Responses) { - printf "%-18s | %7d | %3d%% |\n", $req, $Responses{$req}, int(($Responses{$req} * 100) / $sum); + printf "%-" . $length . "s | %7d | %3d%% |\n", $req, $Responses{$req}, int(($Responses{$req} * 100) / $sum); } - print "-" x38 . "\n"; - printf "%-18s | %7d | %3d%% |\n", "", $sum, 100; + print "-" x($length + 20) . "\n"; + printf "%-" . $length . "s | %7d | %3d%% |\n", "", $sum, 100; } if (keys %Logins) { @@ -216,32 +249,35 @@ if (keys %Logins) { } if (keys %ResponseTimes) { - print "\n**Response timings (counts, seconds) (D= R=)**\n"; - printf "%-18s | %7s | %7s | %7s | %7s |\n", "Response", "cnt", "min", "max", "avg"; - print "-" x60 . "\n"; + $length = MaxLength(\%ResponseTimes); + print "\n**Response timings (counts, seconds) (D= R= F=)**\n"; + print "* Flags: ST:sync-token GCT:getctag\n"; + printf "%-" . $length . "s | %7s | %7s | %7s | %7s |\n", "Response", "cnt", "min", "max", "avg"; + print "-" x($length + 42) . "\n"; foreach my $req (sort keys %ResponseTimes) { - printf "%-18s | %7d | %7.3f | %7.3f | %7.3f |\n", $req + printf "%-" . $length . "s | %7d | %7.3f | %7.3f | %7.3f |\n", $req , $ResponseTimes{$req}->{'cnt'} , $ResponseTimes{$req}->{'min'} , $ResponseTimes{$req}->{'max'} , $ResponseTimes{$req}->{'sum'} / $ResponseTimes{$req}->{'cnt'}; } - print "-" x60 . "\n"; + print "-" x($length + 42) . "\n"; } if (keys %ResponseSizes) { for my $type (sort keys %ResponseSizes) { + $length = MaxLength($ResponseSizes{$type}); print "\n**Response sizes (counts, bytes: $type) (D= R=)**\n"; - printf "%-18s | %7s | %9s | %9s | %9s |\n", "Response", "cnt", "min", "max", "avg"; - print "-" x66 . "\n"; + printf "%-" . $length . "s | %7s | %9s | %9s | %9s |\n", "Response", "cnt", "min", "max", "avg"; + print "-" x($length + 48) . "\n"; foreach my $req (sort keys %{$ResponseSizes{$type}}) { - printf "%-18s | %7d | %9d | %9d | %9d |\n", $req + printf "%-" . $length . "s | %7d | %9d | %9d | %9d |\n", $req , $ResponseSizes{$type}->{$req}->{'cnt'} , $ResponseSizes{$type}->{$req}->{'min'} , $ResponseSizes{$type}->{$req}->{'max'} , $ResponseSizes{$type}->{$req}->{'sum'} / $ResponseSizes{$type}->{$req}->{'cnt'}; } - print "-" x66 . "\n"; + print "-" x($length + 48) . "\n"; } } From 4e0008b5e414af9b962c2432b1db7440c8fb0fa6 Mon Sep 17 00:00:00 2001 From: Peter Bieringer Date: Thu, 11 Dec 2025 08:43:07 +0100 Subject: [PATCH 3/3] changelog for this log extension --- CHANGELOG.md | 1 + 1 file changed, 1 insertion(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 4a1f0cd1..3609a39e 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -9,6 +9,7 @@ * New: [logging] option to log response header on debug loglevel * Adjust: [logging] header/content debug log indended by space to be skipped by logwatch * Improve: remove unnecessary open+read for mtime+size cache +* Extend: add selected XML query properties to request result log line for improved timing analysis incl. logwatch support ## 3.5.9 * Extend: [auth] add support for type http_remote_user