[Git][NTPsec/ntpsec][master] Updated logging to use RFC3339 timestamps.

Ian Bruene gitlab at mg.gitlab.com
Sun Mar 11 17:46:12 UTC 2018


Ian Bruene pushed to branch master at NTPsec / ntpsec


Commits:
068bd1b7 by Ian Bruene at 2018-03-11T17:44:10Z
Updated logging to use RFC3339 timestamps.

Docs now make experimental status clear.

- - - - -


8 changed files:

- docs/includes/ntpsnmpd-body.txt
- ntpclients/ntpsnmpd.py
- pylib/agentx.py
- pylib/packet.py
- pylib/util.py
- tests/pylib/jigs.py
- tests/pylib/test_packet.py
- tests/pylib/test_util.py


Changes:

=====================================
docs/includes/ntpsnmpd-body.txt
=====================================
--- a/docs/includes/ntpsnmpd-body.txt
+++ b/docs/includes/ntpsnmpd-body.txt
@@ -93,8 +93,9 @@ running NTP and SNMP daemons for ntpsnmpd to work.
 
 == Known Limitations ==
 
-This is still a prototype. Parts of the AgentX standard are not yet fully
-implemented, logging not fleshed out yet, some options missing, etc.
+This program is still experimental in nature. Parts of the AgentX standard
+are not yet fully implemented, logging not fleshed out yet, some options
+missing, etc.
 
 == Known Deviations from RFC 5907 ==
 


=====================================
ntpclients/ntpsnmpd.py
=====================================
--- a/ntpclients/ntpsnmpd.py
+++ b/ntpclients/ntpsnmpd.py
@@ -1133,14 +1133,14 @@ def connect(address):
             sock = socket.socket(af, socket.SOCK_STREAM)
             sock.connect((host, port))
     except socket.error as msg:
-        log(repr(msg) + "\n", 1)
+        log(repr(msg), 1)
         sys.exit(1)
     log("connected to master agent at " + address, 3)
     return sock
 
 
 def mainloop(snmpSocket, reconnectionAddr, host=None):
-    log("initing loop\n", 3)
+    log("initing loop", 3)
     dbase = DataSource(host, "/var/ntpsntpd/notify.conf")
     while True:  # Loop reconnection attempts
         control = PacketControl(snmpSocket, dbase, logfp=logfp, debug=debug)
@@ -1149,7 +1149,7 @@ def mainloop(snmpSocket, reconnectionAddr, host=None):
         if control.mainloop(True) is False:  # disconnected
             snmpSocket.close()
             snmpSocket = connect(reconnectionAddr)
-            log("disconnected from master, attempting reconnect\n", 2)
+            log("disconnected from master, attempting reconnect", 2)
         else:  # Something else happened
             break
 
@@ -1157,10 +1157,10 @@ def mainloop(snmpSocket, reconnectionAddr, host=None):
 def daemonize(runfunc, *runArgs):
     pid = os.fork()
     if pid < 0:
-        log("Forking error " + str(pid) + "\n", 1)
+        log("Forking error " + str(pid), 1)
         sys.exit(pid)
     elif pid > 0:  # We are the parent
-        log("Daemonization success, child pid: " + str(pid) + "\n", 3)
+        log("Daemonization success, child pid: " + str(pid), 3)
         sys.exit(0)
 
     # We must be the child
@@ -1186,7 +1186,7 @@ def daemonize(runfunc, *runArgs):
 
 
 def loadSettings(filename, optionList):
-    log("Loading config file: %s\n" % filename, 3)
+    log("Loading config file: %s" % filename, 3)
     if os.path.isfile(filename) is False:
         return None
     options = {}


=====================================
pylib/agentx.py
=====================================
--- a/pylib/agentx.py
+++ b/pylib/agentx.py
@@ -184,7 +184,7 @@ class PacketControl:
             if ptype in self.pduHandlers:
                 self.pduHandlers[ptype](packet)
             else:
-                self.log("Dropping packet type %i, not implemented\n" % ptype,
+                self.log("Dropping packet type %i, not implemented" % ptype,
                          2)
         self.checkResponses()
         if self.lastReception is not None:
@@ -193,7 +193,7 @@ class PacketControl:
                 self.sendPing()
 
     def initNewSession(self):
-        self.log("Initializing new session...\n", 3)
+        self.log("Initializing new session...", 3)
         # We already have a connection, need to open a session.
         openpkt = ax.OpenPDU(True, 23, 0, 0, self.timeout, (),
                              "NTPsec SNMP subagent")
@@ -250,7 +250,7 @@ class PacketControl:
                 self.receivedPackets.append(pkt)
                 if pkt.transactionID > self.highestTransactionID:
                     self.highestTransactionID = pkt.transactionID
-                self.log("Received a full packet: %s\n" % repr(pkt), 4)
+                self.log("Received a full packet: %s" % repr(pkt), 4)
             except ax.ParseDataLengthError:
                 return None  # this happens if we don't have all of a packet
             except (ax.ParseVersionError, ax.ParsePDUTypeError,
@@ -267,7 +267,7 @@ class PacketControl:
     def sendPacket(self, packet, expectsReply, replyTimeout=defaultTimeout,
                    callback=None):
         encoded = packet.encode()
-        self.log("Sending packet (with reply: %s): %s\n" % (expectsReply,
+        self.log("Sending packet (with reply: %s): %s" % (expectsReply,
                                                             repr(packet)), 4)
         self.socket.sendall(encoded)
         if expectsReply is True:
@@ -319,7 +319,7 @@ class PacketControl:
             tmp = tmp[0]
             newdata = tmp.recv(4096)  # Arbitrary value
             if len(newdata) > 0:
-                self.log("Received data: %s\n" % repr(newdata), 5)
+                self.log("Received data: %s" % repr(newdata), 5)
                 data += newdata
                 self.lastReception = time.time()
             else:


=====================================
pylib/packet.py
=====================================
--- a/pylib/packet.py
+++ b/pylib/packet.py
@@ -824,7 +824,7 @@ class ControlSession:
             return hinted_lookup(port="ntp", hints=socket.AI_NUMERICHOST)
         except socket.gaierror as e:
             ntp.util.dolog(self.logfp,
-                           "ntpq: numeric-mode lookup of %s failed, %s\n"
+                           "ntpq: numeric-mode lookup of %s failed, %s"
                            % (hname, e.strerror), self.debug, 3)
         try:
             return hinted_lookup(port="ntp", hints=0)
@@ -874,7 +874,7 @@ class ControlSession:
         else:
             self.hostname = canonname or hname
             self.isnum = False
-        ntp.util.dolog(self.logfp, "Opening host %s\n" % self.hostname,
+        ntp.util.dolog(self.logfp, "Opening host %s" % self.hostname,
                        self.debug, 3)
         self.port = sockaddr[1]
         try:
@@ -935,7 +935,7 @@ class ControlSession:
         while len(xdata) % 4:
             xdata += b"\x00"
         ntp.util.dolog(self.logfp,
-                       "Sending %d octets.  seq=%d\n"
+                       "Sending %d octets.  seq=%d"
                        % (len(xdata), self.sequence), self.debug, 3)
         try:
             self.sock.sendall(polybytes(xdata))
@@ -1022,7 +1022,7 @@ class ControlSession:
         warndbg = (lambda txt, th: ntp.util.dolog(self.logfp, txt,
                                                   self.debug, th))
 
-        warndbg("Fragment collection begins\n", 1)
+        warndbg("Fragment collection begins", 1)
         # Loop until we have an error or a complete response.  Nearly all
         # code paths to loop again use continue.
         while True:
@@ -1038,13 +1038,13 @@ class ControlSession:
             else:
                 tvo = self.secondary_timeout / 1000
 
-            warndbg("At %s, select with timeout %d begins\n"
+            warndbg("At %s, select with timeout %d begins"
                     % (time.asctime(), tvo), 5)
             try:
                 (rd, _, _) = select.select([self.sock], [], [], tvo)
             except select.error:
                 raise ControlException(SERR_SELECT)
-            warndbg("At %s, select with timeout %d ends\n"
+            warndbg("At %s, select with timeout %d ends"
                     % (time.asctime(), tvo), 5)
 
             if not rd:
@@ -1064,14 +1064,14 @@ class ControlSession:
                                          % ("not ", "")[seenlastfrag])
                 raise ControlException(SERR_INCOMPLETE)
 
-            warndbg("At %s, socket read begins\n" % time.asctime(), 4)
+            warndbg("At %s, socket read begins" % time.asctime(), 4)
             try:
                 rawdata = polybytes(self.sock.recv(4096))
             except socket.error:  # pragma: no cover
                 # usually, errno 111: connection refused
                 raise ControlException(SERR_SOCKET)
 
-            warndbg("Received %d octets\n" % len(rawdata), 3)
+            warndbg("Received %d octets" % len(rawdata), 3)
             rpkt = ControlPacket(self)
             try:
                 rpkt.analyze(rawdata)
@@ -1125,7 +1125,7 @@ class ControlSession:
                 continue
 
             warndbg("Recording fragment %d, size = %d offset = %d, "
-                    " end = %d, more=%s\n"
+                    " end = %d, more=%s"
                     % (len(fragments)+1, rpkt.count,
                        rpkt.offset, rpkt.end(), rpkt.more()), 3)
 
@@ -1144,14 +1144,14 @@ class ControlSession:
             if seenlastfrag and fragments[0].offset == 0:
                 for f in range(1, len(fragments)):
                     if fragments[f-1].end() != fragments[f].offset:
-                        warndbg("Hole in fragment sequence, %d of %d\n"
+                        warndbg("Hole in fragment sequence, %d of %d"
                                 % (f, len(fragments)), 1)
                         break
                 else:
                     tempfraglist = [polystr(f.extension) for f in fragments]
                     self.response = polybytes("".join(tempfraglist))
                     warndbg("Fragment collection ends. %d bytes "
-                            " in %d fragments\n"
+                            " in %d fragments"
                             % (len(self.response), len(fragments)), 1)
                     # special loggers, not replacing with dolog()
                     if self.debug >= 5:  # pragma: no cover
@@ -1179,24 +1179,24 @@ class ControlSession:
 
         if ((rpkt.version() > ntp.magic.NTP_VERSION) or
             (rpkt.version() < ntp.magic.NTP_OLDVERSION)):
-            warndbg("Fragment received with version %d\n"
+            warndbg("Fragment received with version %d"
                     % rpkt.version(), 1)
             return False
         if rpkt.mode() != ntp.magic.MODE_CONTROL:
-            warndbg("Fragment received with mode %d\n" % rpkt.mode(), 1)
+            warndbg("Fragment received with mode %d" % rpkt.mode(), 1)
             return False
         if not rpkt.is_response():
-            warndbg("Received request, wanted response\n", 1)
+            warndbg("Received request, wanted response", 1)
             return False
 
         # Check opcode and sequence number for a match.
         # Could be old data getting to us.
         if rpkt.sequence != self.sequence:
-            warndbg("Received sequence number %d, wanted %d\n" %
+            warndbg("Received sequence number %d, wanted %d" %
                     (rpkt.sequence, self.sequence), 1)
             return False
         if rpkt.opcode() != opcode:
-            warndbg("Received opcode %d, wanted %d\n" %
+            warndbg("Received opcode %d, wanted %d" %
                     (rpkt.opcode(), opcode), 1)
             return False
 
@@ -1463,34 +1463,34 @@ This combats source address spoofing
                         # None of the supplied prior entries match, so
                         # toss them from our list and try again.
                         warndbg("no overlap between prior entries and "
-                                "server MRU list\n", 1)
+                                "server MRU list", 1)
                         restarted_count += 1
                         if restarted_count > 8:
                             raise ControlException(SERR_STALL)
                         warndbg("--->   Restarting from the beginning, "
-                                "retry #%u\n" % restarted_count, 1)
+                                "retry #%u" % restarted_count, 1)
                     elif e.errorcode == ntp.control.CERR_BADVALUE:
                         if cap_frags:
                             cap_frags = False
                             warndbg("Reverted to row limit from "
-                                    "fragments limit.\n", 1)
+                                    "fragments limit.", 1)
                         else:
                             # ntpd has lower cap on row limit
                             self.ntpd_row_limit -= 1
                             limit = min(limit, self.ntpd_row_limit)
                             warndbg("Row limit reduced to %d following "
-                                    "CERR_BADVALUE.\n" % limit, 1)
+                                    "CERR_BADVALUE." % limit, 1)
                     elif e.errorcode in (SERR_INCOMPLETE, SERR_TIMEOUT):
                         # Reduce the number of rows/frags requested by
                         # half to recover from lost response fragments.
                         if cap_frags:
                             frags = max(2, frags / 2)
                             warndbg("Frag limit reduced to %d following "
-                                    "incomplete response.\n" % frags, 1)
+                                    "incomplete response." % frags, 1)
                         else:
                             limit = max(2, limit / 2)
                             warndbg("Row limit reduced to %d following "
-                                    " incomplete response.\n" % limit, 1)
+                                    " incomplete response." % limit, 1)
                     elif e.errorcode:
                         raise e
 
@@ -1512,7 +1512,7 @@ This combats source address spoofing
                 curidx = -1
                 mru = None
                 for (tag, val) in variables.items():
-                    warndbg("tag=%s, val=%s\n" % (tag, val), 4)
+                    warndbg("tag=%s, val=%s" % (tag, val), 4)
                     if tag == "nonce":
                         nonce = "%s=%s" % (tag, val)
                     elif tag == "last.older":


=====================================
pylib/util.py
=====================================
--- a/pylib/util.py
+++ b/pylib/util.py
@@ -86,6 +86,7 @@ def dolog(logfp, text, debug, threshold):
     # threshold is the trigger for the current log
     if logfp is None:
         return  # can turn off logging by supplying a None file descriptior
+    text = rfc3339(time.time()) + " " + text + "\n"
     if debug >= threshold:
         logfp.write(text)
         logfp.flush()  # we don't want to lose an important log to a crash


=====================================
tests/pylib/jigs.py
=====================================
--- a/tests/pylib/jigs.py
+++ b/tests/pylib/jigs.py
@@ -6,6 +6,7 @@ from __future__ import print_function, division
 import socket
 import select
 import os.path
+import time
 
 
 master_encoding = 'latin-1'
@@ -355,6 +356,15 @@ class TimeModuleJig:
         self.time_calls += 1
         return self.time_returns.pop(0)
 
+    def strftime(self, f, t=None):
+        if t is None:
+            return time.strftime(f)
+        else:
+            return time.strftime(f, t)
+
+    def gmtime(self, *args, **kwargs):
+        return time.gmtime(*args, **kwargs)
+
 
 class GzipModuleJig:
     def __init__(self):


=====================================
tests/pylib/test_packet.py
=====================================
--- a/tests/pylib/test_packet.py
+++ b/tests/pylib/test_packet.py
@@ -13,6 +13,7 @@ import select
 import sys
 import getpass
 import jigs
+import time
 
 odict = ntp.util.OrderedDict
 
@@ -769,7 +770,11 @@ class TestControlSession(unittest.TestCase):
 
     def test___lookuphost(self):
         logjig = jigs.FileJig()
+        faketimemod = jigs.TimeModuleJig()
+        faketimemod.time_returns = [0] * 10
         try:
+            timetemp = ntp.util.time
+            ntp.util.time = faketimemod
             fakesockmod = jigs.SocketModuleJig()
             ntpp.socket = fakesockmod
             # Init
@@ -793,8 +798,8 @@ class TestControlSession(unittest.TestCase):
             result = cls._ControlSession__lookuphost("blah.com", "family")
             self.assertEqual(result, 42)
             self.assertEqual(logjig.data,
-                             ["ntpq: numeric-mode lookup of blah.com "
-                              "failed, None\n"])
+                             ["1970-01-01T00:00:00Z ntpq: numeric-mode lookup "
+                              "of blah.com failed, None\n"])
             self.assertEqual(fakesockmod.gai_calls,
                              [("blah.com", "ntp", cls.ai_family,
                                socket.SOCK_DGRAM, socket.IPPROTO_UDP,
@@ -809,10 +814,10 @@ class TestControlSession(unittest.TestCase):
             result = cls._ControlSession__lookuphost("blah.com", "family")
             self.assertEqual(result, 42)
             self.assertEqual(logjig.data,
-                             ["ntpq: numeric-mode lookup of blah.com "
-                              "failed, None\n",
-                              "ntpq: standard-mode lookup of blah.com "
-                              "failed, None\n"])
+                             ["1970-01-01T00:00:00Z ntpq: numeric-mode lookup "
+                              "of blah.com failed, None\n",
+                              "ntpq: standard-mode lookup of blah.com failed, "
+                              "None\n"])
             self.assertEqual(fakesockmod.gai_calls,
                              [("blah.com", "ntp", cls.ai_family,
                                socket.SOCK_DGRAM, socket.IPPROTO_UDP,
@@ -828,10 +833,10 @@ class TestControlSession(unittest.TestCase):
             result = cls._ControlSession__lookuphost("blah.com", "family")
             self.assertEqual(result, None)
             self.assertEqual(logjig.data,
-                             ["ntpq: numeric-mode lookup of blah.com "
-                              "failed, None\n",
-                              "ntpq: standard-mode lookup of blah.com "
-                              "failed, None\n",
+                             ["1970-01-01T00:00:00Z ntpq: numeric-mode lookup "
+                              "of blah.com failed, None\n",
+                              "ntpq: standard-mode lookup of blah.com failed, "
+                              "None\n",
                               "ntpq: ndp lookup failed, None\n"])
             self.assertEqual(fakesockmod.gai_calls,
                              [("blah.com", "ntp", cls.ai_family,
@@ -843,6 +848,7 @@ class TestControlSession(unittest.TestCase):
                                socket.SOCK_DGRAM, socket.IPPROTO_UDP, 0)])
         finally:
             ntpp.socket = socket
+            ntp.util.time = timetemp
 
     def test_openhost(self):
         lookups = []
@@ -860,9 +866,13 @@ class TestControlSession(unittest.TestCase):
                 return [("family", "socktype", "protocol", "canon",
                          ("1.2.3.4", 80)), ]
         logjig = jigs.FileJig()
+        faketimemod = jigs.TimeModuleJig()
         try:
             fakesockmod = jigs.SocketModuleJig()
             ntpp.socket = fakesockmod
+            timetemp = ntp.util.time
+            ntp.util.time = faketimemod
+            faketimemod.time_returns = [0] * 10
             # Init
             cls = self.target()
             cls.debug = 3
@@ -877,7 +887,8 @@ class TestControlSession(unittest.TestCase):
             lookups = []
             result = cls.openhost("foo.org")
             self.assertEqual(result, True)
-            self.assertEqual(logjig.data, ["Opening host canon\n"])
+            self.assertEqual(logjig.data,
+                             ["1970-01-01T00:00:00Z Opening host canon\n"])
             self.assertEqual(lookups, [("foo.org", socket.AF_UNSPEC)])
             self.assertEqual(fakesockmod.socket_calls,
                              [("family", "socktype", "protocol")])
@@ -895,7 +906,8 @@ class TestControlSession(unittest.TestCase):
             cls.sock = None
             result = cls.openhost("foo.org")
             self.assertEqual(result, True)
-            self.assertEqual(logjig.data, ["Opening host canon.com\n"])
+            self.assertEqual(logjig.data,
+                             ["1970-01-01T00:00:00Z Opening host canon.com\n"])
             self.assertEqual(lookups, [("foo.org", socket.AF_UNSPEC)])
             self.assertEqual(fakesockmod.socket_calls,
                              [("family", "socktype", "protocol")])
@@ -929,6 +941,7 @@ class TestControlSession(unittest.TestCase):
                              "Error connecting to foo.org: socket! [16]")
         finally:
             ntpp.socket = socket
+            ntp.util.time = timetemp
 
     def test_password(self):
         iojig = jigs.FileJig()
@@ -1002,24 +1015,34 @@ class TestControlSession(unittest.TestCase):
     def test_sendpkt(self):
         logjig = jigs.FileJig()
         sockjig = jigs.SocketJig()
+        faketimemod = jigs.TimeModuleJig()
+        faketimemod.time_returns = [0] * 10
 
         # Init
         cls = self.target()
         cls.logfp = logjig
         cls.sock = sockjig
         cls.debug = 3
-        # Test
-        res = cls.sendpkt(polybytes("blahfoo"))
-        self.assertEqual(res, 0)
-        self.assertEqual(logjig.data, ["Sending 8 octets.  seq=0\n"])
-        self.assertEqual(sockjig.data, [polybytes("blahfoo\x00")])
-        # Test error
-        logjig.__init__()
-        sockjig.fail_send = 1
-        res = cls.sendpkt("blah")
-        self.assertEqual(res, -1)
-        self.assertEqual(logjig.data, ["Sending 4 octets.  seq=0\n",
-                                       "Write to None failed\n"])
+        try:
+            timetemp = ntp.util.time
+            ntp.util.time = faketimemod
+            # Test
+            res = cls.sendpkt(polybytes("blahfoo"))
+            self.assertEqual(res, 0)
+            self.assertEqual(logjig.data,
+                             ["1970-01-01T00:00:00Z Sending 8 octets.  "
+                              "seq=0\n"])
+            self.assertEqual(sockjig.data, [polybytes("blahfoo\x00")])
+            # Test error
+            logjig.__init__()
+            sockjig.fail_send = 1
+            res = cls.sendpkt("blah")
+            self.assertEqual(res, -1)
+            self.assertEqual(logjig.data,
+                             ["1970-01-01T00:00:00Z Sending 4 octets.  seq=0\n",
+                              "Write to None failed\n"])
+        finally:
+            ntp.util.time = timetemp
 
     def test_sendrequest(self):
         logjig = jigs.FileJig()
@@ -1169,129 +1192,153 @@ class TestControlSession(unittest.TestCase):
 
     def test___validate_packet(self):
         logjig = jigs.FileJig()
+        faketimemod = jigs.TimeModuleJig()
         # Init
         cls = self.target()
         cls.debug = 5
         cls.logfp = logjig
-        # Test good packet, empty data
-        raw = "\x0E\x81\x00\x00\x00\x03\x00\x02\x00\x00\x00\x00"
-        pkt = ntpp.ControlPacket(cls)
-        pkt.analyze(raw)
-        self.assertEqual(cls._ControlSession__validate_packet(pkt, raw, 1, 2),
-                         True)
-        self.assertEqual(logjig.data, [])
-        # Test good packet, with data
-        logjig.data = []
-        raw = "\x0E\xA1\x00\x01\x00\x02\x00\x03\x00\x00\x00\x09" \
-              "foo=4223,\x00\x00\x00"
-        pkt = ntpp.ControlPacket(cls)
-        pkt.analyze(raw)
-        cls.sequence = 1
-        self.assertEqual(cls._ControlSession__validate_packet(pkt, raw, 1, 3),
-                         True)
-        self.assertEqual(logjig.data, [])
-        # Test bad packet, bad version
-        # Need to fix version logic 0x46 can be ver == 5, or 0
-        cls.sequence = 0
-        logjig.data = []
-        raw = "\x46\x81\x00\x00\x00\x03\x00\x02\x00\x00\x00\x00"
-        pkt = ntpp.ControlPacket(cls)
-        pkt.analyze(raw)
-        self.assertEqual(cls._ControlSession__validate_packet(pkt, raw, 1, 2),
-                         False)
-        self.assertEqual(logjig.data, ["Fragment received with version 0\n"])
-        # Test bad packet, bad mode
-        logjig.data = []
-        raw = "\x0D\x81\x00\x00\x00\x03\x00\x02\x00\x00\x00\x00"
-        pkt = ntpp.ControlPacket(cls)
-        pkt.analyze(raw)
-        self.assertEqual(cls._ControlSession__validate_packet(pkt, raw, 1, 2),
-                         False)
-        self.assertEqual(logjig.data, ["Fragment received with mode 5\n"])
-        # Test bad packet, bad response bit
-        logjig.data = []
-        raw = "\x0E\x01\x00\x00\x00\x03\x00\x02\x00\x00\x00\x00"
-        pkt = ntpp.ControlPacket(cls)
-        pkt.analyze(raw)
-        self.assertEqual(cls._ControlSession__validate_packet(pkt, raw, 1, 2),
-                         False)
-        self.assertEqual(logjig.data, ["Received request, wanted response\n"])
-        # Test bad packet, bad sequence
-        logjig.data = []
-        raw = "\x0E\x81\x00\x01\x00\x03\x00\x02\x00\x00\x00\x00"
-        pkt = ntpp.ControlPacket(cls)
-        pkt.analyze(raw)
-        self.assertEqual(cls._ControlSession__validate_packet(pkt, raw, 1, 2),
-                         False)
-        self.assertEqual(logjig.data,
-                         ["Received sequence number 1, wanted 0\n"])
-        # Test bad packet, bad opcode
-        logjig.data = []
-        raw = "\x0E\x80\x00\x00\x00\x03\x00\x02\x00\x00\x00\x00"
-        pkt = ntpp.ControlPacket(cls)
-        pkt.analyze(raw)
-        self.assertEqual(cls._ControlSession__validate_packet(pkt, raw, 1, 2),
-                         False)
-        self.assertEqual(logjig.data,
-                         ["Received opcode 0, wanted 1\n"])
-        # Test error packet
-        logjig.data = []
-        raw = "\x0E\xC1\x00\x00" + \
-              chr(ntp.control.CERR_BADVALUE) + \
-              "\x03\x00\x02\x00\x00\x00\x00"
-        pkt = ntpp.ControlPacket(cls)
-        pkt.analyze(raw)
-        try:
-            cls._ControlSession__validate_packet(pkt, raw, 1, 2)
-            self.assertEqual(False, True)  # it should have errored here
-        except ctlerr as e:
-            self.assertEqual(e.errorcode, ntp.control.CERR_BADVALUE)
-        self.assertEqual(logjig.data, [])
-        # Test error packet, with more bit
-        logjig.data = []
-        errcs = chr(ntp.control.CERR_BADVALUE)
-        raw = "\x0E\xE1\x00\x00" + errcs + "\x03\x00\x02\x00\x00\x00\x00"
-        pkt = ntpp.ControlPacket(cls)
-        pkt.analyze(raw)
-        try:
-            cls._ControlSession__validate_packet(pkt, raw, 1, 2)
-            self.assertEqual(False, True)  # it should have errored here
-        except ctlerr as e:
-            self.assertEqual(e.errorcode, ntp.control.CERR_BADVALUE)
-        errstr = "Error " + str(ntp.control.CERR_BADVALUE) + \
-                 " received on non-final fragment\n"
-        self.assertEqual(logjig.data, [errstr])
-        # Test ok-ish packet, bad associd
-        logjig.data = []
-        raw = "\x0E\x81\x00\x00\x00\x03\x00\xFF\x00\x00\x00\x00"
-        pkt = ntpp.ControlPacket(cls)
-        pkt.analyze(raw)
-        self.assertEqual(cls._ControlSession__validate_packet(pkt, raw, 1, 2),
-                         True)
-        self.assertEqual(logjig.data,
-                         ["Association ID 255 doesn't match expected 2\n"])
-        # Test bad data padding
-        logjig.data = []
-        raw = "\x0E\x81\x00\x00\x00\x03\x00\x02\x00\x00\x00\x01@"
-        pkt = ntpp.ControlPacket(cls)
-        pkt.analyze(raw)
-        self.assertEqual(cls._ControlSession__validate_packet(pkt, raw, 1, 2),
-                         False)
-        self.assertEqual(logjig.data,
-                         ["Response fragment not padded, size = 13\n"])
-        # Test too little data
-        logjig.data = []
-        raw = "\x0E\x81\x00\x00\x00\x03\x00\x02\x00\x00\x00\x10foo\x00"
-        pkt = ntpp.ControlPacket(cls)
-        pkt.analyze(raw)
         try:
-            cls._ControlSession__validate_packet(pkt, raw, 1, 2)
-            self.assertEqual(True, False)  # should have errored here
-        except ctlerr as e:
-            self.assertEqual(e.message, ntpp.SERR_INCOMPLETE)
-        self.assertEqual(logjig.data,
-                         ["Response fragment claims 16 octets payload, "
-                          "above 4 received\n"])
+            timetemp = ntp.util.time
+            ntp.util.time = faketimemod
+            faketimemod.time_returns = [0] * 10
+            # Test good packet, empty data
+            raw = "\x0E\x81\x00\x00\x00\x03\x00\x02\x00\x00\x00\x00"
+            pkt = ntpp.ControlPacket(cls)
+            pkt.analyze(raw)
+            self.assertEqual(cls._ControlSession__validate_packet(pkt, raw,
+                                                                  1, 2),
+                             True)
+            self.assertEqual(logjig.data, [])
+            # Test good packet, with data
+            logjig.data = []
+            raw = "\x0E\xA1\x00\x01\x00\x02\x00\x03\x00\x00\x00\x09" \
+                  "foo=4223,\x00\x00\x00"
+            pkt = ntpp.ControlPacket(cls)
+            pkt.analyze(raw)
+            cls.sequence = 1
+            self.assertEqual(cls._ControlSession__validate_packet(pkt, raw,
+                                                                  1, 3),
+                             True)
+            self.assertEqual(logjig.data, [])
+            # Test bad packet, bad version
+            # Need to fix version logic 0x46 can be ver == 5, or 0
+            cls.sequence = 0
+            logjig.data = []
+            raw = "\x46\x81\x00\x00\x00\x03\x00\x02\x00\x00\x00\x00"
+            pkt = ntpp.ControlPacket(cls)
+            pkt.analyze(raw)
+            self.assertEqual(cls._ControlSession__validate_packet(pkt, raw,
+                                                                  1, 2),
+                             False)
+            self.assertEqual(logjig.data,
+                             ["1970-01-01T00:00:00Z Fragment "
+                              "received with version 0\n"])
+            # Test bad packet, bad mode
+            logjig.data = []
+            raw = "\x0D\x81\x00\x00\x00\x03\x00\x02\x00\x00\x00\x00"
+            pkt = ntpp.ControlPacket(cls)
+            pkt.analyze(raw)
+            self.assertEqual(cls._ControlSession__validate_packet(pkt, raw,
+                                                                  1, 2),
+                             False)
+            self.assertEqual(logjig.data,
+                             ["1970-01-01T00:00:00Z Fragment received "
+                              "with mode 5\n"])
+            # Test bad packet, bad response bit
+            logjig.data = []
+            raw = "\x0E\x01\x00\x00\x00\x03\x00\x02\x00\x00\x00\x00"
+            pkt = ntpp.ControlPacket(cls)
+            pkt.analyze(raw)
+            self.assertEqual(cls._ControlSession__validate_packet(pkt, raw,
+                                                                  1, 2),
+                             False)
+            self.assertEqual(logjig.data,
+                             ["1970-01-01T00:00:00Z Received request, "
+                              "wanted response\n"])
+            # Test bad packet, bad sequence
+            logjig.data = []
+            raw = "\x0E\x81\x00\x01\x00\x03\x00\x02\x00\x00\x00\x00"
+            pkt = ntpp.ControlPacket(cls)
+            pkt.analyze(raw)
+            self.assertEqual(cls._ControlSession__validate_packet(pkt, raw,
+                                                                  1, 2),
+                             False)
+            self.assertEqual(logjig.data,
+                             ["1970-01-01T00:00:00Z Received sequence "
+                              "number 1, wanted 0\n"])
+            # Test bad packet, bad opcode
+            logjig.data = []
+            raw = "\x0E\x80\x00\x00\x00\x03\x00\x02\x00\x00\x00\x00"
+            pkt = ntpp.ControlPacket(cls)
+            pkt.analyze(raw)
+            self.assertEqual(cls._ControlSession__validate_packet(pkt, raw,
+                                                                  1, 2),
+                             False)
+            self.assertEqual(logjig.data,
+                             ["1970-01-01T00:00:00Z Received opcode 0, "
+                              "wanted 1\n"])
+            # Test error packet
+            logjig.data = []
+            raw = "\x0E\xC1\x00\x00" + \
+                  chr(ntp.control.CERR_BADVALUE) + \
+                  "\x03\x00\x02\x00\x00\x00\x00"
+            pkt = ntpp.ControlPacket(cls)
+            pkt.analyze(raw)
+            try:
+                cls._ControlSession__validate_packet(pkt, raw, 1, 2)
+                self.assertEqual(False, True)  # it should have errored here
+            except ctlerr as e:
+                self.assertEqual(e.errorcode, ntp.control.CERR_BADVALUE)
+            self.assertEqual(logjig.data, [])
+            # Test error packet, with more bit
+            logjig.data = []
+            errcs = chr(ntp.control.CERR_BADVALUE)
+            raw = "\x0E\xE1\x00\x00" + errcs + "\x03\x00\x02\x00\x00\x00\x00"
+            pkt = ntpp.ControlPacket(cls)
+            pkt.analyze(raw)
+            try:
+                cls._ControlSession__validate_packet(pkt, raw, 1, 2)
+                self.assertEqual(False, True)  # it should have errored here
+            except ctlerr as e:
+                self.assertEqual(e.errorcode, ntp.control.CERR_BADVALUE)
+            errstr = "Error " + str(ntp.control.CERR_BADVALUE) + \
+                     " received on non-final fragment\n"
+            self.assertEqual(logjig.data, [errstr])
+            # Test ok-ish packet, bad associd
+            logjig.data = []
+            raw = "\x0E\x81\x00\x00\x00\x03\x00\xFF\x00\x00\x00\x00"
+            pkt = ntpp.ControlPacket(cls)
+            pkt.analyze(raw)
+            self.assertEqual(cls._ControlSession__validate_packet(pkt, raw,
+                                                                  1, 2),
+                             True)
+            self.assertEqual(logjig.data,
+                             ["Association ID 255 doesn't match expected 2\n"])
+            # Test bad data padding
+            logjig.data = []
+            raw = "\x0E\x81\x00\x00\x00\x03\x00\x02\x00\x00\x00\x01@"
+            pkt = ntpp.ControlPacket(cls)
+            pkt.analyze(raw)
+            self.assertEqual(cls._ControlSession__validate_packet(pkt, raw,
+                                                                  1, 2),
+                             False)
+            self.assertEqual(logjig.data,
+                             ["Response fragment not padded, size = 13\n"])
+            # Test too little data
+            logjig.data = []
+            raw = "\x0E\x81\x00\x00\x00\x03\x00\x02\x00\x00\x00\x10foo\x00"
+            pkt = ntpp.ControlPacket(cls)
+            pkt.analyze(raw)
+            try:
+                cls._ControlSession__validate_packet(pkt, raw, 1, 2)
+                self.assertEqual(True, False)  # should have errored here
+            except ctlerr as e:
+                self.assertEqual(e.message, ntpp.SERR_INCOMPLETE)
+            self.assertEqual(logjig.data,
+                             ["Response fragment claims 16 octets payload, "
+                              "above 4 received\n"])
+        finally:
+            ntp.util.time = timetemp
 
     def test_doquery(self):
         sends = []
@@ -1571,240 +1618,252 @@ class TestControlSession(unittest.TestCase):
         cls.fetch_nonce = fetch_nonce_jig
         cls.doquery = doquery_jig
         cls.logfp = logjig
-        # Test empty varlist
-        result = cls.mrulist()
-        self.assertEqual(nonce_fetch_count, [4])
-        self.assertEqual(queries,
-                         [(10, 0, "nonce=foo, frags=32", False),
-                          (10, 0,
-                           "nonce=foo, frags=32, addr.0=1.2.3.4:23, last.0=40",
-                           False),
-                          (10, 0,
-                           "nonce=foo, frags=32, addr.0=1.2.3.4:23, "
-                           "last.0=41, addr.1=1.2.3.4:23, last.1=40", False),
-                          (10, 0,
-                           "nonce=foo, frags=32, addr.0=10.20.30.40:23, "
-                           "last.0=42, addr.1=1.2.3.4:23, last.1=41, "
-                           "addr.2=1.2.3.4:23, last.2=40", False)])
-        self.assertEqual(isinstance(result, ntpp.MRUList), True)
-        self.assertEqual(len(result.entries), 2)
-        mru = result.entries[0]
-        self.assertEqual(mru.addr, "1.2.3.4:23")
-        self.assertEqual(mru.last, 41)
-        self.assertEqual(mru.first, 23)
-        self.assertEqual(mru.ct, 1)
-        self.assertEqual(mru.mv, 2)
-        self.assertEqual(mru.rs, 3)
-        mru = result.entries[1]
-        self.assertEqual(mru.addr, "10.20.30.40:23")
-        self.assertEqual(mru.last, 42)
-        self.assertEqual(mru.first, 23)
-        self.assertEqual(mru.ct, 1)
-        self.assertEqual(mru.mv, 2)
-        self.assertEqual(mru.rs, 3)
-        # Test with sort and frags (also test frag increment)
-        nonce_fetch_count = [0]
-        query_results = qrm[:]
-        queries = []
-        result = cls.mrulist(variables={"sort": "addr",
-                                        "frags": 24,
-                                        "resall":5})
-        self.assertEqual(nonce_fetch_count, [4])
-        self.assertEqual(queries,
-                         [(10, 0, "nonce=foo, frags=24, resall=0x5", False),
-                          (10, 0,
-                           "nonce=foo, frags=25, resall=0x5, "
-                           "addr.0=1.2.3.4:23, last.0=40",
-                           False),
-                          (10, 0,
-                           "nonce=foo, frags=26, resall=0x5, "
-                           "addr.0=1.2.3.4:23, last.0=41, addr.1=1.2.3.4:23, "
-                           "last.1=40", False),
-                          (10, 0,
-                           "nonce=foo, frags=27, resall=0x5, "
-                           "addr.0=10.20.30.40:23, "
-                           "last.0=42, addr.1=1.2.3.4:23, last.1=41, "
-                           "addr.2=1.2.3.4:23, last.2=40", False)])
-        self.assertEqual(isinstance(result, ntpp.MRUList), True)
-        self.assertEqual(len(result.entries), 2)
-        mru = result.entries[0]
-        self.assertEqual(mru.addr, "10.20.30.40:23")
-        self.assertEqual(mru.last, 42)
-        self.assertEqual(mru.first, 23)
-        self.assertEqual(mru.ct, 1)
-        self.assertEqual(mru.mv, 2)
-        self.assertEqual(mru.rs, 3)
-        mru = result.entries[1]
-        self.assertEqual(mru.addr, "1.2.3.4:23")
-        self.assertEqual(mru.last, 41)
-        self.assertEqual(mru.first, 23)
-        self.assertEqual(mru.ct, 1)
-        self.assertEqual(mru.mv, 2)
-        self.assertEqual(mru.rs, 3)
-        # Test sorter error
-        nonce_fetch_count = [0]
+        faketimemod = jigs.TimeModuleJig()
+        faketimemod.time_returns = [0] * 500
         try:
-            cls.mrulist(variables={"sort": "foo"})
-            errored = False
-        except ctlerr as e:
-            errored = e.message
-        self.assertEqual(errored, ntpp.SERR_BADSORT % "foo")
-        # Test varbind error
-        nonce_fetch_count = [0]
-        try:
-            cls.mrulist(variables={"foo": 1})
-            errored = False
-        except ctlerr as e:
-            errored = e.message
-        self.assertEqual(errored, ntpp.SERR_BADPARAM % "foo")
-        # Test add to request errors
-        # Test None error
-        nonce_fetch_count = [0]
-        queries = []
-        query_fail = [1]
-        query_fail_code = [None]
-        try:
-            cls.mrulist()
-            errored = False
-        except ctlerr as e:
-            errored = e.errorcode
-        self.assertEqual(errored, None)
-        # Test random error
-        nonce_fetch_count = [0]
-        queries = []
-        query_fail = [1]
-        query_fail_code = ["therdaglib"]
-        try:
-            cls.mrulist()
-            errored = False
-        except ctlerr as e:
-            errored = e.errorcode
-        self.assertEqual(errored, "therdaglib")
-        # Test unknown var error
-        nonce_fetch_count = [0]
-        query_results = qrm[:]
-        queries = []
-        query_fail = [1]
-        query_fail_code = [ntp.control.CERR_UNKNOWNVAR] * 2
-        cls.response = ""
-        result = cls.mrulist()
-        self.assertEqual(nonce_fetch_count, [5])
-        self.assertEqual(queries,
-                         [(10, 0, "nonce=foo, frags=32", False),
-                          (10, 0, "nonce=foo, frags=32", False),
-                          (10, 0,
-                           "nonce=foo, frags=32, addr.0=1.2.3.4:23, last.0=40",
-                           False),
-                          (10, 0,
-                           "nonce=foo, frags=32, addr.0=1.2.3.4:23, "
-                           "last.0=41, addr.1=1.2.3.4:23, last.1=40", False),
-                          (10, 0,
-                           "nonce=foo, frags=32, addr.0=10.20.30.40:23, "
-                           "last.0=42, addr.1=1.2.3.4:23, last.1=41, "
-                           "addr.2=1.2.3.4:23, last.2=40", False)])
-        self.assertEqual(isinstance(result, ntpp.MRUList), True)
-        self.assertEqual(len(result.entries), 2)
-        # Test bad value error
-        nonce_fetch_count = [0]
-        query_results = qrm[:]
-        queries = []
-        query_fail = [2]
-        query_fail_code = [ntp.control.CERR_BADVALUE] * 2
-        cls.response = ""
-        logjig.data = []
-        cls.debug = 1
-        result = cls.mrulist()
-        self.assertEqual(nonce_fetch_count, [6])
-        self.assertEqual(queries,
-                         [(10, 0, "nonce=foo, frags=32", False),
-                          (10, 0, "nonce=foo, limit=96", False),
-                          (10, 0, "nonce=foo, limit=96", False),
-                          (10, 0,
-                           "nonce=foo, limit=96, addr.0=1.2.3.4:23, last.0=40",
-                           False),
-                          (10, 0,
-                           "nonce=foo, limit=96, addr.0=1.2.3.4:23, "
-                           "last.0=41, addr.1=1.2.3.4:23, last.1=40", False),
-                          (10, 0,
-                           "nonce=foo, limit=96, addr.0=10.20.30.40:23, "
-                           "last.0=42, addr.1=1.2.3.4:23, last.1=41, "
-                           "addr.2=1.2.3.4:23, last.2=40", False)])
-        self.assertEqual(isinstance(result, ntpp.MRUList), True)
-        self.assertEqual(len(result.entries), 2)
-        self.assertEqual(logjig.data, ["Reverted to row limit from "
-                                       "fragments limit.\n",
-                                       "Row limit reduced to 96 following "
-                                       "CERR_BADVALUE.\n"])
-        # Test incomplete error
-        nonce_fetch_count = [0]
-        query_results = qrm[:]
-        queries = []
-        query_fail = [3]
-        query_fail_code = [ntpp.SERR_INCOMPLETE,
-                           ntp.control.CERR_BADVALUE,  # Trigger cap_frags
-                           ntpp.SERR_INCOMPLETE]
-        cls.response = ""
-        logjig.data = []
-        cls.debug = 1
-        result = cls.mrulist()
-        self.assertEqual(nonce_fetch_count, [7])
-        self.assertEqual(queries,
-                         [(10, 0, "nonce=foo, frags=32", False),
-                          (10, 0, "nonce=foo, frags=16", False),
-                          (10, 0, "nonce=foo, limit=96", False),
-                          (10, 0, "nonce=foo, limit=48", False),
-                          (10, 0,
-                           "nonce=foo, limit=49, addr.0=1.2.3.4:23, last.0=40",
-                           False),
-                          (10, 0,
-                           "nonce=foo, limit=51, addr.0=1.2.3.4:23, "
-                           "last.0=41, addr.1=1.2.3.4:23, last.1=40", False),
-                          (10, 0,
-                           "nonce=foo, limit=52, addr.0=10.20.30.40:23, "
-                           "last.0=42, addr.1=1.2.3.4:23, last.1=41, "
-                           "addr.2=1.2.3.4:23, last.2=40", False)])
-        self.assertEqual(len(result.entries), 2)
-        self.assertEqual(logjig.data,
-                         ["Frag limit reduced to 16 following incomplete "
-                          "response.\n",
-                          "Reverted to row limit from fragments limit.\n",
-                          "Row limit reduced to 48 following  incomplete "
-                          "response.\n"])
-        # Test timeout error
-        nonce_fetch_count = [0]
-        query_results = qrm[:]
-        queries = []
-        query_fail = [3]
-        query_fail_code = [ntpp.SERR_TIMEOUT,
-                           ntp.control.CERR_BADVALUE,  # Trigger cap_frags
-                           ntpp.SERR_TIMEOUT]
-        cls.response = ""
-        logjig.data = []
-        cls.debug = 1
-        result = cls.mrulist()
-        self.assertEqual(nonce_fetch_count, [7])
-        self.assertEqual(queries,
-                         [(10, 0, "nonce=foo, frags=32", False),
-                          (10, 0, "nonce=foo, frags=16", False),
-                          (10, 0, "nonce=foo, limit=96", False),
-                          (10, 0, "nonce=foo, limit=48", False),
-                          (10, 0,
-                           "nonce=foo, limit=49, addr.0=1.2.3.4:23, last.0=40",
-                           False),
-                          (10, 0,
-                           "nonce=foo, limit=51, addr.0=1.2.3.4:23, "
-                           "last.0=41, addr.1=1.2.3.4:23, last.1=40", False),
-                          (10, 0,
-                           "nonce=foo, limit=52, addr.0=10.20.30.40:23, "
-                           "last.0=42, addr.1=1.2.3.4:23, last.1=41, "
-                           "addr.2=1.2.3.4:23, last.2=40", False)])
-        self.assertEqual(len(result.entries), 2)
-        self.assertEqual(logjig.data,
-                         ["Frag limit reduced to 16 following incomplete "
-                          "response.\n",
-                          "Reverted to row limit from fragments limit.\n",
-                          "Row limit reduced to 48 following  incomplete "
-                          "response.\n"])
+            timetemp = ntp.packet.time
+            ntp.util.time = faketimemod
+            # Test empty varlist
+            result = cls.mrulist()
+            self.assertEqual(nonce_fetch_count, [4])
+            self.assertEqual(queries,
+                             [(10, 0, "nonce=foo, frags=32", False),
+                              (10, 0,
+                               "nonce=foo, frags=32, addr.0=1.2.3.4:23, "
+                               "last.0=40",
+                               False),
+                              (10, 0,
+                               "nonce=foo, frags=32, addr.0=1.2.3.4:23, "
+                               "last.0=41, addr.1=1.2.3.4:23, last.1=40",
+                               False),
+                              (10, 0,
+                               "nonce=foo, frags=32, addr.0=10.20.30.40:23, "
+                               "last.0=42, addr.1=1.2.3.4:23, last.1=41, "
+                               "addr.2=1.2.3.4:23, last.2=40", False)])
+            self.assertEqual(isinstance(result, ntpp.MRUList), True)
+            self.assertEqual(len(result.entries), 2)
+            mru = result.entries[0]
+            self.assertEqual(mru.addr, "1.2.3.4:23")
+            self.assertEqual(mru.last, 41)
+            self.assertEqual(mru.first, 23)
+            self.assertEqual(mru.ct, 1)
+            self.assertEqual(mru.mv, 2)
+            self.assertEqual(mru.rs, 3)
+            mru = result.entries[1]
+            self.assertEqual(mru.addr, "10.20.30.40:23")
+            self.assertEqual(mru.last, 42)
+            self.assertEqual(mru.first, 23)
+            self.assertEqual(mru.ct, 1)
+            self.assertEqual(mru.mv, 2)
+            self.assertEqual(mru.rs, 3)
+            # Test with sort and frags (also test frag increment)
+            nonce_fetch_count = [0]
+            query_results = qrm[:]
+            queries = []
+            result = cls.mrulist(variables={"sort": "addr",
+                                            "frags": 24,
+                                            "resall":5})
+            self.assertEqual(nonce_fetch_count, [4])
+            self.assertEqual(queries,
+                             [(10, 0, "nonce=foo, frags=24, resall=0x5", False),
+                              (10, 0,
+                               "nonce=foo, frags=25, resall=0x5, "
+                               "addr.0=1.2.3.4:23, last.0=40",
+                               False),
+                              (10, 0,
+                               "nonce=foo, frags=26, resall=0x5, "
+                               "addr.0=1.2.3.4:23, last.0=41, addr.1=1.2.3.4:23, "
+                               "last.1=40", False),
+                              (10, 0,
+                               "nonce=foo, frags=27, resall=0x5, "
+                               "addr.0=10.20.30.40:23, "
+                               "last.0=42, addr.1=1.2.3.4:23, last.1=41, "
+                               "addr.2=1.2.3.4:23, last.2=40", False)])
+            self.assertEqual(isinstance(result, ntpp.MRUList), True)
+            self.assertEqual(len(result.entries), 2)
+            mru = result.entries[0]
+            self.assertEqual(mru.addr, "10.20.30.40:23")
+            self.assertEqual(mru.last, 42)
+            self.assertEqual(mru.first, 23)
+            self.assertEqual(mru.ct, 1)
+            self.assertEqual(mru.mv, 2)
+            self.assertEqual(mru.rs, 3)
+            mru = result.entries[1]
+            self.assertEqual(mru.addr, "1.2.3.4:23")
+            self.assertEqual(mru.last, 41)
+            self.assertEqual(mru.first, 23)
+            self.assertEqual(mru.ct, 1)
+            self.assertEqual(mru.mv, 2)
+            self.assertEqual(mru.rs, 3)
+            # Test sorter error
+            nonce_fetch_count = [0]
+            try:
+                cls.mrulist(variables={"sort": "foo"})
+                errored = False
+            except ctlerr as e:
+                errored = e.message
+            self.assertEqual(errored, ntpp.SERR_BADSORT % "foo")
+            # Test varbind error
+            nonce_fetch_count = [0]
+            try:
+                cls.mrulist(variables={"foo": 1})
+                errored = False
+            except ctlerr as e:
+                errored = e.message
+            self.assertEqual(errored, ntpp.SERR_BADPARAM % "foo")
+            # Test add to request errors
+            # Test None error
+            nonce_fetch_count = [0]
+            queries = []
+            query_fail = [1]
+            query_fail_code = [None]
+            try:
+                cls.mrulist()
+                errored = False
+            except ctlerr as e:
+                errored = e.errorcode
+            self.assertEqual(errored, None)
+            # Test random error
+            nonce_fetch_count = [0]
+            queries = []
+            query_fail = [1]
+            query_fail_code = ["therdaglib"]
+            try:
+                cls.mrulist()
+                errored = False
+            except ctlerr as e:
+                errored = e.errorcode
+            self.assertEqual(errored, "therdaglib")
+            # Test unknown var error
+            nonce_fetch_count = [0]
+            query_results = qrm[:]
+            queries = []
+            query_fail = [1]
+            query_fail_code = [ntp.control.CERR_UNKNOWNVAR] * 2
+            cls.response = ""
+            result = cls.mrulist()
+            self.assertEqual(nonce_fetch_count, [5])
+            self.assertEqual(queries,
+                             [(10, 0, "nonce=foo, frags=32", False),
+                              (10, 0, "nonce=foo, frags=32", False),
+                              (10, 0,
+                               "nonce=foo, frags=32, addr.0=1.2.3.4:23, last.0=40",
+                               False),
+                              (10, 0,
+                               "nonce=foo, frags=32, addr.0=1.2.3.4:23, "
+                               "last.0=41, addr.1=1.2.3.4:23, last.1=40", False),
+                              (10, 0,
+                               "nonce=foo, frags=32, addr.0=10.20.30.40:23, "
+                               "last.0=42, addr.1=1.2.3.4:23, last.1=41, "
+                               "addr.2=1.2.3.4:23, last.2=40", False)])
+            self.assertEqual(isinstance(result, ntpp.MRUList), True)
+            self.assertEqual(len(result.entries), 2)
+            # Test bad value error
+            nonce_fetch_count = [0]
+            query_results = qrm[:]
+            queries = []
+            query_fail = [2]
+            query_fail_code = [ntp.control.CERR_BADVALUE] * 2
+            cls.response = ""
+            logjig.data = []
+            cls.debug = 1
+            result = cls.mrulist()
+            self.assertEqual(nonce_fetch_count, [6])
+            self.assertEqual(queries,
+                             [(10, 0, "nonce=foo, frags=32", False),
+                              (10, 0, "nonce=foo, limit=96", False),
+                              (10, 0, "nonce=foo, limit=96", False),
+                              (10, 0,
+                               "nonce=foo, limit=96, addr.0=1.2.3.4:23, last.0=40",
+                               False),
+                              (10, 0,
+                               "nonce=foo, limit=96, addr.0=1.2.3.4:23, "
+                               "last.0=41, addr.1=1.2.3.4:23, last.1=40", False),
+                              (10, 0,
+                               "nonce=foo, limit=96, addr.0=10.20.30.40:23, "
+                               "last.0=42, addr.1=1.2.3.4:23, last.1=41, "
+                               "addr.2=1.2.3.4:23, last.2=40", False)])
+            self.assertEqual(isinstance(result, ntpp.MRUList), True)
+            self.assertEqual(len(result.entries), 2)
+            self.assertEqual(logjig.data,
+                             ["1970-01-01T00:00:00Z Reverted to row limit "
+                              "from fragments limit.\n",
+                              "1970-01-01T00:00:00Z Row limit reduced to 96 "
+                              "following CERR_BADVALUE.\n"])
+            # Test incomplete error
+            nonce_fetch_count = [0]
+            query_results = qrm[:]
+            queries = []
+            query_fail = [3]
+            query_fail_code = [ntpp.SERR_INCOMPLETE,
+                               ntp.control.CERR_BADVALUE,  # Trigger cap_frags
+                               ntpp.SERR_INCOMPLETE]
+            cls.response = ""
+            logjig.data = []
+            cls.debug = 1
+            result = cls.mrulist()
+            self.assertEqual(nonce_fetch_count, [7])
+            self.assertEqual(queries,
+                             [(10, 0, "nonce=foo, frags=32", False),
+                              (10, 0, "nonce=foo, frags=16", False),
+                              (10, 0, "nonce=foo, limit=96", False),
+                              (10, 0, "nonce=foo, limit=48", False),
+                              (10, 0,
+                               "nonce=foo, limit=49, addr.0=1.2.3.4:23, last.0=40",
+                               False),
+                              (10, 0,
+                               "nonce=foo, limit=51, addr.0=1.2.3.4:23, "
+                               "last.0=41, addr.1=1.2.3.4:23, last.1=40", False),
+                              (10, 0,
+                               "nonce=foo, limit=52, addr.0=10.20.30.40:23, "
+                               "last.0=42, addr.1=1.2.3.4:23, last.1=41, "
+                               "addr.2=1.2.3.4:23, last.2=40", False)])
+            self.assertEqual(len(result.entries), 2)
+            self.assertEqual(logjig.data,
+                             ["1970-01-01T00:00:00Z Frag limit reduced to 16 "
+                              "following incomplete response.\n",
+                              "1970-01-01T00:00:00Z Reverted to row limit "
+                              "from fragments limit.\n",
+                              "1970-01-01T00:00:00Z Row limit reduced to 48 "
+                              "following  incomplete response.\n"])
+            # Test timeout error
+            nonce_fetch_count = [0]
+            query_results = qrm[:]
+            queries = []
+            query_fail = [3]
+            query_fail_code = [ntpp.SERR_TIMEOUT,
+                               ntp.control.CERR_BADVALUE,  # Trigger cap_frags
+                               ntpp.SERR_TIMEOUT]
+            cls.response = ""
+            logjig.data = []
+            cls.debug = 1
+            result = cls.mrulist()
+            self.assertEqual(nonce_fetch_count, [7])
+            self.assertEqual(queries,
+                             [(10, 0, "nonce=foo, frags=32", False),
+                              (10, 0, "nonce=foo, frags=16", False),
+                              (10, 0, "nonce=foo, limit=96", False),
+                              (10, 0, "nonce=foo, limit=48", False),
+                              (10, 0,
+                               "nonce=foo, limit=49, addr.0=1.2.3.4:23, last.0=40",
+                               False),
+                              (10, 0,
+                               "nonce=foo, limit=51, addr.0=1.2.3.4:23, "
+                               "last.0=41, addr.1=1.2.3.4:23, last.1=40", False),
+                              (10, 0,
+                               "nonce=foo, limit=52, addr.0=10.20.30.40:23, "
+                               "last.0=42, addr.1=1.2.3.4:23, last.1=41, "
+                               "addr.2=1.2.3.4:23, last.2=40", False)])
+            self.assertEqual(len(result.entries), 2)
+            self.assertEqual(logjig.data,
+                             ["1970-01-01T00:00:00Z Frag limit reduced to 16 "
+                              "following incomplete response.\n",
+                              "1970-01-01T00:00:00Z Reverted to row limit "
+                              "from fragments limit.\n",
+                              "1970-01-01T00:00:00Z Row limit reduced to 48 "
+                              "following  incomplete response.\n"])
+        finally:
+            ntp.util.time = timetemp
 
     def test___ordlist(self):
         queries = []


=====================================
tests/pylib/test_util.py
=====================================
--- a/tests/pylib/test_util.py
+++ b/tests/pylib/test_util.py
@@ -35,6 +35,7 @@ class TestPylibUtilMethods(unittest.TestCase):
     def test_dolog(self):
         f = ntp.util.dolog
 
+        faketimemod = jigs.TimeModuleJig()
         # We need a test jig
         class LogTester:
             def __init__(self):
@@ -48,16 +49,23 @@ class TestPylibUtilMethods(unittest.TestCase):
 
             def flush(self):
                 self.flushed = True
-        # Test with logging off (fd == None)
-        #   uh... if someone can think of a way to do that please tell me
-        # Test with logging on, below threshold
-        jig = LogTester()
-        f(jig, "blah", 0, 3)
-        self.assertEqual((jig.written, jig.flushed), (None, False))
-        # Test with logging on, above threshold
-        jig.__init__()  # reset
-        f(jig, "blah", 4, 3)
-        self.assertEqual((jig.written, jig.flushed), ("blah", True))
+        try:
+            timetemp = ntp.util.time
+            ntp.util.time = faketimemod
+            # Test with logging off (fd == None)
+            #   uh... if someone can think of a way to do that please tell me
+            # Test with logging on, below threshold
+            jig = LogTester()
+            faketimemod.time_returns = [0, 1]
+            f(jig, "blah", 0, 3)
+            self.assertEqual((jig.written, jig.flushed), (None, False))
+            # Test with logging on, above threshold
+            jig.__init__()  # reset
+            f(jig, "blah", 4, 3)
+            self.assertEqual((jig.written, jig.flushed),
+                             ("1970-01-01T00:00:01Z blah\n", True))
+        finally:
+            ntp.util.time = timetemp
 
     def test_safeargcast(self):
         f = ntp.util.safeargcast



View it on GitLab: https://gitlab.com/NTPsec/ntpsec/commit/068bd1b770c918ea6aef54a44130227c8c76d12d

---
View it on GitLab: https://gitlab.com/NTPsec/ntpsec/commit/068bd1b770c918ea6aef54a44130227c8c76d12d
You're receiving this email because of your account on gitlab.com.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.ntpsec.org/pipermail/vc/attachments/20180311/a89546a6/attachment.html>


More information about the vc mailing list