wip, new log stuff

diff --git a/hippotat/__init__.py b/hippotat/__init__.py
index abc2a9fd687129eecd9732e258ac68168ed24711..32e685418635f9297fc02cc34586ddc6bd3782c3 100644 (file)
--- a/hippotat/__init__.py
+++ b/hippotat/__init__.py
@@ -7,8 +7,11 @@ import sys
 
 import twisted
 from twisted.internet import reactor
 
 import twisted
 from twisted.internet import reactor

-from twisted.logger import LogLevel

 import twisted.internet.endpoints
 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
 
 import ipaddress
 from ipaddress import AddressValueError


@@ -19,11 +22,10 @@ from configparser import NoOptionError
 
 import collections
 import time
 
 import collections
 import time

+import codecs

 
 import re as regexp
 
 
 import re as regexp
 

-from twisted.python.constants import NamedConstant
-

 import hippotat.slip as slip
 
 class DBG(twisted.python.constants.Names):
 import hippotat.slip as slip
 
 class DBG(twisted.python.constants.Names):


@@ -35,6 +37,19 @@ class DBG(twisted.python.constants.Names):
   QUEUE = NamedConstant()
   QUEUE_CTRL = NamedConstant()
 
   QUEUE = NamedConstant()
   QUEUE_CTRL = NamedConstant()
 

+_hexcodec = codecs.getencoder('hex_codec')
+
+log = twisted.logger.Logger()
+
+def log_debug(dflag, msg, idof=None, d=None):
+  if idof is not None:
+    msg = '[%d] %s' % (id(idof), msg)
+  if d is not None:
+    d = d[0:64]
+    d = _hex_codec(d)[0]
+    msg += ' ' + d
+  log.info('{dflag} {msgcore}', dflag=dflag, msgcore=msg)
+

 defcfg = '''
 [DEFAULT]
 #[<client>] overrides
 defcfg = '''
 [DEFAULT]
 #[<client>] overrides


@@ -96,7 +111,8 @@ class ConfigResults:
 c = ConfigResults()
 
 def log_discard(packet, saddr, daddr, why):
 c = ConfigResults()
 
 def log_discard(packet, saddr, daddr, why):

-  print('DROP ', saddr, daddr, why)
+  
+  Print('Drop ', Saddr, Daddr, why)

 #  syslog.syslog(syslog.LOG_DEBUG,
 #                'discarded packet %s -> %s (%s)' % (saddr, daddr, why))
 
 #  syslog.syslog(syslog.LOG_DEBUG,
 #                'discarded packet %s -> %s (%s)' % (saddr, daddr, why))
 


@@ -195,39 +211,53 @@ class PacketQueue():
     self._max_queue_time = max_queue_time
     self._pq = collections.deque() # packets
 
     self._max_queue_time = max_queue_time
     self._pq = collections.deque() # packets
 

-  def _log_debug(self, fn, pri, msg)
-    log_debug(pri, 
+  def _log(self, dflag, msg, **kwargs)
+    log_debug(dflag, self._desc+' pq: '+msg, **kwargs)

 
   def append(self, packet):
 
   def append(self, packet):

-    log_data(DBG.QUEUE, packet, 'pq %s: append' % self._desc)
+    self._log(DBG.QUEUE, 'append', d=packet)

     self._pq.append((time.monotonic(), packet))
 
   def nonempty(self):
     self._pq.append((time.monotonic(), packet))
 
   def nonempty(self):

-    log_debug(DBG.QUEUE, 'pq %s: nonempty ?' % self._desc)
+    self._log(DBG.QUEUE, 'nonempty ?')

     while True:
       try: (queuetime, packet) = self._pq[0]
     while True:
       try: (queuetime, packet) = self._pq[0]

-      except IndexError: return False
+      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
 
       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._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
       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]
     while True:
       try: (dummy, packet) = self._pq[0]

-      except IndexError: break
+      except IndexError:
+        self._log(DBG.QUEUE, 'process... empty')
+        break
+
+      self._log(DBG.QUEUE_CTRL, 'process... packet', d=packet)

 
       encoded = slip.encode(packet)
       sofar = sizequery()  
 
 
       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:
       if sofar > 0:
         if sofar + len(slip.delimiter) + len(encoded) > max_batch:

+          self._log(DBG.QUEUE_CTRL, 'process... overflow')

           break
         moredata(slip.delimiter)
 
           break
         moredata(slip.delimiter)
 


@@ -317,7 +347,11 @@ def process_cfg_clients(constructor):
 #---------- startup ----------
 
 def common_startup():
 #---------- startup ----------
 
 def common_startup():

-  twisted.logger.globalLogPublisher.addObserver(crash_on_critical)
+  log_formatter = twisted.logger.formatEventAsClassicLogText
+  log_observer = twisted.logger.FileLogObserver(sys.stderr, log_formatter)
+  twisted.logger.globalLogBeginner.beginLoggingTo(
+    [ log_observer, crash_on_critical ]
+    )

 
   optparser.add_option('-c', '--config', dest='configfile',
                        default='/etc/hippotat/config')
 
   optparser.add_option('-c', '--config', dest='configfile',
                        default='/etc/hippotat/config')


@@ -329,5 +363,6 @@ def common_startup():
   cfg.read(opts.configfile)
 
 def common_run():
   cfg.read(opts.configfile)
 
 def common_run():

+  log_debug(DBG.INIT, 'ready')

   reactor.run()
   print('CRASHED (end)', file=sys.stderr)
   reactor.run()
   print('CRASHED (end)', file=sys.stderr)

diff --git a/server b/server
index 68a3ebd0c26a0189de9b67fe056c16a26db92746..6cb8d9861e8ed36d3612ef1e7a9c452d75516d8c 100755 (executable)
--- a/server
+++ b/server
@@ -18,7 +18,7 @@ clients = { }
 
 def route(packet, saddr, daddr):
   def lt(dest):
 
 def route(packet, saddr, daddr):
   def lt(dest):

-    log_data(DBG.ROUTE, packet, 'route: %s -> %s: %s' % (saddr,daddr,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:
   try: dclient = clients[daddr]
   except KeyError: dclient = None
   if dclient is not None:


@@ -59,16 +59,19 @@ class Client():
       limit = cfg.getint('limits',k)
       self.__dict__[k] = min(req, limit)
 
       limit = cfg.getint('limits',k)
       self.__dict__[k] = min(req, limit)
 

-    self._pq = PacketQueue(self.max_queue_time)
+    self._pq = PacketQueue(ip, self.max_queue_time)

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

-    log_debug('DBG.INIT', 'new client %s' % self)
+    self._log(DBG.INIT, 'new')
+
+  def _log(self, pri, msg, **kwargs):
+    log_debug(pri, 'client '+self._ip+': '+msg, **kwargs)

 
   def process_arriving_data(self, d):
 
   def process_arriving_data(self, d):

-    log_data(DBG.FLOW, d, 'client req data: %s' % saddr=self._ip)
+    self._log(DBG.FLOW, 'req data', d=d)

     for packet in slip.decode(d):
       (saddr, daddr) = packet_addrs(packet)
       if saddr != self._ip:
     for packet in slip.decode(d):
       (saddr, daddr) = packet_addrs(packet)
       if saddr != self._ip:


@@ -76,11 +79,11 @@ class Client():
       route(packet, saddr, daddr)
 
   def _req_cancel(self, request):
       route(packet, saddr, daddr)
 
   def _req_cancel(self, request):

-    log_httpreq(DBG.HTTPCTRL, request, 'cancel')
+    self._log(DBG.HTTPCTRL, 'cancel', idof=request)

     request.finish()
 
   def _req_error(self, err, request):
     request.finish()
 
   def _req_error(self, err, request):

-    log_httpreq(DBG.HTTPCTRL, request, 'error %s' % err)
+    self._log(DBG.HTTPCTRL, 'error %s' % err, idof=request)

     self._req_cancel(request)
 
   def queue_outbound(self, packet):
     self._req_cancel(request)
 
   def queue_outbound(self, packet):


@@ -95,26 +98,26 @@ class Client():
     self._check_outbound()
 
   def _check_outbound(self):
     self._check_outbound()
 
   def _check_outbound(self):

-    log_httpreq(DBG.HTTPCTRL, None, 'CHKO')
+    log_debug(DBG.HTTPCTRL, 'CHKO')

     while True:
       try: request = self._rq[0]
       except IndexError: request = None
       if request and request.finished:
     while True:
       try: request = self._rq[0]
       except IndexError: request = None
       if request and request.finished:

-        log_httpreq(DBG.HTTP_CTRL, request, 'CHKO request finished, discard')
+        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._rq.popleft()
         continue
 
       if not self._pq.nonempty():
         # no packets, oh well

-        log_httpreq(DBG.HTTP_CTRL, request, 'CHKO no packets, OUT-DONE')
+        self._log(DBG.HTTP_CTRL, 'CHKO no packets, OUT-DONE', idof=request)

         break
 
       if request is None:
         # no request
         break
 
       if request is None:
         # no request

-        log_httpreq(DBG.HTTP_CTRL, request, 'CHKO no request, OUT-DONE')
+        self._log(DBG.HTTP_CTRL, 'CHKO no request, OUT-DONE', idof=request)

         break
 
         break
 

-      log_httpreq(DBG.HTTP_CTRL, request, 'CHKO processing')
+      self._log(DBG.HTTP_CTRL, 'CHKO processing', idof=request)

       # request, and also some non-expired packets
       self._pq.process((lambda: request.sentLength),
                        request.write,
       # request, and also some non-expired packets
       self._pq.process((lambda: request.sentLength),
                        request.write,


@@ -123,12 +126,12 @@ class Client():
       assert(request.sentLength)
       self._rq.popleft()
       request.finish()
       assert(request.sentLength)
       self._rq.popleft()
       request.finish()

-      log_httpreq(DBG.HTTP, request, 'complete')
+      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()
       # round again, looking for more to do
 
     while len(self._rq) > self.target_requests_outstanding:
       request = self._rq.popleft()

-      log_httpreq(DBG.HTTP, request, 'CHKO above target, returning empty')
+      self._log(DBG.HTTP, 'CHKO above target, returning empty', idof=request)

       request.finish()
 
 def process_request(request, desca):
       request.finish()
 
 def process_request(request, desca):


@@ -154,6 +157,14 @@ def process_request(request, desca):
   cl.process_arriving_data(d)
   cl.new_request(request)
 
   cl.process_arriving_data(d)
   cl.new_request(request)
 

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

 class IphttpResource(twisted.web.resource.Resource):
   isLeaf = True
   def render_POST(self, request):
 class IphttpResource(twisted.web.resource.Resource):
   isLeaf = True
   def render_POST(self, request):