More logs

re6st/ctl.py

@@ -252,15 +252,18 @@ class Babel:
         unidentified = set(n)
         self.neighbours = neighbours = {}
         a = len(self.network)
+        logging.info("Routes: %r", routes)
         for route in routes:
             assert route.flags & 1, route # installed
             if route.prefix.startswith(b'\0\0\0\0\0\0\0\0\0\0\xff\xff'):
+                logging.warning("Ignoring IPv4 route: %r", route)
                 continue
             assert route.neigh_address == route.nexthop, route
             address = route.neigh_address, route.ifindex
             neigh_routes = n[address]
             ip = utils.binFromRawIp(route.prefix)
             if ip[:a] == self.network:
+                logging.debug("Route is on the network: %r", route)
                 prefix = ip[a:route.plen]
                 if prefix and not route.refmetric:
                     neighbours[prefix] = neigh_routes
@@ -275,7 +278,9 @@ class Babel:
                             socket.inet_ntop(socket.AF_INET6, route.prefix),
                             route.plen)
             else:
+                logging.debug("Route is not on the network: %r", route)
                 prefix = None
+            logging.debug("Adding route %r to %r", route, neigh_routes)
             neigh_routes[1][prefix] = route
         self.locked.clear()
         if unidentified:

re6st/registry.py

@@ -102,6 +102,7 @@ class RegistryServer:
                 "email TEXT",
                 "cert TEXT")
         if not self.db.execute("SELECT 1 FROM cert LIMIT 1").fetchone():
+            logging.debug("No existing certs found; creating an unallocated cert")
             self.db.execute("INSERT INTO cert VALUES ('',null,null)")
 
         prev = '-'
@@ -214,6 +215,7 @@ class RegistryServer:
         else:
             if len(msg) >= 1 and msg[0] == code:
                 return prefix.decode(), msg[1:].decode()
+            logging.error("Invalid message or unexpected code: %r", msg)
         return None, None
 
     def select(self, r, w, t):
@@ -267,8 +269,10 @@ class RegistryServer:
                 x = x509.notAfter(cert)
                 if x <= old:
                     if prefix == self.prefix:
-                        logging.critical("Refuse to delete certificate"
-                                         " of main node: wrong clock ?")
+                        logging.critical(
+                            "Refuse to delete certificate of main node:"
+                            " wrong clock ? Alternatively, the database"
+                            " might be in an inconsistent state.")
                         sys.exit(1)
                     logging.info("Delete %s: %s (invalid since %s)",
                         "certificate requested by '%s'" % email
@@ -354,9 +358,12 @@ class RegistryServer:
 
     def getCert(self, client_prefix):
         assert self.lock.locked()
-        return self.db.execute("SELECT cert FROM cert"
+        cert = self.db.execute("SELECT cert FROM cert"
                                " WHERE prefix=? AND cert IS NOT NULL",
-                               (client_prefix,)).fetchone()[0]
+                               (client_prefix,)).fetchone()
+        assert cert, (f"No cert result for prefix '{client_prefix}';"
+                      f" this should not happen, DB is inconsistent")
+        return cert[0]
 
     @rpc_private
     def isToken(self, token):
@@ -437,6 +444,7 @@ class RegistryServer:
         return default
 
     def mergePrefixes(self):
+        logging.debug("Merging prefixes")
         q = self.db.execute
         prev_prefix = None
         max_len = 128,
@@ -459,6 +467,7 @@ class RegistryServer:
                     prev_prefix = prefix
 
     def newPrefix(self, prefix_len, community):
+        logging.info("Allocating /%u prefix for %s", prefix_len, community)
         community_len = len(community)
         prefix_len += community_len
         max_len = 128 - len(self.network)
@@ -498,6 +507,7 @@ class RegistryServer:
 
     @rpc
     def requestCertificate(self, token, req, location='', ip=''):
+        logging.debug("Requesting certificate with token %s", token)
         req = crypto.load_certificate_request(crypto.FILETYPE_PEM, req)
         with self.lock:
             with self.db:
@@ -606,6 +616,8 @@ class RegistryServer:
         return zlib.compress(json.dumps(config).encode("utf-8"))
 
     def _queryAddress(self, peer):
+        logging.info("Querying address for %s/%s %r",
+                     int(peer, 2), len(peer), peer)
         self.sendto(peer, 1)
         s = self.sock,
         timeout = 3
@@ -613,6 +625,7 @@ class RegistryServer:
         # Loop because there may be answers from previous requests.
         while select.select(s, (), (), timeout)[0]:
             prefix, msg = self.recv(1)
+            logging.info("* received: %r - %r", prefix, msg)
             if prefix == peer:
                 return msg
             timeout = max(0, end - time.time())
@@ -626,6 +639,7 @@ class RegistryServer:
 
     @rpc
     def getBootstrapPeer(self, cn):
+        logging.info("Answering bootstrap peer for %s", cn)
         with self.peers_lock:
             age, peers = self.peers
             if age < time.time() or not peers:
@@ -637,6 +651,7 @@ class RegistryServer:
                 peers.append(self.prefix)
                 random.shuffle(peers)
                 self.peers = time.time() + 60, peers
+            logging.debug("peers: %r", peers)
             peer = peers.pop()
             if peer == cn:
                 # Very unlikely (e.g. peer restarted with empty cache),
@@ -646,6 +661,7 @@ class RegistryServer:
         with self.lock:
             msg = self._queryAddress(peer)
             if msg is None:
+                logging.info("No address for %s, returning None", peer)
                 return
             # Remove country for old nodes
             if self.getPeerProtocol(cn) < 7:
@@ -776,6 +792,7 @@ class RegistryServer:
 
     @rpc_private
     def topology(self):
+        logging.debug("Computing topology")
         p = lambda p: '%s/%s' % (int(p, 2), len(p))
         peers = deque((p(self.prefix),))
         graph = defaultdict(set)
@@ -785,6 +802,7 @@ class RegistryServer:
                 r, w, _ = select.select(s, s if peers else (), (), 3)
                 if r:
                     prefix, x = self.recv(5)
+                    logging.debug("Received %s %s", prefix, x)
                     if prefix:
                         prefix = p(prefix)
                         x = x.split()
@@ -799,8 +817,11 @@ class RegistryServer:
                                 graph[x].add(prefix)
                             graph[''].add(prefix)
                 if w:
-                    self.sendto(utils.binFromSubnet(peers.popleft()), 5)
+                    first = peers.popleft()
+                    logging.debug("Sending %s", first)
+                    self.sendto(utils.binFromSubnet(first), 5)
                 elif not r:
+                    logging.debug("No more sockets, stopping")
                     break
         return json.dumps({k: list(v) for k, v in graph.items()})