fix bugs

5 files changed, 55 insertions, 37 deletions

diff --git a/include/hotstuff/entity.h b/include/hotstuff/entity.h
index ce7d9bf..29300a9 100644
--- a/include/hotstuff/entity.h
+++ b/include/hotstuff/entity.h
@@ -224,7 +224,7 @@ class EntityStorage {
     block_t add_blk(Block &&_blk, const ReplicaConfig &config) {
         if (!_blk.verify(config))
         {
-            HOTSTUFF_LOG_WARN("block is invalid");
+            HOTSTUFF_LOG_WARN("invalid %s", std::string(_blk).c_str());
             return nullptr;
         }
         block_t blk = new Block(std::move(_blk));
diff --git a/include/hotstuff/liveness.h b/include/hotstuff/liveness.h
index 3d5a457..0e1103a 100644
--- a/include/hotstuff/liveness.h
+++ b/include/hotstuff/liveness.h
@@ -195,7 +195,7 @@ class PMStickyProposer: virtual public PaceMaker {
     void reset_qc_timer() {
         timer.del();
         timer.add_with_timeout(qc_timeout);
-        HOTSTUFF_LOG_INFO("QC timer reset");
+        HOTSTUFF_LOG_PROTO("QC timer reset");
     }
 
     void clear_promises() {
@@ -223,11 +223,11 @@ class PMStickyProposer: virtual public PaceMaker {
             {
                 if (qc_ref != last_proposed)
                 {
-                    HOTSTUFF_LOG_INFO("proposer misbehave");
+                    HOTSTUFF_LOG_PROTO("proposer misbehave");
                     to_candidate(); /* proposer misbehave */
                 }
             }
-            HOTSTUFF_LOG_INFO("proposer emits new QC");
+            HOTSTUFF_LOG_PROTO("proposer emits new QC");
             last_proposed = prop.blk;
             reset_qc_timer();
         }
@@ -277,13 +277,16 @@ class PMStickyProposer: virtual public PaceMaker {
         (pm_wait_propose = hsc->async_wait_propose()).then([this](const block_t &blk) {
             pm_qc_finish.reject();
             pm_qc_finish = hsc->async_qc_finish(blk).then([this, blk]() {
-                HOTSTUFF_LOG_INFO("collected QC for %s", std::string(*blk).c_str());
+                HOTSTUFF_LOG_PROTO("collected QC for %s", std::string(*blk).c_str());
                 /* managed to collect a QC */
                 to_proposer();
                 gen();
             });
         });
-        reset_qc_timer();
+        double t = salticidae::gen_rand_timeout(candidate_timeout);
+        timer.del();
+        timer.add_with_timeout(t);
+        HOTSTUFF_LOG_PROTO("candidate next try in %.2fs", t);
         gen();
     }
 
@@ -298,7 +301,7 @@ class PMStickyProposer: virtual public PaceMaker {
     void candidate_receive_proposal(const Proposal &prop) {
         auto proposer = prop.proposer;
         auto &p = last_proposed_by[proposer];
-        HOTSTUFF_LOG_INFO("got block %s from %d", std::string(*prop.blk).c_str(), proposer);
+        HOTSTUFF_LOG_PROTO("got block %s from %d", std::string(*prop.blk).c_str(), proposer);
         p.reject();
         p = hsc->async_qc_finish(prop.blk).then([this, proposer]() {
             to_follower(proposer);
@@ -307,7 +310,7 @@ class PMStickyProposer: virtual public PaceMaker {
     }
 
     void to_follower(ReplicaID new_proposer) {
-        HOTSTUFF_LOG_INFO("new role: follower");
+        HOTSTUFF_LOG_PROTO("new role: follower");
         clear_promises();
         role = FOLLOWER;
         proposer = new_proposer;
@@ -326,7 +329,7 @@ class PMStickyProposer: virtual public PaceMaker {
     }
 
     void to_proposer() {
-        HOTSTUFF_LOG_INFO("new role: proposer");
+        HOTSTUFF_LOG_PROTO("new role: proposer");
         clear_promises();
         role = PROPOSER;
         proposer = hsc->get_id();
@@ -335,13 +338,12 @@ class PMStickyProposer: virtual public PaceMaker {
             /* proposer unable to get a QC in time */
             to_candidate();
         });
-        reset_qc_timer();
-        /* prepare the variables for the role of a proposer */
         proposer_propose(hsc->get_genesis());
+        reset_qc_timer();
     }
 
     void to_candidate() {
-        HOTSTUFF_LOG_INFO("new role: candidate");
+        HOTSTUFF_LOG_PROTO("new role: candidate");
         clear_promises();
         role = CANDIDATE;
         proposer = hsc->get_id();
@@ -350,8 +352,8 @@ class PMStickyProposer: virtual public PaceMaker {
             candidate_qc_timeout();
         });
         candidate_timeout = qc_timeout;
-        timer.add_with_timeout(salticidae::gen_rand_timeout(candidate_timeout));
         reg_candidate_receive_proposal();
+        candidate_qc_timeout();
     }
 
     public:
diff --git a/include/hotstuff/util.h b/include/hotstuff/util.h
index 99b5ea4..25dda70 100644
--- a/include/hotstuff/util.h
+++ b/include/hotstuff/util.h
@@ -9,13 +9,25 @@ namespace hotstuff {
 class Logger: public salticidae::Logger {
     public:
     using salticidae::Logger::Logger;
+
+    void proto(const char *fmt, ...) {
+        va_list ap;
+        va_start(ap, fmt);
+        write("proto", fmt, ap);
+        va_end(ap);
+    }
 };
 
 extern Logger logger;
 
+#ifdef HOTSTUFF_PROTO_LOG
+#define HOTSTUFF_ENABLE_LOG_PROTO
+#endif
+
 #ifdef HOTSTUFF_DEBUG_LOG
 #define HOTSTUFF_NORMAL_LOG
 #define HOTSTUFF_ENABLE_LOG_DEBUG
+#define HOTSTUFF_ENABLE_LOG_PROTO
 #endif
 
 #ifdef HOTSTUFF_NORMAL_LOG
@@ -41,6 +53,12 @@ extern Logger logger;
 #define HOTSTUFF_LOG_WARN(...) ((void)0)
 #endif
 
+#ifdef HOTSTUFF_ENABLE_LOG_PROTO
+#define HOTSTUFF_LOG_PROTO(...) hotstuff::logger.proto(__VA_ARGS__)
+#else
+#define HOTSTUFF_LOG_PROTO(...) ((void)0)
+#endif
+
 #define HOTSTUFF_LOG_ERROR(...) hotstuff::logger.error(__VA_ARGS__)
 
 #ifdef HOTSTUFF_BLK_PROFILE
diff --git a/src/consensus.cpp b/src/consensus.cpp
index 58c0f31..66ce05c 100644
--- a/src/consensus.cpp
+++ b/src/consensus.cpp
@@ -7,6 +7,7 @@
 #define LOG_INFO HOTSTUFF_LOG_INFO
 #define LOG_DEBUG HOTSTUFF_LOG_DEBUG
 #define LOG_WARN HOTSTUFF_LOG_WARN
+#define LOG_PROTO HOTSTUFF_LOG_PROTO
 
 namespace hotstuff {
 
@@ -88,9 +89,7 @@ void HotStuffCore::check_commit(const block_t &_blk) {
     {
         const block_t &blk = *it;
         blk->decision = 1;
-#ifdef HOTSTUFF_PROTO_LOG
-        LOG_INFO("commit %s", std::string(*blk).c_str());
-#endif
+        LOG_PROTO("commit %s", std::string(*blk).c_str());
         size_t idx = 0;
         for (auto cmd: blk->cmds)
             do_decide(Finality(id, 1, idx, blk->height,
@@ -137,9 +136,7 @@ void HotStuffCore::on_propose(const std::vector<command_t> &cmds,
     on_deliver_blk(bnew);
     update(bnew_hash);
     Proposal prop(id, bqc->get_hash(), bnew, nullptr);
-#ifdef HOTSTUFF_PROTO_LOG
-    LOG_INFO("propose %s", std::string(*bnew).c_str());
-#endif
+    LOG_PROTO("propose %s", std::string(*bnew).c_str());
     /* self-vote */
     on_receive_vote(
         Vote(id, bqc->get_hash(), bnew_hash,
@@ -151,9 +148,7 @@ void HotStuffCore::on_propose(const std::vector<command_t> &cmds,
 
 void HotStuffCore::on_receive_proposal(const Proposal &prop) {
     if (!update(prop.bqc_hash)) return;
-#ifdef HOTSTUFF_PROTO_LOG
-    LOG_INFO("got %s", std::string(prop).c_str());
-#endif
+    LOG_PROTO("got %s", std::string(prop).c_str());
     block_t bnew = prop.blk;
     sanity_check_delivered(bnew);
     bool opinion = false;
@@ -170,10 +165,9 @@ void HotStuffCore::on_receive_proposal(const Proposal &prop) {
             vheight = bnew->height;
         }
     }
-#ifdef HOTSTUFF_PROTO_LOG
-    LOG_INFO("now state: %s", std::string(*this).c_str());
-#endif
-    if (bnew->qc_ref) on_qc_finish(bnew->qc_ref);
+    LOG_PROTO("now state: %s", std::string(*this).c_str());
+    if (bnew->qc_ref)
+        on_qc_finish(bnew->qc_ref);
     on_receive_proposal_(prop);
     do_vote(prop.proposer,
         Vote(id,
@@ -187,10 +181,8 @@ void HotStuffCore::on_receive_proposal(const Proposal &prop) {
 
 void HotStuffCore::on_receive_vote(const Vote &vote) {
     if (!update(vote.bqc_hash)) return;
-#ifdef HOTSTUFF_PROTO_LOG
-    LOG_INFO("got %s", std::string(vote).c_str());
-    LOG_INFO("now state: %s", std::string(*this).c_str());
-#endif
+    LOG_PROTO("got %s", std::string(vote).c_str());
+    LOG_PROTO("now state: %s", std::string(*this).c_str());
     block_t blk = get_delivered_blk(vote.blk_hash);
     if (vote.cert == nullptr) return;
     /* otherwise the vote is positive */
diff --git a/src/hotstuff.cpp b/src/hotstuff.cpp
index 04b31f8..3626f9d 100644
--- a/src/hotstuff.cpp
+++ b/src/hotstuff.cpp
@@ -57,17 +57,17 @@ void MsgRespBlock::postponed_parse(HotStuffCore *hsc) {
     }
 }
 
+// TODO: improve this function
 promise_t HotStuffBase::exec_command(command_t cmd) {
     const uint256_t &cmd_hash = cmd->get_hash();
     ReplicaID proposer = pmaker->get_proposer();
-    /* not the proposer */
+
     if (proposer != get_id())
         return promise_t([proposer, cmd_hash](promise_t &pm) {
             pm.resolve(Finality(proposer, -1, 0, 0,
                                 cmd_hash, uint256_t()));
         });
 
-
     auto it = decision_waiting.find(cmd_hash);
     if (it == decision_waiting.end())
     {
@@ -87,10 +87,16 @@ promise_t HotStuffBase::exec_command(command_t cmd) {
             if (proposer != get_id())
             {
                 for (auto &cmd: cmds)
-                    decision_waiting
-                        .at(cmd->get_hash())
-                        .resolve(Finality(proposer, -1, 0, 0,
-                                        cmd->get_hash(), uint256_t()));
+                {
+                    const auto &cmd_hash = cmd->get_hash();
+                    auto it = decision_waiting.find(cmd_hash);
+                    if (it != decision_waiting.end())
+                    {
+                        it->second.resolve(Finality(proposer, -1, 0, 0,
+                                                    cmd_hash, uint256_t()));
+                        decision_waiting.erase(it);
+                    }
+                }
             }
             else
                 on_propose(cmds, pmaker->get_parents());
@@ -437,8 +443,8 @@ void HotStuffBase::start(bool eb_loop) {
     uint32_t nfaulty = pn.all_peers().size() / 3;
     if (nfaulty == 0)
         LOG_WARN("too few replicas in the system to tolerate any failure");
-    pmaker->init(this);
     on_init(nfaulty);
+    pmaker->init(this);
     if (eb_loop)
         eb.dispatch();
 }