fix bugs

3 files changed, 33 insertions, 13 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