From 276041ba7d7333118aad72b32b5cc2583553de39 Mon Sep 17 00:00:00 2001 From: brent s Date: Sun, 10 May 2020 05:57:35 -0400 Subject: [PATCH] add logging --- utils/he_ipv6.py | 160 +++++++++++++++++++++++++++++++++++++++++------ 1 file changed, 140 insertions(+), 20 deletions(-) diff --git a/utils/he_ipv6.py b/utils/he_ipv6.py index b64c39a..e9101f2 100755 --- a/utils/he_ipv6.py +++ b/utils/he_ipv6.py @@ -3,12 +3,21 @@ import argparse import configparser import ipaddress +import logging +import logging.handlers import os import socket +import sys ## import requests import requests.auth from pyroute2 import IPRoute +try: + # https://www.freedesktop.org/software/systemd/python-systemd/journal.html#journalhandler-class + from systemd import journal + _has_journald = True +except ImportError: + _has_journald = False # TODO: add checking to see if we're already configured. @@ -19,6 +28,46 @@ from pyroute2 import IPRoute # https://gist.github.com/pklaus/960672 +logfile = '/var/log/tunnelbroker_manager.log' +# Prep the log file. +logfile = os.path.abspath(os.path.expanduser(logfile)) +os.makedirs(os.path.dirname(logfile), exist_ok = True, mode = 0o0700) +if not os.path.isfile(logfile): + with open(logfile, 'w') as fh: + fh.write('') +os.chmod(logfile, 0o0600) + +# And set up logging. +_cfg_args = {'handlers': [], + 'level': logging.DEBUG} +if _has_journald: + # There were some weird changes somewhere along the line. + try: + # But it's *probably* this one. + h = journal.JournalHandler() + except AttributeError: + h = journal.JournaldLogHandler() + # Systemd includes times, so we don't need to. + h.setFormatter(logging.Formatter(style = '{', + fmt = ('{name}:{levelname}:{name}:{filename}:' + '{funcName}:{lineno}: {message}'))) + _cfg_args['handlers'].append(h) +h = logging.handlers.RotatingFileHandler(logfile, + encoding = 'utf8', + # Disable rotating for now. + # maxBytes = 50000000000, + # backupCount = 30 + ) +h.setFormatter(logging.Formatter(style = '{', + fmt = ('{asctime}:' + '{levelname}:{name}:{filename}:' + '{funcName}:{lineno}: {message}'))) +_cfg_args['handlers'].append(h) +logging.basicConfig(**_cfg_args) +logger = logging.getLogger('HE Tunnelbroker Manager') +logger.info('Logging initialized.') + + class TunnelBroker(object): ipget_url = 'https://ipv4.clientinfo.square-r00t.net/' ipget_params = {'raw': '1'} @@ -33,83 +82,153 @@ class TunnelBroker(object): self.wan = wan_ip self.force_update = update self.conf_file = os.path.abspath(os.path.expanduser(conf)) + logger.debug('Using config path: {0}'.format(self.conf_file)) self._conf = configparser.ConfigParser(allow_no_value = True, interpolation = configparser.ExtendedInterpolation()) - self._conf.read(self.conf_file) + try: + self._conf.read(self.conf_file) + logger.debug('Read in configuration successfully.') + except Exception as e: + logger.error('Failed reading configuration: {0}'.format(e)) + raise e if len(self._conf.sections()) < 1: + logger.error('Config file has no sections/tunnels defined.') raise RuntimeError('Config file has no sections/tunnels defined') self.tun_id = tun_id if self.tun_id and self.tun_id not in self._conf.sections(): + logger.error(('The tun_id {0} is not a valid tunnel ID. ' + 'Valid tunnels are: {1}').format(self.tun_id, ', '.join(self._conf.sections()))) raise ValueError('tun_id not a valid tunnel ID') elif not self.tun_id: self.tun_id = self._conf.sections()[0] + logger.debug('Automatically set tun_id to {0}'.format(self.tun_id)) self.cfg = self._conf[self.tun_id] self.server = ipaddress.ip_address(self.cfg['server']) + logger.debug('Set server IP to {0}.'.format(str(self.server))) self.addrs = [ipaddress.ip_network(ip.strip()) for ip in self.cfg['allocations'].split(',')] + logger.debug('Using address allocations: {0}'.format(', '.join([str(ip) for ip in self.addrs]))) for k in ('user', 'update_key'): setattr(self, k, self.cfg[k]) + # Don't log creds, even in debug. + # logger.debug('Set {0} to {1}'.format(k, getattr(self, k))) + self.iface_name = 'he-{0}'.format(self.tun_id) def _get_my_ip(self): if self.wan: + logger.debug('WAN IP tunneling enabled; fetching WAN IP.') req = requests.get(self.ipget_url, params = self.ipget_params) if not req.ok: + logger.error('Could not fetch self IP. Request returned {0}.'.format(req.status_code)) raise RuntimeError('Could not fetch self IP') self.my_ip = ipaddress.ip_address(req.json()['ip']) + logger.debug('Set my_ip to {0}.'.format(str(self.my_ip))) else: + logger.debug('WAN IP tunneling disabled; fetching LAN IP.') if not self.ipr: self.ipr = IPRoute() _defrt = self.ipr.get_default_routes(family = socket.AF_INET) if len(_defrt) != 1: # This (probably) WILL fail on multipath systems. + logger.error('Could not determine default route. Does this machine have a single default route?') raise RuntimeError('Could not determine default IPv4 route') self.my_ip = ipaddress.ip_address(_defrt[0]['attrs']['RTA_PREFSRC']) + logger.debug('Set my_ip to {0}.'.format(str(self.my_ip))) return(None) def start(self): if self.force_update: + logger.debug('IP update forced; updating.') self._get_my_ip() self.update() if not self.ipr: self.ipr = IPRoute() - self.ipr.link('add', - ifname = 'he-{0}'.format(self.tun_id), - kind = 'sit', - sit_local = str(self.my_ip), - sit_remote = str(self.server), - sit_ttl = 255) - self.iface_idx = self.ipr.link_lookup(ifname = 'he-{0}'.format(self.tun_id))[0] - self.ipr.link('set', index = self.iface_idx, state = 'up', mtu = 1480) + try: + self.ipr.link('add', + ifname = self.iface_name, + kind = 'sit', + sit_local = str(self.my_ip), + sit_remote = str(self.server), + sit_ttl = 255) + logger.debug('Added link {0} successfully.'.format(self.iface_name)) + except Exception as e: + logger.error('Could not create link for link {0} ' + '(maybe it already exists?): {1}'.format(self.iface_name, e)) + raise e + try: + self.iface_idx = self.ipr.link_lookup(ifname = self.iface_name)[0] + logger.debug('Found link {0} at index {1}.'.format(self.iface_name, self.iface_idx)) + except Exception as e: + logger.error('Could not set iface_idx for iface name {0}: {1}'.format(self.iface_name, e)) + raise e + try: + self.ipr.link('set', index = self.iface_idx, state = 'up', mtu = 1480) + logger.debug('Set link {0} status to UP.'.format(self.iface_name)) + except Exception as e: + logger.error(('Could not bring up link for iface name {0} at index {1}: ' + '{2}').format(self.iface_name, self.iface_idx, e)) + raise e for a in self.addrs: - self.ipr.addr('add', - index = self.iface_idx, - address = str(a), - mask = a.prefixlen, - family = socket.AF_INET6) - self.ipr.route('add', dst = '::', mask = 0, oif = self.iface_idx, family = socket.AF_INET6) + try: + self.ipr.addr('add', + index = self.iface_idx, + address = str(a.network_address), + mask = a.prefixlen, + family = socket.AF_INET6) + logger.debug('Added address {0} to link {1}.'.format(str(a), self.iface_name)) + except Exception as e: + logger.error(('Could not add address {0} on link {1}: ' + '{2}').format(str(a), self.iface_name, e)) + raise e + try: + self.ipr.route('add', dst = '::', mask = 0, oif = self.iface_idx, family = socket.AF_INET6) + logger.debug('Added default route for link {0}.'.format(self.iface_name)) + except Exception as e: + logger.error(('Could not add default IPv6 route on link {0}: {1}').format(self.iface_name, e)) + raise e self.ipr.close() return(None) def stop(self): if not self.ipr: self.ipr = IPRoute() - self.iface_idx = self.ipr.link_lookup(ifname = 'he-{0}'.format(self.tun_id))[0] - self.ipr.link('set', index = self.iface_idx, state = 'down') - self.ipr.route('del', dst = '::', mask = 0, oif = self.iface_idx, family = socket.AF_INET6) - self.ipr.link('set', index = self.iface_idx, state = 'down') - self.ipr.link('del', index = self.iface_idx) + try: + self.iface_idx = self.ipr.link_lookup(ifname = self.iface_name)[0] + logger.debug('Found link {0} at index {1}.'.format(self.iface_name, self.iface_idx)) + except Exception as e: + logger.error('Could not set iface_idx for link {0}: {1}'.format(self.iface_name, e)) + raise e + try: + self.ipr.link('set', index = self.iface_idx, state = 'down') + except Exception as e: + logger.error('Could not bring down link {0}: {1} (continuing anyways)'.format(self.iface_name, e)) + try: + self.ipr.route('del', dst = '::', mask = 0, oif = self.iface_idx, family = socket.AF_INET6) + except Exception as e: + logger.error(('Could not remove default IPv6 route on link {0}: ' + '{1} (continuing anyways)').format(self.iface_name, e))1 + try: + self.ipr.link('del', index = self.iface_idx) + logger.debug('Deleted link {0}.'.format(self.iface_name)) + except Exception as e: + logger.error('Could not delete link {0}: {1}'.format(self.iface_name, e)) + raise e self.ipr.close() return(None) def update(self, oneshot = False): self._get_my_ip() auth_handler = requests.auth.HTTPBasicAuth(self.user, self.update_key) + logger.debug('Set auth handler.') + logger.debug('Requesting IP update at provider.') req = requests.get(self.api_base, params = {'hostname': self.tun_id, 'myip': self.my_ip}, auth = auth_handler) if not req.ok: + logger.error('Could not update IP at provider. Request returned {0}.'.format(req.status_code)) raise RuntimeError('Could not update client IP in tunnel') status = req.content.decode('utf-8').split()[0].strip() if status.lower() not in ('good', 'nochg'): + logger.error('Returned following failure message: {0}'.format(req.content.decode('utf-8'))) raise RuntimeError('Client IP update returned failure') if self.ipr and oneshot: self.ipr.close() @@ -150,6 +269,7 @@ def parseArgs(): def main(): args = parseArgs().parse_args() + logger.debug('Invoked with args: {0}'.format(vars(args))) tb = TunnelBroker(**vars(args)) if args.oper == 'start': tb.start()