enhance verbose output of hook loader

Fix the logging configuration so the console output actually appears.

Move the console log output to stderr.

Clean up some of the indivual log messages.

Change-Id: I55d1bda61eca7435c3cc776cade8920412f31e03

Author: dhellmann

virtualenvwrapper/hook_loader.py

@@ -82,7 +82,7 @@ def main():
     parser.disable_interspersed_args()  # stop when on option without an '-'
     options, args = parser.parse_args()
 
-    root_logger = logging.getLogger('')
+    root_logger = logging.getLogger('virtualenvwrapper')
 
     # Set up logging to a file
     logfile = os.environ.get('VIRTUALENVWRAPPER_LOG_FILE')
@@ -98,7 +98,7 @@ def main():
         root_logger.addHandler(file_handler)
 
     # Send higher-level messages to the console, too
-    console = logging.StreamHandler()
+    console = logging.StreamHandler(stream=sys.stderr)
     console_level = [logging.WARNING,
                      logging.INFO,
                      logging.DEBUG,
@@ -107,6 +107,7 @@ def main():
     formatter = logging.Formatter('%(name)s %(message)s')
     console.setFormatter(formatter)
     root_logger.addHandler(console)
+    root_logger.setLevel(console_level)
 
     # logging.getLogger(__name__).debug('cli args %s', args)
 
@@ -125,7 +126,7 @@ def main():
     if options.sourcing:
         hook += '_source'
 
-    log = logging.getLogger(__name__)
+    log = logging.getLogger('virtualenvwrapper.hook_loader')
 
     log.debug('Running %s hooks', hook)
     run_hooks(hook, options, args)
@@ -147,13 +148,16 @@ def main():
 
 
 def run_hooks(hook, options, args, output=None):
+    log = logging.getLogger('virtualenvwrapper.hook_loader')
     if output is None:
         output = sys.stdout
 
     namespace = 'virtualenvwrapper.%s' % hook
     if options.names:
+        log.debug('looking for %s hooks %s' % (namespace, options.names))
         hook_mgr = NamedExtensionManager(namespace, options.names)
     else:
+        log.debug('looking for %s hooks' % namespace)
         hook_mgr = ExtensionManager(namespace)
 
     if options.listing:
@@ -169,6 +173,7 @@ def show(ext):
         def get_source(ext, args):
             # Show the shell commands so they can
             # be run in the calling shell.
+            log.debug('getting source instructions for %s' % ext.name)
             contents = (ext.plugin(args) or '').strip()
             if contents:
                 output.write('# %s\n' % ext.name)
@@ -182,6 +187,7 @@ def get_source(ext, args):
     else:
         # Just run the plugin ourselves
         def invoke(ext, args):
+            log.debug('running %s' % ext.name)
             ext.plugin(args)
         try:
             hook_mgr.map(invoke, args[1:])

virtualenvwrapper/user_scripts.py

@@ -217,6 +217,7 @@ def pre_mkvirtualenv(args):
 
 
 def post_mkvirtualenv_source(args):
+    log.debug('post_mkvirtualenv_source %s', str(args))
     return """
 #
 # Run user-provided scripts
@@ -237,6 +238,7 @@ def pre_cpvirtualenv(args):
 
 
 def post_cpvirtualenv_source(args):
+    log.debug('post_cpvirtualenv_source %s', str(args))
     return """
 #
 # Run user-provided scripts
@@ -268,7 +270,7 @@ def pre_activate(args):
 
 
 def post_activate_source(args):
-    log.debug('post_activate')
+    log.debug('post_activate_source')
     return """
 #
 # Run user-provided scripts
@@ -281,7 +283,7 @@ def post_activate_source(args):
 
 
 def pre_deactivate_source(args):
-    log.debug('pre_deactivate')
+    log.debug('pre_deactivate_source')
     return """
 #
 # Run user-provided scripts
@@ -294,7 +296,7 @@ def pre_deactivate_source(args):
 
 
 def post_deactivate_source(args):
-    log.debug('post_deactivate')
+    log.debug('post_deactivate_source')
     return """
 #
 # Run user-provided scripts