diff --git a/aif/network/__init__.py b/aif/network/__init__.py index 0ab5345..c8af31c 100644 --- a/aif/network/__init__.py +++ b/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) diff --git a/aif/network/_common.py b/aif/network/_common.py index 19e7c9c..34275dc 100644 --- a/aif/network/_common.py +++ b/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('') - raise ValueError('ssid must be <= 32 characters') + _logger.error('SSID must be <= 32 characters long.') + 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() diff --git a/aif/system/__init__.py b/aif/system/__init__.py index 08b7c0b..8bfe6b1 100644 --- a/aif/system/__init__.py +++ b/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() diff --git a/aif/system/console.py b/aif/system/console.py index 8de1cf6..d707544 100644 --- a/aif/system/console.py +++ b/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) diff --git a/aif/system/locales.py b/aif/system/locales.py index 23abcfa..460e391 100644 --- a/aif/system/locales.py +++ b/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', - '--force', - # These are overridden by a prefix env var. - # '--inputfile={0}'.format(lpath), - # '--charmap={0}'.format(os.path.join(localesrcdir, 'charmaps', charset)), - '--inputfile={0}'.format(ldef_name), - '--charmap={0}'.format(charset), - '--alias-file={0}'.format(os.path.join(self.chroot_base, - 'usr', 'share', 'locale', 'locale.alias')), - '--prefix={0}'.format(self.chroot_base), - locale], - env = env) + _logger.debug('Invocation environment: {0}'.format(env)) + cmd = subprocess.run(['localedef', + '--force', + # These are overridden by a prefix env var. + # '--inputfile={0}'.format(lpath), + # '--charmap={0}'.format(os.path.join(localesrcdir, 'charmaps', charset)), + '--inputfile={0}'.format(ldef_name), + '--charmap={0}'.format(charset), + '--alias-file={0}'.format(os.path.join(self.chroot_base, + 'usr', 'share', 'locale', 'locale.alias')), + '--prefix={0}'.format(self.chroot_base), + 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) diff --git a/aif/system/services.py b/aif/system/services.py index 6f495ed..3fa7973 100644 --- a/aif/system/services.py +++ b/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) diff --git a/aif/system/users.py b/aif/system/users.py index 5849b7b..075e71a 100644 --- a/aif/system/users.py +++ b/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 ' - 'group/gshadow entries can be generated')) + _logger.error('Group objects must have a gid set before their 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 ' - 'passwd/shadow entries can be generated')) + _logger.error(('User objects must have a uid and primary_group.gid set before their passwd/shadow entries ' + '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_gid = sorted(self.new_groups, key = lambda x: x.gid) + groups_by_name = sorted(self.new_groups, key = lambda group: group.name) + 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) - # TODO: log original owner, permissions, etc. + stats = os.stat(homedir) + _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)