chiark / gitweb /
wip debug
[hippotat.git] / server
diff --git a/server b/server
index 0bbac6d17183c9b5f3a639a6a90be186de9ef9fb..3781d5607ab95d99e2bb4fb7be5e213420742d8b 100755 (executable)
--- a/server
+++ b/server
@@ -2,7 +2,6 @@
 
 from hippotat import *
 
-import sys
 import os
 
 import twisted.internet
@@ -15,53 +14,25 @@ import syslog
 
 clients = { }
 
-defcfg = '''
-[DEFAULT]
-max_batch_down = 65536
-max_queue_time = 10
-max_request_time = 54
-target_requests_outstanding = 3
-ipif = userv root ipif %(local)s,%(peer)s,%(mtu)s,slip %(rnets)s
-
-[virtual]
-mtu = 1500
-# network
-# [server]
-# [relay]
-
-[server]
-addrs = 127.0.0.1 ::1
-port = 8099
-
-[limits]
-max_batch_down = 262144
-max_queue_time = 121
-max_request_time = 121
-target_requests_outstanding = 10
-'''
-
 #---------- "router" ----------
 
-def route(packet, saddr, daddr):
-  print('TRACE ', saddr, daddr, packet)
-  try: client = clients[daddr]
+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 saddr.is_link_local or daddr.is_link_local:
-    log_discard(packet, saddr, daddr, 'link-local')
   elif daddr == c.server or daddr not in c.network:
-    print('TRACE INBOUND ', saddr, daddr, packet)
+    lt('inbound')
     queue_inbound(packet)
   elif daddr == relay:
-    log_discard(packet, saddr, daddr, 'relay')
+    lt('discard relay')
+    log_discard(packet, iface, saddr, daddr, 'relay')
   else:
-    log_discard(packet, saddr, daddr, 'no client')
-
-def log_discard(packet, saddr, daddr, why):
-  print('DROP ', saddr, daddr, why)
-#  syslog.syslog(syslog.LOG_DEBUG,
-#                'discarded packet %s -> %s (%s)' % (saddr, daddr, why))
+    lt('discard no-client')
+    log_discard(packet, iface, saddr, daddr, 'no-client')
 
 #---------- client ----------
 
@@ -76,113 +47,160 @@ class Client():
     # plus from config:
     #  .max_batch_down
     #  .max_queue_time
-    #  .max_request_time
     #  .target_requests_outstanding
 
     if ip not in c.network:
       raise ValueError('client %s not in network' % ip)
 
-    for k in ('max_batch_down','max_queue_time','max_request_time',
+    for k in ('max_batch_down','max_queue_time','http_timeout',
               'target_requests_outstanding'):
       req = cfg.getint(cs, k)
       limit = cfg.getint('limits',k)
       self.__dict__[k] = min(req, limit)
-    self._pq = PacketQueue(self.max_queue_time)
+
+    self._pq = PacketQueue(str(ip), self.max_queue_time)
 
     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, saddr, daddr)
+      route(packet, self._ip, saddr, daddr)
 
   def _req_cancel(self, request):
+    self._log(DBG.HTTP_CTRL, 'cancel', idof=request)
     request.finish()
 
   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 http_request(self, request):
+  def new_request(self, request):
     request.setHeader('Content-Type','application/octet-stream')
-    reactor.callLater(self.max_request_time, self._req_cancel, request)
+    reactor.callLater(self.http_timeout, self._req_cancel, request)
     request.notifyFinish().addErrback(self._req_error, request)
     self._rq.append(request)
     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 = self._rq[0]
       except IndexError: request = None
       if request and request.finished:
+        self._log(DBG.HTTP_CTRL, 'CHKO req finished, discard', idof=request)
         self._rq.popleft()
         continue
 
       if not self._pq.nonempty():
         # no packets, oh well
-        continue
+        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
-      while True:
-        packet = self.pq.popleft()
-        if packet is None: break
-
-        encoded = slip.encode(packet)
-        
-        if request.sentLength > 0:
-          if (request.sentLength + len(slip.delimiter)
-              + len(encoded) > self.max_batch_down):
-            break
-          request.write(slip.delimiter)
-
-        request.write(encoded)
-        self._pq.popLeft()
+      self._pq.process((lambda: request.sentLength),
+                       (lambda d: self._req_write(request, d)),
+                       self.max_batch_down)
 
       assert(request.sentLength)
-      self._rq.popLeft()
+      self._rq.popleft()
       request.finish()
+      self._log(DBG.HTTP, 'complete', idof=request)
       # round again, looking for more to do
 
     while len(self._rq) > self.target_requests_outstanding:
       request = 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.pw: raise ValueError('bad password')
+  desca['pwok']=True
+
+  if tro != cl.target_requests_outstanding:
+    raise ValueError('tro must be %d' % cl.target_requests_outstanding)
+
+  if cto < cl.http_timeout:
+    raise ValueError('cto must be >= %d' % cl.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 IphttpResource(twisted.web.resource.Resource):
   isLeaf = True
   def render_POST(self, request):
-    # find client, update config, etc.
-    ci = ipaddr(request.args['i'])
-    c = clients[ci]
-    pw = request.args['pw']
-    if pw != c.pw: raise ValueError('bad password')
-
-    # update config
-    for r, w in (('mbd', 'max_batch_down'),
-                 ('mqt', 'max_queue_time'),
-                 ('mrt', 'max_request_time'),
-                 ('tro', 'target_requests_outstanding')):
-      try: v = request.args[r]
-      except KeyError: continue
-      v = int(v)
-      c.__dict__[w] = v
-
-    try: d = request.args['d']
-    except KeyError: d = ''
-
-    c.process_arriving_data(d)
-    c.new_request(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
 
   def render_GET(self, request):
+    log_debug(DBG.HTTP, 'GET request')
     return b'<html><body>hippotat</body></html>'
 
 def start_http():
@@ -191,6 +209,7 @@ def start_http():
   for sa in c.saddrs:
     ep = sa.make_endpoint()
     crash_on_defer(ep.listen(site))
+    log_debug(DBG.INIT, 'listening on %s' % sa)
 
 #---------- config and setup ----------
         
@@ -215,8 +234,8 @@ def process_cfg():
                     ('peer', 'relay'),
                     ('rnets','network')))
 
-common_startup(defcfg)
+common_startup()
 process_cfg()
-start_ipif(c.ipif_command, route)
+start_ipif(c.ipif_command, (lambda p,s,d: route(p,"[ipif]",s,d)))
 start_http()
 common_run()