Received: (qmail 2369 invoked by uid 2012); 18 Oct 1998 13:13:43 -0000 Message-Id: <19981018131343.2368.qmail@hyperreal.org> Date: 18 Oct 1998 13:13:43 -0000 From: Klaus Johannes Rusch Reply-To: KlausRusch@atmedia.net To: apbugs@hyperreal.org Subject: Some log records are out of order X-Send-Pr-Version: 3.2 >Number: 3231 >Category: mod_log-any >Synopsis: Some log records are out of order >Confidential: no >Severity: non-critical >Priority: medium >Responsible: apache >State: closed >Class: sw-bug >Submitter-Id: apache >Arrival-Date: Sun Oct 18 06:20:00 PDT 1998 >Last-Modified: Sun Oct 18 15:10:00 PDT 1998 >Originator: KlausRusch@atmedia.net >Organization: >Release: 1.3 >Environment: SunOS columbia.digiweb.com 5.6 Generic_105181-06 sun4u sparc SUNW,Ultra-1 >Description: Some log records are out of order, showing earlier access last, e.g. (anonymized) somehost.domain.com - - [16/Oct/1998:17:07:00 -0400] "GET /Directory/image/bg.gif HTTP/1.0" 200 569 "http://server.domain.com/Directory/page.html" "Mozilla/4.07 [en] (Win98; U)" somehost.domain.com - - [16/Oct/1998:17:07:02 -0400] "GET /Directory/image/story.gif HTTP/1.0" 200 9554 "http://server.domain.com/Directory/page.html" "Mozilla/4.07 [en] (Win98; U)" somehost.domain.com - - [16/Oct/1998:17:07:02 -0400] "GET /Directory/image/welcome.gif HTTP/1.0" 200 1440 "http://server.domain.com/Directory/page.html" "Mozilla/4.07 [en] (Win98; U)" somehost.domain.com - - [16/Oct/1998:17:07:14 -0400] "GET /Directory/page.html HTTP/1.0" 200 24290 "-" "Mozilla/4.07 [en] (Win98; U)" page.html has accessed first, yet in the logs shows up last (possibly due to persistant connection with the HTML file being the first request, and logging occurring only after that request and subsequent subrequests have terminated?) >How-To-Repeat: >Fix: >Audit-Trail: From: Marc Slemko To: Klaus Johannes Rusch Cc: apbugs@hyperreal.org Subject: Re: mod_log-any/3231: Some log records are out of order Date: Sun, 18 Oct 1998 10:06:55 -0700 (PDT) On 18 Oct 1998, Klaus Johannes Rusch wrote: > >Description: Some log records are out of order, showing earlier > access last, e.g. (anonymized) > > somehost.domain.com - - [16/Oct/1998:17:07:00 -0400] "GET /Directory/image/bg.gif HTTP/1.0" 200 569 "http://server.domain.com/Directory/page.html" "Mozilla/4.07 [en] (Win98; U)" > somehost.domain.com - - [16/Oct/1998:17:07:02 -0400] "GET /Directory/image/story.gif HTTP/1.0" 200 9554 "http://server.domain.com/Directory/page.html" "Mozilla/4.07 [en] (Win98; U)" > somehost.domain.com - - [16/Oct/1998:17:07:02 -0400] "GET /Directory/image/welcome.gif HTTP/1.0" 200 1440 "http://server.domain.com/Directory/page.html" "Mozilla/4.07 [en] (Win98; U)" > somehost.domain.com - - [16/Oct/1998:17:07:14 -0400] "GET /Directory/page.html HTTP/1.0" 200 24290 "-" "Mozilla/4.07 [en] (Win98; U)" > > page.html has accessed first, yet in the logs shows up last (possibly > due to persistant connection with the HTML file being the first > request, and logging occurring only after that request and subsequent > subrequests have terminated?) How do you know that page.html was accessed first? It is quite practical that if the client is using multiple connections then it will start downloading the HTML in one, and start getting various images in others as it parses it. In this case, the images are shorter than the HTML so it is very possible that they complete first. From: Klaus Johannes Rusch To: Marc Slemko Cc: apbugs@hyperreal.org Subject: Re: mod_log-any/3231: Some log records are out of order Date: Sun, 18 Oct 1998 22:33:25 CET In , Marc Slemko writes: > On 18 Oct 1998, Klaus Johannes Rusch wrote: > > How do you know that page.html was accessed first? > > It is quite practical that if the client is using multiple connections > then it will start downloading the HTML in one, and start getting various > images in others as it parses it. In this case, the images are shorter > than the HTML so it is very possible that they complete first. So the log time indicates when the request was COMPLETED rather than when the request was STARTED? State-Changed-From-To: open-closed State-Changed-By: marc State-Changed-When: Sun Oct 18 13:52:48 PDT 1998 State-Changed-Why: No evidence of anything actually being logged out of order. From: Marc Slemko To: Klaus Johannes Rusch Cc: Apache bugs database Subject: Re: mod_log-any/3231: Some log records are out of order Date: Sun, 18 Oct 1998 13:52:23 -0700 (PDT) On Sun, 18 Oct 1998, Klaus Johannes Rusch wrote: > In , Marc Slemko writes: > > On 18 Oct 1998, Klaus Johannes Rusch wrote: > > > > How do you know that page.html was accessed first? > > > > It is quite practical that if the client is using multiple connections > > then it will start downloading the HTML in one, and start getting various > > images in others as it parses it. In this case, the images are shorter > > than the HTML so it is very possible that they complete first. > > So the log time indicates when the request was COMPLETED rather than when the > request was STARTED? > Yes. >Unformatted: [In order for any reply to be added to the PR database, ] [you need to include in the Cc line ] [and leave the subject line UNCHANGED. This is not done] [automatically because of the potential for mail loops. ] [If you do not include this Cc, your reply may be ig- ] [nored unless you are responding to an explicit request ] [from a developer. ] [Reply only with text; DO NOT SEND ATTACHMENTS! ]