From bef653839181fa658bc1810822b8b9086c9e0f10 Mon Sep 17 00:00:00 2001 From: =?utf8?q?Roland=20H=C3=A4der?= Date: Thu, 22 Jun 2023 00:01:52 +0200 Subject: [PATCH] Continued: - rewrote more f-masked logger messages to lazy '%' - also made them more common (see EXIT!, ABORT!) --- fba/http/federation.py | 2 +- fba/models/blocks.py | 12 +++--- fba/models/error_log.py | 8 ++-- fba/networks/lemmy.py | 14 +++---- fba/networks/misskey.py | 92 ++++++++++++++++++++--------------------- 5 files changed, 64 insertions(+), 64 deletions(-) diff --git a/fba/http/federation.py b/fba/http/federation.py index f9565da..e87b726 100644 --- 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 51036fc..d659d4f 100644 --- 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 ed1f89f..8e3b693 100644 --- 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 a26fe15..1b8c6d2 100644 --- 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 239814c..1d6fbb4 100644 --- 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"] -- 2.39.5