You are viewing a plain text version of this content. The canonical link for it is here.
Posted to bugs@httpd.apache.org by bu...@apache.org on 2017/02/07 09:09:33 UTC

[Bug 60699] New: Negative response time in an Apache HTTPD access log

https://bz.apache.org/bugzilla/show_bug.cgi?id=60699

            Bug ID: 60699
           Summary: Negative response time in an Apache HTTPD access log
           Product: Apache httpd-2
           Version: 2.4.18
          Hardware: PC
                OS: Linux
            Status: NEW
          Severity: normal
          Priority: P2
         Component: Core
          Assignee: bugs@httpd.apache.org
          Reporter: egil@wp.pl
  Target Milestone: ---

So below is a log line that was recorded recently by our Apache that serves a
proxy for Tomcat. The third number is %D ("The time taken to serve the request,
in microseconds").

123.123.123.123 0 -656931 [01/Feb/2017:08:33:04 +0100] "GET
/api/reader?_dc=1485934382427&page=1&start=0&limit=25&sort=lastName&filter=...
HTTP/1.1" 200 681 "Mozilla/5.0 (Windows NT 6.3) AppleWebKit/537.36 (KHTML, like
Gecko) Chrome/38.0.2125.111 Safari/537.36"

There is another one from a different browser:

123.123.123.124 0 -192246 - - [01/Feb/2017:07:59:27 +0100] "GET /auth/...
HTTP/2" 302 - "Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36
(KHTML, like Gecko) Chrome/55.0.2883.87 Safari/537.36"

Similar time (date), but communication is to different servers (our proxy
connects with AJP to several Tomcat servers).

P.S.: Obviously I modified IP in the log, I also removed parts of URL.

-- 
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org


[Bug 60699] Negative response time in an Apache HTTPD access log

Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=60699

--- Comment #5 from Ruediger Pluem <rp...@apache.org> ---
Do you have an ntp daemon or chrony running? Or do you use a virtual machine
with some virtual machine tools installed? I think it is possible that your
clock got adjusted during the processing of your request.

-- 
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org


[Bug 60699] Negative response time in an Apache HTTPD access log

Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=60699

--- Comment #1 from Luca Toscano <to...@gmail.com> ---
Hi Maciej,

does it happens all the times for a particular request or once in a while? Have
you found a way to reliable reproduce the issue?

Thanks!

-- 
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org


[Bug 60699] Negative response time in an Apache HTTPD access log

Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=60699

--- Comment #2 from Maciej Jaros <eg...@wp.pl> ---
No, unfortunately I don't know how to reproduce this. It just happens from time
to time and is rare.

I'm guessing this happens when the request is not completed and is in some
weird state. But that's a pure guess. Would explain why it is rare thought.

-- 
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org


[Bug 60699] Negative response time in an Apache HTTPD access log

Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=60699

--- Comment #3 from Luca Toscano <to...@gmail.com> ---
Is there anything relevant in the error log around the time of the log with
negative %D? Can you add the full log format that you are using? I'd like to
check what is the "0" value right after the IP address.

As far as I can see the issue seems present for both HTTP/2 and HTTP1.1, can
you confirm ?

-- 
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org


[Bug 60699] Negative response time in an Apache HTTPD access log

Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=60699

Szőgyényi Gábor <sz...@freemail.hu> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |szg0000@freemail.hu

-- 
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org


[Bug 60699] Negative response time in an Apache HTTPD access log

Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=60699

--- Comment #4 from Maciej Jaros <eg...@wp.pl> ---
> Is there anything relevant in the error log 
> around the time of the log with negative %D?

Haven't found any errors in logs.

There are also more requests from the same IP within seconds before and after
the incident which show correct number for `%D`.

Same is true for the second incident described.

> Can you add the full log format that you are using?
> I'd like to check what is the "0" value right after the IP address.

0 is for time in seconds.

Full config for the format:
LogFormat "%h %T %D %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\""
combined

> As far as I can see the issue seems present for both HTTP/2 and HTTP1.1, 
> can you confirm ?

Yes, that's correct. And one is a static response (redirect) and another is
after an AJAX request to API.

-- 
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org