[Checkins] SVN: Products.LongRequestLogger/trunk/ import Products.LongRequestLogger from ERP5 repository
Leonardo Rochael Almeida
leorochael at gmail.com
Sun Aug 7 15:15:06 EDT 2011
Log message for revision 122487:
import Products.LongRequestLogger from ERP5 repository
Changed:
_U Products.LongRequestLogger/trunk/
A Products.LongRequestLogger/trunk/COPYRIGHT.txt
A Products.LongRequestLogger/trunk/LICENSE.txt
A Products.LongRequestLogger/trunk/MANIFEST.in
A Products.LongRequestLogger/trunk/Products/
A Products.LongRequestLogger/trunk/Products/LongRequestLogger/
A Products.LongRequestLogger/trunk/Products/LongRequestLogger/__init__.py
A Products.LongRequestLogger/trunk/Products/LongRequestLogger/dumper.py
A Products.LongRequestLogger/trunk/Products/LongRequestLogger/monitor.py
A Products.LongRequestLogger/trunk/Products/LongRequestLogger/patch.py
A Products.LongRequestLogger/trunk/Products/LongRequestLogger/tests/
A Products.LongRequestLogger/trunk/Products/LongRequestLogger/tests/__init__.py
A Products.LongRequestLogger/trunk/Products/LongRequestLogger/tests/common.py
A Products.LongRequestLogger/trunk/Products/LongRequestLogger/tests/testLongRequestLogger.py
A Products.LongRequestLogger/trunk/Products/LongRequestLogger/version.txt
A Products.LongRequestLogger/trunk/Products/__init__.py
A Products.LongRequestLogger/trunk/README.txt
A Products.LongRequestLogger/trunk/bootstrap.py
A Products.LongRequestLogger/trunk/buildout.cfg
A Products.LongRequestLogger/trunk/docs/
A Products.LongRequestLogger/trunk/docs/HISTORY.txt
A Products.LongRequestLogger/trunk/setup.py
-=-
Property changes on: Products.LongRequestLogger/trunk
___________________________________________________________________
Added: svn:ignore
+ *.egg-info
develop-eggs
eggs
src
parts
.*.cfg
bin
dist
Added: Products.LongRequestLogger/trunk/COPYRIGHT.txt
===================================================================
--- Products.LongRequestLogger/trunk/COPYRIGHT.txt (rev 0)
+++ Products.LongRequestLogger/trunk/COPYRIGHT.txt 2011-08-07 19:15:06 UTC (rev 122487)
@@ -0,0 +1 @@
+Zope Foundation and Contributors
\ No newline at end of file
Added: Products.LongRequestLogger/trunk/LICENSE.txt
===================================================================
--- Products.LongRequestLogger/trunk/LICENSE.txt (rev 0)
+++ Products.LongRequestLogger/trunk/LICENSE.txt 2011-08-07 19:15:06 UTC (rev 122487)
@@ -0,0 +1,44 @@
+Zope Public License (ZPL) Version 2.1
+
+A copyright notice accompanies this license document that identifies the
+copyright holders.
+
+This license has been certified as open source. It has also been designated as
+GPL compatible by the Free Software Foundation (FSF).
+
+Redistribution and use in source and binary forms, with or without
+modification, are permitted provided that the following conditions are met:
+
+1. Redistributions in source code must retain the accompanying copyright
+notice, this list of conditions, and the following disclaimer.
+
+2. Redistributions in binary form must reproduce the accompanying copyright
+notice, this list of conditions, and the following disclaimer in the
+documentation and/or other materials provided with the distribution.
+
+3. Names of the copyright holders must not be used to endorse or promote
+products derived from this software without prior written permission from the
+copyright holders.
+
+4. The right to distribute this software or to use it for any purpose does not
+give you the right to use Servicemarks (sm) or Trademarks (tm) of the
+copyright
+holders. Use of them is covered by separate agreement with the copyright
+holders.
+
+5. If any files are modified, you must cause the modified files to carry
+prominent notices stating that you changed the files and the date of any
+change.
+
+Disclaimer
+
+THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS ``AS IS'' AND ANY EXPRESSED
+OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED WARRANTIES
+OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO
+EVENT SHALL THE COPYRIGHT HOLDERS BE LIABLE FOR ANY DIRECT, INDIRECT,
+INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
+LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, DATA, OR
+PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY THEORY OF
+LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT (INCLUDING
+NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE OF THIS SOFTWARE,
+EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
Added: Products.LongRequestLogger/trunk/MANIFEST.in
===================================================================
--- Products.LongRequestLogger/trunk/MANIFEST.in (rev 0)
+++ Products.LongRequestLogger/trunk/MANIFEST.in 2011-08-07 19:15:06 UTC (rev 122487)
@@ -0,0 +1,4 @@
+recursive-include Products *
+recursive-include docs *
+global-exclude *pyc *~
+
Added: Products.LongRequestLogger/trunk/Products/LongRequestLogger/__init__.py
===================================================================
--- Products.LongRequestLogger/trunk/Products/LongRequestLogger/__init__.py (rev 0)
+++ Products.LongRequestLogger/trunk/Products/LongRequestLogger/__init__.py 2011-08-07 19:15:06 UTC (rev 122487)
@@ -0,0 +1,15 @@
+##############################################################################
+#
+# Copyright (c) 2010 Zope Foundation and Contributors.
+#
+##############################################################################
+
+
+def initialize(context):
+ from Products.LongRequestLogger.dumper import do_enable
+ from Products.LongRequestLogger.patch import do_patch
+ if do_enable():
+ # if not enabled on startup, it won't be enabled, period.
+ # it can be disabled at runtime afterwards, but will not be unpatched.
+ do_patch()
+
Added: Products.LongRequestLogger/trunk/Products/LongRequestLogger/dumper.py
===================================================================
--- Products.LongRequestLogger/trunk/Products/LongRequestLogger/dumper.py (rev 0)
+++ Products.LongRequestLogger/trunk/Products/LongRequestLogger/dumper.py 2011-08-07 19:15:06 UTC (rev 122487)
@@ -0,0 +1,153 @@
+##############################################################################
+#
+# Copyright (c) 2010 Zope Foundation and Contributors.
+#
+##############################################################################
+
+import os
+import os.path
+import traceback
+import logging
+from cStringIO import StringIO
+from thread import get_ident
+import time
+from pprint import pformat
+
+try:
+ from sys import _current_frames
+except ImportError:
+ # Python 2.4 and older
+ from threadframe import dict as _current_frames
+
+class NullHandler(logging.Handler):
+ def __init__(self):
+ logging.Handler.__init__(self)
+ # for comparison purposes below
+ self.baseFilename = 'null'
+
+ def emit(self, *args, **kw):
+ pass
+
+# we might want to change this name later to something more specific
+logger_name = __name__
+log = logging.getLogger(logger_name)
+log.propagate = False
+handler = NullHandler()
+log.addHandler(handler)
+
+formatter = logging.Formatter("%(asctime)s - %(message)s")
+
+DEFAULT_TIMEOUT = 2
+DEFAULT_INTERVAL = 1
+
+def do_enable():
+ global handler
+ # this function is not exactly thread-safe, but it shouldn't matter.
+ # The worse that can happen is that a change in longrequestlogger_file
+ # will stop or change the logging destination of an already running request
+ logfile = os.environ.get('longrequestlogger_file')
+ if logfile:
+ if logfile != 'null':
+ # to imitate FileHandler
+ logfile = os.path.abspath(logfile)
+ if handler.baseFilename != logfile:
+ log.removeHandler(handler)
+ handler.close()
+ if logfile == 'null':
+ handler = NullHandler()
+ else:
+ handler = logging.FileHandler(logfile)
+ handler.formatter = formatter
+ log.addHandler(handler)
+ return log # which is also True as boolean
+ return None # so that Dumpers know they are disabled
+
+def get_configuration():
+ return dict(
+ timeout=float(os.environ.get('longrequestlogger_timeout',
+ DEFAULT_TIMEOUT)),
+ interval=float(os.environ.get('longrequestlogger_interval',
+ DEFAULT_INTERVAL)),
+ )
+
+THREAD_FORMAT = "Thread %s: Started on %.1f; Running for %.1f secs; %s"
+REQUEST_FORMAT = """
+request: %(method)s %(url)s
+retry count: %(retries)s
+form: %(form)s
+other: %(other)s
+""".strip()
+
+class Dumper(object):
+
+ def __init__(self, thread_id=None):
+ if thread_id is None:
+ # assume we're being called by the thread that wants to be
+ # monitored
+ thread_id = get_ident()
+ self.thread_id = thread_id
+ self.start = time.time()
+ # capture it here in case it gets disabled in the future
+ self.log = do_enable()
+ conf = get_configuration()
+ self.timeout = conf['timeout']
+ self.interval = conf['interval']
+
+ def is_enabled(self):
+ return bool(self.log)
+
+ def format_request(self, request):
+ if request is None:
+ return "[No request]"
+ url = request.getURL()
+ if request.get('QUERY_STRING'):
+ url += '?' + request['QUERY_STRING']
+ retries = request.retry_count
+ method = request['REQUEST_METHOD']
+ form = pformat(request.form)
+ other = pformat(request.other)
+ return REQUEST_FORMAT % locals()
+
+ def extract_request(self, frame):
+ # We try to fetch the request from the 'call_object' function because
+ # it's the one that gets called with retried requests.
+ # And we import it locally to get even monkey-patched versions of the
+ # function.
+ from ZPublisher.Publish import call_object
+ func_code = call_object.func_code #@UndefinedVariable
+ while frame is not None:
+ code = frame.f_code
+ if (code is func_code):
+ request = frame.f_locals.get('request')
+ return request
+ frame = frame.f_back
+
+ def extract_request_info(self, frame):
+ request = self.extract_request(frame)
+ return self.format_request(request)
+
+ def get_top_thread_frame(self):
+ return _current_frames()[self.thread_id]
+
+ def get_thread_info(self, frame):
+ request_info = self.extract_request_info(frame)
+ now = time.time()
+ runtime = now - self.start
+ info = THREAD_FORMAT % (self.thread_id,
+ self.start,
+ runtime,
+ request_info)
+ return info
+
+ def format_thread(self):
+ frame = self.get_top_thread_frame()
+ output = StringIO()
+ thread_info = self.get_thread_info(frame)
+ print >> output, thread_info
+ print >> output, "Traceback:"
+ traceback.print_stack(frame, file=output)
+ del frame
+ return output.getvalue()
+
+ def __call__(self):
+ self.log.warning(self.format_thread())
Added: Products.LongRequestLogger/trunk/Products/LongRequestLogger/monitor.py
===================================================================
--- Products.LongRequestLogger/trunk/Products/LongRequestLogger/monitor.py (rev 0)
+++ Products.LongRequestLogger/trunk/Products/LongRequestLogger/monitor.py 2011-08-07 19:15:06 UTC (rev 122487)
@@ -0,0 +1,62 @@
+##############################################################################
+#
+# Copyright (c) 2010 Zope Foundation and Contributors.
+#
+##############################################################################
+
+from threading import Thread
+from threading import Condition
+from Products.LongRequestLogger import dumper
+
+class Monitor(Thread):
+ """Logs the stack-trace of a thread until it's stopped
+
+ m = Monitor(thread.get_ident(), timeout=5, interval=2)
+
+ Wait 5 seconds before dumping the stack-trace of the identified thread
+ every 2 seconds.
+
+ m.stop()
+
+ Stop the monitoring, whether timed-out or not
+ """
+
+ running = False
+
+ def __init__(self,
+ thread_id=None,
+ timeout=None,
+ interval=None):
+ Thread.__init__(self)
+ self.dumper = dumper.Dumper(thread_id=thread_id)
+ self.timeout = timeout or self.dumper.timeout
+ self.interval = interval or self.dumper.interval
+ self.running_condition = Condition()
+ if self.dumper.is_enabled():
+ self.running = True
+ self.start()
+
+ def stop(self):
+ """Stop monitoring the other thread"""
+ # this function is called by the other thread, when it wants to stop
+ # being monitored
+ self.running_condition.acquire()
+ try:
+ if not self.running:
+ return # yes, the finally clause will be run, don't worry
+ self.running = False
+ self.running_condition.notify()
+ finally:
+ self.running_condition.release()
+ self.join()
+
+ def run(self):
+ self.running_condition.acquire()
+ self.running_condition.wait(self.timeout)
+ # If the other thread is still running by now, it's time to monitor it
+ try:
+ while self.running:
+ self.dumper()
+ self.running_condition.wait(self.interval)
+ finally:
+ self.running_condition.release()
Added: Products.LongRequestLogger/trunk/Products/LongRequestLogger/patch.py
===================================================================
--- Products.LongRequestLogger/trunk/Products/LongRequestLogger/patch.py (rev 0)
+++ Products.LongRequestLogger/trunk/Products/LongRequestLogger/patch.py 2011-08-07 19:15:06 UTC (rev 122487)
@@ -0,0 +1,33 @@
+##############################################################################
+#
+# Copyright (c) 2010 Zope Foundation and Contributors.
+#
+##############################################################################
+
+import sys
+from logging import getLogger
+from Products.LongRequestLogger.monitor import Monitor
+
+log = getLogger(__name__)
+
+def wrapper(*args, **kw):
+ m = Monitor()
+ try:
+ result = wrapper.original(*args, **kw)
+ return result
+ finally:
+ m.stop()
+
+def do_patch():
+ from ZPublisher.Publish import publish_module_standard as original
+ wrapper.original = original
+ log.info('patching %s.%s' % (wrapper.original.__module__,
+ wrapper.original.__name__))
+ setattr(sys.modules[wrapper.original.__module__],
+ wrapper.original.__name__,
+ wrapper)
+
+def do_unpatch():
+ setattr(sys.modules[wrapper.original.__module__],
+ wrapper.original.__name__,
+ wrapper.original)
Added: Products.LongRequestLogger/trunk/Products/LongRequestLogger/tests/__init__.py
===================================================================
--- Products.LongRequestLogger/trunk/Products/LongRequestLogger/tests/__init__.py (rev 0)
+++ Products.LongRequestLogger/trunk/Products/LongRequestLogger/tests/__init__.py 2011-08-07 19:15:06 UTC (rev 122487)
@@ -0,0 +1,6 @@
+##############################################################################
+#
+# Copyright (c) 2010 Zope Foundation and Contributors.
+#
+##############################################################################
+
Added: Products.LongRequestLogger/trunk/Products/LongRequestLogger/tests/common.py
===================================================================
--- Products.LongRequestLogger/trunk/Products/LongRequestLogger/tests/common.py (rev 0)
+++ Products.LongRequestLogger/trunk/Products/LongRequestLogger/tests/common.py 2011-08-07 19:15:06 UTC (rev 122487)
@@ -0,0 +1,34 @@
+##############################################################################
+#
+# Copyright (c) 2010 Zope Foundation and Contributors.
+#
+##############################################################################
+
+import time
+
+class Sleeper(object):
+ """This class exists solely to inflate the stack trace, and to be in a
+ file where the stack trace won't be affected by editing of the test file
+ that uses it.
+ """
+
+ def __init__(self, interval):
+ self.interval = interval
+
+ def sleep(self):
+ self._sleep1()
+
+ def _sleep1(self):
+ self._sleep2()
+
+ def _sleep2(self):
+ time.sleep(self.interval)
+
+class App(object):
+
+ def __call__(self, interval):
+ Sleeper(interval).sleep()
+ return "OK"
+
+# Enable this module to be published with ZPublisher.Publish.publish_module()
+bobo_application = App()
Added: Products.LongRequestLogger/trunk/Products/LongRequestLogger/tests/testLongRequestLogger.py
===================================================================
--- Products.LongRequestLogger/trunk/Products/LongRequestLogger/tests/testLongRequestLogger.py (rev 0)
+++ Products.LongRequestLogger/trunk/Products/LongRequestLogger/tests/testLongRequestLogger.py 2011-08-07 19:15:06 UTC (rev 122487)
@@ -0,0 +1,369 @@
+##############################################################################
+#
+# Copyright (c) 2010 Zope Foundation and Contributors.
+#
+##############################################################################
+
+import unittest
+from cStringIO import StringIO
+from doctest import OutputChecker
+from doctest import REPORT_UDIFF, NORMALIZE_WHITESPACE, ELLIPSIS
+
+from Products.LongRequestLogger.tests.common import Sleeper
+import os
+
+class SimpleOutputChecker(OutputChecker):
+ # for certain inputs the doctest output checker is much more convenient
+ # than manually munging assertions, but we don't want to go through all
+ # the trouble of actually writing doctests.
+
+ optionflags = REPORT_UDIFF | NORMALIZE_WHITESPACE | ELLIPSIS
+
+ def __init__(self, want, optionflags=None):
+ self.want = want
+ if optionflags is not None:
+ self.optionflags = optionflags
+
+ def __call__(self, got):
+ assert self.check_output(self.want, got, self.optionflags), \
+ self.output_difference(self, # pretend we're a doctest.Example
+ got, self.optionflags)
+
+check_dump = SimpleOutputChecker('''
+Thread ...: Started on ...; Running for 0.0 secs; [No request]
+<BLANKLINE>
+Traceback:
+...
+ File ".../LongRequestLogger/dumper.py", line ..., in format_thread
+ traceback.print_stack(frame, file=output)
+ File ".../LongRequestLogger/dumper.py", line ..., in get_top_thread_frame
+ return _current_frames()[self.thread_id]
+''')
+
+check_log = SimpleOutputChecker('''
+Products.LongRequestLogger.dumper WARNING
+ Thread ...: Started on ...; Running for 0.0 secs; [No request]
+Traceback:
+...
+ File ".../LongRequestLogger/dumper.py", line ..., in __call__
+ self.log.warning(self.format_thread())
+ File ".../LongRequestLogger/dumper.py", line ..., in format_thread
+ traceback.print_stack(frame, file=output)
+ File ".../LongRequestLogger/dumper.py", line ..., in get_top_thread_frame
+ return _current_frames()[self.thread_id]
+''')
+
+check_monitor_log = SimpleOutputChecker('''
+Products.LongRequestLogger.dumper WARNING
+ Thread ...: Started on ...; Running for 2.0 secs; [No request]
+Traceback:
+...
+ File ".../LongRequestLogger/tests/common.py", line ..., in sleep
+ self._sleep1()
+ File ".../LongRequestLogger/tests/common.py", line ..., in _sleep1
+ self._sleep2()
+ File ".../LongRequestLogger/tests/common.py", line ..., in _sleep2
+ time.sleep(self.interval)
+''')
+
+check_monitor_2_intervals_log = SimpleOutputChecker('''
+Products.LongRequestLogger.dumper WARNING
+ Thread ...: Started on ...; Running for 2.0 secs; [No request]
+Traceback:
+...
+ File ".../LongRequestLogger/tests/common.py", line ..., in sleep
+ self._sleep1()
+ File ".../LongRequestLogger/tests/common.py", line ..., in _sleep1
+ self._sleep2()
+ File ".../LongRequestLogger/tests/common.py", line ..., in _sleep2
+ time.sleep(self.interval)
+Products.LongRequestLogger.dumper WARNING
+ Thread ...: Started on ...; Running for 3.0 secs; [No request]
+Traceback:
+...
+ File ".../LongRequestLogger/tests/common.py", line ..., in sleep
+ self._sleep1()
+ File ".../LongRequestLogger/tests/common.py", line ..., in _sleep1
+ self._sleep2()
+ File ".../LongRequestLogger/tests/common.py", line ..., in _sleep2
+ time.sleep(self.interval)
+Products.LongRequestLogger.dumper WARNING
+ Thread ...: Started on ...; Running for 4.0 secs; [No request]
+Traceback:
+...
+ File ".../LongRequestLogger/tests/common.py", line ..., in sleep
+ self._sleep1()
+ File ".../LongRequestLogger/tests/common.py", line ..., in _sleep1
+ self._sleep2()
+ File ".../LongRequestLogger/tests/common.py", line ..., in _sleep2
+ time.sleep(self.interval)
+''')
+
+check_publishing_1_interval_log = SimpleOutputChecker('''
+Products.LongRequestLogger.dumper WARNING
+ Thread ...: Started on ...; Running for 2.0 secs; request: GET http://localhost
+retry count: 0
+form: {}
+other: {'ACTUAL_URL': 'http://localhost',
+ 'PARENTS': [],
+ 'PUBLISHED': <Products.LongRequestLogger.tests.common.App object at 0x...>,
+ 'RESPONSE': HTTPResponse(''),
+ 'SERVER_URL': 'http://localhost',
+ 'TraversalRequestNameStack': [],
+ 'URL': 'http://localhost',
+ 'interval': 3.5,
+ 'method': 'GET'}
+Traceback:
+...
+ File ".../LongRequestLogger/patch.py", line ..., in wrapper
+ result = wrapper.original(*args, **kw)
+ File ".../ZPublisher/Publish.py", line ..., in publish_module_standard
+ response = publish(request, module_name, after_list, debug=debug)
+...
+ File ".../LongRequestLogger/tests/common.py", line ..., in __call__
+ Sleeper(interval).sleep()
+ File ".../LongRequestLogger/tests/common.py", line ..., in sleep
+ self._sleep1()
+ File ".../LongRequestLogger/tests/common.py", line ..., in _sleep1
+ self._sleep2()
+ File ".../LongRequestLogger/tests/common.py", line ..., in _sleep2
+ time.sleep(self.interval)
+Products.LongRequestLogger.dumper WARNING
+ Thread ...: Started on ...; Running for 3.0 secs; request: GET http://localhost
+retry count: 0
+form: {}
+other: {'ACTUAL_URL': 'http://localhost',
+ 'PARENTS': [],
+ 'PUBLISHED': <Products.LongRequestLogger.tests.common.App object at 0x...>,
+ 'RESPONSE': HTTPResponse(''),
+ 'SERVER_URL': 'http://localhost',
+ 'TraversalRequestNameStack': [],
+ 'URL': 'http://localhost',
+ 'interval': 3.5,
+ 'method': 'GET'}
+Traceback:
+...
+ File ".../LongRequestLogger/patch.py", line ..., in wrapper
+ result = wrapper.original(*args, **kw)
+ File ".../ZPublisher/Publish.py", line ..., in publish_module_standard
+ response = publish(request, module_name, after_list, debug=debug)
+...
+ File ".../LongRequestLogger/tests/common.py", line ..., in __call__
+ Sleeper(interval).sleep()
+ File ".../LongRequestLogger/tests/common.py", line ..., in sleep
+ self._sleep1()
+ File ".../LongRequestLogger/tests/common.py", line ..., in _sleep1
+ self._sleep2()
+ File ".../LongRequestLogger/tests/common.py", line ..., in _sleep2
+ time.sleep(self.interval)
+''')
+
+check_request_formating = SimpleOutputChecker('''
+request: GET http://localhost/foo/bar
+retry count: 0
+form: {}
+other: {'RESPONSE': HTTPResponse(''),
+ 'SERVER_URL': 'http://localhost',
+ 'URL': 'http://localhost/foo/bar',
+ 'method': 'GET'}
+''')
+
+check_monitor_environment_log = SimpleOutputChecker('''
+Products.LongRequestLogger.dumper WARNING
+ Thread ...: Started on ...; Running for 3.5 secs; [No request]
+Traceback:
+...
+ File ".../LongRequestLogger/tests/common.py", line ..., in sleep
+ self._sleep1()
+ File ".../LongRequestLogger/tests/common.py", line ..., in _sleep1
+ self._sleep2()
+ File ".../LongRequestLogger/tests/common.py", line ..., in _sleep2
+ time.sleep(self.interval)
+Products.LongRequestLogger.dumper WARNING
+ Thread ...: Started on ...; Running for 5.5 secs; [No request]
+Traceback:
+...
+ File ".../LongRequestLogger/tests/common.py", line ..., in sleep
+ self._sleep1()
+ File ".../LongRequestLogger/tests/common.py", line ..., in _sleep1
+ self._sleep2()
+ File ".../LongRequestLogger/tests/common.py", line ..., in _sleep2
+ time.sleep(self.interval)
+''')
+
+
+config_env_variables = dict(
+ longrequestlogger_file='null',
+ longrequestlogger_timeout=None,
+ longrequestlogger_interval=None,
+)
+
+class TestLongRequestLogger(unittest.TestCase):
+
+ def setUp(self):
+ from Products.LongRequestLogger.patch import do_patch
+ from Products.LongRequestLogger.dumper import logger_name
+ from zope.testing.loggingsupport import InstalledHandler
+ self.setTestEnvironment()
+ do_patch()
+ self.loghandler = InstalledHandler(logger_name)
+ self.requests = []
+
+ def tearDown(self):
+ from Products.LongRequestLogger.patch import do_unpatch
+ do_unpatch()
+ self.restoreTestEnvironment()
+ self.loghandler.uninstall()
+ for request in self.requests:
+ request.response.stdout.close()
+ request.clear()
+
+ def setTestEnvironment(self):
+ self.old_env = {}
+ for var, value in config_env_variables.items():
+ self.old_env[var] = os.environ.pop(var, None)
+ if value:
+ os.environ[var] = value
+
+ def restoreTestEnvironment(self):
+ for var, value in self.old_env.items():
+ os.environ.pop(var, None)
+ if value is not None:
+ os.environ[var] = value
+
+ def makeRequest(self, path='/', **kw):
+ # create fake request and response for convenience
+ from ZPublisher.HTTPRequest import HTTPRequest
+ from ZPublisher.HTTPResponse import HTTPResponse
+ stdin = StringIO()
+ stdout = StringIO()
+ # minimal environment needed
+ env = dict(SERVER_NAME='localhost',
+ SERVER_PORT='80',
+ REQUEST_METHOD='GET',
+ SCRIPT_NAME=path)
+ response = HTTPResponse(stdout=stdout)
+ request = HTTPRequest(stdin, env, response)
+ self.requests.append(request)
+ return request
+
+ def testDumperFormat(self):
+ from Products.LongRequestLogger.dumper import Dumper
+ dumper = Dumper()
+ check_dump(dumper.format_thread())
+
+ def testDumperRequestExtraction(self):
+ # The dumper extract requests by looking for the frame that contains
+ # call_object and then looking for the 'request' variable inside it
+ from ZPublisher.Publish import call_object
+ from Products.LongRequestLogger.dumper import Dumper
+ def callable():
+ dumper = Dumper()
+ return dumper.extract_request(dumper.get_top_thread_frame())
+
+ request = self.makeRequest('/foo')
+ retrieved_request = call_object(callable, (), request)
+ self.assertTrue(request is retrieved_request)
+
+ def testRequestFormating(self):
+ from Products.LongRequestLogger.dumper import Dumper
+ dumper = Dumper()
+ request = self.makeRequest('/foo/bar')
+ check_request_formating(dumper.format_request(request))
+
+ def testDumperLog(self):
+ from Products.LongRequestLogger.dumper import Dumper
+ dumper = Dumper()
+ # check the dumper will log what we expect when called
+ dumper()
+ check_log(str(self.loghandler))
+
+ def testMonitorStopBeforeTimeout(self):
+ from Products.LongRequestLogger.monitor import Monitor
+ m = Monitor()
+ # sleep just a little to let the other thread start
+ s = Sleeper(0.01)
+ s.sleep()
+ self.assertTrue(m.isAlive())
+ self.assertTrue(m.running)
+ m.stop()
+ self.assertFalse(m.running)
+ self.assertFalse(m.isAlive())
+ # unless this test is so slow that there were 2 seconds interval
+ # between starting the monitor and stopping it, there should be no
+ # logged messages
+ self.assertFalse(self.loghandler.records)
+
+ def testMonitorStopAfterTimeout(self):
+ from Products.LongRequestLogger.monitor import Monitor
+ m = Monitor()
+ s = Sleeper(m.timeout + 0.5)
+ # sleep a little more than the timeout to be on the safe side
+ s.sleep()
+ m.stop()
+ check_monitor_log(str(self.loghandler))
+
+ def testMonitorStopAfterTimeoutAndTwoIntervals(self):
+ from Products.LongRequestLogger.monitor import Monitor
+ m = Monitor()
+ s = Sleeper(m.timeout + 2 * m.interval + 0.5)
+ # sleep a little more than timeout + intervals to be on the safe
+ # side
+ s.sleep()
+ m.stop()
+ check_monitor_2_intervals_log(str(self.loghandler))
+
+ def testMonitorConfigurationDisabled(self):
+ from Products.LongRequestLogger.monitor import Monitor
+ os.environ['longrequestlogger_file'] = ''
+ m = Monitor()
+ s = Sleeper(m.timeout + 2 * m.interval + 0.5)
+ # sleep a little more than timeout + intervals
+ s.sleep()
+ # the thread shouldn't run disabled
+ self.assertFalse(m.isAlive())
+ self.assertFalse(m.running)
+ # stopping shouldn't break nonetheless
+ m.stop()
+ self.assertFalse(m.running)
+ self.assertFalse(m.isAlive())
+ # and there should be no records
+ self.assertFalse(self.loghandler.records)
+
+ def testMonitorWithEnvorinmentConfiguration(self):
+ from Products.LongRequestLogger.monitor import Monitor
+ os.environ['longrequestlogger_timeout'] = '3.5'
+ os.environ['longrequestlogger_interval'] = '2'
+ m = Monitor()
+ s = Sleeper(m.timeout + m.interval + 0.5)
+ # sleep a little more than the timeout to be on the safe side
+ s.sleep()
+ m.stop()
+ check_monitor_environment_log(str(self.loghandler))
+
+ def testIsPatched(self):
+ import ZPublisher.Publish
+ import Products.LongRequestLogger
+ self.assertEquals(
+ ZPublisher.Publish.publish_module_standard,
+ Products.LongRequestLogger.patch.wrapper
+ )
+
+ def testPublish(self):
+ from ZPublisher.Publish import publish_module_standard
+ # Before publishing, there should be no slow query records.
+ self.assertFalse(self.loghandler.records)
+ # Request taking (timeout + interval + margin) 3.5 seconds...
+ request = self.makeRequest('/', interval=3.5)
+ request['interval'] = 3.5
+ publish_module_standard('Products.LongRequestLogger.tests.common',
+ request=request,
+ response=request.response,
+ debug=True)
+ # ...should generate query log records like these
+ check_publishing_1_interval_log(str(self.loghandler))
+
+def test_suite():
+ return unittest.TestSuite((
+ unittest.makeSuite(TestLongRequestLogger),
+ ))
Added: Products.LongRequestLogger/trunk/Products/LongRequestLogger/version.txt
===================================================================
--- Products.LongRequestLogger/trunk/Products/LongRequestLogger/version.txt (rev 0)
+++ Products.LongRequestLogger/trunk/Products/LongRequestLogger/version.txt 2011-08-07 19:15:06 UTC (rev 122487)
@@ -0,0 +1 @@
+1.0
\ No newline at end of file
Added: Products.LongRequestLogger/trunk/Products/__init__.py
===================================================================
--- Products.LongRequestLogger/trunk/Products/__init__.py (rev 0)
+++ Products.LongRequestLogger/trunk/Products/__init__.py 2011-08-07 19:15:06 UTC (rev 122487)
@@ -0,0 +1,6 @@
+# See http://peak.telecommunity.com/DevCenter/setuptools#namespace-packages
+try:
+ __import__('pkg_resources').declare_namespace(__name__)
+except ImportError:
+ from pkgutil import extend_path
+ __path__ = extend_path(__path__, __name__)
Added: Products.LongRequestLogger/trunk/README.txt
===================================================================
--- Products.LongRequestLogger/trunk/README.txt (rev 0)
+++ Products.LongRequestLogger/trunk/README.txt 2011-08-07 19:15:06 UTC (rev 122487)
@@ -0,0 +1,111 @@
+Introduction
+============
+
+This product dumps stack traces of long running requests of a Zope2 instance to
+a log file. If a request takes more than a configured timeout, it's stack trace
+will be dumped periodically to a log file.
+
+It was authored by Leonardo Rochael Almeida, and made possible with developer
+time generously donated by `Nexedi <http://www.nexedi.com/>`_, and with design
+input from Sébastien Robin and Julien Muchembled.
+
+Installation
+============
+
+Buildout Installation
+---------------------
+
+Add "Products.LongRequestLogger[standalone]" to the list of eggs of the part
+that defines your Zope instance.
+
+Buildout Installation for Old Zope Versions
+-------------------------------------------
+
+Add "Products.LongRequestLogger[python24]" to the list of eggs of the part
+that defines your Zope instance. This will automatically pull in the
+'threadframe' module which is needed for Python versions < 2.5.
+
+Manual Installation for Old Zope Versions
+-----------------------------------------
+
+Add the LongRequestLogger package inside your Products instance directory and
+install the 'threadframe' module into the Python interpreter used to run Zope.
+
+Configuration
+=============
+
+Add (or change) the "environment" section of your zope.conf to something like
+this::
+
+ # Products.LongRequestLogger config
+ <environment>
+ longrequestlogger_file $INSTANCE/log/longrequest.log
+ longrequestlogger_timeout 4
+ longrequestlogger_interval 2
+ </environment>
+
+The following variables are recognised:
+
+ * "longrequestlogger_file": This is a mandatory variable. Its absence means the
+ LongRequestLogger monkey-patch to the publication machinery will not be
+ applied. It should point to a file where you want the long requests to be
+ logged.
+
+ * "longrequestlogger_timeout": The amount of seconds after which long requests
+ start being logged. Accepts floating point values and defaults to 2.
+
+ * "longrequestlogger_interval": The frequency at which long requests will have
+ their stack trace logged once they have exceeded their 'timeout' above.
+ Defaults to 1 and accepts floating point values.
+
+For the curious, the use of environment variables instead of ZConfig directives
+is due to two reasons:
+
+ 1. The environment variable can be changed at runtime to affect the behaviour
+ of the logger.
+
+ 2. Old Zope versions don't have the ability to use "product-config" syntax,
+ and writing a ZConfig component for just 3 keys is overkill.
+
+Runtime Configuration
+---------------------
+
+On the first point above, changing the longrequestlogger_file variable changes
+the logging destination for all subsequent requests after the change (and
+likely any ongoing request as well), but if Zope is started without that
+variable defined, then setting at runtime will not have any effect.
+
+The other two variables can also be dynamically changed as well, and will take
+effect at the following request after the change, for all threads in the same
+process.
+
+Interpreting results
+====================
+
+It's important to keep in mind a few important facts about the behaviour of
+Zope2 applications and threads while looking at the results:
+
+ 1. Each thread only handles one request at a time.
+
+ 2. Slow requests will usually have tracebacks with a common top part and a
+ variable bottom part. The key to the cause of the slowdown in a request
+ will be in the limit of both.
+
+If you're in a pinch and don't want to parse the file to rank the slowest
+URLs for investigation, pick up a time in seconds that's a multiple of your
+interval plus the timeout and grep for it. For the default settings, of
+time-out and interval, you will find log entries for 4 then 6 then 8 seconds,
+so you can do a grep like::
+
+ $ grep -n "Running for 8" longrequest.log
+
+And decide with URLs show up more. Then you can open the log file, go to the
+line number reported and navigate the tracebacks by searching up and down
+the file for the same thread id (the number after "Thread" in the reported
+lines). Then analise the difference between the tracebacks of a single request
+to get a hint on what this particular request is doing and why it is slowing
+down.
+
+By doing this for a number of similar requests you will be able to come up with
+optimisations or a caching strategy.
+
Added: Products.LongRequestLogger/trunk/bootstrap.py
===================================================================
--- Products.LongRequestLogger/trunk/bootstrap.py (rev 0)
+++ Products.LongRequestLogger/trunk/bootstrap.py 2011-08-07 19:15:06 UTC (rev 122487)
@@ -0,0 +1,119 @@
+##############################################################################
+#
+# Copyright (c) 2006 Zope Foundation and Contributors.
+# All Rights Reserved.
+#
+# This software is subject to the provisions of the Zope Public License,
+# Version 2.1 (ZPL). A copy of the ZPL should accompany this distribution.
+# THIS SOFTWARE IS PROVIDED "AS IS" AND ANY AND ALL EXPRESS OR IMPLIED
+# WARRANTIES ARE DISCLAIMED, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED
+# WARRANTIES OF TITLE, MERCHANTABILITY, AGAINST INFRINGEMENT, AND FITNESS
+# FOR A PARTICULAR PURPOSE.
+#
+##############################################################################
+"""Bootstrap a buildout-based project
+
+Simply run this script in a directory containing a buildout.cfg.
+The script accepts buildout command-line options, so you can
+use the -c option to specify an alternate configuration file.
+"""
+
+import os, shutil, sys, tempfile, urllib2
+from optparse import OptionParser
+
+tmpeggs = tempfile.mkdtemp()
+
+is_jython = sys.platform.startswith('java')
+
+# parsing arguments
+parser = OptionParser()
+parser.add_option("-v", "--version", dest="version",
+ help="use a specific zc.buildout version")
+parser.add_option("-d", "--distribute",
+ action="store_true", dest="distribute", default=False,
+ help="Use Disribute rather than Setuptools.")
+
+parser.add_option("-c", None, action="store", dest="config_file",
+ help=("Specify the path to the buildout configuration "
+ "file to be used."))
+
+options, args = parser.parse_args()
+
+# if -c was provided, we push it back into args for buildout' main function
+if options.config_file is not None:
+ args += ['-c', options.config_file]
+
+if options.version is not None:
+ VERSION = '==%s' % options.version
+else:
+ VERSION = ''
+
+USE_DISTRIBUTE = options.distribute
+args = args + ['bootstrap']
+
+to_reload = False
+try:
+ import pkg_resources
+ if not hasattr(pkg_resources, '_distribute'):
+ to_reload = True
+ raise ImportError
+except ImportError:
+ ez = {}
+ if USE_DISTRIBUTE:
+ exec urllib2.urlopen('http://python-distribute.org/distribute_setup.py'
+ ).read() in ez
+ ez['use_setuptools'](to_dir=tmpeggs, download_delay=0, no_fake=True)
+ else:
+ exec urllib2.urlopen('http://peak.telecommunity.com/dist/ez_setup.py'
+ ).read() in ez
+ ez['use_setuptools'](to_dir=tmpeggs, download_delay=0)
+
+ if to_reload:
+ reload(pkg_resources)
+ else:
+ import pkg_resources
+
+if sys.platform == 'win32':
+ def quote(c):
+ if ' ' in c:
+ return '"%s"' % c # work around spawn lamosity on windows
+ else:
+ return c
+else:
+ def quote (c):
+ return c
+
+cmd = 'from setuptools.command.easy_install import main; main()'
+ws = pkg_resources.working_set
+
+if USE_DISTRIBUTE:
+ requirement = 'distribute'
+else:
+ requirement = 'setuptools'
+
+if is_jython:
+ import subprocess
+
+ assert subprocess.Popen([sys.executable] + ['-c', quote(cmd), '-mqNxd',
+ quote(tmpeggs), 'zc.buildout' + VERSION],
+ env=dict(os.environ,
+ PYTHONPATH=
+ ws.find(pkg_resources.Requirement.parse(requirement)).location
+ ),
+ ).wait() == 0
+
+else:
+ assert os.spawnle(
+ os.P_WAIT, sys.executable, quote (sys.executable),
+ '-c', quote (cmd), '-mqNxd', quote (tmpeggs), 'zc.buildout' + VERSION,
+ dict(os.environ,
+ PYTHONPATH=
+ ws.find(pkg_resources.Requirement.parse(requirement)).location
+ ),
+ ) == 0
+
+ws.add_entry(tmpeggs)
+ws.require('zc.buildout' + VERSION)
+import zc.buildout.buildout
+zc.buildout.buildout.main(args)
+shutil.rmtree(tmpeggs)
Added: Products.LongRequestLogger/trunk/buildout.cfg
===================================================================
--- Products.LongRequestLogger/trunk/buildout.cfg (rev 0)
+++ Products.LongRequestLogger/trunk/buildout.cfg 2011-08-07 19:15:06 UTC (rev 122487)
@@ -0,0 +1,25 @@
+[buildout]
+extends = http://download.zope.org/Zope2/index/2.12.19/versions.cfg
+
+develop = .
+
+parts =
+ test
+ releaser
+
+versions = versions
+
+[releaser]
+recipe = zc.recipe.egg
+eggs =
+ setuptools
+ zest.releaser
+initialization =
+ import os
+ os.environ['PYTHONPATH'] = os.pathsep.join(sys.path)
+
+[test]
+recipe = zc.recipe.testrunner
+eggs =
+ Products.LongRequestLogger[standalone]
+
Added: Products.LongRequestLogger/trunk/docs/HISTORY.txt
===================================================================
--- Products.LongRequestLogger/trunk/docs/HISTORY.txt (rev 0)
+++ Products.LongRequestLogger/trunk/docs/HISTORY.txt 2011-08-07 19:15:06 UTC (rev 122487)
@@ -0,0 +1,7 @@
+Changelog
+=========
+
+1.0
+-------------------
+
+- Initial release
Added: Products.LongRequestLogger/trunk/setup.py
===================================================================
--- Products.LongRequestLogger/trunk/setup.py (rev 0)
+++ Products.LongRequestLogger/trunk/setup.py 2011-08-07 19:15:06 UTC (rev 122487)
@@ -0,0 +1,45 @@
+##############################################################################
+#
+# Copyright (c) 2010 Zope Foundation and Contributors.
+#
+##############################################################################
+
+from setuptools import setup
+from setuptools import find_packages
+import os.path
+
+version = open(os.path.join("Products","LongRequestLogger",
+ "version.txt")).read().strip()
+description = "Dumps sequential stack traces of long-running Zope2 requests"
+
+setup(name='Products.LongRequestLogger',
+ version=version,
+ description=description,
+ long_description=open("README.txt").read() + "\n" +
+ open(os.path.join("docs", "HISTORY.txt")).read(),
+ classifiers=[
+ "Programming Language :: Python",
+ "Framework :: Zope2",
+ "Intended Audience :: System Administrators",
+ ],
+ keywords='performance zope2 plone erp5',
+ author='Nexedi SA',
+ author_email='erp5-dev at erp5.org',
+ url='http://www.erp5.com/',
+ license='ZPL',
+ packages=find_packages(exclude=['ez_setup']),
+ namespace_packages=['Products'],
+ include_package_data=True,
+ zip_safe=False,
+ install_requires=[
+ 'setuptools',
+ ],
+ extras_require=dict(
+ # With Python versions < 2.5, we need the threadframe module
+ python24=['threadframe'],
+ # we need to work with Zope 2.8 buildouts that might not provide a
+ # Zope2 egg (fake or otherwise). So we declare the full dependency
+ # here.
+ standalone=['Zope2'],
+ ),
+)
More information about the checkins
mailing list