From cbe908e9652d7d32f055d431542c7d479726bfd7 Mon Sep 17 00:00:00 2001 From: "Augusto F. Hack" Date: Tue, 25 Sep 2018 12:09:15 -0300 Subject: [PATCH] logging: logs before & after all transactions To make debugging easier some of the proxies have logs for before and after the transaction is sent. This adds these logs lines to the missing proxies. The general guidelined followed was: - logs prior to the transaction sent are debugging logs - logs after the transaction is mined are: - critical if the transaction failed in an unrecoverable manner - info if the transaction failed in a recoverable manner - info if the transaction was successful - the logs are formatedd with ` `, where state is one of these: - called - failed - successful This did improve the logging but it's not covering all cases, specially the checks done in the channel proxy which can raise an exception --- raiden/network/proxies/discovery.py | 16 ++- raiden/network/proxies/secret_registry.py | 69 +++++------ raiden/network/proxies/token.py | 60 ++++++--- raiden/network/proxies/token_network.py | 116 ++++++++++-------- .../network/proxies/token_network_registry.py | 38 +++--- 5 files changed, 171 insertions(+), 128 deletions(-) diff --git a/raiden/network/proxies/discovery.py b/raiden/network/proxies/discovery.py index 3771555923..811757f055 100644 --- a/raiden/network/proxies/discovery.py +++ b/raiden/network/proxies/discovery.py @@ -1,3 +1,4 @@ +import structlog from eth_utils import is_binary_address, to_checksum_address, to_normalized_address from web3.exceptions import BadFunctionCallOutput @@ -12,10 +13,12 @@ from raiden.network.rpc.smartcontract_proxy import ContractProxy from raiden.network.rpc.transactions import check_transaction_threw from raiden.settings import EXPECTED_CONTRACTS_VERSION -from raiden.utils import compare_versions, pex +from raiden.utils import compare_versions, pex, privatekey_to_address from raiden_contracts.constants import CONTRACT_ENDPOINT_REGISTRY from raiden_contracts.contract_manager import CONTRACT_MANAGER +log = structlog.get_logger(__name__) # pylint: disable=invalid-name + class Discovery: """On chain smart contract raiden node discovery: allows registering @@ -50,6 +53,7 @@ def __init__( raise AddressWrongContract('') self.address = discovery_address + self.node_address = privatekey_to_address(jsonrpc_client.privkey) self.client = jsonrpc_client self.not_found_address = NULL_ADDRESS self.proxy = proxy @@ -58,6 +62,13 @@ def register_endpoint(self, node_address, endpoint): if node_address != self.client.sender: raise ValueError("node_address doesnt match this node's address") + log_details = { + 'node': pex(self.node_address), + 'node_address': pex(node_address), + 'endpoint': endpoint, + } + log.debug('registerEndpoint called', **log_details) + transaction_hash = self.proxy.transact( 'registerEndpoint', endpoint, @@ -67,8 +78,11 @@ def register_endpoint(self, node_address, endpoint): receipt_or_none = check_transaction_threw(self.client, transaction_hash) if receipt_or_none: + log.critical('registerEndpoint failed', **log_details) raise TransactionThrew('Register Endpoint', receipt_or_none) + log.debug('registerEndpoint successful', **log_details) + def endpoint_by_address(self, node_address_bin): node_address_hex = to_checksum_address(node_address_bin) endpoint = self.proxy.contract.functions.findEndpointByAddress( diff --git a/raiden/network/proxies/secret_registry.py b/raiden/network/proxies/secret_registry.py index 9f39a2bad6..54a1f2711f 100644 --- a/raiden/network/proxies/secret_registry.py +++ b/raiden/network/proxies/secret_registry.py @@ -56,67 +56,58 @@ def register_secret(self, secret: typing.Secret): self.register_secret_batch([secret]) def register_secret_batch(self, secrets: List[typing.Secret]): - secret_batch = list() + secrets_to_register = list() + secrethashes_to_register = list() + secrethashes_not_sent = list() secret_registry_transaction = AsyncResult() for secret in secrets: secrethash = sha3(secret) - if not self.check_registered(secrethash): - if secret not in self.open_secret_transactions: - secret_batch.append(secret) - self.open_secret_transactions[secret] = secret_registry_transaction + + is_register_needed = ( + not self.check_registered(secrethash) and + secret not in self.open_secret_transactions + ) + if is_register_needed: + secrets_to_register.append(secret) + secrethashes_to_register.append(secrethash) + self.open_secret_transactions[secret] = secret_registry_transaction else: - log.info( - f'secret {encode_hex(secrethash)} already registered.', - node=pex(self.node_address), - contract=pex(self.address), - secrethash=encode_hex(secrethash), - ) - - if not secret_batch: - return - - log.info( - 'registerSecretBatch called', - node=pex(self.node_address), - contract=pex(self.address), - ) + secrethashes_not_sent.append(secrethash) + + log_details = { + 'node': pex(self.node_address), + 'contract': pex(self.address), + 'secrets': secrethashes_to_register, + 'secrets_not_sent': secrethashes_not_sent, + } + + if not secrets_to_register: + log.debug('registerSecretBatch skipped', **log_details) + + log.debug('registerSecretBatch called', **log_details) try: - transaction_hash = self._register_secret_batch(secret_batch) + transaction_hash = self._register_secret_batch(secrets_to_register) except Exception as e: + log.critical('registerSecretBatch failed', **log_details) secret_registry_transaction.set_exception(e) raise else: + log.info('registerSecretBatch successful', **log_details) secret_registry_transaction.set(transaction_hash) finally: - for secret in secret_batch: + for secret in secrets_to_register: self.open_secret_transactions.pop(secret, None) def _register_secret_batch(self, secrets): - transaction_hash = self.proxy.transact( - 'registerSecretBatch', - secrets, - ) - + transaction_hash = self.proxy.transact('registerSecretBatch', secrets) self.client.poll(transaction_hash) receipt_or_none = check_transaction_threw(self.client, transaction_hash) if receipt_or_none: - log.critical( - 'registerSecretBatch failed', - node=pex(self.node_address), - contract=pex(self.address), - secrets=secrets, - ) raise TransactionThrew('registerSecretBatch', receipt_or_none) - log.info( - 'registerSecretBatch successful', - node=pex(self.node_address), - contract=pex(self.address), - secrets=secrets, - ) return transaction_hash def get_register_block_for_secrethash(self, secrethash: typing.Keccak256) -> int: diff --git a/raiden/network/proxies/token.py b/raiden/network/proxies/token.py index 44bc3b3fe2..190ed2c254 100644 --- a/raiden/network/proxies/token.py +++ b/raiden/network/proxies/token.py @@ -1,12 +1,16 @@ +import structlog from eth_utils import is_binary_address, to_checksum_address, to_normalized_address from raiden.exceptions import TransactionThrew from raiden.network.rpc.client import check_address_has_code from raiden.network.rpc.smartcontract_proxy import ContractProxy from raiden.network.rpc.transactions import check_transaction_threw +from raiden.utils import pex, privatekey_to_address from raiden_contracts.constants import CONTRACT_HUMAN_STANDARD_TOKEN from raiden_contracts.contract_manager import CONTRACT_MANAGER +log = structlog.get_logger(__name__) # pylint: disable=invalid-name + class Token: def __init__( @@ -27,6 +31,7 @@ def __init__( self.address = token_address self.client = jsonrpc_client + self.node_address = privatekey_to_address(jsonrpc_client.privkey) self.proxy = proxy def allowance(self, owner, spender): @@ -35,14 +40,26 @@ def allowance(self, owner, spender): to_checksum_address(spender), ).call() - def approve(self, contract_address, allowance): - """ Aprove `contract_address` to transfer up to `deposit` amount of token. """ - # TODO: check that `contract_address` is a netting channel and that - # `self.address` is one of the participants (maybe add this logic into - # `NettingChannel` and keep this straight forward) + def approve(self, allowed_address, allowance): + """ Aprove `allowed_address` to transfer up to `deposit` amount of token. + + Note: + + For channel deposit please use the channel proxy, since it does + additional validations. + """ + + log_details = { + 'node': pex(self.node_address), + 'contract': pex(self.address), + 'allowed_address': pex(allowed_address), + 'allowance': allowance, + } + log.debug('approve called', **log_details) + transaction_hash = self.proxy.transact( 'approve', - to_checksum_address(contract_address), + to_checksum_address(allowed_address), allowance, ) @@ -61,7 +78,6 @@ def approve(self, contract_address, allowance): "contract is not a valid ERC20 token or you don't have funds " "to use for openning a channel. " ) - raise TransactionThrew(msg, receipt_or_none) # The approve call failed, check the user has enough balance # (assuming the token smart contract may check for the maximum @@ -73,18 +89,22 @@ def approve(self, contract_address, allowance): 'approve failed. Please make sure the corresponding smart ' 'contract is a valid ERC20 token.' ).format(user_balance) - raise TransactionThrew(msg, receipt_or_none) # If the user has enough balance, warn the user the smart contract # may not have the approve function. else: msg = ( - 'Approve failed. \n' - 'Your account balance is {}, the request allowance is {}. ' - 'The smart contract may be rejecting your request for the ' - 'lack of balance.' - ).format(user_balance, allowance) - raise TransactionThrew(msg, receipt_or_none) + f'Approve failed. \n' + f'Your account balance is {user_balance}, ' + f'the request allowance is {allowance}. ' + f'The smart contract may be rejecting your request for the ' + f'lack of balance.' + ) + + log.critical(f'approve failed, {msg}', **log_details) + raise TransactionThrew(msg, receipt_or_none) + + log.info('approve successful', **log_details) def balance_of(self, address): """ Return the balance of `address`. """ @@ -93,6 +113,14 @@ def balance_of(self, address): ).call() def transfer(self, to_address, amount): + log_details = { + 'node': pex(self.node_address), + 'contract': pex(self.address), + 'to_address': pex(to_address), + 'amount': amount, + } + log.debug('transfer called', **log_details) + transaction_hash = self.proxy.transact( 'transfer', to_checksum_address(to_address), @@ -102,6 +130,8 @@ def transfer(self, to_address, amount): self.client.poll(transaction_hash) receipt_or_none = check_transaction_threw(self.client, transaction_hash) if receipt_or_none: + log.critical('transfer failed', **log_details) raise TransactionThrew('Transfer', receipt_or_none) - # TODO: check Transfer event + # TODO: check Transfer event (issue: #2598) + log.info('transfer successful', **log_details) diff --git a/raiden/network/proxies/token_network.py b/raiden/network/proxies/token_network.py index bbfe8cc92b..dc572043a7 100644 --- a/raiden/network/proxies/token_network.py +++ b/raiden/network/proxies/token_network.py @@ -150,6 +150,12 @@ def new_netting_channel( if self.node_address == partner: raise SamePeerAddress('The other peer must not have the same address as the client.') + log_details = { + 'peer1': pex(self.node_address), + 'peer2': pex(partner), + } + log.debug('new_netting_channel called', **log_details) + # Prevent concurrent attempts to open a channel with the same token and # partner address. if partner not in self.open_channel_transactions: @@ -157,13 +163,9 @@ def new_netting_channel( self.open_channel_transactions[partner] = new_open_channel_transaction try: - log.info( - 'new_netting_channel called', - peer1=pex(self.node_address), - peer2=pex(partner), - ) transaction_hash = self._new_netting_channel(partner, settle_timeout) except Exception as e: + log.critical('new_netting_channel failed', **log_details) new_open_channel_transaction.set_exception(e) raise else: @@ -176,20 +178,12 @@ def new_netting_channel( channel_created = self.channel_exists_and_not_settled(self.node_address, partner) if channel_created is False: - log.error( - 'creating new channel failed', - peer1=pex(self.node_address), - peer2=pex(partner), - ) + log.critical('new_netting_channel failed', **log_details) raise RaidenUnrecoverableError('creating new channel failed') channel_identifier = self.detail_channel(self.node_address, partner).channel_identifier - log.info( - 'new_netting_channel created succesfully with', - peer1=pex(self.node_address), - peer2=pex(partner), - channel_identifier=channel_identifier, - ) + log_details['channel_identifier'] = channel_identifier + log.info('new_netting_channel succesful', **log_details) return channel_identifier @@ -515,17 +509,34 @@ def set_total_deposit( partner, ).deposit amount_to_deposit = total_deposit - current_deposit + + log_details = { + 'token_network': pex(self.address), + 'node': pex(self.node_address), + 'partner': pex(partner), + 'total_deposit': total_deposit, + 'amount_to_deposit': amount_to_deposit, + 'id': id(self), + } + log.debug('setTotalDeposit called', **log_details) + + # These two scenarions can happen if two calls to deposit happen + # and then we get here on the second call if total_deposit < current_deposit: - raise DepositMismatch( + msg = ( f'Current deposit ({current_deposit}) is already larger ' - f'than the requested total deposit amount ({total_deposit})', + f'than the requested total deposit amount ({total_deposit})' ) + log.info(f'setTotalDeposit failed, {msg}', **log_details) + raise DepositMismatch(msg) + if amount_to_deposit <= 0: - # Can happen if two calls to deposit happen and then we get here on the second call - raise DepositMismatch( + msg = ( f'total_deposit - current_deposit = ' f'{amount_to_deposit} must be greater than 0.', ) + log.info(f'setTotalDeposit failed, {msg}', **log_details) + raise DepositMismatch(msg) # A node may be setting up multiple channels for the same token # concurrently. Because each deposit changes the user balance this @@ -541,11 +552,13 @@ def set_total_deposit( # current_balance = token.balance_of(self.node_address) if current_balance < amount_to_deposit: - raise DepositMismatch( + msg = ( f'total_deposit - current_deposit = {amount_to_deposit} can not ' f'be larger than the available balance {current_balance}, ' - f'for token at address {pex(token_address)}', + f'for token at address {pex(token_address)}' ) + log.info(f'setTotalDeposit failed, {msg}', **log_details) + raise DepositMismatch(msg) # If there are channels being set up concurrenlty either the # allowance must be accumulated *or* the calls to `approve` and @@ -567,16 +580,6 @@ def set_total_deposit( # making the second deposit fail. token.approve(self.address, amount_to_deposit) - log_details = { - 'token_network': pex(self.address), - 'node': pex(self.node_address), - 'partner': pex(partner), - 'total_deposit': total_deposit, - 'amount_to_deposit': amount_to_deposit, - 'id': id(self), - } - log.info('deposit called', **log_details) - transaction_hash = self.proxy.transact( 'setTotalDeposit', channel_identifier, @@ -591,13 +594,14 @@ def set_total_deposit( if receipt_or_none: if token.allowance(self.node_address, self.address) < amount_to_deposit: log_msg = ( - 'deposit failed. The allowance is insufficient, check concurrent deposits ' - 'for the same token network but different proxies.' + 'setTotalDeposit failed. The allowance is insufficient, ' + 'check concurrent deposits for the same token network ' + 'but different proxies.' ) elif token.balance_of(self.node_address) < amount_to_deposit: - log_msg = 'deposit failed. The address doesnt have funds' + log_msg = 'setTotalDeposit failed. The address doesnt have funds' else: - log_msg = 'deposit failed' + log_msg = 'setTotalDeposit failed' log.critical(log_msg, **log_details) @@ -610,7 +614,7 @@ def set_total_deposit( raise TransactionThrew('Deposit', receipt_or_none) - log.info('deposit successful', **log_details) + log.info('setTotalDeposit successful', **log_details) def close( self, @@ -638,7 +642,7 @@ def close( 'additional_hash': encode_hex(additional_hash), 'signature': encode_hex(signature), } - log.info('close called', **log_details) + log.debug('closeChannel called', **log_details) self._check_for_outdated_channel( self.node_address, @@ -666,7 +670,7 @@ def close( receipt_or_none = check_transaction_threw(self.client, transaction_hash) if receipt_or_none: - log.critical('close failed', **log_details) + log.critical('closeChannel failed', **log_details) self._check_channel_state_for_close( self.node_address, @@ -676,7 +680,7 @@ def close( raise TransactionThrew('Close', receipt_or_none) - log.info('close successful', **log_details) + log.info('closeChannel successful', **log_details) def update_transfer( self, @@ -698,7 +702,7 @@ def update_transfer( 'closing_signature': encode_hex(closing_signature), 'non_closing_signature': encode_hex(non_closing_signature), } - log.info('updateNonClosingBalanceProof called', **log_details) + log.debug('updateNonClosingBalanceProof called', **log_details) self._check_for_outdated_channel( self.node_address, @@ -722,15 +726,19 @@ def update_transfer( receipt_or_none = check_transaction_threw(self.client, transaction_hash) if receipt_or_none: - log.critical('updateNonClosingBalanceProof failed', **log_details) channel_closed = self.channel_is_closed( participant1=self.node_address, participant2=partner, channel_identifier=channel_identifier, ) if channel_closed is False: - raise RaidenUnrecoverableError('Channel is not in a closed state') - raise TransactionThrew('Update NonClosing balance proof', receipt_or_none) + msg = 'Channel is not in a closed state' + log.critical(f'updateNonClosingBalanceProof failed, {msg}', **log_details) + raise RaidenUnrecoverableError(msg) + + msg = 'Update NonClosing balance proof' + log.critical(f'updateNonClosingBalanceProof failed, {msg}', **log_details) + raise TransactionThrew(msg, receipt_or_none) log.info('updateNonClosingBalanceProof successful', **log_details) @@ -750,7 +758,7 @@ def withdraw( 'partner_signature': encode_hex(partner_signature), 'signature': encode_hex(signature), } - log.info('withdraw called', **log_details) + log.debug('setTotalWithdraw called', **log_details) self._check_for_outdated_channel( self.node_address, @@ -764,13 +772,19 @@ def withdraw( partner, ).withdrawn amount_to_withdraw = total_withdraw - current_withdraw + if total_withdraw < current_withdraw: - raise WithdrawMismatch( + msg = ( f'Current withdraw ({current_withdraw}) is already larger ' f'than the requested total withdraw amount ({total_withdraw})', ) + log.critical(f'setTotalWithdraw failed, {msg}', **log_details) + raise WithdrawMismatch(msg) + if amount_to_withdraw <= 0: - raise ValueError(f'withdraw {amount_to_withdraw} must be greater than 0.') + msg = f'withdraw {amount_to_withdraw} must be greater than 0.' + log.critical(f'setTotalWithdraw failed, {msg}', **log_details) + raise ValueError(msg) with self.channel_operations_lock[partner]: transaction_hash = self.proxy.transact( @@ -785,7 +799,7 @@ def withdraw( receipt_or_none = check_transaction_threw(self.client, transaction_hash) if receipt_or_none: - log.critical('withdraw failed', **log_details) + log.critical('setTotalWithdraw failed', **log_details) self._check_channel_state_for_withdraw( self.node_address, @@ -796,7 +810,7 @@ def withdraw( raise TransactionThrew('Withdraw', receipt_or_none) - log.info('withdraw successful', **log_details) + log.info('setTotalWithdraw successful', **log_details) def unlock( self, @@ -875,7 +889,7 @@ def settle( 'partner_locked_amount': partner_locked_amount, 'partner_locksroot': encode_hex(partner_locksroot), } - log.info('settle called', **log_details) + log.debug('settle called', **log_details) self._check_for_outdated_channel( self.node_address, @@ -920,7 +934,7 @@ def settle( self.client.poll(transaction_hash) receipt_or_none = check_transaction_threw(self.client, transaction_hash) if receipt_or_none: - log.info('settle failed', **log_details) + log.critical('settle failed', **log_details) self._check_channel_state_for_settle( self.node_address, partner, diff --git a/raiden/network/proxies/token_network_registry.py b/raiden/network/proxies/token_network_registry.py index 88e05810c2..9cbaa18b09 100644 --- a/raiden/network/proxies/token_network_registry.py +++ b/raiden/network/proxies/token_network_registry.py @@ -82,12 +82,12 @@ def add_token(self, token_address: typing.TokenAddress): if not is_binary_address(token_address): raise InvalidAddress('Expected binary address format for token') - log.info( - 'add_token called', - node=pex(self.node_address), - token_address=pex(token_address), - registry_address=pex(self.address), - ) + log_details = { + 'node': pex(self.node_address), + 'token_address': pex(token_address), + 'registry_address': pex(self.address), + } + log.debug('createERC20TokenNetwork called', **log_details) transaction_hash = self.proxy.transact( 'createERC20TokenNetwork', @@ -97,34 +97,28 @@ def add_token(self, token_address: typing.TokenAddress): self.client.poll(transaction_hash) receipt_or_none = check_transaction_threw(self.client, transaction_hash) if receipt_or_none: - log.info( - 'add_token failed', - node=pex(self.node_address), - token_address=pex(token_address), - registry_address=pex(self.address), - ) if self.get_token_network(token_address): - raise RaidenRecoverableError('Token already registered') + msg = 'Token already registered' + log.info(f'createERC20TokenNetwork failed, {msg}', **log_details) + raise RaidenRecoverableError(msg) + + log.critical(f'createERC20TokenNetwork failed', **log_details) raise TransactionThrew('createERC20TokenNetwork', receipt_or_none) token_network_address = self.get_token_network(token_address) if token_network_address is None: - log.info( - 'add_token failed and check_transaction_threw didnt detect it', - node=pex(self.node_address), - token_address=pex(token_address), - registry_address=pex(self.address), + log.critical( + 'createERC20TokenNetwork failed and check_transaction_threw didnt detect it', + **log_details, ) raise RuntimeError('token_to_token_networks failed') log.info( - 'add_token successful', - node=pex(self.node_address), - token_address=pex(token_address), - registry_address=pex(self.address), + 'createERC20TokenNetwork successful', token_network_address=pex(token_network_address), + **log_details, ) return token_network_address