search

plack / Plack

PSGI toolkit and server adapters
http://plackperl.org/
Other
486 stars 214 forks source link

Plack::Middleware::AccessLog::Timed cannot record %D and %T fields properly #549

Closed astj closed 8 years ago

astj commented 8 years ago

tl;dr

According to documentation of Plack::Middleware::AccessLog::Timed, we can record the time taken to serve the request to logfile with fomat including %D and/or %T. This log is formatted by Apache::LogFormat::Compiler. In its document, %T and %D are described as below:

%T    custom field for handling times in subclasses
%D    custom field for handling sub-second times in subclasses

And according to Apache's LogFormat templates (its superset) those format string are described as below:

Format String Description
%T The time taken to serve the request, in seconds.
%D The time taken to serve the request, in microseconds.

That means:

I wrote a test code to check current behavior of Plack::Middleware::AccessLog::Timed : https://github.com/astj/Plack/commit/d03ab21bd9b56959d93bb68e708d63ebe5c36630

When I run that test, the test fails (result), and from its result, current behavior looks like follows:

This is caused by a bug in Plack::Middleware::AccessLog::Timed and another in Apache::LogFormat::Compiler.

Plack::Middleware::AccessLog::Timed

From documentation of Apache::LogFormat::Compiler, Apache::LogFormat::Compiler::log_line expects its argument $reqtime to be in microseconds. But Plack::Middleware::AccessLog::Timed passes $now - $time in seconds as $reqtime argument.

With this commit this bug will be fixed, but due to Apache::LogFormat::Compiler's bug, that test still fails. : https://github.com/astj/Plack/commit/dac66093f454cc0da52ee3333b265f0383f196d7

Apache::LogFormat::Compiler

The bug in Apache::LogFormat::Compiler is simple. When $reqtime is passed to log_line, %T shoule be formatted to int($reqtime/1_000_000), but with current implementation it's formatted to int($reqtime*1_000_000).

I wrote a test code to check this behavior: https://github.com/astj/Apache-LogFormat-Compiler/commit/ea41df7282c0020ad957ed0d72c5190b20a88eec Unless this bug fixed, %T fields in Plack::Middleware::AccessLog::Timed's output remains still broken.

Suggestion

My suggestion is follows:

miyagawa commented 8 years ago

Sounds about right. We should address this. @kazeburo

kazeburo commented 8 years ago

Thank you @astj. I'll fix this bug as soon as possible.

miyagawa commented 8 years ago

Fixed by #551