* Fixed wrong error code returned from client_context::before_command

* Fixed raw depends_on assignment from native to wsrep::seqno
* More debug logging

include/wsrep/client_context.hpp

@@ -392,7 +392,7 @@ namespace wsrep
         friend class client_toi_mode;
         friend class transaction_context;
 
-
+        void debug_log_state(const char*) const;
         /*!
          * Set client state.
          */

src/client_context.cpp

@@ -4,6 +4,7 @@
 
 #include "wsrep/client_context.hpp"
 #include "wsrep/compiler.hpp"
+#include "wsrep/logger.hpp"
 
 #include <sstream>
 #include <iostream>
@@ -29,6 +30,7 @@ void wsrep::client_context::override_error(enum wsrep::client_error error)
 int wsrep::client_context::before_command()
 {
     wsrep::unique_lock<wsrep::mutex> lock(mutex_);
+    debug_log_state("before_command: enter");
     assert(state_ == s_idle);
     if (server_context_.rollback_mode() == wsrep::server_context::rm_sync)
     {
@@ -63,6 +65,8 @@ int wsrep::client_context::before_command()
                    wsrep::transaction_context::s_aborted);
             assert(transaction_.active() == false);
             assert(current_error() != wsrep::e_success);
+            debug_log_state("before_command: error");
+            return 1;
         }
         else if (transaction_.state() == wsrep::transaction_context::s_aborted)
         {
@@ -74,15 +78,18 @@ int wsrep::client_context::before_command()
             (void)transaction_.after_statement();
             lock.lock();
             assert(transaction_.active() == false);
+            debug_log_state("before_command: error");
+            return 1;
         }
-        return 1;
     }
+    debug_log_state("before_command: success");
     return 0;
 }
 
 void wsrep::client_context::after_command_before_result()
 {
     wsrep::unique_lock<wsrep::mutex> lock(mutex_);
+    debug_log_state("after_command_before_result: enter");
     assert(state() == s_exec);
     if (transaction_.active() &&
         transaction_.state() == wsrep::transaction_context::s_must_abort)
@@ -96,11 +103,13 @@ void wsrep::client_context::after_command_before_result()
         assert(current_error() != wsrep::e_success);
     }
     state(lock, s_result);
+    debug_log_state("after_command_before_result: leave");
 }
 
 void wsrep::client_context::after_command_after_result()
 {
     wsrep::unique_lock<wsrep::mutex> lock(mutex_);
+    debug_log_state("after_command_after_result_enter");
     assert(state() == s_result);
     assert(transaction_.state() != wsrep::transaction_context::s_aborting);
     if (transaction_.active() &&
@@ -117,11 +126,13 @@ void wsrep::client_context::after_command_after_result()
         current_error_ = wsrep::e_success;
     }
     state(lock, s_idle);
+    debug_log_state("after_command_after_result: leave");
 }
 
 int wsrep::client_context::before_statement()
 {
     wsrep::unique_lock<wsrep::mutex> lock(mutex_);
+    debug_log_state("before_statement: enter");
 #if 0
     /*!
      * \todo It might be beneficial to implement timed wait for
@@ -138,8 +149,10 @@ int wsrep::client_context::before_statement()
         transaction_.state() == wsrep::transaction_context::s_must_abort)
     {
         // Rollback and cleanup will happen in after_command_before_result()
+        debug_log_state("before_statement_error");
         return 1;
     }
+    debug_log_state("before_statement: success");
     return 0;
 }
 
@@ -147,6 +160,7 @@ enum wsrep::client_context::after_statement_result
 wsrep::client_context::after_statement()
 {
     // wsrep::unique_lock<wsrep::mutex> lock(mutex_);
+    debug_log_state("after_statement: enter");
     assert(state() == s_exec);
 #if 0
     /*!
@@ -158,18 +172,32 @@ wsrep::client_context::after_statement()
     {
         if (is_autocommit())
         {
+            debug_log_state("after_statement: may_retry");
             return asr_may_retry;
         }
         else
         {
+            debug_log_state("after_statement: error");
             return asr_error;
         }
     }
+    debug_log_state("after_statement: success");
     return asr_success;
 }
 
 // Private
 
+void wsrep::client_context::debug_log_state(const char* context) const
+{
+    if (debug_log_level() >= 1)
+    {
+        wsrep::log_debug() << "client_context: " << context
+                           << ": server: " << server_context_.name()
+                           << " client: " << id_.get()
+                           << " current_error: " << current_error_;
+    }
+}
+
 void wsrep::client_context::state(
     wsrep::unique_lock<wsrep::mutex>& lock WSREP_UNUSED,
     enum wsrep::client_context::state state)

src/dbms_simulator.cpp

@@ -78,6 +78,7 @@ public:
 
         void start(wsrep::client_context* cc)
         {
+            // wsrep::log_debug() << "Start: " << cc;
             wsrep::unique_lock<wsrep::mutex> lock(se_.mutex_);
             if (se_.transactions_.insert(cc).second == false)
             {
@@ -88,6 +89,7 @@ public:
 
         void commit()
         {
+            // wsrep::log_debug() << "Commit: " << cc_;
             if (cc_)
             {
                 wsrep::unique_lock<wsrep::mutex> lock(se_.mutex_);
@@ -99,6 +101,7 @@ public:
 
         void abort()
         {
+            // wsrep::log_debug() << "Abort: " << cc_;
             if (cc_)
             {
                 wsrep::unique_lock<wsrep::mutex> lock(se_.mutex_);
@@ -133,7 +136,7 @@ public:
                 lock.unlock();
                 if (victim_txc->bf_abort(victim_txc_lock, txc.seqno()))
                 {
-                    wsrep::log() << "BF aborted " << victim_txc->id().get();
+                    // wsrep::log() << "BF aborted " << victim_txc->id().get();
                     ++bf_aborts_;
                 }
             }
@@ -359,9 +362,9 @@ private:
     }
     int rollback() override
     {
-        wsrep::log() << "rollback: " << transaction().id().get()
-                     << "state: "
-                     << wsrep::to_string(transaction().state());
+        // wsrep::log() << "rollback: " << transaction().id().get()
+        //             << "state: "
+        //            << wsrep::to_string(transaction().state());
         before_rollback();
         se_trx_.abort();
         after_rollback();
@@ -371,7 +374,7 @@ private:
     void will_replay(wsrep::transaction_context&) override { }
     int replay(wsrep::transaction_context& txc) override
     {
-        wsrep::log() << "replay: " << txc.id().get();
+        // wsrep::log() << "replay: " << txc.id().get();
         wsrep::client_applier_mode applier_mode(*this);
         ++stats_.replays;
         return provider().replay(txc.ws_handle(), this);
@@ -400,6 +403,7 @@ private:
     int client_command(Func f)
     {
         int err(before_command());
+        // wsrep::log_debug() << "before_command: " << err;
         // If err != 0, transaction was BF aborted while client idle
         if (err == 0)
         {
@@ -413,11 +417,13 @@ private:
         after_command_before_result();
         if (current_error())
         {
+            // wsrep::log_info() << "Current error";
             assert(transaction_.state() ==
                    wsrep::transaction_context::s_aborted);
             err = 1;
         }
         after_command_after_result();
+        // wsrep::log_info() << "client_command(): " << err;
         return err;
     }
 
@@ -427,6 +433,7 @@ private:
         int err = client_command(
             [&]()
             {
+                // wsrep::log_debug() << "Start transaction";
                 err = start_transaction(server_.next_transaction_id());
                 assert(err == 0);
                 se_trx_.start(this);
@@ -435,6 +442,7 @@ private:
         err = err || client_command(
             [&]()
             {
+                // wsrep::log_debug() << "Generate write set";
                 assert(transaction().active());
                 assert(err == 0);
                 int data(std::rand() % 10000000);
@@ -453,6 +461,7 @@ private:
         err = err || client_command(
             [&]()
             {
+                // wsrep::log_debug() << "Commit";
                 assert(err == 0);
                 if (do_2pc())
                 {
@@ -467,8 +476,8 @@ private:
             });
 
         assert(err ||
-            transaction().state() == wsrep::transaction_context::s_aborted ||
-            transaction().state() == wsrep::transaction_context::s_committed);
+               transaction().state() == wsrep::transaction_context::s_aborted ||
+               transaction().state() == wsrep::transaction_context::s_committed);
         assert(se_trx_.active() == false);
         assert(transaction().active() == false);
         switch (transaction().state())

src/transaction_context.cpp

@@ -13,6 +13,13 @@
 #include <sstream>
 #include <memory>
 
+#define WSREP_TC_LOG_DEBUG(level, msg)                  \
+    do {                                                \
+        if (client_context_.debug_log_level() < level)  \
+        { }                                             \
+        else wsrep::log_debug() << msg;                 \
+    } while (0)
+
 // Public
 
 wsrep::transaction_context::transaction_context(
@@ -489,12 +496,13 @@ bool wsrep::transaction_context::bf_abort(
 
     if (active() == false)
     {
-        wsrep::log() << "Transaction not active, skipping bf abort";
+        WSREP_TC_LOG_DEBUG(1, "Transaction not active, skipping bf abort");
     }
     else if (ordered() && seqno() < bf_seqno)
     {
-        wsrep::log() << "Not allowed to BF abort transaction ordered before "
-                     << "aborter: " << seqno() << " < " << bf_seqno;
+        WSREP_TC_LOG_DEBUG(1,
+                           "Not allowed to BF abort transaction ordered before "
+                           << "aborter: " << seqno() << " < " << bf_seqno);
     }
     else
     {
@@ -512,31 +520,26 @@ bool wsrep::transaction_context::bf_abort(
             switch (status)
             {
             case wsrep::provider::success:
-                if (client_context_.debug_log_level() >= 1)
-                {
-                    wsrep::log_debug() << "Seqno " << bf_seqno
-                                       << " succesfully BF aborted " << id_.get()
-                                       << " victim_seqno " << victim_seqno;
-                }
+                WSREP_TC_LOG_DEBUG(1, "Seqno " << bf_seqno
+                                   << " succesfully BF aborted " << id_.get()
+                                   << " victim_seqno " << victim_seqno);
                 bf_abort_state_ = state();
                 state(lock, s_must_abort);
                 ret = true;
                 break;
             default:
-                if (client_context_.debug_log_level() >= 1)
-                {
-                    wsrep::log_debug() << "Seqno " << bf_seqno
-                                       << " failed to BF abort " << id_.get()
-                                       << " with status " << status
-                                       << " victim_seqno " << victim_seqno;
-                }
+                WSREP_TC_LOG_DEBUG(1,
+                                   "Seqno " << bf_seqno
+                                   << " failed to BF abort " << id_.get()
+                                   << " with status " << status
+                                   << " victim_seqno " << victim_seqno);
                 break;
             }
             break;
         }
         default:
-            wsrep::log() << "BF abort not allowed in state "
-                         << wsrep::to_string(state());
+            WSREP_TC_LOG_DEBUG(1, "BF abort not allowed in state "
+                               << wsrep::to_string(state()));
             break;
         }
     }
@@ -604,7 +607,7 @@ void wsrep::transaction_context::state(
         os << "unallowed state transition for transaction "
            << id_.get() << ": " << wsrep::to_string(state_)
            << " -> " << wsrep::to_string(next_state);
-        wsrep::log() << os.str();
+        wsrep::log_error() << os.str();
         throw wsrep::runtime_error(os.str());
     }
 }
@@ -854,14 +857,12 @@ void wsrep::transaction_context::cleanup()
 void wsrep::transaction_context::debug_log_state(
     const char* context) const
 {
-    if (client_context_.debug_log_level() >= 1)
-    {
-        wsrep::log_debug() << context
-                           << ": server: " << client_context_.server_context().name()
-                           << ": client: " << client_context_.id().get()
-                           << " trx: " << int64_t(id_.get())
-                           << " state: " << wsrep::to_string(state_)
-                           << " error: "
-                           << wsrep::to_string(client_context_.current_error());
-    }
+    WSREP_TC_LOG_DEBUG(
+        1, context
+        << ": server: " << client_context_.server_context().name()
+        << " client: " << client_context_.id().get()
+        << " trx: " << int64_t(id_.get())
+        << " state: " << wsrep::to_string(state_)
+        << " error: "
+        << wsrep::to_string(client_context_.current_error()));
 }

src/transaction_context_test.cpp

@@ -141,6 +141,13 @@ BOOST_FIXTURE_TEST_CASE_TEMPLATE(transaction_context_1pc, T,
     BOOST_REQUIRE(tc.id() == wsrep::transaction_id(1));
     BOOST_REQUIRE(tc.state() == wsrep::transaction_context::s_executing);
 
+    // Verify that the commit can be succesfully executed in separate command
+    BOOST_REQUIRE(cc.after_statement() == wsrep::client_context::asr_success);
+    cc.after_command_before_result();
+    cc.after_command_after_result();
+    BOOST_REQUIRE(cc.current_error() == wsrep::e_success);
+    BOOST_REQUIRE(cc.before_command() == 0);
+    BOOST_REQUIRE(cc.before_statement() == 0);
     // Run before commit
     BOOST_REQUIRE(cc.before_commit() == 0);
     BOOST_REQUIRE(tc.state() == wsrep::transaction_context::s_committing);
@@ -940,7 +947,7 @@ BOOST_FIXTURE_TEST_CASE_TEMPLATE(
     cc.after_statement();
     cc.after_command_before_result();
     cc.after_command_after_result();
-    cc.before_command();
+    BOOST_REQUIRE(cc.before_command() == 0);
     BOOST_REQUIRE(tc.active());
     BOOST_REQUIRE(tc.state() == wsrep::transaction_context::s_executing);
     wsrep_test::bf_abort_unordered(cc);

src/wsrep_provider_v26.cpp

@@ -323,7 +323,7 @@ namespace
             wsrep::stid(wsrep::id(meta->stid.node.data,
                                   sizeof(meta->stid.node.data)),
                         meta->stid.trx,
-                        meta->stid.conn), wsrep::seqno(meta->depends_on),
+                        meta->stid.conn), wsrep::seqno(seqno_from_native(meta->depends_on)),
             map_flags_from_native(flags));
         if (ret == WSREP_CB_SUCCESS &&
             client_context->server_context().on_apply(