Add logging function calls in DebOps script

This is an initial set of logging function calls in various parts of the
codebase.

(cherry picked from commit bb626eb)

src/debops/__main__.py

@@ -143,4 +143,6 @@ def handler_filter(record: logging.LogRecord):
     try:
         main()
     except KeyboardInterrupt:
+        logger.notice('User interrupted execution',
+                      extra={'block': 'stderr'})
         raise SystemExit('... aborted by user')

src/debops/ansible/inventory.py

@@ -16,6 +16,7 @@
 import itertools
 import random
 import time
+import logging
 
 try:
     # shlex.quote is new in Python 3.3
@@ -27,6 +28,8 @@ def shquote(s):
             return "''"
         return "'" + s.replace("'", "'\"'\"'") + "'"
 
+logger = logging.getLogger(__name__)
+
 
 class AnsibleInventory(object):
 
@@ -81,17 +84,21 @@ def __init__(self, project, name='system', *args, **kwargs):
             self.crypt_method = 'git-crypt'
             if not self._git_crypt_locked():
                 self.encfs_mounted = True
+        logger.debug('Ansible inventory initialized')
 
     def _git_crypt_locked(self):
         """Detect if git-crypt is locked or not"""
         # Based on solution from https://github.com/AGWA/git-crypt/issues/69
+        logger.debug('Checking git-crypt state')
         git_cmd = subprocess.Popen([self._commands['git'], 'config', '--local',
                                     '--get', 'filter.git-crypt.smudge'],
                                    stdout=subprocess.PIPE)
         out, err = git_cmd.communicate()
         if out:
+            logger.debug('git-crypt is in unlocked state')
             return False
         else:
+            logger.debug('git-crypt is in locked state')
             return True
 
     def _get_random_string(self):
@@ -101,6 +108,7 @@ def _get_random_string(self):
         return random_string
 
     def _encrypt_secrets_encfs(self):
+        logger.debug('Preparing to encrypt secrets using EncFS')
         encfs_keyfile = os.path.join(self.encfs_path, '.encfs6.keyfile')
         encfs_configfile = os.path.join(self.encfs_path, '.encfs6.xml')
         encfs_password = self._get_random_string()
@@ -111,18 +119,22 @@ def _encrypt_secrets_encfs(self):
                     itertools.chain.from_iterable(['-r', r]
                                                   for r in gpg_keys))
         except AttributeError:
+            logger.error('List of GPG recipients not specified',
+                         extra={'block': 'stderr'})
             raise ValueError('List of GPG recipients not specified')
 
         if not os.path.exists(self.encfs_path):
             print('Encrypting Ansible secrets using EncFS...')
             os.makedirs(self.encfs_path)
+            logger.debug('Encrypting EncFS keyfile')
             gpg_cmd = subprocess.Popen([self._commands['gpg'], '--encrypt', '--armor',
                                         '--output', encfs_keyfile] + gpg_recipients,
                                        stdin=subprocess.PIPE)
             gpg_cmd.communicate(encfs_password.encode('utf-8'))
             while not os.path.exists(encfs_keyfile):
                 time.sleep(1)
 
+            logger.debug('Creating EncFS filesystem')
             encfs_cmd = subprocess.Popen([
                 self._commands['encfs'], self.encfs_path, self.secret_path,
                 '--extpass',
@@ -141,12 +153,14 @@ def _encrypt_secrets_encfs(self):
                 self.encfs_mounted = True
             self.lock()
 
+            logger.debug('Encrypting EncFS configuration file')
             gpg_cmd = subprocess.Popen([self._commands['gpg'], '--encrypt', '--armor',
                                         '--output', encfs_configfile + '.asc']
                                        + gpg_recipients + [encfs_configfile])
             while not os.path.exists(encfs_configfile + '.asc'):
                 time.sleep(1)
             os.remove(encfs_configfile)
+            logger.debug('EncFS configuration complete')
 
     def createdirs(self):
         skel_dirs = (
@@ -172,9 +186,13 @@ def createdirs(self):
 
     def create(self):
 
+        logger.info('Creating inventory in {} directory'.format(self.root_path))
         try:
             os.makedirs(self.root_path)
         except FileExistsError:
+            logger.error('Cannot create view in {}, directory already '
+                         'exists'.format(self.root_path),
+                         extra={'block': 'stderr'})
             raise IsADirectoryError("Cannot create view in "
                                     + self.root_path + ", directory "
                                     "already exists")
@@ -209,6 +227,7 @@ def create(self):
                         host_as_controller=host_as_controller,
                         hostname=socket.gethostname(),
                         fqdn=socket.getfqdn()))
+            logger.debug('Default hosts file created in Ansible inventory')
 
         encrypted_secrets = self.kwargs.get('encrypt', None)
         if encrypted_secrets is not None:
@@ -218,17 +237,22 @@ def create(self):
                 # git-crypt is handled at the root of the repository,
                 # not in a specific inventory
                 pass
+        logger.debug('Ansible inventory created')
 
     def unlock(self):
         if self.encrypted:
+            logger.debug('Ansible secrets are encrypted, unlocking')
             if self.crypt_method == 'encfs':
+                logger.debug('Detected EncFS as encryption method')
                 keyfile = os.path.join(self.encfs_path, self.encfs_keyfile)
                 configfile = os.path.join(self.encfs_path, self.encfs_configfile)
                 crypted_configfile = os.path.join(self.encfs_path,
                                                   self.encfs_configfile + '.asc')
 
                 if os.path.ismount(self.secret_path):
                     self.encfs_mounted = True
+                    logger.debug('EncFS filesystem is already mounted, '
+                                 'state not changed')
                     return False
                 else:
                     try:
@@ -246,6 +270,7 @@ def unlock(self):
                         raise IOError(17, configfile + ' exists but is not a fifo')
 
                     subprocess_env = os.environ.copy()
+                    logger.debug('Decrypting and mounting EncFS filesystem')
                     encfs = subprocess.Popen([
                         self._commands['encfs'], self.encfs_path, self.secret_path,
                         '--extpass',
@@ -262,28 +287,37 @@ def unlock(self):
                     encfs.communicate()
                     os.remove(configfile)
                     self.encfs_mounted = True
+                    logger.debug('EncFS filesystem mounted')
                     return True
             elif self.crypt_method == 'git-crypt':
+                logger.debug('Detected git-crypt as encryption method')
                 if self._git_crypt_locked():
                     try:
                         if self.project.config.raw['project']['git']['auto_commit']:
                             self.project.commit()
                     except KeyError:
                         # The configuration option might not exist at this time
                         pass
+                    logger.debug('Unlocking secrets using git-crypt')
                     gitcrypt_cmd = subprocess.Popen([self._commands['git-crypt'],
                                                      'unlock'],
                                                     stderr=subprocess.PIPE)
                     out, err = gitcrypt_cmd.communicate()
                     rc = gitcrypt_cmd.returncode
                     if rc == 0:
                         self.encfs_mounted = True
+                        logger.debug('Files encrypted with git-crypt are '
+                                     'decrypted')
                         return True
                     else:
+                        logger.error('Cannot unlock project secrets, '
+                                     'git working directory not clean',
+                                     extra={'block': 'stderr'})
                         raise ChildProcessError('Cannot unlock project secrets, '
                                                 'git working directory not clean')
                 else:
                     self.encfs_mounted = True
+                    logger.debug('git-crypt is already unlocked')
                     return False
 
         else:
@@ -296,32 +330,42 @@ def unlock(self):
 
     def lock(self):
         if self.encrypted:
+            logger.debug('Ansible secrets are encrypted, locking')
             try:
                 if self.project.config.raw['project']['git']['auto_commit']:
                     self.project.commit()
             except KeyError:
                 # The configuration option might not exist at this time
                 pass
             if self.crypt_method == 'encfs':
+                logger.debug('Detected EncFS as encryption method')
                 if os.path.ismount(self.secret_path):
+                    logger.debug('EncFS filesystem is mounted, unmounting')
                     if sys.platform == 'darwin':
                         subprocess.call([self._commands['umount'], self.secret_path])
                     else:
                         subprocess.call([self._commands['fusermount'],
                                          '-u', self.secret_path])
                     self.encfs_mounted = False
+                    logger.debug('EncFS filesystem has been unmounted')
                     return True
             elif self.crypt_method == 'git-crypt':
+                logger.debug('Detected git-crypt as encryption method')
                 if not self._git_crypt_locked():
+                    logger.debug('Encrypted files are unlocked, locking')
                     gitcrypt_cmd = subprocess.Popen([self._commands['git-crypt'],
                                                      'lock'],
                                                     stderr=subprocess.PIPE)
                     out, err = gitcrypt_cmd.communicate()
                     rc = gitcrypt_cmd.returncode
                     if rc == 0:
                         self.encfs_mounted = False
+                        logger.debug('Encrypted files are locked')
                         return True
                     else:
+                        logger.error('Cannot lock project secrets, '
+                                     'git working directory not clean',
+                                     extra={'block': 'stderr'})
                         raise ChildProcessError('Cannot lock project secrets, '
                                                 'git working directory not clean')
 

src/debops/ansibleplaybookrunner.py

@@ -8,9 +8,12 @@
 import subprocess
 import configparser
 import textwrap
+import logging
 import os
 import sys
 
+logger = logging.getLogger(__name__)
+
 
 class AnsiblePlaybookRunner(object):
 
@@ -26,6 +29,7 @@ def __init__(self, project, *args, **kwargs):
         except configparser.NoSectionError:
             path = project.ansible_cfg.path
             if (os.path.exists(path) and os.path.isfile(path)):
+                logger.error('Cannot find [defaults] section in {}.format(path)')
                 raise ValueError("Cannot find [defaults] section in " + path)
             else:
                 raise FileNotFoundError("Cannot find Ansible "
@@ -293,12 +297,28 @@ def execute(self):
         try:
             unlocked = self.inventory.unlock()
 
+            if ('--check' in self._ansible_command or
+                    '-C' in self._ansible_command):
+                logger.info('Checking Ansible playbooks: {}'.format(
+                        ','.join(self._found_playbooks)),
+                        extra={'block': 'stderr'})
+            else:
+                logger.info('Running Ansible playbooks: {}'.format(
+                        ','.join(self._found_playbooks)),
+                        extra={'block': 'stderr'})
             print('Executing Ansible playbooks:')
             for playbook in self._found_playbooks:
                 print(unexpanduser(playbook))
+            logger.debug('Ansible command: {}'.format(
+                    ' '.join(self._ansible_command)))
             executor = subprocess.Popen(' '.join(self._ansible_command),
                                         shell=True)
+            logger.debug('Starting playbook execution')
             std_out, std_err = executor.communicate()
+            logger.debug('Playbook execution finished')
+            if executor.returncode != 0:
+                logger.error('Ansible finished with '
+                             'return code {}'.format(executor.returncode))
             self._ring_bell()
             return executor.returncode
 
@@ -307,6 +327,8 @@ def execute(self):
                                     'git working directory not clean')
 
         except KeyboardInterrupt:
+            logger.notice('Playbook execution interrupted by user',
+                          extra={'block': 'stderr'})
             if unlocked:
                 self.inventory.lock()
             raise SystemExit('... aborted by user')

src/debops/cli.py

@@ -9,7 +9,11 @@
 from .ansiblerunner import AnsibleRunner
 from .ansibleplaybookrunner import AnsiblePlaybookRunner
 from .envrunner import EnvRunner
+import logging
 import sys
+import os
+
+logger = logging.getLogger(__name__)
 
 
 class Interpreter(object):
@@ -18,6 +22,8 @@ def __init__(self, args=None):
         self.args = args
         self.config = Configuration()
         self.parsed_args = Subcommands(self.args)
+        logger.debug('Command line interpreter initialized')
+        logger.debug('Control user=' + os.getlogin())
 
         if self.parsed_args.section == 'project':
             if self.parsed_args.command == 'init':