Mobile app version of vmapp.org
Login or Join
Megan663

: Do you trust timestamps when they are out of order? When Apache2 log file entries have timestamps that are out of order, do you trust the timestamp or the order? 10.1.10.250 - - [20/May/2015:00:43:53

@Megan663

Posted in: #Apache2 #ApacheLogFiles

When Apache2 log file entries have timestamps that are out of order, do you trust the timestamp or the order?

10.1.10.250 - - [20/May/2015:00:43:53 -0600] "GET /foo/bar_1234.jpg HTTP/1.1" 200 738542 "http://www.example.com/foo/bar/jbcore/full.html" "some UA"
10.1.10.250 - - [20/May/2015:00:43:55 -0600] "GET /foo/bar_2345.jpg HTTP/1.1" 200 824394 "http://www.example.com/foo/bar/jbcore/full.html" "some UA"
10.1.10.250 - - [20/May/2015:00:43:57 -0600] "GET /foo/bar_3456.jpg HTTP/1.1" 200 15680 "http://www.example.com/foo/bar/jbcore/full.html" "some UA"
10.1.10.250 - - [20/May/2015:00:43:53 -0600] "GET /foo/bar_4567.jpg HTTP/1.1" 200 822449 "http://www.example.com/foo/bar/jbcore/full.html" "some UA"
10.1.10.250 - - [20/May/2015:00:43:57 -0600] "GET /foo/bar_5678.jpg HTTP/1.1" 200 15062 "http://www.example.com/foo/bar/jbcore/full.html" "some UA"
10.1.10.250 - - [20/May/2015:00:43:56 -0600] "GET /foo/bar_6789.jpg HTTP/1.1" 200 798119 "http://www.example.com/foo/bar/jbcore/full.html" "some UA"
10.1.10.250 - - [20/May/2015:00:43:54 -0600] "GET /foo/bar_7890.jpg HTTP/1.1" 200 836622 "http://www.example.com/foo/bar/jbcore/full.html" "some UA"
10.1.10.250 - - [20/May/2015:00:44:20 -0600] "GET /foo/bar_8901.jpg HTTP/1.1" 200 763120 "http://www.example.com/foo/bar/jbcore/full.html" "some UA"

10.01% popularity Vote Up Vote Down


Login to follow query

More posts by @Megan663

1 Comments

Sorted by latest first Latest Oldest Best

 

@Jamie184

This may seem odd, however, there may be a valid explanation.

Apache can log either the access (start) time or the completion time. At one point, when the feature to select access or completion time was new, Apache changed the default from access to completion, but when the inevitable backlash came, quickly changed the default back to access time. However what did not change as a result of the new feature is that regardless of which log time you select, it is always written to the log file at completion rather than when first accessed. Prior to this, all accesses were logged immediately even if they never really completed. The new method results in a cleaner log file.

So what happens now is that if a request takes a while to complete, it is written to the log file when it is completed which can be several seconds after it was started- hence the access times being out of order slightly. This is not that unusual since sometimes requests can take a few seconds to complete from time to time. However, if this is consistent throughout your log file, I would be looking into whether your server is taking too long to process requests or if there are specific requests that take too long. Otherwise, I would not worry about it at all.

10% popularity Vote Up Vote Down


Back to top | Use Dark Theme