From 8c3b6620f7427fcec21d3ad5955fce5062b60c26 Mon Sep 17 00:00:00 2001 From: Ian Jackson Date: Wed, 29 Mar 2017 23:47:13 +0100 Subject: [PATCH] wip, new log stuff --- hippotat/__init__.py | 57 +++++++++++++++++++++++++++++++++++--------- server | 37 ++++++++++++++++++---------- 2 files changed, 70 insertions(+), 24 deletions(-) diff --git a/hippotat/__init__.py b/hippotat/__init__.py index abc2a9f..32e6854 100644 --- a/hippotat/__init__.py +++ b/hippotat/__init__.py @@ -7,8 +7,11 @@ import sys import twisted from twisted.internet import reactor -from twisted.logger import LogLevel 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 @@ -19,11 +22,10 @@ from configparser import NoOptionError import collections import time +import codecs import re as regexp -from twisted.python.constants import NamedConstant - 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() +_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] #[] overrides @@ -96,7 +111,8 @@ class ConfigResults: 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)) @@ -195,39 +211,53 @@ class PacketQueue(): 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): - 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): - log_debug(DBG.QUEUE, 'pq %s: nonempty ?' % self._desc) + self._log(DBG.QUEUE, 'nonempty ?') 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 + 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: 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() + 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) @@ -317,7 +347,11 @@ def process_cfg_clients(constructor): #---------- 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') @@ -329,5 +363,6 @@ def common_startup(): cfg.read(opts.configfile) def common_run(): + log_debug(DBG.INIT, 'ready') reactor.run() print('CRASHED (end)', file=sys.stderr) diff --git a/server b/server index 68a3ebd..6cb8d98 100755 --- a/server +++ b/server @@ -18,7 +18,7 @@ clients = { } 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: @@ -59,16 +59,19 @@ class Client(): 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 - 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): - 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: @@ -76,11 +79,11 @@ class Client(): 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): - 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): @@ -95,26 +98,26 @@ class Client(): 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: - 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 - 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 - log_httpreq(DBG.HTTP_CTRL, request, 'CHKO no request, OUT-DONE') + self._log(DBG.HTTP_CTRL, 'CHKO no request, OUT-DONE', idof=request) 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, @@ -123,12 +126,12 @@ class Client(): 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() - 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): @@ -154,6 +157,14 @@ def process_request(request, desca): 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): -- 2.30.2