changeset 39:2f717f961996

Better error reporting and cache validation. Fix the processor pipeline in the preview server. Move the `pages` route to first position.
author Ludovic Chabant <ludovic@chabant.com>
date Thu, 21 Aug 2014 22:28:22 -0700
parents 091f99bfbe44
children 4bc166d3a830
files piecrust/app.py piecrust/baking/baker.py piecrust/chefutil.py piecrust/commands/builtin/baking.py piecrust/main.py piecrust/processing/base.py piecrust/serving.py
diffstat 7 files changed, 99 insertions(+), 23 deletions(-) [+]
line wrap: on
line diff
--- a/piecrust/app.py	Thu Aug 21 10:56:17 2014 -0700
+++ b/piecrust/app.py	Thu Aug 21 22:28:22 2014 -0700
@@ -24,7 +24,7 @@
 logger = logging.getLogger(__name__)
 
 
-CACHE_VERSION = 12
+CACHE_VERSION = 13
 
 
 class VariantNotFoundError(Exception):
@@ -68,6 +68,7 @@
 
             actual_cache_key = self._values.get('__cache_key')
             if actual_cache_key == cache_key:
+                self._values['__cache_valid'] = True
                 return
             logger.debug("Outdated cache key '%s' (expected '%s')." % (
                     actual_cache_key, cache_key))
@@ -92,6 +93,7 @@
         self._values['__cache_key'] = cache_key
         config_text = json.dumps(self._values)
         self.cache.write('config.json', config_text)
+        self._values['__cache_valid'] = False
 
     def _validateAll(self, values):
         # Put all the defaults in the `site` section.
@@ -181,6 +183,10 @@
             sitec['sources'] = sourcesc
 
             routesc = []
+            routesc.append({
+                    'url': '/%path:path%',
+                    'source': 'pages',
+                    'func': 'pcurl(path)'})
             sitec['routes'] = routesc
 
             taxonomiesc = {}
@@ -238,9 +244,6 @@
                         'taxonomy': 'categories',
                         'func': 'pccaturl(category)'})
 
-            routesc.append({'url': '/%path:path%', 'source': 'pages',
-                    'func': 'pcurl(path)'})
-
         # Validate sources/routes.
         sourcesc = sitec.get('sources')
         routesc = sitec.get('routes')
--- a/piecrust/baking/baker.py	Thu Aug 21 10:56:17 2014 -0700
+++ b/piecrust/baking/baker.py	Thu Aug 21 22:28:22 2014 -0700
@@ -8,7 +8,7 @@
 import urllib.request, urllib.error, urllib.parse
 from queue import Queue, Empty
 from piecrust.baking.records import TransitionalBakeRecord, BakeRecordPageEntry
-from piecrust.chefutil import format_timed
+from piecrust.chefutil import format_timed, log_friendly_exception
 from piecrust.data.filters import (PaginationFilter, HasFilterClause,
         IsFilterClause, AndBooleanClause)
 from piecrust.processing.base import ProcessorPipeline
@@ -157,7 +157,7 @@
                 ctx, rp = self._bakeSingle(page, sub_uri, cur_sub, out_path,
                         pagination_filter, custom_data)
             except Exception as ex:
-                raise Exception("Error baking page '%s' for URI '%s'." %
+                raise Exception("Error baking page '%s' for URL '%s'." %
                         (page.ref_spec, uri)) from ex
 
             # Copy page assets.
@@ -263,6 +263,10 @@
             logger.debug(format_timed(t, 'loaded previous bake record',
                 colored=False));
 
+        # Figure out if we need to clean the cache because important things
+        # have changed.
+        self._handleCacheValidity(record)
+
         # Gather all sources by realm -- we're going to bake each realm
         # separately so we can handle "overlaying" (i.e. one realm overrides
         # another realm's pages).
@@ -287,6 +291,7 @@
 
         # Save the bake record.
         t = time.clock()
+        record.current.bake_time = time.time()
         record.collapseRecords()
         record.saveCurrent(record_cache.getCachePath(record_name))
         logger.debug(format_timed(t, 'saved bake record', colored=False))
@@ -296,6 +301,43 @@
         logger.info('-------------------------');
         logger.info(format_timed(start_time, 'done baking'));
 
+    def _handleCacheValidity(self, record):
+        start_time = time.clock()
+
+        reason = None
+        if self.force:
+            reason = "ordered to"
+        elif not self.app.config.get('__cache_valid'):
+            # The configuration file was changed, or we're running a new
+            # version of the app.
+            reason = "not valid anymore"
+        elif not record.previous.bake_time:
+            # We have no valid previous bake record.
+            reason = "need bake record regeneration"
+        else:
+            # Check if any template has changed since the last bake. Since
+            # there could be some advanced conditional logic going on, we'd
+            # better just force a bake from scratch if that's the case.
+            max_time = 0
+            for d in self.app.templates_dirs:
+                for _, __, filenames in os.walk(d):
+                    for fn in filenames:
+                        max_time = max(max_time, os.path.getmtime(fn))
+            if max_time >= record.previous.bake_time:
+                reason = "templates modified"
+
+        if reason is not None:
+            cache_dir = self.app.cache_dir
+            if os.path.isdir(cache_dir):
+                logger.debug("Cleaning cache: %s" % cache_dir)
+                shutil.rmtree(cache_dir)
+                self.force = True
+            logger.info(format_timed(start_time,
+                "cleaned cache (reason: %s)" % reason))
+        else:
+            logger.debug(format_timed(start_time, "cache is assumed valid",
+                colored=False))
+
     def _bakeRealm(self, record, realm, srclist):
         # Gather all page factories from the sources and queue them
         # for the workers to pick up. Just skip taxonomy pages for now.
@@ -435,7 +477,16 @@
         for w in pool:
             w.join()
         if abort.is_set():
-            raise Exception("Worker pool was aborted.")
+            excs = [w.abort_exception for w in pool
+                    if w.abort_exception is not None]
+            logger.error("%s errors" % len(excs))
+            if self.app.debug:
+                for e in excs:
+                    logger.exception(e)
+            else:
+                for e in excs:
+                    log_friendly_exception(logger, e)
+            raise Exception("Baking was aborted due to errors.")
 
 
 class BakeWorkerContext(object):
@@ -463,10 +514,10 @@
 
 class BakeWorker(threading.Thread):
     def __init__(self, wid, ctx):
-        super(BakeWorker, self).__init__()
+        super(BakeWorker, self).__init__(name=('worker%d' % wid))
         self.wid = wid
         self.ctx = ctx
-        self.num_bakes = 0
+        self.abort_exception = None
         self._page_baker = PageBaker(ctx.app, ctx.out_dir, ctx.force,
                 ctx.record)
 
@@ -484,8 +535,8 @@
                 self.ctx.work_queue.task_done()
             except Exception as ex:
                 self.ctx.abort_event.set()
-                logger.error("[%d] Critical error, aborting." % self.wid)
-                logger.exception(ex)
+                self.abort_exception = ex
+                logger.debug("[%d] Critical error, aborting." % self.wid)
                 break
 
     def _unsafeRun(self, job):
@@ -503,5 +554,4 @@
                 friendly_count = ' (%d pages)' % bake_res.num_subs
             logger.info(format_timed(start_time, '[%d] %s%s' %
                     (self.wid, friendly_uri, friendly_count)))
-            self.num_bakes += 1
 
--- a/piecrust/chefutil.py	Thu Aug 21 10:56:17 2014 -0700
+++ b/piecrust/chefutil.py	Thu Aug 21 22:28:22 2014 -0700
@@ -9,3 +9,11 @@
         return '[%s%s%s] %s' % (Fore.GREEN, time_str, Fore.RESET, message)
     return '[%s] %s' % (time_str, message)
 
+
+def log_friendly_exception(logger, ex):
+    indent = ''
+    while ex:
+        logger.error('%s%s' % (indent, str(ex)))
+        indent += '  '
+        ex = ex.__cause__
+
--- a/piecrust/commands/builtin/baking.py	Thu Aug 21 10:56:17 2014 -0700
+++ b/piecrust/commands/builtin/baking.py	Thu Aug 21 22:28:22 2014 -0700
@@ -41,7 +41,12 @@
             # a web server to handle serving default documents.
             ctx.app.config.set('site/pretty_urls', False)
 
-        baker.bake()
+        try:
+            baker.bake()
+            return 0
+        except Exception as ex:
+            logger.error(str(ex))
+            return 1
 
 
 class ShowRecordCommand(ChefCommand):
@@ -59,7 +64,7 @@
     def run(self, ctx):
         out_dir = ctx.args.output or os.path.join(ctx.app.root_dir, '_counter')
         record_cache = ctx.app.cache.getCache('bake_r')
-        record_name = hashlib.md5(out_dir).hexdigest() + '.record'
+        record_name = hashlib.md5(out_dir.encode('utf8')).hexdigest() + '.record'
         if not record_cache.has(record_name):
             raise Exception("No record has been created for this output path. "
                             "Did you bake there yet?")
--- a/piecrust/main.py	Thu Aug 21 10:56:17 2014 -0700
+++ b/piecrust/main.py	Thu Aug 21 22:28:22 2014 -0700
@@ -5,7 +5,7 @@
 import argparse
 import colorama
 from piecrust.app import PieCrust, PieCrustConfiguration, APP_VERSION
-from piecrust.chefutil import format_timed
+from piecrust.chefutil import format_timed, log_friendly_exception
 from piecrust.environment import StandardEnvironment
 from piecrust.pathutil import SiteNotFoundError, find_app_root
 from piecrust.plugins.base import PluginLoader
@@ -57,7 +57,8 @@
         if pre_args.debug:
             logger.exception(ex)
         else:
-            logger.error(str(ex))
+            log_friendly_exception(logger, ex)
+        return 1
 
 
 class PreParsedChefArgs(object):
@@ -122,7 +123,7 @@
         log_handler.setFormatter(ColoredFormatter("%(message)s"))
     root_logger.addHandler(log_handler)
     if res.log_file:
-        root_logger.addHandler(logging.FileHandler(res.log_file))
+        root_logger.addHandler(logging.FileHandler(res.log_file, mode='w'))
 
     return res
 
--- a/piecrust/processing/base.py	Thu Aug 21 10:56:17 2014 -0700
+++ b/piecrust/processing/base.py	Thu Aug 21 22:28:22 2014 -0700
@@ -115,12 +115,18 @@
 
 
 class ProcessorPipelineRecordEntry(object):
-    def __init__(self, rel_input, is_processed=False, is_overridden=False):
+    def __init__(self, base_dir, rel_input, is_processed=False,
+            is_overridden=False):
+        self.base_dir = base_dir
         self.rel_input = rel_input
         self.rel_outputs = []
         self.is_processed = is_processed
         self.is_overridden = is_overridden
 
+    @property
+    def path(self):
+        return os.path.join(self.base_dir, self.rel_input)
+
 
 class ProcessingContext(object):
     def __init__(self, base_dir, job_queue, record=None):
@@ -284,7 +290,8 @@
         # This can happen if a theme file (processed via a mount point)
         # is overridden in the user's website.
         if record.hasOverrideEntry(rel_path):
-            record.addEntry(ProcessorPipelineRecordEntry(rel_path,
+            record.addEntry(ProcessorPipelineRecordEntry(
+                    job.base_dir, rel_path,
                     is_processed=False, is_overridden=True))
             logger.info(format_timed(start_time,
                     '%s [not baked, overridden]' % rel_path))
@@ -294,7 +301,7 @@
         tree_root = builder.build(rel_path)
         print_node(tree_root, recursive=True)
         leaves = tree_root.getLeaves()
-        fi = ProcessorPipelineRecordEntry(rel_path)
+        fi = ProcessorPipelineRecordEntry(job.base_dir, rel_path)
         fi.rel_outputs = [l.path for l in leaves]
         record.addEntry(fi)
 
--- a/piecrust/serving.py	Thu Aug 21 10:56:17 2014 -0700
+++ b/piecrust/serving.py	Thu Aug 21 22:28:22 2014 -0700
@@ -42,11 +42,12 @@
         # Bake all the assets so we know what we have, and so we can serve
         # them to the client. We need a temp app for this.
         app = PieCrust(root_dir=self.root_dir, debug=self.debug)
+        mounts = app.assets_dirs
         self._out_dir = os.path.join(app.cache_dir, 'server')
         self._skip_patterns = app.config.get('baker/skip_patterns')
         self._force_patterns = app.config.get('baker/force_patterns')
         pipeline = ProcessorPipeline(
-                app, self._out_dir,
+                app, mounts, self._out_dir,
                 skip_patterns=self._skip_patterns,
                 force_patterns=self._force_patterns)
         self._record = pipeline.run()
@@ -112,10 +113,11 @@
         # Yep, we know about this URL because we processed an asset that
         # maps to it... make sure it's up to date by re-processing it
         # before serving.
-        asset_in_path = os.path.join(app.root_dir, entry.rel_input)
+        mounts = app.assets_dirs
+        asset_in_path = entry.path
         asset_out_path = os.path.join(self._out_dir, rel_req_path)
         pipeline = ProcessorPipeline(
-                app, self._out_dir,
+                app, mounts, self._out_dir,
                 skip_patterns=self._skip_patterns,
                 force_patterns=self._force_patterns)
         pipeline.run(asset_in_path)