i think that's it for logging on system libs

aif/network/__init__.py

@@ -42,6 +42,7 @@ class Net(object):
         elif self.provider == 'networkd':
             self.provider = networkd
         else:
+            _logger.error('Unable to determine which network provider to use based on configuration.')
             raise RuntimeError('Could not determine provider')
         self.connections = []
         self._initConns()
@@ -62,6 +63,7 @@ class Net(object):
             fh.write('{0}\n'.format(self.hostname))
         os.chown(cfg, 0, 0)
         os.chmod(cfg, 0o0644)
+        _logger.info('Wrote: {0}'.format(cfg))
         for iface in self.connections:
             for src, dest in iface.services.items():
                 realdest = os.path.join(chroot_base, dest)

aif/network/_common.py

@@ -63,10 +63,11 @@ def convertPSK(ssid, passphrase):
         _logger.error('WPA passphrase must be an ASCII string')
         raise ValueError('Passed invalid encoding for WPA PSK string')
     if len(ssid) > 32:
-        _logger.error('')
+        _logger.error('SSID must be <= 32 characters long.')
-        raise ValueError('ssid must be <= 32 characters')
+        raise ValueError('Invalid ssid length')
     if not 7 < len(passphrase) < 64:
-        raise ValueError('passphrase must be >= 8 and <= 32 characters')
+        _logger.error('Passphrase must be >= 8 and <= 32 characters long.')
+        raise ValueError('Invalid passphrase length')
     raw_psk = pbkdf2_hmac('sha1', str(passphrase), str(ssid), 4096, 32)
     hex_psk = binascii.hexlify(raw_psk)
     str_psk = hex_psk.decode('utf-8')
@@ -92,7 +93,8 @@ def convertWifiCrypto(crypto_xmlobj, ssid):
             try:
                 crypto['auth']['passphrase'] = psk_xml.text.strip('\r').strip('\n')
             except UnicodeDecodeError:
-                raise ValueError('WPA-PSK passphrases must be ASCII')
+                _logger.error('WPA-PSK passphrases must be ASCII.')
+                raise ValueError('Invalid WPA-PSK encoding')
             crypto['auth']['psk'] = convertPSK(ssid, crypto['auth']['passphrase'])
         else:
             crypto['auth']['psk'] = psk_xml.text.strip().lower()

aif/system/__init__.py

@@ -1,20 +1,30 @@
+import logging
+##
+from lxml import etree
+##
 from . import locales
 from . import console
 from . import users
 from . import services
 
 
+_logger = logging.getLogger(__name__)
+
+
 class Sys(object):
     def __init__(self, chroot_base, system_xml):
         self.xml = system_xml
+        _logger.debug('system_xml: {0}'.format(etree.tostring(self.xml, with_tail = False).decode('utf-8')))
         self.chroot_base = chroot_base
         self.locale = locales.Locale(self.chroot_base, self.xml.find('locales'))
+        self.console = console.Console(self.chroot_base, self.xml.find('console'))
         self.tz = locales.Timezone(self.chroot_base, self.xml.attrib.get('timezone', 'UTC'))
         self.user = users.UserDB(self.chroot_base, self.xml.find('rootPassword'), self.xml.find('users'))
         self.services = services.ServiceDB(self.chroot_base, self.xml.find('services'))
 
     def apply(self):
         self.locale.writeConf()
+        self.console.writeConf()
         self.tz.apply()
         self.user.writeConf()
         self.services.apply()

aif/system/console.py

@@ -1,74 +1,18 @@
 import configparser
 import io
+import logging
 import os
 import pathlib
 import re
 
 
+_logger = logging.getLogger(__name__)
+
+
 _font_re = re.compile(r'(\.(psfu?|fnt))?(\.gz)?$', re.IGNORECASE)
 _kbd_re = re.compile(r'(\.map)?(\.gz)?$')
 
 
-class Font(object):
-    def __init__(self, font_xml):
-        self.xml = font_xml
-        self.settings = {}
-        if self.xml:
-            chk = {'FONT': self.xml.find('font'),
-                   'FONT_MAP': self.xml.find('map'),
-                   'FONT_UNIMAP': self.xml.find('unicodeMap')}
-            for setting, xml in chk.items():
-                if xml:
-                    self.settings[setting] = xml.text.strip()
-
-    def verify(self, chroot_base = '/'):
-        if 'FONT' not in self.settings.keys():
-            return(None)
-        fontdir = pathlib.Path(chroot_base).joinpath('usr', 'share', 'kbd', 'consolefonts')
-        fontnames = [_font_re.sub('', p.stem) for p in fontdir.iterdir() if not p.stem.startswith(('README.',
-                                                                                                   'partialfonts',
-                                                                                                   'ERRORS'))]
-        if self.settings['FONT'] not in fontnames:
-            raise ValueError('console font is not installed on target system')
-        return(True)
-
-
-class Keyboard(object):
-    def __init__(self, chroot_base, keyboard_xml):
-        self.xml = keyboard_xml
-        self.chroot_base = chroot_base
-        self.settings = {}
-        if self.xml:
-            chk = {'KEYMAP': self.xml.find('map'),
-                   'KEYMAP_TOGGLE': self.xml.find('toggle')}
-            for setting, xml in chk.items():
-                if xml:
-                    self.settings[setting] = xml.text.strip()
-
-    def verify(self):
-        kbdnames = []
-        for i in ('KEYMAP', 'KEYMAP_TOGGLE'):
-            if i in self.settings.keys():
-                kbdnames.append(self.settings[i])
-        if not kbdnames:
-            return(None)
-        keymapdir = os.path.join(self.chroot_base, 'usr', 'share', 'kbd', 'keymaps')
-        kbdmaps = []
-        for root, dirs, files in os.walk(keymapdir, topdown = True):
-            if root.endswith('/include'):
-                dirs[:] = []
-                files[:] = []
-                continue
-            for f in files:
-                if f.endswith('.inc'):
-                    continue
-                kbdmaps.append(_kbd_re.sub('', f))
-        for k in kbdnames:
-            if k not in kbdmaps:
-                raise ValueError('keyboard map "{0}" is not installed on target system'.format(k))
-        return(True)
-
-
 class Console(object):
     def __init__(self, chroot_base, console_xml):
         self.xml = console_xml
@@ -96,4 +40,73 @@ class Console(object):
                 fh.write(line)
         os.chmod(cfg, 0o0644)
         os.chown(cfg, 0, 0)
+        _logger.info('Wrote: {0}'.format(cfg))
         return(None)
+
+
+class Font(object):
+    def __init__(self, font_xml):
+        self.xml = font_xml
+        self.settings = {}
+        if self.xml:
+            chk = {'FONT': self.xml.find('font'),
+                   'FONT_MAP': self.xml.find('map'),
+                   'FONT_UNIMAP': self.xml.find('unicodeMap')}
+            for setting, xml in chk.items():
+                if xml:
+                    self.settings[setting] = xml.text.strip()
+        _logger.debug('Rendered settings: {0}'.format(self.settings))
+
+    def verify(self, chroot_base = '/'):
+        if 'FONT' not in self.settings.keys():
+            _logger.warning('Attempted to verify settings with no chosen font.')
+            return(None)
+        fontdir = pathlib.Path(chroot_base).joinpath('usr', 'share', 'kbd', 'consolefonts')
+        fontnames = [_font_re.sub('', p.stem) for p in fontdir.iterdir() if not p.stem.startswith(('README.',
+                                                                                                   'partialfonts',
+                                                                                                   'ERRORS'))]
+        _logger.debug('Rendered list of supported console fonts on target system: {0}'.format(','.join(fontnames)))
+        if self.settings['FONT'] not in fontnames:
+            _logger.error('Console font {0} not installed on target system.'.format(self.settings['FONT']))
+            raise ValueError('Specified console font not available on target system')
+        return(True)
+
+
+class Keyboard(object):
+    def __init__(self, chroot_base, keyboard_xml):
+        self.xml = keyboard_xml
+        self.chroot_base = chroot_base
+        self.settings = {}
+        if self.xml:
+            chk = {'KEYMAP': self.xml.find('map'),
+                   'KEYMAP_TOGGLE': self.xml.find('toggle')}
+            for setting, xml in chk.items():
+                if xml:
+                    self.settings[setting] = xml.text.strip()
+        _logger.debug('Rendered settings: {0}'.format(self.settings))
+
+    def verify(self):
+        kbdnames = []
+        for i in ('KEYMAP', 'KEYMAP_TOGGLE'):
+            if i in self.settings.keys():
+                kbdnames.append(self.settings[i])
+        if not kbdnames:
+            _logger.warning('Attempted to verify settings with no chosen keyboard map(s).')
+            return(None)
+        keymapdir = os.path.join(self.chroot_base, 'usr', 'share', 'kbd', 'keymaps')
+        kbdmaps = []
+        for root, dirs, files in os.walk(keymapdir, topdown = True):
+            if root.endswith('/include'):
+                dirs[:] = []
+                files[:] = []
+                continue
+            for f in files:
+                if f.endswith('.inc'):
+                    continue
+                kbdmaps.append(_kbd_re.sub('', f))
+        _logger.debug('Rendered list of supported keyboard maps on target system: {0}'.format(','.join(kbdmaps)))
+        for k in kbdnames:
+            if k not in kbdmaps:
+                _logger.error('Keyboard map {0} not installed on target system.'.format(k))
+                raise ValueError('Specified keyboard map not available on target system')
+        return(True)

aif/system/locales.py

@@ -1,11 +1,16 @@
 import configparser
 import copy
 import io
+import logging
 import os
 import re
 import shutil
 import subprocess
 
+
+_logger = logging.getLogger(__name__)
+
+
 # TODO: time
 _locale_re = re.compile(r'^(?!#\s|)$')
 _locale_def_re = re.compile(r'([^.]*)[^@]*(.*)')
@@ -31,6 +36,8 @@ class Locale(object):
                 self.userlocales.append(locale)
         if not self.userlocales:
             self.userlocales = ['en_US', 'en_US.UTF-8']
+        _logger.debug('Rendered locales: {0}'.format(dict(self._localevars['BASE'])))
+        _logger.debug('Rendered user locales: {0}'.format(','.join(self.userlocales)))
         return(None)
 
     def _verify(self):
@@ -46,10 +53,13 @@ class Locale(object):
             if locale in self.userlocales:
                 # "Uncomment" the locale (self.writeConf() actually writes the change)
                 self.rawlocales[idx] = '{0} {1}'.format(locale, charset)
+        _logger.debug('Rendered system locales: {0}'.format(self.syslocales))
         userl = set(self.userlocales)
         sysl = set(self.syslocales.keys())
+        missing_locales = (userl - sysl)
         if (userl - sysl):
-            raise ValueError('non-existent locale specified')
+            _logger.error('Specified locale(s) {0} that does not exist on the target system.'.format(missing_locales))
+            raise ValueError('Missing locale(s)')
         return(None)
 
     def writeConf(self):
@@ -62,7 +72,9 @@ class Locale(object):
             fh.write('# Generated by AIF-NG.\n\n')
             fh.write('\n'.join(self.rawlocales))
             fh.write('\n')
+        _logger.info('Wrote: {0}'.format(localegen))
         # If only the locale DB wasn't in a hopelessly binary format.
+        # These destinations are built by the below subprocess call.
         for root, dirs, files in os.walk(localedbdir):
             for f in files:
                 fpath = os.path.join(root, f)
@@ -70,7 +82,7 @@ class Locale(object):
             for d in dirs:
                 dpath = os.path.join(root, d)
                 shutil.rmtree(dpath)
-        # TODO: logging
+        _logger.debug('Pruned locale destination.')
         for locale in self.userlocales:
             lpath = os.path.join(localesrcdir, 'locales', locale)
             charset = self.syslocales[locale]
@@ -79,20 +91,32 @@ class Locale(object):
             else:
                 ldef_name = _locale_def_re.sub(r'\g<1>\g<2>', locale)
                 lpath = os.path.join(localesrcdir, 'locales', ldef_name)
-            env = copy.deepycopy(dict(os.environ))
+            env = copy.deepcopy(dict(os.environ))
             env['I18NPATH'] = localesrcdir
-            subprocess.run(['localedef',
+            _logger.debug('Invocation environment: {0}'.format(env))
-                            '--force',
+            cmd = subprocess.run(['localedef',
-                            # These are overridden by a prefix env var.
+                                  '--force',
-                            # '--inputfile={0}'.format(lpath),
+                                  # These are overridden by a prefix env var.
-                            # '--charmap={0}'.format(os.path.join(localesrcdir, 'charmaps', charset)),
+                                  # '--inputfile={0}'.format(lpath),
-                            '--inputfile={0}'.format(ldef_name),
+                                  # '--charmap={0}'.format(os.path.join(localesrcdir, 'charmaps', charset)),
-                            '--charmap={0}'.format(charset),
+                                  '--inputfile={0}'.format(ldef_name),
-                            '--alias-file={0}'.format(os.path.join(self.chroot_base,
+                                  '--charmap={0}'.format(charset),
-                                                                   'usr', 'share', 'locale', 'locale.alias')),
+                                  '--alias-file={0}'.format(os.path.join(self.chroot_base,
-                            '--prefix={0}'.format(self.chroot_base),
+                                                                         'usr', 'share', 'locale', 'locale.alias')),
-                            locale],
+                                  '--prefix={0}'.format(self.chroot_base),
-                           env = env)
+                                  locale],
+                                 stdout = subprocess.PIPE,
+                                 stderr = subprocess.PIPE,
+                                 env = env)
+            _logger.info('Executed: {0}'.format(' '.join(cmd.args)))
+            if cmd.returncode != 0:
+                _logger.warning('Command returned non-zero status')
+                _logger.debug('Exit status: {0}'.format(str(cmd.returncode)))
+                for a in ('stdout', 'stderr'):
+                    x = getattr(cmd, a)
+                    if x:
+                        _logger.debug('{0}: {1}'.format(a.upper(), x.decode('utf-8').strip()))
+                raise RuntimeError('Failed to render locales successfully')
         cfg = os.path.join(self.chroot_base, 'etc', 'locale.conf')
         # And now we write the variables.
         # We have to strip out the section from the ini.
@@ -106,6 +130,7 @@ class Locale(object):
                 fh.write(line)
         os.chmod(cfg, 0o0644)
         os.chown(cfg, 0, 0)
+        _logger.info('Wrote: {0}'.format(cfg))
         return(None)
 
 
@@ -118,6 +143,7 @@ class Timezone(object):
         tzfilebase = os.path.join('usr', 'share', 'zoneinfo', self.tz)
         tzfile = os.path.join(self.chroot_base, tzfilebase)
         if not os.path.isfile(tzfile):
+            _logger.error('Timezone {0} does not have a matching timezone file on target system.'.format(self.tz))
             raise ValueError('Invalid timezone')
         return(tzfilebase)
 
@@ -127,4 +153,5 @@ class Timezone(object):
         if os.path.isfile(tzdestfile):
             os.remove(tzdestfile)
         os.symlink(tzsrcfile, tzdestfile)
+        _logger.info('Created symlink: {0} => {1}'.format(tzsrcfile, tzdestfile))
         return(None)

aif/system/services.py

@@ -1,3 +1,4 @@
+import logging
 import os
 import pathlib
 import re
@@ -5,6 +6,9 @@ import re
 import aif.utils
 
 
+_logger = logging.getLogger(__name__)
+
+
 _svc_suffixes = ('service', 'socket', 'device', 'mount', 'automount', 'swap', 'target',
                  'path', 'timer', 'slice', 'scope')
 _svc_re = re.compile(r'\.({0})$'.format('|'.join(_svc_suffixes)))
@@ -34,6 +38,12 @@ class Service(object):
         else:
             self.unit_file = '{0}.{1}'.format(self.name, self.type)
             self.dest_file = self.unit_file
+        if self.slice:
+            _logger.info('Initialized service: {0}@{1}'.format(self.name, self.slice))
+        else:
+            _logger.info('Initialized service: {0}'.format(self.name))
+        for a in ('name', 'slice', 'type', 'enabled'):
+            _logger.debug('{0}: {1}'.format(a.title(), getattr(self, a)))
 
 
 class ServiceDB(object):
@@ -54,7 +64,11 @@ class ServiceDB(object):
             if svc.enabled:
                 if not os.path.isfile(dest_path):
                     os.symlink(src_path, dest_path)
+                    _logger.info('Created symlink: {0} => {1}'.format(src_path, dest_path))
+                _logger.debug('{0} enabled'.format(svc.name))
             else:
                 if os.path.exists(dest_path):
                     os.remove(dest_path)
+                    _logger.info('Removed file/symlink: {0}'.format(dest_path))
+                _logger.debug('{0} disabled'.format(svc.name))
         return(None)

aif/system/users.py

@@ -5,6 +5,7 @@
 # https://wiki.archlinux.org/index.php/users_and_groups#File_list
 
 import datetime
+import logging
 import os
 import re
 import shutil
@@ -17,6 +18,9 @@ import aif.utils
 import aif.constants_fallback
 
 
+_logger = logging.getLogger(__name__)
+
+
 _skipline_re = re.compile(r'^\s*(#|$)')
 _now = datetime.datetime.utcnow()
 _epoch = datetime.datetime.fromtimestamp(0)
@@ -46,11 +50,14 @@ class Group(object):
         else:
             if not self.password:
                 self.password = '!!'
+        _logger.info('Rendered G=group entry')
+        for a in ('name', 'gid', 'password', 'create'):
+            _logger.debug('{0}: {1}'.format(a.title(), getattr(self, a)))
 
     def genFileLine(self):
         if not self.gid:
-            raise RuntimeError(('Group objects must have a gid set before their '
+            _logger.error('Group objects must have a gid set before their group/gshadow entries can be generated')
-                                'group/gshadow entries can be generated'))
+            raise RuntimeError('Need GID')
         # group(5)
         self.group_entry = [self.name,  # Group name
                             'x',  # Password, normally, but we use shadow for this
@@ -61,6 +68,8 @@ class Group(object):
                               (self.password.hash if self.password.hash else '!!'),  # Password hash (if it has one)
                               ','.join(self.admins),  # Users with administrative control of group
                               ','.join(self.members)]  # Comma-separated members of group
+        _logger.debug('Rendered group entry: {0}'.format(self.group_entry))
+        _logger.debug('Rendered gshadow entry: {0}'.format(self.gshadow_entry))
         return(None)
 
     def parseGroupLine(self, line):
@@ -71,6 +80,9 @@ class Group(object):
             self.members = set(members)
         self.gid = int(groupdict['gid'])
         self.name = groupdict['name']
+        _logger.info('Parsed group line.')
+        for a in ('name', 'gid', 'members'):
+            _logger.debug('{0}: {1}'.format(a.title(), getattr(self, a)))
         return(None)
 
     def parseGshadowLine(self, line):
@@ -85,6 +97,9 @@ class Group(object):
             self.admins = set(admins)
         if members:
             self.members = set(members)
+        _logger.info('Parsed gshadow line.')
+        for a in ('password', 'admins', 'members'):
+            _logger.debug('{0}: {1}'.format(a.title(), getattr(self, a)))
         return(None)
 
 
@@ -132,6 +147,7 @@ class Password(object):
         if self.hash not in ('', None):
             self.hash_type = re.sub(r'_crypt$', '', self._pass_context.identify(self.hash))
             if not self.hash_type:
+                _logger.warning('Unable to detect hash type for string {0}'.format(self.hash))
                 warnings.warn('Could not determine hash type')
         return(None)
 
@@ -160,6 +176,7 @@ class User(object):
 
     def _initVals(self):
         if self.xml is None:
+            _logger.debug('Instantiated blank User object.')
             # We manually assign these.
             return(None)
         self.name = self.xml.attrib['name']
@@ -206,12 +223,14 @@ class User(object):
             g = Group(group_xml)
             g.members.add(self.name)
             self.groups.append(g)
+        _logger.info('User object for {0} instantiated.'.format(self.name))
         return(None)
 
     def genFileLine(self):
         if not all((self.uid, self.primary_group.gid)):
-            raise RuntimeError(('User objects must have a uid and primary_group.gid set before their '
+            _logger.error(('User objects must have a uid and primary_group.gid set before their passwd/shadow entries '
-                                'passwd/shadow entries can be generated'))
+                           'can be generated'))
+            raise RuntimeError('Need UID/primary_group.gid')
         # passwd(5)
         self.passwd_entry = [self.name,  # Username
                              'x',  # self.password.hash is not used because shadow, but this would be password
@@ -230,6 +249,20 @@ class User(object):
                              (str(self.inactive_period) if self.inactive_period else ''),  # Password inactivity period
                              (str((self.expire_date - _epoch).days) if self.expire_date else ''),  # Expiration date
                              '']  # "Reserved"
+        _logger.debug('Rendered passwd entry: {0}'.format(self.passwd_entry))
+        _logger.debug('Rendered shadow entry: {0}'.format(self.shadow_entry))
+        return(None)
+
+    def parsePasswdLine(self, line):
+        userdict = dict(zip(['name', 'password', 'uid', 'gid', 'comment', 'home', 'shell'],
+                            line.split(':')))
+        self.name = userdict['name']
+        self.primary_group = int(userdict['gid'])  # This gets transformed by UserDB() to the proper Group() obj
+        self.uid = int(userdict['uid'])
+        for k in ('home', 'shell'):
+            if userdict[k].strip() != '':
+                setattr(self, k, userdict[k])
+        _logger.debug('Parsed passwd entry: {0}'.format(userdict))
         return(None)
 
     def parseShadowLine(self, line):
@@ -249,19 +282,9 @@ class User(object):
             self.expire_date = None
         else:
             self.expire_date = datetime.datetime.fromtimestamp(shadowdict['expire_date'])
+        _logger.debug('Parsed shadow entry: {0}'.format(shadowdict))
         return(shadowdict)
 
-    def parsePasswdLine(self, line):
-        userdict = dict(zip(['name', 'password', 'uid', 'gid', 'comment', 'home', 'shell'],
-                            line.split(':')))
-        self.name = userdict['name']
-        self.primary_group = int(userdict['gid'])  # This gets transformed by UserDB() to the proper Group() obj
-        self.uid = int(userdict['uid'])
-        for k in ('home', 'shell'):
-            if userdict[k].strip() != '':
-                setattr(self, k, userdict[k])
-        return(None)
-
 
 class UserDB(object):
     def __init__(self, chroot_base, rootpass_xml, users_xml):
@@ -322,6 +345,7 @@ class UserDB(object):
             if k in self.login_defaults.keys():
                 v = self.login_defaults[k].lower()
                 self.login_defaults[k] = (True if v == 'yes' else False)
+        _logger.debug('Parsed login defaults config: {0}'.format(self.login_defaults))
         return(None)
 
     def _parseShadow(self):
@@ -371,7 +395,8 @@ class UserDB(object):
             u = User(user_xml)
             # TODO: system accounts?
             if u.name in [i.name for i in self.new_users]:
-                warnings.warn(('User {0} already specified; skipping').format(u.name))
+                _logger.warning('User {0} already specified; skipping to avoid duplicate conflicts.'.format(u.name))
+                warnings.warn('User already specified')
                 continue
             if not u.uid:
                 u.uid = self.getAvailUID()
@@ -431,42 +456,49 @@ class UserDB(object):
 
     def writeConf(self):
         # We shouldn't really use this, because root should be at the beginning.
-        users_by_name = sorted(self.new_users, key = lambda x: x.name)
+        users_by_name = sorted(self.new_users, key = lambda user: user.name)
         # This automatically puts root first (uid = 0)
-        users_by_uid = sorted(self.new_users, key = lambda x: x.uid)
+        users_by_uid = sorted(self.new_users, key = lambda user: user.uid)
         # Ditto.
-        groups_by_name = sorted(self.new_groups, key = lambda x: x.name)
+        groups_by_name = sorted(self.new_groups, key = lambda group: group.name)
-        groups_by_gid = sorted(self.new_groups, key = lambda x: x.gid)
+        groups_by_gid = sorted(self.new_groups, key = lambda group: group.gid)
         for x in (self.new_users, self.new_groups):
             for i in x:
                 i.genFileLine()
         for f in (self.passwd_file, self.shadow_file, self.group_file, self.gshadow_file):
             backup = '{0}-'.format(f)
             shutil.copy2(f, backup)
+            _logger.info('Wrote: {0}'.format(backup))
         with open(self.passwd_file, 'w') as fh:
             for u in users_by_uid:
                 fh.write(':'.join(u.passwd_entry))
                 fh.write('\n')
+        _logger.info('Wrote: {0}'.format(self.passwd_file))
         with open(self.shadow_file, 'w') as fh:
             for u in self.new_users:
                 fh.write(':'.join(u.shadow_entry))
                 fh.write('\n')
+        _logger.info('Wrote: {0}'.format(self.shadow_file))
         with open(self.group_file, 'w') as fh:
             for g in groups_by_gid:
                 fh.write(':'.join(g.group_entry))
                 fh.write('\n')
+        _logger.info('Wrote: {0}'.format(self.group_file))
         with open(self.gshadow_file, 'w') as fh:
             for g in self.new_users:
                 fh.write(':'.join(g.gshadow_entry))
                 fh.write('\n')
+        _logger.info('Wrote: {0}'.format(self.gshadow_file))
         for u in self.new_users:
             if u.new:
                 homedir = os.path.join(self.chroot_base, u.home)
                 # We only set perms for the homedir itself. It's up to the user to specify in a post script if this
                 # needs to be different.
                 if os.path.isdir(homedir):
-                    os.stat(homedir)
+                    stats = os.stat(homedir)
-                    # TODO: log original owner, permissions, etc.
+                    _logger.warning('Homedir {0} for user {1} already exists; original stat: {2}'.format(homedir,
+                                                                                                         u.name,
+                                                                                                         stats))
                 os.makedirs(homedir, exist_ok = True)
                 shutil.copytree(os.path.join(self.chroot_base, 'etc', 'skel'), homedir)
                 os.chown(homedir, u.uid, u.primary_group.gid)
@@ -490,4 +522,5 @@ class UserDB(object):
                                                            ('NOPASSWD: ' if not u.sudoPassword else '')))
             os.chown(sudo_file, 0, 0)
             os.chmod(sudo_file, 0o0440)
+            _logger.info('Wrote: {0}'.format(sudo_file))
         return(None)