nginx access logs, timestamps "jump back"

[assistlydavid]

Hi there,

We're running multiple nginx web servers on EC2 behind multiple ELBs (load balancers).  I'm seeing strange behaviour in our nginx system logs.  This strange behaviour seems to coincide with brief outages spotted by our external monitoring (chartbeat & new relic).  I'm not sure whether I'm on the right track here, investigating this strange logging ... or if it's just a coincidence and this is normal logging for nginx.

It starts with typical nginx logging, timestamps increasing chronologically.  Then there's a jump back in the timestamps while a large block of ELB-only traffic is logged (health checks).  After that, logging returns to normal (increasing chronologically) and the timestamps resume from where they left off before the ELB-only burst.

For example (details changed to protect the innocent):

1.2.3.4 - - [14/Mar/2011:06:39:08 +0000]  "GET /stuff HTTP/1.1" 301 178 "-" "Jakarta Commons-HttpClient/3.1" http example.com /stuff
10.162.18.95 - - [14/Mar/2011:06:23:17 +0000]  "GET /host HTTP/1.1" 200 0 "-" "ELB-HealthChecker/1.0" - 10.162.217.229:80 /host
10.162.126.84 - - [14/Mar/2011:06:23:19 +0000]  "GET /host HTTP/1.1" 200 0 "-" "ELB-HealthChecker/1.0" - 10.162.217.229:80 /host
10.162.151.170 - - [14/Mar/2011:06:23:19 +0000]  "GET /host HTTP/1.1" 200 0 "-" "ELB-HealthChecker/1.0" - 10.162.217.229:80 /host
10.162.19.235 - - [14/Mar/2011:06:23:19 +0000]  "GET /host HTTP/1.1" 200 0 "-" "ELB-HealthChecker/1.0" - 10.162.217.229:80 /host
. . .
LOTS (~ 100)
. . .
10.162.151.170 - - [14/Mar/2011:06:38:47 +0000]  "GET /host HTTP/1.1" 200 0 "-" "ELB-HealthChecker/1.0" - 10.162.217.229:80 /host
10.162.19.235 - - [14/Mar/2011:06:38:47 +0000]  "GET /host HTTP/1.1" 200 0 "-" "ELB-HealthChecker/1.0" - 10.162.217.229:80 /host
10.162.18.95 - - [14/Mar/2011:06:39:01 +0000]  "GET /host HTTP/1.1" 200 0 "-" "ELB-HealthChecker/1.0" - 10.162.217.229:80 /host
10.162.126.84 - - [14/Mar/2011:06:39:03 +0000]  "GET /host HTTP/1.1" 200 0 "-" "ELB-HealthChecker/1.0" - 10.162.217.229:80 /host
10.162.151.170 - - [14/Mar/2011:06:39:03 +0000]  "GET /host HTTP/1.1" 200 0 "-" "ELB-HealthChecker/1.0" - 10.162.217.229:80 /host
10.162.19.235 - - [14/Mar/2011:06:39:03 +0000]  "GET /host HTTP/1.1" 200 0 "-" "ELB-HealthChecker/1.0" - 10.162.217.229:80 /host
10.162.126.84 - - [14/Mar/2011:06:39:19 +0000]  "GET /host HTTP/1.1" 200 0 "-" "ELB-HealthChecker/1.0" - 10.162.217.229:80 /host
10.162.151.170 - - [14/Mar/2011:06:39:19 +0000]  "GET /host HTTP/1.1" 200 0 "-" "ELB-HealthChecker/1.0" - 10.162.217.229:80 /host
10.162.19.235 - - [14/Mar/2011:06:39:19 +0000]  "GET /host HTTP/1.1" 200 0 "-" "ELB-HealthChecker/1.0" - 10.162.217.229:80 /host
10.162.151.170 - - [14/Mar/2011:06:39:35 +0000]  "GET /host HTTP/1.1" 200 0 "-" "ELB-HealthChecker/1.0" - 10.162.217.229:80 /host
10.162.151.170 - - [14/Mar/2011:06:39:51 +0000]  "GET /host HTTP/1.1" 200 0 "-" "ELB-HealthChecker/1.0" - 10.162.217.229:80 /host
2.3.4.5 - - [14/Mar/2011:06:39:58 +0000]  "GET /stuff HTTP/1.1" 200 113 "http://example.com/stuff" "Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10_6_6; en-US) AppleWebKit/534.16 (KHTML, like Gecko) Chrome/10.0.648.133 Safari/534.16" http example.com /stuff
3.4.5.6 - - [14/Mar/2011:06:39:59 +0000]  "GET /stuff HTTP/1.1" 200 113 "http://example.com/stuff" "Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10_6_6; en-US) AppleWebKit/534.16 (KHTML, like Gecko) Chrome/10.0.648.133 Safari/534.16" http example.com /stuff

Notice the jump back in time, then ELB-only traffic is logged, then logging returns to normal once the ELB timestamps have caught up with user traffic.

Should I expect all nginx log messages to increase chronologically?  What would explain these large jumps back?

We redefined our log format to use a 32k buffer.  Unfortunately, I can't risk changing/disabling this in production to see if the behaviour changes.  Could there be more than one 32k buffer flushing at different times?

Thanks.

Cheers,
David.

Posted at Nginx Forum: http://forum.nginx.org/read.php?2,182969,182969#msg-182969