Bug 60699

Summary: Negative response time in an Apache HTTPD access log
Product: Apache httpd-2 Reporter: Maciej Jaros <egil>
Component: CoreAssignee: Apache HTTPD Bugs Mailing List <bugs>
Status: NEW ---    
Severity: normal CC: szg0000
Priority: P2    
Version: 2.4.18   
Target Milestone: ---   
Hardware: PC   
OS: Linux   

Description Maciej Jaros 2017-02-07 09:09:33 UTC
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.
Comment 1 Luca Toscano 2017-05-27 07:27:58 UTC
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!
Comment 2 Maciej Jaros 2017-05-28 12:14:35 UTC
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.
Comment 3 Luca Toscano 2017-06-04 08:20:10 UTC
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 ?
Comment 4 Maciej Jaros 2017-08-21 09:52:48 UTC
> 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.
Comment 5 Ruediger Pluem 2017-08-21 10:49:30 UTC
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.