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