Welcome! Log In Create A New Profile

Advanced

nginx access logs, timestamps "jump back"

March 15, 2011 12:41AM
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.
Subject Author Posted

nginx access logs, timestamps "jump back"

assistlydavid March 15, 2011 12:41AM

Re: nginx access logs, timestamps "jump back"

Maxim Dounin March 15, 2011 01:40AM

Re: nginx access logs, timestamps "jump back"

assistlydavid March 15, 2011 10:26PM

Re: nginx access logs, timestamps "jump back"

Maxim Dounin March 16, 2011 10:30AM

Re: nginx access logs, timestamps "jump back"

assistlydavid March 16, 2011 07:03PM



Sorry, only registered users may post in this forum.

Click here to login

Online Users

Guests: 324
Record Number of Users: 8 on April 13, 2023
Record Number of Guests: 421 on December 02, 2018
Powered by nginx      Powered by FreeBSD      PHP Powered      Powered by MariaDB      ipv6 ready