Archived

This forum has been archived. Please start a new discussion on GitHub.

Ice.Context Javascript for Glacier2 Router

janos
janos Germany
edited August 2016 in Help Center

Hi there,

I have implemented from the docs a custom replication group filter. I wanted to do the first tests, but the filter doesn't get called with the context, only after the SessionManager created it's session. I'd like to select (pre-filter) the SessionManager from the Replica Group, to decide where to create the session.

I am referring to these sections from the docs:
https://doc.zeroc.com/display/Ice36/Load+Balancing#LoadBalancing-ImplementingaCustomReplicaGroupFilter
https://doc.zeroc.com/display/Ice36/IceGrid+and+Glacier2+Integration#IceGridandGlacier2Integration-UsingReplicatedSessionManagers.

I have the same implemented an implicit context in my javascript client as:

var id = new Ice.InitializationData();
id.properties = Ice.createProperties();
id.properties.setProperty("Ice.Default.Router", getRouterProxyAddress(datacenter));

communicator = Ice.initialize(id);
var implicitContext = communicator.getImplicitContext();
implicitContext.put("Region", region);

return Glacier2.RouterPrx.checkedCast(communicator.getDefaultRouter());

So far so good. The Context is being parsed and sent along with the requests, after the session has been created. For selecting the appropriate SessionManager from the replica group, I need the RegistryPlugin to be called before, which does get called, except without the Context.

RegistryPlugin stdout:

Glacier2 Ice Log:

I even tried to set the context on the router explicitly before creating the session.

routerContext = new Ice.Context();
routerContext.add("Region", region);

var router = routerPrx.ice_context(routerContext);

// create a session with the router
var sessionPrx = router.createSession("username", "password");

This results in having my context to double up.

What's confusing is, that the replicated SessionManager does receive the context, for the create operation:

I'd like to pick the appropriate SessionManager based on the context before the adapter is selected from the replicate group. How can I achieve that?

Thanks in advance!

Janos

Comments

  • benoit
    benoit Rennes, France

    Hi Janos,

    There's no way at present to achieve this. The context set on the router proxy for the createSession invocation is not transmitted by Glacier2 to the Ice locator findAdapterById call sent by Glacier2 to IceGrid to find the adapter of the session manager.

    One way to achieve this would be to implement a session manager which would just act as a forwarder for the real session manager. This session manager would get the createSession call with the context. It would then create a proxy on the replicated session manger with a locator proxy which has the correct context set and invoke createSession on it.

    See the IceGrid/customLoadBalancing demo for an example on how to set a context on the locator proxy (either through configuration or programmatically).

    Cheers,
    Benoit.

  • janos
    janos Germany

    Hi Benoit,

    thanks for the detailed description. If I understand you correctly, you mean something like this:
    On the server side:

    public class RoutingSessionManagerImpl extends _SessionManagerDisp {
    
        @Override
        public SessionPrx create(String userId, SessionControlPrx control, Current __current) throws CannotCreateSessionException {
            return Glacier2.SessionPrxHelper.uncheckedCast(__current.adapter.addWithUUID(new RoutingSessionImpl()));
        }
    }
    
    public class RoutingSessionImpl extends _SessionDisp {
    
        @Override
        public RegionalSessionManager createRegionalSessionManager(Current __current) {
            // Context contains Region information, so it will be forwarded
            return RegionalSessionManager.uncheckedCast(__current.adapter.getCommunicator().stringToProxy("RegionalSessionManager@ReplicaGroup"));
        }
    
        @Override
        public void destroy(Current __current) {
    
        }
    }
    
    public class RegionalSessionManagerImpl extends _SessionManagerDisp {
    
        @Override
        public SessionPrx create(String userId, SessionControlPrx control, Current __current) throws CannotCreateSessionException {
            RegionalSessionImpl session = new RegionalSessionImpl();
    
            // store and initialize session at backend
    
            return RegionalSessionManagerPrxHelper.uncheckedCast(__current.adapter.addWithUUID(session));
        }
    }
    
    public class RegionalSessionImpl extends _SessionDisp {
    
        @Override
        public void destroy(Current __current) {
            // dispose of initialized session related objects at backend
        }
    
        // my session interface methods
        @Override
        public void myCustomMethod(Current __current) {
    
        }
    }
    

    Slice:

    interface RoutingSession extends Glacier2::Session {
        RegionalSessionManager createRegionalSessionManager();
    };
    
    interface RegionalSession extends Glacier2::Session {
        void myCustomMethod();
    };
    

    On the client side (pseudo):

    var id = new Ice.InitializationData();
    id.properties = Ice.createProperties();
    id.properties.setProperty("Ice.Default.Router", getRouterProxyAddress(datacenter));
    
    communicator = Ice.initialize(id);
    var implicitContext = communicator.getImplicitContext();
    implicitContext.put("Region", region);
    
    var router = Glacier2.RouterPrx.checkedCast(communicator.getDefaultRouter());
    
    var session = RoutingSessionPrx.uncheckedCast(router.createSession("username", "password"));
    
    var concreteManager = session.createRegionalSessionManager(); // on proxy call connection will be established including the context of the default locator/router
    var rsession = concreteManager.create();
    
    // now ready to handle session
    rsession.myCustomMethod();
    

    The part with the creation of the second sessionmanager seems not so clear to me. What should the server return within the RoutingSession?

    Kind regards
    Janos

  • benoit
    benoit Rennes, France
    edited August 2016

    Hi,

    I meant something simpler actually. No need for new Slice interfaces or client side changes.

    You just need an additional session manager object that forwards the create call to the regional session manager:

    public class RoutingSessionManagerImpl extends _SessionManagerDisp 
    {
        @Override
        public SessionPrx create(String userId, SessionControlPrx control, Current current) 
            throws CannotCreateSessionException 
        {
            Ice.Communicator com = current.adapter.getCommunicator();
            Ice.LocatorPrx locator = (Ice.LocatorPrx)com.getDefaultLocator();
            Ice.ObjectPrx regional = com.stringToProxy("RegionalSessionManager@ReplicaGroup");
    
            //
            // Use a locator with this call's context to resolve the replica group endpoints 
            // using the "Region" context provided by the client.
            //
            regional = regional.ice_locator((Ice.LocatorPrx)locator.ice_context(current.ctx));
    
            return SessionManagerPrx.uncheckedCast(regional).create(userId, control);
        }
    }
    

    Glacier2 configured session manager proxy should point to this session manager object instead of the regional session manager.

    Cheers,
    Benoit.

  • janos
    janos Germany

    Hi,

    that's actually an amazing solution! Implementing that I can route the creation of the proxy to I'm doing something definitely wrong, with one of the configs. The session does get created via the router SessionManager and I can confirm the context being used for the locator.

    DEBUG com...RoutingSessionManagerI:29 - Routing creation of session to 'RegionalSessionManager@ReplicaGroup' with Region: 'LOCAL'
    DEBUG com....RoutingSessionManagerI:36 - RegionalSessionManager created.
    DEBUG com....RoutingSessionManagerI:37 - Locator's context on RegionalSessionManager for Region: LOCAL
    DEBUG com....RegionalSessionManagerI:26 - Creating session proxy with UUID: bbf753ce-411e-4084-81cf-f10af8ae2b08
    INFO  com....ClientManager:42 - Registering session with id: bbf753ce-411e-4084-81cf-f10af8ae2b08 for user.
    

    The session is being created even if the target Region's server/adapter is not active. I looked up the registry log and found that the RegistryPlugin doesn't get called on resolving the proxy, rather ever so randomly, regardless of the requests on the replica group (e.g. in the log below there's no entry for the create session made at 08:22 or 08:55):

    07:54:38 PM CEST filtering... Region context property was not found in request context
    07:55:31 PM CEST filtering... Region context property was not found in request context
    07:58:37 PM CEST filtering... Region context property was not found in request context
    08:37:21 PM CEST filtering... Region context property was not found in request context
    08:50:58 PM CEST filtering... Region context property was not found in request context
    09:05:40 PM CEST filtering... Region context property was not found in request context
    09:05:40 PM CEST filtering... Region context property was not found in request context
    09:06:16 PM CEST filtering... Region context property was not found in request context
    09:08:22 PM CEST filtering... Region context property was not found in request context
    
    1. This is the Glacier2 Template I use. (Interestingly as I exported from IceGridAdminGUI, I noticed that the filter doesn't show up in the file, but exists within the GUI. Does it get removed on export or is it a bug? Is this the reason why the RegistryPlugin is not getting called?
    <replica-group id="Backends">
             <description>Development Environment access to Backend Provider and Sessions</description>
             <load-balancing type="adaptive" load-sample="1" n-replicas="0"/>
             <object identity="${application}.PermissionVerifier"/>
             <object identity="${application}.RoutingSessionManager"/>
             <object identity="${application}.RegionalSessionManager"/>
    </replica-group>
    <server-template id="Glacier2">
             <parameter name="instance-name" default="${application}.Glacier2"/>
             <parameter name="client-endpoints"/>
             <parameter name="server-endpoints"/>
             <parameter name="session-timeout" default="0"/>
             <server id="${instance-name}" activation="always" application-distrib="false" exe="glacier2router">
                <properties>
                   <property name="Glacier2.Client.Endpoints" value="${client-endpoints}"/>
                   <property name="Glacier2.Server.Endpoints" value="${server-endpoints}"/>
                   <property name="Glacier2.InstanceName" value="${instance-name}"/>
                   <property name="Glacier2.SessionTimeout" value="${session-timeout}"/>
                   <property name="Glacier2.Client.ForwardContext" value="1"/>
                   <property name="Ice.Default.Locator" value="IceGrid/Locator:tcp -h hostname -p port"/>
                   <property name="Glacier2.SessionManager" value="${application}.RoutingSessionManager@Backends"/>
                   <property name="Glacier2.PermissionsVerifier" value="${application}.PermissionVerifier@Backends"/>
                   <property name="Glacier2.SessionManager.LocatorCacheTimeout" value="0"/>
                   <property name="Glacier2.SSLSessionManager.LocatorCacheTimeout" value="0"/>
                   <property name="Ice.StdErr" value="${node.datadir}/router_err.txt"/>
                   <property name="Ice.StdOut" value="${node.datadir}/router_out.txt"/>
                   <property name="Ice.Trace.Slicing" value="1"/>
                   <property name="Ice.Trace.Retry" value="1"/>
                   <property name="Ice.Trace.Protocol" value="1"/>
                   <property name="Ice.Trace.Network" value="1"/>
                   <property name="Ice.Trace.Locator" value="1"/>
                   <property name="Ice.Trace.Admin" value="1"/>
                   <property name="Ice.Trace.Admin.Properties" value="1"/>
                   <property name="Ice.Trace.Admin.Logger" value="1"/>
                   <property name="Ice.Trace.Threadpool" value="1"/>
                </properties>
             </server>
          </server-template>
    
    1. And the last issue I see with this is that despite the IceGrid.Registry.DynamicRegistration=1 property, the IceGridAdminGUI doesn't show the dynamically registered object adapter - if I start it in my IDE (it does register successfully). Or is this something what is only a GUI issue?
    INFO  com....Provider:108 - Registered ObjectAdapter with name: AppD.Provider-1
    DEBUG com....Provider:109 - Registered PermissionVerifierI with name: AppD.PermissionVerifier
    DEBUG com....Provider:110 - Registered RoutingSessionManagerI with name: AppD.RoutingSessionManager
    DEBUG com....Provider:111 - Registered RegionalSessionManagerI with name: AppD.RegionalSessionManager
    

    Sorry for the long description, I don't want it to look messy, I figure it's just easier for you to see what I'm working with to spot my eventually beginner mistakes.

    Thanks a lot!

    Janos

  • benoit
    benoit Rennes, France
    edited August 2016

    Hi,

    The IceGridAdmin GUI not exporting the filter is a bug. We will fix this for the next release. As long at it shows up, in the GUI and that you see calls to filter implementation, it should be working fine.

    It isn't clear from your description what is the problem. The filter being called without a context set is probably expected if you use the replica group for other Ice objects as well (which appears to be the case since you use it for the RoutingSessionManager object).

    The filter should be called with a context set when the routing session manager invokes the create operation and the endpoints aren't already in the locator cache (once the endpoints are cached for a given locator, the routing session manager won't necessarily call again IceGrid to resolve the endpoints).

    You can enable locator tracing in the routing session manager server to see when it's calling IceGrid with Ice.Trace.Locator=2.

    Can you show the implementation of your replica group filter? Are you returning the endpoints of a single replica (the endpoints of the regional session manager)?

    Dynamically registered object adapters should show up in the IceGridAdmin GUI when you click on the registry node in the tree. Here, we display the deployed applications on the registry and the dynamically registered well-known objects and adapters. Note that they don't show up in tree like for object adapters from servers deployed with the deployment facility.

    Cheers,
    Benoit.

  • janos
    janos Germany

    Hi,

    The problem is that the filter plugin only gets called every 5 minutes, regardless if I make requests every minute. For example I made started multiple sessions right now and the last log entry from the filter plugin is from last night.

    Placing the Ice.Trace.Locator=2 on the Server hosting the RoutingSessionManager doesn't show entries in the log:

    8/26/16 07:16:35:554    Trace   Locator registered server `Provider-1' with the locator registry
    8/26/16 07:16:35:597    Trace   Locator updated object adapter `AppD.Provider-1' endpoints with the locator registry endpoints = tcp -h "2a02:...:0:1%eth0" -p 54272 -t 60000:tcp -h ipaddress -p 54272 -t 60000
    

    It seems to me that the RoutingSessionManager already has cached the endpoints and doesn't call back to the IceGrid when reaching for the RegionalSessionManager. Is there a way to clear the cached endpoints?

    On Glacier2 I have turned off the Locator cache (Glacier2.SessionManager.LocatorCacheTimeout=0).

    Here's the filter plugin, I modified the currency filter plugin from the ice-demos:

    Ice::StringSeq ReplicaGroupFilterI::filter(const string&, const Ice::StringSeq& adapters, const Ice::ConnectionPtr&, const Ice::Context& ctx) {
        cout << now("%I:%M:%S %p %Z") << " filtering...\n";
        Ice::Context::const_iterator p = ctx.find("Region");
    
        int adaptersCounter = 0;
        for(Ice::StringSeq::const_iterator q = adapters.begin(); q != adapters.end(); ++q) {
            adaptersCounter++;
        }
        cout << now("%I:%M:%S %p %Z") << " Adapter available in total: " << adaptersCounter << "\n";
    
        if(p == ctx.end()) {
            cout << now("%I:%M:%S %p %Z") << " Region context property was not found in request context\n";
            return adapters;
        }
    
        string region = p->second;
        cout << now("%I:%M:%S %p %Z") << " Found '" << region << "' region in context\n";
    
        // get region values from server descriptors
        Ice::StringSeq filteredAdapters;
        int counter = 0;
        for(Ice::StringSeq::const_iterator q = adapters.begin(); q != adapters.end(); ++q) {
            string arg =  _facade->getPropertyForAdapter(*q, "Regions");
    
            cout << now("%I:%M:%S %p %Z") << " Found " << arg << "region entries on adapter " << &q << "\n";
    
            if(arg.find(region) != string::npos || arg.find("All") != string::npos)
            {
                counter++;
                filteredAdapters.push_back(*q);
            }
        }
    
        cout << now("%I:%M:%S %p %Z") << " Returning " << counter << " adapters for connection to choose from\n";
    
        return filteredAdapters;
    }
    

    Problem 2: Regarding dynamic registration, if I start a debug session in my IDE and it shows that it has registered itself with the registry, I expected the object adapter to show up in the list of dynamically registered adapters, but it doesn't. That also probably means that it doesn't participate in the replica group and it cannot be filtered either. Is there a tested way to debug server/service instances from an IDE?

    Kind regards,
    Janos

  • benoit
    benoit Rennes, France

    Hi,

    For problem 1, you can disable locator caching by calling ice_locatorCacheTimeout(0) on the regional session manager proxy:

    regional = regional.ice_locatorCacheTimeout(0)

    See https://doc.zeroc.com/display/Ice36/Locator+Semantics+for+Clients for more information on the locator cache.

    For problem 2, if I understand it correctly, you are starting "by hand" a server that is supposed to be started by an IceGrid node? Are you disabling the server with the GUI to prevent IceGrid from starting it? For debugging, the easiest is to let IceGrid start the server and then attach with the debugger to the process.

    Cheers,
    Benoit.

  • janos
    janos Germany
    Hi,

    Regarding "problem 2", you are correct. I should have thought of this myself. Attaching to the jvm is the easiest solution. Thanks! :) I don't have to start a new instance or register it, just use the one already there.

    Setting the locatorCacheTimeout to 0 has no effect. There is still no outgoing call from the server querying the replica for the regional manager. I don't understand why.

    Regards,
    Janos
  • benoit
    benoit Rennes, France

    Hi,

    Ok you need to tell me a little more about your deployment. Is the problem that the routing session manager is always re-using the same regional session manager instance or that it's using one which isn't of the correct region?

    I see that you are returning endpoints for multiple replicas from your replica group filter. The routing session manager will receive these endpoints and pick a random endpoint among the endpoints available to create the new session manager. Once a connection is established to a region session manager, it will be re-used for subsequent calls. To eventually use other endpoints, you can disable this behavior by calling ice_connectionCached(false) on the proxy in addition of disabling the locator cache timeout.

    Another other option would be to always return the endpoints for a single region manager from the replica group filter.

    Cheers,
    Benoit.

  • janos
    janos Germany
    Hi Benoit,

    As I understand the concept, as long as the context is not defined, the filter returns all adapters. If there's a context it returns only a set of adapters with matching regions. I would describe the problem as you said, the returned adapter is not from the region, which is needed.

    1. Should I create a separate replica group just for the regional session manager?
    2. Or should I use a more advanced filter to separate the managers?

    3. Does the filter method get called with a prefiltered set of endpoints for the well-known objects or with everything from the replica group?

    I have no problem letting the runtime reuse the cached endpoints as long as it matches the region of the context.

    I am trying to achieve a geo replicated session creation so the session gets created for the client at the closest server. The router itself will be preselected, so I'd need to get the session creation to the right server. Sorry if I'm describing the issue inadequately.

    I'll try your suggestion regarding connection cache in the morning.

    Best
    Janos
  • benoit
    benoit Rennes, France

    Hi Janos,

    It's up to your filter implementation to decide what to do when the "Region" context is not present. Returning all the adapters is fine and it is more or less equivalent to the "Random" load balancing strategy with n-replicas being set to return all the replica's adapters. Creating a separate replica group isn't necessary.

    The filter method is called with all the adapter IDs. You should be able to verify this by just adding some tracing to your filter.

    The best would be to enable the following tracing on the server which host the routing session manager:

    Ice.Trace.Protocol=1
    Ice.Trace.Locator=2
    

    For each create session manager call, you should see that the call on the region session manager replicated proxy should trigger a "findAdapterById" call to the IceGrid locator and this call should have the region context set. Here's the tracing I see for example when using the "customReplicaGroup" demo:

    -- 08/31/16 09:16:59.610 ./client: Locator: searching for adapter by id
       adapter = ReplicatedPricingAdapter
    -- 08/31/16 09:16:59.611 ./client: Protocol: sending asynchronous request
       message type = 0 (request)
       compression status = 0 (not compressed; do not compress response, if any)
       message size = 101
       request id = 2
       identity = DemoIceGrid/Locator
       facet = 
       operation = findAdapterById
       mode = 1 (nonmutating)
       context = currency/USD
       encoding = 1.1
    -- 08/31/16 09:16:59.611 ./client: Protocol: received reply 
       message type = 2 (reply)
       compression status = 0 (not compressed; do not compress response, if any)
       message size = 67
       request id = 2
       reply status = 0 (ok)
       encoding = 1.1
    -- 08/31/16 09:16:59.612 ./client: Locator: retrieved endpoints from locator, adding to locator table
       adapter = ReplicatedPricingAdapter
       endpoints = tcp -h localhost -p 61331 -t 60000
    

    You should see similar tracing for the resolution of each distinct region session manager. You should also see the matching tracing from your filter each time the routing session manager shows a findAdapterById call in the tracing.

    Cheers,
    Benoit.

  • janos
    janos Germany
    edited September 2016

    Hi Benoit,

    I made the changes you suggested and I can't find a matching filter log to the findadapterById. Unfortunately both findAdapterById calls have no context. I expected the second one to carry the context, set in the routing session manager, as we discussed.

    Here's the implementation:

       @Override
        public SessionPrx create(String userId, SessionControlPrx sessionControlPrx, Current current) throws CannotCreateSessionException {
            Communicator communicator = current.adapter.getCommunicator();
            LocatorPrx locatorPrx = communicator.getDefaultLocator();
            String envPrefix = EEnvironment.getEnvPrefix();
            String regionalProxyAddress = String.format("%sRegionalSessionManager@%sBackends", envPrefix, envPrefix);
            ObjectPrx regional = communicator.stringToProxy(regionalProxyAddress);
            Map<String, String> ctx = current.ctx;
    
            _log.debug("Routing creation of session to '{}' with Region: '{}'", regionalProxyAddress, ctx.get("Region"));
    
            // Use locator with this call's context to resolve the replica group endpoints
            // using the "Region" context provided by the client
            //
            regional = regional.ice_locator((LocatorPrx) locatorPrx.ice_context(ctx));
            regional = regional.ice_locatorCacheTimeout(0); // remove cached locator endpoints
            regional = regional.ice_connectionCached(false); // disable connection caching
    
            _log.debug("Locator's context on RegionalSessionManager for Region: {}", regional.ice_getLocator().ice_getContext().get("Region"));
    
            // return the FMSession created from the routed RegionalSessionManagerI
            return SessionManagerPrxHelper.uncheckedCast(regional).create(userId, sessionControlPrx);
        }
    }
    

    Server Log:

    9/1/16 06:56:42:687 Trace   Protocol    received request  message type = 0 (request) compression status = 0 (not compressed; do not compress response, if any) message size = 156 request id = 1 identity = AppD.PermissionVerifier facet =  operation = checkPermissions mode = 1 (nonmutating) context = Region/LOCAL encoding = 1.1
    
    9/1/16 06:56:42:691 Trace   Protocol    received request  message type = 0 (request) compression status = 0 (not compressed; do not compress response, if any) message size = 151 request id = 2 identity = AppD.SessionManager facet =  operation = create mode = 0 (normal) context = Region/LOCAL encoding = 1.1
    
    9/1/16 06:56:42:714 Trace   Protocol    sending request  message type = 0 (request) compression status = 0 (not compressed; do not compress response, if any) message size = 144 request id = 1 identity = AppD.RegionalSessionManager facet =  operation = create mode = 0 (normal) context =  encoding = 1.1
    
    9/1/16 06:56:43:162 Trace   Protocol    received request  message type = 0 (request) compression status = 0 (not compressed; do not compress response, if any) message size = 162 request id = 3 identity = session/99a7a092-011e-48ca-9c78-10e90fb03710 facet =  operation = setCallback mode = 0 (normal) context = Region/LOCAL encoding = 1.1
    

    Filter log (doesn't match timestamp):

    06:45:49 AM CEST Adapter Pool size: 1
    06:45:49 AM CEST Region context property was not found in request context
    

    Glacier2 log:

    9/1/16 06:56:42:677 Trace   Protocol    received request  message type = 0 (request) compression status = 0 (not compressed; do not compress response, if any) message size = 147 request id = 2 identity = Glacier2/router facet =  operation = createSession mode = 0 (normal) context = Region/LOCAL encoding = 1.1
    9/1/16 06:56:42:677 Trace   Locator found endpoints in locator table adapter = Backends endpoints = tcp -h -p 54958 -t 60000:tcp -h -p 54958 -t 60000:
    9/1/16 06:56:42:678 Trace   Locator searching for adapter by id adapter = Backends
    9/1/16 06:56:42:680 Trace   Protocol    received validate connection  message type = 3 (validate connection) compression status = 0 (not compressed; do not compress response, if any) message size = 14
    9/1/16 06:56:42:680 Trace   Protocol    sending asynchronous request message type = 0 (request) compression status = 0 (not compressed; do not compress response, if any) message size = 75 request id = 1 identity = IceGrid/Locator facet =  operation = findAdapterById mode = 1 (nonmutating) context =  encoding = 1.1
    9/1/16 06:56:42:681 Trace   Protocol    received reply  message type = 2 (reply) compression status = 0 (not compressed; do not compress response, if any) message size = 121 request id = 1 reply status = 0 (ok) encoding = 1.1
    9/1/16 06:56:42:682 Trace   Locator retrieved endpoints from locator, adding to locator table adapter = Backends endpoints = tcp -h "" -p 34310 -t 60000:tcp -h ip -p 34310 -t 60000:
    9/1/16 06:56:42:686 Trace   Protocol    received validate connection  message type = 3 (validate connection) compression status = 0 (not compressed; do not compress response, if any) message size = 14
    9/1/16 06:56:42:686 Trace   Protocol    sending asynchronous request message type = 0 (request) compression status = 0 (not compressed; do not compress response, if any) message size = 156 request id = 1 identity = AppD.PermissionVerifier facet =  operation = checkPermissions mode = 1 (nonmutating) context = Region/LOCAL encoding = 1.1
    9/1/16 06:56:42:690 Trace   Protocol    received reply  message type = 2 (reply) compression status = 0 (not compressed; do not compress response, if any) message size = 27 request id = 1 reply status = 0 (ok) encoding = 1.1
    9/1/16 06:56:42:690 Trace   Locator searching for adapter by id adapter = Backends
    9/1/16 06:56:42:690 Trace   Protocol    sending asynchronous request message type = 0 (request) compression status = 0 (not compressed; do not compress response, if any) message size = 75 request id = 2 identity = IceGrid/Locator facet =  operation = findAdapterById mode = 1 (nonmutating) context =  encoding = 1.1
    9/1/16 06:56:42:691 Trace   Protocol    received reply  message type = 2 (reply) compression status = 0 (not compressed; do not compress response, if any) message size = 121 request id = 2 reply status = 0 (ok) encoding = 1.1
    

    Best regards
    Janos

  • benoit
    benoit Rennes, France

    Hi,

    Why don't we see more tracing in the server logs? Did you enable Ice.Trace.Locator on the server as well? We should see locator traces between the sending of two create operations.

    Cheers,
    Benoit.

  • Hi,

    I know, right? Both locator and protocol are enabled with level 2 as you suggested. That is on the server template. They are successfully deployed to the instance and available in the config folder on the node.

    Best
    Janos

  • benoit
    benoit Rennes, France

    Did you install a custom logger? Something's not right with the server traces. We only see received requests and other traces such as the sending of the replies are missing. Can you post the full log of a server run with the creation of few sessions?

    Cheers,
    Benoit.

  • Sorry, I completely forgot about the Logger I put in the initialization Data.

    Here's the complete log for a request:

    9/2/16 15:53:24:476 Trace   Protocol    sending validate connection  message type = 3 (validate connection) compression status = 0 (not compressed; do not compress response, if any) message size = 14
    9/2/16 15:53:24:481 Trace   Protocol    received request  message type = 0 (request) compression status = 0 (not compressed; do not compress response, if any) message size = 156 request id = 1 identity = AppD.PermissionVerifier facet =  operation = checkPermissions mode = 1 (nonmutating) context = Region/LOCAL encoding = 1.1
    9/2/16 15:53:24:484 Trace   Protocol    sending reply  message type = 2 (reply) compression status = 0 (not compressed; do not compress response, if any) message size = 27 request id = 1 reply status = 0 (ok) encoding = 1.1
    9/2/16 15:53:24:607 Trace   Protocol    received request  message type = 0 (request) compression status = 0 (not compressed; do not compress response, if any) message size = 151 request id = 2 identity = AppD.SessionManager facet =  operation = create mode = 0 (normal) context = Region/LOCAL encoding = 1.1
    9/2/16 15:53:24:654 Trace   Protocol    sending request  message type = 0 (request) compression status = 0 (not compressed; do not compress response, if any) message size = 144 request id = 1 identity = AppD.RegionalSessionManager facet =  operation = create mode = 0 (normal) context =  encoding = 1.1
    9/2/16 15:53:24:745 Trace   Protocol    received reply  message type = 2 (reply) compression status = 0 (not compressed; do not compress response, if any) message size = 91 request id = 1 reply status = 0 (ok) encoding = 1.1
    9/2/16 15:53:24:746 Trace   Protocol    sending reply  message type = 2 (reply) compression status = 0 (not compressed; do not compress response, if any) message size = 91 request id = 2 reply status = 0 (ok) encoding = 1.1
    9/2/16 15:53:25:172 Trace   Protocol    received request  message type = 0 (request) compression status = 0 (not compressed; do not compress response, if any) message size = 162 request id = 3 identity = session/1f206f98-a449-47ac-88f1-1e451a4ecfe7 facet =  operation = setCallback mode = 0 (normal) context = Region/LOCAL encoding = 1.1
    9/2/16 15:53:25:176 Trace   Protocol    sending reply  message type = 2 (reply) compression status = 0 (not compressed; do not compress response, if any) message size = 25 request id = 3 reply status = 0 (ok) encoding = 1.1
    9/2/16 15:53:25:300 Trace   Protocol    received request  message type = 0 (request) compression status = 0 (not compressed; do not compress response, if any) message size = 97 request id = 4 identity = session/1f206f98-a449-47ac-88f1-1e451a4ecfe7 facet =  operation = getGenericQ mode = 0 (normal) context = Region/LOCAL encoding = 1.1
    9/2/16 15:53:25:314 Trace   Protocol    sending reply  message type = 2 (reply) compression status = 0 (not compressed; do not compress response, if any) message size = 84 request id = 4 reply status = 0 (ok) encoding = 1.1
    

    And attached are multiple requests altogether.

    The filter log from the registry:

    09:32:34 PM CEST filtering...
    09:32:34 PM CEST Adapter Pool size: 1
    09:32:34 PM CEST Region context property was not found in request context
    09:33:20 PM CEST filtering...
    09:33:20 PM CEST Adapter Pool size: 1
    09:33:20 PM CEST Region context property was not found in request context
    09:33:37 PM CEST filtering...
    09:33:37 PM CEST Adapter Pool size: 1
    09:33:37 PM CEST Region context property was not found in request context
    06:45:49 AM CEST filtering...
    06:45:49 AM CEST Adapter Pool size: 1
    06:45:49 AM CEST Region context property was not found in request context
    06:45:49 AM CEST filtering...
    06:45:49 AM CEST Adapter Pool size: 1
    06:45:49 AM CEST Region context property was not found in request context
    06:56:42 AM CEST filtering...
    06:56:42 AM CEST Adapter Pool size: 1
    06:56:42 AM CEST Region context property was not found in request context
    06:56:42 AM CEST filtering...
    06:56:42 AM CEST Adapter Pool size: 1
    06:56:42 AM CEST Region context property was not found in request context
    07:44:09 AM CEST filtering...
    07:44:09 AM CEST Adapter Pool size: 1
    07:44:09 AM CEST Region context property was not found in request context
    

    Best Janos

  • benoit
    benoit Rennes, France
    edited September 2016

    Hi,

    Ok I think I know what's going on... do you register the routing session manager on a server which also hosts a local region session manager? I believe the routing session manager always uses the local regional session manager through collocation optimization and doesn't bother going to the IceGrid locator to find one.

    Can you try disabling collocation optimization to see if it fixes the issue?

    regional = regional.ice_collocationOptimized(false);
    

    Cheers,
    Benoit.

  • Hi,

    I didn't realize that the concept of collocation extended beyond the node-registry.
    There's actually progress, the filter is getting called with the context delivering endpoint as expected. I am still experimenting with the code as the behavior is inconsistent, after a certain time (n-th request) there is no filter call anymore. But the general problem is now solved! Thank you very much for your patience! :)

    Cheers
    Janos