Project

General

Profile

Bug #2807

%D and %{UNIT}T of mod_accesslog do not work as expected

Added by slim 7 months ago. Updated 7 months ago.

Status:
Fixed
Priority:
Normal
Assignee:
-
Category:
mod_accesslog
Target version:
Start date:
2017-04-26
Due date:
% Done:

0%

Estimated time:
Missing in 1.5.x:

Description

mod_accesslog allows to log time used by a request via %D and %{UNIT}T tags of accesslog.format.

%D described as "time used in ms" when ms assumed to be miliseconds (1000 ms = 1 sec). Time used is logged in microseconds (1000'000 microseconds - 1 sec) instead.

%{UNIT}T stated as "time used in UNIT (s, ms, us, or ns)". Instead a timestamp is logged when "ms", "us" or "ns" are used

Associated revisions

Revision b23065e5 (diff)
Added by gstrauss 7 months ago

[mod_accesslog] flag high precision ts for %T (fixes #2807)

flag high precision ts for %T after parsing %{xxx}T config

x-ref:
"%D and %{UNIT}T of mod_accesslog do not work as expected"
https://redmine.lighttpd.net/issues/2807

History

#1

Updated by gstrauss 7 months ago

  • Category set to documentation
  • Status changed from New to Fixed
  • Target version changed from 1.4.x to 1.4.46

%D described as "time used in ms" when ms assumed to be miliseconds (1000 ms = 1 sec). Time used is logged in microseconds (1000'000 microseconds - 1 sec) instead.

%D logs in microseconds, similar to Apache. I updated the incorrect doc at Docs_ModAccessLog

%{UNIT}T stated as "time used in UNIT (s, ms, us, or ns)". Instead a timestamp is logged when "ms", "us" or "ns" are used

I was not able to reproduce this -- %{s}T and %T both print the time in seconds for me. What you may be seeing is log buffering. If you send another request (over a second later), does the first line get logged? If you are still having a problem, please share your accesslog.format config.

#2

Updated by gstrauss 7 months ago

Clarification: the accesslog will be buffered until the buffer is full, unless %t is part of the format string. If %t is part of the format string, the log will be flushed on the next request after the time has changed (in seconds).

#3

Updated by slim 7 months ago

kinda of unix epoch timestamp is logged when %{ms}T or %{us}T is used in accesslog.format string instead of time used to process request in miliseconds or microseconds as expected

should I create separrate ticket for this ?

#4

Updated by gstrauss 7 months ago

I am sorry, but I did not understand the wording in your statement. Would you please clarify in a few complete sentences?

Since there was a documentation mistake, you may continue to ask specific questions about accesslog formats here in order to clarify the behavior.

Please do not file a new ticket to ask questions.
Questions are usually best asked in the forums (https://redmine.lighttpd.net/projects/lighttpd/boards)

#5

Updated by slim 7 months ago

as stated in docs:
"%{ms}T" - log time used in miliseconds
"%{us}T" - log time used in microseconds

as actually logged:
"%{ms}T" - unix timestamp of a request + two digits of something
"%{us}T" - unix timestamp of a request + four digits of something

#6

Updated by gstrauss 7 months ago

  • Category changed from documentation to mod_accesslog

If you can, please try the patch attached to this ticket. I had noticed an inconsistency at startup initialization time which might not have enabled high precision timestamps.

#7

Updated by slim 7 months ago

the patch looks good - milisecs and microsecs work now as expected

Also available in: Atom