process putatives: break out log_ignore
[hippotat] / hippotatlib / __init__.py
1 # -*- python -*-
2 #
3 # Hippotat - Asinine IP Over HTTP program
4 # hippotatlib/__init__.py - common library code
5 #
6 # Copyright 2017 Ian Jackson
7 #
8 # GPLv3+
9 #
10 # This program is free software: you can redistribute it and/or modify
11 # it under the terms of the GNU General Public License as published by
12 # the Free Software Foundation, either version 3 of the License, or
13 # (at your option) any later version.
14 #
15 # This program is distributed in the hope that it will be useful,
16 # but WITHOUT ANY WARRANTY; without even the implied warranty of
17 # MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
18 # GNU General Public License for more details.
19 #
20 # You should have received a copy of the GNU General Public License
21 # along with this program, in the file GPLv3. If not,
22 # see <http://www.gnu.org/licenses/>.
23
24
25 import signal
26 signal.signal(signal.SIGINT, signal.SIG_DFL)
27
28 import sys
29 import os
30
31 from zope.interface import implementer
32
33 import twisted
34 from twisted.internet import reactor
35 import twisted.internet.endpoints
36 import twisted.logger
37 from twisted.logger import LogLevel
38 import twisted.python.constants
39 from twisted.python.constants import NamedConstant
40
41 import ipaddress
42 from ipaddress import AddressValueError
43
44 from optparse import OptionParser
45 import configparser
46 from configparser import ConfigParser
47 from configparser import NoOptionError
48
49 from functools import partial
50
51 import collections
52 import time
53 import codecs
54 import traceback
55
56 import re as regexp
57
58 import hippotatlib.slip as slip
59
60 class DBG(twisted.python.constants.Names):
61 INIT = NamedConstant()
62 CONFIG = NamedConstant()
63 ROUTE = NamedConstant()
64 DROP = NamedConstant()
65 OWNSOURCE = NamedConstant()
66 FLOW = NamedConstant()
67 HTTP = NamedConstant()
68 TWISTED = NamedConstant()
69 QUEUE = NamedConstant()
70 HTTP_CTRL = NamedConstant()
71 QUEUE_CTRL = NamedConstant()
72 HTTP_FULL = NamedConstant()
73 CTRL_DUMP = NamedConstant()
74 SLIP_FULL = NamedConstant()
75 DATA_COMPLETE = NamedConstant()
76
77 _hex_codec = codecs.getencoder('hex_codec')
78
79 #---------- logging ----------
80
81 org_stderr = sys.stderr
82
83 log = twisted.logger.Logger()
84
85 debug_set = set()
86 debug_def_detail = DBG.HTTP
87
88 def log_debug(dflag, msg, idof=None, d=None):
89 if dflag not in debug_set: return
90 #print('---------------->',repr((dflag, msg, idof, d)), file=sys.stderr)
91 if idof is not None:
92 msg = '[%#x] %s' % (id(idof), msg)
93 if d is not None:
94 trunc = ''
95 if not DBG.DATA_COMPLETE in debug_set:
96 if len(d) > 64:
97 d = d[0:64]
98 trunc = '...'
99 d = _hex_codec(d)[0].decode('ascii')
100 msg += ' ' + d + trunc
101 log.info('{dflag} {msgcore}', dflag=dflag, msgcore=msg)
102
103 def logevent_is_boringtwisted(event):
104 try:
105 if event.get('log_level') != LogLevel.info:
106 return False
107 dflag = event.get('dflag')
108 if dflag is False : return False
109 if dflag in debug_set: return False
110 if dflag is None and DBG.TWISTED in debug_set: return False
111 return True
112 except Exception:
113 print('EXCEPTION (IN BORINGTWISTED CHECK)',
114 traceback.format_exc(), file=org_stderr)
115 return False
116
117 @implementer(twisted.logger.ILogFilterPredicate)
118 class LogNotBoringTwisted:
119 def __call__(self, event):
120 return (
121 twisted.logger.PredicateResult.no
122 if logevent_is_boringtwisted(event) else
123 twisted.logger.PredicateResult.yes
124 )
125
126 #---------- default config ----------
127
128 defcfg = '''
129 [COMMON]
130 max_batch_down = 65536
131 max_queue_time = 10
132 target_requests_outstanding = 3
133 http_timeout = 30
134 http_timeout_grace = 5
135 max_requests_outstanding = 6
136 max_batch_up = 4000
137 http_retry = 5
138 port = 80
139 vroutes = ''
140 ifname_client = hippo%%d
141 ifname_server = shippo%%d
142
143 #[server] or [<client>] overrides
144 ipif = userv root ipif %(local)s,%(peer)s,%(mtu)s,slip,%(ifname)s %(rnets)s
145
146 # relating to virtual network
147 mtu = 1500
148
149 # addrs = 127.0.0.1 ::1
150 # url
151
152 # relating to virtual network
153 vvnetwork = 172.24.230.192
154 # vnetwork = <prefix>/<len>
155 # vaddr = <ipaddr>
156 # vrelay = <ipaddr>
157
158
159 # [<client-ip4-or-ipv6-address>]
160 # password = <password> # used by both, must match
161
162 [LIMIT]
163 max_batch_down = 262144
164 max_queue_time = 121
165 http_timeout = 121
166 target_requests_outstanding = 10
167 '''
168
169 # these need to be defined here so that they can be imported by import *
170 cfg = ConfigParser(strict=False)
171 optparser = OptionParser()
172
173 _mimetrans = bytes.maketrans(b'-'+slip.esc, slip.esc+b'-')
174 def mime_translate(s):
175 # SLIP-encoded packets cannot contain ESC ESC.
176 # Swap `-' and ESC. The result cannot contain `--'
177 return s.translate(_mimetrans)
178
179 class ConfigResults:
180 def __init__(self):
181 pass
182 def __repr__(self):
183 return 'ConfigResults('+repr(self.__dict__)+')'
184
185 def log_discard(packet, iface, saddr, daddr, why):
186 log_debug(DBG.DROP,
187 'discarded packet [%s] %s -> %s: %s' % (iface, saddr, daddr, why),
188 d=packet)
189
190 #---------- packet parsing ----------
191
192 def packet_addrs(packet):
193 version = packet[0] >> 4
194 if version == 4:
195 addrlen = 4
196 saddroff = 3*4
197 factory = ipaddress.IPv4Address
198 elif version == 6:
199 addrlen = 16
200 saddroff = 2*4
201 factory = ipaddress.IPv6Address
202 else:
203 raise ValueError('unsupported IP version %d' % version)
204 saddr = factory(packet[ saddroff : saddroff + addrlen ])
205 daddr = factory(packet[ saddroff + addrlen : saddroff + addrlen*2 ])
206 return (saddr, daddr)
207
208 #---------- address handling ----------
209
210 def ipaddr(input):
211 try:
212 r = ipaddress.IPv4Address(input)
213 except AddressValueError:
214 r = ipaddress.IPv6Address(input)
215 return r
216
217 def ipnetwork(input):
218 try:
219 r = ipaddress.IPv4Network(input)
220 except NetworkValueError:
221 r = ipaddress.IPv6Network(input)
222 return r
223
224 #---------- ipif (SLIP) subprocess ----------
225
226 class SlipStreamDecoder():
227 def __init__(self, desc, on_packet):
228 self._buffer = b''
229 self._on_packet = on_packet
230 self._desc = desc
231 self._log('__init__')
232
233 def _log(self, msg, **kwargs):
234 log_debug(DBG.SLIP_FULL, 'slip %s: %s' % (self._desc, msg), **kwargs)
235
236 def inputdata(self, data):
237 self._log('inputdata', d=data)
238 data = self._buffer + data
239 self._buffer = b''
240 packets = slip.decode(data, True)
241 self._buffer = packets.pop()
242 for packet in packets:
243 self._maybe_packet(packet)
244 self._log('bufremain', d=self._buffer)
245
246 def _maybe_packet(self, packet):
247 self._log('maybepacket', d=packet)
248 if len(packet):
249 self._on_packet(packet)
250
251 def flush(self):
252 self._log('flush')
253 data = self._buffer
254 self._buffer = b''
255 packets = slip.decode(data)
256 assert(len(packets) == 1)
257 self._maybe_packet(packets[0])
258
259 class _IpifProcessProtocol(twisted.internet.protocol.ProcessProtocol):
260 def __init__(self, router):
261 self._router = router
262 self._decoder = SlipStreamDecoder('ipif', self.slip_on_packet)
263 def connectionMade(self): pass
264 def outReceived(self, data):
265 self._decoder.inputdata(data)
266 def slip_on_packet(self, packet):
267 (saddr, daddr) = packet_addrs(packet)
268 if saddr.is_link_local or daddr.is_link_local:
269 log_discard(packet, 'ipif', saddr, daddr, 'link-local')
270 return
271 self._router(packet, saddr, daddr)
272 def processEnded(self, status):
273 status.raiseException()
274
275 def start_ipif(command, router):
276 ipif = _IpifProcessProtocol(router)
277 reactor.spawnProcess(ipif,
278 '/bin/sh',['sh','-xc', command],
279 childFDs={0:'w', 1:'r', 2:2},
280 env=None)
281 return ipif
282
283 def queue_inbound(ipif, packet):
284 log_debug(DBG.FLOW, "queue_inbound", d=packet)
285 ipif.transport.write(slip.delimiter)
286 ipif.transport.write(slip.encode(packet))
287 ipif.transport.write(slip.delimiter)
288
289 #---------- packet queue ----------
290
291 class PacketQueue():
292 def __init__(self, desc, max_queue_time):
293 self._desc = desc
294 assert(desc + '')
295 self._max_queue_time = max_queue_time
296 self._pq = collections.deque() # packets
297
298 def _log(self, dflag, msg, **kwargs):
299 log_debug(dflag, self._desc+' pq: '+msg, **kwargs)
300
301 def append(self, packet):
302 self._log(DBG.QUEUE, 'append', d=packet)
303 self._pq.append((time.monotonic(), packet))
304
305 def nonempty(self):
306 self._log(DBG.QUEUE, 'nonempty ?')
307 while True:
308 try: (queuetime, packet) = self._pq[0]
309 except IndexError:
310 self._log(DBG.QUEUE, 'nonempty ? empty.')
311 return False
312
313 age = time.monotonic() - queuetime
314 if age > self._max_queue_time:
315 # strip old packets off the front
316 self._log(DBG.QUEUE, 'dropping (old)', d=packet)
317 self._pq.popleft()
318 continue
319
320 self._log(DBG.QUEUE, 'nonempty ? nonempty.')
321 return True
322
323 def process(self, sizequery, moredata, max_batch):
324 # sizequery() should return size of batch so far
325 # moredata(s) should add s to batch
326 self._log(DBG.QUEUE, 'process...')
327 while True:
328 try: (dummy, packet) = self._pq[0]
329 except IndexError:
330 self._log(DBG.QUEUE, 'process... empty')
331 break
332
333 self._log(DBG.QUEUE_CTRL, 'process... packet', d=packet)
334
335 encoded = slip.encode(packet)
336 sofar = sizequery()
337
338 self._log(DBG.QUEUE_CTRL,
339 'process... (sofar=%d, max=%d) encoded' % (sofar, max_batch),
340 d=encoded)
341
342 if sofar > 0:
343 if sofar + len(slip.delimiter) + len(encoded) > max_batch:
344 self._log(DBG.QUEUE_CTRL, 'process... overflow')
345 break
346 moredata(slip.delimiter)
347
348 moredata(encoded)
349 self._pq.popleft()
350
351 #---------- error handling ----------
352
353 _crashing = False
354
355 def crash(err):
356 global _crashing
357 _crashing = True
358 print('========== CRASH ==========', err,
359 '===========================', file=sys.stderr)
360 try: reactor.stop()
361 except twisted.internet.error.ReactorNotRunning: pass
362
363 def crash_on_defer(defer):
364 defer.addErrback(lambda err: crash(err))
365
366 def crash_on_critical(event):
367 if event.get('log_level') >= LogLevel.critical:
368 crash(twisted.logger.formatEvent(event))
369
370 #---------- config processing ----------
371
372 def _cfg_process_putatives():
373 servers = { }
374 clients = { }
375 # maps from abstract object to canonical name for cs's
376
377 def putative(cmap, abstract, canoncs):
378 try:
379 current_canoncs = cmap[abstract]
380 except KeyError:
381 pass
382 else:
383 assert(current_canoncs == canoncs)
384 cmap[abstract] = canoncs
385
386 server_pat = r'[-.0-9A-Za-z]+'
387 client_pat = r'[.:0-9a-f]+'
388 server_re = regexp.compile(server_pat)
389 serverclient_re = regexp.compile(
390 server_pat + r' ' + '(?:' + client_pat + '|LIMIT)')
391
392 for cs in cfg.sections():
393 def log_ignore(why):
394 print('warning: ignoring config section [%s] (%s)' % (cs, why),
395 file=sys.stderr)
396
397 if cs == 'LIMIT' or cs == 'COMMON':
398 # plan A "[LIMIT]" or "[COMMON]"
399 continue
400
401 try:
402 # plan B "[<client>]" part 1
403 ci = ipaddr(cs)
404 except AddressValueError:
405
406 if server_re.fullmatch(cs):
407 # plan C "[<servername>]"
408 putative(servers, cs, cs)
409 continue
410
411 if serverclient_re.fullmatch(cs):
412 # plan D "[<servername> <client>]" part 1
413 (pss,pcs) = cs.split(' ')
414
415 if pcs == 'LIMIT':
416 # plan E "[<servername> LIMIT]"
417 continue
418
419 try:
420 # plan D "[<servername> <client>]" part 2
421 ci = ipaddr(pc)
422 except AddressValueError:
423 # plan F "[<some thing we do not understand>]"
424 log_ignore('bad-addr')
425 continue
426
427 else: # no AddressValueError
428 # plan D "[<servername> <client]" part 3
429 putative(clients, ci, pcs)
430 putative(servers, pss, pss)
431 continue
432
433 else: # no AddressValueError
434 # plan B "[<client>" part 2
435 putative(clients, ci, cs)
436 continue
437
438 return (servers, clients)
439
440 def cfg_process_general(c, ss):
441 c.mtu = cfg1getint(ss, 'mtu')
442
443 def cfg_process_saddrs(c, ss):
444 class ServerAddr():
445 def __init__(self, port, addrspec):
446 self.port = port
447 # also self.addr
448 try:
449 self.addr = ipaddress.IPv4Address(addrspec)
450 self._endpointfactory = twisted.internet.endpoints.TCP4ServerEndpoint
451 self._inurl = b'%s'
452 except AddressValueError:
453 self.addr = ipaddress.IPv6Address(addrspec)
454 self._endpointfactory = twisted.internet.endpoints.TCP6ServerEndpoint
455 self._inurl = b'[%s]'
456 def make_endpoint(self):
457 return self._endpointfactory(reactor, self.port,
458 interface= '%s' % self.addr)
459 def url(self):
460 url = b'http://' + (self._inurl % str(self.addr).encode('ascii'))
461 if self.port != 80: url += b':%d' % self.port
462 url += b'/'
463 return url
464 def __repr__(self):
465 return 'ServerAddr'+repr((self.port,self.addr))
466
467 c.port = cfg1getint(ss,'port')
468 c.saddrs = [ ]
469 for addrspec in cfg1get(ss, 'addrs').split():
470 sa = ServerAddr(c.port, addrspec)
471 c.saddrs.append(sa)
472
473 def cfg_process_vnetwork(c, ss):
474 c.vnetwork = ipnetwork(cfg1get(ss,'vnetwork'))
475 if c.vnetwork.num_addresses < 3 + 2:
476 raise ValueError('vnetwork needs at least 2^3 addresses')
477
478 def cfg_process_vaddr(c, ss):
479 try:
480 c.vaddr = cfg1get(ss,'vaddr')
481 except NoOptionError:
482 cfg_process_vnetwork(c, ss)
483 c.vaddr = next(c.vnetwork.hosts())
484
485 def cfg_search_section(key,sections):
486 for section in sections:
487 if cfg.has_option(section, key):
488 return section
489 raise NoOptionError(key, repr(sections))
490
491 def cfg_get_raw(*args, **kwargs):
492 # for passing to cfg_search
493 return cfg.get(*args, raw=True, **kwargs)
494
495 def cfg_search(getter,key,sections):
496 section = cfg_search_section(key,sections)
497 return getter(section, key)
498
499 def cfg1get(section,key, getter=cfg.get,**kwargs):
500 section = cfg_search_section(key,[section,'COMMON'])
501 return getter(section,key,**kwargs)
502
503 def cfg1getint(section,key, **kwargs):
504 return cfg1get(section,key, getter=cfg.getint,**kwargs);
505
506 def cfg_process_client_limited(cc,ss,sections,key):
507 val = cfg_search(cfg1getint, key, sections)
508 lim = cfg_search(cfg1getint, key, ['%s LIMIT' % ss, 'LIMIT'])
509 cc.__dict__[key] = min(val,lim)
510
511 def cfg_process_client_common(cc,ss,cs,ci):
512 # returns sections to search in, iff password is defined, otherwise None
513 cc.ci = ci
514
515 sections = ['%s %s' % (ss,cs),
516 cs,
517 ss,
518 'COMMON']
519
520 try: pwsection = cfg_search_section('password', sections)
521 except NoOptionError: return None
522
523 pw = cfg1get(pwsection, 'password')
524 cc.password = pw.encode('utf-8')
525
526 cfg_process_client_limited(cc,ss,sections,'target_requests_outstanding')
527 cfg_process_client_limited(cc,ss,sections,'http_timeout')
528
529 return sections
530
531 def cfg_process_ipif(c, sections, varmap):
532 for d, s in varmap:
533 try: v = getattr(c, s)
534 except AttributeError: continue
535 setattr(c, d, v)
536
537 #print('CFGIPIF',repr((varmap, sections, c.__dict__)),file=sys.stderr)
538
539 section = cfg_search_section('ipif', sections)
540 c.ipif_command = cfg1get(section,'ipif', vars=c.__dict__)
541
542 #---------- startup ----------
543
544 def log_debug_config(m):
545 if not DBG.CONFIG in debug_set: return
546 print('DBG.CONFIG:', m)
547
548 def common_startup(process_cfg):
549 # calls process_cfg(putative_clients, putative_servers)
550
551 # ConfigParser hates #-comments after values
552 trailingcomments_re = regexp.compile(r'#.*')
553 cfg.read_string(trailingcomments_re.sub('', defcfg))
554 need_defcfg = True
555
556 def readconfig(pathname, mandatory=True):
557 def log(m, p=pathname):
558 if not DBG.CONFIG in debug_set: return
559 log_debug_config('%s: %s' % (m, p))
560
561 try:
562 files = os.listdir(pathname)
563
564 except FileNotFoundError:
565 if mandatory: raise
566 log('skipped')
567 return
568
569 except NotADirectoryError:
570 cfg.read(pathname)
571 log('read file')
572 return
573
574 # is a directory
575 log('directory')
576 re = regexp.compile('[^-A-Za-z0-9_]')
577 for f in os.listdir(pathname):
578 if re.search(f): continue
579 subpath = pathname + '/' + f
580 try:
581 os.stat(subpath)
582 except FileNotFoundError:
583 log('entry skipped', subpath)
584 continue
585 cfg.read(subpath)
586 log('entry read', subpath)
587
588 def oc_config(od,os, value, op):
589 nonlocal need_defcfg
590 need_defcfg = False
591 readconfig(value)
592
593 def oc_extra_config(od,os, value, op):
594 readconfig(value)
595
596 def read_defconfig():
597 readconfig('/etc/hippotat/config.d', False)
598 readconfig('/etc/hippotat/passwords.d', False)
599 readconfig('/etc/hippotat/master.cfg', False)
600
601 def oc_defconfig(od,os, value, op):
602 nonlocal need_defcfg
603 need_defcfg = False
604 read_defconfig(value)
605
606 def dfs_less_detailed(dl):
607 return [df for df in DBG.iterconstants() if df <= dl]
608
609 def ds_default(od,os,dl,op):
610 global debug_set
611 debug_set.clear
612 debug_set |= set(dfs_less_detailed(debug_def_detail))
613
614 def ds_select(od,os, spec, op):
615 for it in spec.split(','):
616
617 if it.startswith('-'):
618 mutator = debug_set.discard
619 it = it[1:]
620 else:
621 mutator = debug_set.add
622
623 if it == '+':
624 dfs = DBG.iterconstants()
625
626 else:
627 if it.endswith('+'):
628 mapper = dfs_less_detailed
629 it = it[0:len(it)-1]
630 else:
631 mapper = lambda x: [x]
632
633 try:
634 dfspec = DBG.lookupByName(it)
635 except ValueError:
636 optparser.error('unknown debug flag %s in --debug-select' % it)
637
638 dfs = mapper(dfspec)
639
640 for df in dfs:
641 mutator(df)
642
643 optparser.add_option('-D', '--debug',
644 nargs=0,
645 action='callback',
646 help='enable default debug (to stdout)',
647 callback= ds_default)
648
649 optparser.add_option('--debug-select',
650 nargs=1,
651 type='string',
652 metavar='[-]DFLAG[+]|[-]+,...',
653 help=
654 '''enable (`-': disable) each specified DFLAG;
655 `+': do same for all "more interesting" DFLAGSs;
656 just `+': all DFLAGs.
657 DFLAGS: ''' + ' '.join([df.name for df in DBG.iterconstants()]),
658 action='callback',
659 callback= ds_select)
660
661 optparser.add_option('-c', '--config',
662 nargs=1,
663 type='string',
664 metavar='CONFIGFILE',
665 dest='configfile',
666 action='callback',
667 callback= oc_config)
668
669 optparser.add_option('--extra-config',
670 nargs=1,
671 type='string',
672 metavar='CONFIGFILE',
673 dest='configfile',
674 action='callback',
675 callback= oc_extra_config)
676
677 optparser.add_option('--default-config',
678 action='callback',
679 callback= oc_defconfig)
680
681 (opts, args) = optparser.parse_args()
682 if len(args): optparser.error('no non-option arguments please')
683
684 if need_defcfg:
685 read_defconfig()
686
687 try:
688 (pss, pcs) = _cfg_process_putatives()
689 process_cfg(opts, pss, pcs)
690 except (configparser.Error, ValueError):
691 traceback.print_exc(file=sys.stderr)
692 print('\nInvalid configuration, giving up.', file=sys.stderr)
693 sys.exit(12)
694
695
696 #print('X', debug_set, file=sys.stderr)
697
698 log_formatter = twisted.logger.formatEventAsClassicLogText
699 stdout_obs = twisted.logger.FileLogObserver(sys.stdout, log_formatter)
700 stderr_obs = twisted.logger.FileLogObserver(sys.stderr, log_formatter)
701 pred = twisted.logger.LogLevelFilterPredicate(LogLevel.error)
702 stdsomething_obs = twisted.logger.FilteringLogObserver(
703 stderr_obs, [pred], stdout_obs
704 )
705 global file_log_observer
706 file_log_observer = twisted.logger.FilteringLogObserver(
707 stdsomething_obs, [LogNotBoringTwisted()]
708 )
709 #log_observer = stdsomething_obs
710 twisted.logger.globalLogBeginner.beginLoggingTo(
711 [ file_log_observer, crash_on_critical ]
712 )
713
714 def common_run():
715 log_debug(DBG.INIT, 'entering reactor')
716 if not _crashing: reactor.run()
717 print('ENDED', file=sys.stderr)
718 sys.exit(16)