Templates trace logging introduced.

CHANGES.txt

@@ -5,6 +5,8 @@ Features
 --------
 
 * Support passing ``--poll`` to ``nikola auto`` to better deal with symlink farms.
+* Trace template usage when an environment variable ``NIKOLA_TEMPLATES_TRACE``
+  is set to any non-empty value.
 
 Bugfixes
 --------

docs/theming.rst

@@ -7,7 +7,7 @@
 .. author: The Nikola Team
 
 :Version: 8.3.0
-:Author: Roberto Alsina <ralsina@netmanagers.com.ar>
+:Author: Roberto Alsina <ralsina@netmanagers.com.ar> and others
 
 .. class:: alert alert-primary float-md-right
 
@@ -130,8 +130,9 @@ The following keys are currently supported:
 
     The parent is so you don’t have to create a full theme each time: just
     create an empty theme, set the parent, and add the bits you want modified.
-    You **must** define a parent, otherwise many features won’t work due to
-    missing templates, messages, and assets.
+    It is strongly recommended you define a parent.  If you don't, many features
+    won’t work due to missing templates, messages, and assets until your home-grown
+    template is complete.
 
     The following settings are recommended:
 
@@ -184,8 +185,16 @@ so ``post.tmpl`` only define the content, and the layout is inherited from ``bas
 
 Another concept is theme inheritance. You do not need to duplicate all the
 default templates in your theme — you can just override the ones you want
-changed, and the rest will come from the parent theme. (Every theme needs a
-parent.)
+changed, and the rest will come from the parent theme.  If your theme does not
+define a parent, it needs to be complete.  It is generally a lot harder to
+come up with a complete theme, compared to only changing a few files and using
+the rest from a suitable parent theme.
+
+.. Tip::
+
+   If you set the environment variable ``NIKOLA_TEMPLATES_TRACE`` to any non-empty value
+   (``true`` is recommended), Nikola will log template usage, both on output and also
+   into a file ``templates_log.txt``.
 
 Apart from the `built-in templates`_ listed below, you can add other templates for specific
 pages, which the user can then use in his ``POSTS`` or ``PAGES`` option in
@@ -194,11 +203,11 @@ page via the ``template`` metadata, and custom templates can be added in the
 ``templates/`` folder of your site.
 
 If you want to modify (override) a built-in template, use ``nikola theme -c
-<name>.tmpl``.  This command will copy the specified template file to the
-``templates/`` directory of your currently used theme.
+<name>.tmpl``.  This command will copy the specified template file from the
+parent theme to the ``templates/`` directory of your currently used theme.
 
 Keep in mind that your theme is *yours*, so you can require whatever data you
-want (eg. you may depend on specific custom ``GLOBAL_CONTEXT`` variables, or
+want (e.g., you may depend on specific custom ``GLOBAL_CONTEXT`` variables, or
 post meta attributes). You don’t need to keep the same theme structure as the
 default themes do (although many of those names are hardcoded). Inheriting from
 at least ``base`` (or ``base-jinja``) is heavily recommended, but not strictly

nikola/__init__.py

@@ -29,8 +29,15 @@
 import os
 import sys
 
+# The current Nikola version:
 __version__ = '8.3.0'
+# A flag whether logging should emmit debug information:
 DEBUG = bool(os.getenv('NIKOLA_DEBUG'))
+# A flag whether special templates trace logging should be generated:
+TEMPLATES_TRACE = bool(os.getenv('NIKOLA_TEMPLATES_TRACE'))
+# When this flag is set, fewer exceptions are handled internally;
+# instead they are left unhandled for the run time system to deal with them,
+# which typically leads to the stack traces being exposed.
 SHOW_TRACEBACKS = bool(os.getenv('NIKOLA_SHOW_TRACEBACKS'))
 
 if sys.version_info[0] == 2:

nikola/log.py

@@ -30,7 +30,7 @@
 import logging
 import warnings
 
-from nikola import DEBUG
+from nikola import DEBUG, TEMPLATES_TRACE
 
 __all__ = (
     "get_logger",
@@ -86,6 +86,10 @@ class LoggingMode(enum.Enum):
     QUIET = 2
 
 
+_LOGGING_FMT = "[%(asctime)s] %(levelname)s: %(name)s: %(message)s"
+_LOGGING_DATEFMT = "%Y-%m-%d %H:%M:%S"
+
+
 def configure_logging(logging_mode: LoggingMode = LoggingMode.NORMAL) -> None:
     """Configure logging for Nikola.
 
@@ -103,8 +107,8 @@ def configure_logging(logging_mode: LoggingMode = LoggingMode.NORMAL) -> None:
     handler = logging.StreamHandler()
     handler.setFormatter(
         ColorfulFormatter(
-            fmt="[%(asctime)s] %(levelname)s: %(name)s: %(message)s",
-            datefmt="%Y-%m-%d %H:%M:%S",
+            fmt=_LOGGING_FMT,
+            datefmt=_LOGGING_DATEFMT,
         )
     )
 
@@ -137,6 +141,39 @@ def get_logger(name: str, handlers=None) -> logging.Logger:
 
 
 LOGGER = get_logger("Nikola")
+TEMPLATES_LOGGER = get_logger("nikola.templates")
+
+
+def init_template_trace_logging(filename: str) -> None:
+    """Initialize the tracing of the template system.
+
+    This tells a theme designer which templates are being exercised
+    and for which output files, and, if applicable, input files.
+
+    As there is lots of other stuff happening on the normal output stream,
+    this info is also written to a log file.
+    """    
+    TEMPLATES_LOGGER.level = logging.DEBUG
+    formatter = logging.Formatter(
+        fmt=_LOGGING_FMT,
+        datefmt=_LOGGING_DATEFMT,
+    )
+    shandler = logging.StreamHandler()
+    shandler.setFormatter(formatter)
+    shandler.setLevel(logging.DEBUG)
+
+    fhandler = logging.FileHandler(filename, encoding="UTF-8")
+    fhandler.setFormatter(formatter)
+    fhandler.setLevel(logging.DEBUG)
+
+    TEMPLATES_LOGGER.handlers = [shandler, fhandler]
+    TEMPLATES_LOGGER.propagate = False
+
+    TEMPLATES_LOGGER.info("Template usage being traced to file %s", filename)
+
+
+if TEMPLATES_TRACE:
+    init_template_trace_logging("templates_log.txt")
 
 
 # Push warnings to logging

nikola/nikola.py

@@ -395,7 +395,7 @@ def __init__(self, **config):
         self.timeline = []
         self.pages = []
         self._scanned = False
-        self._template_system = None
+        self._template_system: typing.Optional[TemplateSystem] = None
         self._THEMES = None
         self._MESSAGES = None
         self.filters = {}
@@ -1459,7 +1459,11 @@ def render_template(self, template_name, output_name, context, url_type=None, is
         If ``is_fragment`` is set to ``True``, a HTML fragment will
         be rendered and not a whole HTML document.
         """
-        local_context = {}
+        if "post" in context and context["post"] is not None:
+            utils.TEMPLATES_LOGGER.debug("For %s, template %s builds %s", context["post"].source_path, template_name, output_name)
+        else:
+            utils.TEMPLATES_LOGGER.debug("Template %s builds %s", template_name, output_name)
+        local_context: typing.Dict[str, typing.Any] = {}
         local_context["template_name"] = template_name
         local_context.update(self.GLOBAL_CONTEXT)
         local_context.update(context)

nikola/utils.py

@@ -66,7 +66,7 @@
 
 # Renames
 from nikola import DEBUG  # NOQA
-from .log import LOGGER, get_logger  # NOQA
+from .log import LOGGER, TEMPLATES_LOGGER, get_logger  # NOQA
 from .hierarchy_utils import TreeNode, clone_treenode, flatten_tree_structure, sort_classifications
 from .hierarchy_utils import join_hierarchical_category_path, parse_escaped_hierarchical_category_name