Continued:

- rewrote more f-masked logger messages to lazy '%'
- also made them more common (see EXIT!, ABORT!)

diff --git a/fba/http/federation.py b/fba/http/federation.py
index f9565da222e1cb54ee3f488dcbbb02821a633d14..e87b72655b69413c7935700801ec066f74e1981d 100644 (file)
--- a/fba/http/federation.py
+++ b/fba/http/federation.py
@@ -214,7 +214,7 @@ def fetch_peers(domain: str, software: str) -> list:
     logger.debug("Adding %d for domain='%s'", len(peers), domain)
     instances.set_total_peers(domain, peers)
 
-    logger.debug("Returning peers[]='%s' - EXIT!", type(peers))
+    logger.debug("peers()=%d - EXIT!", len(peers))
     return peers
 
 def fetch_nodeinfo(domain: str, path: str = None) -> dict:

diff --git a/fba/models/blocks.py b/fba/models/blocks.py
index 51036fc37203879a438f7fbe8a5d7df96576dc07..d659d4f479014a2f20ae55b18be39976f68a7553 100644 (file)
--- a/fba/models/blocks.py
+++ b/fba/models/blocks.py
@@ -28,7 +28,7 @@ logging.basicConfig(level=logging.INFO)
 logger = logging.getLogger(__name__)
 
 def update_reason(reason: str, blocker: str, blocked: str, block_level: str):
-    logger.debug(f"reason='{reason}',blocker={blocker},blocked={blocked},block_level={block_level} - CALLED!")
+    logger.debug("reason='%s',blocker='%s',blocked='%s',block_level='%s' - CALLED!", reason, blocker, blocked, block_level)
     if not isinstance(reason, str) and reason is not None:
         raise ValueError(f"Parameter reason[]='{type(reason)}' is not 'str'")
     elif not isinstance(blocker, str):
@@ -50,7 +50,7 @@ def update_reason(reason: str, blocker: str, blocked: str, block_level: str):
     elif block_level == "accept":
         raise ValueError("Accepted domains are not wanted here")
 
-    logger.debug("Updating block reason:", reason, blocker, blocked, block_level)
+    logger.debug("Updating block reason='%s',blocker='%s',blocked='%s',block_level='%s'", reason, blocker, blocked, block_level)
     database.cursor.execute(
         "UPDATE blocks SET reason = ?, last_seen = ? WHERE blocker = ? AND blocked = ? AND block_level = ? AND (reason IS NULL OR reason = '') LIMIT 1",
         [
@@ -64,7 +64,7 @@ def update_reason(reason: str, blocker: str, blocked: str, block_level: str):
     logger.debug("EXIT!")
 
 def update_last_seen(blocker: str, blocked: str, block_level: str):
-    logger.debug("Updating last_seen for:", blocker, blocked, block_level)
+    logger.debug("blocker='%s',blocked='%s',block_level='%s' - CALLED!", blocker, blocked, block_level)
     if not isinstance(blocker, str):
         raise ValueError(f"Parameter blocker[]='{type(blocker)}' is not 'str'")
     elif blocker == "":
@@ -96,7 +96,7 @@ def update_last_seen(blocker: str, blocked: str, block_level: str):
     logger.debug("EXIT!")
 
 def is_instance_blocked(blocker: str, blocked: str, block_level: str) -> bool:
-    logger.debug(f"blocker={blocker},blocked={blocked},block_level={block_level} - CALLED!")
+    logger.debug("blocker='%s',blocked='%s',block_level='%s' - CALLED!", blocker, blocked, block_level)
     if not isinstance(blocker, str):
         raise ValueError(f"Parameter blocker[]='{type(blocker)}' is not of type 'str'")
     elif blocker == "":
@@ -127,11 +127,11 @@ def is_instance_blocked(blocker: str, blocked: str, block_level: str) -> bool:
 
     is_blocked = database.cursor.fetchone() is not None
 
-    logger.debug(f"is_blocked='{is_blocked}' - EXIT!")
+    logger.debug("is_blocked='%s' - EXIT!", is_blocked)
     return is_blocked
 
 def add_instance(blocker: str, blocked: str, reason: str, block_level: str):
-    logger.debug("blocker,blocked,reason,block_level:", blocker, blocked, reason, block_level)
+    logger.debug("blocker='%s',blocked='%s',reason='%s',block_level='%s' - CALLED!", blocker, blocked, reason, block_level)
     if not isinstance(blocker, str):
         raise ValueError(f"Parameter blocker[]='{type(blocker)}' is not 'str'")
     elif blocker == "":

diff --git a/fba/models/error_log.py b/fba/models/error_log.py
index ed1f89fd7720946a41d8850cdb14855ba334aa89..8e3b693ca07f58e750b98c0eca5c76e3337e8ee3 100644 (file)
--- a/fba/models/error_log.py
+++ b/fba/models/error_log.py
@@ -27,7 +27,7 @@ logging.basicConfig(level=logging.INFO)
 logger = logging.getLogger(__name__)
 
 def add(domain: str, error: dict):
-    logger.debug("domain,error[]:", domain, type(error))
+    logger.debug("domain='%s',error[]='%s' - CALLED!", domain, type(error))
     if not isinstance(domain, str):
         raise ValueError(f"Parameter domain[]='{type(domain)}' is not 'str'")
     elif domain == "":
@@ -44,11 +44,11 @@ def add(domain: str, error: dict):
         logger.debug("Writing to error_log is disabled in configuruation file - EXIT!")
         return
 
-    logger.debug("BEFORE error[]:", type(error))
+    logger.debug("error[]='%s' - BEFORE!", type(error))
     if isinstance(error, BaseException, error, json.decoder.JSONDecodeError):
         error = f"error[{type(error)}]='{str(error)}'"
+    logger.debug("error[]='%s' - AFTER!", type(error))
 
-    logger.debug("AFTER error[]:", type(error))
     if isinstance(error, str):
         database.cursor.execute("INSERT INTO error_log (domain, error_code, error_message, created) VALUES (?, 999, ?, ?)",[
             domain,
@@ -64,7 +64,7 @@ def add(domain: str, error: dict):
         ])
 
     # Cleanup old entries
-    logger.debug(f"Purging old records (distance: {config.get('error_log_cleanup')})")
+    logger.debug("Purging old records (distance: %d)", config.get('error_log_cleanup'))
     database.cursor.execute("DELETE FROM error_log WHERE created < ?", [time.time() - config.get("error_log_cleanup")])
 
     logger.debug("EXIT!")

diff --git a/fba/networks/lemmy.py b/fba/networks/lemmy.py
index a26fe15bccfb2ce1486328200e14bb46ec5574ca..1b8c6d23b5616f5ad9e9122fb007ef2c84d7d24c 100644 (file)
--- a/fba/networks/lemmy.py
+++ b/fba/networks/lemmy.py
@@ -60,12 +60,12 @@ def fetch_peers(domain: str) -> list:
         logger.debug("Checking CSRF for domain='%s'", domain)
         headers = csrf.determine(domain, dict())
     except network.exceptions as exception:
-        logger.warning(f"Exception '{type(exception)}' during checking CSRF (fetch_peers,{__name__}) - EXIT!")
+        logger.warning("Exception '%s' during checking CSRF (fetch_peers,%s) - EXIT!", type(exception), __name__)
         instances.set_last_error(domain, exception)
         return peers
 
     try:
-        logger.debug(f"domain='{domain}' is Lemmy, fetching JSON ...")
+        logger.debug("Fetching '/api/v3/site' from domain='%s' ...", domain)
         data = network.get_json_api(
             domain,
             "/api/v3/site",
@@ -75,10 +75,10 @@ def fetch_peers(domain: str) -> list:
 
         logger.debug("data[]='%s'", type(data))
         if "error_message" in data:
-            logger.warning("Could not reach any JSON API:", domain)
+            logger.warning("Could not reach any JSON API: domain='%s'", domain)
             instances.set_last_error(domain, data)
         elif "federated_instances" in data["json"] and isinstance(data["json"]["federated_instances"], dict):
-            logger.debug(f"Found federated_instances for domain='{domain}'")
+            logger.debug("Found federated_instances for domain='%s'", domain)
             peers = peers + federation.add_peers(data["json"]["federated_instances"])
             logger.debug("Added instance(s) to peers")
         else:
@@ -86,13 +86,13 @@ def fetch_peers(domain: str) -> list:
             instances.set_last_error(domain, data)
 
     except network.exceptions as exception:
-        logger.warning(f"Exception during fetching JSON: domain='{domain}',exception[{type(exception)}]:'{str(exception)}'")
+        logger.warning("Exception during fetching JSON: domain='%s',exception[%s]:'%s'", domain, type(exception), str(exception))
         instances.set_last_error(domain, exception)
 
-    logger.debug(f"Adding '{len(peers)}' for domain='{domain}'")
+    logger.debug("Adding %d for domain='%s'", len(peers), domain)
     instances.set_total_peers(domain, peers)
 
-    logger.debug("Returning peers[]:", type(peers))
+    logger.debug("peers()=%d - EXIT!", len(peers))
     return peers
 
 def fetch_blocks(domain: str, origin: str, nodeinfo_url: str):

diff --git a/fba/networks/misskey.py b/fba/networks/misskey.py
index 239814ceb1a68876d5f7acd9d97be3784492d6d2..1d6fbb438a18ff4303731d6ed4313d37184358c3 100644 (file)
--- a/fba/networks/misskey.py
+++ b/fba/networks/misskey.py
@@ -47,10 +47,10 @@ def fetch_peers(domain: str) -> list:
     elif domain.endswith(".tld"):
         raise ValueError(f"domain='{domain}' is a fake domain, please don't crawl them!")
 
-    logger.debug(f"domain='{domain}' is misskey, sending API POST request ...")
-    peers   = list()
-    offset  = 0
-    step    = config.get("misskey_limit")
+    logger.debug("domain='%s' is misskey, sending API POST request ...", domain)
+    peers  = list()
+    offset = 0
+    step   = config.get("misskey_limit")
 
     # No CSRF by default, you don't have to add network.api_headers by yourself here
     headers = tuple()
@@ -59,7 +59,7 @@ def fetch_peers(domain: str) -> list:
         logger.debug("Checking CSRF for domain='%s'", domain)
         headers = csrf.determine(domain, dict())
     except network.exceptions as exception:
-        logger.warning(f"Exception '{type(exception)}' during checking CSRF (fetch_peers,{__name__}) - EXIT!")
+        logger.warning("Exception '%s' during checking CSRF (fetch_peers,%s) - EXIT!", type(exception), __name__)
         instances.set_last_error(domain, exception)
         return peers
 
@@ -67,7 +67,7 @@ def fetch_peers(domain: str) -> list:
     # instances page-by-page, since that troonware doesn't support
     # sending them all at once
     while True:
-        logger.debug(f"Fetching offset='{offset}' from '{domain}' ...")
+        logger.debug("Fetching offset='%d' from domain='%s' ...", offset, domain)
         if offset == 0:
             fetched = network.post_json_api(domain, "/api/federation/instances", json.dumps({
                 "sort" : "+pubAt",
@@ -85,56 +85,56 @@ def fetch_peers(domain: str) -> list:
         # Check records
         logger.debug("fetched[]='%s'", type(fetched))
         if "error_message" in fetched:
-            logger.warning(f"post_json_api() for domain='{domain}' returned error message: {fetched['error_message']}")
+            logger.warning("post_json_api() for domain='%s' returned error message: '%s'", domain, fetched['error_message'])
             instances.set_last_error(domain, fetched)
             break
         elif isinstance(fetched["json"], dict) and "error" in fetched["json"] and "message" in fetched["json"]["error"]:
-            logger.warning(f"post_json_api() returned error: {fetched['error']['message']}")
+            logger.warning("post_json_api() returned error: '%s'", fetched['error']['message'])
             instances.set_last_error(domain, fetched["json"]["error"]["message"])
             break
 
         rows = fetched["json"]
 
-        logger.debug(f"rows()={len(rows)}")
+        logger.debug("rows(%d)[]='%s'", len(rows), type(rows))
         if len(rows) == 0:
-            logger.debug(f"Returned zero bytes, exiting loop, domain='{domain}'")
+            logger.debug("Returned zero bytes, domain='%s' - BREAK!", domain)
             break
         elif len(rows) != config.get("misskey_limit"):
-            logger.debug(f"Fetched '{len(rows)}' row(s) but expected: '{config.get('misskey_limit')}'")
+            logger.debug("Fetched %d row(s) but expected: %d", len(rows), config.get('misskey_limit'))
             offset = offset + (config.get("misskey_limit") - len(rows))
         else:
-            logger.debug(f"Raising offset by step={step}")
+            logger.debug("Raising offset by step='%d'", step)
             offset = offset + step
 
         already = 0
-        logger.debug(f"rows({len(rows)})[]='{type(rows)}'")
+        logger.debug("rows(%d))[]='%s'", len(rows), type(rows))
         for row in rows:
             logger.debug(f"row()={len(row)}")
             if "host" not in row:
-                logger.warning(f"row()={len(row)} does not contain key 'host': {row},domain='{domain}'")
+                logger.warning("row()=%d does not contain key 'host': row='%s',domain='%s' - SKIPPED!", len(row), row, domain)
                 continue
             elif not isinstance(row["host"], str):
-                logger.warning(f"row[host][]='{type(row['host'])}' is not 'str' - SKIPPED!")
+                logger.warning("row[host][]='%s' is not 'str' - SKIPPED!", type(row['host']))
                 continue
             elif not utils.is_domain_wanted(row["host"]):
-                logger.debug(f"row[host]='{row['host']}' is not wanted, domain='{domain}' - SKIPPED!")
+                logger.debug("row[host]='%s' is not wanted, domain='{domain}' - SKIPPED!", row['host'])
                 continue
             elif row["host"] in peers:
-                logger.debug(f"Not adding row[host]='{row['host']}', already found.")
+                logger.debug("Not adding row[host]='%s', already found - SKIPPED!", row['host'])
                 already = already + 1
                 continue
 
-            logger.debug(f"Adding peer: '{row['host']}'")
+            logger.debug("Adding peer: '%s'", row['host'])
             peers.append(row["host"])
 
         if already == len(rows):
-            logger.debug(f"Host returned same set of '{already}' instances, aborting loop!")
+            logger.debug("Host returned same set of %d instance(s) - BREAK!", already)
             break
 
-    logger.debug(f"Adding '{len(peers)}' for domain='{domain}'")
+    logger.debug("Adding %d for domain='%s'", len(peers), domain)
     instances.set_total_peers(domain, peers)
 
-    logger.debug(f"Returning peers[]='{type(peers)}'")
+    logger.debug("peers()=%d - EXIT!", len(peers))
     return peers
 
 def fetch_blocks(domain: str) -> dict:
@@ -152,7 +152,7 @@ def fetch_blocks(domain: str) -> dict:
     elif domain.endswith(".tld"):
         raise ValueError(f"domain='{domain}' is a fake domain, please don't crawl them!")
 
-    logger.debug(f"Fetching misskey blocks from domain='{domain}'")
+    logger.debug("Fetching misskey blocks from domain='%s'", domain)
     blocklist = {
         "suspended": [],
         "blocked"  : []
@@ -168,7 +168,7 @@ def fetch_blocks(domain: str) -> dict:
         logger.debug("Checking CSRF for domain='%s'", domain)
         headers = csrf.determine(domain, dict())
     except network.exceptions as exception:
-        logger.warning(f"Exception '{type(exception)}' during checking CSRF (fetch_blocks,{__name__}) - EXIT!")
+        logger.warning("Exception '%s' during checking CSRF (fetch_blocks,%s) - EXIT!", type(exception), __name__)
         instances.set_last_error(domain, exception)
         return blocklist
 
@@ -176,7 +176,7 @@ def fetch_blocks(domain: str) -> dict:
     # instances page-by-page since it doesn't support sending them all at once
     while True:
         try:
-            logger.debug(f"Fetching offset='{offset}' from '{domain}' ...")
+            logger.debug("Fetching offset='%d' from domain='%s' ...", offset, domain)
             if offset == 0:
                 logger.debug("Sending JSON API request to domain,step,offset:", domain, step, offset)
                 fetched = network.post_json_api(domain, "/api/federation/instances", json.dumps({
@@ -197,31 +197,31 @@ def fetch_blocks(domain: str) -> dict:
 
             logger.debug("fetched[]='%s'", type(fetched))
             if "error_message" in fetched:
-                logger.warning(f"post_json_api() for domain='{domain}' returned error message: {fetched['error_message']}")
+                logger.warning("post_json_api() for domain='%s' returned error message: '%s'", domain, fetched['error_message'])
                 instances.set_last_error(domain, fetched)
                 break
             elif isinstance(fetched["json"], dict) and "error" in fetched["json"] and "message" in fetched["json"]["error"]:
-                logger.warning(f"post_json_api() returned error: {fetched['error']['message']}")
+                logger.warning("post_json_api() returned error: '%s'", fetched['error']['message'])
                 instances.set_last_error(domain, fetched["json"]["error"]["message"])
                 break
 
             rows = fetched["json"]
 
-            logger.debug(f"rows({len(rows)})={rows} - suspend")
+            logger.debug("rows(%d)[]='%s'", len(rows), type(rows))
             if len(rows) == 0:
-                logger.debug("Returned zero bytes, exiting loop:", domain)
+                logger.debug("Returned zero bytes, domain='%s' - BREAK!", domain)
                 break
             elif len(rows) != config.get("misskey_limit"):
-                logger.debug(f"Fetched '{len(rows)}' row(s) but expected: '{config.get('misskey_limit')}'")
+                logger.debug("Fetched %d row(s) but expected: %d", len(rows), config.get('misskey_limit'))
                 offset = offset + (config.get("misskey_limit") - len(rows))
             else:
-                logger.debug("Raising offset by step:", step)
+                logger.debug("Raising offset by step='%d'", step)
                 offset = offset + step
 
             count = 0
             for instance in rows:
                 # Is it there?
-                logger.debug(f"instance[{type(instance)}]='{instance}' - suspend")
+                logger.debug("instance[%s]='%s'", type(instance), instance)
                 if "isSuspended" in instance and instance["isSuspended"] and not dicts.has_key(blocklist["suspended"], "domain", instance["host"]):
                     count = count + 1
                     blocklist["suspended"].append({
@@ -230,13 +230,13 @@ def fetch_blocks(domain: str) -> dict:
                         "reason": None
                     })
 
-            logger.debug(f"count={count}")
+            logger.debug("count=%d", count)
             if count == 0:
-                logger.debug("API is no more returning new instances, aborting loop!")
+                logger.debug("API is no more returning new instances, aborting loop! domain='%s'", domain)
                 break
 
         except network.exceptions as exception:
-            logger.warning(f"Caught error, exiting loop: domain='{domain}',exception[{type(exception)}]='{str(exception)}'")
+            logger.warning("Caught error, exiting loop: domain='%s',exception[%s]='%s'", domain, type(exception), str(exception))
             instances.set_last_error(domain, exception)
             offset = 0
             break
@@ -245,7 +245,7 @@ def fetch_blocks(domain: str) -> dict:
         # Fetch blocked (full suspended) instances
         try:
             if offset == 0:
-                logger.debug("Sending JSON API request to domain,step,offset:", domain, step, offset)
+                logger.debug("Sending JSON API request to domain='%s',step='%d',offset='%d'", domain, step, offset)
                 fetched = network.post_json_api(domain, "/api/federation/instances", json.dumps({
                     "sort"   : "+pubAt",
                     "host"   : None,
@@ -253,7 +253,7 @@ def fetch_blocks(domain: str) -> dict:
                     "limit"  : step
                 }), headers)
             else:
-                logger.debug("Sending JSON API request to domain,step,offset:", domain, step, offset)
+                logger.debug("Sending JSON API request to domain='%s',step='%d',offset='%d'", domain, step, offset)
                 fetched = network.post_json_api(domain, "/api/federation/instances", json.dumps({
                     "sort"   : "+pubAt",
                     "host"   : None,
@@ -264,31 +264,31 @@ def fetch_blocks(domain: str) -> dict:
 
             logger.debug("fetched[]='%s'", type(fetched))
             if "error_message" in fetched:
-                logger.warning(f"post_json_api() for domain='{domain}' returned error message: {fetched['error_message']}")
+                logger.warning("post_json_api() for domain='%s' returned error message: '%s'", domain, fetched['error_message'])
                 instances.set_last_error(domain, fetched)
                 break
             elif isinstance(fetched["json"], dict) and "error" in fetched["json"] and "message" in fetched["json"]["error"]:
-                logger.warning(f"post_json_api() returned error: {fetched['error']['message']}")
+                logger.warning("post_json_api() returned error: '%s'", fetched['error']['message'])
                 instances.set_last_error(domain, fetched["json"]["error"]["message"])
                 break
 
             rows = fetched["json"]
 
-            logger.debug(f"rows({len(rows)})={rows} - blocked")
+            logger.debug("rows(%d)[]='%s'", len(rows), type(rows))
             if len(rows) == 0:
-                logger.debug("Returned zero bytes, exiting loop:", domain)
+                logger.debug("Returned zero bytes, domain='%s' - BREAK!", domain)
                 break
             elif len(rows) != config.get("misskey_limit"):
-                logger.debug(f"Fetched '{len(rows)}' row(s) but expected: '{config.get('misskey_limit')}'")
+                logger.debug("Fetched %d row(s) but expected: '{config.get('misskey_limit')}'", len(rows))
                 offset = offset + (config.get("misskey_limit") - len(rows))
             else:
-                logger.debug("Raising offset by step:", step)
+                logger.debug("Raising offset by step='%d'", step)
                 offset = offset + step
 
             count = 0
             for instance in rows:
                 # Is it there?
-                logger.debug(f"instance[{type(instance)}]='{instance}' - blocked")
+                logger.debug("instance[%s]='%s'", type(instance), instance)
                 if "isBlocked" in instance and instance["isBlocked"] and not dicts.has_key(blocklist["blocked"], "domain", instance["host"]):
                     count = count + 1
                     blocklist["blocked"].append({
@@ -296,18 +296,18 @@ def fetch_blocks(domain: str) -> dict:
                         "reason": None
                     })
 
-            logger.debug(f"count={count}")
+            logger.debug("count=%d", count)
             if count == 0:
                 logger.debug("API is no more returning new instances, aborting loop!")
                 break
 
         except network.exceptions as exception:
-            logger.warning(f"Caught error, exiting loop: domain='{domain}',exception[{type(exception)}]='{str(exception)}'")
+            logger.warning("Caught error, exiting loop: domain='%s',exception[%s]='%s'", domain, type(exception), str(exception))
             instances.set_last_error(domain, exception)
             offset = 0
             break
 
-    logger.debug(f"Returning for domain='{domain}',blocked()={len(blocklist['blocked'])},suspended()={len(blocklist['suspended'])}")
+    logger.debug("blocked()=%d,suspended()=%d - EXIT!", len(blocklist['blocked']), len(blocklist['suspended']))
     return {
         "reject"        : blocklist["blocked"],
         "followers_only": blocklist["suspended"]