Commit c470257b authored by Petr Špaček's avatar Petr Špaček

Deckard: reimplement dprint using logging module

parent 1893341e
#!/usr/bin/env python #!/usr/bin/env python
from __future__ import print_function from __future__ import print_function
import logging
import argparse import argparse
import sys import sys
import os import os
...@@ -292,8 +293,7 @@ def test_platform(*args): ...@@ -292,8 +293,7 @@ def test_platform(*args):
raise NotImplementedError('not supported at all on Windows') raise NotImplementedError('not supported at all on Windows')
if __name__ == '__main__': if __name__ == '__main__':
test_platform() # auxilitary classes for argparse
class ColonSplitter(argparse.Action): # pylint: disable=too-few-public-methods class ColonSplitter(argparse.Action): # pylint: disable=too-few-public-methods
"""Split argument string into list holding items separated by colon.""" """Split argument string into list holding items separated by colon."""
def __call__(self, parser, namespace, values, option_string=None): def __call__(self, parser, namespace, values, option_string=None):
...@@ -311,19 +311,27 @@ if __name__ == '__main__': ...@@ -311,19 +311,27 @@ if __name__ == '__main__':
def __call__(self, parser, namespace, values, option_string=None): def __call__(self, parser, namespace, values, option_string=None):
setattr(namespace, self.dest, values) setattr(namespace, self.dest, values)
test_platform()
logging.basicConfig(level=logging.ERROR)
log = logging.getLogger('deckard')
argparser = argparse.ArgumentParser() argparser = argparse.ArgumentParser()
argparser.add_argument('--qmin', help='query minimization (default: enabled)', default=True, argparser.add_argument('--qmin', help='query minimization (default: enabled)', default=True,
action=EnvDefault, envvar='QMIN', type=str2bool) action=EnvDefault, envvar='QMIN', type=str2bool)
argparser.add_argument('scenario', help='path to test scenario') argparser.add_argument('scenario', help='path to test scenario')
argparser.add_argument('binary', help='executable to test') argparser.add_argument('binary', help='executable to test')
argparser.add_argument('templates', help='colon-separated list of jinja2 template files', action=ColonSplitter) argparser.add_argument('templates', help='colon-separated list of jinja2 template files',
argparser.add_argument('configs', help='colon-separated list of files to be generated from jinja2 templates', action=ColonSplitter) action=ColonSplitter)
argparser.add_argument('configs',
help='colon-separated list of files to be generated from templates',
action=ColonSplitter)
argparser.add_argument('additional', help='additional parameters for the binary', nargs='*') argparser.add_argument('additional', help='additional parameters for the binary', nargs='*')
args = argparser.parse_args() args = argparser.parse_args()
if len(args.templates) != len(args.configs): if len(args.templates) != len(args.configs):
print("ERROR: Number of jinja2 template files is not equal to number of config files to be generated") log.critical('Number of jinja2 template files is not equal '
print("i.e. len(templates) != len(configs), see usage") 'to number of config files to be generated, '
'i.e. len(templates) != len(configs)')
sys.exit(1) sys.exit(1)
# Scan for scenarios # Scan for scenarios
......
from __future__ import print_function
import os
import threading
dprint_lock = threading.Lock()
def dprint(tag, msg):
""" Verbose logging (if enabled). """
if 'VERBOSE' in os.environ:
dprint_lock.acquire()
print(tag, msg)
dprint_lock.release()
from __future__ import absolute_import from __future__ import absolute_import
import logging
import dns.message import dns.message
import dns.rrset import dns.rrset
import dns.rcode import dns.rcode
...@@ -16,7 +17,6 @@ import random ...@@ -16,7 +17,6 @@ import random
import string import string
import time import time
from datetime import datetime from datetime import datetime
from pydnstest.dprint import dprint
from pydnstest.testserver import recvfrom_msg, sendto_msg from pydnstest.testserver import recvfrom_msg, sendto_msg
...@@ -383,6 +383,7 @@ class Range: ...@@ -383,6 +383,7 @@ class Range:
""" """
Range represents a set of scripted queries valid for given step range. Range represents a set of scripted queries valid for given step range.
""" """
log = logging.getLogger('pydnstest.scenario.Range')
def __init__(self, a, b): def __init__(self, a, b):
""" Initialize reply range. """ """ Initialize reply range. """
...@@ -395,8 +396,8 @@ class Range: ...@@ -395,8 +396,8 @@ class Range:
self.sent = 0 self.sent = 0
def __del__(self): def __del__(self):
dtag = '[ RANGE %d-%d ] %s' % (self.a, self.b, self.addresses) self.log.info('[ RANGE %d-%d ] %s received: %d sent: %d',
dprint(dtag, 'received: %d sent: %d' % (self.received, self.sent)) self.a, self.b, self.addresses, self.received, self.sent)
def add(self, entry): def add(self, entry):
""" Append a scripted response to the range""" """ Append a scripted response to the range"""
...@@ -434,18 +435,27 @@ class Range: ...@@ -434,18 +435,27 @@ class Range:
return None return None
class StepLogger(logging.LoggerAdapter):
"""
Prepent Step identification before each log message.
"""
def process(self, msg, kwargs):
return '[STEP %s %s] %s' % (self.extra['id'], self.extra['type'], msg), kwargs
class Step: class Step:
""" """
Step represents one scripted action in a given moment, Step represents one scripted action in a given moment,
each step has an order identifier, type and optionally data entry. each step has an order identifier, type and optionally data entry.
""" """
require_data = ['QUERY', 'CHECK_ANSWER', 'REPLY'] require_data = ['QUERY', 'CHECK_ANSWER', 'REPLY']
def __init__(self, id, type, extra_args): def __init__(self, id, type, extra_args):
""" Initialize single scenario step. """ """ Initialize single scenario step. """
self.id = int(id) self.id = int(id)
self.type = type self.type = type
self.log = StepLogger(logging.getLogger('pydnstest.scenario.Step'),
{'id': id, 'type': type})
self.args = extra_args self.args = extra_args
self.data = [] self.data = []
self.queries = [] self.queries = []
...@@ -475,9 +485,9 @@ class Step: ...@@ -475,9 +485,9 @@ class Step:
def play(self, ctx): def play(self, ctx):
""" Play one step from a scenario. """ """ Play one step from a scenario. """
dtag = '[ STEP %03d ] %s' % (self.id, self.type)
if self.type == 'QUERY': if self.type == 'QUERY':
dprint(dtag, self.data[0].message.to_text()) self.log.info('')
self.log.debug(self.data[0].message.to_text())
# Parse QUERY-specific parameters # Parse QUERY-specific parameters
choice, tcp, source = None, False, None choice, tcp, source = None, False, None
for v in self.args: for v in self.args:
...@@ -491,17 +501,16 @@ class Step: ...@@ -491,17 +501,16 @@ class Step:
choice = v choice = v
return self.__query(ctx, tcp=tcp, choice=choice, source=source) return self.__query(ctx, tcp=tcp, choice=choice, source=source)
elif self.type == 'CHECK_OUT_QUERY': elif self.type == 'CHECK_OUT_QUERY':
dprint(dtag, '') self.log.info('')
pass # Ignore pass # Ignore
elif self.type == 'CHECK_ANSWER' or self.type == 'ANSWER': elif self.type == 'CHECK_ANSWER' or self.type == 'ANSWER':
dprint(dtag, '') self.log.info('')
return self.__check_answer(ctx) return self.__check_answer(ctx)
elif self.type == 'TIME_PASSES': elif self.type == 'TIME_PASSES':
dprint(dtag, '') self.log.info('')
return self.__time_passes(ctx) return self.__time_passes(ctx)
elif self.type == 'REPLY' or self.type == 'MOCK': elif self.type == 'REPLY' or self.type == 'MOCK':
dprint(dtag, '') self.log.info('')
pass
elif self.type == 'LOG': elif self.type == 'LOG':
if not ctx.log: if not ctx.log:
raise Exception('scenario has no log interface') raise Exception('scenario has no log interface')
...@@ -519,22 +528,21 @@ class Step: ...@@ -519,22 +528,21 @@ class Step:
raise Exception("response definition required") raise Exception("response definition required")
expected = self.data[0] expected = self.data[0]
if expected.is_raw_data_entry is True: if expected.is_raw_data_entry is True:
dprint("", ctx.last_raw_answer.to_text()) self.log.debug("raw answer: %s", ctx.last_raw_answer.to_text())
expected.cmp_raw(ctx.last_raw_answer) expected.cmp_raw(ctx.last_raw_answer)
else: else:
if ctx.last_answer is None: if ctx.last_answer is None:
raise Exception("no answer from preceding query") raise Exception("no answer from preceding query")
dprint("", ctx.last_answer.to_text()) self.log.debug("answer: %s", ctx.last_answer.to_text())
expected.match(ctx.last_answer) expected.match(ctx.last_answer)
def __replay(self, ctx, chunksize=8): def __replay(self, ctx, chunksize=8):
dtag = '[ STEP %03d ] %s' % (self.id, self.type)
nqueries = len(self.queries) nqueries = len(self.queries)
if len(self.args) > 0 and self.args[0].isdigit(): if len(self.args) > 0 and self.args[0].isdigit():
nqueries = int(self.args.pop(0)) nqueries = int(self.args.pop(0))
destination = ctx.client[ctx.client.keys()[0]] destination = ctx.client[ctx.client.keys()[0]]
dprint(dtag, 'replaying %d queries to %s@%d (%s)' % self.log.info('replaying %d queries to %s@%d (%s)',
(nqueries, destination[0], destination[1], ' '.join(self.args))) nqueries, destination[0], destination[1], ' '.join(self.args))
if 'INTENSIFY' in os.environ: if 'INTENSIFY' in os.environ:
nqueries *= int(os.environ['INTENSIFY']) nqueries *= int(os.environ['INTENSIFY'])
tstart = datetime.now() tstart = datetime.now()
...@@ -542,7 +550,7 @@ class Step: ...@@ -542,7 +550,7 @@ class Step:
# Keep/print the statistics # Keep/print the statistics
rtt = (datetime.now() - tstart).total_seconds() * 1000 rtt = (datetime.now() - tstart).total_seconds() * 1000
pps = 1000 * nrcvd / rtt pps = 1000 * nrcvd / rtt
dprint(dtag, 'sent: %d, received: %d (%d ms, %d p/s)' % (nsent, nrcvd, rtt, pps)) self.log.debug('sent: %d, received: %d (%d ms, %d p/s)', nsent, nrcvd, rtt, pps)
tag = None tag = None
for arg in self.args: for arg in self.args:
if arg.upper().startswith('PRINT'): if arg.upper().startswith('PRINT'):
...@@ -642,6 +650,7 @@ class Step: ...@@ -642,6 +650,7 @@ class Step:
class Scenario: class Scenario:
log = logging.getLogger('pydnstest.scenatio.Scenario')
def __init__(self, info, filename=''): def __init__(self, info, filename=''):
""" Initialize scenario with description. """ """ Initialize scenario with description. """
...@@ -709,9 +718,8 @@ class Scenario: ...@@ -709,9 +718,8 @@ class Scenario:
step.play(self) step.play(self)
except Exception as e: except Exception as e:
if (step.repeat_if_fail > 0): if (step.repeat_if_fail > 0):
dprint("[play]", self.log.info("[play] step %d: exception - '%s', retrying step %d (%d left)",
"step %d: exception catched - '%s', retrying step %d (%d left)" % step.id, e, step.next_if_fail, step.repeat_if_fail)
(step.id, e, step.next_if_fail, step.repeat_if_fail))
step.repeat_if_fail -= 1 step.repeat_if_fail -= 1
if (step.pause_if_fail > 0): if (step.pause_if_fail > 0):
time.sleep(step.pause_if_fail) time.sleep(step.pause_if_fail)
......
from __future__ import absolute_import from __future__ import absolute_import
from __future__ import print_function from __future__ import print_function
import logging
import threading import threading
import select import select
import socket import socket
...@@ -11,7 +12,6 @@ import dns.rdatatype ...@@ -11,7 +12,6 @@ import dns.rdatatype
import itertools import itertools
import struct import struct
import binascii import binascii
from pydnstest.dprint import dprint
def recvfrom_msg(stream, raw=False): def recvfrom_msg(stream, raw=False):
...@@ -178,11 +178,12 @@ class TestServer: ...@@ -178,11 +178,12 @@ class TestServer:
True if client socket should be closed by caller True if client socket should be closed by caller
False if client socket should be kept open False if client socket should be kept open
""" """
log = logging.getLogger('pydnstest.testserver.handle_query')
client_address = client.getsockname()[0] client_address = client.getsockname()[0]
query, addr = recvfrom_msg(client) query, addr = recvfrom_msg(client)
if query is None: if query is None:
return False return False
dprint("[ handle_query ]", "%s incoming query from %s\n%s" % (client_address, addr, query)) log.debug('server %s received query from %s: %s', addr, client_address, query)
response = dns.message.make_response(query) response = dns.message.make_response(query)
is_raw_data = False is_raw_data = False
if self.scenario is not None: if self.scenario is not None:
...@@ -190,15 +191,16 @@ class TestServer: ...@@ -190,15 +191,16 @@ class TestServer:
if response: if response:
if is_raw_data is False: if is_raw_data is False:
data_to_wire = response.to_wire(max_size=65535) data_to_wire = response.to_wire(max_size=65535)
dprint("[ handle_query ]", "response\n%s" % response) log.debug('response: %s', response)
else: else:
data_to_wire = response data_to_wire = response
dprint("[ handle_query ]", "raw response found") log.debug('raw response not printed')
else: else:
response = dns.message.make_response(query) response = dns.message.make_response(query)
response.set_rcode(dns.rcode.SERVFAIL) response.set_rcode(dns.rcode.SERVFAIL)
data_to_wire = response.to_wire() data_to_wire = response.to_wire()
dprint("[ handle_query ]", "response failed, SERVFAIL") log.error('no response found for question %s, answering with SERVFAIL',
'; '.join([str(rr) for rr in query.question]))
sendto_msg(client, data_to_wire, addr) sendto_msg(client, data_to_wire, addr)
return True return True
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment