Merge error reporting changes from trunk:

- remove unused import.
- change SimpleItem.py to use python logging module
- log at error when standard_error_message can't be rendered
- give more useful info about errors rendering standard_error_message to the browser.
- all conflict errors are counted and logged at info
- logging makes it clear where the conflict has been resolved and where it hasn't
- errors seen by the user are rendered with standard_error_message and are sent to the error_log which will likely copy them to the event log, depending on the users setup.
- also checking in a functional test for generating write conflict errors.
  
(I'll be committing to CHANGES.TXT shortly, I just wanted to keep the merges simpler)

lib/python/OFS/SimpleItem.py

@@ -30,10 +30,10 @@ from ComputedAttribute import ComputedAttribute
 from AccessControl import getSecurityManager, Unauthorized
 from AccessControl.ZopeSecurityPolicy import getRoles
 from Acquisition import aq_base, aq_parent, aq_inner, aq_acquire
+from DocumentTemplate.html_quote import html_quote
 from DocumentTemplate.ustr import ustr
 from zExceptions.ExceptionFormatter import format_exception
 from zExceptions import Redirect
-from zLOG import LOG, BLATHER
 
 from CopySupport import CopySource
 from Traversable import Traversable
@@ -41,6 +41,8 @@ import ZDOM
 
 HTML=Globals.HTML
 
+import logging
+logger = logging.getLogger()
 
 class Item(Base, Resource, CopySource, App.Management.Tabs, Traversable,
            ZDOM.Element,
@@ -210,17 +212,21 @@ class Item(Base, Resource, CopySource, App.Management.Tabs, Traversable,
                 else:
                     v = HTML.__call__(s, client, REQUEST, **kwargs)
             except:
-                LOG('OFS', BLATHER,
+                logger.error(
                     'Exception while rendering an error message',
-                    error=sys.exc_info())
+                    exc_info=True
+                    )
                 try:
                     strv = str(error_value)
                 except:
                     strv = ('<unprintable %s object>' % 
                             str(type(error_value).__name__))
                 v = strv + (
-                    " (Also, an error occurred while attempting "
-                    "to render the standard error message.)")
+                    (" (Also, the following error occurred while attempting "
+                     "to render the standard error message, please see the "
+                     "event log for full details: %s)")%(
+                    html_quote(sys.exc_info()[1]),
+                    ))
             raise error_type, v, tb
         finally:
             if hasattr(self, '_v_eek'): del self._v_eek

lib/python/Products/Transience/Transience.py

@@ -36,7 +36,6 @@ from BTrees.IOBTree import IOBTree
 
 from Persistence import Persistent
 from OFS.SimpleItem import SimpleItem
-from ZPublisher.Publish import Retry
 from AccessControl import ClassSecurityInfo, getSecurityManager
 from AccessControl.SecurityManagement import newSecurityManager, \
      setSecurityManager

lib/python/ZPublisher/tests/generate_conflicts.py

+## This script requires:
+## - python2.4
+## - Zope 3's zope.testbrowser package:
+##   http://www.zope.org/Members/benji_york/ZopeTestbrowser-0.9.0.tgz
+##
+## The just run:
+## $python2.4 generate_conflicts.py
+import base64
+import string
+import threading
+import urllib2
+
+from zope.testbrowser.browser import Browser
+
+# create our browser
+class AuthBrowser(Browser):
+
+    def addBasicAuth(self,username,password):        
+        self.addHeader(
+            'Authorization',
+            'Basic '+base64.encodestring(username+':'+password).strip()
+            )
+
+    def open(self,uri,include_server=True):
+        if include_server:
+            uri = server+uri
+        return Browser.open(self,uri)
+
+browser = AuthBrowser()
+
+# constants
+server = 'http://localhost:8080'
+# the following user must be able to view the management screens
+# and create file objects
+username = 'username'
+password = 'password'
+browser.addBasicAuth(username,password)
+threads = 10
+filename = 'conflict.txt'
+filesize = 10000
+hits = 5
+
+# delete the file if it's already there
+browser.open('/manage_main')
+if filename in [c.optionValue
+                for c in browser.getControl(name='ids:list').controls]:
+    browser.open('/manage_delObjects?ids:list='+filename)
+
+# create it
+browser.open('/manage_addFile?id='+filename)
+
+# edit it, hopefully causing conflicts
+data = 'X'*filesize
+class EditThread(threading.Thread):
+
+    def __init__(self,i):
+        self.conflicts = 0
+        self.browser = AuthBrowser()
+        self.browser.handleErrors = False
+        self.browser.addBasicAuth(username,password)
+        threading.Thread.__init__(self,name=str(i))
+        
+    def run(self):
+        for i in range(1,hits+1):            
+            self.browser.open('/conflict.txt/manage_main')
+            self.browser.getControl(name='title').value='Test Title'
+            self.browser.getControl(name='filedata:text').value = data
+            try:
+                self.browser.getControl(name='manage_edit:method').click()
+            except urllib2.HTTPError,e:
+                # print e.read()
+                self.conflicts += 1
+                print "Thread %s - CONFLICT" % self.getName()
+            else:
+                print "Thread %s - EDIT" % self.getName()
+
+thread_objects = []
+for i in range(1,threads+1):
+    t = EditThread(i)
+    thread_objects.append(t)
+    t.start()
+for t in thread_objects:
+    t.join()
+total = 0
+print
+for t in thread_objects:
+    print "Thread %s - %i conflicts seen" % (t.getName(),t.conflicts)
+    total += t.conflicts
+print
+print "%i conflicts seen by browsers" % total
+

lib/python/Zope2/App/startup.py

@@ -18,9 +18,9 @@ from AccessControl.SecurityManagement import newSecurityManager
 from AccessControl.SecurityManagement import noSecurityManager
 from Acquisition import aq_acquire
 from App.config import getConfiguration
+from time import asctime
 from types import StringType, ListType
 from zExceptions import Unauthorized
-from zLOG import LOG, WARNING, INFO, BLATHER, log_time
 from ZODB.POSException import ConflictError
 import transaction
 import AccessControl.User
@@ -28,6 +28,7 @@ import App.FindHomes
 import ExtensionClass
 import Globals
 import imp
+import logging
 import OFS.Application
 import os
 import sys
@@ -103,7 +104,7 @@ def startup():
     noSecurityManager()
 
     global startup_time
-    startup_time = log_time()
+    startup_time = asctime()
 
     Zope2.zpublisher_transactions_manager = TransactionsManager()
     Zope2.zpublisher_exception_hook = zpublisher_exception_hook
@@ -132,8 +133,13 @@ class RequestContainer(ExtensionClass.Base):
     def __init__(self,r): self.REQUEST=r
 
 conflict_errors = 0
+unresolved_conflict_errors = 0
+
+conflict_logger = logging.getLogger('ZODB.Conflict')
 
 def zpublisher_exception_hook(published, REQUEST, t, v, traceback):
+    global unresolved_conflict_errors
+    global conflict_errors
     try:
         if isinstance(t, StringType):
             if t.lower() in ('unauthorized', 'redirect'):
@@ -142,20 +148,31 @@ def zpublisher_exception_hook(published, REQUEST, t, v, traceback):
             if t is SystemExit:
                 raise
             if issubclass(t, ConflictError):
-                # First, we need to close the current connection. We'll
-                # do this by releasing the hold on it. There should be
-                # some sane protocol for this, but for now we'll use
-                # brute force:
-                global conflict_errors
                 conflict_errors = conflict_errors + 1
-                method_name = REQUEST.get('PATH_INFO', '')
-                err = ('ZODB conflict error at %s '
-                       '(%s conflicts since startup at %s)')
-                LOG(err % (method_name, conflict_errors, startup_time),
-                    INFO, '')
-                LOG('Conflict traceback', BLATHER, '', error=sys.exc_info())
+                # This logs _all_ conflict errors
+                conflict_logger.info(
+                    '%s at %s (%i conflicts, of which %i'
+                    ' were unresolved, since startup at %s)',
+                    v,
+                    REQUEST.get('PATH_INFO', '<unknown>'),
+                    conflict_errors,
+                    unresolved_conflict_errors,
+                    startup_time
+                    )
+                # This debug logging really doesn't help a lot...
+                conflict_logger.debug('Conflict traceback',exc_info=True)
                 raise ZPublisher.Retry(t, v, traceback)
-            if t is ZPublisher.Retry: v.reraise()
+            if t is ZPublisher.Retry:
+                try:
+                    v.reraise()
+                except:
+                    # we catch the re-raised exception so that it gets
+                    # stored in the error log and gets rendered with
+                    # standard_error_message
+                    t, v, traceback = sys.exc_info()
+                if issubclass(t, ConflictError):
+                    # ouch, a user saw this conflict error :-(
+                    unresolved_conflict_errors += 1
 
         try:
             log = aq_acquire(published, '__error_log__', containment=1)
@@ -204,6 +221,7 @@ def zpublisher_exception_hook(published, REQUEST, t, v, traceback):
     finally:
         traceback=None
 
+ac_logger = logging.getLogger('event.AccessControl')
 
 class TransactionsManager:
     def begin(self,
@@ -220,7 +238,7 @@ class TransactionsManager:
     def recordMetaData(self, object, request,
                        # Optimize global var lookups:
                        hasattr=hasattr, getattr=getattr,
-                       LOG=LOG, WARNING=WARNING,
+                       logger=ac_logger,
                        ):
         request_get = request.get
         if hasattr(object, 'getPhysicalPath'):