Docserver: greatly improve the error logging by (a) preserving the stack traces in Futures,

(b) actually logging the stack trace, and (c) respecting DeadlineExceededErrors.

BUG=167432

Review URL: https://codereview.chromium.org/14333015

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@196309 0039d316-1c4b-4281-b951-d872f2087c98

13 files changed, 209 insertions, 60 deletions

diff --git a/chrome/common/extensions/docs/server2/app.yaml b/chrome/common/extensions/docs/server2/app.yaml
index 89a5442..9e564f9d 100644
--- a/chrome/common/extensions/docs/server2/app.yaml
+++ b/chrome/common/extensions/docs/server2/app.yaml
@@ -1,5 +1,5 @@
 application: chrome-apps-doc
-version: 2-0-22
+version: 2-0-23
 runtime: python27
 api_version: 1
 threadsafe: false
diff --git a/chrome/common/extensions/docs/server2/appengine_wrappers.py b/chrome/common/extensions/docs/server2/appengine_wrappers.py
index cf0562d..be4d00e 100644
--- a/chrome/common/extensions/docs/server2/appengine_wrappers.py
+++ b/chrome/common/extensions/docs/server2/appengine_wrappers.py
@@ -23,13 +23,15 @@ def IsDevServer():
 # This will attempt to import the actual App Engine modules, and if it fails,
 # they will be replaced with fake modules. This is useful during testing.
 try:
+  import google.appengine.api.files as files
+  import google.appengine.api.logservice as logservice
+  import google.appengine.api.memcache as memcache
+  import google.appengine.api.urlfetch as urlfetch
   import google.appengine.ext.blobstore as blobstore
   from google.appengine.ext.blobstore.blobstore import BlobReferenceProperty
   import google.appengine.ext.db as db
   import google.appengine.ext.webapp as webapp
-  import google.appengine.api.files as files
-  import google.appengine.api.memcache as memcache
-  import google.appengine.api.urlfetch as urlfetch
+  from google.appengine.runtime import DeadlineExceededError
 except ImportError:
   import re
   from StringIO import StringIO
@@ -65,6 +67,9 @@ except ImportError:
     def wait(self):
       pass
 
+  class DeadlineExceededError(Exception):
+    pass
+
   class FakeUrlFetch(object):
     """A fake urlfetch module that uses the current
     |FAKE_URL_FETCHER_CONFIGURATION| to map urls to fake fetchers.
@@ -91,10 +96,6 @@ except ImportError:
       rpc.result = self.fetch(url)
   urlfetch = FakeUrlFetch()
 
-  class NotImplemented(object):
-    def __getattr__(self, attr):
-      raise NotImplementedError()
-
   _BLOBS = {}
   class FakeBlobstore(object):
     class BlobReader(object):
@@ -146,6 +147,14 @@ except ImportError:
 
   files = FakeFiles()
 
+  class Logservice(object):
+    AUTOFLUSH_ENABLED = True
+
+    def flush(self):
+      pass
+
+  logservice = Logservice()
+
   class InMemoryMemcache(object):
     """An in-memory memcache implementation.
     """
diff --git a/chrome/common/extensions/docs/server2/caching_file_system.py b/chrome/common/extensions/docs/server2/caching_file_system.py
index 8ddfeeb..6e9fa8e 100644
--- a/chrome/common/extensions/docs/server2/caching_file_system.py
+++ b/chrome/common/extensions/docs/server2/caching_file_system.py
@@ -60,7 +60,7 @@ class CachingFileSystem(FileSystem):
     else:
       version = dir_stat.child_versions.get(path.split('/')[-1], None)
       if version is None:
-        raise FileNotFoundError('Version was None for %s' % path)
+        raise FileNotFoundError('No stat found for %s in %s' % (path, dir_path))
     mapping = { path: version }
 
     for child_path, child_version in dir_stat.child_versions.iteritems():
diff --git a/chrome/common/extensions/docs/server2/cron.yaml b/chrome/common/extensions/docs/server2/cron.yaml
index c36e8c1..175a7ba 100644
--- a/chrome/common/extensions/docs/server2/cron.yaml
+++ b/chrome/common/extensions/docs/server2/cron.yaml
@@ -2,15 +2,19 @@ cron:
 - description: Load everything for trunk.
   url: /cron/trunk
   schedule: every 5 minutes
+  target: 2-0-23
 
 - description: Load everything for dev.
   url: /cron/dev
   schedule: every 5 minutes
+  target: 2-0-23
 
 - description: Load everything for beta.
   url: /cron/beta
   schedule: every 5 minutes
+  target: 2-0-23
 
 - description: Load everything for stable.
   url: /cron/stable
   schedule: every 5 minutes
+  target: 2-0-23
diff --git a/chrome/common/extensions/docs/server2/future.py b/chrome/common/extensions/docs/server2/future.py
index 98deef6..8048248 100644
--- a/chrome/common/extensions/docs/server2/future.py
+++ b/chrome/common/extensions/docs/server2/future.py
@@ -2,29 +2,34 @@
 # Use of this source code is governed by a BSD-style license that can be
 # found in the LICENSE file.
 
+import sys
+
 _no_value = object()
 
 class Future(object):
-  """Stores a value, error, or delegate to be used later.
-  """
-  def __init__(self, value=_no_value, error=None, delegate=None):
+  '''Stores a value, error, or delegate to be used later.
+  '''
+  def __init__(self, value=_no_value, delegate=None):
     self._value = value
-    self._error = error
     self._delegate = delegate
-    if (self._value is _no_value and
-        self._error is None and
-        self._delegate is None):
-      raise ValueError('Must have either a value, error, or delegate.')
+    self._exc_info = None
+    if (self._value is _no_value and self._delegate is None):
+      raise ValueError('Must have either a value or delegate.')
 
   def Get(self):
-    """Gets the stored value, error, or delegate contents.
-    """
+    '''Gets the stored value, error, or delegate contents.
+    '''
     if self._value is not _no_value:
       return self._value
-    if self._error is not None:
-      raise self._error
+    if self._exc_info is not None:
+      self._Raise()
     try:
       self._value = self._delegate.Get()
-    except Exception as self._error:
-      raise
-    return self._value
+      return self._value
+    except:
+      self._exc_info = sys.exc_info()
+      self._Raise()
+
+  def _Raise(self):
+    exc_info = self._exc_info
+    raise exc_info[0], exc_info[1], exc_info[2]
diff --git a/chrome/common/extensions/docs/server2/future_test.py b/chrome/common/extensions/docs/server2/future_test.py
new file mode 100755
index 0000000..3b31a0c
--- /dev/null
+++ b/chrome/common/extensions/docs/server2/future_test.py
@@ -0,0 +1,74 @@
+#!/usr/bin/env python
+# Copyright 2013 The Chromium Authors. All rights reserved.
+# Use of this source code is governed by a BSD-style license that can be
+# found in the LICENSE file.
+
+import traceback
+import unittest
+
+from future import Future
+
+class FutureTest(unittest.TestCase):
+  def testNoValueOrDelegate(self):
+    self.assertRaises(ValueError, Future)
+
+  def testValue(self):
+    future = Future(value=42)
+    self.assertEqual(42, future.Get())
+    self.assertEqual(42, future.Get())
+
+  def testDelegateValue(self):
+    assertFalse = self.assertFalse
+    class delegate(object):
+      def __init__(self):
+        self._get_called = False
+      def Get(self):
+        assertFalse(self._get_called)
+        self._get_called = True
+        return 42
+
+    future = Future(delegate=delegate())
+    self.assertEqual(42, future.Get())
+    self.assertEqual(42, future.Get())
+
+  def testErrorThrowingDelegate(self):
+    class FunkyException(Exception):
+      pass
+
+    # Set up a chain of functions to test the stack trace.
+    def qux():
+      raise FunkyException()
+    def baz():
+      return qux()
+    def bar():
+      return baz()
+    def foo():
+      return bar()
+    chain = [foo, bar, baz, qux]
+
+    assertFalse = self.assertFalse
+    class delegate(object):
+      def __init__(self):
+        self._get_called = False
+      def Get(self):
+        assertFalse(self._get_called)
+        self._get_called = True
+        return foo()
+
+    fail = self.fail
+    assertTrue = self.assertTrue
+    def assert_raises_full_stack(future, err):
+      try:
+        future.Get()
+        fail('Did not raise %s' % err)
+      except Exception as e:
+        assertTrue(isinstance(e, err))
+        stack = traceback.format_exc()
+        assertTrue(all(stack.find(fn.__name__) != -1 for fn in chain))
+
+    future = Future(delegate=delegate())
+    assert_raises_full_stack(future, FunkyException)
+    assert_raises_full_stack(future, FunkyException)
+
+if __name__ == '__main__':
+  unittest.main()
diff --git a/chrome/common/extensions/docs/server2/handler.py b/chrome/common/extensions/docs/server2/handler.py
index 4d12f86..af26823 100644
--- a/chrome/common/extensions/docs/server2/handler.py
+++ b/chrome/common/extensions/docs/server2/handler.py
@@ -5,8 +5,10 @@
 import logging
 import os
 from StringIO import StringIO
+import traceback
 
-from appengine_wrappers import IsDevServer, memcache, urlfetch, webapp
+from appengine_wrappers import (
+    DeadlineExceededError, IsDevServer, logservice, memcache, urlfetch, webapp)
 from branch_utility import BranchUtility
 from server_instance import ServerInstance
 import svn_constants
@@ -99,7 +101,9 @@ class Handler(webapp.RequestHandler):
       start_time = time.time()
       files = [f for f in server_instance.content_cache.GetFromFileListing(d)
                if not f.endswith('/')]
-      for f in files:
+      logging.info('cron/%s: rendering %s files from %s...' % (
+          channel, len(files), d))
+      for i, f in enumerate(files):
         error = None
         path = '%s%s' % (path_prefix, f)
         try:
@@ -107,27 +111,38 @@ class Handler(webapp.RequestHandler):
           server_instance.Get(path, MockRequest(path), response)
           if response.status != 200:
             error = 'Got %s response' % response.status
+        except DeadlineExceededError:
+          logging.error(
+              'cron/%s: deadline exceeded rendering %s (%s of %s): %s' % (
+                  channel, path, i + 1, len(files), traceback.format_exc()))
+          raise
         except error:
           pass
         if error:
           logging.error('cron/%s: error rendering %s: %s' % (
               channel, path, error))
           success = False
-      logging.info('cron/%s: rendering %s files took %s seconds' % (
-          channel, len(files), time.time() - start_time))
+      logging.info('cron/%s: rendering %s files from %s took %s seconds' % (
+          channel, len(files), d, time.time() - start_time))
       return success
 
-    # Don't use "or" since we want to evaluate everything no matter what.
-    success = any((
+    success = True
+    for path, path_prefix in (
         # Note: rendering the public templates will pull in all of the private
         # templates.
-        run_cron_for_dir(svn_constants.PUBLIC_TEMPLATE_PATH),
-        run_cron_for_dir(svn_constants.STATIC_PATH, path_prefix='static/'),
+        (svn_constants.PUBLIC_TEMPLATE_PATH, ''),
         # Note: rendering the public templates will have pulled in the .js and
         # manifest.json files (for listing examples on the API reference pages),
         # but there are still images, CSS, etc.
-        run_cron_for_dir(svn_constants.EXAMPLES_PATH,
-                         path_prefix='extensions/examples/')))
+        (svn_constants.STATIC_PATH, 'static/'),
+        (svn_constants.EXAMPLES_PATH, 'extensions/examples/')):
+      try:
+        # Note: don't try to short circuit any of this stuff. We want to run
+        # the cron for all the directories regardless of intermediate failures.
+        success = run_cron_for_dir(path, path_prefix=path_prefix) and success
+      except DeadlineExceededError:
+        success = False
+        break
 
     if success:
       self.response.status = 200
@@ -184,7 +199,13 @@ class Handler(webapp.RequestHandler):
       return
 
     if path.startswith('/cron'):
-      self._HandleCron(path)
+      # Crons often time out, and when they do *and* then eventually try to
+      # flush logs they die. Turn off autoflush and manually do so at the end.
+      logservice.AUTOFLUSH_ENABLED = False
+      try:
+        self._HandleCron(path)
+      finally:
+        logservice.flush()
       return
 
     # Redirect paths like "directory" to "directory/". This is so relative
diff --git a/chrome/common/extensions/docs/server2/integration_test.py b/chrome/common/extensions/docs/server2/integration_test.py
index 262e8ee..7f86804 100755
--- a/chrome/common/extensions/docs/server2/integration_test.py
+++ b/chrome/common/extensions/docs/server2/integration_test.py
@@ -8,14 +8,17 @@
 import build_server
 build_server.main()
 
-from handler import Handler
-from local_renderer import LocalRenderer
+import logging
 import optparse
 import os
 import sys
 import time
 import unittest
 
+from handler import Handler
+from local_renderer import LocalRenderer
+from test_util import DisableLogging
+
 # Arguments set up if __main__ specifies them.
 _BASE_PATH = os.path.join(
     os.path.abspath(os.path.dirname(__file__)), os.pardir, os.pardir)
@@ -81,7 +84,6 @@ class IntegrationTest(unittest.TestCase):
     '''
     if _EXPLICIT_TEST_FILES is None:
       return
-    print('Rendering %s explicit files...' % len(_EXPLICIT_TEST_FILES))
     for filename in _EXPLICIT_TEST_FILES:
       print('Rendering %s...' % filename)
       start_time = time.time()
@@ -93,9 +95,10 @@ class IntegrationTest(unittest.TestCase):
       finally:
         print('Took %s seconds' % (time.time() - start_time))
 
+  @DisableLogging('warning')
   def testFileNotFound(self):
     render_content, render_status, _ = self._renderer.Render(
-        '/extensions/notfound.html')
+        '/extensions/notfound.html', always_online=True)
     self.assertEqual(404, render_status)
 
 if __name__ == '__main__':
diff --git a/chrome/common/extensions/docs/server2/server_instance.py b/chrome/common/extensions/docs/server2/server_instance.py
index 6f900bb..7f3e6cd 100644
--- a/chrome/common/extensions/docs/server2/server_instance.py
+++ b/chrome/common/extensions/docs/server2/server_instance.py
@@ -5,6 +5,7 @@
 from fnmatch import fnmatch
 import logging
 import mimetypes
+import traceback
 import os
 
 from api_data_source import APIDataSource
@@ -243,7 +244,7 @@ class ServerInstance(object):
       elif path.endswith('.html'):
         content = templates.Render(path)
     except FileNotFoundError as e:
-      logging.warning(e)
+      logging.warning(traceback.format_exc())
 
     response.headers['x-frame-options'] = 'sameorigin'
     if content is None:
diff --git a/chrome/common/extensions/docs/server2/template_data_source.py b/chrome/common/extensions/docs/server2/template_data_source.py
index 7185d4d..eae5330 100644
--- a/chrome/common/extensions/docs/server2/template_data_source.py
+++ b/chrome/common/extensions/docs/server2/template_data_source.py
@@ -4,10 +4,11 @@
 
 import logging
 import os
+import traceback
 
 from branch_utility import BranchUtility
-from docs_server_utils import FormatKey
 import compiled_file_system as compiled_fs
+from docs_server_utils import FormatKey
 from file_system import FileNotFoundError
 from third_party.handlebar import Handlebar
 import url_constants
@@ -144,5 +145,5 @@ class TemplateDataSource(object):
       return self._cache.GetFromFile(
           '/'.join((base_path, FormatKey(template_name))))
     except FileNotFoundError as e:
-      logging.error(e)
+      logging.warning(traceback.format_exc())
       return None
diff --git a/chrome/common/extensions/docs/server2/template_data_source_test.py b/chrome/common/extensions/docs/server2/template_data_source_test.py
index 813f2fd..9a5d438 100755
--- a/chrome/common/extensions/docs/server2/template_data_source_test.py
+++ b/chrome/common/extensions/docs/server2/template_data_source_test.py
@@ -14,6 +14,7 @@ from local_file_system import LocalFileSystem
 from object_store_creator import ObjectStoreCreator
 from reference_resolver import ReferenceResolver
 from template_data_source import TemplateDataSource
+from test_util import DisableLogging
 from third_party.handlebar import Handlebar
 
 class _FakeRequest(object):
@@ -59,17 +60,20 @@ class TemplateDataSourceTest(unittest.TestCase):
         api_data_factory,
         self._fake_api_list_data_source_factory,
         ObjectStoreCreator.TestFactory())
-    return (TemplateDataSource.Factory('fake_channel',
-                                       api_data_factory,
-                                       self._fake_api_list_data_source_factory,
-                                       self._fake_intro_data_source_factory,
-                                       self._fake_samples_data_source_factory,
-                                       self._fake_sidenav_data_source_factory,
-                                       compiled_fs_factory,
-                                       reference_resolver_factory,
-                                       '.',
-                                       '.')
-            .Create(_FakeRequest(), 'extensions/foo'))
+    @DisableLogging('error')  # "was never set" error
+    def create_from_factory(factory):
+      return factory.Create(_FakeRequest(), 'extensions/foo')
+    return create_from_factory(TemplateDataSource.Factory(
+        'fake_channel',
+        api_data_factory,
+        self._fake_api_list_data_source_factory,
+        self._fake_intro_data_source_factory,
+        self._fake_samples_data_source_factory,
+        self._fake_sidenav_data_source_factory,
+        compiled_fs_factory,
+        reference_resolver_factory,
+        '.',
+        '.'))
 
   def testSimple(self):
     self._base_path = os.path.join(self._base_path, 'simple')
@@ -88,6 +92,16 @@ class TemplateDataSourceTest(unittest.TestCase):
     self.assertEqual(template_a2.render({}, {'templates': {}}).text,
         t_data_source.get('test2').render({}, {'templates': {}}).text)
 
+  @DisableLogging('warning')
+  def testNotFound(self):
+    self._base_path = os.path.join(self._base_path, 'simple')
+    fetcher = LocalFileSystem(self._base_path)
+    compiled_fs_factory = CompiledFileSystem.Factory(
+        fetcher,
+        ObjectStoreCreator.TestFactory())
+    t_data_source = self._CreateTemplateDataSource(
+        compiled_fs_factory,
+        ObjectStoreCreator.TestFactory())
     self.assertEqual(None, t_data_source.get('junk.html'))
 
   def testPartials(self):
diff --git a/chrome/common/extensions/docs/server2/test_file_system.py b/chrome/common/extensions/docs/server2/test_file_system.py
index 8efdcc2..6ad8b14 100644
--- a/chrome/common/extensions/docs/server2/test_file_system.py
+++ b/chrome/common/extensions/docs/server2/test_file_system.py
@@ -43,13 +43,11 @@ class TestFileSystem(FileSystem):
     return self._ReadImpl(paths, binary=binary)
 
   def _ReadImpl(self, paths, binary=False):
-    try:
-      result = {}
-      for path in paths:
-        result[path] = self._ResolvePath(path)
-      return Future(value=result)
-    except FileNotFoundError as error:
-      return Future(error=error)
+    test_fs = self
+    class Delegate(object):
+      def Get(self):
+        return dict((path, test_fs._ResolvePath(path)) for path in paths)
+    return Future(delegate=Delegate())
 
   def _ResolvePath(self, path):
     def Resolve(parts):
diff --git a/chrome/common/extensions/docs/server2/test_util.py b/chrome/common/extensions/docs/server2/test_util.py
new file mode 100644
index 0000000..1f3aed1
--- /dev/null
+++ b/chrome/common/extensions/docs/server2/test_util.py
@@ -0,0 +1,19 @@
+# Copyright 2013 The Chromium Authors. All rights reserved.
+# Use of this source code is governed by a BSD-style license that can be
+# found in the LICENSE file.
+
+import logging
+
+def DisableLogging(name):
+  '''Disables the log with |name| for the duration of the decorated function.
+  '''
+  def decorator(fn):
+    def impl(*args, **optargs):
+      saved = getattr(logging, name)
+      setattr(logging, name, lambda _: None)
+      try:
+        return fn(*args, **optargs)
+      finally:
+        setattr(logging, name, saved)
+    return impl
+  return decorator