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.
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!
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.
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 ?
> 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.
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.