[Zope] Ever seen this problem?

Eric W. Sink eric@sourcegear.com
Mon, 13 Dec 1999 09:27:39 -0600


A followup to my own post.  We are still having problems, but we have
some new information:

> We tried activating the debug_log once, using instructions obtained
> from a message posted to this list.  Unfortunately, that was the
> attempt wherein Zope ran for half an hour under heavy load with no
> problem.

Our server got hung up again, last night at 3:42am.  But this time, I
had the debug log running.  The result may be interesting to somebody,
but I don't think I know enough to interpret it.

The last two entries in Z2.log are:

aaa.bbb.ccc.ddd - - [13/Dec/1999:03:42:50 -0500] "GET /SRF/images/srflogo64 HTTP/1.0" 200 18236 "http://www.sourcegear.com/SRF" "Mozilla/4.7 [en] (WinNT; U)"
aaa.bbb.ccc.ddd - - [13/Dec/1999:03:42:51 -0500] "GET /SRF/images/srfad HTTP/1.0" 200 49994 "http://www.sourcegear.com/SRF" "Mozilla/4.7 [en] (WinNT; U)"

and those entries seem to be reflected properly in the debug.log file:

B 143352400 1999-12-13T03:42:50 GET /SRF/images/srflogo64
I 143352400 1999-12-13T03:42:50 0
B 144071968 1999-12-13T03:42:50 GET /SRF/images/srfad
I 144071968 1999-12-13T03:42:50 0
A 143352400 1999-12-13T03:42:50 200 18236
E 143352400 1999-12-13T03:42:50
A 144071968 1999-12-13T03:42:50 200 49994
E 144071968 1999-12-13T03:42:51

The debug.log file has an obvious pattern.  Every web server hit seems
to generate four entries in the file, each with a different letter at
the beginning of the line: B, I, A, and E.  I'm speculating that these
entries correspond to four stages of serving the transaction, and that
the B and E probably refer to Beginning and End.

There are no further entries in Z2.log, but there are LOTS of
subsequent entries in debug.log.  The first few look like this:

B 143461304 1999-12-13T03:43:04 GET /robots.txt
I 143461304 1999-12-13T03:43:04 0
B 143095944 1999-12-13T03:43:10 GET /Store
I 143095944 1999-12-13T03:43:10 0
B 143514056 1999-12-13T03:44:59 GET /SOS
I 143514056 1999-12-13T03:44:59 0

and that remains the pattern for the remainder of the debug.log file.
Every attempted web transaction generates a B line and an I line, but
there is never an A or E line.

It appears interesting to note that the first failed transaction
attempt was a fetch of /robots.txt, but I think that's a coincidence.
We do not have a robots.txt file on our site right now, but there are
lots of other occurrences in the log files of attempts to fetch that
file, returning the 404 properly.

Any ideas?

-- 
Eric W. Sink, Software Craftsman
SourceGear Corporation
eric@sourcegear.com