Re: [Zope-dev] Logging of ConflictError

2005-12-05 Thread Chris Withers

Dennis Allison wrote:

Dieter's point about not includeing the traceback makes sense
if all it does is report on the reporting code.


Yeah, the traceback just shows where the ConflictError was raised, not 
what caused it, and theyr'e always in very different places...



Wlorent, do you envision a single ConflicError or two -- one which
succeeds on retry and another where the retry fails?


Huh?

ConflictErrors are ConflictErrors, it's a server level decision as to 
how they're handled. Zope chooses to retry the whole request up to 3 
times when a ConflictError occurs.


The new logging code I put in records exactly how many conflicts have 
occurrred, and how many remain unresolved even after 3 retries.


I know you've been having fun with this type of error, so you might well 
want to grav the changes from svn and give them a spin...


cheers,

Chris

--
Simplistix - Content Management, Zope  Python Consulting
   - http://www.simplistix.co.uk

___
Zope-Dev maillist  -  Zope-Dev@zope.org
http://mail.zope.org/mailman/listinfo/zope-dev
**  No cross posts or HTML encoding!  **
(Related lists - 
http://mail.zope.org/mailman/listinfo/zope-announce

http://mail.zope.org/mailman/listinfo/zope )


Re: [Zope-dev] Logging of ConflictError

2005-12-04 Thread Dieter Maurer
Florent Guillaume wrote at 2005-12-2 22:59 +0100:
 ...
If you look at the way their purpose is explained in zLOG, you'll see  
that level INFO is reserved for things like server startup and  
shutdown.
Or, as shown above, initial mounting of databases. Anything  
recurring that can happen many times in the life of the server but  
does not pose any problems should *not* be visible at INFO.

Really?

You infer that from the

  INFO  For things like startup and shutdown, do you?

That's very weak reasoning...

  The level obviously has an importance association:
  higher values indicate higher importance.


If fact, the ConflictError messages should not be reported
at INFO but at level PROBLEM because

   they are not causing any immediate problems, but
   deserve attention.

On the other hand, that's exactly what BLATHER is for folks! Use it!  

You see it this way. I do not:

  ConflictErrors are definitely as important as mount
  messages and therefore should be reported on at least
  the level of mount reports: i.e. at INFO or above.

-- 
Dieter
___
Zope-Dev maillist  -  Zope-Dev@zope.org
http://mail.zope.org/mailman/listinfo/zope-dev
**  No cross posts or HTML encoding!  **
(Related lists - 
 http://mail.zope.org/mailman/listinfo/zope-announce
 http://mail.zope.org/mailman/listinfo/zope )


Re: [Zope-dev] Logging of ConflictError

2005-12-04 Thread Dennis Allison

Dieter's point about not includeing the traceback makes sense
if all it does is report on the reporting code.

Wlorent, do you envision a single ConflicError or two -- one which
succeeds on retry and another where the retry fails?


On Sun, 4 Dec 2005, Dieter Maurer wrote:

 Florent Guillaume wrote at 2005-12-2 22:59 +0100:
  ...
 If you look at the way their purpose is explained in zLOG, you'll see  
 that level INFO is reserved for things like server startup and  
 shutdown.
 Or, as shown above, initial mounting of databases. Anything  
 recurring that can happen many times in the life of the server but  
 does not pose any problems should *not* be visible at INFO.
 
 Really?
 
 You infer that from the
 
   INFO  For things like startup and shutdown, do you?
 
 That's very weak reasoning...
 
   The level obviously has an importance association:
   higher values indicate higher importance.
 
 
 If fact, the ConflictError messages should not be reported
 at INFO but at level PROBLEM because
 
they are not causing any immediate problems, but
deserve attention.
 
 On the other hand, that's exactly what BLATHER is for folks! Use it!  
 
 You see it this way. I do not:
 
   ConflictErrors are definitely as important as mount
   messages and therefore should be reported on at least
   the level of mount reports: i.e. at INFO or above.
 
 

-- 

___
Zope-Dev maillist  -  Zope-Dev@zope.org
http://mail.zope.org/mailman/listinfo/zope-dev
**  No cross posts or HTML encoding!  **
(Related lists - 
 http://mail.zope.org/mailman/listinfo/zope-announce
 http://mail.zope.org/mailman/listinfo/zope )


Re: [Zope-dev] Logging of ConflictError

2005-12-02 Thread Chris Withers

Hi Florent,

Damn, I was working on this at the same time :-S

Florent Guillaume wrote:

I've improved the logging of ConflictError in Zope 2.9 and trunk.

http://svn.zope.org/?rev=40454view=rev

Now you'll get two things:
- logs at level BLATHER for each conflict, but it may be retried
- log at level ERROR when the conflict can't be retried anymore and is 
returned to the browser as an error.


In my work, I've actually changed this to use the new, proper logging 
calls. I'll be comitting later this morning.


I removed the log at level INFO because it is very misleading for system 
administrators in my experience.


I don't think so, I've actually changed and enhanced this in my work. 
You now get a log at INFO whenever a conflict occurs. It includes more 
information than the old version, as you'll see...


Do people want this also for 2.8? Note that it changes the log format, 
so may break third party tools that parse logs.


I was planning on rolling my changes out to 2.8, 2.9 and the trunk. 
Unless anyone strenuously objects, I still intend to do that. I cleaned 
up a lot of the code and made a few other changes that generally improve 
logging.


It's a shame Florent and I were genuinely working on this at the same 
time without the other knowing...


cheers,

Chris

--
Simplistix - Content Management, Zope  Python Consulting
   - http://www.simplistix.co.uk

___
Zope-Dev maillist  -  Zope-Dev@zope.org
http://mail.zope.org/mailman/listinfo/zope-dev
**  No cross posts or HTML encoding!  **
(Related lists - 
http://mail.zope.org/mailman/listinfo/zope-announce

http://mail.zope.org/mailman/listinfo/zope )


Re: [Zope-dev] Logging of ConflictError

2005-12-02 Thread Florent Guillaume

On 2 Dec 2005, at 11:09, Chris Withers wrote:

Damn, I was working on this at the same time :-S

Florent Guillaume wrote:

I've improved the logging of ConflictError in Zope 2.9 and trunk.
http://svn.zope.org/?rev=40454view=rev
Now you'll get two things:
- logs at level BLATHER for each conflict, but it may be retried
- log at level ERROR when the conflict can't be retried anymore  
and is returned to the browser as an error.


In my work, I've actually changed this to use the new, proper  
logging calls. I'll be comitting later this morning.


It doesn't really matter, zLOG has a compatibility layer that ends up  
doing the same thing.


I removed the log at level INFO because it is very misleading for  
system administrators in my experience.


I don't think so, I've actually changed and enhanced this in my  
work. You now get a log at INFO whenever a conflict occurs. It  
includes more information than the old version, as you'll see...


Please no. Don't put anything at INFO. A conflict error is either  
something normal that should be at level BLATHER or below, or an  
ERROR that a sysadmin wants to see logged as such. INFO sucks for  
recurring stuff like that that in addition contain the word error  
which it isn't. I can't count the number of sysadmin/customers/ 
hosting providers that freak out when something like that appears in  
the log and call us and we have to explain that yes, it's not logical  
but...


Do people want this also for 2.8? Note that it changes the log  
format, so may break third party tools that parse logs.


I was planning on rolling my changes out to 2.8, 2.9 and the trunk.  
Unless anyone strenuously objects, I still intend to do that. I  
cleaned up a lot of the code and made a few other changes that  
generally improve logging.


It's a shame Florent and I were genuinely working on this at the  
same time without the other knowing...


Well, I told you on the list that I was already working on this. You  
didn't pay attention I guess.


Florent

--
Florent Guillaume, Nuxeo (Paris, France)   Director of RD
+33 1 40 33 71 59   http://nuxeo.com   [EMAIL PROTECTED]



___
Zope-Dev maillist  -  Zope-Dev@zope.org
http://mail.zope.org/mailman/listinfo/zope-dev
**  No cross posts or HTML encoding!  **
(Related lists - 
http://mail.zope.org/mailman/listinfo/zope-announce

http://mail.zope.org/mailman/listinfo/zope )


Re: [Zope-dev] Logging of ConflictError

2005-12-02 Thread Florent Guillaume

On 2 Dec 2005, at 11:09, Chris Withers wrote:
I was planning on rolling my changes out to 2.8, 2.9 and the trunk.  
Unless anyone strenuously objects, I still intend to do that. I  
cleaned up a lot of the code and made a few other changes that  
generally improve logging.


I strenuously object to you overwriting without consultation code I  
just checked in and that was approved by at least 3 people.


And I'm totally -1 on any logging at level INFO or above about  
retriable conflict errors.


Florent

--
Florent Guillaume, Nuxeo (Paris, France)   Director of RD
+33 1 40 33 71 59   http://nuxeo.com   [EMAIL PROTECTED]



___
Zope-Dev maillist  -  Zope-Dev@zope.org
http://mail.zope.org/mailman/listinfo/zope-dev
**  No cross posts or HTML encoding!  **
(Related lists - 
http://mail.zope.org/mailman/listinfo/zope-announce

http://mail.zope.org/mailman/listinfo/zope )


Re: [Zope-dev] Logging of ConflictError

2005-12-02 Thread Chris Withers

Florent Guillaume wrote:
It doesn't really matter, zLOG has a compatibility layer that ends up  
doing the same thing.


python's logging module has a cleaner, nicer syntax.

Please no. Don't put anything at INFO. A conflict error is either  
something normal that should be at level BLATHER or below, or an  ERROR 
that a sysadmin wants to see logged as such. 


Not so. If I'm getting 1,000 resolved conflict errors a day, that can be 
a big performance hit, and there are those of us who have hard 
performance targets to meet ;-) Turning on debug logging is, in itself, 
a performance hit, so I don't want to have to do that on a production 
service where I want to observe the number of conflict errors occurring 
over a long period of time, like, say, a month.


INFO sucks for  recurring 
stuff like that that in addition contain the word error  which it 
isn't.


Well, that's a problem with the exception naming, and I agree with you, 
but I don't know how hard that is to change.


I can't count the number of sysadmin/customers/ hosting providers 
that freak out when something like that appears in  the log and call us 
and we have to explain that yes, it's not logical  but...


Stupid sysadmins can't be helped. It's being logged at INFO, not ERROR 
or WARNING. I agree, the exception should be renamed to just Conflict, 
but that's a totally different discussion.


Well, I told you on the list that I was already working on this. You  
didn't pay attention I guess.


You made a vague comment on the 21st Nov.
I made a definite commitment on the 24th Nov.
On the 25th, you said you were working on it in response to my question.
Now, by yesterday, 6 days later, nothing had happened, so I fixed this 
and did some other work with stupid error messages along the way.

Then, suddenly, yesterday you commit. *sigh*

Anyway, I'm going to check in the changes because they're materially the 
same but the code is cleaner.


Whether resolved conflict errors are logged at INFO or DEBUG is a 
seperate discussion and one which I'd like to see a lot more comments on 
than have been seen so far. The +1s from people yesterday were about the 
general merging of the fix to 2.8, which I would also +1 to ;-)


However, changing from INFO to DEBUG is a change in functionality which 
_I_ strenuously object to. People _need_ to be aware that they are 
seeing conflict errors, even if they are resolved. I, for one, really 
really want to be able to look in the event log and see if _any_ 
conflict errors are occurring, resolved or not, and keep track of the 
number of them so I can spot any performance hotspots before they become 
critical. FWIW, the stuff I log at INFO makes it clearer as to which 
conflicts are resolved or not, so your sysadmin types should be happier.


What do people other than Florent, whose view I think we know, feel 
about this?


cheers,

Chris

--
Simplistix - Content Management, Zope  Python Consulting
   - http://www.simplistix.co.uk
___
Zope-Dev maillist  -  Zope-Dev@zope.org
http://mail.zope.org/mailman/listinfo/zope-dev
**  No cross posts or HTML encoding!  **
(Related lists - 
http://mail.zope.org/mailman/listinfo/zope-announce

http://mail.zope.org/mailman/listinfo/zope )


Re: [Zope-dev] Logging of ConflictError

2005-12-02 Thread Chris Withers

Florent Guillaume wrote:
Please no. Don't put anything at INFO. A conflict error is either  
something normal that should be at level BLATHER or below, or an  ERROR 
that a sysadmin wants to see logged as such. 


Incidentally, your changes result in most users seeing two errors in 
their logs when they should just see one. I'm not aware of many serious 
users who don't copy the output of the error_log object to the event 
log, so with your changes, you'll end up with the error that ends up in 
the error_log, and your seperate LOG call's message.


cheers,

Chris

--
Simplistix - Content Management, Zope  Python Consulting
   - http://www.simplistix.co.uk
___
Zope-Dev maillist  -  Zope-Dev@zope.org
http://mail.zope.org/mailman/listinfo/zope-dev
**  No cross posts or HTML encoding!  **
(Related lists - 
http://mail.zope.org/mailman/listinfo/zope-announce

http://mail.zope.org/mailman/listinfo/zope )


Re: [Zope-dev] Logging of ConflictError

2005-12-02 Thread Jens Vagelpohl


On 2 Dec 2005, at 14:16, Chris Withers wrote:
Please no. Don't put anything at INFO. A conflict error is either   
something normal that should be at level BLATHER or below, or an   
ERROR that a sysadmin wants to see logged as such.


Not so. If I'm getting 1,000 resolved conflict errors a day, that  
can be a big performance hit, and there are those of us who have  
hard performance targets to meet ;-) Turning on debug logging is,  
in itself, a performance hit, so I don't want to have to do that on  
a production service where I want to observe the number of conflict  
errors occurring over a long period of time, like, say, a month.


I agree with this argumentation. It is true that conflicts are a  
normal part of operation, as we all like to tell people who are  
scared/confused by them, but if you see so many that it bothers you  
seeing it at INFO level you know you have a problem that needs fixing.


Same is true for the panicking sysadmins that call up the developers.  
If they call because of that they should have gotten better training  
before starting to admin Zope setups, or they shouldn't be doing it  
at all.


jens

___
Zope-Dev maillist  -  Zope-Dev@zope.org
http://mail.zope.org/mailman/listinfo/zope-dev
**  No cross posts or HTML encoding!  **
(Related lists - 
http://mail.zope.org/mailman/listinfo/zope-announce

http://mail.zope.org/mailman/listinfo/zope )


Re: [Zope-dev] Logging of ConflictError

2005-12-02 Thread Paul Winkler
On Fri, Dec 02, 2005 at 02:09:56PM +0100, Florent Guillaume wrote:
 On 2 Dec 2005, at 11:09, Chris Withers wrote:
 I was planning on rolling my changes out to 2.8, 2.9 and the trunk.  
 Unless anyone strenuously objects, I still intend to do that. I  
 cleaned up a lot of the code and made a few other changes that  
 generally improve logging.
 
 I strenuously object to you overwriting without consultation code I  
 just checked in and that was approved by at least 3 people.

I'm +1 on having failed retries show up at level ERROR.

I'm neutral on having successful retries show up at level INFO, BLATHER,
or in some other log handler entirely.  Conflict errors are a pretty
small part of my world and I don't really have a strong opinion on this
part of the debate, and I don't have time to review either of
your patches.

-- 

Paul Winkler
http://www.slinkp.com
___
Zope-Dev maillist  -  Zope-Dev@zope.org
http://mail.zope.org/mailman/listinfo/zope-dev
**  No cross posts or HTML encoding!  **
(Related lists - 
 http://mail.zope.org/mailman/listinfo/zope-announce
 http://mail.zope.org/mailman/listinfo/zope )


Re: [Zope-dev] Logging of ConflictError

2005-12-02 Thread Dieter Maurer
Florent Guillaume wrote at 2005-12-1 19:49 +0100:
I've improved the logging of ConflictError in Zope 2.9 and trunk.

http://svn.zope.org/?rev=40454view=rev

Now you'll get two things:
- logs at level BLATHER for each conflict, but it may be retried
- log at level ERROR when the conflict can't be retried anymore and is 
returned to the browser as an error.

Apparently, you stopped following our thread (you, Chris, me):

  In my view, a ConflictError observed by the user
  should be treated exactly like any other exception observed by the user:
  it should go through the error_log and standard_error_message.
  It might be logged (when the user decides that exceptions seen
  by the user should be logged).

  The approach to achieve this it to fix a bug in Zope's
  zpublisher_exception_hook, not to add an explicit log
  when the final retry fails (though the extra log entry
  will not hurt significantly).


-- 
Dieter
___
Zope-Dev maillist  -  Zope-Dev@zope.org
http://mail.zope.org/mailman/listinfo/zope-dev
**  No cross posts or HTML encoding!  **
(Related lists - 
 http://mail.zope.org/mailman/listinfo/zope-announce
 http://mail.zope.org/mailman/listinfo/zope )


Re: [Zope-dev] Logging of ConflictError

2005-12-02 Thread Dieter Maurer
Florent Guillaume wrote at 2005-12-2 13:33 +0100:
 ...
Please no. Don't put anything at INFO. A conflict error is either  
something normal that should be at level BLATHER or below, or an  
ERROR that a sysadmin wants to see logged as such.

I strongly disagree with you:

  ConflictErrors are essential hints that your system might
  come into trouble (they can turn into real error).

  These hints are at least as important as e.g.

2005-12-02T07:17:59 INFO ZODB.Mount Opening database for mounting: 
'144160968_1010482273.050062'
--
2005-12-02T07:17:59 INFO ZODB.Mount Mounted database 
'144160968_1010482273.050062' at /temp_folder

  Looks like INFO is a better level than BLATHER...

-- 
Dieter
___
Zope-Dev maillist  -  Zope-Dev@zope.org
http://mail.zope.org/mailman/listinfo/zope-dev
**  No cross posts or HTML encoding!  **
(Related lists - 
 http://mail.zope.org/mailman/listinfo/zope-announce
 http://mail.zope.org/mailman/listinfo/zope )


Re: [Zope-dev] Logging of ConflictError

2005-12-02 Thread Florent Guillaume

On 2 Dec 2005, at 20:40, Dieter Maurer wrote:

Florent Guillaume wrote at 2005-12-1 19:49 +0100:

I've improved the logging of ConflictError in Zope 2.9 and trunk.

http://svn.zope.org/?rev=40454view=rev

Now you'll get two things:
- logs at level BLATHER for each conflict, but it may be retried
- log at level ERROR when the conflict can't be retried anymore  
and is

returned to the browser as an error.


Apparently, you stopped following our thread (you, Chris, me):

  In my view, a ConflictError observed by the user
  should be treated exactly like any other exception observed by  
the user:

  it should go through the error_log and standard_error_message.


That's what my patch did.


  It might be logged (when the user decides that exceptions seen
  by the user should be logged).


I can agree with that.


  The approach to achieve this it to fix a bug in Zope's
  zpublisher_exception_hook, not to add an explicit log
  when the final retry fails (though the extra log entry
  will not hurt significantly).


The patch I did included the fix you proposed in the patch in the  
mailing list archives based on the collector entry.


Florent

--
Florent Guillaume, Nuxeo (Paris, France)   Director of RD
+33 1 40 33 71 59   http://nuxeo.com   [EMAIL PROTECTED]



___
Zope-Dev maillist  -  Zope-Dev@zope.org
http://mail.zope.org/mailman/listinfo/zope-dev
**  No cross posts or HTML encoding!  **
(Related lists - 
http://mail.zope.org/mailman/listinfo/zope-announce

http://mail.zope.org/mailman/listinfo/zope )


Re: [Zope-dev] Logging of ConflictError

2005-12-02 Thread Florent Guillaume

On 2 Dec 2005, at 20:50, Dieter Maurer wrote:


Florent Guillaume wrote at 2005-12-2 13:33 +0100:

...
Please no. Don't put anything at INFO. A conflict error is either
something normal that should be at level BLATHER or below, or an
ERROR that a sysadmin wants to see logged as such.


I strongly disagree with you:

  ConflictErrors are essential hints that your system might
  come into trouble (they can turn into real error).

  These hints are at least as important as e.g.

2005-12-02T07:17:59 INFO ZODB.Mount Opening database for mounting:  
'144160968_1010482273.050062'

--
2005-12-02T07:17:59 INFO ZODB.Mount Mounted database  
'144160968_1010482273.050062' at /temp_folder


  Looks like INFO is a better level than BLATHER...



If you look at the way their purpose is explained in zLOG, you'll see  
that level INFO is reserved for things like server startup and  
shutdown. Or, as shown above, initial mounting of databases. Anything  
recurring that can happen many times in the life of the server but  
does not pose any problems should *not* be visible at INFO.


On the other hand, that's exactly what BLATHER is for folks! Use it!  
Note that it's another reason for not using the default python  
loggers who have a stupidly small number of levels.


If you want to audit your server status to see if there are changes  
real errors will happen, INFO is *not* the level to use.


Anyway, there's sufficient disagreement here, I'll send another mail  
to ask for people's votes.


Florent

--
Florent Guillaume, Nuxeo (Paris, France)   Director of RD
+33 1 40 33 71 59   http://nuxeo.com   [EMAIL PROTECTED]



___
Zope-Dev maillist  -  Zope-Dev@zope.org
http://mail.zope.org/mailman/listinfo/zope-dev
**  No cross posts or HTML encoding!  **
(Related lists - 
http://mail.zope.org/mailman/listinfo/zope-announce

http://mail.zope.org/mailman/listinfo/zope )


Re: [Zope-dev] Logging of ConflictError

2005-12-02 Thread Chris Withers

Paul Winkler wrote:


I'm +1 on having failed retries show up at level ERROR.


With Florent's changes you get 'em twice, with mine, you get 'em once ;-)


I'm neutral on having successful retries show up at level INFO, BLATHER,
or in some other log handler entirely.  Conflict errors are a pretty
small part of my world and I don't really have a strong opinion on this
part of the debate, and I don't have time to review either of
your patches.


Well, if you ever run into performance problems, you might care about 
them...


Chris

--
Simplistix - Content Management, Zope  Python Consulting
   - http://www.simplistix.co.uk

___
Zope-Dev maillist  -  Zope-Dev@zope.org
http://mail.zope.org/mailman/listinfo/zope-dev
**  No cross posts or HTML encoding!  **
(Related lists - 
http://mail.zope.org/mailman/listinfo/zope-announce

http://mail.zope.org/mailman/listinfo/zope )


[Zope-dev] Logging of ConflictError

2005-12-01 Thread Florent Guillaume

I've improved the logging of ConflictError in Zope 2.9 and trunk.

http://svn.zope.org/?rev=40454view=rev

Now you'll get two things:
- logs at level BLATHER for each conflict, but it may be retried
- log at level ERROR when the conflict can't be retried anymore and is 
returned to the browser as an error.


I removed the log at level INFO because it is very misleading for system 
administrators in my experience.


Do people want this also for 2.8? Note that it changes the log format, so 
may break third party tools that parse logs.


Florent

--
Florent Guillaume, Nuxeo (Paris, France)   CTO, Director of RD
+33 1 40 33 71 59   http://nuxeo.com   [EMAIL PROTECTED]
___
Zope-Dev maillist  -  Zope-Dev@zope.org
http://mail.zope.org/mailman/listinfo/zope-dev
**  No cross posts or HTML encoding!  **
(Related lists - 
http://mail.zope.org/mailman/listinfo/zope-announce

http://mail.zope.org/mailman/listinfo/zope )


Re: [Zope-dev] Logging of ConflictError

2005-12-01 Thread Chris McDonough

+1

On Dec 1, 2005, at 1:49 PM, Florent Guillaume wrote:


I've improved the logging of ConflictError in Zope 2.9 and trunk.

http://svn.zope.org/?rev=40454view=rev

Now you'll get two things:
- logs at level BLATHER for each conflict, but it may be retried
- log at level ERROR when the conflict can't be retried anymore and  
is returned to the browser as an error.


I removed the log at level INFO because it is very misleading for  
system administrators in my experience.


Do people want this also for 2.8? Note that it changes the log  
format, so may break third party tools that parse logs.


Florent

--
Florent Guillaume, Nuxeo (Paris, France)   CTO, Director of RD
+33 1 40 33 71 59   http://nuxeo.com   [EMAIL PROTECTED]
___
Zope-Dev maillist  -  Zope-Dev@zope.org
http://mail.zope.org/mailman/listinfo/zope-dev
**  No cross posts or HTML encoding!  **
(Related lists - http://mail.zope.org/mailman/listinfo/zope-announce
http://mail.zope.org/mailman/listinfo/zope )



___
Zope-Dev maillist  -  Zope-Dev@zope.org
http://mail.zope.org/mailman/listinfo/zope-dev
**  No cross posts or HTML encoding!  **
(Related lists - 
http://mail.zope.org/mailman/listinfo/zope-announce

http://mail.zope.org/mailman/listinfo/zope )


[Zope-dev] Logging after ConflictError Retries

2005-06-09 Thread Malcolm Cleaton
After a ConflictError causes a request to be retried, a few things go a
bit wrong with error handling and logging in the Zope server.

1. If the request is abandoned after repeated ConflictErrors, no error at
all appears in the error log.

The following change to Zope/App/startup.py appears to fix this, although
I'm not sufficiently experienced in the depths of Zope to be sure there
are no downsides:

162,163c162
 if REQUEST.supports_retry():
 raise ZPublisher.Retry(t, v, traceback)
---
 raise ZPublisher.Retry(t, v, traceback)

If a Retry error is raised again here even though we don't support any
more retries, the ZServer calls the exception hook again with the Retry
error, we throw it again and the error logging is missed. Simply not
raising the Retry error again once we don't support any more retries means
we fall through to the rest of the exception handling hook, and the
ConflictError itself is logged, which I think is right.


2. If there is at least one ConflictError and then the request finishes
with an error (either more ConflictErrors or something else), the Z2 log
shows the request as having been answered with status 200, although
actually a status 500 error response has been served.

I've managed to work out what's causing this, but fixing may be more
fiddly. What happens is, once the request is abandoned because of the
error, when control comes back to publish_module_standard in Publish.py,
response.exception() is called on the original response, not on the latest
retry. Then, when HTTPResponse _finish() is called, it traces down to the
latest retry to find the status code for the logging, which is now the
wrong one.

I can think of a few things which might fix this, but they all feel like
they might also break many other subtle things, and I've got The Fear; can
somebody more experienced in the core comment on the Right Way?

I've submitted this to the Collector:
http://www.zope.org/Collectors/Zope/1805

Thanks,
Malcolm.

-- 

[] j a m k i t
  web solutions for charities

 malcolm cleaton
T:  020 7549 0520
F:  020 7490 1152
M:  07986 563852
W: www.jamkit.com


___
Zope-Dev maillist  -  Zope-Dev@zope.org
http://mail.zope.org/mailman/listinfo/zope-dev
**  No cross posts or HTML encoding!  **
(Related lists - 
 http://mail.zope.org/mailman/listinfo/zope-announce
 http://mail.zope.org/mailman/listinfo/zope )


Re: [Zope-dev] Logging after ConflictError Retries

2005-06-09 Thread Dieter Maurer
Malcolm Cleaton wrote at 2005-6-9 10:13 +0100:
After a ConflictError causes a request to be retried, a few things go a
bit wrong with error handling and logging in the Zope server.

1. If the request is abandoned after repeated ConflictErrors, no error at
all appears in the error log.

Right: please file a bug report.

The fix is (almost surely) to replace in .../Zope/App/startup.py:

   if t is ZPublisher.Retry: v.reraise()

by

   if t is ZPublisher.Retry: t, v, traceback = v._args

 ...
2. If there is at least one ConflictError and then the request finishes
with an error (either more ConflictErrors or something else), the Z2 log
shows the request as having been answered with status 200, although
actually a status 500 error response has been served.

I've managed to work out what's causing this, but fixing may be more
fiddly. What happens is, once the request is abandoned because of the
error, when control comes back to publish_module_standard in Publish.py,
response.exception() is called on the original response, not on the latest
retry. Then, when HTTPResponse _finish() is called, it traces down to the
latest retry to find the status code for the logging, which is now the
wrong one.

This should only happen when publish itself raises an exception.
Usually, publish should *NOT* raise an exception, when
the request fails (although exceeding the maximal number
of retries may cause this).


Nevertheless, the mixed use of response and request.response
in publish_module_standard
looks wrong. Almost surely, request.response should
get the value of response when publish succeeds and
both are different.
Thus I expect, we should have:

 response = publish(...)
 request.response = response
  except ...


Please file two bug reports for the problems you discovered...

-- 
Dieter
___
Zope-Dev maillist  -  Zope-Dev@zope.org
http://mail.zope.org/mailman/listinfo/zope-dev
**  No cross posts or HTML encoding!  **
(Related lists - 
 http://mail.zope.org/mailman/listinfo/zope-announce
 http://mail.zope.org/mailman/listinfo/zope )