Add better logging

gogsmaker.py

@@ -6,13 +6,16 @@ import os
 import sys
 import subprocess
 import hmac
+import logging
+import coloredlogs
 from hashlib import sha256
 from threading import Thread
 from functools import wraps
-from termcolor import colored
 from flask import Flask, request
 from . import settings
 
+LOGGER_NAME = __name__
+
 app = Flask(__name__)
 
 
@@ -42,6 +45,18 @@ def repo_path(hook):
     return os.path.join(settings.CLONE_ROOT, hook['name'])
 
 
+def subprocess_run(command, **kwargs):
+    ''' Run subprocess with default arguments '''
+    args = {
+        'check': True,
+        'stdout': subprocess.DEVNULL,
+        'stderr': subprocess.PIPE,
+    }
+    args.update(kwargs)
+
+    return subprocess.run(command, **args)
+
+
 class MakeWorker(Thread):
     ''' A make job '''
 
@@ -54,11 +69,15 @@ class MakeWorker(Thread):
     def run(self):
         ''' Run the make job '''
         try:
-            subprocess.run(['make', '-C', self.path, '--']
+            subprocess_run(['make', '-C', self.path, '--']
                            + self.hook['targets'])
-        except subprocess.CalledProcessError:
+        except subprocess.CalledProcessError as error:
-            print('Hook {}: failed to make'.format(self.hook['name']),
+            logging.error(
-                  file=sys.stderr)
+                ("Hook %s: make failed with status %s. "
+                 "Error output:\n%s\n"),
+                self.hook['name'],
+                error.returncode,
+                error.stderr.decode('utf-8'))
 
 
 def update_repo(hook, clone_url):
@@ -66,17 +85,29 @@ def update_repo(hook, clone_url):
     path = repo_path(hook)
     if os.path.isdir(os.path.join(path, '.git')):  # Repo is already cloned
         try:
-            subprocess.run(['git', '-C', path, 'reset', '--hard'],
+            subprocess_run(['git', '-C', path, 'reset', '--hard']
-                           check=True)  # Just in case.
+                           )  # Just in case.
-            subprocess.run(['git', '-C', path, 'pull'], check=True)
+            subprocess_run(['git', '-C', path, 'pull'])
-        except subprocess.CalledProcessError:
+        except subprocess.CalledProcessError as error:
+            logging.error(
+                ("Hook %s: git failed with status %s. "
+                 "Error output:\n%s\n"),
+                hook['name'],
+                error.returncode,
+                error.stderr.decode('utf-8'))
             raise GitError("Cannot pull {}".format(hook['name']))
 
-    else:  # Simply update
+    else:  # Repo is to be cloned
         try:
-            subprocess.run(['mkdir', '-p', path])
+            subprocess_run(['mkdir', '-p', path])
-            subprocess.run(['git', 'clone', clone_url, path], check=True)
+            subprocess_run(['git', 'clone', clone_url, path], check=True)
-        except subprocess.CalledProcessError:
+        except subprocess.CalledProcessError as error:
+            logging.error(
+                ("Hook %s: git failed cloning with status %s. "
+                 "Error output:\n%s"),
+                hook['name'],
+                error.returncode,
+                error.stderr.decode('utf-8'))
             raise GitError("Cannot clone {}".format(clone_url))
 
 
@@ -140,12 +171,23 @@ def view_root(payload, hook):
 
 
 @app.before_first_request  # FIXME this should be run on startup...
+def startup_actions():
+    setup_logger()
+    check_settings()
+
+
+def setup_logger():
+    ''' Setup the default logger '''
+    coloredlogs.install(
+        fmt="%(asctime)s [%(levelname)s] %(message)s",
+    )
+
+
 def check_settings():
     ''' Check the supplied settings '''
     if settings.DEBUG:
-        print(colored('WARNING! ', 'red', attrs=['bold'])
+        logging.warning('GogsMaker is running in DEBUG MODE, this is '
-              + 'GogsMaker is running in DEBUG MODE, this is unsuitable for '
+                        'unsuitable for production environments!')
-              + 'production environments!')
 
     required_keys = ['name', 'url', 'targets', 'secret']
     for hook_id, hook in enumerate(settings.HOOKS):
@@ -156,7 +198,7 @@ def check_settings():
                 else:
                     descr = '{} (#{})'.format(hook['name'], hook_id)
 
-                print((colored('FATAL! ', 'red', attrs=['bold'])
+                logging.critical(('Configuration error: hook %s lacks '
-                       + 'Configuration error: hook {} lacks attribute {}.')
+                                  'attribute %s.'),
-                      .format(descr, key))
+                                 descr, key)
                 sys.exit(1)

requirements.txt

@@ -4,4 +4,5 @@ itsdangerous==0.24
 Jinja2==2.10
 MarkupSafe==1.0
 Werkzeug==0.14.1
-termcolor==1.1.0
+humanfriendly==4.8
+coloredlogs==9.0