daemon: record the deferred for a request in the queue, too

[hippotat] / hippotatd

#!/usr/bin/python3
#
# Hippotat - Asinine IP Over HTTP program
# ./hippotatd - server main program
#
# Copyright 2017 Ian Jackson
#
# AGPLv3+ + CAFv2+
#
#    This program is free software: you can redistribute it and/or
#    modify it under the terms of the GNU Affero General Public
#    License as published by the Free Software Foundation, either
#    version 3 of the License, or (at your option) any later version,
#    with the "CAF Login Exception" as published by Ian Jackson
#    (version 2, or at your option any later version) as an Additional
#    Permission.
#
#    This program is distributed in the hope that it will be useful,
#    but WITHOUT ANY WARRANTY; without even the implied warranty of
#    MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
#    Affero General Public License for more details.
#
#    You should have received a copy of the GNU Affero General Public
#    License and the CAF Login Exception along with this program, in
#    the file AGPLv3+CAFv2.  If not, email Ian Jackson
#    <ijackson@chiark.greenend.org.uk>.

#@ import sys; sys.path.append('@PYBUILD_INSTALL_DIR@')
from hippotatlib import *

import os
import tempfile
import atexit
import shutil
import subprocess

import twisted.internet
from twisted.web.server import NOT_DONE_YET

import twisted.web.static

import hippotatlib.ownsource
from hippotatlib.ownsource import SourceShipmentPreparer

#import twisted.web.server import Site
#from twisted.web.resource import Resource

import syslog

cleanups = [ ]

clients = { }

#---------- "router" ----------

def route(packet, iface, saddr, daddr):
  def lt(dest):
    log_debug(DBG.ROUTE, 'route: %s -> %s: %s' % (saddr,daddr,dest), d=packet)
  try: dclient = clients[daddr]
  except KeyError: dclient = None
  if dclient is not None:
    lt('client')
    dclient.queue_outbound(packet)
  elif daddr == c.vaddr or daddr not in c.vnetwork:
    lt('inbound')
    queue_inbound(ipif, packet)
  elif daddr == c.vrelay:
    lt('discard relay')
    log_discard(packet, iface, saddr, daddr, 'relay')
  else:
    lt('discard no-client')
    log_discard(packet, iface, saddr, daddr, 'no-client')

#---------- client ----------

class Client():
  def __init__(self, ip, cc):
    # instance data members
    self._ip = ip
    self.cc = cc
    self._rq = collections.deque() # requests
    self._pq = PacketQueue(str(ip), self.cc.max_queue_time)

    if ip not in c.vnetwork:
      raise ValueError('client %s not in vnetwork' % ip)

    if ip in clients:
      raise ValueError('multiple client cfg sections for %s' % ip)
    clients[ip] = self

    self._log(DBG.INIT, 'new')

  def _log(self, dflag, msg, **kwargs):
    log_debug(dflag, ('client %s: ' % self._ip)+msg, **kwargs)

  def process_arriving_data(self, d):
    self._log(DBG.FLOW, "req data (enc'd)", d=d)
    if not len(d): return
    for packet in slip.decode(d):
      (saddr, daddr) = packet_addrs(packet)
      if saddr != self._ip:
        raise ValueError('wrong source address %s' % saddr)
      route(packet, self._ip, saddr, daddr)

  def _req_cancel(self, request):
    self._log(DBG.HTTP_CTRL, 'cancel', idof=request)
    try: request.finish()
    except Exception: pass

  def _req_error(self, err, request):
    self._log(DBG.HTTP_CTRL, 'error %s' % err, idof=request)
    self._req_cancel(request)

  def queue_outbound(self, packet):
    self._pq.append(packet)
    self._check_outbound()

  def _req_fin(self, dummy, request, cl):
    self._log(DBG.HTTP_CTRL, '_req_fin ' + repr(dummy), idof=request)
    try: cl.cancel()
    except twisted.internet.error.AlreadyCalled: pass

  def new_request(self, request):
    request.setHeader('Content-Type','application/octet-stream')
    cl = reactor.callLater(self.cc.http_timeout, self._req_cancel, request)
    nf = request.notifyFinish()
    nf.addErrback(self._req_error, request)
    nf.addCallback(self._req_fin, request, cl)
    self._rq.append((request,nf))
    self._check_outbound()

  def _req_write(self, req, d):
    self._log(DBG.HTTP, 'req_write ', idof=req, d=d)
    req.write(d)

  def _check_outbound(self):
    log_debug(DBG.HTTP_CTRL, 'CHKO')
    while True:
      try: (request,nf) = self._rq[0]
      except IndexError: request = None
      if request and nf.called:
        self._log(DBG.HTTP_CTRL, 'CHKO req finished, discard', idof=request)
        self._rq.popleft()
        continue

      if not self._pq.nonempty():
        # no packets, oh well
        self._log(DBG.HTTP_CTRL, 'CHKO no packets, OUT-DONE', idof=request)
        break

      if request is None:
        # no request
        self._log(DBG.HTTP_CTRL, 'CHKO no request, OUT-DONE', idof=request)
        break

      self._log(DBG.HTTP_CTRL, 'CHKO processing', idof=request)
      # request, and also some non-expired packets
      self._pq.process((lambda: request.sentLength),
                       (lambda d: self._req_write(request, d)),
                       self.cc.max_batch_down)

      assert(request.sentLength)
      self._rq.popleft()
      request.finish()
      self._log(DBG.HTTP, 'complete', idof=request)
      # round again, looking for more to do

    while len(self._rq) > self.cc.target_requests_outstanding:
      (request, nf) = self._rq.popleft()
      self._log(DBG.HTTP, 'CHKO above target, returning empty', idof=request)
      request.finish()

def process_request(request, desca):
  # find client, update config, etc.
  metadata = request.args[b'm'][0]
  metadata = metadata.split(b'\r\n')
  (ci_s, pw, tro, cto) = metadata[0:4]
  desca['m[0,2:3]'] = [ci_s, tro, cto]
  ci_s = ci_s.decode('utf-8')
  tro = int(tro); desca['tro']= tro
  cto = int(cto); desca['cto']= cto
  ci = ipaddr(ci_s)
  desca['ci'] = ci
  cl = clients[ci]
  if pw != cl.cc.password: raise ValueError('bad password')
  desca['pwok']=True

  if tro != cl.cc.target_requests_outstanding:
    raise ValueError('tro must be %d' % cl.cc.target_requests_outstanding)

  if cto < cl.cc.http_timeout:
    raise ValueError('cto must be >= %d' % cl.cc.http_timeout)

  try:
    d = request.args[b'd'][0]
    desca['d'] = d
    desca['dlen'] = len(d)
  except KeyError:
    d = b''
    desca['dlen'] = None

  log_http(desca, 'processing', idof=id(request), d=d)

  d = mime_translate(d)

  cl.process_arriving_data(d)
  cl.new_request(request)

def log_http(desca, msg, **kwargs):
  try:
    kwargs['d'] = desca['d']
    del desca['d']
  except KeyError:
    pass
  log_debug(DBG.HTTP, msg + repr(desca), **kwargs)

class NotStupidResource(twisted.web.resource.Resource):
  # why this is not the default is a mystery!
  def getChild(self, name, request):
    if name == b'': return self
    else: return twisted.web.resource.Resource.getChild(name, request)

class IphttpResource(NotStupidResource):
  def render_POST(self, request):
    log_debug(DBG.HTTP_FULL,
              'req recv: ' + repr(request) + ' ' + repr(request.args),
              idof=id(request))
    desca = {'d': None}
    try: process_request(request, desca)
    except Exception as e:
      emsg = traceback.format_exc()
      log_http(desca, 'RETURNING EXCEPTION ' + emsg)
      request.setHeader('Content-Type','text/plain; charset="utf-8"')
      request.setResponseCode(400)
      return (emsg + ' # ' + repr(desca) + '\r\n').encode('utf-8')
    log_debug(DBG.HTTP_CTRL, '...', idof=id(request))
    return NOT_DONE_YET

  # instantiator should set
  # self.hippotat_sources = (source_names[0], source_names[1])
  def __init__(self):
    self.hippotat_sources = [None, None]
    super().__init__()

  def render_GET(self, request):
    log_debug(DBG.HTTP, 'GET request')
    s = '<html><body>hippotat\n'
    (s0,s1) = self.hippotat_sources
    if s0:
      s += '<p><a href="%s">source</a>\n' % s0
      if self.hippotat_sources[1]:
        s += ('(and that of dependency <a href="%s">packages</a>)\n' % s1)
      s += 'available'
    else:
      s += 'TESTING'
    s += '</body></html>'
    return s.encode('utf-8')

def start_http():
  resource = IphttpResource()
  site = twisted.web.server.Site(resource)

  for sa in c.saddrs:
    ep = sa.make_endpoint()
    crash_on_defer(ep.listen(site))
    log_debug(DBG.INIT, 'listening on %s' % sa)

  td = tempfile.mkdtemp()

  def cleanup():
    try: shutil.rmtree(td)
    except FileNotFoundError: pass
    
  cleanups.append(cleanup)

  ssp = SourceShipmentPreparer(td)
  ssp.logger = partial(log_debug, DBG.OWNSOURCE)
  if DBG.OWNSOURCE in debug_set: ssp.stream_debug = sys.stdout
  ssp.download_packages = opts.ownsource >= 2
  if opts.ownsource >= 1: ssp.generate()

  for ix in (0,1):
    bn = ssp.output_names[ix]
    op = ssp.output_paths[ix]
    if op is None: continue
    resource.hippotat_sources[ix] = bn
    subresource =twisted.web.static.File(op)
    resource.putChild(bn.encode('utf-8'), subresource)

  reactor.callLater(0.1, (lambda: log.info('hippotatd started', dflag=False)))

#---------- config and setup ----------

def process_cfg(_opts, putative_servers, putative_clients):
  global opts
  opts = _opts

  global c
  c = ConfigResults()
  try: c.server = cfg1get('SERVER','server')
  except NoOptionError: c.server = 'SERVER'

  cfg_process_general(c, c.server)
  cfg_process_saddrs(c, c.server)
  cfg_process_vnetwork(c, c.server)
  cfg_process_vaddr(c, c.server)

  for (ci,cs) in putative_clients.items():
    cc = ConfigResults()
    sections = cfg_process_client_common(cc,c.server,cs,ci)
    if not sections: continue
    cfg_process_client_limited(cc,c.server,sections, 'max_batch_down')
    cfg_process_client_limited(cc,c.server,sections, 'max_queue_time')
    Client(ci, cc)

  try:
    c.vrelay = cfg1get(c.server, 'vrelay')
  except NoOptionError:
    for search in c.vnetwork.hosts():
      if search == c.vaddr: continue
      c.vrelay = search
      break

  try: c.ifname = cfg1get(c.server, 'ifname_server', raw=True)
  except NoOptionError: pass

  cfg_process_ipif(c,
                   [c.server, 'COMMON'],
                   (('local','vaddr'),
                    ('peer', 'vrelay'),
                    ('rnets','vnetwork')))

  if opts.printconfig is not None:
    try: val = cfg1get(c.server, opts.printconfig)
    except NoOptionError: pass
    else: print(val)
    sys.exit(0)

def catch_termination():
  def run_cleanups():
    for cleanup in cleanups:
      cleanup()

  atexit.register(run_cleanups)

  def signal_handler(name, sig, *args):
    signal.signal(sig, signal.SIG_DFL)
    print('exiting due to %s' % name, file=sys.stderr)
    run_cleanups()
    os.kill(os.getpid(), sig)
    raise RuntimeError('did not die due to signal %s !' % name)

  for sig in (signal.SIGINT, signal.SIGTERM):
    try: signame = sig.name
    except AttributeError: signame = "signal %d" % sig
    signal.signal(sig, partial(signal_handler, signame))

def daemonise():
  global syslogfacility
  if opts.daemon and opts.syslogfacility is None:
    opts.syslogfacility = 'daemon'

  if opts.syslogfacility is not None:
    facilnum = syslog.__dict__['LOG_' + opts.syslogfacility.upper()]
    syslog.openlog('hippotatd',
                   facility=facilnum,
                   logoption=syslog.LOG_PID)
    def emit(event):
      if logevent_is_boringtwisted(event): return
      m = twisted.logger.formatEvent(event)
      #print(repr(event), m, file=org_stderr)
      level = event.get('log_level')
      if   event.get('dflag',None) is not None: sl = syslog.LOG_DEBUG
      elif level == LogLevel.critical         : sl = syslog.LOG_CRIT
      elif level == LogLevel.error            : sl = syslog.LOG_ERR
      elif level == LogLevel.warn             : sl = syslog.LOG_WARNING
      else                                    : sl = syslog.LOG_INFO
      syslog.syslog(sl,m)
      failure = event.get('log_failure')
      if failure is not None:
        for l in failure.getTraceback().split('\n'):
          syslog.syslog(sl,l)
    glp = twisted.logger.globalLogPublisher
    glp.addObserver(emit)
    log_debug(DBG.INIT, 'starting to log to syslog')

  #log.crit('daemonic hippotatd crashed', dflag=False)
  if opts.daemon:
    daemonic_reactor = (twisted.internet.interfaces.IReactorDaemonize
                        .providedBy(reactor))
    if daemonic_reactor: reactor.beforeDaemonize()
    if opts.pidfile is not None:
      pidfile_h = open(opts.pidfile, 'w')
    rfd, wfd = os.pipe()
    childpid = os.fork()
    if childpid:
      # we are the parent
      os.close(wfd)
      st = os.read(rfd, 1)
      try:
        st = st[0]
      except IndexError:
        st = 127
        log.critical('daemonic hippotatd crashed', dflag=False)
      os._exit(st)
    os.close(rfd)
    os.setsid()
    grandchildpid = os.fork()
    if grandchildpid:
      # we are the intermediate child
      if opts.pidfile is not None:
        print(grandchildpid, file=pidfile_h)
        pidfile_h.close()
      os._exit(0)

    if opts.pidfile is not None:
      pidfile_h.close()
                                                                        
    logger = subprocess.Popen(['logger','-d',
                               '-t','hippotat[%d](stderr)' % os.getpid(),
                               '-p',opts.syslogfacility + '.err'],
                              stdin=subprocess.PIPE,
                              stdout=subprocess.DEVNULL,
                              stderr=subprocess.DEVNULL,
                              restore_signals=True)
    
    nullfd = os.open('/dev/null', os.O_RDWR)
    os.dup2(nullfd, 0)
    os.dup2(nullfd, 1)
    os.dup2(logger.stdin.fileno(), 2)
    os.close(nullfd)
    if daemonic_reactor: reactor.afterDaemonize()
    log_debug(DBG.INIT, 'daemonised')
    os.write(wfd, b'\0')
    os.close(wfd)

  if opts.syslogfacility is not None:
    glp.removeObserver(hippotatlib.file_log_observer)

optparser.add_option('--ownsource', default=2,
                     action='store_const', dest='ownsource', const=2,
                     help='source download fully enabled (default)')

optparser.add_option('--ownsource-local',
                     action='store_const', dest='ownsource', const=1,
                     help='source download is local source code only')

optparser.add_option('--no-ownsource',
                     action='store_const', dest='ownsource', const=0,
                     help='source download disabled (for testing only)')

optparser.add_option('--daemon',
                     action='store_true', dest='daemon', default=False,
                     help='daemonize (and log to syslog)')

optparser.add_option('--pidfile',
                     nargs=1, type='string',
                     action='store', dest='pidfile', default=None,
                     help='write pid to this file')

optparser.add_option('--syslog-facility',
                     nargs=1, type='string',action='store',
                     metavar='FACILITY', dest='syslogfacility',
                     default=None,
                     help='log to syslog, with specified facility')

optparser.add_option('--print-config',
                     nargs=1, type='string',action='store',
                     metavar='OPTION', dest='printconfig',
                     default=None,
                     help='print one config option value and exit')

common_startup(process_cfg)
catch_termination()
start_http()
daemonise()
ipif = start_ipif(c.ipif_command, (lambda p,s,d: route(p,"[ipif]",s,d)))
common_run()