Merge pull request #467 from neonlabsorg/322-check_try_except_block_f…

…or_right_logging

322 check try except block for right logging

proxy/environment.py

@@ -18,6 +18,7 @@
 WRITE_TRANSACTION_COST_IN_DB = os.environ.get("WRITE_TRANSACTION_COST_IN_DB", "NO") == "YES"
 RETRY_ON_BLOCKED = max(int(os.environ.get("RETRY_ON_BLOCKED", "32")), 1)
 RETRY_ON_FAIL = int(os.environ.get("RETRY_ON_FAIL", "2"))
+RETRY_ON_FAIL_ON_GETTING_CONFIRMED_TRANSACTION = max(int(os.environ.get("RETRY_ON_FAIL_ON_GETTING_CONFIRMED_TRANSACTION", "1000")), 1)
 
 
 @logged_group("neon.proxy")

proxy/indexer/indexer.py

@@ -266,7 +266,7 @@ def neon_addr_fmt(neon_tx: NeonTxInfo):
     def _getadd_tx(self, storage_account, neon_tx=None, blocked_accounts=[str]) -> NeonTxObject:
         tx = self.state.get_tx(storage_account)
         if tx and neon_tx and tx.neon_tx and (neon_tx.sign != tx.neon_tx.sign):
-            self._log_warning(f'storage {storage_account}, tx.neon_tx({tx.neon_tx}) != neon_tx({neon_tx})')
+            self.warning(f'{self}: tx.neon_tx({tx.neon_tx}) != neon_tx({neon_tx}), storage: {storage_account}')
             self.state.unmark_ix_used(tx)
             self.state.del_tx(tx)
             tx = None
@@ -278,9 +278,6 @@ def _getadd_tx(self, storage_account, neon_tx=None, blocked_accounts=[str]) -> N
             tx.neon_tx = neon_tx
         return tx
 
-    def _log_warning(self, msg: str):
-        self.warning(f'{self}: {msg}')
-
     def _decoding_start(self):
         """
         Start decoding process:
@@ -369,7 +366,7 @@ def _init_tx_from_holder(self, holder_account: str, storage_account: str, blocke
 
         rlp_error = tx.neon_tx.decode(rlp_sign=rlp_sign, rlp_data=bytes(rlp_data))
         if rlp_error:
-            self._log_warning(f'Neon tx rlp error "{rlp_error}"')
+            self.error(f'{self} Neon tx rlp error: {rlp_error}')
 
         tx.holder_account = holder_account
         tx.move_ix_used(holder)

proxy/indexer/indexer_base.py

@@ -6,6 +6,8 @@
 from typing import Dict, Union
 from logged_groups import logged_group
 
+from ..environment import RETRY_ON_FAIL_ON_GETTING_CONFIRMED_TRANSACTION
+
 try:
     from sql_dict import SQLDict
     from trx_receipts_storage import TrxReceiptsStorage
@@ -38,7 +40,6 @@ def __init__(self,
         self.max_known_tx = self.transaction_receipts.max_known_trx()
         self._move_data_from_old_table()
 
-
     def _move_data_from_old_table(self):
         if self.transaction_receipts.size() == 0:
             transaction_receipts_old = SQLDict(tablename="known_transactions")
@@ -107,7 +108,6 @@ def gather_unknown_transactions(self):
         self.debug(max_known_tx)
         self.max_known_tx = max_known_tx
 
-
     def _get_signatures(self, before, until):
         opts: Dict[str, Union[int, str]] = {}
         if until is not None:
@@ -118,19 +118,21 @@ def _get_signatures(self, before, until):
         result = self.client._provider.make_request("getSignaturesForAddress", self.evm_loader_id, opts)
         return result['result']
 
-
     def _get_tx_receipts(self, solana_signature):
         # trx = None
-        retry = True
+        retry = RETRY_ON_FAIL_ON_GETTING_CONFIRMED_TRANSACTION
 
-        while retry:
+        while retry > 0:
             try:
                 trx = self.client.get_confirmed_transaction(solana_signature)['result']
                 self._add_trx(solana_signature, trx)
-                retry = False
+                retry = 0
             except Exception as err:
-                self.debug(err)
+                self.debug(f'Exception on get_confirmed_transaction: "{err}"')
                 time.sleep(1)
+                retry -= 1
+                if retry == 0:
+                    self.error(f'Exception on get_confirmed_transaction: "{err}"')
 
         self.counter_ += 1
         if self.counter_ % 100 == 0:

proxy/indexer/indexer_db.py

@@ -44,7 +44,7 @@ def submit_transaction(self, neon_tx: NeonTxInfo, neon_res: NeonTxResultInfo, us
             self._txs_db.set_tx(tx)
         except Exception as err:
             err_tb = "".join(traceback.format_tb(err.__traceback__))
-            self.warning('Exception on submitting transaction. ' +
+            self.error('Exception on submitting transaction. ' +
                            f'Type(err): {type(err)}, Error: {err}, Traceback: {err_tb}')
 
     def _fill_block_from_net(self, block: SolanaBlockDBInfo):

proxy/indexer/pythnetwork.py

@@ -161,7 +161,7 @@ def update_mapping(self, mapping_acc: PublicKey):
                 self.info(f'Product account {prod_acc}: {symbol}')
                 self.price_accounts[symbol] = product['price_acc']
             except Exception as err:
-                self.warning(f'Failed to read product account {prod_acc}: {err}')
+                self.error(f'Failed to read product account {prod_acc}: {err}')
                 continue
 
     def get_price(self, symbol):

proxy/indexer/utils.py

@@ -212,7 +212,6 @@ def decode(self, rlp_sign: bytes, rlp_data: bytes):
 
             return None
         except Exception as e:
-            self.warning(f'Exception on RLP decoding: {e}')
             self.error = e
             return self.error
 
@@ -457,7 +456,7 @@ def call(self, *args):
             self.debug(cmd)
             return subprocess.check_output(cmd, universal_newlines=True)
         except subprocess.CalledProcessError as err:
-            self.debug("ERR: solana error {}".format(err))
+            self.error("ERR: solana error {}".format(err))
             raise
 
     def unlock_accounts(self, blocked_storages):

proxy/plugin/solana_rest_api.py

@@ -113,7 +113,7 @@ def eth_estimateGas(self, param):
             value = param.get('value', "")
             return estimate_gas(self.client, self.signer, contract_id, EthereumAddress(caller_id), data, value)
         except Exception as err:
-            self.debug("Exception on eth_estimateGas: %s", err)
+            self.error("Exception on eth_estimateGas: {}".format(err))
             raise
 
     def __repr__(self):
@@ -216,7 +216,7 @@ def eth_getStorageAt(self, account, position, block_identifier):
             value = neon_cli().call('get-storage-at', account, position)
             return value
         except Exception as err:
-            self.debug(f"Neon-cli failed to execute: {err}")
+            self.error(f"eth_getStorageAt: Neon-cli failed to execute: {err}")
             return '0x00'
 
     def eth_getBlockByHash(self, block_hash, full):
@@ -273,7 +273,7 @@ def eth_call(self, obj, tag):
             value = obj.get('value', '')
             return "0x"+call_emulated(contract_id, caller_id, data, value)['result']
         except Exception as err:
-            self.debug("eth_call %s", err)
+            self.error("eth_call Exception %s", err)
             raise
 
     def eth_getTransactionCount(self, account, tag):
@@ -282,7 +282,7 @@ def eth_getTransactionCount(self, account, tag):
             acc_info = getAccountInfo(self.client, EthereumAddress(account))
             return hex(int.from_bytes(acc_info.trx_count, 'little'))
         except Exception as err:
-            print("Can't get account info: %s"%err)
+            self.error("eth_getTransactionCount: Can't get account info: %s", err)
             return hex(0)
 
     def _getTransactionReceipt(self, tx):
@@ -395,10 +395,10 @@ def eth_sendRawTransaction(self, rawTrx):
             self._log_transaction_error(err)
             raise
         except EthereumError as err:
-            self.debug("eth_sendRawTransaction EthereumError:%s", err)
+            self.error("eth_sendRawTransaction EthereumError:%s", err)
             raise
         except Exception as err:
-            self.debug("eth_sendRawTransaction type(err):%s, Exception:%s", type(err), err)
+            self.error("eth_sendRawTransaction type(err):%s, Exception:%s", type(err), err)
             raise
 
     def _log_transaction_error(self, error: SolanaTrxError):
@@ -527,7 +527,7 @@ def process_request(self, request):
             response['error'] = err.getError()
         except Exception as err:
             err_tb = "".join(traceback.format_tb(err.__traceback__))
-            self.warning('Exception on process request. ' +
+            self.error('Exception on process request. ' +
                            f'Type(err): {type(err)}, Error: {err}, Traceback: {err_tb}')
             response['error'] = {'code': -32000, 'message': str(err)}
 
@@ -545,7 +545,7 @@ def handle_request(self, request: HttpParser) -> None:
                 })))
             return
         start_time = time.time()
-        self.debug('<<< %s 0x%x %s', threading.get_ident(), id(self.model), request.body.decode('utf8'))
+        self.info('handle_request <<< %s 0x%x %s', threading.get_ident(), id(self.model), request.body.decode('utf8'))
         response = None
 
         try:
@@ -566,7 +566,7 @@ def handle_request(self, request: HttpParser) -> None:
             response = {'jsonrpc': '2.0', 'error': {'code': -32000, 'message': str(err)}}
 
         resp_time_ms = (time.time() - start_time)*1000  # convert this into milliseconds
-        self.debug('>>> %s 0x%0x %s %s resp_time_ms= %s', threading.get_ident(), id(self.model), json.dumps(response),
+        self.info('handle_request >>> %s 0x%0x %s %s resp_time_ms= %s', threading.get_ident(), id(self.model), json.dumps(response),
                      request.get('method', '---'),
                      resp_time_ms)