log election results in election pipeline

bigchaindb/core.py

@@ -623,7 +623,6 @@ class Bigchain(object):
                                                          block['id']))
         keyring = self.nodes_except_me + [self.me]
         result = self.consensus.voting.block_election(block, votes, keyring)
-        # TODO: logging
         return result
 
     def block_election_status(self, block):

bigchaindb/pipelines/election.py

@@ -16,6 +16,7 @@ from bigchaindb import Bigchain
 
 
 logger = logging.getLogger(__name__)
+logger_results = logging.getLogger('pipeline.election.results')
 
 
 class Election:
@@ -32,13 +33,29 @@ class Election:
             next_vote: The next vote.
 
         """
-        next_block = self.bigchain.get_block(
-            next_vote['vote']['voting_for_block'])
+        try:
+            block_id = next_vote['vote']['voting_for_block']
+            node = next_vote['node_pubkey']
+        except IndexError:
+            return
 
-        block_status = self.bigchain.block_election_status(next_block)
-        if block_status == self.bigchain.BLOCK_INVALID:
+        next_block = self.bigchain.get_block(block_id)
+
+        result = self.bigchain.block_election_status(next_block)
+        if result['status'] == self.bigchain.BLOCK_INVALID:
             return Block.from_dict(next_block)
 
+        # Log the result
+        if result['status'] != self.bigchain.BLOCK_UNDECIDED:
+            msg = 'node:%s block:%s status:%s' % \
+                (node, block_id, result['status'])
+            # Extra data can be accessed via the log formatter.
+            # See logging.dictConfig.
+            logger_results.debug(msg, extra={
+                'current_vote': next_vote,
+                'election_result': result,
+            })
+
     def requeue_transactions(self, invalid_block):
         """
         Liquidates transactions from invalid blocks so they can be processed again

bigchaindb/voting.py

@@ -34,6 +34,7 @@ class Voting:
             cls.partition_eligible_votes(votes, eligible_voters)
         n_voters = len(eligible_voters)
         results = cls.count_votes(eligible_votes)
+        results['block_id'] = block['id']
         results['status'] = cls.decide_votes(n_voters, **results['counts'])
         results['ineligible'] = ineligible_votes
         return results

tests/test_voting.py

@@ -149,7 +149,7 @@ def test_block_election(b):
             return True
 
     keyring = 'abc'
-    block = {'block': {'voters': 'ab'}}
+    block = {'id': 'xyz', 'block': {'voters': 'ab'}}
     votes = [{
         'node_pubkey': c,
         'vote': {'is_block_valid': True, 'previous_block': 'a'}
@@ -157,6 +157,7 @@ def test_block_election(b):
 
     assert TestVoting.block_election(block, votes, keyring) == {
         'status': VALID,
+        'block_id': 'xyz',
         'counts': {'n_agree_prev_block': 2, 'n_valid': 2, 'n_invalid': 0},
         'ineligible': [votes[-1]],
         'cheat': [],