From 72b084e8f06e3e7607942ac6411326bab09e114c Mon Sep 17 00:00:00 2001 From: spalen0 Date: Tue, 23 Jun 2026 16:29:39 +0200 Subject: [PATCH] refactor(logging): consolidate multi-line log blocks and quiet third-party loggers MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Stat/header output emitted one logger call per line, repeating the `[ts] LEVEL name:` prefix on every row. Combine each consecutive same-level block into a single record with embedded newlines so the prefix shows once while line breaks stay readable. Touches gauntlet, compound, usdai, infinifi, ethena, origin (lrt-pegs), safe, bad-debt, and yearn shadow-debt paths. Add toggleable suppression of noisy third-party loggers (web3, urllib3, requests, …) in utils/logger.py via `quiet_dependency_loggers()`: capped at WARNING by default so they don't bury our own output, applied on import so every protocol subprocess inherits it. Controlled by the new DEP_LOG_LEVEL env var (set DEBUG/TRACE to bring the chatter back). Also called from the two root-configuring entrypoints (automation CLI, alert_large_flows) which use plain `logging.basicConfig`. Co-Authored-By: Claude Opus 4.8 --- automation/__main__.py | 4 +++ protocols/bad-debt/bad-debt-trigger.py | 3 +- protocols/compound/collateral.py | 23 ++++++++------ protocols/ethena/ethena.py | 13 +++++--- protocols/infinifi/main.py | 16 +++++----- protocols/lrt-pegs/origin_protocol.py | 12 ++++++-- protocols/safe/main.py | 3 +- protocols/usdai/main.py | 18 +++++++---- protocols/yearn/alert_large_flows.py | 4 +++ protocols/yearn/check_shadow_debt.py | 18 +++++------ utils/gauntlet.py | 21 +++++++------ utils/logger.py | 42 ++++++++++++++++++++++++++ 12 files changed, 123 insertions(+), 54 deletions(-) diff --git a/automation/__main__.py b/automation/__main__.py index 4bbd8d64..bb6ed42e 100644 --- a/automation/__main__.py +++ b/automation/__main__.py @@ -26,8 +26,12 @@ def _configure_logging() -> None: import os + from utils.logger import quiet_dependency_loggers + level = os.environ.get("LOG_LEVEL", "INFO").upper() logging.basicConfig(level=level, format="%(asctime)s %(levelname)s %(name)s: %(message)s") + # Keep web3/urllib3 chatter out of the orchestrator logs; DEP_LOG_LEVEL re-enables it. + quiet_dependency_loggers() def cmd_list(config: JobsConfig) -> int: diff --git a/protocols/bad-debt/bad-debt-trigger.py b/protocols/bad-debt/bad-debt-trigger.py index a105d4f8..f67fea9d 100644 --- a/protocols/bad-debt/bad-debt-trigger.py +++ b/protocols/bad-debt/bad-debt-trigger.py @@ -60,8 +60,7 @@ def get_data(): def send_telegram_message(message): - logger.info("Sending telegram message...") - logger.info("%s", message) + logger.info("Sending telegram message...\n%s", message) bot_token = os.getenv("BAD_DEBT_TELEGRAM_TOKEN") chat_id = os.getenv("BAD_DEBT_TELEGRAM_CHAT_ID") url = f"https://api.telegram.org/bot{bot_token}/sendMessage" diff --git a/protocols/compound/collateral.py b/protocols/compound/collateral.py index 13950c41..97f23be3 100644 --- a/protocols/compound/collateral.py +++ b/protocols/compound/collateral.py @@ -219,12 +219,15 @@ def _analyze_market(market: MarketData) -> list[str]: logger.info("Market %s has no collateral", market.name) return alerts - logger.info("Market: %s (risk level %d)", market.name, market.risk_level) - logger.info("Total supply: %s", format_usd(market.total_supply_usd)) - logger.info("Total borrow: %s", format_usd(market.total_borrow_usd)) - logger.info("Total collateral: %s", format_usd(total_collateral_usd)) - logger.debug("--------------------------------") - logger.debug("Asset | Supply | Allocation") + logger.info( + "Market: %s (risk level %d)\nTotal supply: %s\nTotal borrow: %s\nTotal collateral: %s", + market.name, + market.risk_level, + format_usd(market.total_supply_usd), + format_usd(market.total_borrow_usd), + format_usd(total_collateral_usd), + ) + logger.debug("--------------------------------\nAsset | Supply | Allocation") total_risk_level = 0.0 unknown_assets: list[str] = [] @@ -290,9 +293,11 @@ def _analyze_market(market: MarketData) -> list[str]: "Please update SUPPLY\\_ASSETS in utils/assets.py" ) - logger.info("Total risk level: %s", f"{total_risk_level:.1%}") - logger.info("Reserves: %s", format_usd(market.reserves_usd)) - logger.info("================================") + logger.info( + "Total risk level: %s\nReserves: %s\n================================", + f"{total_risk_level:.1%}", + format_usd(market.reserves_usd), + ) return alerts diff --git a/protocols/ethena/ethena.py b/protocols/ethena/ethena.py index 9994d8dd..c2ab685d 100644 --- a/protocols/ethena/ethena.py +++ b/protocols/ethena/ethena.py @@ -53,8 +53,7 @@ def fetch_json(url: str) -> dict | None: try: resp = requests.get(url, timeout=REQUEST_TIMEOUT) if resp.status_code != 200: - logger.error("HTTP %s for %s", resp.status_code, url) - logger.error("%s", resp.text) + logger.error("HTTP %s for %s\n%s", resp.status_code, url, resp.text) return None return resp.json() except Exception as e: @@ -442,9 +441,13 @@ def chaos_labs_check(): # Calculate and report backing metrics for transparency backing_ratio = attestation.backing_assets_usd_value / attestation.total_supply reserve_buffer = attestation.backing_assets_and_reserve_fund_usd_value - attestation.total_supply - logger.info("Attestation from Chaos Labs: %s", attestation.timestamp) - logger.info("Backing Ratio: %s (%s%%)", f"{backing_ratio:.4f}", f"{backing_ratio * 100:,.2f}") - logger.info("Reserve Buffer: $%s", f"{reserve_buffer:,.2f}") + logger.info( + "Attestation from Chaos Labs: %s\nBacking Ratio: %s (%s%%)\nReserve Buffer: $%s", + attestation.timestamp, + f"{backing_ratio:.4f}", + f"{backing_ratio * 100:,.2f}", + f"{reserve_buffer:,.2f}", + ) if __name__ == "__main__": diff --git a/protocols/infinifi/main.py b/protocols/infinifi/main.py index 56ea2a36..fb338c81 100644 --- a/protocols/infinifi/main.py +++ b/protocols/infinifi/main.py @@ -153,8 +153,7 @@ def main(): # target_reserve_ratio = to_float(params.get("reserveRatio")) # target_illiquid_ratio = to_float(params.get("illiquidTargetRatio")) - logger.info("--- Infinifi Stats ---") - logger.info("iUSD Supply: $%s", f"{iusd_supply:,.2f}") + logger.info("--- Infinifi Stats ---\niUSD Supply: $%s", f"{iusd_supply:,.2f}") if liquid_reserves > 0: logger.info("Liquid Reserves: $%s", f"{liquid_reserves:,.2f}") @@ -171,8 +170,7 @@ def main(): logger.info("Total Backing: [Data Not Available]") if total_backing > 0: - logger.info("Liquid Ratio: %.2f%%", reserve_ratio * 100) - logger.info("Illiquid Ratio: %.2f%%", illiquid_ratio * 100) + logger.info("Liquid Ratio: %.2f%%\nIlliquid Ratio: %.2f%%", reserve_ratio * 100, illiquid_ratio * 100) if pending_redemptions > 0: logger.info("Pending Redeems: $%s", f"{pending_redemptions:,.2f}") @@ -386,9 +384,13 @@ def is_safe_farm(farm): if risky_exposure > 0: min_required = risky_exposure * JUNIOR_RISKY_COVERAGE_MIN - logger.info("Junior TVL: $%s", f"{junior_tvl:,.2f}") - logger.info("Risky Exposure: $%s", f"{risky_exposure:,.2f}") - logger.info("Min Required: $%s (%.0f%%)", f"{min_required:,.2f}", JUNIOR_RISKY_COVERAGE_MIN * 100) + logger.info( + "Junior TVL: $%s\nRisky Exposure: $%s\nMin Required: $%s (%.0f%%)", + f"{junior_tvl:,.2f}", + f"{risky_exposure:,.2f}", + f"{min_required:,.2f}", + JUNIOR_RISKY_COVERAGE_MIN * 100, + ) cache_key_junior_risky = f"{PROTOCOL}_junior_below_risky_breach" if junior_tvl < min_required: diff --git a/protocols/lrt-pegs/origin_protocol.py b/protocols/lrt-pegs/origin_protocol.py index ce510bcc..6d6bb39c 100644 --- a/protocols/lrt-pegs/origin_protocol.py +++ b/protocols/lrt-pegs/origin_protocol.py @@ -135,9 +135,15 @@ def process_origin(chain: Chain): redeem_value = metrics.redeem_value wrapped_oeth_redeem_value = metrics.wrapped_oeth_redeem_value - logger.info("Redeem value for OETH on %s: %s", chain.name, f"{redeem_value / 1e18:.6f}") - logger.info("Wrapped OETH redeem value on %s: %s", chain.name, f"{wrapped_oeth_redeem_value / 1e18:.6f}") - logger.info("Vault backing ratio on %s: %s", chain.name, f"{metrics.backing_ratio / 1e18:.6f}") + logger.info( + "Redeem value for OETH on %s: %s\nWrapped OETH redeem value on %s: %s\nVault backing ratio on %s: %s", + chain.name, + f"{redeem_value / 1e18:.6f}", + chain.name, + f"{wrapped_oeth_redeem_value / 1e18:.6f}", + chain.name, + f"{metrics.backing_ratio / 1e18:.6f}", + ) # Caching for wrapped OETH redeem value, if value is lower, send telegram message cache_key = get_cache_key(chain) diff --git a/protocols/safe/main.py b/protocols/safe/main.py index a13ff14d..cc782042 100644 --- a/protocols/safe/main.py +++ b/protocols/safe/main.py @@ -98,8 +98,7 @@ def get_safe_transactions( time.sleep(wait_time) continue else: - logger.error("Error: %s", response.status_code) - logger.error("Response text: %s", response.text) + logger.error("Error: %s\nResponse text: %s", response.status_code, response.text) return [] logger.error("Failed after %s retries for %s on %s", max_retries, safe_address, network_name) diff --git a/protocols/usdai/main.py b/protocols/usdai/main.py index 771e89f1..6744c32b 100644 --- a/protocols/usdai/main.py +++ b/protocols/usdai/main.py @@ -113,10 +113,13 @@ def main(): pyusd_assets_fmt = pyusd_assets_raw / (10**PYUSD_DECIMALS) pyusd_assets_18_raw = pyusd_assets_raw * (10 ** max(USDAI_DECIMALS - PYUSD_DECIMALS, 0)) - logger.info("--- USDai Stats ---") - logger.info("USDai Supply: $%s", f"{usdai_supply_fmt:,.2f}") - logger.info("USDai Bridged: $%s", f"{bridged_supply_fmt:,.2f}") - logger.info("%s Assets: $%s", PYUSD_SYMBOL, f"{pyusd_assets_fmt:,.2f}") + logger.info( + "--- USDai Stats ---\nUSDai Supply: $%s\nUSDai Bridged: $%s\n%s Assets: $%s", + f"{usdai_supply_fmt:,.2f}", + f"{bridged_supply_fmt:,.2f}", + PYUSD_SYMBOL, + f"{pyusd_assets_fmt:,.2f}", + ) # Invariant: # totalSupply + bridgedSupply <= pyUSD.balanceOf(USDai) (all in 1e18 scale) @@ -125,8 +128,11 @@ def main(): invariant_gap_fmt = invariant_gap_raw / (10**USDAI_DECIMALS) required_backing_fmt = required_backing_raw / (10**USDAI_DECIMALS) - logger.info("Required Backing: $%s (supply + bridged)", f"{required_backing_fmt:,.2f}") - logger.info("Invariant Gap: $%s (required - pyUSD assets)", f"{invariant_gap_fmt:,.2f}") + logger.info( + "Required Backing: $%s (supply + bridged)\nInvariant Gap: $%s (required - pyUSD assets)", + f"{required_backing_fmt:,.2f}", + f"{invariant_gap_fmt:,.2f}", + ) cache_key_invariant_breach = f"{PROTOCOL}_backing_invariant_breach" if invariant_gap_raw >= USDAI_INVARIANT_BREACH_THRESHOLD_RAW: diff --git a/protocols/yearn/alert_large_flows.py b/protocols/yearn/alert_large_flows.py index 36063f92..37e4badb 100644 --- a/protocols/yearn/alert_large_flows.py +++ b/protocols/yearn/alert_large_flows.py @@ -483,6 +483,10 @@ def main(): format="[%(name)s] %(levelname)s %(message)s", stream=sys.stderr, ) + # Keep web3/urllib3 chatter out; DEP_LOG_LEVEL re-enables it when debugging. + from utils.logger import quiet_dependency_loggers + + quiet_dependency_loggers() _logger.info( "start limit=%s threshold_usd=%s since_seconds=%s chain_ids=%s", args.limit, diff --git a/protocols/yearn/check_shadow_debt.py b/protocols/yearn/check_shadow_debt.py index 8be924a2..da8756ee 100644 --- a/protocols/yearn/check_shadow_debt.py +++ b/protocols/yearn/check_shadow_debt.py @@ -287,9 +287,7 @@ def print_summary(issues: List[ShadowDebtIssue]) -> None: Args: issues: List of shadow debt issues. """ - logger.info("=" * 80) - logger.info("SHADOW DEBT SUMMARY") - logger.info("=" * 80) + logger.info("=" * 80 + "\nSHADOW DEBT SUMMARY\n" + "=" * 80) # Group by chain issues_by_chain: Dict[Chain, List[ShadowDebtIssue]] = {} @@ -299,8 +297,7 @@ def print_summary(issues: List[ShadowDebtIssue]) -> None: issues_by_chain[issue.chain].append(issue) for chain, chain_issues in sorted(issues_by_chain.items(), key=lambda x: x[0].name): - logger.info("%s:", chain.name) - logger.info("-" * 80) + logger.info("%s:\n%s", chain.name, "-" * 80) for issue in chain_issues: shadow_debt_pct = ( @@ -310,14 +307,15 @@ def print_summary(issues: List[ShadowDebtIssue]) -> None: # Extract token name from vault symbol (e.g., "yvWETH" -> "WETH", "yvUSDC" -> "USDC") token_symbol = issue.vault_symbol.replace("yv", "").replace("yvault-", "") - logger.info(" Vault: %s (%s)", issue.vault_symbol, issue.vault_address) logger.info( - " Shadow Debt: %s %s (%s%% of total vault debt)", + " Vault: %s (%s)\n Shadow Debt: %s %s (%s%% of total vault debt)\n Affected Strategies: %d", + issue.vault_symbol, + issue.vault_address, format_amount(issue.total_shadow_debt, issue.vault_decimals), token_symbol, f"{shadow_debt_pct:.1f}", + len(issue.strategies_with_shadow_debt), ) - logger.info(" Affected Strategies: %d", len(issue.strategies_with_shadow_debt)) for strategy in issue.strategies_with_shadow_debt: logger.info( @@ -329,9 +327,7 @@ def print_summary(issues: List[ShadowDebtIssue]) -> None: logger.info("") - logger.info("=" * 80) - logger.info("Total: %d vault(s) with shadow debt issues", len(issues)) - logger.info("=" * 80) + logger.info("=" * 80 + "\nTotal: %d vault(s) with shadow debt issues\n" + "=" * 80, len(issues)) def build_alert_message(issues: List[ShadowDebtIssue]) -> str: diff --git a/utils/gauntlet.py b/utils/gauntlet.py index 91ca9ef1..ac6ff63f 100644 --- a/utils/gauntlet.py +++ b/utils/gauntlet.py @@ -146,12 +146,14 @@ def fetch_borrow_metrics_from_gauntlet( charts = charts["charts"] total_risk_level = 0.0 - logger.info("Market: %s", market_key) - logger.info("Assigned Risk Level: %s", vault_risk_level) - logger.info("Total supply: %s", format_usd(total_supply)) - logger.info("Total borrow: %s", format_usd(total_borrow)) - logger.debug("--------------------------------") - logger.debug("Asset | Supply | Allocation") + logger.info( + "Market: %s\nAssigned Risk Level: %s\nTotal supply: %s\nTotal borrow: %s", + market_key, + vault_risk_level, + format_usd(total_supply), + format_usd(total_borrow), + ) + logger.debug("--------------------------------\nAsset | Supply | Allocation") for chart in charts: if chart["key"] == "market_health_timeseries_asset_supply": @@ -200,8 +202,9 @@ def fetch_borrow_metrics_from_gauntlet( f"💸 Total borrow: {format_usd(total_borrow)}\n" ) - logger.info("--------------------------------") - logger.info("Total risk level: %s", f"{total_risk_level:.1%}") - logger.info("================================") + logger.info( + "--------------------------------\nTotal risk level: %s\n================================", + f"{total_risk_level:.1%}", + ) return alerts diff --git a/utils/logger.py b/utils/logger.py index 4d549d86..0c7689b0 100644 --- a/utils/logger.py +++ b/utils/logger.py @@ -8,6 +8,42 @@ load_dotenv() +# Third-party libraries that emit high-volume per-request / per-connection noise +# (e.g. `web3.manager.RequestManager Making request. Method: ...`). They're +# capped to their own level so our own output isn't buried. Quiet by default; +# bring the chatter back without touching our level via `DEP_LOG_LEVEL=DEBUG` +# (or any other level name) in the environment. +_DEPENDENCY_LOGGERS = ( + "web3", + "urllib3", + "requests", + "aiohttp", + "asyncio", + "websockets", + "hpack", + "httpx", + "httpcore", + "eth", + "ens", +) + + +def quiet_dependency_loggers(level: str | None = None) -> None: + """Cap noisy third-party loggers at `level` (default `DEP_LOG_LEVEL` env or + WARNING), leaving our own loggers untouched. + + Fully reversible — pass a lower level (e.g. ``DEP_LOG_LEVEL=DEBUG``) to + surface dependency output again. Idempotent and safe to call repeatedly. + + Args: + level: Level name to pin dependency loggers to. Falls back to the + ``DEP_LOG_LEVEL`` env var, then ``WARNING``. + """ + name = (level or os.getenv("DEP_LOG_LEVEL", "WARNING") or "WARNING").upper() + numeric = getattr(logging, name, logging.WARNING) + for logger_name in _DEPENDENCY_LOGGERS: + logging.getLogger(logger_name).setLevel(numeric) + def get_logger(name: str) -> logging.Logger: """Return a pre-configured logger for the given protocol or module name.""" @@ -20,3 +56,9 @@ def get_logger(name: str) -> logging.Logger: level = os.getenv("LOG_LEVEL", "INFO").upper() logger.setLevel(getattr(logging, level, logging.INFO)) return logger + + +# Apply once on import so every script (each protocol runs in its own +# subprocess that imports this module) inherits quiet dependency loggers, +# regardless of whether it configures the root logger via basicConfig. +quiet_dependency_loggers()