logging to network providers

aif/disk/block_fallback.py

@@ -44,14 +44,16 @@ class Disk(object):
         if self.devpath == 'auto':
             self.devpath = '/dev/{0}'.format(blkinfo.BlkDiskInfo().get_disks()[0]['kname'])
         if not os.path.isfile(self.devpath):
-            raise ValueError('{0} does not exist; please specify an explicit device path'.format(self.devpath))
+            _logger.error('Disk {0} does not exist; please specify an explicit device path'.format(self.devpath))
+            raise ValueError('Disk not found')
         self.table_type = self.xml.attrib.get('diskFormat', 'gpt').lower()
         if self.table_type in ('bios', 'mbr', 'dos'):
             self.table_type = 'msdos'
         validlabels = parted.getLabels()
         if self.table_type not in validlabels:
-            raise ValueError(('Disk format {0} is not valid for this architecture;'
+            _logger.error(('Disk format ({0}) is not valid for this architecture;'
                            'must be one of: {1}'.format(self.table_type, ', '.join(list(validlabels)))))
+            raise ValueError('Invalid disk format')
         self.device = parted.getDevice(self.devpath)
         self.disk = parted.freshDisk(self.device, self.table_type)
         _logger.debug('Configured parted device for {0}.'.format(self.devpath))
@@ -152,9 +154,10 @@ class Partition(object):
             self.part_type = parted.PARTITION_NORMAL
         self.fs_type = self.xml.attrib['fsType'].lower()
         if self.fs_type not in aif.constants.PARTED_FSTYPES:
-            raise ValueError(('{0} is not a valid partition filesystem type; '
+            _logger.error(('{0} is not a valid partition filesystem type; must be one of: '
-                              'must be one of: {1}').format(self.xml.attrib['fsType'],
+                           '{1}').format(self.xml.attrib['fsType'],
                                          ', '.join(sorted(aif.constants.PARTED_FSTYPES))))
+            raise ValueError('Invalid partition filesystem type')
         self.disk = diskobj
         self.device = self.disk.device
         self.devpath = '{0}{1}'.format(self.device.path, self.partnum)

aif/disk/mdadm_fallback.py

@@ -92,9 +92,8 @@ class Member(object):
             elif k == 'unused_space':
                 r = _mdblock_unused_re.search(v)
                 if not r:
-                    raise ValueError(('Could not parse {0} for '
+                    _logger.error('Could not parse {0} for {1}\'s superblock'.format(orig_k, self.devpath))
-                                      '{1}\'s superblock').format(orig_k,
+                    raise RuntimeError('Could not parse unused space in superblock')
-                                                                  self.devpath))
                 v = {}
                 for i in ('before', 'after'):
                     v[i] = int(r.group(i))  # in sectors
@@ -102,9 +101,8 @@ class Member(object):
                 k = 'badblock_log_entries'
                 r = _mdblock_badblock_re.search(v)
                 if not r:
-                    raise ValueError(('Could not parse {0} for '
+                    _logger.error('Could not parse {0} for {1}\'s superblock'.format(orig_k, self.devpath))
-                                      '{1}\'s superblock').format(orig_k,
+                    raise RuntimeError('Could not parse badblocks in superblock')
-                                                                  self.devpath))
                 v = {}
                 for i in ('entries', 'offset'):
                     v[i] = int(r.group(i)) # offset is in sectors
@@ -118,9 +116,8 @@ class Member(object):
             elif re.search(r'^((avail|used)_dev|array)_size$', k):
                 r = _mdblock_size_re.search(v)
                 if not r:
-                    raise ValueError(('Could not parse {0} for '
+                    _logger.error('Could not parse {0} for {1}\'s superblock'.format(orig_k, self.devpath))
-                                      '{1}\'s superblock').format(orig_k,
+                    raise RuntimeError('Could not parse size value in superblock')
-                                                                  self.devpath))
                 v = {}
                 for i in ('sectors', 'GB', 'GiB'):
                     v[i] = float(r.group(i))
@@ -204,7 +201,7 @@ class Array(object):
     def addMember(self, memberobj):
         if not isinstance(memberobj, Member):
             _logger.error('memberobj must be of type aif.disk.mdadm.Member')
-            raise ValueError('Invalid memberobj type')
+            raise TypeError('Invalid memberobj type')
         memberobj.prepare()
         self.members.append(memberobj)
         return(None)

aif/network/__init__.py

@@ -1,5 +1,8 @@
+import logging
 import os
 ##
+from lxml import etree
+##
 from . import _common
 from . import netctl
 from . import networkd
@@ -21,11 +24,16 @@ from . import networkmanager
 #     from . import networkd_fallback as networkd
 
 
+_logger = logging.getLogger(__name__)
+
+
 class Net(object):
     def __init__(self, chroot_base, network_xml):
         self.xml = network_xml
+        # We don't bother logging the entirety of network_xml here because we do it in the respective networks
         self.chroot_base = chroot_base
         self.hostname = self.xml.attrib['hostname'].strip()
+        _logger.info('Hostname: {0}'.format(self.hostname))
         self.provider = self.xml.attrib.get('provider', 'networkd').strip()
         if self.provider == 'netctl':
             self.provider = netctl
@@ -46,6 +54,7 @@ class Net(object):
             elif e.tag == 'wireless':
                 conn = self.provider.Wireless(e)
             self.connections.append(conn)
+            _logger.info('Added connection of type {0}.'.format(type(conn).__name__))
 
     def apply(self, chroot_base):
         cfg = os.path.join(chroot_base, 'etc', 'hostname')

aif/network/_common.py

@@ -1,9 +1,11 @@
 import binascii
 import ipaddress
+import logging
 import os
 import pathlib
 import re
 ##
+from lxml import etree
 from passlib.crypto.digest import pbkdf2_hmac
 from pyroute2 import IPDB
 ##
@@ -15,8 +17,10 @@ import aif.utils
 # from gi.repository import GObject, NM, GLib
 
 
+_logger = logging.getLogger('net:_common')
+
+
 def canonizeEUI(phyaddr):
-    # The easy transformations first.
     phyaddr = re.sub(r'[.:-]', '', phyaddr.upper().strip())
     eui = ':'.join(['{0}'.format(phyaddr[i:i+2]) for i in range(0, 12, 2)])
     return(eui)
@@ -33,6 +37,7 @@ def convertIpTuples(addr_xmlobj):
     else:
         components = addr_xmlobj.text.strip().split('/')
         if len(components) > 2:
+            _logger.error('Too many slashes in IP/CIDR string.')
             raise ValueError('Invalid IP/CIDR format: {0}'.format(addr_xmlobj.text))
         if len(components) == 1:
             addr = ipaddress.ip_address(components[0])
@@ -45,6 +50,8 @@ def convertIpTuples(addr_xmlobj):
         try:
             gw = ipaddress.ip_address(addr_xmlobj.attrib.get('gateway').strip())
         except (ValueError, AttributeError):
+            _logger.warning(('Non-conformant gateway value (attempting automatic gateway address): '
+                             '{0}').format(addr_xmlobj.attrib.get('gateway')))
             gw = next(net.hosts())
     return((addr, net, gw))
 
@@ -53,20 +60,24 @@ def convertPSK(ssid, passphrase):
     try:
         passphrase = passphrase.encode('utf-8').decode('ascii').strip('\r').strip('\n')
     except UnicodeDecodeError:
-        raise ValueError('passphrase must be an ASCII string')
+        _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')
     if not 7 < len(passphrase) < 64:
         raise ValueError('passphrase must be >= 8 and <= 32 characters')
     raw_psk = pbkdf2_hmac('sha1', str(passphrase), str(ssid), 4096, 32)
     hex_psk = binascii.hexlify(raw_psk)
     str_psk = hex_psk.decode('utf-8')
+    _logger.debug('Converted ({0}){1} to {2}'.format(str(passphrase), str(ssid), str_psk))
     return(str_psk)
 
 
 def convertWifiCrypto(crypto_xmlobj, ssid):
     crypto = {'type': crypto_xmlobj.find('type').text.strip(),
               'auth': {}}
+    _logger.info('Parsing a WiFi crypto object.')
     creds_xml = crypto_xmlobj.xpath('psk|enterprise')[0]
     # if crypto['type'] in ('wpa', 'wpa2', 'wpa3'):
     if crypto['type'] in ('wpa', 'wpa2'):
@@ -88,6 +99,7 @@ def convertWifiCrypto(crypto_xmlobj, ssid):
     # TODO: enterprise support
     # elif crypto['mode'] == 'enterprise':
     #     pass
+    _logger.debug('Rendered crypto settings: {0}'.format(crypto))
     return(crypto)
 
 
@@ -100,7 +112,8 @@ def getDefIface(ifacetype):
     elif ifacetype == 'wireless':
         prefix = 'wl'
     else:
-        raise ValueError('ifacetype must be one of "ethernet" or "wireless"')
+        _logger.error('ifacetype must be one of "ethernet" or "wireless"')
+        raise ValueError('Invalid iface type')
     ifname = None
     with IPDB() as ipdb:
         for iface in ipdb.interfaces.keys():
@@ -108,6 +121,7 @@ def getDefIface(ifacetype):
                 ifname = iface
                 break
     if not ifname:
+        _logger.warning('Unable to find default interface')
         return(None)
     return(ifname)
 
@@ -125,13 +139,16 @@ def isNotPersistent(chroot_base = '/'):
         return(True)
     cmds = aif.utils.kernelCmdline(chroot_base)
     if 'net.ifnames' in cmds.keys() and cmds['net.ifnames'] == '0':
+        _logger.debug('System network interfaces are not persistent')
         return(True)
+    _logger.debug('System network interfaces are persistent')
     return(False)
 
 
 class BaseConnection(object):
     def __init__(self, iface_xml):
         self.xml = iface_xml
+        _logger.debug('iface_xml: {0}'.format(etree.tostring(self.xml, with_tail = False).decode('utf-8')))
         self.id = self.xml.attrib['id'].strip()
         self.device = self.xml.attrib['device'].strip()
         self.is_defroute = aif.utils.xmlBool(self.xml.attrib.get('defroute', 'false').strip())
@@ -197,6 +214,7 @@ class BaseConnection(object):
         self._initAddrs()
         self._initResolvers()
         self._initRoutes()
+        _logger.info('Instantiated network provider {0}'.format(type(self).__name__))
 
     def _initAddrs(self):
         for addrtype in ('ipv4', 'ipv6'):

aif/network/netctl.py

@@ -1,11 +1,15 @@
 import configparser
 import io
+import logging
 import os
 ##
 import aif.utils
 from . import _common
 
 
+_logger = logging.getLogger(__name__)
+
+
 class Connection(_common.BaseConnection):
     def __init__(self, iface_xml):
         super().__init__(iface_xml)
@@ -28,6 +32,7 @@ class Connection(_common.BaseConnection):
         self.desc = None
 
     def _initCfg(self):
+        _logger.info('Building config.')
         if self.device == 'auto':
             self.device = _common.getDefIface(self.connection_type)
         self.desc = ('A {0} profile for {1} (generated by AIF-NG)').format(self.connection_type,
@@ -76,6 +81,7 @@ class Connection(_common.BaseConnection):
             elif self.addrs[addrtype]:
                 if 'IPCustom' not in self._cfg['BASE']:
                     # TODO: do this more cleanly somehow? Might conflict with other changes earlier/later.
+                    #       Could I shlex it?
                     # Weird hack because netctl doesn't natively support assigning add'l addrs to
                     # a dhcp/dhcp6/slaac iface.
                     self._cfg['BASE']['IPCustom'] = []
@@ -105,6 +111,9 @@ class Connection(_common.BaseConnection):
         # Weird hack because netctl doesn't natively support assigning add'l addrs to a dhcp/dhcp6/slaac iface.
         if 'IPCustom' in self._cfg['BASE'].keys() and isinstance(self._cfg['BASE']['IPCustom'], list):
             self._cfg['BASE']['IPCustom'] = '({0})'.format(' '.join(self._cfg['BASE']['IPCustom']))
+        _logger.info('Config built successfully.')
+        # TODO: does this render correctly?
+        _logger.debug('Config: {0}'.format(dict(self._cfg['BASE'])))
         return(None)
 
     def writeConf(self, chroot_base):
@@ -128,6 +137,7 @@ class Connection(_common.BaseConnection):
                                'After': 'sys-subsystem-net-devices-{0}.device'.format(self.device)}
         with open(systemd_file, 'w') as fh:
             systemd_cfg.write(fh, space_around_delimiters = False)
+        _logger.info('Wrote systemd unit: {0}'.format(systemd_file))
         # This is where it gets... weird.
         # Gross hacky workarounds because netctl, while great for simple setups, sucks for complex/advanced ones.
         no_auto = not all((self.auto['resolvers']['ipv4'],
@@ -200,7 +210,7 @@ class Connection(_common.BaseConnection):
                         'ipv4': tuple(),
                         'ipv6': tuple()}}}
             # This ONLY works for DHCPv6 on the IPv6 side. Not SLAAC. Netctl doesn't use a dhcp client for
-            # SLAAC.
+            # SLAAC, just iproute2. :|
             # x = routers, addresses, resolvers
             # t = ipv4/ipv6 dicts
             # i = ipv4/ipv6 key
@@ -249,6 +259,7 @@ class Connection(_common.BaseConnection):
                 fh.write('\n')
             os.chmod(custom_cfg, 0o0644)
             os.chown(custom_cfg, 0, 0)
+        _logger.info('Wrote: {0}'.format(custom_cfg))
         # And we have to strip out the section from the ini.
         cfgbuf = io.StringIO()
         self._cfg.write(cfgbuf, space_around_delimiters = False)
@@ -260,6 +271,7 @@ class Connection(_common.BaseConnection):
                 fh.write(line)
         os.chmod(netctl_file, 0o0600)
         os.chown(netctl_file, 0, 0)
+        _logger.info('Wrote: {0}'.format(netctl_file))
         return(None)
 
 

aif/network/networkd.py

@@ -1,3 +1,4 @@
+import logging
 import os
 ##
 # We have to use Jinja2 because while there are ways to *parse* an INI with duplicate keys
@@ -9,6 +10,9 @@ import aif.utils
 from . import _common
 
 
+_logger = logging.getLogger(__name__)
+
+
 class Connection(_common.BaseConnection):
     def __init__(self, iface_xml):
         super().__init__(iface_xml)
@@ -35,6 +39,7 @@ class Connection(_common.BaseConnection):
         self._initJ2()
 
     def _initCfg(self):
+        _logger.info('Building config.')
         if self.device == 'auto':
             self.device = _common.getDefIface(self.connection_type)
         self._cfg = {'Match': {'Name': self.device},
@@ -90,9 +95,11 @@ class Connection(_common.BaseConnection):
             if 'IPv6AcceptRA' not in self._cfg.keys():
                 self._cfg['IPv6AcceptRA'] = {'UseDNS': ('true' if self.auto['resolvers']['ipv6'] else 'false')}
         self._initConnCfg()
+        _logger.info('Config built successfully.')
         return(None)
 
     def _initJ2(self):
+        _logger.debug('Fetching template from networkd.conf.j2')
         self.j2_env = jinja2.Environment(loader = jinja2.FileSystemLoader(searchpath = './'))
         self.j2_env.filters.update(aif.utils.j2_filters)
         self.j2_tpl = self.j2_env.get_template('networkd.conf.j2')
@@ -109,6 +116,9 @@ class Connection(_common.BaseConnection):
         os.chmod(cfgfile, 0o0644)
         os.chown(cfgfile, 0, 0)
         self._writeConnCfg(chroot_base)
+        _logger.info('Wrote: {0}'.format(cfgfile))
+        _logger.debug('Rendering variables: {0}'.format(self._cfg))
+        _logger.debug('Rendered template: {0}'.format(self.j2_tpl.render(cfg = self._cfg)))
         return(None)
 
 
@@ -149,6 +159,7 @@ class Wireless(Connection):
                 self._wpasupp['psk'] = crypto['auth']['psk']
         else:
             self._wpasupp['key_mgmt'] = 'NONE'
+        _logger.debug('Fetching template from wpa_supplicant.conf.j2')
         self.wpasupp_tpl = self.j2_env.get_template('wpa_supplicant.conf.j2')
         self.services[('/usr/lib/systemd/system/wpa_supplicant@.service')] = ('etc/systemd/'
                                                                               'system/'
@@ -167,4 +178,7 @@ class Wireless(Connection):
             fh.write(self.wpasupp_tpl.render(wpa = self._wpasupp))
         os.chown(cfgfile, 0, 0)
         os.chmod(cfgfile, 0o0640)
+        _logger.info('Wrote: {0}'.format(cfgfile))
+        _logger.debug('Rendering variables: {0}'.format(self._wpasupp))
+        _logger.debug('Rendered template: {0}'.format(self.wpasupp_tpl.render(wpa = self._wpasupp)))
         return(None)

aif/network/networkmanager.py

@@ -1,12 +1,15 @@
 import configparser
 import datetime
+import logging
 import os
 import uuid
 ##
-import aif.utils
 from . import _common
 
 
+_logger = logging.getLogger(__name__)
+
+
 class Connection(_common.BaseConnection):
     def __init__(self, iface_xml):
         super().__init__(iface_xml)
@@ -26,6 +29,7 @@ class Connection(_common.BaseConnection):
         self.uuid = uuid.uuid4()
 
     def _initCfg(self):
+        _logger.info('Building config.')
         if self.device == 'auto':
             self.device = _common.getDefIface(self.connection_type)
         self._cfg = configparser.ConfigParser()
@@ -89,6 +93,13 @@ class Connection(_common.BaseConnection):
                                                                                         str(net.prefixlen),
                                                                                         str(gw))
         self._initConnCfg()
+        _logger.info('Config built successfully.')
+        # TODO: does this render correctly?
+        # This is only for debug logging.
+        _logout = {}
+        for s in self._cfg.sections():
+            _logout[s] = dict(self._cfg[s])
+        _logger.debug('Config: {0}'.format(_logout))
         return(None)
 
     def writeConf(self, chroot_base):
@@ -109,6 +120,7 @@ class Connection(_common.BaseConnection):
         os.chmod(cfgroot, 0o0755)
         os.chmod(cfgdir, 0o0700)
         os.chmod(cfgpath, 0o0600)
+        _logger.info('Wrote: {0}'.format(cfgpath))
         return(None)
 
 

aif/utils/sources.py

@@ -187,7 +187,7 @@ class Downloader(object):
                 dl.data.seek(0, 0)
             if not fnargs['keys']:
                 _logger.debug('Found no keys in keys_xml')
-                raise ValueError('Could not find any keys')
+                raise RuntimeError('Could not find any keys')
         if sigs_xml is not None:
             for sig_text_xml in sigs_xml.findall('signature'):
                 _logger.debug('Found <signature>')