From f1c2b417144fa159d87864f150264d2565e6f45d Mon Sep 17 00:00:00 2001 From: tecnovert Date: Sat, 22 Feb 2025 15:54:13 +0000 Subject: [PATCH] Add safe_logs option to anonymise logs. (#264) * Add safe_logs option to anonymise logs. * Extend logger class. --- basicswap/base.py | 6 +- basicswap/basicswap.py | 1139 ++++++++++++----------------- basicswap/interface/bch.py | 72 +- basicswap/interface/btc.py | 81 +- basicswap/interface/dcr/dcr.py | 63 +- basicswap/interface/firo.py | 4 +- basicswap/interface/nav.py | 57 +- basicswap/interface/part.py | 27 +- basicswap/interface/xmr.py | 18 +- basicswap/protocols/xmr_swap_1.py | 7 +- basicswap/util/crypto.py | 8 +- basicswap/util/logging.py | 42 ++ tests/basicswap/test_btc_xmr.py | 16 + 13 files changed, 735 insertions(+), 805 deletions(-) create mode 100644 basicswap/util/logging.py diff --git a/basicswap/base.py b/basicswap/base.py index be05b91..09ecb4b 100644 --- a/basicswap/base.py +++ b/basicswap/base.py @@ -1,7 +1,7 @@ # -*- coding: utf-8 -*- # Copyright (c) 2019-2024 tecnovert -# Copyright (c) 2024 The Basicswap developers +# Copyright (c) 2024-2025 The Basicswap developers # Distributed under the MIT software license, see the accompanying # file LICENSE or http://www.opensource.org/licenses/mit-license.php. @@ -28,6 +28,9 @@ from .rpc import ( from .util import ( TemporaryError, ) +from .util.logging import ( + BSXLogger, +) from .chainparams import ( Coins, chainparams, @@ -75,6 +78,7 @@ class BaseApp(DBMethods): self.delay_event.set() def prepareLogging(self): + logging.setLoggerClass(BSXLogger) self.log = logging.getLogger(self.log_name) self.log.propagate = False diff --git a/basicswap/basicswap.py b/basicswap/basicswap.py index 2f8b432..5d5e9c0 100644 --- a/basicswap/basicswap.py +++ b/basicswap/basicswap.py @@ -44,7 +44,6 @@ from .util import ( format_timestamp, DeserialiseNum, h2b, - hex_or_none, i2b, zeroIfNone, make_int, @@ -176,13 +175,13 @@ def threadPollXMRChainState(swap_client, coin_type): new_height = ci.getChainHeight() if new_height != cc["chain_height"]: swap_client.log.debug( - "New {} block at height: {}".format(ci.ticker(), new_height) + f"New {ci.ticker()} block at height: {new_height}" ) with swap_client.mxDB: cc["chain_height"] = new_height except Exception as e: swap_client.log.warning( - "threadPollXMRChainState {}, error: {}".format(ci.ticker(), str(e)) + f"threadPollXMRChainState {ci.ticker()}, error: {e}" ) swap_client.chainstate_delay_event.wait( random.randrange(20, 30) @@ -194,16 +193,16 @@ def threadPollWOWChainState(swap_client, coin_type): cc = swap_client.coin_clients[coin_type] while not swap_client.chainstate_delay_event.is_set(): try: - new_height = ci.getChainHeight() + new_height: int = ci.getChainHeight() if new_height != cc["chain_height"]: swap_client.log.debug( - "New {} block at height: {}".format(ci.ticker(), new_height) + f"New {ci.ticker()} block at height: {new_height}" ) with swap_client.mxDB: cc["chain_height"] = new_height except Exception as e: swap_client.log.warning( - "threadPollWOWChainState {}, error: {}".format(ci.ticker(), str(e)) + f"threadPollWOWChainState {ci.ticker()}, error: {e}" ) swap_client.chainstate_delay_event.wait( random.randrange(20, 30) @@ -216,21 +215,18 @@ def threadPollChainState(swap_client, coin_type): while not swap_client.chainstate_delay_event.is_set(): try: chain_state = ci.getBlockchainInfo() + new_height: int = chain_state["blocks"] if chain_state["bestblockhash"] != cc["chain_best_block"]: swap_client.log.debug( - "New {} block at height: {}".format( - ci.ticker(), chain_state["blocks"] - ) + f"New {ci.ticker()} block at height: {new_height}" ) with swap_client.mxDB: - cc["chain_height"] = chain_state["blocks"] + cc["chain_height"] = new_height cc["chain_best_block"] = chain_state["bestblockhash"] if "mediantime" in chain_state: cc["chain_median_time"] = chain_state["mediantime"] except Exception as e: - swap_client.log.warning( - "threadPollChainState {}, error: {}".format(ci.ticker(), str(e)) - ) + swap_client.log.warning(f"threadPollChainState {ci.ticker()}, error: {e}") swap_client.chainstate_delay_event.wait( random.randrange(20, 30) ) # Random to stagger updates @@ -352,6 +348,21 @@ class BasicSwap(BaseApp): self._is_encrypted = None self._is_locked = None + # Keep sensitive info out of the log file (WIP) + self.log.safe_logs = self.settings.get("safe_logs", False) + if self.log.safe_logs and self.debug: + raise ValueError("Safe logs mode is incompatible with debug mode") + + if self.log.safe_logs: + self.log.warning("Safe log enabled.") + if "safe_logs_prefix" in self.settings: + self.log.safe_logs_prefix = self.settings["safe_logs_prefix"].encode( + encoding="utf-8" + ) + else: + self.log.warning('Using random "safe_logs_prefix".') + self.log.safe_logs_prefix = random.randbytes(8) + # TODO: Set dynamically self.balance_only_coins = (Coins.LTC_MWEB,) self.scriptless_coins = ( @@ -512,6 +523,18 @@ class BasicSwap(BaseApp): self.swaps_in_progress.clear() + def logIDB(self, concept_id: bytes) -> str: + return self.log.id(concept_id, prefix="B_") + + def logIDO(self, concept_id: bytes) -> str: + return self.log.id(concept_id, prefix="O_") + + def logIDM(self, concept_id: bytes) -> str: + return self.log.id(concept_id, prefix="M_") + + def logIDT(self, concept_id: bytes) -> str: + return self.log.id(concept_id, prefix="T_") + def handleSessionErrors(self, e, cursor, tag): if self.debug: self.log.error(traceback.format_exc()) @@ -810,7 +833,7 @@ class BasicSwap(BaseApp): def pi(self, protocol_ind): if protocol_ind not in self.protocolInterfaces: - raise ValueError("Unknown protocol_ind {}".format(int(protocol_ind))) + raise ValueError(f"Unknown protocol_ind {protocol_ind}") return self.protocolInterfaces[protocol_ind] def createInterface(self, coin): @@ -909,9 +932,7 @@ class BasicSwap(BaseApp): self.getChainDatadirPath(coin), pidfilename + ".pid" ) self.log.debug( - "Reading %s rpc credentials from auth cookie %s", - Coins(coin).name, - authcookiepath, + f"Reading {Coins(coin).name} rpc credentials from auth cookie {authcookiepath}", ) # Wait for daemon to start # Test pids to ensure authcookie is read for the correct process @@ -929,7 +950,7 @@ class BasicSwap(BaseApp): break except Exception as e: if self.debug: - self.log.warning("Error, iteration %d: %s", i, str(e)) + self.log.warning(f"Error, iteration {i}: {e}") self.delay_event.wait(0.5) try: if ( @@ -963,7 +984,7 @@ class BasicSwap(BaseApp): ) self.log.info(f"Python version: {platform.python_version()}") self.log.info(f"SQLite version: {sqlite3.sqlite_version}") - self.log.info(f"Timezone offset: {time.timezone} ({time.tzname[0]})") + self.log.debug(f"Timezone offset: {time.timezone} ({time.tzname[0]})") upgradeDatabase(self, self.db_version) upgradeDatabaseData(self, self.db_data_version) @@ -982,7 +1003,7 @@ class BasicSwap(BaseApp): self.waitForDaemonRPC(c) core_version = ci.getDaemonVersion() - self.log.info("%s Core version %d", ci.coin_name(), core_version) + self.log.info(f"{ci.coin_name()} Core version {core_version}") self.coin_clients[c]["core_version"] = core_version thread_func = { @@ -1010,17 +1031,17 @@ class BasicSwap(BaseApp): is not False ): self.log.warning( - "%s staking is not disabled.", ci.coin_name() + f"{ci.coin_name()} staking is not disabled." ) except Exception as e: - self.log.error("Sanity checks failed: %s", str(e)) + self.log.error(f"Sanity checks failed: {e}") elif c in (Coins.XMR, Coins.WOW): try: ci.ensureWalletExists() except Exception as e: # noqa: F841 self.log.warning( - "Can't open %s wallet, could be locked.", ci.coin_name() + f"Can't open {ci.coin_name()} wallet, could be locked." ) continue elif c == Coins.LTC: @@ -1039,10 +1060,7 @@ class BasicSwap(BaseApp): self._network.startNetwork() self.log.debug( - "network_key %s\nnetwork_pubkey %s\nnetwork_addr %s", - self.network_key, - self.network_pubkey, - self.network_addr, + f"network_key {self.network_key}\nnetwork_pubkey {self.network_pubkey}\nnetwork_addr {self.network_addr}" ) ro = self.callrpc("smsglocalkeys") @@ -1078,7 +1096,7 @@ class BasicSwap(BaseApp): ) self.processMsg(get_msg) nm += 1 - self.log.info("Scanned %d unread messages.", nm) + self.log.info(f"Scanned {nm} unread messages.") def stopDaemon(self, coin) -> None: if coin in (Coins.XMR, Coins.DCR, Coins.WOW): @@ -1089,7 +1107,7 @@ class BasicSwap(BaseApp): try: for i in range(num_tries): self.callcoincli(coin, "stop", timeout=10) - self.log.debug("Trying to stop %s", Coins(coin).name) + self.log.debug(f"Trying to stop {Coins(coin).name}") stopping = True # self.delay_event will be set here time.sleep(i + 1) @@ -1107,14 +1125,14 @@ class BasicSwap(BaseApp): # TODO: Query lock on .lock properly if os.path.exists(authcookiepath): self.log.debug( - "Waiting on .cookie file %s", Coins(coin).name + f"Waiting on .cookie file {Coins(coin).name}" ) time.sleep(i + 1) time.sleep(4) # Extra time to settle return - self.log.error("stopDaemon %s", str(ex)) + self.log.error(f"stopDaemon {ex}") self.log.error(traceback.format_exc()) - raise ValueError("Could not stop {}".format(Coins(coin).name)) + raise ValueError(f"Could not stop {Coins(coin).name}") def stopDaemons(self) -> None: for c in self.activeCoins(): @@ -1138,9 +1156,7 @@ class BasicSwap(BaseApp): ci = self.ci(check_coin_type) # checkWallets can adjust the wallet name. if ci.checkWallets() < 1: - self.log.error( - "No wallets found for coin {}.".format(ci.coin_name()) - ) + self.log.error(f"No wallets found for coin {ci.coin_name()}.") # systemd will try to restart the process if fail_code != 0 self.stopRunning(1) @@ -1159,15 +1175,10 @@ class BasicSwap(BaseApp): return except Exception as ex: self.log.warning( - "Can't connect to %s RPC: %s. Trying again in %d second/s, %d/%d.", - Coins(coin_type).name, - str(ex), - (1 + i), - i + 1, - startup_tries, + f"Can't connect to {Coins(coin_type).name} RPC: {ex}. Trying again in {1 + i} second/s, {1 + i}/{startup_tries}." ) self.delay_event.wait(1 + i) - self.log.error("Can't connect to %s RPC, exiting.", Coins(coin_type).name) + self.log.error(f"Can't connect to {Coins(coin_type).name} RPC, exiting.") self.stopRunning(1) # systemd will try to restart the process if fail_code != 0 def checkCoinsReady(self, coin_from, coin_to) -> None: @@ -1268,9 +1279,7 @@ class BasicSwap(BaseApp): try: self.ci(c).unlockWallet(password) except Exception as e: - self.log.warning( - "Failed to unlock wallet {}".format(getCoinName(c)) - ) + self.log.warning(f"Failed to unlock wallet {getCoinName(c)}") if coin is not None or c == Coins.PART: raise e if c == Coins.PART: @@ -1313,7 +1322,7 @@ class BasicSwap(BaseApp): return ci = self.ci(interface_type) db_key_coin_name = ci.coin_name().lower() - self.log.info("Initialising {} wallet.".format(ci.coin_name())) + self.log.info(f"Initialising {ci.coin_name()} wallet.") if interface_type in (Coins.XMR, Coins.WOW): key_view = self.getWalletKey(interface_type, 1, for_ed25519=True) @@ -1330,7 +1339,7 @@ class BasicSwap(BaseApp): ci.initialiseWallet(root_key) except Exception as e: # < 0.21: sethdseed cannot set a new HD seed while still in Initial Block Download. - self.log.error("initialiseWallet failed: {}".format(str(e))) + self.log.error(f"initialiseWallet failed: {e}") if raise_errors: raise e if self.debug: @@ -1417,9 +1426,9 @@ class BasicSwap(BaseApp): def activateBid(self, cursor, bid) -> None: if bid.bid_id in self.swaps_in_progress: - self.log.debug("Bid %s is already in progress", bid.bid_id.hex()) + self.log.debug(f"Bid {self.log.id(bid.bid_id)} is already in progress") - self.log.debug("Loading active bid %s", bid.bid_id.hex()) + self.log.debug(f"Loading active bid {self.log.id(bid.bid_id)}") offer = self.getOffer(bid.offer_id, cursor=cursor) if not offer: @@ -1516,7 +1525,7 @@ class BasicSwap(BaseApp): def deactivateBid(self, cursor, offer, bid) -> None: # Remove from in progress - self.log.debug("Removing bid from in-progress: %s", bid.bid_id.hex()) + self.log.debug(f"Removing bid from in-progress: {self.log.id(bid.bid_id)}") self.swaps_in_progress.pop(bid.bid_id, None) bid.in_progress = 0 @@ -1565,7 +1574,7 @@ class BasicSwap(BaseApp): try: ci_from.unlockInputs(xmr_swap_a_lock_tx) except Exception as e: - self.log.debug("unlockInputs failed {}".format(str(e))) + self.log.debug(f"unlockInputs failed {e}") pass # Invalid parameter, unknown transaction elif SwapTypes.SELLER_FIRST: pass # No prevouts are locked @@ -1653,7 +1662,7 @@ class BasicSwap(BaseApp): for coin in (coin_from, coin_to): if coin in self.balance_only_coins: - raise ValueError("Invalid coin: {}".format(coin.name)) + raise ValueError(f"Invalid coin: {coin.name}") if swap_type == SwapTypes.XMR_SWAP: reverse_bid: bool = self.is_reverse_ads_bid(coin_from, coin_to) @@ -1662,14 +1671,10 @@ class BasicSwap(BaseApp): if itx_coin in self.coins_without_segwit + self.scriptless_coins: if ptx_coin in self.coins_without_segwit + self.scriptless_coins: raise ValueError( - "{} -> {} is not currently supported".format( - coin_from.name, coin_to.name - ) + f"{coin_from.name} -> {coin_to.name} is not currently supported" ) raise ValueError( - "Invalid swap type for: {} -> {}".format( - coin_from.name, coin_to.name - ) + f"Invalid swap type for: {coin_from.name} -> {coin_to.name}" ) else: if ( @@ -1677,30 +1682,30 @@ class BasicSwap(BaseApp): or coin_to in self.adaptor_swap_only_coins ): raise ValueError( - "Invalid swap type for: {} -> {}".format( - coin_from.name, coin_to.name - ) + f"Invalid swap type for: {coin_from.name} -> {coin_to.name}" ) def notify(self, event_type, event_data, cursor=None) -> None: show_event = event_type not in self._disabled_notification_types if event_type == NT.OFFER_RECEIVED: - self.log.debug("Received new offer %s", event_data["offer_id"]) + offer_id: bytes = bytes.fromhex(event_data["offer_id"]) + self.log.debug(f"Received new offer {self.log.id(offer_id)}") if self.ws_server and show_event: event_data["event"] = "new_offer" self.ws_server.send_message_to_all(json.dumps(event_data)) elif event_type == NT.BID_RECEIVED: + offer_id: bytes = bytes.fromhex(event_data["offer_id"]) + offer_type: str = event_data["type"] + bid_id: bytes = bytes.fromhex(event_data["bid_id"]) self.log.info( - "Received valid bid %s for %s offer %s", - event_data["bid_id"], - event_data["type"], - event_data["offer_id"], + f"Received valid bid {self.log.id(bid_id)} for {offer_type} offer {self.log.id(offer_id)}" ) if self.ws_server and show_event: event_data["event"] = "new_bid" self.ws_server.send_message_to_all(json.dumps(event_data)) elif event_type == NT.BID_ACCEPTED: - self.log.info("Received valid bid accept for %s", event_data["bid_id"]) + bid_id: bytes = bytes.fromhex(event_data["bid_id"]) + self.log.info(f"Received valid bid accept for {self.log.id(bid_id)}") if self.ws_server and show_event: event_data["event"] = "bid_accepted" self.ws_server.send_message_to_all(json.dumps(event_data)) @@ -2235,11 +2240,11 @@ class BasicSwap(BaseApp): self.add(SentOffer(offer_id=offer_id), cursor) finally: self.closeDB(cursor) - self.log.info("Sent OFFER %s", offer_id.hex()) + self.log.info(f"Sent OFFER {self.log.id(offer_id)}") return offer_id def revokeOffer(self, offer_id, security_token=None) -> None: - self.log.info("Revoking offer %s", offer_id.hex()) + self.log.info(f"Revoking offer {self.log.id(offer_id)}") cursor = self.openDB() try: @@ -2269,12 +2274,14 @@ class BasicSwap(BaseApp): msg_id = self.sendSmsg( offer.addr_from, self.network_addr, payload_hex, msg_valid ) - self.log.debug("Revoked offer %s in msg %s", offer_id.hex(), msg_id.hex()) + self.log.debug( + f"Revoked offer {self.log.id(offer_id)} in msg {self.log.id(msg_id)}" + ) finally: self.closeDB(cursor, commit=False) def archiveOffer(self, offer_id) -> None: - self.log.info("Archiving offer %s", offer_id.hex()) + self.log.info(f"Archiving offer {self.log.id(offer_id)}") cursor = self.openDB() try: offer = self.queryOne(Offer, cursor, {"offer_id": offer_id}) @@ -2294,7 +2301,7 @@ class BasicSwap(BaseApp): self.closeDB(cursor) def editOffer(self, offer_id, data) -> None: - self.log.info("Editing offer %s", offer_id.hex()) + self.log.info(f"Editing offer {self.log.id(offer_id)}") cursor = self.openDB() try: offer = self.queryOne(Offer, cursor, {"offer_id": offer_id}) @@ -2476,9 +2483,7 @@ class BasicSwap(BaseApp): def getReceiveAddressFromPool(self, coin_type, bid_id: bytes, tx_type, cursor=None): self.log.debug( - "Get address from pool bid_id {}, type {}, coin {}".format( - bid_id.hex(), tx_type, coin_type - ) + f"Get address from pool bid_id {self.log.id(bid_id)}, type {tx_type}, coin {coin_type}" ) try: use_cursor = self.openDB(cursor) @@ -2507,7 +2512,7 @@ class BasicSwap(BaseApp): def returnAddressToPool(self, bid_id: bytes, tx_type): self.log.debug( - "Return address to pool bid_id {}, type {}".format(bid_id.hex(), tx_type) + f"Return address to pool bid_id {self.log.id(bid_id)}, type {tx_type}" ) try: cursor = self.openDB() @@ -2517,7 +2522,7 @@ class BasicSwap(BaseApp): cursor, {"tx_type": int(tx_type), "bid_id": bid_id}, ) - self.log.debug("Returning address to pool addr {}".format(record.addr)) + self.log.debug(f"Returning address to pool addr {record.addr}") # unset PooledAddress.bid_id query = "UPDATE addresspool SET bid_id = NULL WHERE bid_id = :bid_id AND tx_type = :tx_type" @@ -2534,7 +2539,7 @@ class BasicSwap(BaseApp): self.coin_clients[coin_type]["use_segwit"] ) self.log.debug( - "Generated new receive address %s for %s", new_addr, Coins(coin_type).name + f"Generated new receive address {self.log.addr(new_addr)} for {Coins(coin_type).name}" ) return new_addr @@ -2551,39 +2556,45 @@ class BasicSwap(BaseApp): def withdrawCoin(self, coin_type, value, addr_to, subfee: bool) -> str: ci = self.ci(coin_type) - if subfee and coin_type in (Coins.XMR, Coins.WOW): - self.log.info( - "withdrawCoin sweep all {} to {}".format(ci.ticker(), addr_to) - ) - else: - self.log.info( - "withdrawCoin {} {} to {} {}".format( - value, ci.ticker(), addr_to, " subfee" if subfee else "" + info_str: str = "" + if self.log.safe_logs is False: + if subfee and coin_type in (Coins.XMR, Coins.WOW): + info_str = f" sweep all to {addr_to}" + else: + info_str = " {} to {}{}".format( + value, addr_to, " subfee" if subfee else "" ) - ) + self.log.info(f"withdrawCoin {ci.ticker()}{info_str}") txid = ci.withdrawCoin(value, addr_to, subfee) - self.log.debug("In txn: {}".format(txid)) + self.log.info_s(f"In txn: {txid}") return txid def withdrawLTC(self, type_from, value, addr_to, subfee: bool) -> str: ci = self.ci(Coins.LTC) self.log.info( - "withdrawLTC {} {} to {} {}".format( - value, type_from, addr_to, " subfee" if subfee else "" + "withdrawLTC{}".format( + "" + if self.log.safe_logs + else " {} {} to {} {}".format( + value, type_from, addr_to, " subfee" if subfee else "" + ) ) ) - txid = ci.withdrawCoin(value, type_from, addr_to, subfee) - self.log.debug("In txn: {}".format(txid)) + self.log.info_s(f"In txn: {txid}") return txid def withdrawParticl( self, type_from: str, type_to: str, value, addr_to: str, subfee: bool ) -> str: self.log.info( - "withdrawParticl {} {} to {} {} {}".format( - value, type_from, type_to, addr_to, " subfee" if subfee else "" + "withdrawParticl{}".format( + "" + if self.log.safe_logs + else " {} {} to {} {} {}".format( + value, type_from, type_to, addr_to, " subfee" if subfee else "" + ) ) ) @@ -2594,11 +2605,11 @@ class BasicSwap(BaseApp): ci = self.ci(Coins.PART) txid = ci.sendTypeTo(type_from, type_to, value, addr_to, subfee) - self.log.debug("In txn: {}".format(txid)) + self.log.info_s(f"In txn: {txid}") return txid def cacheNewAddressForCoin(self, coin_type, cursor=None): - self.log.debug("cacheNewAddressForCoin %s", Coins(coin_type).name) + self.log.debug(f"cacheNewAddressForCoin {Coins(coin_type).name}") key_str = "receive_addr_" + self.ci(coin_type).coin_name().lower() addr = self.getReceiveAddressForCoin(coin_type) self.setStringKV(key_str, addr, cursor) @@ -2625,9 +2636,7 @@ class BasicSwap(BaseApp): expect_address = self.getCachedMainWalletAddress(ci) if expect_address is None: self.log.warning( - "Can't find expected main wallet address for coin {}".format( - ci.coin_name() - ) + f"Can't find expected main wallet address for coin {ci.coin_name()}" ) return False ci._have_checked_seed = True @@ -2635,24 +2644,21 @@ class BasicSwap(BaseApp): if expect_address == wallet_address: ci.setWalletSeedWarning(False) return True - self.log.warning( - "Wallet for coin {} not derived from swap seed.\n Expected {}\n Have {}".format( - ci.coin_name(), expect_address, wallet_address - ) - ) + msg: str = f"Wallet for coin {ci.coin_name()} not derived from swap seed." + if not self.log.safe_logs: + msg += f"\n Expected {expect_address}\n Have {wallet_address}" + self.log.warning(msg) return False expect_seedid = self.getStringKV("main_wallet_seedid_" + ci.coin_name().lower()) if expect_seedid is None: self.log.warning( - "Can't find expected wallet seed id for coin {}.".format(ci.coin_name()) + f"Can't find expected wallet seed id for coin {ci.coin_name()}." ) _, is_locked = self.getLockedState() if is_locked is False: self.log.warning( - "Setting seed id for coin {} from master key.".format( - ci.coin_name() - ) + f"Setting seed id for coin {ci.coin_name()} from master key." ) root_key = self.getWalletKey(c, 1) self.storeSeedIDForCoin(root_key, c) @@ -2661,7 +2667,7 @@ class BasicSwap(BaseApp): return False if c == Coins.BTC and len(ci.rpc("listwallets")) < 1: - self.log.warning("Missing wallet for coin {}".format(ci.coin_name())) + self.log.warning(f"Missing wallet for coin {ci.coin_name()}") return False if ci.checkExpectedSeed(expect_seedid): ci.setWalletSeedWarning(False) @@ -2673,23 +2679,19 @@ class BasicSwap(BaseApp): ) if ci.checkExpectedSeed(expect_seedid): ci.setWalletSeedWarning(False) - self.log.warning( - "{} is using the legacy extkey.".format(ci.coin_name()) - ) + self.log.warning(f"{ci.coin_name()} is using the legacy extkey.") return True self.log.warning( - "Wallet for coin {} not derived from swap seed.".format(ci.coin_name()) + f"Wallet for coin {ci.coin_name()} not derived from swap seed." ) return False def reseedWallet(self, coin_type): - self.log.info("reseedWallet %s", coin_type) ci = self.ci(coin_type) + self.log.info(f"reseedWallet {ci.coin_name()}") if ci.knownWalletSeed(): raise ValueError( - "{} wallet seed is already derived from the particl mnemonic".format( - ci.coin_name() - ) + f"{ci.coin_name()} wallet seed is already derived from the particl mnemonic" ) self.initialiseWallet(coin_type, raise_errors=True) @@ -2703,7 +2705,7 @@ class BasicSwap(BaseApp): raise ValueError("Wallet seed doesn't match expected.") def getCachedAddressForCoin(self, coin_type, cursor=None): - self.log.debug("getCachedAddressForCoin %s", Coins(coin_type).name) + self.log.debug(f"getCachedAddressForCoin {Coins(coin_type).name}") # TODO: auto refresh after used ci = self.ci(coin_type) @@ -2720,7 +2722,7 @@ class BasicSwap(BaseApp): return addr def cacheNewStealthAddressForCoin(self, coin_type): - self.log.debug("cacheNewStealthAddressForCoin %s", Coins(coin_type).name) + self.log.debug(f"cacheNewStealthAddressForCoin {Coins(coin_type).name}") if coin_type == Coins.LTC_MWEB: coin_type = Coins.LTC @@ -2731,7 +2733,7 @@ class BasicSwap(BaseApp): return addr def getCachedStealthAddressForCoin(self, coin_type, cursor=None): - self.log.debug("getCachedStealthAddressForCoin %s", Coins(coin_type).name) + self.log.debug(f"getCachedStealthAddressForCoin {Coins(coin_type).name}") if coin_type == Coins.LTC_MWEB: coin_type = Coins.LTC @@ -2742,7 +2744,7 @@ class BasicSwap(BaseApp): addr = self.getStringKV(key_str, use_cursor) if addr is None: addr = ci.getNewStealthAddress() - self.log.info("Generated new stealth address for %s", coin_type) + self.log.info(f"Generated new stealth address for {ci.coin_name()}") self.setStringKV(key_str, addr, use_cursor) finally: if cursor is None: @@ -2750,7 +2752,7 @@ class BasicSwap(BaseApp): return addr def getCachedWalletRestoreHeight(self, ci, cursor=None): - self.log.debug("getCachedWalletRestoreHeight %s", ci.coin_name()) + self.log.debug(f"getCachedWalletRestoreHeight {ci.coin_name()}") key_str = "restore_height_" + ci.coin_name().lower() use_cursor = self.openDB(cursor) @@ -2759,9 +2761,7 @@ class BasicSwap(BaseApp): wrh = self.getIntKV(key_str, use_cursor) except Exception: wrh = ci.getWalletRestoreHeight() - self.log.info( - "Found restore height for %s, block %d", ci.coin_name(), wrh - ) + self.log.info(f"Found restore height for {ci.coin_name()}, block {wrh}") self.setIntKV(key_str, wrh, use_cursor) finally: if cursor is None: @@ -2787,7 +2787,7 @@ class BasicSwap(BaseApp): def getProofOfFunds(self, coin_type, amount_for: int, extra_commit_bytes): ci = self.ci(coin_type) self.log.debug( - "getProofOfFunds %s %s", ci.coin_name(), ci.format_amount(amount_for) + f"getProofOfFunds {ci.coin_name()} {ci.format_amount(amount_for)}" ) if self.coin_clients[coin_type]["connection_type"] != "rpc": @@ -2829,7 +2829,7 @@ class BasicSwap(BaseApp): def createActionInSession( self, delay: int, action_type: int, linked_id: bytes, cursor ) -> None: - self.log.debug("createAction %d %s", action_type, linked_id.hex()) + self.log.debug(f"createAction {action_type} {self.log.id(linked_id)}") now: int = self.getTime() action = Action( active_ind=1, @@ -2885,7 +2885,7 @@ class BasicSwap(BaseApp): def logBidEvent( self, bid_id: bytes, event_type: int, event_msg: str, cursor ) -> None: - self.log.debug("logBidEvent %s %s", bid_id.hex(), event_type) + self.log.debug(f"logBidEvent {self.log.id(bid_id)} {event_type}") self.logEvent(Concepts.BID, bid_id, event_type, event_msg, cursor) def countBidEvents(self, bid, event_type, cursor): @@ -3025,18 +3025,16 @@ class BasicSwap(BaseApp): if test_bid_rate == offer.rate: if amount != test_amount: - self.log.info( - "Reducing bid amount-from from {} to {} to match offer rate.".format( - amount, test_amount - ) - ) + msg: str = "Reducing bid amount-from" + if not self.log.safe_logs: + msg += f" from {amount} to {test_amount} to match offer rate." + self.log.info(msg) elif amount_to != test_amount_to: # Only show on first loop iteration (amount from unchanged) - self.log.info( - "Reducing bid amount-to from {} to {} to match offer rate.".format( - amount_to, test_amount_to - ) - ) + msg: str = "Reducing bid amount-to" + if not self.log.safe_logs: + msg += f" from {amount_to} to {test_amount_to} to match offer rate." + self.log.info(msg) amount = test_amount amount_to = test_amount_to bid_rate = test_bid_rate @@ -3047,10 +3045,10 @@ class BasicSwap(BaseApp): self, offer_id: bytes, amount: int, addr_send_from: str = None, extra_options={} ) -> bytes: # Bid to send bid.amount * bid.rate of coin_to in exchange for bid.amount of coin_from - self.log.debug("postBid for offer: %s", offer_id.hex()) + self.log.debug(f"postBid for offer: {self.log.id(offer_id)}") offer = self.getOffer(offer_id) - ensure(offer, "Offer not found: {}.".format(offer_id.hex())) + ensure(offer, f"Offer not found: {offer_id.hex()}.") ensure(offer.expire_at > self.getTime(), "Offer has expired") if offer.swap_type == SwapTypes.XMR_SWAP: @@ -3146,7 +3144,7 @@ class BasicSwap(BaseApp): self.saveBidInSession(bid_id, bid, cursor) - self.log.info("Sent BID %s", bid_id.hex()) + self.log.info(f"Sent BID {self.log.id(bid_id)}") return bid_id finally: self.closeDB(cursor) @@ -3301,7 +3299,7 @@ class BasicSwap(BaseApp): return events def acceptBid(self, bid_id: bytes, cursor=None) -> None: - self.log.info("Accepting bid %s", bid_id.hex()) + self.log.info(f"Accepting bid {self.log.id(bid_id)}") try: use_cursor = self.openDB(cursor) @@ -3354,13 +3352,11 @@ class BasicSwap(BaseApp): op_hash = OpCodes.OP_SHA256 if bid.initiate_tx is not None: - self.log.warning( - "Initiate txn %s already exists for bid %s", - bid.initiate_tx.txid, - bid_id.hex(), - ) txid = bid.initiate_tx.txid script = bid.initiate_tx.script + self.log.warning( + f"Initiate txn {self.log.id(txid)} already exists for bid {self.log.id(bid_id)}" + ) else: if offer.lock_type < TxLockTypes.ABS_LOCK_BLOCKS: sequence = ci_from.getExpectedSequence( @@ -3379,10 +3375,7 @@ class BasicSwap(BaseApp): else: lock_value = self.getTime() + offer.lock_value self.log.debug( - "Initiate %s lock_value %d %d", - ci_from.coin_name(), - offer.lock_value, - lock_value, + f"Initiate {ci_from.coin_name()} lock_value {offer.lock_value} {lock_value}", ) script = atomic_swap_1.buildContractScript( lock_value, @@ -3413,10 +3406,7 @@ class BasicSwap(BaseApp): txid = ci_from.publishTx(bytes.fromhex(txn)) self.log.debug( - "Submitted initiate txn %s to %s chain for bid %s", - txid, - ci_from.coin_name(), - bid_id.hex(), + f"Submitted initiate txn {txid} to {ci_from.coin_name()} chain for bid {self.log.id(bid_id)}", ) bid.initiate_tx = SwapTx( bid_id=bid_id, @@ -3438,10 +3428,12 @@ class BasicSwap(BaseApp): # Check non-bip68 final try: txid = ci_from.publishTx(bid.initiate_txn_refund) - self.log.error("Submit refund_txn unexpectedly worked: " + txid) + self.log.error( + f"Submit refund_txn unexpectedly worked {self.logIDT(bytes.fromhex(txid))}" + ) except Exception as ex: if ci_from.isTxNonFinalError(str(ex)) is False: - self.log.error("Submit refund_txn unexpected error" + str(ex)) + self.log.error(f"Submit refund_txn unexpected error: {ex}") raise ex if txid is not None: @@ -3471,7 +3463,7 @@ class BasicSwap(BaseApp): accept_msg_id, cursor=use_cursor, ) - self.log.info("Sent BID_ACCEPT %s", accept_msg_id.hex()) + self.log.info(f"Sent BID_ACCEPT {self.logIDM(accept_msg_id)}") bid.setState(BidStates.BID_ACCEPTED) @@ -3511,14 +3503,14 @@ class BasicSwap(BaseApp): ) -> bytes: # Bid to send bid.amount * bid.rate of coin_to in exchange for bid.amount of coin_from # Send MSG1L F -> L or MSG0F L -> F - self.log.debug("postXmrBid %s", offer_id.hex()) + self.log.debug(f"postXmrBid {self.logIDO(offer_id)}") try: cursor = self.openDB() offer, xmr_offer = self.getXmrOffer(offer_id, cursor=cursor) - ensure(offer, "Offer not found: {}.".format(offer_id.hex())) - ensure(xmr_offer, "Adaptor-sig offer not found: {}.".format(offer_id.hex())) + ensure(offer, f"Offer not found: {self.log.id(offer_id)}.") + ensure(xmr_offer, f"Adaptor-sig offer not found: {self.log.id(offer_id)}.") ensure( offer.protocol_version >= MINPROTO_VERSION_ADAPTOR_SIG, "Incompatible offer protocol version", @@ -3538,7 +3530,7 @@ class BasicSwap(BaseApp): bid_created_at: int = self.getTime() if offer.swap_type != SwapTypes.XMR_SWAP: - raise ValueError("TODO: Unknown swap type " + offer.swap_type.name) + raise ValueError(f"TODO: Unknown swap type {offer.swap_type.name}") if not (self.debug and extra_options.get("debug_skip_validation", False)): self.validateBidValidTime( @@ -3605,7 +3597,7 @@ class BasicSwap(BaseApp): self.saveBidInSession(xmr_swap.bid_id, bid, cursor, xmr_swap) self.commitDB() - self.log.info("Sent ADS_BID_LF %s", xmr_swap.bid_id.hex()) + self.log.info(f"Sent ADS_BID_LF {self.logIDB(xmr_swap.bid_id)}") return xmr_swap.bid_id msg_buf = XmrBidMessage() @@ -3731,9 +3723,7 @@ class BasicSwap(BaseApp): if bid.chain_b_height_start < wallet_restore_height: bid.chain_b_height_start = wallet_restore_height self.log.warning( - "Adaptor-sig swap restore height clamped to {}".format( - wallet_restore_height - ) + f"Adaptor-sig swap restore height clamped to {wallet_restore_height}" ) bid.setState(BidStates.BID_SENT) @@ -3749,14 +3739,14 @@ class BasicSwap(BaseApp): cursor=cursor, ) - self.log.info("Sent XMR_BID_FL %s", xmr_swap.bid_id.hex()) + self.log.info(f"Sent XMR_BID_FL {self.logIDB(xmr_swap.bid_id)}") return xmr_swap.bid_id finally: self.closeDB(cursor) def acceptXmrBid(self, bid_id: bytes, cursor=None) -> None: # MSG1F and MSG2F L -> F - self.log.info("Accepting adaptor-sig bid %s", bid_id.hex()) + self.log.info(f"Accepting adaptor-sig bid {self.log.id(bid_id)}") now: int = self.getTime() try: @@ -3935,9 +3925,7 @@ class BasicSwap(BaseApp): # Double check txns before sending self.log.debug( - "Bid: {} - Double checking chain A lock txns are valid before sending bid accept.".format( - bid_id.hex() - ) + f"Bid: {self.log.id(bid_id)} - Double checking chain A lock txns are valid before sending bid accept." ) check_lock_tx_inputs = False # TODO: check_lock_tx_inputs without txindex _, xmr_swap.a_lock_tx_vout = ci_from.verifySCLockTx( @@ -4051,14 +4039,14 @@ class BasicSwap(BaseApp): ) # Add to swaps_in_progress only when waiting on txns - self.log.info("Sent XMR_BID_ACCEPT_LF %s", bid_id.hex()) + self.log.info(f"Sent XMR_BID_ACCEPT_LF {self.log.id(bid_id)}") return bid_id finally: if cursor is None: self.closeDB(use_cursor) def acceptADSReverseBid(self, bid_id: bytes, cursor=None) -> None: - self.log.info("Accepting reverse adaptor-sig bid %s", bid_id.hex()) + self.log.info(f"Accepting reverse adaptor-sig bid {self.log.id(bid_id)}") now: int = self.getTime() try: @@ -4193,7 +4181,7 @@ class BasicSwap(BaseApp): msg_sequence=k, cursor=use_cursor, ) - self.log.info("Sent ADS_BID_ACCEPT_FL %s", bid_msg_ids[0].hex()) + self.log.info(f"Sent ADS_BID_ACCEPT_FL {self.logIDM(bid_msg_ids[0])}") self.saveBidInSession(bid_id, bid, use_cursor, xmr_swap=xmr_swap) finally: if cursor is None: @@ -4222,20 +4210,22 @@ class BasicSwap(BaseApp): def abandonBid(self, bid_id: bytes) -> None: if not self.debug: - self.log.error("Can't abandon bid %s when not in debug mode.", bid_id.hex()) + self.log.error( + f"Can't abandon bid {self.log.id(bid_id)} when not in debug mode." + ) return - self.log.info("Abandoning Bid %s", bid_id.hex()) + self.log.info(f"Abandoning Bid {self.log.id(bid_id)}") self.deactivateBidForReason(bid_id, BidStates.BID_ABANDONED) def timeoutBid(self, bid_id: bytes, cursor=None) -> None: - self.log.info("Bid %s timed-out", bid_id.hex()) + self.log.info(f"Bid {self.log.id(bid_id)} timed-out") self.deactivateBidForReason(bid_id, BidStates.SWAP_TIMEDOUT, cursor=cursor) def setBidError( self, bid_id: bytes, bid, error_str: str, save_bid: bool = True, xmr_swap=None ) -> None: - self.log.error("Bid %s - Error: %s", bid_id.hex(), error_str) + self.log.error(f"Bid {self.log.id(bid_id)} - Error: {error_str}") bid.setState(BidStates.BID_ERROR) bid.state_note = "error msg: " + error_str if save_bid: @@ -4254,10 +4244,7 @@ class BasicSwap(BaseApp): else: addr_to = ci.encode_p2sh(initiate_script) self.log.debug( - "Create initiate txn for coin %s to %s for bid %s", - Coins(coin_type).name, - addr_to, - bid_id.hex(), + f"Create initiate txn for coin {ci.coin_name()} to {addr_to} for bid {self.log.id(bid_id)}" ) if prefunded_tx: @@ -4273,7 +4260,7 @@ class BasicSwap(BaseApp): return txn_signed, vout def deriveParticipateScript(self, bid_id: bytes, bid, offer) -> bytearray: - self.log.debug("deriveParticipateScript for bid %s", bid_id.hex()) + self.log.debug(f"deriveParticipateScript for bid {self.log.id(bid_id)}") coin_to = Coins(offer.coin_to) ci_to = self.ci(coin_to) @@ -4304,8 +4291,8 @@ class BasicSwap(BaseApp): ) else: # Lock from the height or time of the block containing the initiate txn - coin_from = Coins(offer.coin_from) - block_header = self.ci(coin_from).getBlockHeaderFromHeight( + ci_from = self.ci(offer.coin_from) + block_header = ci_from.getBlockHeaderFromHeight( bid.initiate_tx.chain_height ) initiate_tx_block_hash = block_header["hash"] @@ -4319,23 +4306,16 @@ class BasicSwap(BaseApp): cblock_height = block_header_at["height"] self.log.debug( - "Setting lock value from height of block %s %s", - Coins(coin_to).name, - cblock_hash, + f"Setting lock value from height of block {ci_to.coin_name()} {cblock_hash}" ) contract_lock_value = cblock_height + lock_value else: self.log.debug( - "Setting lock value from time of block %s %s", - Coins(coin_from).name, - initiate_tx_block_hash, + f"Setting lock value from time of block {ci_from.coin_name()} {initiate_tx_block_hash}" ) contract_lock_value = initiate_tx_block_time + lock_value self.log.debug( - "participate %s lock_value %d %d", - Coins(coin_to).name, - lock_value, - contract_lock_value, + f"participate {ci_to.coin_name()} lock_value {lock_value} {contract_lock_value}" ) participate_script = atomic_swap_1.buildContractScript( contract_lock_value, @@ -4363,7 +4343,7 @@ class BasicSwap(BaseApp): if bid.debug_ind == DebugTypes.MAKE_INVALID_PTX: amount_to -= 1 self.log.debug( - "bid %s: Make invalid PTx for testing: %d.", bid_id.hex(), bid.debug_ind + f"bid {self.log.id(bid_id)}: Make invalid PTx for testing: {bid.debug_ind}." ) self.logBidEvent( bid.bid_id, @@ -4413,7 +4393,7 @@ class BasicSwap(BaseApp): fee_rate=None, cursor=None, ): - self.log.debug("createRedeemTxn for coin %s", Coins(coin_type).name) + self.log.debug(f"createRedeemTxn for coin {Coins(coin_type).name}") ci = self.ci(coin_type) if for_txn_type == "participate": @@ -4460,9 +4440,7 @@ class BasicSwap(BaseApp): tx_fee = (fee_rate * tx_vsize) / 1000 self.log.debug( - "Redeem tx fee %s, rate %s", - ci.format_amount(tx_fee, conv_int=True, r=1), - str(fee_rate), + f"Redeem tx fee {ci.format_amount(tx_fee, conv_int=True, r=1)}, rate {fee_rate}" ) amount_out = prev_amount - ci.make_int(tx_fee, r=1) @@ -4481,7 +4459,7 @@ class BasicSwap(BaseApp): ) assert addr_redeem_out is not None - self.log.debug("addr_redeem_out %s", addr_redeem_out) + self.log.debug(f"addr_redeem_out {addr_redeem_out}") redeem_txn = ci.createRedeemTxn( prevout, addr_redeem_out, amount_out, txn_script @@ -4547,7 +4525,7 @@ class BasicSwap(BaseApp): ) if coin_type in (Coins.DCR,): txsize = len(redeem_txn) // 2 - self.log.debug("size paid, actual size %d %d", tx_vsize, txsize) + self.log.debug(f"size paid, actual size {tx_vsize} {txsize}") ensure(tx_vsize >= txsize, "underpaid fee") elif ci.use_tx_vsize(): self.log.debug( @@ -4562,10 +4540,7 @@ class BasicSwap(BaseApp): redeem_txid = ci.getTxid(bytes.fromhex(redeem_txn)) self.log.debug( - "Have valid redeem txn %s for contract %s tx %s", - redeem_txid.hex(), - for_txn_type, - prev_txnid, + f"Have valid redeem tx {self.log.id(redeem_txid)} for contract {for_txn_type} tx {self.log.id(prev_txnid)}" ) return redeem_txn @@ -4580,7 +4555,7 @@ class BasicSwap(BaseApp): tx_type=TxTypes.ITX_REFUND, cursor=None, ): - self.log.debug("createRefundTxn for coin %s", Coins(coin_type).name) + self.log.debug(f"createRefundTxn for coin {Coins(coin_type).name}") if self.coin_clients[coin_type]["connection_type"] != "rpc": return None @@ -4621,9 +4596,7 @@ class BasicSwap(BaseApp): tx_fee = (fee_rate * tx_vsize) / 1000 self.log.debug( - "Refund tx fee %s, rate %s", - ci.format_amount(tx_fee, conv_int=True, r=1), - str(fee_rate), + f"Refund tx fee {ci.format_amount(tx_fee, conv_int=True, r=1)}, rate {fee_rate}" ) amount_out = ci.make_int(prevout["amount"], r=1) - ci.make_int(tx_fee, r=1) @@ -4635,7 +4608,7 @@ class BasicSwap(BaseApp): coin_type, bid.bid_id, tx_type, cursor ) ensure(addr_refund_out is not None, "addr_refund_out is null") - self.log.debug("addr_refund_out %s", addr_refund_out) + self.log.debug(f"addr_refund_out {addr_refund_out}") locktime: int = 0 if ( @@ -4707,7 +4680,7 @@ class BasicSwap(BaseApp): ) if coin_type in (Coins.DCR,): txsize = len(refund_txn) // 2 - self.log.debug("size paid, actual size %d %d", tx_vsize, txsize) + self.log.debug(f"size paid, actual size {tx_vsize} {txsize}") ensure(tx_vsize >= txsize, "underpaid fee") elif ci.use_tx_vsize(): self.log.debug( @@ -4723,30 +4696,25 @@ class BasicSwap(BaseApp): refund_txid = ci.getTxid(bytes.fromhex(refund_txn)) prev_txid = ci.getTxid(bytes.fromhex(txn)) self.log.debug( - "Have valid refund txn %s for contract tx %s", - refund_txid.hex(), - prev_txid.hex(), + f"Have valid refund tx {self.log.id(refund_txid)} for contract tx {self.log.id(prev_txid)}", ) return refund_txn def initiateTxnConfirmed(self, bid_id: bytes, bid, offer) -> None: - self.log.debug("initiateTxnConfirmed for bid %s", bid_id.hex()) + self.log.debug(f"initiateTxnConfirmed for bid {self.log.id(bid_id)}") bid.setState(BidStates.SWAP_INITIATED) bid.setITxState(TxStates.TX_CONFIRMED) if bid.debug_ind == DebugTypes.BUYER_STOP_AFTER_ITX: self.log.debug( - "bid %s: Abandoning bid for testing: %d, %s.", - bid_id.hex(), - bid.debug_ind, - DebugTypes(bid.debug_ind).name, + f"{self.logIDB(bid_id)}: Abandoning for testing: {bid.debug_ind}, {DebugTypes(bid.debug_ind).name}." ) bid.setState(BidStates.BID_ABANDONED) self.logBidEvent( bid.bid_id, EventLogTypes.DEBUG_TWEAK_APPLIED, - "ind {}".format(bid.debug_ind), + f"ind {bid.debug_ind}", None, ) return # Bid saved in checkBidState @@ -4756,21 +4724,18 @@ class BasicSwap(BaseApp): if bid.was_sent: if bid.participate_tx is not None: self.log.warning( - "Participate txn %s already exists for bid %s", - bid.participate_tx.txid, - bid_id.hex(), + f"Participate tx {self.log.id(bid.participate_tx.txid)} already exists for bid {self.log.id(bid_id)}" ) else: - self.log.debug("Preparing participate txn for bid %s", bid_id.hex()) - - coin_to = Coins(offer.coin_to) - txn = self.createParticipateTxn(bid_id, bid, offer, participate_script) - txid = self.ci(coin_to).publishTx(bytes.fromhex(txn)) self.log.debug( - "Submitted participate txn %s to %s chain for bid %s", - txid, - chainparams[coin_to]["name"], - bid_id.hex(), + f"Preparing participate txn for bid {self.log.id(bid_id)}" + ) + + ci_to = self.ci(offer.coin_to) + txn = self.createParticipateTxn(bid_id, bid, offer, participate_script) + txid = ci_to.publishTx(bytes.fromhex(txn)) + self.log.debug( + f"Submitted participate tx {self.log.id(txid)} to {ci_to.coin_name()} chain for bid {self.log.id(bid_id)}" ) bid.setPTxState(TxStates.TX_SENT) self.logEvent( @@ -4815,13 +4780,13 @@ class BasicSwap(BaseApp): cc["last_height_checked"] = tx_height cc["block_check_min_time"] = block_time self.setIntKV("block_check_min_time_" + coin_name, block_time, cursor) - self.log.debug("Start checking %s chain at height %d", coin_name, tx_height) + self.log.debug(f"Start checking {coin_name} chain at height {tx_height}") elif cc["last_height_checked"] > tx_height: cc["last_height_checked"] = tx_height cc["block_check_min_time"] = block_time self.setIntKV("block_check_min_time_" + coin_name, block_time, cursor) self.log.debug( - "Rewind %s chain last height checked to %d", coin_name, tx_height + f"Rewind {coin_name} chain last height checked to {tx_height}" ) else: self.log.debug( @@ -4852,20 +4817,17 @@ class BasicSwap(BaseApp): # Start checking for spends of participate_txn before fully confirmed ci = self.ci(coin_type) self.log.debug( - "Watching %s chain for spend of output %s %d", - ci.coin_name().lower(), - txid_hex, - vout, + f"Watching {ci.coin_name()} chain for spend of output {self.logIDT(bid.participate_tx.txid)} {vout}" ) self.addWatchedOutput( coin_type, bid_id, txid_hex, vout, BidStates.SWAP_PARTICIPATING ) def participateTxnConfirmed(self, bid_id: bytes, bid, offer) -> None: - self.log.debug("participateTxnConfirmed for bid %s", bid_id.hex()) + self.log.debug(f"participateTxnConfirmed for bid {self.log.id(bid_id)}") if bid.debug_ind == DebugTypes.DONT_CONFIRM_PTX: - self.log.debug("Not confirming PTX for debugging", bid_id.hex()) + self.log.debug(f"Not confirming PTX for debugging {self.log.id(bid_id)}") return bid.setState(BidStates.SWAP_PARTICIPATING) @@ -4877,10 +4839,7 @@ class BasicSwap(BaseApp): txn = self.createRedeemTxn(ci_to.coin_type(), bid) txid = ci_to.publishTx(bytes.fromhex(txn)) self.log.debug( - "Submitted participate redeem txn %s to %s chain for bid %s", - txid, - ci_to.coin_name(), - bid_id.hex(), + f"Submitted participate redeem tx {self.log.id(txid)} to {ci_to.coin_name()} chain for bid {self.log.id(bid_id)}." ) self.logEvent( Concepts.BID, bid.bid_id, EventLogTypes.PTX_REDEEM_PUBLISHED, "", None @@ -4948,7 +4907,10 @@ class BasicSwap(BaseApp): if assert_txid is not None: try: ro = self.callcoinrpc(coin_type, "getmempoolentry", [assert_txid]) - self.log.debug("Tx %s found in mempool, fee %s", assert_txid, ro["fee"]) + fee = ro["fee"] + self.log.debug( + f"Tx {self.log.id(assert_txid)} found in mempool, fee {fee}" + ) # TODO: Save info return None except Exception: @@ -5041,7 +5003,7 @@ class BasicSwap(BaseApp): or bid.xmr_b_lock_tx.chain_height is None or xmr_swap.b_lock_tx_id != found_txid ): - self.log.debug("Found lock tx B in {} chain".format(ci_to.coin_name())) + self.log.debug(f"Found lock tx B in {ci_to.coin_name()} chain") xmr_swap.b_lock_tx_id = found_txid if bid.xmr_b_lock_tx is None: bid.xmr_b_lock_tx = SwapTx( @@ -5051,9 +5013,7 @@ class BasicSwap(BaseApp): ) if bid.xmr_b_lock_tx.txid != found_txid: self.log.debug( - "Updating {} lock txid: {}".format( - ci_to.coin_name(), found_txid.hex() - ) + f"Updating {ci_to.coin_name()} lock txid: {self.log.id(found_txid)}" ) bid.xmr_b_lock_tx.txid = found_txid @@ -5088,9 +5048,7 @@ class BasicSwap(BaseApp): if was_received: if bid.debug_ind == DebugTypes.BID_DONT_SPEND_COIN_A_LOCK_REFUND: self.log.debug( - "Adaptor-sig bid %s: Stalling bid for testing: %d.", - bid_id.hex(), - bid.debug_ind, + f"Adaptor-sig bid {self.log.id(bid_id)}: Stalling bid for testing: {bid.debug_ind}." ) bid.setState(BidStates.BID_STALLED_FOR_TEST) rv = True @@ -5131,9 +5089,7 @@ class BasicSwap(BaseApp): ) self.log.info( - "Submitted coin a lock refund spend tx for bid {}, txid {}".format( - bid_id.hex(), txid_str - ) + f"Submitted coin a lock refund spend tx for bid {self.log.id(bid_id)}, txid {self.log.id(txid_str)}" ) bid.txns[TxTypes.XMR_SWAP_A_LOCK_REFUND_SPEND] = SwapTx( bid_id=bid_id, @@ -5144,8 +5100,7 @@ class BasicSwap(BaseApp): self.commitDB() except Exception as ex: self.log.debug( - "Trying to publish coin a lock refund spend tx: %s", - str(ex), + f"Trying to publish coin a lock refund spend tx: {ex}" ) if was_sent: @@ -5173,9 +5128,7 @@ class BasicSwap(BaseApp): cursor, ) self.log.info( - "Submitted coin a lock refund swipe tx for bid {}".format( - bid_id.hex() - ) + f"Submitted coin a lock refund swipe tx for bid {self.log.id(bid_id)}" ) bid.txns[TxTypes.XMR_SWAP_A_LOCK_REFUND_SWIPE] = SwapTx( bid_id=bid_id, @@ -5211,9 +5164,7 @@ class BasicSwap(BaseApp): txid=bytes.fromhex(txid_hex), ) self.log.info( - "Submitted mercy tx for bid {}, txid {}".format( - bid_id.hex(), txid_hex - ) + f"Submitted mercy tx for bid {self.log.id(bid_id)}, txid {self.log.id(txid_hex)}" ) self.logBidEvent( bid_id, @@ -5223,17 +5174,14 @@ class BasicSwap(BaseApp): ) else: self.log.info( - "Not sending mercy tx for bid {}".format( - bid_id.hex() - ) + f"Not sending mercy tx for bid {self.log.id(bid_id)}" ) self.saveBidInSession(bid_id, bid, cursor, xmr_swap) self.commitDB() except Exception as ex: self.log.debug( - "Trying to publish coin a lock refund swipe tx: %s", - str(ex), + f"Trying to publish coin a lock refund swipe tx: {ex}" ) if BidStates(bid.state) == BidStates.XMR_SWAP_NOSCRIPT_TX_RECOVERED: @@ -5242,7 +5190,7 @@ class BasicSwap(BaseApp): found_tx = ci_to.findTxnByHash(txid_hex) if found_tx is not None: self.log.info( - "Found coin b lock recover tx bid %s", bid_id.hex() + f"Found coin b lock recover tx bid {self.log.id(bid_id)}" ) rv = True # Remove from swaps_in_progress bid.setState(BidStates.XMR_SWAP_FAILED_REFUNDED) @@ -5273,9 +5221,7 @@ class BasicSwap(BaseApp): ) self.log.info( - "Submitted coin a lock refund tx for bid {}".format( - bid_id.hex() - ) + f"Submitted coin a lock refund tx for bid {self.log.id(bid_id)}" ) self.logBidEvent( bid.bid_id, @@ -5294,9 +5240,7 @@ class BasicSwap(BaseApp): except Exception as ex: if ci_from.isTxExistsError(str(ex)): self.log.info( - "Found coin a lock refund tx for bid {}".format( - bid_id.hex() - ) + f"Found coin a lock refund tx for bid {self.log.id(bid_id)}" ) txid = ci_from.getTxid(xmr_swap.a_lock_refund_tx) if TxTypes.XMR_SWAP_A_LOCK_REFUND not in bid.txns: @@ -5326,9 +5270,7 @@ class BasicSwap(BaseApp): ): delay = self.get_delay_event_seconds() self.log.info( - "Recovering adaptor-sig swap chain B lock tx for bid %s in %d seconds", - bid_id.hex(), - delay, + f"Recovering adaptor-sig swap chain B lock tx for bid {self.log.id(bid_id)} in {delay} seconds" ) self.createActionInSession( delay, @@ -5427,9 +5369,7 @@ class BasicSwap(BaseApp): if was_sent: delay = self.get_delay_event_seconds() self.log.info( - "Sending adaptor-sig swap chain B lock tx for bid %s in %d seconds", - bid_id.hex(), - delay, + f"Sending adaptor-sig swap chain B lock tx for bid {self.log.id(bid_id)} in {delay} seconds", ) self.createActionInSession( delay, ActionTypes.SEND_XMR_SWAP_LOCK_TX_B, bid_id, cursor @@ -5476,15 +5416,13 @@ class BasicSwap(BaseApp): if bid.debug_ind == DebugTypes.BID_STOP_AFTER_COIN_B_LOCK: self.log.debug( - "Adaptor-sig bid %s: Stalling bid for testing: %d.", - bid_id.hex(), - bid.debug_ind, + f"Adaptor-sig bid {self.log.id(bid_id)}: Stalling bid for testing: {bid.debug_ind}." ) bid.setState(BidStates.BID_STALLED_FOR_TEST) self.logBidEvent( bid.bid_id, EventLogTypes.DEBUG_TWEAK_APPLIED, - "ind {}".format(bid.debug_ind), + f"ind {bid.debug_ind}", cursor, ) elif ( @@ -5500,16 +5438,12 @@ class BasicSwap(BaseApp): if was_received: if TxTypes.XMR_SWAP_A_LOCK_REFUND in bid.txns: self.log.warning( - "Not releasing ads script coin lock tx for bid {}: Chain A lock refund tx already exists.".format( - bid_id.hex() - ) + f"Not releasing ads script coin lock tx for bid {self.log.id(bid_id)}: Chain A lock refund tx already exists." ) else: delay = self.get_delay_event_seconds() self.log.info( - "Releasing ads script coin lock tx for bid %s in %d seconds", - bid_id.hex(), - delay, + f"Releasing ads script coin lock tx for bid {self.log.id(bid_id)} in {delay} seconds." ) self.createActionInSession( delay, @@ -5529,17 +5463,13 @@ class BasicSwap(BaseApp): try: txn_hex = ci_from.getMempoolTx(xmr_swap.a_lock_spend_tx_id) self.log.info( - "Found lock spend txn in %s mempool, %s", - ci_from.coin_name(), - xmr_swap.a_lock_spend_tx_id.hex(), + f"Found lock spend txn in {ci_from.coin_name()} mempool, {self.logIDT(xmr_swap.a_lock_spend_tx_id)}" ) self.process_XMR_SWAP_A_LOCK_tx_spend( bid_id, xmr_swap.a_lock_spend_tx_id.hex(), txn_hex, cursor ) except Exception as e: - self.log.debug( - "getrawtransaction lock spend tx failed: %s", str(e) - ) + self.log.debug(f"getrawtransaction lock spend tx failed: {e}") elif state == BidStates.XMR_SWAP_SCRIPT_TX_REDEEMED: if ( was_received @@ -5550,24 +5480,20 @@ class BasicSwap(BaseApp): ): if self.haveDebugInd(bid_id, DebugTypes.BID_DONT_SPEND_COIN_B_LOCK): self.log.debug( - "Adaptor-sig bid %s: Stalling bid for testing: %d.", - bid_id.hex(), - bid.debug_ind, + f"Adaptor-sig bid {self.log.id(bid_id)}: Stalling bid for testing: {bid.debug_ind}." ) # If BID_STALLED_FOR_TEST is set process_XMR_SWAP_A_LOCK_tx_spend would fail self.logBidEvent( bid.bid_id, EventLogTypes.DEBUG_TWEAK_APPLIED, - "ind {}".format(bid.debug_ind), + f"ind {bid.debug_ind}", cursor, ) else: bid.setState(BidStates.SWAP_DELAYING) delay = self.get_delay_event_seconds() self.log.info( - "Redeeming coin b lock tx for bid %s in %d seconds", - bid_id.hex(), - delay, + f"Redeeming coin b lock tx for bid {self.log.id(bid_id)} in {delay} seconds." ) self.createActionInSession( delay, @@ -5582,7 +5508,9 @@ class BasicSwap(BaseApp): found_tx = ci_to.findTxnByHash(txid_hex) if found_tx is not None: - self.log.info("Found coin b lock spend tx bid %s", bid_id.hex()) + self.log.info( + f"Found coin b lock spend tx bid {self.log.id(bid_id)}" + ) rv = True # Remove from swaps_in_progress bid.setState(BidStates.SWAP_COMPLETED) self.saveBidInSession(bid_id, bid, cursor, xmr_swap) @@ -5625,7 +5553,7 @@ class BasicSwap(BaseApp): # Return True to remove bid from in-progress list state = BidStates(bid.state) - self.log.debug("checkBidState %s %s", bid_id.hex(), str(state)) + self.log.debug(f"checkBidState {self.log.id(bid_id)} {state}") if offer.swap_type == SwapTypes.XMR_SWAP: return self.checkXmrBidState(bid_id, bid, offer) @@ -5639,7 +5567,7 @@ class BasicSwap(BaseApp): # TODO: Batch calls to scantxoutset # TODO: timeouts if state == BidStates.BID_ABANDONED: - self.log.info("Deactivating abandoned bid: %s", bid_id.hex()) + self.log.info(f"Deactivating abandoned bid: {self.log.id(bid_id)}") return True # Mark bid for archiving if state == BidStates.BID_ACCEPTED: # Waiting for initiate txn to be confirmed in 'from' chain @@ -5704,9 +5632,7 @@ class BasicSwap(BaseApp): if bid.initiate_tx.conf is not None: self.log.debug( - "initiate_txnid %s confirms %d", - initiate_txnid_hex, - bid.initiate_tx.conf, + f"initiate_txnid {self.log.id(initiate_txnid_hex)} confirms {bid.initiate_tx.conf}" ) if ( @@ -5745,7 +5671,7 @@ class BasicSwap(BaseApp): and bid.state_time + atomic_swap_1.INITIATE_TX_TIMEOUT < self.getTime() ): self.log.info( - "Swap timed out waiting for initiate tx for bid %s", bid_id.hex() + f"Swap timed out waiting for initiate tx for bid {self.log.id(bid_id)}" ) bid.setState( BidStates.SWAP_TIMEDOUT, "Timed out waiting for initiate tx" @@ -5792,10 +5718,7 @@ class BasicSwap(BaseApp): None if participate_txid is None else participate_txid.hex(), ) self.log.debug( - "Found bid %s participate txn %s in chain %s", - bid_id.hex(), - txid, - Coins(coin_to).name, + f"Found bid {self.log.id(bid_id)} participate txn {self.log.id(txid)} in chain {ci_to.coin_name()}." ) self.addParticipateTxn( bid_id, bid, coin_to, txid, index, found["height"] @@ -5816,9 +5739,7 @@ class BasicSwap(BaseApp): if bid.participate_tx.conf is not None: self.log.debug( - "participate txid %s confirms %d", - bid.participate_tx.txid.hex(), - bid.participate_tx.conf, + f"participate txid {self.log.id(bid.participate_tx.txid)} confirms {bid.participate_tx.conf}." ) if ( bid.participate_tx.conf @@ -5833,7 +5754,7 @@ class BasicSwap(BaseApp): # Wait for user input pass else: - self.log.warning("checkBidState unknown state %s", state) + self.log.warning(f"checkBidState unknown state {state}") if state > BidStates.BID_ACCEPTED: # Wait for spend of all known swap txns @@ -5842,7 +5763,7 @@ class BasicSwap(BaseApp): if (itx_state is None or itx_state >= TxStates.TX_REDEEMED) and ( ptx_state is None or ptx_state >= TxStates.TX_REDEEMED ): - self.log.info("Swap completed for bid %s", bid_id.hex()) + self.log.info(f"Swap completed for bid {self.log.id(bid_id)}") self.returnAddressToPool( bid_id, @@ -5879,10 +5800,7 @@ class BasicSwap(BaseApp): try: txid = ci_from.publishTx(bid.initiate_txn_refund) self.log.debug( - "Submitted initiate refund txn %s to %s chain for bid %s", - txid, - chainparams[coin_from]["name"], - bid_id.hex(), + f"Submitted initiate refund txn {self.log.id(txid)} to {ci_from.coin_name()} chain for bid {self.log.id(bid_id)}." ) self.logEvent( Concepts.BID, @@ -5895,7 +5813,7 @@ class BasicSwap(BaseApp): except Exception as ex: if ci_from.isTxNonFinalError(str(ex)) is False: self.log.warning( - "Error trying to submit initiate refund txn: %s", str(ex) + f"Error trying to submit initiate refund txn: {ex}" ) if ( @@ -5905,10 +5823,7 @@ class BasicSwap(BaseApp): try: txid = ci_to.publishTx(bid.participate_txn_refund) self.log.debug( - "Submitted participate refund txn %s to %s chain for bid %s", - txid, - chainparams[coin_to]["name"], - bid_id.hex(), + f"Submitted participate refund txn {self.log.id(txid)} to {ci_to.coin_name()} chain for bid {self.log.id(bid_id)}." ) self.logEvent( Concepts.BID, @@ -5921,7 +5836,7 @@ class BasicSwap(BaseApp): except Exception as ex: if ci_to.isTxNonFinalError(str(ex)): self.log.warning( - "Error trying to submit participate refund txn: %s", str(ex) + f"Error trying to submit participate refund txn: {ex}" ) return False # Bid is still active @@ -5947,11 +5862,7 @@ class BasicSwap(BaseApp): self, coin_type, bid_id, txid_hex, vout, tx_type, swap_type=None ): self.log.debug( - "Adding watched output %s bid %s tx %s type %s", - Coins(coin_type).name, - bid_id.hex(), - txid_hex, - tx_type, + f"Adding watched output {Coins(coin_type).name} bid {self.log.id(bid_id)} tx {self.log.id(txid_hex)} type {tx_type}" ) watched = self.coin_clients[coin_type]["watched_outputs"] @@ -5966,10 +5877,7 @@ class BasicSwap(BaseApp): def removeWatchedOutput(self, coin_type, bid_id: bytes, txid_hex: str) -> None: # Remove all for bid if txid is None self.log.debug( - "removeWatchedOutput %s %s %s", - Coins(coin_type).name, - bid_id.hex(), - txid_hex, + f"removeWatchedOutput {Coins(coin_type).name} {self.log.id(bid_id)} {self.log.id(txid_hex)}" ) old_len = len(self.coin_clients[coin_type]["watched_outputs"]) for i in range(old_len - 1, -1, -1): @@ -5977,20 +5885,14 @@ class BasicSwap(BaseApp): if wo.bid_id == bid_id and (txid_hex is None or wo.txid_hex == txid_hex): del self.coin_clients[coin_type]["watched_outputs"][i] self.log.debug( - "Removed watched output %s %s %s", - Coins(coin_type).name, - bid_id.hex(), - wo.txid_hex, + f"Removed watched output {Coins(coin_type).name} {self.log.id(bid_id)} {self.log.id(wo.txid_hex)}" ) def addWatchedScript( self, coin_type, bid_id, script: bytes, tx_type, swap_type=None ): self.log.debug( - "Adding watched script %s bid %s type %s", - Coins(coin_type).name, - bid_id.hex(), - tx_type, + f"Adding watched script {Coins(coin_type).name} bid {self.log.id(bid_id)} type {tx_type}." ) watched = self.coin_clients[coin_type]["watched_scripts"] @@ -6009,7 +5911,7 @@ class BasicSwap(BaseApp): self.log.debug( "removeWatchedScript {} {}{}".format( Coins(coin_type).name, - bid_id.hex(), + {self.log.id(bid_id)}, (" type " + str(tx_type)) if tx_type is not None else "", ) ) @@ -6023,14 +5925,14 @@ class BasicSwap(BaseApp): ): del self.coin_clients[coin_type]["watched_scripts"][i] self.log.debug( - "Removed watched script %s %s", Coins(coin_type).name, bid_id.hex() + f"Removed watched script {Coins(coin_type).name} {self.log.id(bid_id)}" ) def initiateTxnSpent( self, bid_id: bytes, spend_txid: str, spend_n: int, spend_txn ) -> None: self.log.debug( - "Bid %s initiate txn spent by %s %d", bid_id.hex(), spend_txid, spend_n + f"Bid {self.log.id(bid_id)} initiate txn spent by {self.logIDT(spend_txid)} {spend_n}." ) if bid_id in self.swaps_in_progress: @@ -6046,19 +5948,13 @@ class BasicSwap(BaseApp): secret = self.extractSecret(coin_from, bid, spend_in) if secret is None: self.log.info( - "Bid %s initiate txn refunded by %s %d", - bid_id.hex(), - spend_txid, - spend_n, + f"Bid {self.log.id(bid_id)} initiate txn refunded by {self.logIDT(spend_txid)} {spend_n}." ) # TODO: Wait for depth? bid.setITxState(TxStates.TX_REFUNDED) else: self.log.info( - "Bid %s initiate txn redeemed by %s %d", - bid_id.hex(), - spend_txid, - spend_n, + f"Bid {self.log.id(bid_id)} initiate txn redeemed by {self.logIDT(spend_txid)} {spend_n}." ) # TODO: Wait for depth? bid.setITxState(TxStates.TX_REDEEMED) @@ -6070,7 +5966,7 @@ class BasicSwap(BaseApp): self, bid_id: bytes, spend_txid: str, spend_n: int, spend_txn ) -> None: self.log.debug( - "Bid %s participate txn spent by %s %d", bid_id.hex(), spend_txid, spend_n + f"Bid {self.log.id(bid_id)} participate txn spent by {self.logIDT(spend_txid)} {spend_n}." ) # TODO: More SwapTypes @@ -6087,19 +5983,13 @@ class BasicSwap(BaseApp): secret = self.extractSecret(coin_to, bid, spend_in) if secret is None: self.log.info( - "Bid %s participate txn refunded by %s %d", - bid_id.hex(), - spend_txid, - spend_n, + f"Bid {self.log.id(bid_id)} participate txn refunded by {self.logIDT(spend_txid)} {spend_n}." ) # TODO: Wait for depth? bid.setPTxState(TxStates.TX_REFUNDED) else: self.log.debug( - "Secret %s extracted from participate spend %s %d", - secret.hex(), - spend_txid, - spend_n, + f"Secret {secret.hex()} extracted from participate spend {self.logIDT(spend_txid)} {spend_n}" ) bid.recovered_secret = secret # TODO: Wait for depth? @@ -6108,24 +5998,19 @@ class BasicSwap(BaseApp): if bid.was_sent: if bid.debug_ind == DebugTypes.DONT_SPEND_ITX: self.log.debug( - "bid %s: Abandoning bid for testing: %d, %s.", - bid_id.hex(), - bid.debug_ind, - DebugTypes(bid.debug_ind).name, + f"{self.logIDB(bid_id)}: Abandoning for testing: {bid.debug_ind}, {DebugTypes(bid.debug_ind).name}." ) bid.setState(BidStates.BID_ABANDONED) self.logBidEvent( bid.bid_id, EventLogTypes.DEBUG_TWEAK_APPLIED, - "ind {}".format(bid.debug_ind), + f"ind {bid.debug_ind}", None, ) else: delay = self.get_short_delay_event_seconds() self.log.info( - "Redeeming ITX for bid %s in %d seconds", - bid_id.hex(), - delay, + f"Redeeming ITX for bid {self.log.id(bid_id)} in {delay} seconds." ) self.createAction(delay, ActionTypes.REDEEM_ITX, bid_id) # TODO: Wait for depth? new state SWAP_TXI_REDEEM_SENT? @@ -6137,7 +6022,7 @@ class BasicSwap(BaseApp): self, bid_id: bytes, spend_txid_hex, spend_txn_hex, cursor=None ) -> None: self.log.debug( - "Detected spend of Adaptor-sig swap coin a lock tx for bid %s", bid_id.hex() + f"Detected spend of Adaptor-sig swap coin a lock tx for bid {self.log.id(bid_id)}" ) try: use_cursor = self.openDB(cursor) @@ -6146,7 +6031,7 @@ class BasicSwap(BaseApp): ensure(xmr_swap, "Adaptor-sig swap not found: {}.".format(bid_id.hex())) if BidStates(bid.state) == BidStates.BID_STALLED_FOR_TEST: - self.log.debug("Bid stalled %s", bid_id.hex()) + self.log.debug(f"Bid stalled{self.log.id(bid_id)}") return offer, xmr_offer = self.getXmrOfferFromSession(use_cursor, bid.offer_id) @@ -6194,9 +6079,7 @@ class BasicSwap(BaseApp): else: # Could already be processed if spend was detected in the mempool self.log.warning( - "Coin a lock tx spend ignored due to bid state for bid {}".format( - bid_id.hex() - ) + f"Coin a lock tx spend ignored due to bid state for bid {self.log.id(bid_id)}." ) elif spending_txid == xmr_swap.a_lock_refund_tx_id or ( @@ -6261,8 +6144,7 @@ class BasicSwap(BaseApp): self, bid_id: bytes, spend_txid_hex: str, spend_txn ) -> None: self.log.debug( - "Detected spend of Adaptor-sig swap coin a lock refund tx for bid %s", - bid_id.hex(), + f"Detected spend of Adaptor-sig swap coin a lock refund tx for bid {self.log.id(bid_id)}." ) try: cursor = self.openDB() @@ -6298,7 +6180,7 @@ class BasicSwap(BaseApp): and is_spending_lock_refund_tx ): self.log.info( - "Found coin a lock refund spend tx, bid {}".format(bid_id.hex()) + f"Found coin a lock refund spend tx, bid {self.log.id(bid_id)}." ) # bch txids change @@ -6334,9 +6216,7 @@ class BasicSwap(BaseApp): if bid.xmr_b_lock_tx is not None: delay = self.get_delay_event_seconds() self.log.info( - "Recovering adaptor-sig swap chain B lock tx for bid %s in %d seconds", - bid_id.hex(), - delay, + f"Recovering adaptor-sig swap chain B lock tx for bid {self.log.id(bid_id)} in {delay} seconds." ) self.createActionInSession( delay, @@ -6354,9 +6234,7 @@ class BasicSwap(BaseApp): else: self.log.info( - "Coin a lock refund spent by unknown tx, bid {}".format( - bid_id.hex() - ) + f"Coin a lock refund spent by unknown tx, bid {self.log.id(bid_id)}." ) mercy_keyshare = None @@ -6376,9 +6254,7 @@ class BasicSwap(BaseApp): ) except Exception as e: self.log.warning( - "Could not extract mercy output from swipe tx: {}, {}".format( - spend_txid_hex, e - ) + f"Could not extract mercy output from swipe tx: {self.log.id(spend_txid_hex)}, {e}." ) if mercy_keyshare is None: @@ -6386,9 +6262,7 @@ class BasicSwap(BaseApp): else: delay = self.get_delay_event_seconds() self.log.info( - "Redeeming coin b lock tx for bid %s in %d seconds", - bid_id.hex(), - delay, + f"Redeeming coin b lock tx for bid {self.log.id(bid_id)} in {delay} seconds." ) self.createActionInSession( delay, @@ -6457,31 +6331,23 @@ class BasicSwap(BaseApp): self.saveBid(watched_script.bid_id, bid) else: self.log.warning( - "Could not find active bid for found watched script: {}".format( - watched_script.bid_id.hex() - ) + f"Could not find active bid for found watched script: {self.logIDB(watched_script.bid_id)}." ) elif watched_script.tx_type == TxTypes.XMR_SWAP_A_LOCK: self.log.info( - "Found chain A lock txid {} for bid: {}".format( - txid.hex(), watched_script.bid_id.hex() - ) + f"Found chain A lock txid {self.log.id(txid)} for bid: {self.log.id(watched_script.bid_id)}." ) bid = self.swaps_in_progress[watched_script.bid_id][0] if bid.xmr_a_lock_tx.txid != txid: self.log.debug( - "Updating xmr_a_lock_tx from {} to {}".format( - hex_or_none(bid.xmr_a_lock_tx.txid), txid.hex() - ) + f"Updating xmr_a_lock_tx from {self.log.id(bid.xmr_a_lock_tx.txid)} to {txid}." ) bid.xmr_a_lock_tx.txid = txid bid.xmr_a_lock_tx.vout = vout self.saveBid(watched_script.bid_id, bid) elif watched_script.tx_type == TxTypes.XMR_SWAP_B_LOCK: self.log.info( - "Found chain B lock txid {} for bid: {}".format( - txid.hex(), watched_script.bid_id.hex() - ) + f"Found chain B lock txid {self.log.id(txid)} for bid: {self.log.id(watched_script.bid_id)}." ) bid = self.swaps_in_progress[watched_script.bid_id][0] bid.xmr_b_lock_tx = SwapTx( @@ -6492,9 +6358,7 @@ class BasicSwap(BaseApp): ) if bid.xmr_b_lock_tx.txid != txid: self.log.debug( - "Updating xmr_b_lock_tx from {} to {}".format( - hex_or_none(bid.xmr_b_lock_tx.txid), txid.hex() - ) + f"Updating xmr_b_lock_tx from {self.log.id(bid.xmr_b_lock_tx.txid)} to {self.log.id(txid)}." ) bid.xmr_b_lock_tx.txid = txid bid.xmr_b_lock_tx.vout = vout @@ -6502,9 +6366,7 @@ class BasicSwap(BaseApp): self.saveBid(watched_script.bid_id, bid) else: self.log.warning( - "Unknown found watched script tx type for bid {}".format( - watched_script.bid_id.hex() - ) + f"Unknown found watched script tx type for bid {self.log.id(watched_script.bid_id)}." ) self.removeWatchedScript( @@ -6520,11 +6382,11 @@ class BasicSwap(BaseApp): len(tx["vout"]) < 2 or ci.make_int(tx["vout"][vout]["value"]) != 546 ): # Dust limit - self.log.info("Found tx is not a mercy tx for bid: {}".format(bid_id.hex())) + self.log.info(f"Found tx is not a mercy tx for bid: {self.log.id(bid_id)}.") self.removeWatchedScript(coin_type, bid_id, watched_script.script) return - self.log.info("Found mercy tx for bid: {}".format(bid_id.hex())) + self.log.info(f"Found mercy tx for bid: {self.log.id(bid_id)}.") self.logBidEvent( bid_id, EventLogTypes.BCH_MERCY_TX_FOUND, txid.hex(), cursor=None @@ -6532,7 +6394,7 @@ class BasicSwap(BaseApp): if bid_id not in self.swaps_in_progress: self.log.warning( - "Could not find active bid for found mercy tx: {}".format(bid_id.hex()) + f"Could not find active bid for found mercy tx: {self.logIDB(bid_id)}." ) else: mercy_keyshare = bytes.fromhex( @@ -6551,7 +6413,7 @@ class BasicSwap(BaseApp): delay = self.get_delay_event_seconds() self.log.info( - "Redeeming coin b lock tx for bid %s in %d seconds", bid_id.hex(), delay + f"Redeeming coin b lock tx for bid {self.logIDB(bid_id)} in {delay} seconds." ) self.createAction(delay, ActionTypes.REDEEM_XMR_SWAP_LOCK_TX_B, bid_id) @@ -6608,7 +6470,7 @@ class BasicSwap(BaseApp): def checkForSpends(self, coin_type, c): # assert (self.mxDB.locked()) - self.log.debug("checkForSpends %s", Coins(coin_type).name) + self.log.debug(f"checkForSpends {Coins(coin_type).name}.") # TODO: Check for spends on watchonly txns where possible if self.coin_clients[coin_type].get("have_spent_index", False): @@ -6623,17 +6485,13 @@ class BasicSwap(BaseApp): ) except Exception as ex: if "Unable to get spent info" not in str(ex): - self.log.warning("getspentinfo %s", str(ex)) + self.log.warning(f"getspentinfo {ex}") if found_spend is not None: - self.log.debug( - "Found spend in spentindex %s %d in %s %d", - o.txid_hex, - o.vout, - found_spend["txid"], - found_spend["index"], - ) spend_txid = found_spend["txid"] spend_n = found_spend["index"] + self.log.debug( + f"Found spend in spentindex {self.logIDT(o.txid_hex)} {o.vout} in {self.logIDT(spend_txid)} {spend_n}" + ) spend_txn = self.callcoinrpc( Coins.PART, "getrawtransaction", [spend_txid, True] ) @@ -6647,9 +6505,7 @@ class BasicSwap(BaseApp): last_height_checked: int = c["last_height_checked"] block_check_min_time: int = c["block_check_min_time"] self.log.debug( - "{} chain_blocks, last_height_checked {} {}".format( - ci.ticker(), chain_blocks, last_height_checked - ) + f"{ci.ticker()} chain_blocks, last_height_checked {chain_blocks} {last_height_checked}." ) blocks_checked: int = 0 @@ -6659,15 +6515,11 @@ class BasicSwap(BaseApp): blocks_checked += 1 if blocks_checked % 10000 == 0: self.log.debug( - "{} chain_blocks, last_height_checked, blocks_checked {} {} {}".format( - ci.ticker(), chain_blocks, last_height_checked, blocks_checked - ) + f"{ci.ticker()} chain_blocks, last_height_checked, blocks_checked {chain_blocks} {last_height_checked} {blocks_checked}." ) if blocks_checked > self._max_check_loop_blocks: self.log.debug( - "Hit max_check_loop_blocks for {} chain_blocks, last_height_checked {} {}".format( - ci.ticker(), chain_blocks, last_height_checked - ) + f"Hit max_check_loop_blocks for {ci.ticker()} chain_blocks, last_height_checked {chain_blocks} {last_height_checked}" ) break @@ -6678,13 +6530,11 @@ class BasicSwap(BaseApp): if "Block not available (pruned data)" in str(e): # TODO: Better solution? bci = ci.getBlockchainInfo() + pruneheight = bci["pruneheight"] self.log.error( - "Coin %s last_height_checked %d set to pruneheight %d", - ci.coin_name(), - last_height_checked, - bci["pruneheight"], + f"Coin {ci.coin_name()} last_height_checked {last_height_checked} set to pruneheight {pruneheight}." ) - last_height_checked = bci["pruneheight"] + last_height_checked = pruneheight continue else: self.logException(f"getblock error {e}") @@ -6707,20 +6557,14 @@ class BasicSwap(BaseApp): if "scriptPubKey" in txo and "hex" in txo["scriptPubKey"]: # TODO: Optimise by loading rawtx in CTransaction if bytes.fromhex(txo["scriptPubKey"]["hex"]) == s.script: + txid_bytes = bytes.fromhex(tx["txid"]) self.log.debug( - "Found script from search for bid %s: %s %d", - s.bid_id.hex(), - tx["txid"], - i, + f"Found script from search for bid {self.log.id(s.bid_id)}: {self.logIDT(txid_bytes)} {i}." ) if s.tx_type == TxTypes.BCH_MERCY: - self.processMercyTx( - coin_type, s, bytes.fromhex(tx["txid"]), i, tx - ) + self.processMercyTx(coin_type, s, txid_bytes, i, tx) else: - self.processFoundScript( - coin_type, s, bytes.fromhex(tx["txid"]), i - ) + self.processFoundScript(coin_type, s, txid_bytes, i) for o in c["watched_outputs"]: for i, inp in enumerate(tx["vin"]): @@ -6728,14 +6572,11 @@ class BasicSwap(BaseApp): if inp_txid is None: # Coinbase continue if inp_txid == o.txid_hex and inp["vout"] == o.vout: + txid = tx["txid"] self.log.debug( - "Found spend from search %s %d in %s %d", - o.txid_hex, - o.vout, - tx["txid"], - i, + f"Found spend from search {self.logIDT(o.txid_hex)} {o.vout} in {self.logIDT(txid)} {i}." ) - self.processSpentOutput(coin_type, o, tx["txid"], i, tx) + self.processSpentOutput(coin_type, o, txid, i, tx) last_height_checked += 1 self.updateCheckedBlock(ci, c, block) @@ -6781,9 +6622,7 @@ class BasicSwap(BaseApp): remove_if_expired(msg) if num_messages + num_removed > 0: - self.log.info( - "Expired {} / {} messages.".format(num_removed, num_messages) - ) + self.log.info(f"Expired {num_removed} / {num_messages} messages.") finally: if rpc_conn: @@ -6792,7 +6631,7 @@ class BasicSwap(BaseApp): def expireDBRecords(self) -> None: if self._is_locked is True: - self.log.debug("Not expiring database records while system locked") + self.log.debug("Not expiring database records while system locked.") return if not self._expire_db_records: return @@ -6801,7 +6640,7 @@ class BasicSwap(BaseApp): def checkAcceptedBids(self) -> None: # Check for bids stuck as accepted (not yet in-progress) if self._is_locked is True: - self.log.debug("Not checking accepted bids while system locked") + self.log.debug("Not checking accepted bids while system locked.") return now: int = self.getTime() @@ -6823,7 +6662,7 @@ class BasicSwap(BaseApp): ) for row in q: bid_id = row[0] - self.log.info("Timing out bid {}.".format(bid_id.hex())) + self.log.info(f"Timing out bid {self.log.id(bid_id)}.") self.timeoutBid(bid_id, cursor) finally: @@ -6950,9 +6789,7 @@ class BasicSwap(BaseApp): self.receiveXmrBid(bid, cursor) except Exception as ex: self.log.info( - "Verify adaptor-sig bid {} failed: {}".format( - bid.bid_id.hex(), str(ex) - ) + f"Verify adaptor-sig bid {self.log.id(bid.bid_id)} failed: {ex}" ) if self.debug: self.log.error(traceback.format_exc()) @@ -6970,7 +6807,7 @@ class BasicSwap(BaseApp): continue if bid.created_at + ttl_xmr_split_messages < now: self.log.debug( - "Expiring partially received bid: {}".format(bid.bid_id.hex()) + f"Expiring partially received bid: {self.log.id(bid.bid_id)}." ) bid.setState(BidStates.BID_ERROR, "Timed out") self.updateDB( @@ -7000,9 +6837,7 @@ class BasicSwap(BaseApp): if self.debug: self.log.error(traceback.format_exc()) self.log.info( - "Verify adaptor-sig bid accept {} failed: {}".format( - bid.bid_id.hex(), str(ex) - ) + f"Verify adaptor-sig bid accept {self.log.id(bid.bid_id)} failed: {ex}." ) bid.setState( BidStates.BID_ERROR, "Failed accept validation: " + str(ex) @@ -7018,9 +6853,7 @@ class BasicSwap(BaseApp): continue if bid.created_at + ttl_xmr_split_messages < now: self.log.debug( - "Expiring partially received bid accept: {}".format( - bid.bid_id.hex() - ) + f"Expiring partially received bid accept: {self.log.id(bid.bid_id)}." ) bid.setState(BidStates.BID_ERROR, "Timed out") self.updateDB( @@ -7052,7 +6885,7 @@ class BasicSwap(BaseApp): if self.shouldAutoAcceptBid(offer, bid, cursor=cursor): delay = self.get_delay_event_seconds() self.log.info( - "Auto accepting bid %s in %d seconds", bid.bid_id.hex(), delay + f"Auto accepting bid {self.log.id(bid.bid_id)} in {delay} seconds." ) self.createActionInSession( delay, ActionTypes.ACCEPT_BID, bid.bid_id, cursor @@ -7258,15 +7091,13 @@ class BasicSwap(BaseApp): # Offer may not have been received yet, or involved an inactive coin on this node. self.log.debug( - "Offer not found to revoke: {}".format(msg_data.offer_msg_id.hex()) + f"Offer not found to revoke: {self.log.id(msg_data.offer_msg_id)}." ) return if offer.expire_at <= now: self.log.debug( - "Offer is already expired, no need to revoke: {}".format( - msg_data.offer_msg_id.hex() - ) + f"Offer is already expired, no need to revoke: {self.log.id(msg_data.offer_msg_id)}." ) return @@ -7383,7 +7214,7 @@ class BasicSwap(BaseApp): bid_amount = bid.amount_to bid_rate = options.get("bid_rate") - self.log.debug("Evaluating against strategy {}".format(strategy.record_id)) + self.log.debug(f"Evaluating against strategy {strategy.record_id}.") now: int = self.getTime() if bid.expire_at < now: @@ -7425,11 +7256,11 @@ class BasicSwap(BaseApp): num_not_completed += 1 max_concurrent_bids = opts.get("max_concurrent_bids", 1) self.log.debug( - f"active_bids {num_not_completed}, max_concurrent_bids {max_concurrent_bids}" + f"active_bids {num_not_completed}, max_concurrent_bids {max_concurrent_bids}." ) if num_not_completed >= max_concurrent_bids: raise AutomationConstraintTemporary( - "Already have {} bids to complete".format(num_not_completed) + f"Already have {num_not_completed} bids to complete" ) identity_stats = self.queryOne( @@ -7456,9 +7287,7 @@ class BasicSwap(BaseApp): return True except (AutomationConstraint, AutomationConstraintTemporary) as e: - self.log.info( - "Not auto accepting bid {}, {}".format(bid.bid_id.hex(), str(e)) - ) + self.log.info(f"Not auto accepting bid {self.log.id(bid.bid_id)}, {e}.") if self.debug: self.logEvent( Concepts.BID, @@ -7489,7 +7318,7 @@ class BasicSwap(BaseApp): self.closeDB(use_cursor) def processBid(self, msg) -> None: - self.log.debug("Processing bid msg %s", msg["msgid"]) + self.log.debug("Processing bid msg {}.".format(self.log.id(msg["msgid"]))) now: int = self.getTime() bid_bytes = bytes.fromhex(msg["hex"][2:-2]) bid_data = BidMessage(init_all=False) @@ -7532,9 +7361,9 @@ class BasicSwap(BaseApp): bid_data.proof_address, bid_data.proof_signature, proof_utxos, offer_id ) self.log.debug( - "Proof of funds %s %s", - bid_data.proof_address, - self.ci(coin_to).format_amount(sum_unspent), + "Proof of funds {} {}.".format( + bid_data.proof_address, self.ci(coin_to).format_amount(sum_unspent) + ) ) ensure(sum_unspent >= bid_data.amount_to, "Proof of funds failed") @@ -7593,11 +7422,15 @@ class BasicSwap(BaseApp): if self.shouldAutoAcceptBid(offer, bid): delay = self.get_delay_event_seconds() - self.log.info("Auto accepting bid %s in %d seconds", bid_id.hex(), delay) + self.log.info( + f"Auto accepting bid {self.log.id(bid_id)} in {delay} seconds." + ) self.createAction(delay, ActionTypes.ACCEPT_BID, bid_id) def processBidAccept(self, msg) -> None: - self.log.debug("Processing bid accepted msg %s", msg["msgid"]) + self.log.debug( + "Processing bid accepted msg {}".format(self.log.id(msg["msgid"])) + ) now: int = self.getTime() bid_accept_bytes = bytes.fromhex(msg["hex"][2:-2]) bid_accept_data = BidAcceptMessage(init_all=False) @@ -7607,7 +7440,7 @@ class BasicSwap(BaseApp): ensure(len(bid_accept_data.initiate_txid) == 32, "Bad initiate_txid length") ensure(len(bid_accept_data.contract_script) < 100, "Bad contract_script length") - self.log.debug("for bid %s", bid_accept_data.bid_msg_id.hex()) + self.log.debug("for bid {self.log.id(bid_accept_data.bid_msg_id)}.") bid_id: bytes = bid_accept_data.bid_msg_id bid, offer = self.getBidAndOffer(bid_id) @@ -7628,9 +7461,7 @@ class BasicSwap(BaseApp): ) self.log.info( - "Received valid bid accept %s for bid %s sent to self", - accept_msg_id.hex(), - bid_id.hex(), + f"Received valid bid accept {self.logIDM(accept_msg_id)} for bid {self.log.id(bid_id)} sent to self." ) return raise ValueError("Wrong bid state: {}".format(BidStates(bid.state).name)) @@ -7723,7 +7554,7 @@ class BasicSwap(BaseApp): self.notify(NT.BID_ACCEPTED, {"bid_id": bid_id.hex()}) def receiveXmrBid(self, bid, cursor) -> None: - self.log.debug("Receiving adaptor-sig bid %s", bid.bid_id.hex()) + self.log.debug(f"Receiving adaptor-sig bid {self.log.id(bid.bid_id)}.") offer, xmr_offer = self.getXmrOfferFromSession(cursor, bid.offer_id) ensure(offer, "Offer not found: {}.".format(bid.offer_id.hex())) @@ -7808,10 +7639,9 @@ class BasicSwap(BaseApp): if reverse_bid or self.shouldAutoAcceptBid(offer, bid, cursor): delay = self.get_delay_event_seconds() self.log.info( - "Auto accepting %sadaptor-sig bid %s in %d seconds", - "reverse " if reverse_bid else "", - bid.bid_id.hex(), - delay, + "Auto accepting {}adaptor-sig bid {} in {} seconds.".format( + "reverse " if reverse_bid else "", self.log.id(bid.bid_id), delay + ) ) self.createActionInSession( delay, ActionTypes.ACCEPT_XMR_BID, bid.bid_id, cursor @@ -7822,7 +7652,7 @@ class BasicSwap(BaseApp): def receiveXmrBidAccept(self, bid, cursor) -> None: # Follower receiving MSG1F and MSG2F - self.log.debug("Receiving adaptor-sig bid accept %s", bid.bid_id.hex()) + self.log.debug(f"Receiving adaptor-sig bid accept {self.log.id(bid.bid_id)}.") offer, xmr_offer = self.getXmrOffer(bid.offer_id, cursor=cursor) ensure(offer, "Offer not found: {}.".format(bid.offer_id.hex())) @@ -7903,9 +7733,7 @@ class BasicSwap(BaseApp): delay = self.get_delay_event_seconds() self.log.info( - "Responding to adaptor-sig bid accept %s in %d seconds", - bid.bid_id.hex(), - delay, + f"Responding to adaptor-sig bid accept {self.log.id(bid.bid_id)} in {delay} seconds." ) self.createActionInSession( delay, ActionTypes.SIGN_XMR_SWAP_LOCK_TX_A, bid.bid_id, cursor @@ -7913,7 +7741,9 @@ class BasicSwap(BaseApp): def processXmrBid(self, msg) -> None: # MSG1L - self.log.debug("Processing adaptor-sig bid msg %s", msg["msgid"]) + self.log.debug( + "Processing adaptor-sig bid msg {}".format(self.log.id(msg["msgid"])) + ) now: int = self.getTime() bid_bytes = bytes.fromhex(msg["hex"][2:-2]) bid_data = XmrBidMessage(init_all=False) @@ -7992,9 +7822,7 @@ class BasicSwap(BaseApp): if bid.chain_b_height_start < wallet_restore_height: bid.chain_b_height_start = wallet_restore_height self.log.warning( - "Adaptor-sig swap restore height clamped to {}".format( - wallet_restore_height - ) + f"Adaptor-sig swap restore height clamped to {wallet_restore_height}." ) else: ensure( @@ -8008,9 +7836,7 @@ class BasicSwap(BaseApp): bid.setState(BidStates.BID_RECEIVING) self.log.info( - "Receiving adaptor-sig bid %s for offer %s", - bid_id.hex(), - bid_data.offer_msg_id.hex(), + f"Receiving adaptor-sig bid {self.log.id(bid_id)} for offer {self.log.id(bid_data.offer_msg_id)}." ) self.saveBid(bid_id, bid, xmr_swap=xmr_swap) @@ -8023,7 +7849,11 @@ class BasicSwap(BaseApp): def processXmrBidAccept(self, msg) -> None: # F receiving MSG1F and MSG2F - self.log.debug("Processing adaptor-sig bid accept msg %s", msg["msgid"]) + self.log.debug( + "Processing adaptor-sig bid accept msg {}.".format( + self.log.id(msg["msgid"]) + ) + ) msg_bytes = bytes.fromhex(msg["hex"][2:-2]) msg_data = XmrBidAcceptMessage(init_all=False) @@ -8031,7 +7861,7 @@ class BasicSwap(BaseApp): ensure(len(msg_data.bid_msg_id) == 28, "Bad bid_msg_id length") - self.log.debug("for bid %s", msg_data.bid_msg_id.hex()) + self.log.debug(f"for bid {self.log.id(msg_data.bid_msg_id)}.") bid, xmr_swap = self.getXmrBid(msg_data.bid_msg_id) ensure(bid, "Bid not found: {}.".format(msg_data.bid_msg_id.hex())) ensure( @@ -8166,7 +7996,7 @@ class BasicSwap(BaseApp): **refundExtraArgs, ) - self.log.info("Checking leader's lock refund tx signature") + self.log.info("Checking leader's lock refund tx signature.") prevout_amount = ci_from.getLockTxSwapOutputValue(bid, xmr_swap) v = ci_from.verifyTxSig( xmr_swap.a_lock_refund_tx, @@ -8206,14 +8036,14 @@ class BasicSwap(BaseApp): self.setBidError(bid.bid_id, bid, str(ex), xmr_swap=xmr_swap) def watchXmrSwap(self, bid, offer, xmr_swap, cursor=None) -> None: - self.log.debug("Adaptor-sig swap in progress, bid %s", bid.bid_id.hex()) + self.log.debug(f"Adaptor-sig swap in progress, bid {self.log.id(bid.bid_id)}.") self.swaps_in_progress[bid.bid_id] = (bid, offer) reverse_bid: bool = self.is_reverse_ads_bid(offer.coin_from, offer.coin_to) coin_from = Coins(offer.coin_to if reverse_bid else offer.coin_from) self.setLastHeightCheckedStart(coin_from, bid.chain_a_height_start, cursor) - if bid.xmr_a_lock_tx.txid: + if bid.xmr_a_lock_tx and bid.xmr_a_lock_tx.txid: self.addWatchedOutput( coin_from, bid.bid_id, @@ -8246,7 +8076,7 @@ class BasicSwap(BaseApp): def sendXmrBidTxnSigsFtoL(self, bid_id, cursor) -> None: # F -> L: Sending MSG3L - self.log.debug("Signing adaptor-sig bid lock txns %s", bid_id.hex()) + self.log.debug(f"Signing adaptor-sig bid lock txns {self.logIDB(bid_id)}.") bid, xmr_swap = self.getXmrBidFromSession(cursor, bid_id) ensure(bid, "Bid not found: {}.".format(bid_id.hex())) @@ -8315,9 +8145,7 @@ class BasicSwap(BaseApp): cursor=cursor, ) self.log.info( - "Sent XMR_BID_TXN_SIGS_FL %s for bid %s", - coin_a_lock_tx_sigs_l_msg_id.hex(), - bid_id.hex(), + f"Sent XMR_BID_TXN_SIGS_FL {self.logIDM(coin_a_lock_tx_sigs_l_msg_id)} for bid {self.log.id(bid_id)}." ) if ci_from.watch_blocks_for_scripts() and self.isBchXmrSwap(offer): @@ -8333,15 +8161,13 @@ class BasicSwap(BaseApp): if a_lock_tx_id: self.log.debug( - "Waiting for lock tx A {} to {} chain for bid {}".format( - a_lock_tx_id.hex(), ci_from.coin_name(), bid_id.hex() - ) + f"Waiting for lock tx A {self.log.id(a_lock_tx_id)} to {ci_from.coin_name()} chain for bid {self.log.id(bid_id)}." ) else: find_script: bytes = ci_from.getScriptDest(xmr_swap.a_lock_tx_script) self.log.debug( "Waiting for lock tx A with script {} to {} chain for bid {}".format( - find_script.hex(), ci_from.coin_name(), bid_id.hex() + find_script.hex(), ci_from.coin_name(), self.log.id(bid_id) ) ) @@ -8363,7 +8189,9 @@ class BasicSwap(BaseApp): def sendXmrBidCoinALockTx(self, bid_id: bytes, cursor) -> None: # Offerer/Leader. Send coin A lock tx - self.log.debug("Sending coin A lock tx for adaptor-sig bid %s", bid_id.hex()) + self.log.debug( + f"Sending coin A lock tx for adaptor-sig bid {self.log.id(bid_id)}." + ) bid, xmr_swap = self.getXmrBidFromSession(cursor, bid_id) ensure(bid, "Bid not found: {}.".format(bid_id.hex())) @@ -8421,16 +8249,14 @@ class BasicSwap(BaseApp): if bid.xmr_a_lock_tx and bid.xmr_a_lock_tx.state: if bid.xmr_a_lock_tx.state >= TxStates.TX_SENT: self.log.warning( - "Lock tx has already been sent {}".format( - bid.xmr_a_lock_tx.txid.hex() - ) + f"Lock tx has already been sent {self.logIDT(bid.xmr_a_lock_tx.txid)}." ) lock_tx_sent = True if lock_tx_sent is False: lock_tx_signed = ci_from.signTxWithWallet(xmr_swap.a_lock_tx) if not self.isBchXmrSwap(offer): - # Double check txid hashn't changed, can happen if the prevouts are not segwit + # Double check txid hasn't changed, can happen if the prevouts are not segwit if ci_from.getTxid(lock_tx_signed) != xmr_swap.a_lock_tx_id: self.log.debug(f"Before tx {xmr_swap.a_lock_tx.hex()}") self.log.debug(f"After tx {lock_tx_signed.hex()}") @@ -8440,7 +8266,7 @@ class BasicSwap(BaseApp): if txid_hex != b2h(xmr_swap.a_lock_tx_id): self.log.info( - "Recomputing refund transactions and txids after lock tx publish" + "Recomputing refund transactions and txids after lock tx publish." ) xmr_swap.a_lock_tx = lock_tx_signed xmr_swap.a_lock_tx_id = bytes.fromhex(txid_hex) @@ -8476,10 +8302,7 @@ class BasicSwap(BaseApp): xmr_swap.a_lock_tx, xmr_swap.a_lock_tx_script ) self.log.debug( - "Submitted lock txn %s to %s chain for bid %s", - txid_hex, - ci_from.coin_name(), - bid_id.hex(), + f"Submitted lock tx {self.log.id(txid_hex)} to {ci_from.coin_name()} chain for bid {self.log.id(bid_id)}.", ) if bid.xmr_a_lock_tx is None: @@ -8497,9 +8320,7 @@ class BasicSwap(BaseApp): delay = self.get_short_delay_event_seconds() self.log.info( - "Sending lock spend tx message for bid %s in %d seconds", - bid_id.hex(), - delay, + f"Sending lock spend tx message for bid {self.log.id(bid_id)} in {delay} seconds." ) self.createActionInSession( delay, ActionTypes.SEND_XMR_SWAP_LOCK_SPEND_MSG, bid_id, cursor @@ -8509,7 +8330,9 @@ class BasicSwap(BaseApp): def sendXmrBidCoinBLockTx(self, bid_id: bytes, cursor) -> None: # Follower sending coin B lock tx - self.log.debug("Sending coin B lock tx for adaptor-sig bid %s", bid_id.hex()) + self.log.debug( + f"Sending coin B lock tx for adaptor-sig bid {self.log.id(bid_id)}." + ) bid, xmr_swap = self.getXmrBidFromSession(cursor, bid_id) ensure(bid, "Bid not found: {}.".format(bid_id.hex())) @@ -8530,23 +8353,19 @@ class BasicSwap(BaseApp): if bid.xmr_b_lock_tx: self.log.warning( - "Coin B lock tx {} exists for adaptor-sig bid {}".format( - bid.xmr_b_lock_tx.b_lock_tx_id, bid_id.hex() - ) + f"Coin B lock tx {self.log.id(bid.xmr_b_lock_tx.b_lock_tx_id)} exists for adaptor-sig bid {self.log.id(bid_id)}." ) return if bid.debug_ind == DebugTypes.BID_STOP_AFTER_COIN_A_LOCK: self.log.debug( - "Adaptor-sig bid %s: Stalling bid for testing: %d.", - bid_id.hex(), - bid.debug_ind, + f"Adaptor-sig bid {self.log.id(bid_id)}: Stalling bid for testing: {bid.debug_ind}." ) bid.setState(BidStates.BID_STALLED_FOR_TEST) self.logBidEvent( bid.bid_id, EventLogTypes.DEBUG_TWEAK_APPLIED, - "ind {}".format(bid.debug_ind), + f"ind {bid.debug_ind}", cursor, ) self.saveBidInSession(bid_id, bid, cursor, xmr_swap, save_in_progress=offer) @@ -8559,28 +8378,23 @@ class BasicSwap(BaseApp): ): bid.amount_to -= int(bid.amount_to * 0.1) self.log.debug( - "Adaptor-sig bid %s: Debug %d - Reducing lock b txn amount by 10%% to %s.", - bid_id.hex(), - bid.debug_ind, - ci_to.format_amount(bid.amount_to), + f"Adaptor-sig bid {self.log.id(bid_id)}: Debug {bid.debug_ind} - Reducing lock b txn amount by 10%% to {ci_to.format_amount(bid.amount_to)}.", ) self.logBidEvent( bid.bid_id, EventLogTypes.DEBUG_TWEAK_APPLIED, - "ind {}".format(bid.debug_ind), + f"ind {bid.debug_ind}", cursor, ) if bid.debug_ind == DebugTypes.SEND_LOCKED_XMR: unlock_time = 10000 self.log.debug( - "Adaptor-sig bid %s: Debug %d - Sending locked XMR.", - bid_id.hex(), - bid.debug_ind, + f"Adaptor-sig bid {self.log.id(bid_id)}: Debug {id.debug_ind} - Sending locked XMR." ) self.logBidEvent( bid.bid_id, EventLogTypes.DEBUG_TWEAK_APPLIED, - "ind {}".format(bid.debug_ind), + f"ind {bid.debug_ind}", cursor, ) @@ -8594,23 +8408,20 @@ class BasicSwap(BaseApp): ) if bid.debug_ind == DebugTypes.B_LOCK_TX_MISSED_SEND: self.log.debug( - "Adaptor-sig bid %s: Debug %d - Losing xmr lock tx %s.", - bid_id.hex(), - bid.debug_ind, - b_lock_tx_id.hex(), + f"Adaptor-sig bid {self.log.id(bid_id)}: Debug {bid.debug_ind} - Losing xmr lock tx {self.log.id(b_lock_tx_id)}." ) self.logBidEvent( bid.bid_id, EventLogTypes.DEBUG_TWEAK_APPLIED, - "ind {}".format(bid.debug_ind), + f"ind {bid.debug_ind}", cursor, ) raise TemporaryError("Fail for debug event") except Exception as ex: if self.debug: self.log.error(traceback.format_exc()) - error_msg = "publishBLockTx failed for bid {} with error {}".format( - bid_id.hex(), str(ex) + error_msg = ( + f"publishBLockTx failed for bid {self.log.id(bid_id)} with error {ex}" ) num_retries = self.countBidEvents( bid, EventLogTypes.FAILED_TX_B_LOCK_PUBLISH, cursor @@ -8624,9 +8435,7 @@ class BasicSwap(BaseApp): ): delay = self.get_delay_retry_seconds() self.log.info( - "Retrying sending adaptor-sig swap chain B lock tx for bid %s in %d seconds", - bid_id.hex(), - delay, + "Retrying sending adaptor-sig swap chain B lock tx for bid {self.log.id(bid_id)} in {delay} seconds." ) self.createActionInSession( delay, ActionTypes.SEND_XMR_SWAP_LOCK_TX_B, bid_id, cursor @@ -8645,10 +8454,7 @@ class BasicSwap(BaseApp): return self.log.debug( - "Submitted lock txn %s to %s chain for bid %s", - b_lock_tx_id.hex(), - ci_to.coin_name(), - bid_id.hex(), + f"Submitted lock txn {self.log.id(bid_id)} to {ci_to.coin_name()} chain for bid {self.log.id(bid_id)}." ) bid.xmr_b_lock_tx = SwapTx( bid_id=bid_id, @@ -8660,22 +8466,20 @@ class BasicSwap(BaseApp): self.logBidEvent(bid.bid_id, EventLogTypes.LOCK_TX_B_PUBLISHED, "", cursor) if bid.debug_ind == DebugTypes.BID_STOP_AFTER_COIN_B_LOCK: self.log.debug( - "Adaptor-sig bid %s: Stalling bid for testing: %d.", - bid_id.hex(), - bid.debug_ind, + "Adaptor-sig bid {self.log.id(bid_id)}: Stalling bid for testing: {bid.debug_ind}." ) bid.setState(BidStates.BID_STALLED_FOR_TEST) self.logBidEvent( bid.bid_id, EventLogTypes.DEBUG_TWEAK_APPLIED, - "ind {}".format(bid.debug_ind), + f"ind {bid.debug_ind}", cursor, ) self.saveBidInSession(bid_id, bid, cursor, xmr_swap, save_in_progress=offer) def sendXmrBidLockRelease(self, bid_id: bytes, cursor) -> None: # Leader sending lock tx a release secret (MSG5F) - self.log.debug("Sending bid secret for adaptor-sig bid %s", bid_id.hex()) + self.log.debug(f"Sending bid secret for adaptor-sig bid {self.log.id(bid_id)}.") bid, xmr_swap = self.getXmrBidFromSession(cursor, bid_id) ensure(bid, "Bid not found: {}.".format(bid_id.hex())) @@ -8715,7 +8519,9 @@ class BasicSwap(BaseApp): def redeemXmrBidCoinALockTx(self, bid_id: bytes, cursor) -> None: # Follower redeeming A lock tx - self.log.debug("Redeeming coin A lock tx for adaptor-sig bid %s", bid_id.hex()) + self.log.debug( + f"Redeeming coin A lock tx for adaptor-sig bid {self.log.id(bid_id)}." + ) bid, xmr_swap = self.getXmrBidFromSession(cursor, bid_id) ensure(bid, "Bid not found: {}.".format(bid_id.hex())) @@ -8727,9 +8533,7 @@ class BasicSwap(BaseApp): if TxTypes.XMR_SWAP_A_LOCK_REFUND in bid.txns: self.log.warning( - "Not redeeming coin A lock tx for bid {}: Chain A lock refund tx already exists.".format( - bid_id.hex() - ) + f"Not redeeming coin A lock tx for bid {self.log.id(bid_id)}: Chain A lock refund tx already exists." ) return @@ -8817,10 +8621,7 @@ class BasicSwap(BaseApp): txid = bytes.fromhex(ci_from.publishTx(xmr_swap.a_lock_spend_tx)) self.log.debug( - "Submitted lock spend txn %s to %s chain for bid %s", - txid.hex(), - ci_from.coin_name(), - bid_id.hex(), + f"Submitted lock spend txn {self.log.id(txid)} to {ci_from.coin_name()} chain for bid {self.log.id(bid_id)}." ) self.logBidEvent( bid.bid_id, EventLogTypes.LOCK_TX_A_SPEND_TX_PUBLISHED, "", cursor @@ -8834,16 +8635,16 @@ class BasicSwap(BaseApp): bid.xmr_a_lock_spend_tx.setState(TxStates.TX_NONE) else: self.log.warning( - "Chain A lock TX %s already exists for bid %s", - bid.xmr_a_lock_spend_tx.txid.hex(), - bid_id.hex(), + f"Chain A lock TX {self.log.id(bid.xmr_a_lock_spend_tx.txid)} already exists for bid {self.log.id(bid_id)}." ) self.saveBidInSession(bid_id, bid, cursor, xmr_swap, save_in_progress=offer) def redeemXmrBidCoinBLockTx(self, bid_id: bytes, cursor) -> None: # Leader redeeming B lock tx - self.log.debug("Redeeming coin B lock tx for adaptor-sig bid %s", bid_id.hex()) + self.log.debug( + f"Redeeming coin B lock tx for adaptor-sig bid {self.log.id(bid_id)}." + ) bid, xmr_swap = self.getXmrBidFromSession(cursor, bid_id) ensure(bid, "Bid not found: {}.".format(bid_id.hex())) @@ -8930,17 +8731,14 @@ class BasicSwap(BaseApp): lock_tx_vout=lock_tx_vout, ) self.log.debug( - "Submitted lock B spend txn %s to %s chain for bid %s", - txid.hex(), - ci_to.coin_name(), - bid_id.hex(), + f"Submitted lock B spend txn {self.log.id(txid)} to {ci_to.coin_name()} chain for bid {self.log.id(bid_id)}." ) self.logBidEvent( bid.bid_id, EventLogTypes.LOCK_TX_B_SPEND_TX_PUBLISHED, "", cursor ) except Exception as ex: - error_msg = "spendBLockTx failed for bid {} with error {}".format( - bid_id.hex(), str(ex) + error_msg = ( + f"spendBLockTx failed for bid {self.log.id(bid_id)} with error {ex}" ) num_retries = self.countBidEvents( bid, EventLogTypes.FAILED_TX_B_SPEND, cursor @@ -8954,7 +8752,7 @@ class BasicSwap(BaseApp): ): delay = self.get_delay_retry_seconds() self.log.info( - f"Retrying sending adaptor-sig swap chain B spend tx for bid {bid_id.hex()} in {delay} seconds" + f"Retrying sending adaptor-sig swap chain B spend tx for bid {self.log.id(bid_id)} in {delay} seconds." ) self.createActionInSession( delay, ActionTypes.REDEEM_XMR_SWAP_LOCK_TX_B, bid_id, cursor @@ -8982,7 +8780,9 @@ class BasicSwap(BaseApp): def recoverXmrBidCoinBLockTx(self, bid_id: bytes, cursor) -> None: # Follower recovering B lock tx - self.log.debug("Recovering coin B lock tx for adaptor-sig bid %s", bid_id.hex()) + self.log.debug( + f"Recovering coin B lock tx for adaptor-sig bid {self.log.id(bid_id)}" + ) bid, xmr_swap = self.getXmrBidFromSession(cursor, bid_id) ensure(bid, "Bid not found: {}.".format(bid_id.hex())) @@ -9043,19 +8843,14 @@ class BasicSwap(BaseApp): lock_tx_vout=lock_tx_vout, ) self.log.debug( - "Submitted lock B refund txn %s to %s chain for bid %s", - txid.hex(), - ci_to.coin_name(), - bid_id.hex(), + f"Submitted lock B refund txn {self.log.id(txid)} to {ci_to.coin_name()} chain for bid {self.log.id(bid_id)}." ) self.logBidEvent( bid.bid_id, EventLogTypes.LOCK_TX_B_REFUND_TX_PUBLISHED, "", cursor ) except Exception as ex: # TODO: Make min-conf 10? - error_msg = "spendBLockTx refund failed for bid {} with error {}".format( - bid_id.hex(), str(ex) - ) + error_msg = f"spendBLockTx refund failed for bid {self.log.id(bid_id)} with error {ex}" num_retries = self.countBidEvents( bid, EventLogTypes.FAILED_TX_B_REFUND, cursor ) @@ -9069,9 +8864,7 @@ class BasicSwap(BaseApp): ): delay = self.get_delay_retry_seconds() self.log.info( - "Retrying sending adaptor-sig swap chain B refund tx for bid %s in %d seconds", - bid_id.hex(), - delay, + f"Retrying sending adaptor-sig swap chain B refund tx for bid {self.log.id(bid_id)} in {delay} seconds." ) self.createActionInSession( delay, ActionTypes.RECOVER_XMR_SWAP_LOCK_TX_B, bid_id, cursor @@ -9102,7 +8895,7 @@ class BasicSwap(BaseApp): def sendXmrBidCoinALockSpendTxMsg(self, bid_id: bytes, cursor) -> None: # Send MSG4F L -> F self.log.debug( - "Sending coin A lock spend tx msg for adaptor-sig bid %s", bid_id.hex() + f"Sending coin A lock spend tx msg for adaptor-sig bid {self.log.id(bid_id)}." ) bid, xmr_swap = self.getXmrBidFromSession(cursor, bid_id) @@ -9139,7 +8932,11 @@ class BasicSwap(BaseApp): def processXmrBidCoinALockSigs(self, msg) -> None: # Leader processing MSG3L - self.log.debug("Processing xmr coin a follower lock sigs msg %s", msg["msgid"]) + self.log.debug( + "Processing xmr coin a follower lock sigs msg {}.".format( + self.log.id(msg["msgid"]) + ) + ) msg_bytes = bytes.fromhex(msg["hex"][2:-2]) msg_data = XmrBidLockTxSigsMessage(init_all=False) @@ -9213,7 +9010,7 @@ class BasicSwap(BaseApp): prevout_amount, ) - self.log.debug("Setting lock refund spend tx sigs") + self.log.debug("Setting lock refund spend tx sigs.") witness_stack = [] if coin_from not in (Coins.DCR,): witness_stack += [ @@ -9263,9 +9060,7 @@ class BasicSwap(BaseApp): delay = self.get_delay_event_seconds() self.log.info( - "Sending coin A lock tx for adaptor-sig bid %s in %d seconds", - bid_id.hex(), - delay, + f"Sending coin A lock tx for adaptor-sig bid {self.log.id(bid_id)} in {delay} seconds." ) self.createAction(delay, ActionTypes.SEND_XMR_SWAP_LOCK_TX_A, bid_id) @@ -9278,7 +9073,11 @@ class BasicSwap(BaseApp): def processXmrBidLockSpendTx(self, msg) -> None: # Follower receiving MSG4F - self.log.debug("Processing adaptor-sig bid lock spend tx msg %s", msg["msgid"]) + self.log.debug( + "Processing adaptor-sig bid lock spend tx msg {}.".format( + self.log.id(msg["msgid"]) + ) + ) msg_bytes = bytes.fromhex(msg["hex"][2:-2]) msg_data = XmrBidLockSpendTxMessage(init_all=False) @@ -9329,9 +9128,7 @@ class BasicSwap(BaseApp): bid.setState(BidStates.XMR_SWAP_MSG_SCRIPT_LOCK_SPEND_TX) else: self.log.warning( - "processXmrBidLockSpendTx bid {} unexpected state {}".format( - bid_id.hex(), bid.state - ) + f"processXmrBidLockSpendTx bid {self.log.id(bid_id)} unexpected state {bid.state}." ) self.saveBid(bid_id, bid, xmr_swap=xmr_swap) except Exception as ex: @@ -9343,7 +9140,7 @@ class BasicSwap(BaseApp): self.swaps_in_progress[bid_id] = (bid, offer) def processXmrSplitMessage(self, msg) -> None: - self.log.debug("Processing xmr split msg %s", msg["msgid"]) + self.log.debug("Processing xmr split msg {}".format(self.log.id(msg["msgid"]))) now: int = self.getTime() msg_bytes = bytes.fromhex(msg["hex"][2:-2]) msg_data = XmrSplitMessage(init_all=False) @@ -9351,7 +9148,7 @@ class BasicSwap(BaseApp): # Validate data ensure(len(msg_data.msg_id) == 28, "Bad msg_id length") - self.log.debug("for bid %s", msg_data.msg_id.hex()) + self.log.debug(f"for bid {self.log.id(msg_data.msg_id)}.") # TODO: Wait for bid msg to arrive first @@ -9372,9 +9169,7 @@ class BasicSwap(BaseApp): num_exists = q[0] if num_exists > 0: self.log.warning( - "Ignoring duplicate xmr_split_data entry: ({}, {}, {})".format( - msg_data.msg_id.hex(), msg_data.msg_type, msg_data.sequence - ) + f"Ignoring duplicate xmr_split_data entry: ({self.logIDM(msg_data.msg_id)}, {msg_data.msg_type}, {msg_data.sequence})." ) return @@ -9391,7 +9186,11 @@ class BasicSwap(BaseApp): self.closeDB(cursor) def processXmrLockReleaseMessage(self, msg) -> None: - self.log.debug("Processing adaptor-sig swap lock release msg %s", msg["msgid"]) + self.log.debug( + "Processing adaptor-sig swap lock release msg {}.".format( + self.log.id(msg["msgid"]) + ) + ) msg_bytes = bytes.fromhex(msg["hex"][2:-2]) msg_data = XmrBidLockReleaseMessage(init_all=False) @@ -9406,7 +9205,7 @@ class BasicSwap(BaseApp): ensure(xmr_swap, "Adaptor-sig swap not found: {}.".format(bid_id.hex())) if BidStates(bid.state) in (BidStates.BID_STALLED_FOR_TEST,): - self.log.debug("Bid stalled %s", bid_id.hex()) + self.log.debug(f"Bid stalled {self.log.id(bid_id)}.") return offer, xmr_offer = self.getXmrOffer(bid.offer_id) @@ -9451,9 +9250,7 @@ class BasicSwap(BaseApp): else: delay = self.get_delay_event_seconds() self.log.info( - "Redeeming coin A lock tx for adaptor-sig bid %s in %d seconds", - bid_id.hex(), - delay, + f"Redeeming coin A lock tx for adaptor-sig bid {self.log.id(bid_id)} in {delay} seconds." ) self.createAction(delay, ActionTypes.REDEEM_XMR_SWAP_LOCK_TX_A, bid_id) @@ -9462,7 +9259,11 @@ class BasicSwap(BaseApp): self.swaps_in_progress[bid_id] = (bid, offer) def processADSBidReversed(self, msg) -> None: - self.log.debug("Processing adaptor-sig reverse bid msg %s", msg["msgid"]) + self.log.debug( + "Processing adaptor-sig reverse bid msg {}.".format( + self.log.id(msg["msgid"]) + ) + ) now: int = self.getTime() bid_bytes = bytes.fromhex(msg["hex"][2:-2]) @@ -9529,9 +9330,7 @@ class BasicSwap(BaseApp): if bid.chain_b_height_start < wallet_restore_height: bid.chain_b_height_start = wallet_restore_height self.log.warning( - "Adaptor-sig swap restore height clamped to {}".format( - wallet_restore_height - ) + f"Adaptor-sig swap restore height clamped to {wallet_restore_height}." ) else: ensure( @@ -9545,9 +9344,7 @@ class BasicSwap(BaseApp): bid.setState(BidStates.BID_RECEIVED) # BID_REQUEST_RECEIVED self.log.info( - "Received reverse adaptor-sig bid %s for offer %s", - bid_id.hex(), - bid_data.offer_msg_id.hex(), + f"Received reverse adaptor-sig bid {self.log.id(bid_id)} for offer {self.log.id(bid_data.offer_msg_id)}." ) self.saveBid(bid_id, bid, xmr_swap=xmr_swap) @@ -9567,9 +9364,7 @@ class BasicSwap(BaseApp): if self.shouldAutoAcceptBid(offer, bid, cursor, options=options): delay = self.get_delay_event_seconds() self.log.info( - "Auto accepting reverse adaptor-sig bid %s in %d seconds", - bid.bid_id.hex(), - delay, + f"Auto accepting reverse adaptor-sig bid {self.log.id(bid.bid_id)} in {delay} seconds." ) self.createActionInSession( delay, ActionTypes.ACCEPT_AS_REV_BID, bid.bid_id, cursor @@ -9579,7 +9374,11 @@ class BasicSwap(BaseApp): self.closeDB(cursor) def processADSBidReversedAccept(self, msg) -> None: - self.log.debug("Processing adaptor-sig reverse bid accept msg %s", msg["msgid"]) + self.log.debug( + "Processing adaptor-sig reverse bid accept msg {}.".format( + self.log.id(msg["msgid"]) + ) + ) msg_bytes = bytes.fromhex(msg["hex"][2:-2]) msg_data = ADSBidIntentAcceptMessage(init_all=False) @@ -9635,17 +9434,13 @@ class BasicSwap(BaseApp): if bid.chain_b_height_start < wallet_restore_height: bid.chain_b_height_start = wallet_restore_height self.log.warning( - "Reverse adaptor-sig swap restore height clamped to {}".format( - wallet_restore_height - ) + f"Reverse adaptor-sig swap restore height clamped to {wallet_restore_height}" ) bid.setState(BidStates.BID_RECEIVING) self.log.info( - "Receiving reverse adaptor-sig bid %s for offer %s", - bid_id.hex(), - bid.offer_id.hex(), + f"Receiving reverse adaptor-sig bid {self.log.id(bid_id)} for offer {self.log.id(bid.offer_id)}." ) self.saveBid(bid_id, bid, xmr_swap=xmr_swap) @@ -9689,12 +9484,10 @@ class BasicSwap(BaseApp): except InactiveCoin as ex: self.log.debug( - "Ignoring message involving inactive coin {}, type {}".format( - Coins(ex.coinid).name, MessageTypes(msg_type).name - ) + f"Ignoring message involving inactive coin {Coins(ex.coinid).name}, type {MessageTypes(msg_type).name}." ) except Exception as ex: - self.log.error("processMsg %s", str(ex)) + self.log.error(f"processMsg {ex}") if self.debug: self.log.error(traceback.format_exc()) self.logEvent( @@ -9889,7 +9682,7 @@ class BasicSwap(BaseApp): self.log.error("checkBidState %s", traceback.format_exc()) if self.is_transient_error(ex): self.log.warning( - "checkBidState %s %s", bid_id.hex(), str(ex) + f"checkBidState {self.log.id(bid_id)} {ex}." ) self.logBidEvent( bid_id, @@ -9898,7 +9691,7 @@ class BasicSwap(BaseApp): cursor=None, ) else: - self.log.error("checkBidState %s %s", bid_id.hex(), str(ex)) + self.log.error(f"checkBidState {self.log.id(bid_id)} {ex}.") self.setBidError(bid_id, v[0], str(ex)) for bid_id, bid, offer in to_remove: @@ -9946,7 +9739,7 @@ class BasicSwap(BaseApp): self.logException(f"update {ex}") def manualBidUpdate(self, bid_id: bytes, data) -> None: - self.log.info("Manually updating bid %s", bid_id.hex()) + self.log.info(f"Manually updating bid {self.log.id(bid_id)}.") add_bid_action = -1 try: @@ -9958,11 +9751,13 @@ class BasicSwap(BaseApp): has_changed = False if bid.state != data["bid_state"]: bid.setState(data["bid_state"]) - self.log.warning("Set state to %s", strBidState(bid.state)) + self.log.warning(f"Set state to {strBidState(bid.state)}.") has_changed = True if data.get("bid_action", -1) != -1: - self.log.warning("Adding action", ActionTypes(data["bid_action"]).name) + self.log.warning( + "Adding action {}.".format(ActionTypes(data["bid_action"]).name) + ) add_bid_action = ActionTypes(data["bid_action"]) has_changed = True @@ -9971,12 +9766,10 @@ class BasicSwap(BaseApp): if bid.debug_ind is None and data["debug_ind"] == -1: pass # Already unset else: - self.log.debug( - "Bid %s Setting debug flag: %s", - bid_id.hex(), - data["debug_ind"], - ) bid.debug_ind = data["debug_ind"] + self.log.debug( + f"Bid {self.log.id(bid_id)} Setting debug flag: {bid.debug_ind}" + ) has_changed = True if data.get("kbs_other", None) is not None: @@ -10006,7 +9799,7 @@ class BasicSwap(BaseApp): self.closeDB(cursor, commit=False) def editGeneralSettings(self, data): - self.log.info("Updating general settings") + self.log.info("Updating general settings.") settings_changed = False suggest_reboot = False settings_copy = copy.deepcopy(self.settings) @@ -10121,7 +9914,7 @@ class BasicSwap(BaseApp): return settings_changed, suggest_reboot def editSettings(self, coin_name: str, data): - self.log.info(f"Updating settings {coin_name}") + self.log.info(f"Updating settings {coin_name}.") settings_changed = False suggest_reboot = False settings_copy = copy.deepcopy(self.settings) @@ -10235,7 +10028,7 @@ class BasicSwap(BaseApp): return settings_changed, suggest_reboot def enableCoin(self, coin_name: str) -> None: - self.log.info("Enabling coin %s", coin_name) + self.log.info(f"Enabling coin {coin_name}.") coin_id = self.getCoinIdFromName(coin_name) if coin_id in (Coins.PART, Coins.PART_BLIND, Coins.PART_ANON): @@ -10262,7 +10055,7 @@ class BasicSwap(BaseApp): # Client must be restarted def disableCoin(self, coin_name: str) -> None: - self.log.info("Disabling coin %s", coin_name) + self.log.info(f"Disabling coin {coin_name}.") coin_id = self.getCoinIdFromName(coin_name) if coin_id in (Coins.PART, Coins.PART_BLIND, Coins.PART_ANON): @@ -10372,7 +10165,7 @@ class BasicSwap(BaseApp): return rv except Exception as e: - self.log.warning("getWalletInfo failed with: %s", str(e)) + self.log.warning(f"getWalletInfo failed with: {e}.") def getWalletInfo(self, coin): ci = self.ci(coin) @@ -10420,7 +10213,7 @@ class BasicSwap(BaseApp): ) except Exception as e: self.log.warning( - f"getCachedStealthAddressForCoin for {ci.coin_name()} failed with: {e}" + f"getCachedStealthAddressForCoin for {ci.coin_name()} failed with: {e}." ) rv["mweb_balance"] = walletinfo["mweb_balance"] rv["mweb_pending"] = ( @@ -10429,7 +10222,7 @@ class BasicSwap(BaseApp): return rv except Exception as e: - self.log.warning(f"getWalletInfo for {ci.coin_name()} failed with: {e}") + self.log.warning(f"getWalletInfo for {ci.coin_name()} failed with: {e}.") def addWalletInfoRecord(self, coin, info_type, wi) -> None: coin_id = int(coin) @@ -10449,7 +10242,7 @@ class BasicSwap(BaseApp): cursor.execute(query_str, {"coin_id": coin_id, "info_type": info_type}) self.commitDB() except Exception as e: - self.log.error(f"addWalletInfoRecord {e}") + self.log.error(f"addWalletInfoRecord {e}.") finally: self.closeDB(cursor, commit=False) @@ -10465,7 +10258,7 @@ class BasicSwap(BaseApp): if wi: self.addWalletInfoRecord(coin, 1, wi) except Exception as e: - self.log.error(f"updateWalletInfo {e}") + self.log.error(f"updateWalletInfo {e}.") finally: self._updating_wallets_info[int(coin)] = False @@ -10497,7 +10290,7 @@ class BasicSwap(BaseApp): try: handle.result(timeout=self._wallet_update_timeout) except Exception as e: - self.log.error(f"updateWalletInfo {e}") + self.log.error(f"updateWalletInfo {e}.") def getWalletsInfo(self, opts=None): rv = {} @@ -10910,7 +10703,7 @@ class BasicSwap(BaseApp): self.closeDB(cursor, commit=False) def updateAutomationStrategy(self, strategy_id: int, data: dict) -> None: - self.log.debug(f"updateAutomationStrategy {strategy_id}") + self.log.debug(f"updateAutomationStrategy {strategy_id}.") try: cursor = self.openDB() strategy = self.queryOne( @@ -10971,7 +10764,9 @@ class BasicSwap(BaseApp): "extkey", ["deriveAccount", "smsg keys", "78900"] ) smsg_account_id = smsg_account["account"] - self.log.info(f"Creating smsg keys account {smsg_account_id}") + self.log.info( + f"Creating smsg keys account {self.log.addr(smsg_account_id)}." + ) extkey = self.callrpc("extkey") # Disable receiving on all chains @@ -11110,8 +10905,8 @@ class BasicSwap(BaseApp): continue if smsg_addr["receive"] != 0: self.log.warning( - "Disabling smsg key found in core and not bsx: {}".format( - smsg_addr["address"] + "Disabling smsg key found in core and not bsx: {}.".format( + self.log.addr(smsg_addr["address"]) ) ) self.callrpc("smsglocalkeys", ["recv", "-", smsg_addr["address"]]) @@ -11131,7 +10926,7 @@ class BasicSwap(BaseApp): return use_addr def createCoinALockRefundSwipeTx(self, ci, bid, offer, xmr_swap, xmr_offer): - self.log.debug("Creating %s lock refund swipe tx", ci.coin_name()) + self.log.debug(f"Creating {ci.coin_name()} lock refund swipe tx.") reverse_bid: bool = self.is_reverse_ads_bid(offer.coin_from, offer.coin_to) a_fee_rate: int = xmr_offer.b_fee_rate if reverse_bid else xmr_offer.a_fee_rate @@ -11183,7 +10978,7 @@ class BasicSwap(BaseApp): xmr_swap.a_lock_refund_swipe_tx = ci.setTxSignature(spend_tx, witness_stack) def setBidDebugInd(self, bid_id: bytes, debug_ind, add_to_bid: bool = True) -> None: - self.log.debug("Bid %s Setting debug flag: %s", bid_id.hex(), debug_ind) + self.log.debug(f"Bid {self.log.id(bid_id)} Setting debug flag: {debug_ind}.") self._debug_cases.append((bid_id, debug_ind)) if add_to_bid is False: @@ -11209,7 +11004,7 @@ class BasicSwap(BaseApp): return False def storeOfferRevoke(self, offer_id: bytes, sig) -> bool: - self.log.debug("Storing revoke request for offer: %s", offer_id.hex()) + self.log.debug(f"Storing revoke request for offer: {self.log.id(offer_id)}.") for pair in self._possibly_revoked_offers: if offer_id == pair[0]: return False @@ -11248,7 +11043,7 @@ class BasicSwap(BaseApp): self.closeDB(cursor, commit=False) def add_connection(self, host, port, peer_pubkey): - self.log.info("add_connection %s %d %s", host, port, peer_pubkey.hex()) + self.log.info(f"add_connection {host} {port} {peer_pubkey.hex()}.") self._network.add_connection(host, port, peer_pubkey) def get_network_info(self): @@ -11265,7 +11060,7 @@ class BasicSwap(BaseApp): def lookupRates(self, coin_from, coin_to, output_array=False): self.log.debug( - "lookupRates {}, {}".format( + "lookupRates {}, {}.".format( Coins(int(coin_from)).name, Coins(int(coin_to)).name ) ) diff --git a/basicswap/interface/bch.py b/basicswap/interface/bch.py index 29e2e86..074ed35 100644 --- a/basicswap/interface/bch.py +++ b/basicswap/interface/bch.py @@ -1,13 +1,13 @@ #!/usr/bin/env python # -*- coding: utf-8 -*- -# Copyright (c) 2024 The Basicswap developers +# Copyright (c) 2024-2025 The Basicswap developers # Distributed under the MIT software license, see the accompanying # file LICENSE or http://www.opensource.org/licenses/mit-license.php. from typing import Union from basicswap.contrib.test_framework.messages import COutPoint, CTransaction, CTxIn -from basicswap.util import b2h, b2i, ensure, i2h +from basicswap.util import b2i, ensure, i2b from basicswap.util.script import decodePushData, decodeScriptNum from .btc import BTCInterface, ensure_op, findOutput from basicswap.rpc import make_rpc_func @@ -454,11 +454,14 @@ class BCHInterface(BTCInterface): tx.rehash() self._log.info( - "createSCLockSpendTx %s:\n fee_rate, size, fee: %ld, %ld, %ld.", - i2h(tx.sha256), - tx_fee_rate, - size, - pay_fee, + "createSCLockSpendTx {}{}.".format( + self._log.id(i2b(tx.sha256)), + ( + "" + if self._log.safe_logs + else f":\n fee_rate, vsize, fee: {tx_fee_rate}, {size}, {pay_fee}" + ), + ) ) return tx.serialize_without_witness() @@ -506,11 +509,14 @@ class BCHInterface(BTCInterface): tx.rehash() self._log.info( - "createSCLockRefundTx %s:\n fee_rate, vsize, fee: %ld, %ld, %ld.", - i2h(tx.sha256), - tx_fee_rate, - vsize, - pay_fee, + "createSCLockRefundTx {}{}.".format( + self._log.id(i2b(tx.sha256)), + ( + "" + if self._log.safe_logs + else f":\n fee_rate, vsize, fee: {tx_fee_rate}, {vsize}, {pay_fee}" + ), + ) ) return tx.serialize_without_witness(), refund_script, tx.vout[0].nValue @@ -582,11 +588,14 @@ class BCHInterface(BTCInterface): tx.rehash() self._log.info( - "createSCLockRefundSpendToFTx %s:\n fee_rate, vsize, fee: %ld, %ld, %ld.", - i2h(tx.sha256), - tx_fee_rate, - vsize, - pay_fee, + "createSCLockRefundSpendToFTx {}{}.".format( + self._log.id(i2b(tx.sha256)), + ( + "" + if self._log.safe_logs + else f":\n fee_rate, vsize, fee: {tx_fee_rate}, {vsize}, {pay_fee}" + ), + ) ) return tx.serialize_without_witness() @@ -780,7 +789,7 @@ class BCHInterface(BTCInterface): tx = self.loadTx(tx_bytes) txid = self.getTxid(tx) - self._log.info("Verifying lock tx: {}.".format(b2h(txid))) + self._log.info("Verifying lock tx: {}.".format(self._log.id(txid))) ensure(tx.nVersion == self.txVersion(), "Bad version") ensure(tx.nLockTime == 0, "Bad nLockTime") # TODO match txns created by cores @@ -835,7 +844,7 @@ class BCHInterface(BTCInterface): tx = self.loadTx(tx_bytes) txid = self.getTxid(tx) - self._log.info("Verifying lock refund tx: {}.".format(b2h(txid))) + self._log.info("Verifying lock refund tx: {}.".format(self._log.id(txid))) ensure(tx.nVersion == self.txVersion(), "Bad version") ensure(tx.nLockTime == 0, "nLockTime not 0") @@ -881,7 +890,7 @@ class BCHInterface(BTCInterface): size = self.getTxSize(tx) vsize = size - self._log.info( + self._log.info_s( "tx amount, vsize, fee: %ld, %ld, %ld", locked_coin, vsize, fee_paid ) @@ -905,7 +914,7 @@ class BCHInterface(BTCInterface): # Must have only one output sending lock refund tx value - fee to leader's address, TODO: follower shouldn't need to verify destination addr tx = self.loadTx(tx_bytes) txid = self.getTxid(tx) - self._log.info("Verifying lock refund spend tx: {}.".format(b2h(txid))) + self._log.info("Verifying lock refund spend tx: {}.".format(self._log.id(txid))) ensure(tx.nVersion == self.txVersion(), "Bad version") ensure(tx.nLockTime == 0, "nLockTime not 0") @@ -947,9 +956,7 @@ class BCHInterface(BTCInterface): size = self.getTxSize(tx) vsize = size - self._log.info( - "tx amount, vsize, fee: %ld, %ld, %ld", tx_value, vsize, fee_paid - ) + self._log.info_s(f"tx amount, vsize, fee: {tx_value}, {vsize}, {fee_paid}") return True @@ -962,7 +969,7 @@ class BCHInterface(BTCInterface): tx = self.loadTx(tx_bytes) txid = self.getTxid(tx) - self._log.info("Verifying lock spend tx: {}.".format(b2h(txid))) + self._log.info("Verifying lock spend tx: {}.".format(self._log.id(txid))) ensure(tx.nVersion == self.txVersion(), "Bad version") ensure(tx.nLockTime == 0, "nLockTime not 0") @@ -995,7 +1002,7 @@ class BCHInterface(BTCInterface): size = self.getTxSize(tx) vsize = size - self._log.info( + self._log.info_s( "tx amount, vsize, fee: %ld, %ld, %ld", tx.vout[0].nValue, vsize, fee_paid ) @@ -1115,11 +1122,14 @@ class BCHInterface(BTCInterface): tx.rehash() self._log.info( - "createMercyTx %s:\n fee_rate, vsize, fee: %ld, %ld, %ld.", - i2h(tx.sha256), - 1, - vsize, - pay_fee, + "createMercyTx {}{}.".format( + self._log.id(i2b(tx.sha256)), + ( + "" + if self._log.safe_logs + else f":\n fee_rate, vsize, fee: {1}, {vsize}, {pay_fee}" + ), + ) ) txHex = tx.serialize_without_witness() diff --git a/basicswap/interface/btc.py b/basicswap/interface/btc.py index 9063814..618ddec 100644 --- a/basicswap/interface/btc.py +++ b/basicswap/interface/btc.py @@ -21,7 +21,6 @@ from basicswap.basicswap_util import ( from basicswap.interface.base import Secp256k1Interface from basicswap.util import ( ensure, - b2h, i2b, b2i, i2h, @@ -319,7 +318,9 @@ class BTCInterface(Secp256k1Interface): if wallet_name in ("mweb",): continue - change_watchonly_wallet: bool = self._rpc_wallet_watch == self._rpc_wallet + change_watchonly_wallet: bool = ( + self._rpc_wallet_watch == self._rpc_wallet + ) self._rpc_wallet = wallet_name self._log.info( @@ -733,11 +734,14 @@ class BTCInterface(Secp256k1Interface): tx.rehash() self._log.info( - "createSCLockRefundTx %s:\n fee_rate, vsize, fee: %ld, %ld, %ld.", - i2h(tx.sha256), - tx_fee_rate, - vsize, - pay_fee, + "createSCLockRefundTx {}{}.".format( + self._log.id(i2b(tx.sha256)), + ( + "" + if self._log.safe_logs + else f":\n fee_rate, vsize, fee: {tx_fee_rate}, {vsize}, {pay_fee}" + ), + ) ) return tx.serialize(), refund_script, tx.vout[0].nValue @@ -788,11 +792,14 @@ class BTCInterface(Secp256k1Interface): tx.rehash() self._log.info( - "createSCLockRefundSpendTx %s:\n fee_rate, vsize, fee: %ld, %ld, %ld.", - i2h(tx.sha256), - tx_fee_rate, - vsize, - pay_fee, + "createSCLockRefundSpendTx {}{}.".format( + self._log.id(i2b(tx.sha256)), + ( + "" + if self._log.safe_logs + else f":\n fee_rate, vsize, fee: {tx_fee_rate}, {vsize}, {pay_fee}" + ), + ) ) return tx.serialize() @@ -855,11 +862,14 @@ class BTCInterface(Secp256k1Interface): tx.rehash() self._log.info( - "createSCLockRefundSpendToFTx %s:\n fee_rate, vsize, fee: %ld, %ld, %ld.", - i2h(tx.sha256), - tx_fee_rate, - vsize, - pay_fee, + "createSCLockRefundSpendToFTx {}{}.".format( + self._log.id(i2b(tx.sha256)), + ( + "" + if self._log.safe_logs + else f":\n fee_rate, vsize, fee: {tx_fee_rate}, {vsize}, {pay_fee}" + ), + ) ) return tx.serialize() @@ -902,11 +912,14 @@ class BTCInterface(Secp256k1Interface): tx.rehash() self._log.info( - "createSCLockSpendTx %s:\n fee_rate, vsize, fee: %ld, %ld, %ld.", - i2h(tx.sha256), - tx_fee_rate, - vsize, - pay_fee, + "createSCLockSpendTx {}{}.".format( + self._log.id(i2b(tx.sha256)), + ( + "" + if self._log.safe_logs + else f":\n fee_rate, vsize, fee: {tx_fee_rate}, {vsize}, {pay_fee}" + ), + ) ) return tx.serialize() @@ -931,7 +944,7 @@ class BTCInterface(Secp256k1Interface): tx = self.loadTx(tx_bytes) txid = self.getTxid(tx) - self._log.info("Verifying lock tx: {}.".format(b2h(txid))) + self._log.info("Verifying lock tx: {}.".format(self._log.id(txid))) ensure(tx.nVersion == self.txVersion(), "Bad version") ensure(tx.nLockTime == 0, "Bad nLockTime") # TODO match txns created by cores @@ -1019,7 +1032,7 @@ class BTCInterface(Secp256k1Interface): tx = self.loadTx(tx_bytes) txid = self.getTxid(tx) - self._log.info("Verifying lock refund tx: {}.".format(b2h(txid))) + self._log.info("Verifying lock refund tx: {}.".format(self._log.id(txid))) ensure(tx.nVersion == self.txVersion(), "Bad version") ensure(tx.nLockTime == 0, "nLockTime not 0") @@ -1058,7 +1071,7 @@ class BTCInterface(Secp256k1Interface): vsize = self.getTxVSize(tx, add_witness_bytes=witness_bytes) fee_rate_paid = fee_paid * 1000 // vsize - self._log.info( + self._log.info_s( "tx amount, vsize, feerate: %ld, %ld, %ld", locked_coin, vsize, @@ -1087,7 +1100,7 @@ class BTCInterface(Secp256k1Interface): # Must have only one output sending lock refund tx value - fee to leader's address, TODO: follower shouldn't need to verify destination addr tx = self.loadTx(tx_bytes) txid = self.getTxid(tx) - self._log.info("Verifying lock refund spend tx: {}.".format(b2h(txid))) + self._log.info("Verifying lock refund spend tx: {}.".format(self._log.id(txid))) ensure(tx.nVersion == self.txVersion(), "Bad version") ensure(tx.nLockTime == 0, "nLockTime not 0") @@ -1124,7 +1137,7 @@ class BTCInterface(Secp256k1Interface): vsize = self.getTxVSize(tx, add_witness_bytes=witness_bytes) fee_rate_paid = fee_paid * 1000 // vsize - self._log.info( + self._log.info_s( "tx amount, vsize, feerate: %ld, %ld, %ld", tx_value, vsize, fee_rate_paid ) @@ -1142,7 +1155,7 @@ class BTCInterface(Secp256k1Interface): tx = self.loadTx(tx_bytes) txid = self.getTxid(tx) - self._log.info("Verifying lock spend tx: {}.".format(b2h(txid))) + self._log.info("Verifying lock spend tx: {}.".format(self._log.id(txid))) ensure(tx.nVersion == self.txVersion(), "Bad version") ensure(tx.nLockTime == 0, "nLockTime not 0") @@ -1180,7 +1193,7 @@ class BTCInterface(Secp256k1Interface): vsize = self.getTxVSize(tx, add_witness_bytes=witness_bytes) fee_rate_paid = fee_paid * 1000 // vsize - self._log.info( + self._log.info_s( "tx amount, vsize, feerate: %ld, %ld, %ld", tx.vout[0].nValue, vsize, @@ -1490,7 +1503,7 @@ class BTCInterface(Secp256k1Interface): witness_bytes = 109 vsize = self.getTxVSize(tx, add_witness_bytes=witness_bytes) pay_fee = round(fee_rate * vsize / 1000) - self._log.info( + self._log.info_s( f"BLockSpendTx fee_rate, vsize, fee: {fee_rate}, {vsize}, {pay_fee}." ) return pay_fee @@ -1508,7 +1521,9 @@ class BTCInterface(Secp256k1Interface): lock_tx_vout=None, ) -> bytes: self._log.info( - "spendBLockTx: {} {}\n".format(chain_b_lock_txid.hex(), lock_tx_vout) + "spendBLockTx: {} {}\n".format( + self._log.id(chain_b_lock_txid), lock_tx_vout + ) ) locked_n = lock_tx_vout @@ -1589,7 +1604,9 @@ class BTCInterface(Secp256k1Interface): # Add watchonly address and rescan if required if not self.isAddressMine(dest_address, or_watch_only=True): self.importWatchOnlyAddress(dest_address, "bid") - self._log.info("Imported watch-only addr: {}".format(dest_address)) + self._log.info( + "Imported watch-only addr: {}".format(self._log.addr(dest_address)) + ) self._log.info( "Rescanning {} chain from height: {}".format( self.coin_name(), rescan_from diff --git a/basicswap/interface/dcr/dcr.py b/basicswap/interface/dcr/dcr.py index ac9ecf9..83a7306 100644 --- a/basicswap/interface/dcr/dcr.py +++ b/basicswap/interface/dcr/dcr.py @@ -27,7 +27,6 @@ from basicswap.interface.btc import ( ) from basicswap.util import ( ensure, - b2h, b2i, i2b, i2h, @@ -1130,11 +1129,14 @@ class DCRInterface(Secp256k1Interface): fee_info["size"] = size self._log.info( - "createSCLockSpendTx %s:\n fee_rate, size, fee: %ld, %ld, %ld.", - tx.TxHash().hex(), - tx_fee_rate, - size, - pay_fee, + "createSCLockSpendTx {}{}.".format( + self._log.id(tx.TxHash()), + ( + "" + if self._log.safe_logs + else f":\n fee_rate, size, fee: {tx_fee_rate}, {size}, {pay_fee}" + ), + ) ) return tx.serialize(TxSerializeType.NoWitness) @@ -1174,11 +1176,14 @@ class DCRInterface(Secp256k1Interface): tx.vout[0].value = locked_coin - pay_fee self._log.info( - "createSCLockRefundTx %s:\n fee_rate, size, fee: %ld, %ld, %ld.", - tx.TxHash().hex(), - tx_fee_rate, - size, - pay_fee, + "createSCLockRefundTx {}{}.".format( + self._log.id(tx.TxHash()), + ( + "" + if self._log.safe_logs + else f":\n fee_rate, size, fee: {tx_fee_rate}, {size}, {pay_fee}" + ), + ) ) return tx.serialize(TxSerializeType.NoWitness), refund_script, tx.vout[0].value @@ -1222,11 +1227,14 @@ class DCRInterface(Secp256k1Interface): tx.vout[0].value = locked_coin - pay_fee self._log.info( - "createSCLockRefundSpendTx %s:\n fee_rate, size, fee: %ld, %ld, %ld.", - tx.TxHash().hex(), - tx_fee_rate, - size, - pay_fee, + "createSCLockRefundSpendTx {}{}.".format( + self._log.id(tx.TxHash()), + ( + "" + if self._log.safe_logs + else f":\n fee_rate, size, fee: {tx_fee_rate}, {size}, {pay_fee}" + ), + ) ) return tx.serialize(TxSerializeType.NoWitness) @@ -1251,7 +1259,7 @@ class DCRInterface(Secp256k1Interface): tx = self.loadTx(tx_bytes) txid = self.getTxid(tx) - self._log.info("Verifying lock tx: {}.".format(b2h(txid))) + self._log.info("Verifying lock tx: {}.".format(self._log.id(txid))) ensure(tx.version == self.txVersion(), "Bad version") ensure(tx.locktime == 0, "Bad locktime") @@ -1327,7 +1335,7 @@ class DCRInterface(Secp256k1Interface): tx = self.loadTx(tx_bytes) txid = self.getTxid(tx) - self._log.info("Verifying lock spend tx: {}.".format(b2h(txid))) + self._log.info("Verifying lock spend tx: {}.".format(self._log.id(txid))) ensure(tx.version == self.txVersion(), "Bad version") ensure(tx.locktime == 0, "Bad locktime") @@ -1397,7 +1405,7 @@ class DCRInterface(Secp256k1Interface): tx = self.loadTx(tx_bytes) txid = self.getTxid(tx) - self._log.info("Verifying lock refund tx: {}.".format(b2h(txid))) + self._log.info("Verifying lock refund tx: {}.".format(self._log.id(txid))) ensure(tx.version == self.txVersion(), "Bad version") ensure(tx.locktime == 0, "locktime not 0") @@ -1460,7 +1468,7 @@ class DCRInterface(Secp256k1Interface): # Must have only one output sending lock refund tx value - fee to leader's address, TODO: follower shouldn't need to verify destination addr tx = self.loadTx(tx_bytes) txid = self.getTxid(tx) - self._log.info("Verifying lock refund spend tx: {}.".format(b2h(txid))) + self._log.info("Verifying lock refund spend tx: {}.".format(self._log.id(txid))) ensure(tx.version == self.txVersion(), "Bad version") ensure(tx.locktime == 0, "locktime not 0") @@ -1546,11 +1554,14 @@ class DCRInterface(Secp256k1Interface): tx.vout[0].value = locked_amount - pay_fee self._log.info( - "createSCLockRefundSpendToFTx %s:\n fee_rate, size, fee: %ld, %ld, %ld.", - tx.TxHash().hex(), - tx_fee_rate, - size, - pay_fee, + "createSCLockRefundSpendToFTx {}{}.".format( + self._log.id(tx.TxHash()), + ( + "" + if self._log.safe_logs + else f":\n fee_rate, size, fee: {tx_fee_rate}, {size}, {pay_fee}" + ), + ) ) return tx.serialize(TxSerializeType.NoWitness) @@ -1719,7 +1730,7 @@ class DCRInterface(Secp256k1Interface): witness_bytes = 115 size = len(tx.serialize()) + witness_bytes pay_fee = round(fee_rate * size / 1000) - self._log.info( + self._log.info_s( f"BLockSpendTx fee_rate, vsize, fee: {fee_rate}, {size}, {pay_fee}." ) return pay_fee diff --git a/basicswap/interface/firo.py b/basicswap/interface/firo.py index 2d9747d..33d9c1b 100644 --- a/basicswap/interface/firo.py +++ b/basicswap/interface/firo.py @@ -105,7 +105,9 @@ class FIROInterface(BTCInterface): if not self.isAddressMine(dest_address, or_watch_only=True): self.importWatchOnlyAddress(dest_address, "bid") - self._log.info("Imported watch-only addr: {}".format(dest_address)) + self._log.info( + "Imported watch-only addr: {}".format(self._log.addr(dest_address)) + ) self._log.info( "Rescanning {} chain from height: {}".format( self.coin_name(), rescan_from diff --git a/basicswap/interface/nav.py b/basicswap/interface/nav.py index 1211e1f..0cf322e 100644 --- a/basicswap/interface/nav.py +++ b/basicswap/interface/nav.py @@ -41,7 +41,6 @@ from basicswap.util.address import ( from basicswap.util import ( b2i, i2b, - i2h, ensure, ) from basicswap.basicswap_util import ( @@ -552,7 +551,9 @@ class NAVInterface(BTCInterface): if not self.isAddressMine(dest_address, or_watch_only=True): self.importWatchOnlyAddress(dest_address, "bid") - self._log.info("Imported watch-only addr: {}".format(dest_address)) + self._log.info( + "Imported watch-only addr: {}".format(self._log.addr(dest_address)) + ) self._log.info( "Rescanning {} chain from height: {}".format( self.coin_name(), rescan_from @@ -816,11 +817,14 @@ class NAVInterface(BTCInterface): tx.rehash() self._log.info( - "createSCLockRefundTx %s:\n fee_rate, vsize, fee: %ld, %ld, %ld.", - i2h(tx.sha256), - tx_fee_rate, - vsize, - pay_fee, + "createSCLockRefundTx {}{}.".format( + self._log.id(i2b(tx.sha256)), + ( + "" + if self._log.safe_logs + else f":\n fee_rate, vsize, fee: {tx_fee_rate}, {vsize}, {pay_fee}" + ), + ) ) return tx.serialize(), refund_script, tx.vout[0].nValue @@ -871,11 +875,14 @@ class NAVInterface(BTCInterface): tx.rehash() self._log.info( - "createSCLockRefundSpendTx %s:\n fee_rate, vsize, fee: %ld, %ld, %ld.", - i2h(tx.sha256), - tx_fee_rate, - vsize, - pay_fee, + "createSCLockRefundSpendTx {}{}.".format( + self._log.id(i2b(tx.sha256)), + ( + "" + if self._log.safe_logs + else f":\n fee_rate, vsize, fee: {tx_fee_rate}, {vsize}, {pay_fee}" + ), + ) ) return tx.serialize() @@ -928,11 +935,14 @@ class NAVInterface(BTCInterface): tx.rehash() self._log.info( - "createSCLockRefundSpendToFTx %s:\n fee_rate, vsize, fee: %ld, %ld, %ld.", - i2h(tx.sha256), - tx_fee_rate, - vsize, - pay_fee, + "createSCLockRefundSpendToFTx {}{}.".format( + self._log.id(i2b(tx.sha256)), + ( + "" + if self._log.safe_logs + else f":\n fee_rate, vsize, fee: {tx_fee_rate}, {vsize}, {pay_fee}" + ), + ) ) return tx.serialize() @@ -975,11 +985,14 @@ class NAVInterface(BTCInterface): tx.rehash() self._log.info( - "createSCLockSpendTx %s:\n fee_rate, vsize, fee: %ld, %ld, %ld.", - i2h(tx.sha256), - tx_fee_rate, - vsize, - pay_fee, + "createSCLockSpendTx {}{}.".format( + self._log.id(i2b(tx.sha256)), + ( + "" + if self._log.safe_logs + else f":\n fee_rate, vsize, fee: {tx_fee_rate}, {vsize}, {pay_fee}" + ), + ) ) return tx.serialize() diff --git a/basicswap/interface/part.py b/basicswap/interface/part.py index 80db020..59e3a2d 100644 --- a/basicswap/interface/part.py +++ b/basicswap/interface/part.py @@ -477,7 +477,7 @@ class PARTInterfaceBlind(PARTInterface): ): lock_tx_obj = self.rpc("decoderawtransaction", [tx_bytes.hex()]) lock_txid_hex = lock_tx_obj["txid"] - self._log.info("Verifying lock tx: {}.".format(lock_txid_hex)) + self._log.info("Verifying lock tx: {}.".format(self._log.id(lock_txid_hex))) ensure(lock_tx_obj["version"] == self.txVersion(), "Bad version") ensure(lock_tx_obj["locktime"] == 0, "Bad nLockTime") @@ -541,7 +541,9 @@ class PARTInterfaceBlind(PARTInterface): ): lock_refund_tx_obj = self.rpc("decoderawtransaction", [tx_bytes.hex()]) lock_refund_txid_hex = lock_refund_tx_obj["txid"] - self._log.info("Verifying lock refund tx: {}.".format(lock_refund_txid_hex)) + self._log.info( + "Verifying lock refund tx: {}.".format(self._log.id(lock_refund_txid_hex)) + ) ensure(lock_refund_tx_obj["version"] == self.txVersion(), "Bad version") ensure(lock_refund_tx_obj["locktime"] == 0, "Bad nLockTime") @@ -630,7 +632,9 @@ class PARTInterfaceBlind(PARTInterface): lock_refund_spend_tx_obj = self.rpc("decoderawtransaction", [tx_bytes.hex()]) lock_refund_spend_txid_hex = lock_refund_spend_tx_obj["txid"] self._log.info( - "Verifying lock refund spend tx: {}.".format(lock_refund_spend_txid_hex) + "Verifying lock refund spend tx: {}.".format( + self._log.id(lock_refund_spend_txid_hex) + ) ) ensure(lock_refund_spend_tx_obj["version"] == self.txVersion(), "Bad version") @@ -789,11 +793,14 @@ class PARTInterfaceBlind(PARTInterface): ) actual_tx_fee_rate = pay_fee * 1000 // vsize self._log.info( - "createSCLockSpendTx %s:\n fee_rate, vsize, fee: %ld, %ld, %ld.", - lock_spend_tx_obj["txid"], - actual_tx_fee_rate, - vsize, - pay_fee, + "createSCLockSpendTx {}{}.".format( + self._log.id(lock_spend_tx_obj["txid"]), + ( + "" + if self._log.safe_logs + else f":\n fee_rate, vsize, fee: {actual_tx_fee_rate}, {vsize}, {pay_fee}" + ), + ) ) fee_info["vsize"] = vsize @@ -808,7 +815,9 @@ class PARTInterfaceBlind(PARTInterface): ): lock_spend_tx_obj = self.rpc("decoderawtransaction", [tx_bytes.hex()]) lock_spend_txid_hex = lock_spend_tx_obj["txid"] - self._log.info("Verifying lock spend tx: {}.".format(lock_spend_txid_hex)) + self._log.info( + "Verifying lock spend tx: {}.".format(self._log.id(lock_spend_txid_hex)) + ) ensure(lock_spend_tx_obj["version"] == self.txVersion(), "Bad version") ensure(lock_spend_tx_obj["locktime"] == 0, "Bad nLockTime") diff --git a/basicswap/interface/xmr.py b/basicswap/interface/xmr.py index 4a206ca..355dac9 100644 --- a/basicswap/interface/xmr.py +++ b/basicswap/interface/xmr.py @@ -180,7 +180,19 @@ class XMRInterface(CoinInterface): if self._wallet_password is not None: params["password"] = self._wallet_password rv = self.rpc_wallet("generate_from_keys", params) - self._log.info("generate_from_keys %s", dumpj(rv)) + if "address" in rv: + new_address: str = rv["address"] + is_watch_only: bool = "Watch-only" in rv.get("info", "") + self._log.info( + "Generated{} {} wallet: {}".format( + " watch-only" if is_watch_only else "", + self.coin_name(), + self._log.addr(new_address), + ) + ) + else: + self._log.debug("generate_from_keys %s", dumpj(rv)) + raise ValueError("generate_from_keys failed") def openWallet(self, filename): params = {"filename": filename} @@ -406,7 +418,9 @@ class XMRInterface(CoinInterface): params["priority"] = self._fee_priority rv = self.rpc_wallet("transfer", params) self._log.info( - "publishBLockTx %s to address_b58 %s", rv["tx_hash"], shared_addr + "publishBLockTx %s to address_b58 %s", + self._log.id(rv["tx_hash"]), + self._log.addr(shared_addr), ) tx_hash = bytes.fromhex(rv["tx_hash"]) diff --git a/basicswap/protocols/xmr_swap_1.py b/basicswap/protocols/xmr_swap_1.py index e2a7276..b6eaa8b 100644 --- a/basicswap/protocols/xmr_swap_1.py +++ b/basicswap/protocols/xmr_swap_1.py @@ -44,7 +44,7 @@ def addLockRefundSigs(self, xmr_swap, ci): def recoverNoScriptTxnWithKey(self, bid_id: bytes, encoded_key, cursor=None): - self.log.info(f"Manually recovering {bid_id.hex()}") + self.log.info(f"Manually recovering {self.log.id(bid_id)}") # Manually recover txn if other key is known try: use_cursor = self.openDB(cursor) @@ -119,10 +119,7 @@ def recoverNoScriptTxnWithKey(self, bid_id: bytes, encoded_key, cursor=None): lock_tx_vout=lock_tx_vout, ) self.log.debug( - "Submitted lock B spend txn %s to %s chain for bid %s", - txid.hex(), - ci_follower.coin_name(), - bid_id.hex(), + f"Submitted lock B spend txn {self.log.id(txid)} to {ci_follower.coin_name()} chain for bid {self.log.id(bid_id)}." ) self.logBidEvent( bid.bid_id, diff --git a/basicswap/util/crypto.py b/basicswap/util/crypto.py index 5435638..646d5e4 100644 --- a/basicswap/util/crypto.py +++ b/basicswap/util/crypto.py @@ -1,16 +1,16 @@ # -*- coding: utf-8 -*- -# Copyright (c) 2022-2024 tecnovert +# Copyright (c) 2022-2025 tecnovert # Distributed under the MIT software license, see the accompanying # file LICENSE or http://www.opensource.org/licenses/mit-license.php. +from hashlib import sha256 as hashlib_sha256 # hashlib is faster than pycryptodome from basicswap.contrib.blake256.blake256 import blake_hash - -from Crypto.Hash import HMAC, RIPEMD160, SHA256, SHA512 # pycryptodome +from Crypto.Hash import HMAC, RIPEMD160, SHA512 # pycryptodome def sha256(data: bytes) -> bytes: - h = SHA256.new() + h = hashlib_sha256() h.update(data) return h.digest() diff --git a/basicswap/util/logging.py b/basicswap/util/logging.py new file mode 100644 index 0000000..043d4df --- /dev/null +++ b/basicswap/util/logging.py @@ -0,0 +1,42 @@ +# -*- coding: utf-8 -*- + +# Copyright (c) 2025 The Basicswap developers +# Distributed under the MIT software license, see the accompanying +# file LICENSE or http://www.opensource.org/licenses/mit-license.php. + +import logging +from basicswap.util.crypto import ( + sha256, +) + + +class BSXLogger(logging.Logger): + def __init__(self, name): + super().__init__(name) + self.safe_logs = False + self.safe_logs_prefix = b"" + + def addr(self, addr: str) -> str: + if self.safe_logs: + return ( + "A_" + + sha256(self.safe_logs_prefix + addr.encode(encoding="utf-8"))[ + :8 + ].hex() + ) + return addr + + def id(self, concept_id: bytes, prefix: str = "") -> str: + if concept_id is None: + return prefix + "None" + if isinstance(concept_id, str): + concept_id = bytes.fromhex(concept_id) + if self.safe_logs: + return (prefix if len(prefix) > 0 else "_") + sha256( + self.safe_logs_prefix + concept_id + )[:8].hex() + return prefix + concept_id.hex() + + def info_s(self, msg, *args, **kwargs): + if self.safe_logs is False: + self.info(msg, *args, **kwargs) diff --git a/tests/basicswap/test_btc_xmr.py b/tests/basicswap/test_btc_xmr.py index 35335d8..866fbed 100644 --- a/tests/basicswap/test_btc_xmr.py +++ b/tests/basicswap/test_btc_xmr.py @@ -770,6 +770,14 @@ class TestFunctions(BaseTest): class BasicSwapTest(TestFunctions): + @classmethod + def setUpClass(cls): + super(BasicSwapTest, cls).setUpClass() + if False: + for client in cls.swap_clients: + client.log.safe_logs = True + client.log.safe_logs_prefix = b"tests" + def test_001_nested_segwit(self): # p2sh-p2wpkh logging.info( @@ -2141,6 +2149,14 @@ class TestBTC_PARTB(TestFunctions): start_ltc_nodes = False base_rpc_port = BTC_BASE_RPC_PORT + @classmethod + def setUpClass(cls): + super(TestBTC_PARTB, cls).setUpClass() + if False: + for client in cls.swap_clients: + client.log.safe_logs = True + client.log.safe_logs_prefix = b"tests" + def test_01_a_full_swap(self): self.prepare_balance(self.test_coin_to, 100.0, 1801, 1800) self.do_test_01_full_swap(self.test_coin_from, self.test_coin_to)