Merge lp:~marcustomlinson/unity-scopes-api/disable_timeouts_in_debug_mode into lp:unity-scopes-api/devel

[Marcus Tomlinson]

Disable process and locate timeouts completely in debug mode

[PS Jenkins bot (ps-jenkins)]

PASSED: Continuous integration, rev:608
http://jenkins.qa.ubuntu.com/job/unity-scopes-api-devel-ci/1483/
Executed test runs:
    SUCCESS: http://jenkins.qa.ubuntu.com/job/unity-scopes-api-devel-wily-amd64-ci/24
    SUCCESS: http://jenkins.qa.ubuntu.com/job/unity-scopes-api-devel-wily-armhf-ci/24
        deb: http://jenkins.qa.ubuntu.com/job/unity-scopes-api-devel-wily-armhf-ci/24/artifact/work/output/*zip*/output.zip
    SUCCESS: http://jenkins.qa.ubuntu.com/job/unity-scopes-api-devel-wily-i386-ci/24

Click here to trigger a rebuild:
http://s-jenkins.ubuntu-ci:8080/job/unity-scopes-api-devel-ci/1483/rebuild

review: Approve (continuous-integration)

[Paweł Stołowski (stolowski)]

102 - auto future = mw_base()->twoway_pool()->submit([&] { return this->invoke_twoway_(request_builder, -1, 30000); });
103 + auto future = mw_base()->twoway_pool()->submit([&] { return this->invoke_twoway_(request_builder, -1, -1); });

This change looks a bit suspicious, is this intended? In full context it is:

    if (!debug_mode_)
    {
        capnp::MallocMessageBuilder request_builder;
        make_request_(request_builder, "debug_mode");

        auto future = mw_base()->twoway_pool()->submit([&] { return this->invoke_twoway_(request_builder, -1, -1); });

Which, if I understand it correctly, means we don't apply timeout when running normally (i.e. not in debug mode)?

review: Needs Information

[Marcus Tomlinson (marcustomlinson)]

> 102 - auto future = mw_base()->twoway_pool()->submit([&] { return
> this->invoke_twoway_(request_builder, -1, 30000); });
> 103 + auto future = mw_base()->twoway_pool()->submit([&] { return
> this->invoke_twoway_(request_builder, -1, -1); });
>
> This change looks a bit suspicious, is this intended? In full context it is:
>
> if (!debug_mode_)
> {
> capnp::MallocMessageBuilder request_builder;
> make_request_(request_builder, "debug_mode");
>
> auto future = mw_base()->twoway_pool()->submit([&] { return
> this->invoke_twoway_(request_builder, -1, -1); });
>
> Which, if I understand it correctly, means we don't apply timeout when running
> normally (i.e. not in debug mode)?

So the timeout we're disabling here is the locate() call that happens implicitly when making any request. It goes:
    1. reg->locate(scope) - first ensure the scope is running
    2. scope->debug_mode() - make the actual request

The issue there is if a scope actually is in debug mode and it takes long to start up, that implicit locate() call will time out prematurely.

In the situation where a scope is not in debug mode but starts up slowly (E.g. has a breakpoint in start()), the registry's own "Process.Timeout" will kick in (which is configured according to the "DebugMode" state of each scope config as they are added). Meaning, that implicit locate() call will actually still timeout due to the registry's "Process.Timeout" constraint when a regular scope takes too long to start.

Make sense?

[lp:~marcustomlinson/unity-scopes-api/disable_timeouts_in_debug_mode]

609. By Marcus Tomlinson on 2015-07-01

Added comment on why we disable locate() timeout on debug_mode request.
Also fixed my mistake of disabling the two-way timeout there aswell (oops).

[Marcus Tomlinson (marcustomlinson)]

> > 102 - auto future = mw_base()->twoway_pool()->submit([&] { return
> > this->invoke_twoway_(request_builder, -1, 30000); });
> > 103 + auto future = mw_base()->twoway_pool()->submit([&] { return
> > this->invoke_twoway_(request_builder, -1, -1); });
> >
> > This change looks a bit suspicious, is this intended? In full context it is:
> >
> > if (!debug_mode_)
> > {
> > capnp::MallocMessageBuilder request_builder;
> > make_request_(request_builder, "debug_mode");
> >
> > auto future = mw_base()->twoway_pool()->submit([&] { return
> > this->invoke_twoway_(request_builder, -1, -1); });
> >
> > Which, if I understand it correctly, means we don't apply timeout when
> running
> > normally (i.e. not in debug mode)?
>
> So the timeout we're disabling here is the locate() call that happens
> implicitly when making any request. It goes:
> 1. reg->locate(scope) - first ensure the scope is running
> 2. scope->debug_mode() - make the actual request
>
> The issue there is if a scope actually is in debug mode and it takes long to
> start up, that implicit locate() call will time out prematurely.
>
> In the situation where a scope is not in debug mode but starts up slowly (E.g.
> has a breakpoint in start()), the registry's own "Process.Timeout" will kick
> in (which is configured according to the "DebugMode" state of each scope
> config as they are added). Meaning, that implicit locate() call will actually
> still timeout due to the registry's "Process.Timeout" constraint when a
> regular scope takes too long to start.
>
> Make sense?

Sorry, that was a little confusing (even to me) :P Add a comment to the code.

[PS Jenkins bot (ps-jenkins)]

PASSED: Continuous integration, rev:609
http://jenkins.qa.ubuntu.com/job/unity-scopes-api-devel-ci/1485/
Executed test runs:
    SUCCESS: http://jenkins.qa.ubuntu.com/job/unity-scopes-api-devel-wily-amd64-ci/26
    SUCCESS: http://jenkins.qa.ubuntu.com/job/unity-scopes-api-devel-wily-armhf-ci/26
        deb: http://jenkins.qa.ubuntu.com/job/unity-scopes-api-devel-wily-armhf-ci/26/artifact/work/output/*zip*/output.zip
    SUCCESS: http://jenkins.qa.ubuntu.com/job/unity-scopes-api-devel-wily-i386-ci/26

Click here to trigger a rebuild:
http://s-jenkins.ubuntu-ci:8080/job/unity-scopes-api-devel-ci/1485/rebuild

review: Approve (continuous-integration)

[Michi Henning (michihenning)]

Looks good to me. Thanks for the comment, that really made a huge difference!

review: Approve

=== modified file 'include/unity/scopes/internal/zmq_middleware/ZmqObjectProxy.h'
--- include/unity/scopes/internal/zmq_middleware/ZmqObjectProxy.h	2015-02-09 02:23:22 +0000
+++ include/unity/scopes/internal/zmq_middleware/ZmqObjectProxy.h	2015-07-01 16:48:22 +0000
@@ -91,8 +91,10 @@
 
     TwowayOutParams invoke_twoway_(capnp::MessageBuilder& request);
     TwowayOutParams invoke_twoway_(capnp::MessageBuilder& request,
+                                   int64_t twoway_timeout);
+    TwowayOutParams invoke_twoway_(capnp::MessageBuilder& request,
                                    int64_t twoway_timeout,
-                                   int64_t locate_timeout = -1);
+                                   int64_t locate_timeout);
 
 private:
     TwowayOutParams invoke_twoway__(capnp::MessageBuilder& request, int64_t timeout);
 
=== modified file 'scoperegistry/scoperegistry.cpp'
--- scoperegistry/scoperegistry.cpp	2015-07-01 10:59:49 +0000
+++ scoperegistry/scoperegistry.cpp	2015-07-01 16:48:22 +0000
@@ -423,10 +423,10 @@
                 scope_dir.filename().native();
     }
 
-    // Check if this scope has requested debug mode, if so, set the process timeout to 30s
+    // Check if this scope has requested debug mode, if so, disable process timeout
     if (sc.debug_mode())
     {
-        exec_data.timeout_ms = 30000;
+        exec_data.timeout_ms = -1;
     }
     else
     {
 
=== modified file 'src/scopes/internal/RegistryObject.cpp'
--- src/scopes/internal/RegistryObject.cpp	2015-04-23 10:11:51 +0000
+++ src/scopes/internal/RegistryObject.cpp	2015-07-01 16:48:22 +0000
@@ -736,9 +736,17 @@
 
 bool RegistryObject::ScopeProcess::wait_for_state(std::unique_lock<std::mutex>& lock, ProcessState state) const
 {
-    return state_change_cond_.wait_for(lock,
-                                       std::chrono::milliseconds(exec_data_.timeout_ms),
-                                       [this, &state]{return state_ == state;});
+    if (exec_data_.timeout_ms == -1)
+    {
+        state_change_cond_.wait(lock, [this, &state]{return state_ == state;});
+        return true;
+    }
+    else
+    {
+        return state_change_cond_.wait_for(lock,
+                                           std::chrono::milliseconds(exec_data_.timeout_ms),
+                                           [this, &state]{return state_ == state;});
+    }
 }
 
 void RegistryObject::ScopeProcess::kill(std::unique_lock<std::mutex>& lock)
 
=== modified file 'src/scopes/internal/zmq_middleware/ZmqObject.cpp'
--- src/scopes/internal/zmq_middleware/ZmqObject.cpp	2015-01-06 01:05:48 +0000
+++ src/scopes/internal/zmq_middleware/ZmqObject.cpp	2015-07-01 16:48:22 +0000
@@ -190,7 +190,13 @@
 
 ZmqObjectProxy::TwowayOutParams ZmqObjectProxy::invoke_twoway_(capnp::MessageBuilder& request)
 {
-    return invoke_twoway_(request, timeout_);
+    return invoke_twoway_(request, timeout_, mw_base()->locate_timeout());
+}
+
+ZmqObjectProxy::TwowayOutParams ZmqObjectProxy::invoke_twoway_(capnp::MessageBuilder& request,
+                                                               int64_t twoway_timeout)
+{
+    return invoke_twoway_(request, twoway_timeout, mw_base()->locate_timeout());
 }
 
 ZmqObjectProxy::TwowayOutParams ZmqObjectProxy::invoke_twoway_(capnp::MessageBuilder& request,
@@ -211,14 +217,8 @@
         try
         {
             ObjectProxy new_proxy;
-            if (locate_timeout != -1)
-            {
-                new_proxy = registry_proxy->locate(identity(), locate_timeout);
-            }
-            else
-            {
-                new_proxy = registry_proxy->locate(identity());
-            }
+            new_proxy = registry_proxy->locate(identity(), locate_timeout);
+
             // update our proxy with the newly received data
             // (we need to first store values in local variables outside of the mutex,
             // otherwise we will deadlock on the following ZmqObjectProxy methods)
 
=== modified file 'src/scopes/internal/zmq_middleware/ZmqScope.cpp'
--- src/scopes/internal/zmq_middleware/ZmqScope.cpp	2015-07-01 10:59:49 +0000
+++ src/scopes/internal/zmq_middleware/ZmqScope.cpp	2015-07-01 16:48:22 +0000
@@ -325,7 +325,18 @@
         capnp::MallocMessageBuilder request_builder;
         make_request_(request_builder, "debug_mode");
 
-        auto future = mw_base()->twoway_pool()->submit([&] { return this->invoke_twoway_(request_builder, -1, 30000); });
+        // When making any two-way request there is an implicit locate() call made to the registry to first ensure that
+        // the scope is actually running - I.e. 1. reg->locate(scope), 2. scope->request().
+
+        // Here we are trying to determine whether the target scope is in debug mode, hence we cannot assume upfront
+        // that it will start up within the regular timeout constraint. Therefore we need to disable the locate()
+        // timeout here to allow enough time for debugged scopes to reply.
+
+        // In the situation where a scope is not in debug mode but starts up slowly, the registry's own
+        // "Process.Timeout" will kick in, meaning that the implicit locate() call will return at a regular timeout for
+        // regular scopes, and will not timeout for debugged scopes.
+
+        auto future = mw_base()->twoway_pool()->submit([&] { return this->invoke_twoway_(request_builder, timeout(), -1); });
         auto out_params = future.get();
         auto response = out_params.reader->getRoot<capnproto::Response>();
         throw_if_runtime_exception(response);
@@ -344,11 +355,10 @@
 
 ZmqObjectProxy::TwowayOutParams ZmqScope::invoke_scope_(capnp::MessageBuilder& in_params, int64_t timeout)
 {
-    // Check if this scope has requested debug mode, if so, disable two-way timeout and set
-    // locate timeout to 30s.
+    // Check if this scope has requested debug mode, if so, disable two-way and locate timeouts.
     if (debug_mode())
     {
-        return this->invoke_twoway_(in_params, -1, 30000);
+        return this->invoke_twoway_(in_params, -1, -1);
     }
     return this->invoke_twoway_(in_params, timeout);
 }