From b3ad169189f218104c50ab627b3f3bd3eff5a629 Mon Sep 17 00:00:00 2001 From: Andrew Nikitin Date: Wed, 11 Apr 2018 18:14:22 +0300 Subject: [PATCH 1/3] [INDY-1265] Increase log level Signed-off-by: Andrew Nikitin --- plenum/common/ledger.py | 2 +- plenum/common/ledger_manager.py | 2 +- plenum/server/node.py | 6 +++--- plenum/server/replica.py | 26 +++++++++++++------------- plenum/test/stasher.py | 4 ++-- stp_core/loop/looper.py | 1 + stp_core/network/keep_in_touch.py | 2 +- stp_zmq/zstack.py | 2 +- 8 files changed, 23 insertions(+), 22 deletions(-) diff --git a/plenum/common/ledger.py b/plenum/common/ledger.py index f2fc5ca9f3..addc2eb09c 100644 --- a/plenum/common/ledger.py +++ b/plenum/common/ledger.py @@ -81,7 +81,7 @@ def discardTxns(self, count: int): self.uncommittedTree = self.treeWithAppliedTxns( self.uncommittedTxns) self.uncommittedRootHash = self.uncommittedTree.root_hash - logger.debug('Discarding {} txns and root hash {} and new root hash ' + logger.info('Discarding {} txns and root hash {} and new root hash ' 'is {}. {} are still uncommitted'. format(count, old_hash, self.uncommittedRootHash, len(self.uncommittedTxns))) diff --git a/plenum/common/ledger_manager.py b/plenum/common/ledger_manager.py index e514984391..aac94e7454 100644 --- a/plenum/common/ledger_manager.py +++ b/plenum/common/ledger_manager.py @@ -1092,7 +1092,7 @@ def appendToLedger(self, ledgerId: int, txn: Any) -> Dict: return ledgerInfo.ledger.append(txn) def stashLedgerStatus(self, ledgerId: int, status, frm: str): - logger.debug("{} stashing ledger status {} from {}". + logger.info("{} stashing ledger status {} from {}". format(self, status, frm)) ledgerInfo = self.getLedgerInfoByType(ledgerId) ledgerInfo.stashedLedgerStatuses.append((status, frm)) diff --git a/plenum/server/node.py b/plenum/server/node.py index 702377439f..4e043f97a6 100644 --- a/plenum/server/node.py +++ b/plenum/server/node.py @@ -1417,7 +1417,7 @@ def msgHasAcceptableInstId(self, msg, frm) -> bool: if instId not in self.msgsForFutureReplicas: self.msgsForFutureReplicas[instId] = deque() self.msgsForFutureReplicas[instId].append((msg, frm)) - logger.debug("{} queueing message {} for future protocol " + logger.info("{} queueing message {} for future protocol " "instance {}".format(self, msg, instId)) return False return True @@ -1439,7 +1439,7 @@ def msgHasAcceptableViewNo(self, msg, frm) -> bool: elif view_no > self.viewNo: if view_no not in self.msgsForFutureViews: self.msgsForFutureViews[view_no] = deque() - logger.debug('{} stashing a message for a future view: {}'. + logger.info('{} stashing a message for a future view: {}'. format(self, msg)) self.msgsForFutureViews[view_no].append((msg, frm)) if isinstance(msg, ViewChangeDone): @@ -1533,7 +1533,7 @@ def validateNodeMsg(self, wrappedMsg): self.verifySignature(message) except BaseExc as ex: raise SuspiciousNode(frm, ex, message) from ex - logger.trace("{} received node message from {}: {}". + logger.info("{} received node message from {}: {}". format(self, frm, message), extra={"cli": False}) return message, frm diff --git a/plenum/server/replica.py b/plenum/server/replica.py index ef0f5b2b88..a6c3128d10 100644 --- a/plenum/server/replica.py +++ b/plenum/server/replica.py @@ -336,7 +336,7 @@ def h(self) -> int: def h(self, n): self._h = n self.H = self._h + self.config.LOG_SIZE - self.logger.debug('{} set watermarks as {} {}'.format(self, self.h, self.H)) + self.logger.info('{} set watermarks as {} {}'.format(self, self.h, self.H)) @property def last_ordered_3pc(self) -> tuple: @@ -345,7 +345,7 @@ def last_ordered_3pc(self) -> tuple: @last_ordered_3pc.setter def last_ordered_3pc(self, key3PC): self._last_ordered_3pc = key3PC - self.logger.debug('{} set last ordered as {}'.format( + self.logger.info('{} set last ordered as {}'.format( self, self._last_ordered_3pc)) @property @@ -795,7 +795,7 @@ def processPostElectionMsgs(self): """ while self.postElectionMsgs: msg = self.postElectionMsgs.popleft() - self.logger.debug("{} processing pended msg {}".format(self, msg)) + self.logger.info("{} processing pended msg {}".format(self, msg)) self.dispatchThreePhaseMsg(*msg) def dispatchThreePhaseMsg(self, msg: ThreePhaseMsg, sender: str) -> Any: @@ -827,7 +827,7 @@ def dispatchThreePhaseMsg(self, msg: ThreePhaseMsg, sender: str) -> Any: except SuspiciousNode as ex: self.node.reportSuspiciousNodeEx(ex) else: - self.logger.warning("{} stashing 3 phase message {} since ppSeqNo {} is " + self.logger.info("{} stashing 3 phase message {} since ppSeqNo {} is " "not between {} and {}".format( self, msg, msg.ppSeqNo, self.h, self.H)) self.stashOutsideWatermarks((msg, sender)) @@ -845,7 +845,7 @@ def processThreePhaseMsg(self, msg: ThreePhaseMsg, sender: str): if self.isPrimary is None: if not self.can_process_since_view_change_in_progress(msg): self.postElectionMsgs.append((msg, sender)) - self.logger.debug("Replica {} pended request {} from {}".format( + self.logger.info("Replica {} pended request {} from {}".format( self, msg, sender)) return self.dispatchThreePhaseMsg(msg, sender) @@ -865,7 +865,7 @@ def _process_valid_preprepare(self, pre_prepare, sender): key = (pre_prepare.viewNo, pre_prepare.ppSeqNo) if not self.node.isParticipating: self.stashingWhileCatchingUp.add(key) - self.logger.warning('{} stashing PRE-PREPARE{}'.format(self, key)) + self.logger.info('{} stashing PRE-PREPARE{}'.format(self, key)) return None old_state_root = self.stateRootHash(pre_prepare.ledgerId, to_str=False) why_not_applied = self._apply_pre_prepare(pre_prepare, sender) @@ -968,7 +968,7 @@ def tryPrepare(self, pp: PrePrepare): if rv: self.doPrepare(pp) else: - self.logger.debug("{} cannot send PREPARE since {}".format(self, msg)) + self.logger.info("{} cannot send PREPARE since {}".format(self, msg)) def processPrepare(self, prepare: Prepare, sender: str) -> None: """ @@ -1043,7 +1043,7 @@ def tryOrder(self, commit: Commit): self.logger.trace("{} returning request to node".format(self)) self.doOrder(commit) else: - self.logger.debug("{} cannot return request to node: {}".format(self, reason)) + self.logger.info("{} cannot return request to node: {}".format(self, reason)) return canOrder def doPrepare(self, pp: PrePrepare): @@ -1597,7 +1597,7 @@ def has_prepared(self, key): def doOrder(self, commit: Commit): key = (commit.viewNo, commit.ppSeqNo) - self.logger.debug("{} ordering COMMIT {}".format(self, key)) + self.logger.info("{} ordering COMMIT {}".format(self, key)) return self.order_3pc_key(key) def order_3pc_key(self, key): @@ -1787,7 +1787,7 @@ def checkIfCheckpointStable(self, key: Tuple[int, int]): return False def stashCheckpoint(self, ck: Checkpoint, sender: str): - self.logger.debug('{} stashing {} from {}'.format(self, ck, sender)) + self.logger.info('{} stashing {} from {}'.format(self, ck, sender)) seqNoStart, seqNoEnd = ck.seqNoStart, ck.seqNoEnd if ck.viewNo not in self.stashedRecvdCheckpoints: self.stashedRecvdCheckpoints[ck.viewNo] = {} @@ -1990,7 +1990,7 @@ def compact_ordered(self): def enqueue_pre_prepare(self, ppMsg: PrePrepare, sender: str, nonFinReqs: Set = None): if nonFinReqs: - self.logger.debug( + self.logger.info( "Queueing pre-prepares due to unavailability of finalised " "requests. PrePrepare {} from {}".format( ppMsg, sender)) @@ -1998,7 +1998,7 @@ def enqueue_pre_prepare(self, ppMsg: PrePrepare, sender: str, else: # Possible exploit, an malicious party can send an invalid # pre-prepare and over-write the correct one? - self.logger.debug( + self.logger.info( "Queueing pre-prepares due to unavailability of previous " "pre-prepares. {} from {}".format(ppMsg, sender)) self.prePreparesPendingPrevPP[ppMsg.viewNo, ppMsg.ppSeqNo] = ( @@ -2071,7 +2071,7 @@ def dequeue_prepares(self, viewNo: int, ppSeqNo: int): " view no {} and seq no {}".format(self, i, viewNo, ppSeqNo)) def enqueue_commit(self, request: Commit, sender: str): - self.logger.debug("Queueing commit due to unavailability of PREPARE. " + self.logger.info("Queueing commit due to unavailability of PREPARE. " "Request {} from {}".format(request, sender)) key = (request.viewNo, request.ppSeqNo) if key not in self.commitsWaitingForPrepare: diff --git a/plenum/test/stasher.py b/plenum/test/stasher.py index b6b83c201e..7a2ae20161 100644 --- a/plenum/test/stasher.py +++ b/plenum/test/stasher.py @@ -47,7 +47,7 @@ def stashAll(self, age): for rx in list(self.queue): secondsToDelay = tester(rx) if secondsToDelay: - logger.debug("{} stashing message {} for " + logger.info("{} stashing message {} for " "{} seconds". format(self.name, rx, secondsToDelay)) self.delayeds.append(StasherDelayed(item=rx, timestamp=age + secondsToDelay, rule=tester.__name__)) @@ -75,7 +75,7 @@ def unstashAll(self, age, *names, ignore_age_check=False): else: msg = '({:.0f} milliseconds overdue)'.format( (age - d.timestamp) * 1000) - logger.debug( + logger.info( "{} unstashing message {} {}". format(self.name, d.item, msg)) self.queue.appendleft(d.item) diff --git a/stp_core/loop/looper.py b/stp_core/loop/looper.py index a2be71cd14..84130c9548 100644 --- a/stp_core/loop/looper.py +++ b/stp_core/loop/looper.py @@ -103,6 +103,7 @@ def __init__(self, asyncio.set_event_loop(evl) self.loop = evl + logger.info("Starting up indy-node") self.runFut = self.loop.create_task(self.runForever()) # type: Task self.running = True # type: bool diff --git a/stp_core/network/keep_in_touch.py b/stp_core/network/keep_in_touch.py index 2da55fdbc4..f19fe4235a 100644 --- a/stp_core/network/keep_in_touch.py +++ b/stp_core/network/keep_in_touch.py @@ -63,7 +63,7 @@ def conns(self, value: Set[str]) -> None: self._conns = value ins = value - old outs = old - value - logger.debug("{}'s connections changed from {} to {}".format(self, + logger.info("{}'s connections changed from {} to {}".format(self, old, value)) self._connsChanged(ins, outs) diff --git a/stp_zmq/zstack.py b/stp_zmq/zstack.py index c1fe0787a9..2c8fac0bcb 100644 --- a/stp_zmq/zstack.py +++ b/stp_zmq/zstack.py @@ -716,7 +716,7 @@ def transmit(self, msg, uid, timeout=None, serialized=False): logger.trace('{} transmitting message {} to {}' .format(self, msg, uid)) if not remote.isConnected and msg not in self.healthMessages: - logger.debug('Remote {} is not connected - ' + logger.info('Remote {} is not connected - ' 'message will not be sent immediately.' 'If this problem does not resolve itself - ' 'check your firewall settings'.format(uid)) From 524fe38f4c99a87f07985a93f7c7b6e04c51774f Mon Sep 17 00:00:00 2001 From: Andrew Nikitin Date: Wed, 11 Apr 2018 18:22:22 +0300 Subject: [PATCH 2/3] [INDY-1264] Remove unused exception handlers in tests Signed-off-by: Andrew Nikitin --- plenum/test/conftest.py | 5 ++++- plenum/test/pool_transactions/helper.py | 16 ++-------------- plenum/test/script/helper.py | 5 ----- 3 files changed, 6 insertions(+), 20 deletions(-) diff --git a/plenum/test/conftest.py b/plenum/test/conftest.py index d8821244a1..618e59e30b 100644 --- a/plenum/test/conftest.py +++ b/plenum/test/conftest.py @@ -999,7 +999,10 @@ def sdk_pool_handle(looper, txnPoolNodeSet, tdirWithPoolTxns, sdk_pool_name): pool_handle = looper.loop.run_until_complete( _gen_pool_handler(tdirWithPoolTxns, sdk_pool_name)) yield pool_handle - looper.loop.run_until_complete(close_pool_ledger(pool_handle)) + try: + looper.loop.run_until_complete(close_pool_ledger(pool_handle)) + except Exception as e: + logger.debug("Unhandled exception: {}".format(e)) async def _gen_wallet_handler(pool_name, wallet_name): diff --git a/plenum/test/pool_transactions/helper.py b/plenum/test/pool_transactions/helper.py index 04543b28c0..37fae0f3cf 100644 --- a/plenum/test/pool_transactions/helper.py +++ b/plenum/test/pool_transactions/helper.py @@ -467,20 +467,8 @@ def updateNodeData(looper, stewardClient, stewardWallet, node, node_data): def sdk_pool_refresh(looper, sdk_pool_handle): - for tries in range(REFRESH_TRY_COUNT): - try: - looper.loop.run_until_complete( - refresh_pool_ledger(sdk_pool_handle)) - except IndyError as e: - if e.error_code == ErrorCode.PoolLedgerTerminated: - logger.debug("PoolLedgerTerminated: Refresh try number: {}".format(tries)) - elif e.error_code == ErrorCode.CommonIOError: - logger.debug("CommonIOError: Refresh try number: {}".format(tries)) - else: - logger.debug("Unexpected IndyError: {}".format(e)) - - else: - return + looper.loop.run_until_complete( + refresh_pool_ledger(sdk_pool_handle)) def sdk_build_get_txn_request(looper, steward_did, data): request = looper.loop.run_until_complete( diff --git a/plenum/test/script/helper.py b/plenum/test/script/helper.py index fb4827b68c..423e77ef67 100644 --- a/plenum/test/script/helper.py +++ b/plenum/test/script/helper.py @@ -71,11 +71,6 @@ def changeNodeHa(looper, txnPoolNodeSet, tdirWithClientPoolTxns, retryWait=1, customTimeout=electionTimeout) - # start client and check the node HA - # anotherClient, _ = genTestClient(tmpdir=tdirWithClientPoolTxns, - # # usePoolLedger=True) - # looper.add(anotherClient) - # looper.run(eventually(anotherClient.ensureConnectedToNodes)) sdk_pool_refresh(looper, sdk_pool_handle) sdk_send_random_and_check(looper, txnPoolNodeSet, sdk_pool_handle, From 20200af9c98c6afb152b5300c1ded97ea917c8f6 Mon Sep 17 00:00:00 2001 From: Andrew Nikitin Date: Wed, 11 Apr 2018 18:36:22 +0300 Subject: [PATCH 3/3] [INDY-1265] flake8 fixes Signed-off-by: Andrew Nikitin --- plenum/common/ledger.py | 6 +++--- plenum/common/ledger_manager.py | 2 +- plenum/server/node.py | 12 ++++++------ plenum/server/replica.py | 6 +++--- stp_core/network/keep_in_touch.py | 4 ++-- stp_zmq/zstack.py | 6 +++--- 6 files changed, 18 insertions(+), 18 deletions(-) diff --git a/plenum/common/ledger.py b/plenum/common/ledger.py index addc2eb09c..d29f5af19f 100644 --- a/plenum/common/ledger.py +++ b/plenum/common/ledger.py @@ -82,9 +82,9 @@ def discardTxns(self, count: int): self.uncommittedTxns) self.uncommittedRootHash = self.uncommittedTree.root_hash logger.info('Discarding {} txns and root hash {} and new root hash ' - 'is {}. {} are still uncommitted'. - format(count, old_hash, self.uncommittedRootHash, - len(self.uncommittedTxns))) + 'is {}. {} are still uncommitted'. + format(count, old_hash, self.uncommittedRootHash, + len(self.uncommittedTxns))) def treeWithAppliedTxns(self, txns: List, currentTree=None): """ diff --git a/plenum/common/ledger_manager.py b/plenum/common/ledger_manager.py index aac94e7454..b34304cb9e 100644 --- a/plenum/common/ledger_manager.py +++ b/plenum/common/ledger_manager.py @@ -1093,7 +1093,7 @@ def appendToLedger(self, ledgerId: int, txn: Any) -> Dict: def stashLedgerStatus(self, ledgerId: int, status, frm: str): logger.info("{} stashing ledger status {} from {}". - format(self, status, frm)) + format(self, status, frm)) ledgerInfo = self.getLedgerInfoByType(ledgerId) ledgerInfo.stashedLedgerStatuses.append((status, frm)) diff --git a/plenum/server/node.py b/plenum/server/node.py index 4e043f97a6..d044f8e53c 100644 --- a/plenum/server/node.py +++ b/plenum/server/node.py @@ -1418,7 +1418,7 @@ def msgHasAcceptableInstId(self, msg, frm) -> bool: self.msgsForFutureReplicas[instId] = deque() self.msgsForFutureReplicas[instId].append((msg, frm)) logger.info("{} queueing message {} for future protocol " - "instance {}".format(self, msg, instId)) + "instance {}".format(self, msg, instId)) return False return True @@ -1440,7 +1440,7 @@ def msgHasAcceptableViewNo(self, msg, frm) -> bool: if view_no not in self.msgsForFutureViews: self.msgsForFutureViews[view_no] = deque() logger.info('{} stashing a message for a future view: {}'. - format(self, msg)) + format(self, msg)) self.msgsForFutureViews[view_no].append((msg, frm)) if isinstance(msg, ViewChangeDone): # TODO this is put of the msgs queue scope @@ -1534,8 +1534,8 @@ def validateNodeMsg(self, wrappedMsg): except BaseExc as ex: raise SuspiciousNode(frm, ex, message) from ex logger.info("{} received node message from {}: {}". - format(self, frm, message), - extra={"cli": False}) + format(self, frm, message), + extra={"cli": False}) return message, frm def unpackNodeMsg(self, msg, frm) -> None: @@ -2875,8 +2875,8 @@ def send(self, self.nodestack.remotes.values()] recipientsNum = 'all' - logger.debug("{} sending message {} to {} recipients: {}" - .format(self, msg, recipientsNum, remoteNames)) + logger.info("{} sending message {} to {} recipients: {}" + .format(self, msg, recipientsNum, remoteNames)) self.nodestack.send(msg, *rids, signer=signer, message_splitter=message_splitter) def sendToNodes(self, msg: Any, names: Iterable[str] = None, message_splitter=None): diff --git a/plenum/server/replica.py b/plenum/server/replica.py index a6c3128d10..4f8cdbe3c7 100644 --- a/plenum/server/replica.py +++ b/plenum/server/replica.py @@ -828,8 +828,8 @@ def dispatchThreePhaseMsg(self, msg: ThreePhaseMsg, sender: str) -> Any: self.node.reportSuspiciousNodeEx(ex) else: self.logger.info("{} stashing 3 phase message {} since ppSeqNo {} is " - "not between {} and {}".format( - self, msg, msg.ppSeqNo, self.h, self.H)) + "not between {} and {}".format( + self, msg, msg.ppSeqNo, self.h, self.H)) self.stashOutsideWatermarks((msg, sender)) def processThreePhaseMsg(self, msg: ThreePhaseMsg, sender: str): @@ -2072,7 +2072,7 @@ def dequeue_prepares(self, viewNo: int, ppSeqNo: int): def enqueue_commit(self, request: Commit, sender: str): self.logger.info("Queueing commit due to unavailability of PREPARE. " - "Request {} from {}".format(request, sender)) + "Request {} from {}".format(request, sender)) key = (request.viewNo, request.ppSeqNo) if key not in self.commitsWaitingForPrepare: self.commitsWaitingForPrepare[key] = deque() diff --git a/stp_core/network/keep_in_touch.py b/stp_core/network/keep_in_touch.py index f19fe4235a..2c8e0e4666 100644 --- a/stp_core/network/keep_in_touch.py +++ b/stp_core/network/keep_in_touch.py @@ -64,8 +64,8 @@ def conns(self, value: Set[str]) -> None: ins = value - old outs = old - value logger.info("{}'s connections changed from {} to {}".format(self, - old, - value)) + old, + value)) self._connsChanged(ins, outs) def checkConns(self): diff --git a/stp_zmq/zstack.py b/stp_zmq/zstack.py index 2c8fac0bcb..b368adac26 100644 --- a/stp_zmq/zstack.py +++ b/stp_zmq/zstack.py @@ -717,9 +717,9 @@ def transmit(self, msg, uid, timeout=None, serialized=False): .format(self, msg, uid)) if not remote.isConnected and msg not in self.healthMessages: logger.info('Remote {} is not connected - ' - 'message will not be sent immediately.' - 'If this problem does not resolve itself - ' - 'check your firewall settings'.format(uid)) + 'message will not be sent immediately.' + 'If this problem does not resolve itself - ' + 'check your firewall settings'.format(uid)) return True, err_str except zmq.Again: logger.debug(