chiark / gitweb /
wip debug
[hippotat.git] / hippotat / __init__.py
index ee844cd53faa83b09602c3231043b2d9fb588861..0b059e59e2384d0b20cf388ec17887198e66c8ae 100644 (file)
 # -*- python -*-
 
-import hippotat.slip as slip
+import signal
+signal.signal(signal.SIGINT, signal.SIG_DFL)
+
+import sys
+
+from zope.interface import implementer
+
+import twisted
+from twisted.internet import reactor
+import twisted.internet.endpoints
+import twisted.logger
+from twisted.logger import LogLevel
+import twisted.python.constants
+from twisted.python.constants import NamedConstant
 
 import ipaddress
 from ipaddress import AddressValueError
 
+from optparse import OptionParser
+from configparser import ConfigParser
+from configparser import NoOptionError
+
+from functools import partial
+
+import collections
+import time
+import codecs
+import traceback
+
+import re as regexp
+
+import hippotat.slip as slip
+
+class DBG(twisted.python.constants.Names):
+  INIT = NamedConstant()
+  ROUTE = NamedConstant()
+  DROP = NamedConstant()
+  FLOW = NamedConstant()
+  HTTP = NamedConstant()
+  TWISTED = NamedConstant()
+  QUEUE = NamedConstant()
+  HTTP_CTRL = NamedConstant()
+  QUEUE_CTRL = NamedConstant()
+  HTTP_FULL = NamedConstant()
+  CTRL_DUMP = NamedConstant()
+  SLIP_FULL = NamedConstant()
+  DATA_COMPLETE = NamedConstant()
+
+_hex_codec = codecs.getencoder('hex_codec')
+
+#---------- logging ----------
+
+org_stderr = sys.stderr
+
+log = twisted.logger.Logger()
+
+debug_set = set()
+debug_def_detail = DBG.HTTP
+
+def log_debug(dflag, msg, idof=None, d=None):
+  if dflag not in debug_set: return
+  #print('---------------->',repr((dflag, msg, idof, d)), file=sys.stderr)
+  if idof is not None:
+    msg = '[%#x] %s' % (id(idof), msg)
+  if d is not None:
+    trunc = ''
+    if not DBG.DATA_COMPLETE in debug_set:
+      if len(d) > 64:
+        d = d[0:64]
+        trunc = '...'
+    d = _hex_codec(d)[0].decode('ascii')
+    msg += ' ' + d + trunc
+  log.info('{dflag} {msgcore}', dflag=dflag, msgcore=msg)
+
+@implementer(twisted.logger.ILogFilterPredicate)
+class LogNotBoringTwisted:
+  def __call__(self, event):
+    yes = twisted.logger.PredicateResult.yes
+    no  = twisted.logger.PredicateResult.no
+    try:
+      if event.get('log_level') != LogLevel.info:
+        return yes
+      dflag = event.get('dflag')
+      if dflag                         in debug_set: return yes
+      if dflag is None and DBG.TWISTED in debug_set: return yes
+      return no
+    except Exception:
+      print(traceback.format_exc(), file=org_stderr)
+      return yes
+
+#---------- default config ----------
+
+defcfg = '''
+[DEFAULT]
+#[<client>] overrides
+max_batch_down = 65536           # used by server, subject to [limits]
+max_queue_time = 10              # used by server, subject to [limits]
+target_requests_outstanding = 3  # must match; subject to [limits] on server
+http_timeout = 30                # used by both } must be
+http_timeout_grace = 5           # used by both }  compatible
+max_requests_outstanding = 4     # used by client
+max_batch_up = 4000              # used by client
+http_retry = 5                   # used by client
+
+#[server] or [<client>] overrides
+ipif = userv root ipif %(local)s,%(peer)s,%(mtu)s,slip %(rnets)s
+# extra interpolations:  %(local)s        %(peer)s          %(rnet)s
+#  obtained   on server  [virtual]server  [virtual]relay    [virtual]network
+#      from   on client  <client>         [virtual]server   [virtual]routes
+
+[virtual]
+mtu = 1500
+routes = ''
+# network = <prefix>/<len>  # mandatory for server
+# server  = <ipaddr>   # used by both, default is computed from `network'
+# relay   = <ipaddr>   # used by server, default from `network' and `server'
+#  default server is first host in network
+#  default relay is first host which is not server
+
+[server]
+# addrs = 127.0.0.1 ::1    # mandatory for server
+port = 80                  # used by server
+# url              # used by client; default from first `addrs' and `port'
+
+# [<client-ip4-or-ipv6-address>]
+# password = <password>    # used by both, must match
+
+[limits]
+max_batch_down = 262144           # used by server
+max_queue_time = 121              # used by server
+http_timeout = 121                # used by server
+target_requests_outstanding = 10  # used by server
+'''
+
+# these need to be defined here so that they can be imported by import *
+cfg = ConfigParser()
+optparser = OptionParser()
+
+_mimetrans = bytes.maketrans(b'-'+slip.esc, slip.esc+b'-')
+def mime_translate(s):
+  # SLIP-encoded packets cannot contain ESC ESC.
+  # Swap `-' and ESC.  The result cannot contain `--'
+  return s.translate(_mimetrans)
+
+class ConfigResults:
+  def __init__(self, d = { }):
+    self.__dict__ = d
+  def __repr__(self):
+    return 'ConfigResults('+repr(self.__dict__)+')'
+
+c = ConfigResults()
+
+def log_discard(packet, iface, saddr, daddr, why):
+  log_debug(DBG.DROP,
+            'discarded packet [%s] %s -> %s: %s' % (iface, saddr, daddr, why),
+            d=packet)
+
 #---------- packet parsing ----------
 
 def packet_addrs(packet):
@@ -38,3 +190,294 @@ def ipnetwork(input):
   except NetworkValueError:
     r = ipaddress.IPv6Network(input)
   return r
+
+#---------- ipif (SLIP) subprocess ----------
+
+class SlipStreamDecoder():
+  def __init__(self, desc, on_packet):
+    self._buffer = b''
+    self._on_packet = on_packet
+    self._desc = desc
+    self._log('__init__')
+
+  def _log(self, msg, **kwargs):
+    log_debug(DBG.SLIP_FULL, 'slip %s: %s' % (self._desc, msg), **kwargs)
+
+  def inputdata(self, data):
+    self._log('inputdata', d=data)
+    packets = slip.decode(data)
+    packets[0] = self._buffer + packets[0]
+    self._buffer = packets.pop()
+    for packet in packets:
+      self._maybe_packet(packet)
+    self._log('bufremain', d=self._buffer)
+
+  def _maybe_packet(self, packet):
+    self._log('maybepacket', d=packet)
+    if len(packet):
+      self._on_packet(packet)
+
+  def flush(self):
+    self._log('flush')
+    self._maybe_packet(self._buffer)
+    self._buffer = b''
+
+class _IpifProcessProtocol(twisted.internet.protocol.ProcessProtocol):
+  def __init__(self, router):
+    self._router = router
+    self._decoder = SlipStreamDecoder('ipif', self.slip_on_packet)
+  def connectionMade(self): pass
+  def outReceived(self, data):
+    self._decoder.inputdata(data)
+  def slip_on_packet(self, packet):
+    (saddr, daddr) = packet_addrs(packet)
+    if saddr.is_link_local or daddr.is_link_local:
+      log_discard(packet, 'ipif', saddr, daddr, 'link-local')
+      return
+    self._router(packet, saddr, daddr)
+  def processEnded(self, status):
+    status.raiseException()
+
+def start_ipif(command, router):
+  global ipif
+  ipif = _IpifProcessProtocol(router)
+  reactor.spawnProcess(ipif,
+                       '/bin/sh',['sh','-xc', command],
+                       childFDs={0:'w', 1:'r', 2:2},
+                       env=None)
+
+def queue_inbound(packet):
+  log_debug(DBG.FLOW, "queue_inbound", d=packet)
+  ipif.transport.write(slip.delimiter)
+  ipif.transport.write(slip.encode(packet))
+  ipif.transport.write(slip.delimiter)
+
+#---------- packet queue ----------
+
+class PacketQueue():
+  def __init__(self, desc, max_queue_time):
+    self._desc = desc
+    assert(desc + '')
+    self._max_queue_time = max_queue_time
+    self._pq = collections.deque() # packets
+
+  def _log(self, dflag, msg, **kwargs):
+    log_debug(dflag, self._desc+' pq: '+msg, **kwargs)
+
+  def append(self, packet):
+    self._log(DBG.QUEUE, 'append', d=packet)
+    self._pq.append((time.monotonic(), packet))
+
+  def nonempty(self):
+    self._log(DBG.QUEUE, 'nonempty ?')
+    while True:
+      try: (queuetime, packet) = self._pq[0]
+      except IndexError:
+        self._log(DBG.QUEUE, 'nonempty ? empty.')
+        return False
+
+      age = time.monotonic() - queuetime
+      if age > self._max_queue_time:
+        # strip old packets off the front
+        self._log(DBG.QUEUE, 'dropping (old)', d=packet)
+        self._pq.popleft()
+        continue
+
+      self._log(DBG.QUEUE, 'nonempty ? nonempty.')
+      return True
+
+  def process(self, sizequery, moredata, max_batch):
+    # sizequery() should return size of batch so far
+    # moredata(s) should add s to batch
+    self._log(DBG.QUEUE, 'process...')
+    while True:
+      try: (dummy, packet) = self._pq[0]
+      except IndexError:
+        self._log(DBG.QUEUE, 'process... empty')
+        break
+
+      self._log(DBG.QUEUE_CTRL, 'process... packet', d=packet)
+
+      encoded = slip.encode(packet)
+      sofar = sizequery()  
+
+      self._log(DBG.QUEUE_CTRL,
+                'process... (sofar=%d, max=%d) encoded' % (sofar, max_batch),
+                d=encoded)
+
+      if sofar > 0:
+        if sofar + len(slip.delimiter) + len(encoded) > max_batch:
+          self._log(DBG.QUEUE_CTRL, 'process... overflow')
+          break
+        moredata(slip.delimiter)
+
+      moredata(encoded)
+      self._pq.popleft()
+
+#---------- error handling ----------
+
+_crashing = False
+
+def crash(err):
+  global _crashing
+  _crashing = True
+  print('========== CRASH ==========', err,
+        '===========================', file=sys.stderr)
+  try: reactor.stop()
+  except twisted.internet.error.ReactorNotRunning: pass
+
+def crash_on_defer(defer):
+  defer.addErrback(lambda err: crash(err))
+
+def crash_on_critical(event):
+  if event.get('log_level') >= LogLevel.critical:
+    crash(twisted.logger.formatEvent(event))
+
+#---------- config processing ----------
+
+def process_cfg_common_always():
+  global mtu
+  c.mtu = cfg.get('virtual','mtu')
+
+def process_cfg_ipif(section, varmap):
+  for d, s in varmap:
+    try: v = getattr(c, s)
+    except AttributeError: continue
+    setattr(c, d, v)
+
+  #print(repr(c))
+
+  c.ipif_command = cfg.get(section,'ipif', vars=c.__dict__)
+
+def process_cfg_network():
+  c.network = ipnetwork(cfg.get('virtual','network'))
+  if c.network.num_addresses < 3 + 2:
+    raise ValueError('network needs at least 2^3 addresses')
+
+def process_cfg_server():
+  try:
+    c.server = cfg.get('virtual','server')
+  except NoOptionError:
+    process_cfg_network()
+    c.server = next(c.network.hosts())
+
+class ServerAddr():
+  def __init__(self, port, addrspec):
+    self.port = port
+    # also self.addr
+    try:
+      self.addr = ipaddress.IPv4Address(addrspec)
+      self._endpointfactory = twisted.internet.endpoints.TCP4ServerEndpoint
+      self._inurl = b'%s'
+    except AddressValueError:
+      self.addr = ipaddress.IPv6Address(addrspec)
+      self._endpointfactory = twisted.internet.endpoints.TCP6ServerEndpoint
+      self._inurl = b'[%s]'
+  def make_endpoint(self):
+    return self._endpointfactory(reactor, self.port, self.addr)
+  def url(self):
+    url = b'http://' + (self._inurl % str(self.addr).encode('ascii'))
+    if self.port != 80: url += b':%d' % self.port
+    url += b'/'
+    return url
+    
+def process_cfg_saddrs():
+  try: port = cfg.getint('server','port')
+  except NoOptionError: port = 80
+
+  c.saddrs = [ ]
+  for addrspec in cfg.get('server','addrs').split():
+    sa = ServerAddr(port, addrspec)
+    c.saddrs.append(sa)
+
+def process_cfg_clients(constructor):
+  c.clients = [ ]
+  for cs in cfg.sections():
+    if not (':' in cs or '.' in cs): continue
+    ci = ipaddr(cs)
+    pw = cfg.get(cs, 'password')
+    pw = pw.encode('utf-8')
+    constructor(ci,cs,pw)
+
+#---------- startup ----------
+
+def common_startup():
+  optparser.add_option('-c', '--config', dest='configfile',
+                       default='/etc/hippotat/config')
+
+  def dfs_less_detailed(dl):
+    return [df for df in DBG.iterconstants() if df <= dl]
+
+  def ds_default(od,os,dl,op):
+    global debug_set
+    debug_set = set(dfs_less_detailed(debug_def_detail))
+
+  def ds_select(od,os, spec, op):
+    last_df = next(DBG.iterconstants())
+    mutator = debug_set.add
+
+    for it in spec.split(','):
+
+      if not len(it):
+        for df in dfs_less_detailed(last_df):
+          mutator(df)
+        continue
+
+      if it.startswith('-'):
+        mutator = debug_set.discard
+        it = it[1:]
+      else:
+        mutator = debug_set.add
+        
+      try:
+        df = DBG.lookupByName(it)
+      except ValueError:
+        optparser.error('unknown debug flag %s in --debug-select' % it)
+      mutator(df)
+      last_df = df
+
+  optparser.add_option('-D', '--debug',
+                       nargs=0,
+                       action='callback',
+                       help='enable default debug (to stdout)',
+                       callback= ds_default)
+
+  optparser.add_option('--debug-select',
+                       nargs=1,
+                       type='string',
+                       metavar='[-]DFLAG[,],...',
+                       help=
+'''enable (or with -, disable) each specified DFLAG;
+empty entry means do the same for all DFLAGS "more interesting"
+than the last (or, all DFLAGs)''',
+                       action='callback',
+                       callback= ds_select)
+
+  (opts, args) = optparser.parse_args()
+  if len(args): optparser.error('no non-option arguments please')
+
+  print(repr(debug_set), file=sys.stderr)
+
+  re = regexp.compile('#.*')
+  cfg.read_string(re.sub('', defcfg))
+  cfg.read(opts.configfile)
+
+  log_formatter = twisted.logger.formatEventAsClassicLogText
+  stdout_obs = twisted.logger.FileLogObserver(sys.stdout, log_formatter)
+  stderr_obs = twisted.logger.FileLogObserver(sys.stderr, log_formatter)
+  pred = twisted.logger.LogLevelFilterPredicate(LogLevel.error)
+  stdsomething_obs = twisted.logger.FilteringLogObserver(
+    stderr_obs, [pred], stdout_obs
+  )
+  log_observer = twisted.logger.FilteringLogObserver(
+    stdsomething_obs, [LogNotBoringTwisted()]
+  )
+  #log_observer = stdsomething_obs
+  twisted.logger.globalLogBeginner.beginLoggingTo(
+    [ log_observer, crash_on_critical ]
+    )
+
+def common_run():
+  log_debug(DBG.INIT, 'entering reactor')
+  if not _crashing: reactor.run()
+  print('CRASHED (end)', file=sys.stderr)