You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@httpd.apache.org by "Lentes, Bernd" <be...@helmholtz-muenchen.de> on 2011/04/27 17:13:48 UTC
[users@httpd] entries in access_log not chronological
Hi,
we have an Apache 1.3.27. Some entries in the access_log are not chronological, e.g.:
146.107.x.x - - [23/Apr/2011:22:01:03 +0200] "GET / HTTP/1.0" 200 1456
146.107.x.x - - [23/Apr/2011:22:01:03 +0200] "GET / HTTP/1.0" 200 1456
146.107.x.x - - [23/Apr/2011:22:01:03 +0200] "GET / HTTP/1.0" 200 1456
146.107.x.x - - [23/Apr/2011:22:01:03 +0200] "GET / HTTP/1.0" 200 1456
146.107.x.x - - [23/Apr/2011:22:01:03 +0200] "GET / HTTP/1.0" 200 1456
146.107.x.x - - [23/Apr/2011:10:27:30 +0200] "GET / HTTP/1.0" 200 1456
146.107.x.x - - [23/Apr/2011:22:01:03 +0200] "GET / HTTP/1.0" 200 1456
146.107.x.x - - [23/Apr/2011:22:01:03 +0200] "GET / HTTP/1.0" 200 1456
146.107.x.x - - [23/Apr/2011:10:29:36 +0200] "GET / HTTP/1.0" 200 1456
146.107.x.x - - [23/Apr/2011:10:31:43 +0200] "GET / HTTP/1.0" 200 1456
Does anyone know the reason ?
Thanks.
Bernd
--
Bernd Lentes
Systemadministration
Institut für Entwicklungsgenetik
HelmholtzZentrum münchen
bernd.lentes@helmholtz-muenchen.de
phone: +49 89 3187 1241
fax: +49 89 3187 3826
http://www.helmholtz-muenchen.de/idg
Führung bedeutet, die Anderen groß zu machen und sich selbst klein
Helmholtz Zentrum München
Deutsches Forschungszentrum für Gesundheit und Umwelt (GmbH)
Ingolstädter Landstr. 1
85764 Neuherberg
www.helmholtz-muenchen.de
Aufsichtsratsvorsitzende: MinDir´in Bärbel Brumme-Bothe
Geschäftsführer: Prof. Dr. Günther Wess und Dr. Nikolaus Blum
Registergericht: Amtsgericht München HRB 6466
USt-IdNr: DE 129521671
---------------------------------------------------------------------
The official User-To-User support forum of the Apache HTTP Server Project.
See <URL:http://httpd.apache.org/userslist.html> for more info.
To unsubscribe, e-mail: users-unsubscribe@httpd.apache.org
" from the digest: users-digest-unsubscribe@httpd.apache.org
For additional commands, e-mail: users-help@httpd.apache.org
Re: [users@httpd] entries in access_log not chronological
Posted by Eric Covener <co...@gmail.com>.
On Wed, Apr 27, 2011 at 11:13 AM, Lentes, Bernd
<be...@helmholtz-muenchen.de> wrote:
> Hi,
>
> we have an Apache 1.3.27. Some entries in the access_log are not chronological, e.g.:
They're logged when they're complete, but the timestamp in the logfile
is when the request was recevied. When they're out of order, it just
means that some requests took a long time to complete and were lapped
by other requests.
--
Eric Covener
covener@gmail.com
---------------------------------------------------------------------
The official User-To-User support forum of the Apache HTTP Server Project.
See <URL:http://httpd.apache.org/userslist.html> for more info.
To unsubscribe, e-mail: users-unsubscribe@httpd.apache.org
" from the digest: users-digest-unsubscribe@httpd.apache.org
For additional commands, e-mail: users-help@httpd.apache.org
RE: [users@httpd] entries in access_log not chronological
Posted by "Lentes, Bernd" <be...@helmholtz-muenchen.de>.
Jeffrey E Burgoyne wrote:
>
> >
> > I think i've been the victim of a DOS, realised with a SYN
> Flood. I'm
> > not sure, but if yes, that's the first time.
> > Currently i try to understand what happened. I have an entry in
> > error_log which hit me on that idea:
> > "[Sat Apr 23 15:19:02 2011] [error] server reached
> MaxClients setting,
> > consider raising the MaxClients setting"
>
> Pretty sure a syn flood would not do that.
>
You are right. The linux i'm using has implmented SYN COOKIES, which is a protection against SYN FLOODS:
pc51332:/opt/bioinformatics/soft/apache/logs # cat /proc/sys/net/ipv4/tcp_syncookies
1
more information:
http://en.wikipedia.org/wiki/SYN_cookies
http://cr.yp.to/syncookies.html
Bernd
Helmholtz Zentrum München
Deutsches Forschungszentrum für Gesundheit und Umwelt (GmbH)
Ingolstädter Landstr. 1
85764 Neuherberg
www.helmholtz-muenchen.de
Aufsichtsratsvorsitzende: MinDir´in Bärbel Brumme-Bothe
Geschäftsführer: Prof. Dr. Günther Wess und Dr. Nikolaus Blum
Registergericht: Amtsgericht München HRB 6466
USt-IdNr: DE 129521671
RE: [users@httpd] entries in access_log not chronological
Posted by "Lentes, Bernd" <be...@helmholtz-muenchen.de>.
Jeffrey E Burgoyne wrote:
> >
> >>
> >> Actually I think the behavior is the same, but the entry
> >> in the logs
> >> is different. I know in 1.3 it was chronological, which
> >> leads me to
> >> believe it was actually the finish time not the end time.
> >
> > Where is the difference between the finish time and the end time ?
> > Isn't that the same ?
>
> Sorry, finish time not start time.
you mean start time not finish time ?
>
> >
> > I think i've been the victim of a DOS, realised with a SYN
> > Flood. I'm
> > not sure, but if yes, that's the first time.
> > Currently i try to understand what happened. I have an entry in
> > error_log which hit me on that idea:
> > "[Sat Apr 23 15:19:02 2011] [error] server reached
> > MaxClients setting,
> > consider raising the MaxClients setting"
>
> Pretty sure a syn flood would not do that.
does a typ syn on port 80 starts already a new child process ?
>
> I'll bet that for some reason the connections are being kept
> open. Could be anything, even as simple as a bad keep alive session.
>
> Use the server-status page to see where the connections are
> being held open. It has some good diagnostics, including a
> column for how long the request has been served for.
>
>
> >
> > This is strange because this server has very rare visits, normally
> > just my monitoring tool which checks the webserver every
> > two minutes.
> > This tool (ServersAlive, a windows application) never
> > caused any problems.
> > And beginning from saturday 15:30 the tool complains that it can't
> > access the webserver.
> > I had a lot of sockets on the webserver:
> >
> > tcp 133 0 146.107.x.x:80 146.107.135.80:3134
> CLOSE_WAIT
> > -
> > tcp 133 0 146.107.x.x:80 146.107.135.80:3370
> CLOSE_WAIT
> > -
> > tcp 133 0 146.107.x.x:80 146.107.135.80:3102
> CLOSE_WAIT
> > -
> > tcp 133 0 146.107.x.x:80 146.107.135.80:3351
> CLOSE_WAIT
> > -
> > tcp 133 0 146.107.x.x:80 146.107.135.80:3083
> CLOSE_WAIT
> > -
> > tcp 133 0 146.107.x.x:80 146.107.135.80:3333
> CLOSE_WAIT
> > -
> > tcp 133 0 146.107.x.x:80 146.107.135.80:3170
> CLOSE_WAIT
> > -
> > tcp 133 0 146.107.x.x:80 146.107.135.80:3152
> CLOSE_WAIT
> > -
> > tcp 133 0 146.107.x.x:80 146.107.135.80:3393
> CLOSE_WAIT
> > -
> > tcp 133 0 146.107.x.x:80 146.107.135.80:3247
> CLOSE_WAIT
> > -
> > tcp 133 0 146.107.x.x:80 146.107.135.80:3218
> CLOSE_WAIT
> > -
> > tcp 133 0 146.107.x.x:80 146.107.135.80:3059
> CLOSE_WAIT
> > -
> > tcp 133 0 146.107.x.x:80 146.107.135.80:3312
> CLOSE_WAIT
> > -
> > tcp 133 0 146.107.x.x:80 146.107.135.80:3293
> CLOSE_WAIT
> > -
> > tcp 133 0 146.107.x.x:80 146.107.135.80:3030
> CLOSE_WAIT
> > -
> > tcp 133 0 146.107.x.x:80 146.107.135.80:3269
> CLOSE_WAIT
> > -
> > ...
And i also had 150 httpd processes running, + the one from root to open port 80.
>
> OK, based on this and what you wrote below there is something
> with the networking, I am pretty sure. Basically you are
> waiting on IO, which can be network, not just disk. Plus all
> those open connections for what looks likes hours doing
> nothing is also a dead give away. And yes that load average
> is very high, just waiting for IO.
>
>
>
> >
> > The IP 146.107.135.80 is the WinBox my monitoring tool is
> running on.
> >
> >
> > Also "top" on the linux box running the apache was very interesting:
> >
> > top - 13:17:45 up 25 days, 23:40, 4 users, load average: 155.00,
> > 155.01,
> > 155.03
> > Tasks: 587 total, 1 running, 586 sleeping, 0 stopped, 0 zombie
> > Cpu(s): 0.2% us, 0.3% sy, 0.0% ni, 0.0% id, 99.5% wa,
> 0.0% hi,
> > 0.0% si
> > Mem: 2075564k total, 1802740k used, 272824k free,
> > 130936k buffers
> > Swap: 1028152k total, 0k used, 1028152k free,
> > 914700k cached
> >
> > PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
> > 12820 root 17 0 2028 1236 1540 R 1.0 0.1 0:00.23 top
> > 1 root 16 0 588 240 444 S 0.0 0.0 0:22.23 init
> > 2 root RT 0 0 0 0 S 0.0 0.0
> > 0:00.00 migration/0
> > 3 root 34 19 0 0 0 S 0.0 0.0
> > 0:00.22 ksoftirqd/0
> >
Bernd
Helmholtz Zentrum München
Deutsches Forschungszentrum für Gesundheit und Umwelt (GmbH)
Ingolstädter Landstr. 1
85764 Neuherberg
www.helmholtz-muenchen.de
Aufsichtsratsvorsitzende: MinDir´in Bärbel Brumme-Bothe
Geschäftsführer: Prof. Dr. Günther Wess und Dr. Nikolaus Blum
Registergericht: Amtsgericht München HRB 6466
USt-IdNr: DE 129521671
RE: [users@httpd] entries in access_log not chronological
Posted by "Lentes, Bernd" <be...@helmholtz-muenchen.de>.
Jeffrey E Burgoyne wrote:
>
> Actually I think the behavior is the same, but the entry in
> the logs is different. I know in 1.3 it was chronological,
> which leads me to believe it was actually the finish time not
> the end time.
Where is the difference between the finish time and the end time ? Isn't that the same ?
> And yes you are correct about the ten hours, although that
> really seems odd if not downright impossible now that you
> point that out. I did not notice the time lag.
>
> I'd definitely use the %T to ensure those numbers are
> correct. Not saying they are incorrect, but they are well
> beyond anything I have seen or could imagine.
>
> >
I think i've been the victim of a DOS, realised with a SYN Flood. I'm not sure, but if yes, that's the first time.
Currently i try to understand what happened. I have an entry in error_log which hit me on that idea:
"[Sat Apr 23 15:19:02 2011] [error] server reached MaxClients setting, consider raising the MaxClients setting"
This is strange because this server has very rare visits, normally just my monitoring tool which checks the webserver every two minutes.
This tool (ServersAlive, a windows application) never caused any problems. And beginning from saturday 15:30 the tool complains that it can't access the webserver.
I had a lot of sockets on the webserver:
tcp 133 0 146.107.x.x:80 146.107.135.80:3134 CLOSE_WAIT -
tcp 133 0 146.107.x.x:80 146.107.135.80:3370 CLOSE_WAIT -
tcp 133 0 146.107.x.x:80 146.107.135.80:3102 CLOSE_WAIT -
tcp 133 0 146.107.x.x:80 146.107.135.80:3351 CLOSE_WAIT -
tcp 133 0 146.107.x.x:80 146.107.135.80:3083 CLOSE_WAIT -
tcp 133 0 146.107.x.x:80 146.107.135.80:3333 CLOSE_WAIT -
tcp 133 0 146.107.x.x:80 146.107.135.80:3170 CLOSE_WAIT -
tcp 133 0 146.107.x.x:80 146.107.135.80:3152 CLOSE_WAIT -
tcp 133 0 146.107.x.x:80 146.107.135.80:3393 CLOSE_WAIT -
tcp 133 0 146.107.x.x:80 146.107.135.80:3247 CLOSE_WAIT -
tcp 133 0 146.107.x.x:80 146.107.135.80:3218 CLOSE_WAIT -
tcp 133 0 146.107.x.x:80 146.107.135.80:3059 CLOSE_WAIT -
tcp 133 0 146.107.x.x:80 146.107.135.80:3312 CLOSE_WAIT -
tcp 133 0 146.107.x.x:80 146.107.135.80:3293 CLOSE_WAIT -
tcp 133 0 146.107.x.x:80 146.107.135.80:3030 CLOSE_WAIT -
tcp 133 0 146.107.x.x:80 146.107.135.80:3269 CLOSE_WAIT -
...
The IP 146.107.135.80 is the WinBox my monitoring tool is running on.
Also "top" on the linux box running the apache was very interesting:
top - 13:17:45 up 25 days, 23:40, 4 users, load average: 155.00, 155.01, 155.03
Tasks: 587 total, 1 running, 586 sleeping, 0 stopped, 0 zombie
Cpu(s): 0.2% us, 0.3% sy, 0.0% ni, 0.0% id, 99.5% wa, 0.0% hi, 0.0% si
Mem: 2075564k total, 1802740k used, 272824k free, 130936k buffers
Swap: 1028152k total, 0k used, 1028152k free, 914700k cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
12820 root 17 0 2028 1236 1540 R 1.0 0.1 0:00.23 top
1 root 16 0 588 240 444 S 0.0 0.0 0:22.23 init
2 root RT 0 0 0 0 S 0.0 0.0 0:00.00 migration/0
3 root 34 19 0 0 0 S 0.0 0.0 0:00.22 ksoftirqd/0
The load average is ... impressing. But working on the bash, the server reacted normally.
Also the CPU time for IO-waiting (99.5% wa) was extremly high, although the led for harddisk activity didn't flash often.
Bernd
> > Jeffrey E Burgoyne wrote:
> >
> >>
> >> The time listed is the time the request was received and
> the order is
> >> based on the time it finished is the most likely culprit. Requests
> >> taking longer will cause this.
> >>
> >> You can verify by adding %T parameter to your logging as
> that gives
> >> you the time it took to finish the request.
> >>
> >
> > Thanks for the explaination. I will add the %T in my logs. Is the
> > behaviour in Apache 1.3 and 2 the same ?
> > Concerning my requests that would mean that some requests needed
> > nearly 10 hours to be served, right ?
> >
> >>
> >>
> >
Helmholtz Zentrum München
Deutsches Forschungszentrum für Gesundheit und Umwelt (GmbH)
Ingolstädter Landstr. 1
85764 Neuherberg
www.helmholtz-muenchen.de
Aufsichtsratsvorsitzende: MinDir´in Bärbel Brumme-Bothe
Geschäftsführer: Prof. Dr. Günther Wess und Dr. Nikolaus Blum
Registergericht: Amtsgericht München HRB 6466
USt-IdNr: DE 129521671
RE: [users@httpd] entries in access_log not chronological
Posted by Jeffrey E Burgoyne <bu...@keenuh.com>.
Actually I think the behavior is the same, but the entry in the logs is
different. I know in 1.3 it was chronological, which leads me to believe
it was actually the finish time not the end time. To be honest that was a
few years ago, I remember the change but not the details.
And yes you are correct about the ten hours, although that really seems
odd if not downright impossible now that you point that out. I did not
notice the time lag.
I'd definitely use the %T to ensure those numbers are correct. Not saying
they are incorrect, but they are well beyond anything I have seen or could
imagine.
>
> Jeffrey E Burgoyne wrote:
>
>>
>> The time listed is the time the request was received and the
>> order is based on the time it finished is the most likely
>> culprit. Requests taking longer will cause this.
>>
>> You can verify by adding %T parameter to your logging as that
>> gives you the time it took to finish the request.
>>
>
> Thanks for the explaination. I will add the %T in my logs. Is the
> behaviour in Apache 1.3 and 2 the same ?
> Concerning my requests that would mean that some requests needed nearly 10
> hours to be served, right ?
>
>>
>>
>> > Hi,
>> >
>> > we have an Apache 1.3.27. Some entries in the access_log are not
>> > chronological, e.g.:
>> >
>> > 146.107.x.x - - [23/Apr/2011:22:01:03 +0200] "GET /
>> HTTP/1.0" 200 1456
>> > 146.107.x.x - - [23/Apr/2011:22:01:03 +0200] "GET /
>> HTTP/1.0" 200 1456
>> > 146.107.x.x - - [23/Apr/2011:22:01:03 +0200] "GET /
>> HTTP/1.0" 200 1456
>> > 146.107.x.x - - [23/Apr/2011:22:01:03 +0200] "GET /
>> HTTP/1.0" 200 1456
>> > 146.107.x.x - - [23/Apr/2011:22:01:03 +0200] "GET /
>> HTTP/1.0" 200 1456
>> > 146.107.x.x - - [23/Apr/2011:10:27:30 +0200] "GET /
>> HTTP/1.0" 200 1456
>> > 146.107.x.x - - [23/Apr/2011:22:01:03 +0200] "GET /
>> HTTP/1.0" 200 1456
>> > 146.107.x.x - - [23/Apr/2011:22:01:03 +0200] "GET /
>> HTTP/1.0" 200 1456
>> > 146.107.x.x - - [23/Apr/2011:10:29:36 +0200] "GET /
>> HTTP/1.0" 200 1456
>> > 146.107.x.x - - [23/Apr/2011:10:31:43 +0200] "GET /
>> HTTP/1.0" 200 1456
>> >
>
> Bernd
>
> Helmholtz Zentrum München
> Deutsches Forschungszentrum für Gesundheit und Umwelt (GmbH)
> Ingolstädter Landstr. 1
> 85764 Neuherberg
> www.helmholtz-muenchen.de
> Aufsichtsratsvorsitzende: MinDir´in Bärbel Brumme-Bothe
> Geschäftsführer: Prof. Dr. Günther Wess und Dr. Nikolaus Blum
> Registergericht: Amtsgericht München HRB 6466
> USt-IdNr: DE 129521671
>
--
Jeffrey Burgoyne
Chief Technology Officer
KCSI Keenuh Consulting Services Inc
www.keenuh.com
burgoyne@keenuh.com
---------------------------------------------------------------------
The official User-To-User support forum of the Apache HTTP Server Project.
See <URL:http://httpd.apache.org/userslist.html> for more info.
To unsubscribe, e-mail: users-unsubscribe@httpd.apache.org
" from the digest: users-digest-unsubscribe@httpd.apache.org
For additional commands, e-mail: users-help@httpd.apache.org
RE: [users@httpd] entries in access_log not chronological
Posted by "Lentes, Bernd" <be...@helmholtz-muenchen.de>.
Jeffrey E Burgoyne wrote:
>
> The time listed is the time the request was received and the
> order is based on the time it finished is the most likely
> culprit. Requests taking longer will cause this.
>
> You can verify by adding %T parameter to your logging as that
> gives you the time it took to finish the request.
>
Thanks for the explaination. I will add the %T in my logs. Is the behaviour in Apache 1.3 and 2 the same ?
Concerning my requests that would mean that some requests needed nearly 10 hours to be served, right ?
>
>
> > Hi,
> >
> > we have an Apache 1.3.27. Some entries in the access_log are not
> > chronological, e.g.:
> >
> > 146.107.x.x - - [23/Apr/2011:22:01:03 +0200] "GET /
> HTTP/1.0" 200 1456
> > 146.107.x.x - - [23/Apr/2011:22:01:03 +0200] "GET /
> HTTP/1.0" 200 1456
> > 146.107.x.x - - [23/Apr/2011:22:01:03 +0200] "GET /
> HTTP/1.0" 200 1456
> > 146.107.x.x - - [23/Apr/2011:22:01:03 +0200] "GET /
> HTTP/1.0" 200 1456
> > 146.107.x.x - - [23/Apr/2011:22:01:03 +0200] "GET /
> HTTP/1.0" 200 1456
> > 146.107.x.x - - [23/Apr/2011:10:27:30 +0200] "GET /
> HTTP/1.0" 200 1456
> > 146.107.x.x - - [23/Apr/2011:22:01:03 +0200] "GET /
> HTTP/1.0" 200 1456
> > 146.107.x.x - - [23/Apr/2011:22:01:03 +0200] "GET /
> HTTP/1.0" 200 1456
> > 146.107.x.x - - [23/Apr/2011:10:29:36 +0200] "GET /
> HTTP/1.0" 200 1456
> > 146.107.x.x - - [23/Apr/2011:10:31:43 +0200] "GET /
> HTTP/1.0" 200 1456
> >
Bernd
Helmholtz Zentrum München
Deutsches Forschungszentrum für Gesundheit und Umwelt (GmbH)
Ingolstädter Landstr. 1
85764 Neuherberg
www.helmholtz-muenchen.de
Aufsichtsratsvorsitzende: MinDir´in Bärbel Brumme-Bothe
Geschäftsführer: Prof. Dr. Günther Wess und Dr. Nikolaus Blum
Registergericht: Amtsgericht München HRB 6466
USt-IdNr: DE 129521671