Add logging module to Basilisp (#243)

* Add logging module to Basilisp

* Satisfy MyPy overlords

* Fix linting errors now

Author: chrisrink10

.prospector.yaml

@@ -16,6 +16,7 @@ pep8:
 pylint:
   disable:
     - len-as-condition
+    - logging-fstring-interpolation
     - no-else-return
     - protected-access
     - unsubscriptable-object

Makefile

@@ -13,6 +13,7 @@ release:
 
 .PHONY: repl
 repl:
+	@BASILISP_USE_DEV_LOGGER=true
 	@pipenv run basilisp repl
 
 

src/basilisp/cli.py

@@ -14,6 +14,8 @@
 import basilisp.main as basilisp
 import basilisp.reader as reader
 
+importlib.import_module('basilisp.logging')
+
 
 @click.group()
 def cli():

src/basilisp/compiler.py

@@ -4,6 +4,7 @@
 import functools
 import importlib
 import itertools
+import logging
 import sys
 import types
 import uuid
@@ -35,6 +36,8 @@
 from basilisp.lang.util import genname, munge
 from basilisp.util import Maybe, partition
 
+logger = logging.getLogger(__name__)
+
 USE_VAR_INDIRECTION = 'use_var_indirection'
 
 _BUILTINS_NS = 'builtins'
@@ -483,10 +486,8 @@ def _def_ast(ctx: CompilerContext, form: llist.List) -> ASTStream:
     yield from meta_nodes
     yield from def_nodes
 
-    # TODO: log this out, rather than emitting as a warning
-    # https://github.com/chrisrink10/basilisp/issues/121
     if safe_name in ctx.current_ns.module.__dict__:
-        print(f"WARNING: redefining local Python name '{safe_name}' in module '{ctx.current_ns.module.__name__}'")
+        logger.warning(f"redefining local Python name '{safe_name}' in module '{ctx.current_ns.module.__name__}'")
 
     yield _dependency(ast.Assign(targets=[ast.Name(id=safe_name, ctx=ast.Store())],
                                  value=Maybe(def_value).map(_unwrap_node).or_else_get(ast.NameConstant(None))))

src/basilisp/importer.py

@@ -1,5 +1,6 @@
 import importlib.machinery
 import importlib.util
+import logging
 import os.path
 import sys
 import types
@@ -11,6 +12,8 @@
 import basilisp.reader as reader
 from basilisp.lang.util import demunge
 
+logger = logging.getLogger(__name__)
+
 
 class BasilispImporter(MetaPathFinder, SourceLoader):
     """Python import hook to allow directly loading Basilisp code within
@@ -39,6 +42,7 @@ def find_spec(self,
             for filename in filenames:
                 if os.path.exists(filename):
                     state = {'fullname': fullname, "filename": filename, 'path': entry, 'target': target}
+                    logger.debug(f"Found potential Basilisp module '{fullname}' in file '{filename}'")
                     return importlib.machinery.ModuleSpec(fullname, self, origin=filename, loader_state=state)
         return None
 
@@ -59,6 +63,7 @@ def get_filename(self, fullname: str) -> str:
         return spec.loader_state.filename
 
     def create_module(self, spec: importlib.machinery.ModuleSpec):
+        logger.debug(f"Creating Basilisp module '{spec.name}''")
         mod = types.ModuleType(spec.name)
         mod.__file__ = spec.loader_state["filename"]
         mod.__loader__ = spec.loader
@@ -88,8 +93,10 @@ def exec_module(self, module):
         ns: runtime.Namespace = runtime.set_current_ns(ns_name).value
         ns.module = module
 
+        logger.debug(f"Reading and compiling Basilisp module '{fullname}''")
         forms = reader.read_file(filename, resolver=runtime.resolve_alias)
         compiler.compile_module(forms, compiler.CompilerContext(), module, filename)
+        logger.debug(f"Loaded Basilisp module '{fullname}''")
 
         # Because we want to (by default) add 'basilisp.core into every namespace by default,
         # we want to make sure we don't try to add 'basilisp.core into itself, causing a

src/basilisp/lang/runtime.py

@@ -2,6 +2,7 @@
 import functools
 import importlib
 import itertools
+import logging
 import math
 import threading
 import types
@@ -23,6 +24,8 @@
 from basilisp.lang.typing import LispNumber
 from basilisp.util import Maybe
 
+logger = logging.getLogger(__name__)
+
 _CORE_NS = 'basilisp.core'
 _REPL_DEFAULT_NS = 'user'
 _NS_VAR_NAME = '*ns*'
@@ -741,6 +744,7 @@ def init_ns_var(which_ns: str = _CORE_NS,
     core_ns = Namespace.get_or_create(core_sym)
     ns_var = Var.intern(
         core_sym, sym.Symbol(ns_var_name), core_ns, dynamic=True)
+    logger.debug(f'Created namespace variable {sym.symbol(ns_var_name, ns=which_ns)}')
     return ns_var
 
 
@@ -751,9 +755,11 @@ def set_current_ns(ns_name: str,
     """Set the value of the dynamic variable `*ns*` in the current thread."""
     symbol = sym.Symbol(ns_name)
     ns = Namespace.get_or_create(symbol, module=module)
-    ns_var = Maybe(Var.find(sym.Symbol(ns_var_name, ns=ns_var_ns))) \
+    ns_var_sym = sym.Symbol(ns_var_name, ns=ns_var_ns)
+    ns_var = Maybe(Var.find(ns_var_sym)) \
         .or_else_raise(lambda: RuntimeException(f"Dynamic Var {sym.Symbol(ns_var_name, ns=ns_var_ns)} not bound!"))
     ns_var.push_bindings(ns)
+    logger.debug(f'Setting {ns_var_sym} to {ns}')
     return ns_var
 
 
@@ -765,27 +771,32 @@ def ns_bindings(ns_name: str,
     """Context manager for temporarily changing the value of basilisp.core/*ns*."""
     symbol = sym.Symbol(ns_name)
     ns = Namespace.get_or_create(symbol, module=module)
-    ns_var = Maybe(Var.find(sym.Symbol(ns_var_name, ns=ns_var_ns))) \
+    ns_var_sym = sym.Symbol(ns_var_name, ns=ns_var_ns)
+    ns_var = Maybe(Var.find(ns_var_sym)) \
         .or_else_raise(lambda: RuntimeException(f"Dynamic Var {sym.Symbol(ns_var_name, ns=ns_var_ns)} not bound!"))
 
     try:
+        logger.debug(f'Binding {ns_var_sym} to {ns}')
         ns_var.push_bindings(ns)
         yield ns_var.value
     finally:
         ns_var.pop_bindings()
+        logger.debug(f'Reset bindings for {ns_var_sym} to {ns_var.value}')
 
 
 @contextlib.contextmanager
 def remove_ns_bindings(ns_var_name: str = _NS_VAR_NAME,
                        ns_var_ns: str = _NS_VAR_NS):
     """Context manager to pop the most recent bindings for basilisp.core/*ns* after
     completion of the code under management."""
-    ns_var = Maybe(Var.find(sym.Symbol(ns_var_name, ns=ns_var_ns))) \
+    ns_var_sym = sym.Symbol(ns_var_name, ns=ns_var_ns)
+    ns_var = Maybe(Var.find(ns_var_sym)) \
         .or_else_raise(lambda: RuntimeException(f"Dynamic Var {sym.Symbol(ns_var_name, ns=ns_var_ns)} not bound!"))
     try:
         yield
     finally:
         ns_var.pop_bindings()
+        logger.debug(f'Reset bindings for {ns_var_sym} to {ns_var.value}')
 
 
 def get_current_ns(ns_var_name: str = _NS_VAR_NAME,

src/basilisp/logging.py

@@ -0,0 +1,28 @@
+import logging
+import os
+
+
+def _get_default_level() -> str:
+    """Get the default logging level for Basilisp."""
+    return os.getenv('BASILISP_LOGGING_LEVEL', 'WARNING')
+
+
+def _get_default_handler(level: str, formatter: logging.Formatter) -> logging.Handler:
+    """Get the default logging handler for Basilisp."""
+    handler: logging.Handler = logging.NullHandler()
+    if os.getenv('BASILISP_USE_DEV_LOGGER') == 'true':
+        handler = logging.StreamHandler()
+
+    handler.setFormatter(formatter)
+    handler.setLevel(level)
+    return handler
+
+
+_DEFAULT_FORMAT = '%(asctime)s %(levelname)s [%(name)s.%(funcName)s:%(lineno)d] - %(message)s'
+_DEFAULT_FORMATTER = logging.Formatter(_DEFAULT_FORMAT)
+_DEFAULT_LEVEL = _get_default_level()
+_DEFAULT_HANDLER = _get_default_handler(_DEFAULT_LEVEL, _DEFAULT_FORMATTER)
+
+logger = logging.getLogger('basilisp')
+logger.setLevel(_DEFAULT_LEVEL)
+logger.addHandler(_DEFAULT_HANDLER)

src/basilisp/main.py

@@ -3,6 +3,8 @@
 import basilisp.importer as importer
 import basilisp.lang.runtime as runtime
 
+importlib.import_module('basilisp.logging')
+
 
 def init():
     """Initialize the runtime environment for evaluation."""