adkg: update logs

[azixus]

This should allow us to get a good understanding of what happens if a node gets stuck during the ADKG with an info-level.

This gives us the following logs for n = 4, t = 1. Let me know what you guys think:

INFO ACSS::get_share{sid=SessionId(1)}: adkg::rbc::r4: Node `2` listening for RBC with parameters (n = `4`, t = `1`)
INFO ACSS::get_share{sid=SessionId(3)}: adkg::rbc::r4: Node `2` listening for RBC with parameters (n = `4`, t = `1`)
INFO ACSS::get_share{sid=SessionId(4)}: adkg::rbc::r4: Node `2` listening for RBC with parameters (n = `4`, t = `1`)
INFO RBC::listen{sid=SessionId(1)}: adkg::rbc::r4: Node `2` listening for RBC with parameters (n = `4`, t = `1`)
INFO RBC::listen{sid=SessionId(3)}: adkg::rbc::r4: Node `2` listening for RBC with parameters (n = `4`, t = `1`)
INFO RBC::listen{sid=SessionId(4)}: adkg::rbc::r4: Node `2` listening for RBC with parameters (n = `4`, t = `1`)
INFO adkg::adkg: ADKG main thread of node `2` waiting on ABA task to complete
INFO ACSS::get_share{sid=SessionId(1)}:received_proposal{proposal_sender=PartyId(1)}: adkg::rbc::r4::handlers: Node `2` accepted proposal
INFO ACSS::get_share{sid=SessionId(1)}: adkg::rbc::r4::handlers: Node `2` received t + 1 echos, waiting for t + 1 readys to change state count_echos=2 count_readys=0
INFO ACSS::deal{sid=SessionId(2)}: adkg::rbc::r4: Leader `2` starting RBC with parameters (n = `4`, t = `1`)
INFO ACSS::deal{sid=SessionId(2)}: adkg::rbc::r4: Node `2` listening for RBC with parameters (n = `4`, t = `1`)
INFO ACSS::deal{sid=SessionId(2)}:received_proposal{proposal_sender=PartyId(2)}: adkg::rbc::r4::handlers: Node `2` accepted proposal
INFO ACSS::deal{sid=SessionId(2)}: adkg::rbc::r4::handlers: Node `2` received t + 1 echos, waiting for t + 1 readys to change state count_echos=2 count_readys=0
INFO ACSS::deal{sid=SessionId(2)}: adkg::rbc::r4::handlers: Node `2` changing state to ready
INFO ACSS::get_share{sid=SessionId(1)}: adkg::rbc::r4::handlers: Node `2` changing state to ready
INFO ACSS::get_share{sid=SessionId(1)}: adkg::rbc::r4::handlers: Node `2` recovered message from `3` codewords, changing state to complete
INFO ACSS::get_share{sid=SessionId(1)}: adkg::rbc::r4: Node `2` completed RBC
INFO ACSS::deal{sid=SessionId(2)}: adkg::rbc::r4::handlers: Node `2` recovered message from `3` codewords, changing state to complete
INFO ACSS::deal{sid=SessionId(2)}: adkg::rbc::r4: Node `2` completed RBC
INFO ACSS::deal{sid=SessionId(2)}: adkg::vss::acss::hbacss0: Node `2` received valid shares. Starting ACSS protocol.
INFO ACSS::get_share{sid=SessionId(1)}: adkg::vss::acss::hbacss0: Node `2` received valid shares. Starting ACSS protocol.
INFO ACSS::deal{sid=SessionId(2)}: adkg::vss::acss::hbacss0::handlers: Node `2` received 2t + 1 Oks, sending Ready to all
INFO ACSS::deal{sid=SessionId(2)}: adkg::vss::acss::hbacss0::handlers: Node `2` received 2t + 1 Ready, ACSS has decided on a share, sending it through channel
INFO adkg::adkg: Node 2 completed ACSS with sid 2
INFO ACSS::get_share{sid=SessionId(3)}:received_proposal{proposal_sender=PartyId(3)}: adkg::rbc::r4::handlers: Node `2` accepted proposal
INFO ACSS::get_share{sid=SessionId(1)}: adkg::vss::acss::hbacss0::handlers: Node `2` received 2t + 1 Oks, sending Ready to all
INFO ACSS::get_share{sid=SessionId(3)}: adkg::rbc::r4::handlers: Node `2` received t + 1 echos, waiting for t + 1 readys to change state count_echos=2 count_readys=0
INFO ACSS::get_share{sid=SessionId(1)}: adkg::vss::acss::hbacss0::handlers: Node `2` received 2t + 1 Ready, ACSS has decided on a share, sending it through channel
INFO adkg::adkg: Node 2 completed ACSS with sid 1
INFO ACSS::get_share{sid=SessionId(1)}: adkg::vss::acss::hbacss0::handlers: Node `2` received n Ready, ACSS is Complete
INFO ACSS::get_share{sid=SessionId(3)}: adkg::rbc::r4::handlers: Node `2` changing state to ready
INFO ACSS::get_share{sid=SessionId(1)}: adkg::vss::acss::hbacss0: ACSS of node 2 successfully completed.
INFO ACSS::get_share{sid=SessionId(3)}: adkg::rbc::r4::handlers: Node `2` recovered message from `3` codewords, changing state to complete
INFO ACSS::get_share{sid=SessionId(3)}: adkg::rbc::r4: Node `2` completed RBC
INFO ACSS::get_share{sid=SessionId(3)}: adkg::vss::acss::hbacss0: Node `2` received valid shares. Starting ACSS protocol.
INFO ACSS::deal{sid=SessionId(2)}: adkg::vss::acss::hbacss0::handlers: Node `2` received n Ready, ACSS is Complete
INFO ACSS::deal{sid=SessionId(2)}: adkg::vss::acss::hbacss0: ACSS of leader node 2 successfully completed.
INFO ACSS::get_share{sid=SessionId(4)}:received_proposal{proposal_sender=PartyId(4)}: adkg::rbc::r4::handlers: Node `2` accepted proposal
INFO ACSS::get_share{sid=SessionId(3)}: adkg::vss::acss::hbacss0::handlers: Node `2` received 2t + 1 Oks, sending Ready to all
INFO ACSS::get_share{sid=SessionId(4)}: adkg::rbc::r4::handlers: Node `2` received t + 1 echos, waiting for t + 1 readys to change state count_echos=2 count_readys=0
INFO ACSS::get_share{sid=SessionId(3)}: adkg::vss::acss::hbacss0::handlers: Node `2` received 2t + 1 Ready, ACSS has decided on a share, sending it through channel
INFO adkg::adkg: Node 2 completed ACSS with sid 3
INFO adkg::adkg: Node 2 set its own RBC input rbc_input=[SessionId(1), SessionId(2), SessionId(3)]
INFO RBC::start{sid=SessionId(2)}: adkg::rbc::r4: Leader `2` starting RBC with parameters (n = `4`, t = `1`)
INFO RBC::start{sid=SessionId(2)}: adkg::rbc::r4: Node `2` listening for RBC with parameters (n = `4`, t = `1`)
INFO RBC::listen{sid=SessionId(4)}:received_proposal{proposal_sender=PartyId(4)}: adkg::rbc::r4::handlers: Node `2` accepted proposal
INFO RBC::listen{sid=SessionId(3)}:received_proposal{proposal_sender=PartyId(3)}: adkg::rbc::r4::handlers: Node `2` accepted proposal
INFO RBC::start{sid=SessionId(2)}:received_proposal{proposal_sender=PartyId(2)}: adkg::rbc::r4::handlers: Node `2` accepted proposal
INFO RBC::listen{sid=SessionId(3)}: adkg::rbc::r4::handlers: Node `2` received t + 1 echos, waiting for t + 1 readys to change state count_echos=2 count_readys=0
INFO RBC::listen{sid=SessionId(4)}: adkg::rbc::r4::handlers: Node `2` received t + 1 echos, waiting for t + 1 readys to change state count_echos=2 count_readys=0
INFO RBC::listen{sid=SessionId(4)}: adkg::rbc::r4::handlers: Node `2` changing state to ready
INFO RBC::listen{sid=SessionId(3)}: adkg::rbc::r4::handlers: Node `2` changing state to ready
INFO RBC::start{sid=SessionId(2)}: adkg::rbc::r4::handlers: Node `2` received t + 1 echos, waiting for t + 1 readys to change state count_echos=2 count_readys=0
INFO ACSS::get_share{sid=SessionId(4)}: adkg::rbc::r4::handlers: Node `2` changing state to ready
INFO RBC::start{sid=SessionId(2)}: adkg::rbc::r4::handlers: Node `2` changing state to ready
INFO RBC::listen{sid=SessionId(3)}: adkg::rbc::r4::handlers: Node `2` recovered message from `3` codewords, changing state to complete
INFO RBC::listen{sid=SessionId(3)}: adkg::rbc::r4: Node `2` completed RBC
INFO adkg::adkg: Node 2 completed RBC with sid `3` rbc_output={SessionId(2), SessionId(1), SessionId(3)}
INFO propose{sid=SessionId(3)}:propose_internal{aba_input=One}: adkg::aba::crain20: Node `2` executing ABA with sid `3` and estimate One
INFO propose{sid=SessionId(3)}:propose_internal{aba_input=One}: adkg::aba::crain20: Node `2` started ABA round 1 estimate=One
INFO RBC::listen{sid=SessionId(4)}: adkg::rbc::r4::handlers: Node `2` recovered message from `3` codewords, changing state to complete
INFO RBC::listen{sid=SessionId(4)}: adkg::rbc::r4: Node `2` completed RBC
INFO adkg::adkg: Node 2 completed RBC with sid `4` rbc_output={SessionId(1), SessionId(2), SessionId(3)}
INFO propose{sid=SessionId(4)}:propose_internal{aba_input=One}: adkg::aba::crain20: Node `2` executing ABA with sid `4` and estimate One
INFO propose{sid=SessionId(4)}:propose_internal{aba_input=One}: adkg::aba::crain20: Node `2` started ABA round 1 estimate=One
INFO ACSS::get_share{sid=SessionId(4)}: adkg::rbc::r4::handlers: Node `2` recovered message from `3` codewords, changing state to complete
INFO ACSS::get_share{sid=SessionId(4)}: adkg::rbc::r4: Node `2` completed RBC
INFO RBC::start{sid=SessionId(2)}: adkg::rbc::r4::handlers: Node `2` recovered message from `3` codewords, changing state to complete
INFO RBC::start{sid=SessionId(2)}: adkg::rbc::r4: Node `2` completed RBC
INFO adkg::adkg: Node 2 completed RBC with sid `2` rbc_output={SessionId(3), SessionId(2), SessionId(1)}
INFO propose{sid=SessionId(2)}:propose_internal{aba_input=One}: adkg::aba::crain20: Node `2` executing ABA with sid `2` and estimate One
INFO propose{sid=SessionId(2)}:propose_internal{aba_input=One}: adkg::aba::crain20: Node `2` started ABA round 1 estimate=One
INFO ACSS::get_share{sid=SessionId(3)}: adkg::vss::acss::hbacss0::handlers: Node `2` received n Ready, ACSS is Complete
INFO RBC::listen{sid=SessionId(1)}:received_proposal{proposal_sender=PartyId(1)}: adkg::rbc::r4::handlers: Node `2` accepted proposal
INFO ACSS::get_share{sid=SessionId(3)}: adkg::vss::acss::hbacss0: ACSS of node 2 successfully completed.
INFO ACSS::get_share{sid=SessionId(4)}: adkg::vss::acss::hbacss0: Node `2` received valid shares. Starting ACSS protocol.
INFO RBC::listen{sid=SessionId(1)}: adkg::rbc::r4::handlers: Node `2` received t + 1 echos, waiting for t + 1 readys to change state count_echos=2 count_readys=0
INFO RBC::listen{sid=SessionId(1)}: adkg::rbc::r4::handlers: Node `2` changing state to ready
INFO ACSS::get_share{sid=SessionId(4)}: adkg::vss::acss::hbacss0::handlers: Node `2` received 2t + 1 Oks, sending Ready to all
INFO ACSS::get_share{sid=SessionId(4)}: adkg::vss::acss::hbacss0::handlers: Node `2` received 2t + 1 Ready, ACSS has decided on a share, sending it through channel
INFO ACSS::get_share{sid=SessionId(4)}:implicate_handler{implicate_sender=PartyId(1)}: adkg::vss::acss::hbacss0::handlers: Node `2` received an Implicate message from node `1`
WARN ACSS::get_share{sid=SessionId(4)}:implicate_handler{implicate_sender=PartyId(1)}: adkg::vss::acss::hbacss0: Failed to decrypt pedersen party shares
WARN ACSS::get_share{sid=SessionId(4)}:implicate_handler{implicate_sender=PartyId(1)}: adkg::vss::acss::hbacss0::handlers: Node `2` discovered that an invalid share was sent to node `1`, sending own shared key.
INFO adkg::adkg: Node 2 completed ACSS with sid 4
INFO adkg::adkg: Node 2 completed all ACSS, exiting ADKG ACSS handler task
INFO RBC::listen{sid=SessionId(1)}: adkg::rbc::r4::handlers: Node `2` recovered message from `3` codewords, changing state to complete
INFO RBC::listen{sid=SessionId(1)}: adkg::rbc::r4: Node `2` completed RBC
INFO adkg::adkg: Node 2 completed RBC with sid `1` rbc_output={SessionId(1), SessionId(2), SessionId(3)}
INFO adkg::adkg: Node 2 completed all RBCs, exiting RBC handler task
INFO adkg::adkg: ADKG RBC task of node `2` exiting due to all outputs obtained
INFO propose{sid=SessionId(1)}:propose_internal{aba_input=One}: adkg::aba::crain20: Node `2` executing ABA with sid `1` and estimate One
INFO propose{sid=SessionId(1)}:propose_internal{aba_input=One}: adkg::aba::crain20: Node `2` started ABA round 1 estimate=One
INFO propose{sid=SessionId(3)}:propose_internal{aba_input=One}: adkg::aba::crain20: Node 2 sid `3` decided on estimate `One`
INFO propose{sid=SessionId(3)}:propose_internal{aba_input=One}: adkg::aba::crain20: Node `2` started ABA round 2 estimate=One
INFO adkg::adkg: Node 2 completed ABA with sid 3 and got estimate One
INFO adkg::aba::crain20: Node `2` in ABA with sid `3` stopping recv_thread
INFO propose{sid=SessionId(3)}: adkg::aba::crain20: Node `2` aborting ABA with sid `3`, cause: cancellation token
INFO propose{sid=SessionId(4)}:propose_internal{aba_input=One}: adkg::aba::crain20: Node 2 sid `4` decided on estimate `One`
INFO propose{sid=SessionId(4)}:propose_internal{aba_input=One}: adkg::aba::crain20: Node `2` started ABA round 2 estimate=One
INFO adkg::adkg: Node 2 completed ABA with sid 4 and got estimate One
INFO adkg::aba::crain20: Node `2` in ABA with sid `4` stopping recv_thread
INFO propose{sid=SessionId(4)}: adkg::aba::crain20: Node `2` aborting ABA with sid `4`, cause: cancellation token
INFO propose{sid=SessionId(2)}:propose_internal{aba_input=One}: adkg::aba::crain20: Node 2 sid `2` decided on estimate `One`
INFO propose{sid=SessionId(2)}:propose_internal{aba_input=One}: adkg::aba::crain20: Node `2` started ABA round 2 estimate=One
INFO adkg::adkg: Node 2 completed ABA with sid 2 and got estimate One
INFO adkg::aba::crain20: Node `2` in ABA with sid `2` stopping recv_thread
INFO propose{sid=SessionId(2)}: adkg::aba::crain20: Node `2` aborting ABA with sid `2`, cause: cancellation token
INFO propose{sid=SessionId(1)}:propose_internal{aba_input=One}: adkg::aba::crain20: Node 2 sid `1` decided on estimate `One`
INFO propose{sid=SessionId(1)}:propose_internal{aba_input=One}: adkg::aba::crain20: Node `2` started ABA round 2 estimate=One
INFO adkg::adkg: Node 2 completed ABA with sid 1 and got estimate One
INFO propose{sid=SessionId(1)}: adkg::aba::crain20: Node `2` aborting ABA with sid `1`, cause: cancellation token
INFO adkg::aba::crain20: Node `2` in ABA with sid `1` stopping recv_thread
INFO adkg::adkg: ADKG ABA task of node `2` exiting due to all ABAs completed
INFO adkg::adkg: ADKG main thread of node `2` obtained the final list of parties: [SessionId(2), SessionId(3), SessionId(1)]
INFO ACSS::get_share{sid=SessionId(4)}: adkg::vss::acss::hbacss0::handlers: Node `2` received n Ready, ACSS is Complete
INFO ACSS::get_share{sid=SessionId(4)}: adkg::vss::acss::hbacss0: ACSS of node 2 successfully completed.

[CluEleSsUK]

lgtm! The ultimate test is a ceremony though :p

[AnomalRoil]

A few comments