Fix for cleos and keosd race condition #8671

allenhan2 · 2020-02-20T22:29:42Z

Change Description

issue: #8614
When keosd is not running, cleos will start keosd, then immediately try to connect to its socket, then fails because wallet_api has not started yet right after http port starts taking incoming traffic.

The fix is to let http_plugin startup yield to others' (including wallet api) startup finish.

Consensus Changes

Consensus Changes

API Changes

API Changes

Documentation Additions

Documentation Additions

swatanabe-b1

I think a better approach would be something like Matt's old PR #5705.
You can avoid the issues with threading that he mentioned with something along these lines:

open a pipe
fork
3.1) in the child, start appbase, then close the pipe.
3.2) in the parent, wait on the pipe for EOF and then exit.

swatanabe-b1 · 2020-02-20T22:47:13Z

programs/cleos/main.cpp

-            try_local_port(2000);
+
+            std::string keos_msg;
+            constexpr size_t TOTOAL_RETRIES = 10;


swatanabe-b1 · 2020-02-20T22:47:47Z

programs/cleos/main.cpp

+            for(; tries<TOTOAL_RETRIES; ++tries)
+            {
+               std::this_thread::sleep_for(std::chrono::milliseconds(KEOS_WAIT_TIME_MS));
+               std::getline(keos_out, keos_msg);


getline is blocking. There's no need to wait.

It behaves as syncing, if keosd returns -1 before (daemonizing) sending "keosd::config::keosd_started_msg", pstream will make getline return immediately. Then, cleos knows that retry fails, print out err msg, then move on, no wait.

if keosd is already there before cleos runs, cleos won't wait. Otherwise, cleos starts keosd, and wait for keosd finishing startup (right before daemonizing). For any reason, if keosd hangs within startup, cleos will hang there too.

If cleos should run independently from keosd, then correct, will change to non-block read instead.

The new approach is making http_plug startup yield to wallet-api startup. So, no change here.

allenhan2 · 2020-02-21T03:12:53Z

The problem seems to me is that the cleos does not know when keosd finishes startup (before daemonizing). not sure why using fork and pipe helps sync the state.

current pstream is the wrapper around pipe between parent and child. Using async read will make cleos and keosd independent.

swatanabe-b1 · 2020-02-21T14:15:24Z

The problem seems to me is that the cleos does not know when keosd finishes startup (before daemonizing). not sure why using fork and pipe helps sync the state.

Did you look at #5705? I meant to use fork at startup in keosd.

current pstream is the wrapper around pipe between parent and child. Using async read will make cleos and keosd independent.

You shouldn't abuse stdout for this synchronization. keosd may write other things to stdout and will break if it's a pipe whose other end is closed instead of /dev/null.

allenhan2 · 2020-02-21T14:24:27Z

thanks steve, only saw matt's issue description but did not see his PR. understand what you mean now.

allenhan2 · 2020-02-21T16:40:25Z

chatted with @spoonincode, and suggestion is focusing on why it is broken and not before, could be related to some subtle asio priority issue. At the same time, chatted with @swatanabe-b1, and could be the issue is always there. I will do more research on this before further action.

allenhan2 · 2020-02-25T02:14:27Z

From code, the issue is cleos thinks keosd is ready when http port is pingable. But, very often wallet api has not finished loading yet when port is pingable.
Since I can not pass the logging setting from cleos -> keos ->http_plugin->wallet api loading, I can not verify my theory.
However, it helps cleos to sync with keosd state by adding signal sync. It is minimal change to make cleos and keosd working.
The syncing issue is application level, need to refactor and test across all applications in the future.

heifner

I'll let Steven comment on approach. These are mainly style comments.

heifner · 2020-02-25T02:35:45Z

programs/cleos/CLI11.hpp

+      static constexpr uint32_t WAIT_DURATION_MS = 8000;
+   };
+}  // cleos
+}  // eosio


This should not go in this file. This file is copied from an open source project.

heifner · 2020-02-25T02:36:20Z

programs/cleos/main.cpp

+           if (!cleos::KeosdSignalHndl::wait_keosd_start())
+           {
+              std::cerr << "Failed to launch " << binPath << std::endl;
+           }
        } else {


Follow code style found in files you modify.

heifner · 2020-02-25T02:36:56Z

programs/cleos/main.cpp

@@ -77,6 +77,7 @@ Usage: ./cleos create account [OPTIONS] creator name OwnerKey ActiveKey
 #include <fc/exception/exception.hpp>
 #include <fc/variant_object.hpp>
 #include <fc/static_variant.hpp>
+#include <thread>


include not needed.

heifner · 2020-02-25T02:42:16Z

programs/keosd/main.cpp

@@ -43,12 +60,23 @@ int main(int argc, char** argv)
         .default_unix_socket_path = keosd::config::key_store_executable_name + ".sock",
         .default_http_port = 0
      });
+      const int parent_id = get_parent_pid(argc, argv);
+      const int argc_no_parent_id = (parent_id > 0) ? argc - 2 : argc;
+      char** const argv_no_parent_id = (parent_id > 0) ? &argv[2] : argv;


This seems very fragile. What if it is not the first argument?

heifner · 2020-02-25T02:42:54Z

programs/keosd/main.cpp

+      {
+         break;
+      }
+   }


Use consistent code style found used in files you modify.

heifner · 2020-02-25T02:44:41Z

programs/cleos/CLI11.hpp

+
+namespace eosio {
+   namespace cleos {
+   struct KeosdSignalHndl {


Use snake case for all struct/classes. Follow code style found in existing code.

heifner · 2020-02-25T02:46:04Z

programs/cleos/CLI11.hpp

+         return (ready_signal_received == KEOSD_READY);
+      }
+      static state ready_signal_received;
+      static constexpr uint32_t WAIT_DURATION_MS = 8000;


All caps is used for macros not constants.

heifner · 2020-02-25T02:46:21Z

programs/cleos/CLI11.hpp

+namespace eosio {
+   namespace cleos {
+   struct KeosdSignalHndl {
+      enum state : size_t


Use enum class

heifner · 2020-02-25T02:46:31Z

programs/cleos/CLI11.hpp

+      enum state : size_t
+      {
+         KEOSD_NOT_READY = 0,
+         KEOSD_READY = 1


Do not use all caps for constants

heifner · 2020-02-25T02:47:06Z

programs/cleos/CLI11.hpp

+         }
+         return (ready_signal_received == KEOSD_READY);
+      }
+      static state ready_signal_received;


init variable

spoonincode · 2020-02-25T04:05:48Z

The current approach, as cheesy at it is, has worked correctly in the past. From a quick code review, I am a little suspicious that the http thread pool may have introduced this problem. The thread_pool starts event handling immediately, so when the HTTP server starts listening in http_pligin::plugin_startup() it is able to service incoming requests immediately. However, it's not until wallet_api_plugin::plugin_startup() that the wallet endpoints are registered. I'm pretty sure http_plugin startup will always run before wallet_api_plugin::plugin_startup(), so it's ready to serve requests before wallet endpoints are registered.

Previously back when there was no http thread pool, the event loop http plugin was using wouldn't have been pumped until all the plugin startup()s had been called.

I wonder if we simply moved the add_api() calls in wallet_api's startup to wallet_api's initialize if everything would be fixed? It's a little icky because I think it means the wallet plugin may be sent requests before wallet's startup()....... but the wallet plugin doesn't have a startup() so I don't think we'd run afoul of anything at the moment?

Though, fwiw, I'm much in favor of a better startup solution. But the approach in this PR and the previous daemonization approach I did don't support win32. That's something that in my opinion we need to be mindful about.

spoonincode · 2020-02-25T14:21:45Z

Well, if the above theory is really the problem, probably having http_plugin post() its startup routine to the main thread event loop is even better.

allenhan2 · 2020-02-25T14:31:59Z

@spoonincode made a quick try, your theory works. Let me see how to make the http_plugin post()

swatanabe-b1 · 2020-02-25T14:33:31Z

programs/cleos/CLI11.hpp

+      }
+
+      static void handle_keosd_start_signal(int) {
+         ready_signal_received = KEOSD_READY;


This causes a data race. See [intro.races]
"Two actions are potentially concurrent if... they are unsequenced, at least one is performed by a signal handler, and they are not both performed by the same signal handler invocation."

"The execution of a program contains a data race if it contains two potentially concurrent conflicting actions, at least one of which is not atomic, and neither happens before the other..."

Cool, thanks, it is good reading.

swatanabe-b1 · 2020-02-25T14:38:23Z

programs/keosd/main.cpp

+
+      if (parent_id > 0)
+      {
+         const int ret_sig_que = kill(parent_id, SIGUSR1);


What happens if the parent has already exited?
What happens if keosd initialization fails (e.g. someone else launched keosd concurrently).

allenhan2 · 2020-02-25T20:38:24Z

Added post to delay the threadpool and related port initialization in http_plugin's startup. If any exception during delayed initialization, shutdown the app. Tested on my mac desktop, seems working well. Please let me know any other tests or test cases.
thanks, @spoonincode @swatanabe-b1 @heifner

heifner · 2020-02-26T12:53:50Z

plugins/http_plugin/http_plugin.cpp

-      if(my->listen_endpoint) {
+      app().post(appbase::priority::high, [this] ()
+      {
+         my->thread_pool.emplace( "http", my->thread_pool_size );


This should be moved into the try-catch.

The new approach is to make http start_up yield to wallet api start_up, no change on cleos side

allenhan2 · 2020-02-26T16:34:30Z

@swatanabe-b1 could you please help to give a review of this new approach. @heifner asks your review on the approach (even it was for the previous one),
BTW, dismissed your comments on the old approach though.
thanks!

These changes were supposed to fix the problem of keosd auto-start by cleos, which manifests itself in the following error message: $ ./programs/cleos/cleos wallet list .../programs/keosd/keosd" launched Unable to connect to keosd, if keosd is running please kill the ...process and try again. I cannot confirm that the fix works, but the patch from #8671 is applied verbatim without conflicts.

allenhan2 added 2 commits February 20, 2020 17:05

Fix for cleos and keosd race condition

897bf86

add terminate after all tries failed

7c7a39b

swatanabe-b1 previously requested changes Feb 20, 2020

View reviewed changes

Using signal to sync when keosd is ready

475d54d

heifner suggested changes Feb 25, 2020

View reviewed changes

swatanabe-b1 reviewed Feb 25, 2020

View reviewed changes

allenhan2 added 2 commits February 25, 2020 15:28

Delay http plugin startup and revert sync change between cleos and keos

b854280

add missing logging back

a396a87

heifner reviewed Feb 26, 2020

View reviewed changes

include all actions in try-catch

9cafb7c

swatanabe-b1 approved these changes Feb 26, 2020

View reviewed changes

spoonincode approved these changes Feb 26, 2020

View reviewed changes

heifner approved these changes Mar 2, 2020

View reviewed changes

allenhan2 merged commit a58e485 into develop Mar 2, 2020

allenhan2 deleted the cleos_keods_race branch March 2, 2020 19:50

allenhan2 mentioned this pull request Mar 2, 2020

cleos/keosd race condition #8614

Closed

revl mentioned this pull request May 8, 2020

Fix for cleos and keosd race condition - 2.0 #9065

Merged

3 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix for cleos and keosd race condition #8671

Fix for cleos and keosd race condition #8671

allenhan2 commented Feb 20, 2020 •

edited

Loading

swatanabe-b1 left a comment

swatanabe-b1 Feb 20, 2020

swatanabe-b1 Feb 20, 2020

allenhan2 Feb 21, 2020 •

edited

Loading

allenhan2 Feb 26, 2020

allenhan2 commented Feb 21, 2020

swatanabe-b1 commented Feb 21, 2020

allenhan2 commented Feb 21, 2020

allenhan2 commented Feb 21, 2020 •

edited

Loading

allenhan2 commented Feb 25, 2020

heifner left a comment

heifner Feb 25, 2020

heifner Feb 25, 2020

heifner Feb 25, 2020

heifner Feb 25, 2020

heifner Feb 25, 2020

heifner Feb 25, 2020

heifner Feb 25, 2020

heifner Feb 25, 2020

heifner Feb 25, 2020

heifner Feb 25, 2020

spoonincode commented Feb 25, 2020

spoonincode commented Feb 25, 2020

allenhan2 commented Feb 25, 2020

swatanabe-b1 Feb 25, 2020

allenhan2 Feb 26, 2020

swatanabe-b1 Feb 25, 2020

allenhan2 commented Feb 25, 2020

heifner Feb 26, 2020

allenhan2 Feb 26, 2020

allenhan2 commented Feb 26, 2020

Fix for cleos and keosd race condition #8671

Fix for cleos and keosd race condition #8671

Conversation

allenhan2 commented Feb 20, 2020 • edited Loading

Change Description

Consensus Changes

API Changes

Documentation Additions

swatanabe-b1 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

allenhan2 Feb 21, 2020 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

allenhan2 commented Feb 21, 2020

swatanabe-b1 commented Feb 21, 2020

allenhan2 commented Feb 21, 2020

allenhan2 commented Feb 21, 2020 • edited Loading

allenhan2 commented Feb 25, 2020

heifner left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

spoonincode commented Feb 25, 2020

spoonincode commented Feb 25, 2020

allenhan2 commented Feb 25, 2020

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

allenhan2 commented Feb 25, 2020

Choose a reason for hiding this comment

Choose a reason for hiding this comment

allenhan2 commented Feb 26, 2020

allenhan2 commented Feb 20, 2020 •

edited

Loading

allenhan2 Feb 21, 2020 •

edited

Loading

allenhan2 commented Feb 21, 2020 •

edited

Loading