style: add logs in registry

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 = '-'
@@ -267,8 +268,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 +357,12 @@ class RegistryServer:
 
     def getCert(self, client_prefix):
         assert self.lock.locked()
-        return self.db.execute("SELECT cert FROM cert"
-                               " WHERE prefix=? AND cert IS NOT NULL",
-                               (client_prefix,)).fetchone()[0]
+        cert = self.db.execute("SELECT cert FROM cert"
+                                   " WHERE prefix=? AND cert IS NOT NULL",
+                               (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 +443,7 @@ class RegistryServer:
         return default
 
     def mergePrefixes(self):
+        logging.debug("Merging prefixes")
         q = self.db.execute
         prev_prefix = None
         max_len = 128,
@@ -459,6 +466,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 +506,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 +615,7 @@ class RegistryServer:
         return zlib.compress(json.dumps(config).encode("utf-8"))
 
     def _queryAddress(self, peer):
+        logging.info("Querying address for %s/%s", int(peer, 2), len(peer))
         self.sendto(peer, 1)
         s = self.sock,
         timeout = 3
@@ -613,6 +623,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: %s - %s", prefix, msg)
             if prefix == peer:
                 return msg
             timeout = max(0, end - time.time())
@@ -626,6 +637,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 +649,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 +659,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:
@@ -775,7 +789,8 @@ class RegistryServer:
         return json.dumps(peer_dict)
 
     @rpc_private
-    def topology(self):
+    def topology(self) -> str:
+        logging.debug("Computing topology")
         p = lambda p: '%s/%s' % (int(p, 2), len(p))
         peers = deque((p(self.prefix),))
         graph = defaultdict(set)
@@ -785,6 +800,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 and x:
                         prefix = p(prefix)
                         x = x.split()
@@ -799,8 +815,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()})