Communication via topics does not work after transitioning from Ice 3.5 to 3.7

ptriantd · August 2019

Hi everyone,

After upgrading to Ubuntu18.04 and Ice 3.7, creating a topic publisher fails with src/Ice/Reference.cpp:1643: ::Ice::NoEndpointException: no suitable endpoint available for proxy IceStorm/TopicManager -t -e 1.0 Aborted (core dumped)

Communication via proxy works fine though!

I am thinking that this might have to do with some configuration issue due to upgrading from 3.5 to 3.7.

My configuration is as follows:

config.registry

IceGrid.InstanceName=IceGrid
Ice.Default.Locator = IceGrid/Locator:tcp -p 4061
Ice.Trace.Network = 1
IceGrid.Registry.Client.Endpoints = tcp -p 4061
IceGrid.Registry.Server.Endpoints=tcp
IceGrid.Registry.Internal.Endpoints=tcp
IceGrid.Registry.LMDB.Path=db

IceGrid.Registry.PermissionsVerifier=IceGrid/NullPermissionsVerifier
IceGrid.Registry.AdminPermissionsVerifier=IceGrid/NullPermissionsVerifier

IceGrid.Registry.DynamicRegistration=1
IceGrid.Registry.SessionTimeout=300
Ice.MessageSizeMax=10000000

IceGrid.Node.CollocateRegistry=1

IceGridAdmin.Username=foo
IceGridAdmin.Password=bar

config.node

Ice.Default.Locator = IceGrid/Locator:tcp -p 4061

IceGrid.Node.Name=Node1

IceGrid.Node.Endpoints=tcp
IceGrid.Node.Data=data

Ice.Trace.Network=1

application.xml

<icegrid>

  <application name="Demo">

   <server-template id="IceStorm">
     <parameter name="instance-name" default="IceStorm"/>
     <parameter name="topic-manager-endpoints" default="tcp -h localhost"/>
     <parameter name="publish-endpoints" default="tcp"/>

     <icebox id="${instance-name}" exe="icebox" activation="always">

       <service name="${instance-name}" entry="IceStormService,35:createIceStorm">

         <dbenv name="${service}"/>

         <adapter name="${service}.TopicManager"
          id="${instance-name}.TopicManager"
          endpoints="${topic-manager-endpoints}">
          <object identity="${instance-name}/TopicManager" type="::IceStorm::TopicManager"/>
        </adapter>

        <adapter name="${service}.Publish"
          id="${instance-name}.Publish"
          endpoints="${publish-endpoints}"/>

          <properties>
           <property name="${service}.InstanceName" value="${instance-name}"/>
           <property name="${service}.Trace.TopicManager" value="2"/>
           <property name="${service}.Trace.Topic" value="2"/>
           <property name="${service}.Trace.Subscriber" value="2"/>
         </properties>

       </service>
     </icebox>
   </server-template>

   <node name="Node1">
    <server-instance template="IceStorm"/>
  </node>

</application>

</icegrid>

and the commands I am executing are:

icegridregistry --Ice.Config=config.registry &
icegridnode --Ice.Config=config.node &
icegridadmin --Ice.Config=config.registry,config.node -e "application add 'application.xml'" &

Any idea what might be going wrong?

xdm · August 2019

You should update the IceStorm entry point to 3.7 IceStormService,37:createIceStorm instead of IceStormService,35:createIceStorm in your server template.

If you want to run icegridregistry and icegridnode in background is preferable to use --daemon command line argument instead of &.

I don't see why you want to run icegridamin in background, this command shouldn't take too long to finish.

Cheers,
José

ptriantd · August 2019

Hi José,

Thanks for that! Unfortunately, it doesn't seem to fix the issue

Also, if this was the problem, wouldn't proxies not work too? The weird thing for me is that communication via proxy works fine.

Best,
Pavlos

xdm · August 2019

What is the process that crash? can you provide a stack trace of the crash?

ptriantd · August 2019

Sure!

This is what I am getting on the subscriber side:

-- 07/31/19 17:16:38.969 Network: listening for tcp connections
   local address = :::42447
   local interfaces = 127.0.0.1, 172.17.0.2
-- 07/31/19 17:16:38.969 Network: published endpoints for object adapter `TextMessengerAdapter':
   tcp -h 172.17.0.2 -p 42447 -t 60000
-- 07/31/19 17:16:38.969 Network: accepting tcp connections at :::42447
-- 07/31/19 17:16:38.969 Locator: searching for well-known object
   well-known proxy = IceStorm/TopicManager -t -e 1.0
-- 07/31/19 17:16:38.970 Network: established tcp connection
   local address = 127.0.0.1:35250
   remote address = 127.0.0.1:4061
-- 07/31/19 17:16:38.971 Locator: retrieved adapter for well-known object from locator, adding to locator cache
   well-known proxy = IceStorm/TopicManager -t -e 1.0
   adapter = IceStorm.TopicManager
-- 07/31/19 17:16:38.971 Locator: searching for adapter by id
   adapter = IceStorm.TopicManager
-- 07/31/19 17:16:39.515 Locator: no endpoints configured for adapter
   adapter = IceStorm.TopicManager
-- 07/31/19 17:16:39.516 Locator: searching for well-known object
   well-known proxy = IceStorm/TopicManager -t -e 1.0
-- 07/31/19 17:16:39.516 Locator: retrieved adapter for well-known object from locator, adding to locator cache
   well-known proxy = IceStorm/TopicManager -t -e 1.0
   adapter = IceStorm.TopicManager
-- 07/31/19 17:16:39.516 Locator: searching for adapter by id
   adapter = IceStorm.TopicManager
-- 07/31/19 17:16:39.978 Locator: no endpoints configured for adapter
   adapter = IceStorm.TopicManager
terminate called after throwing an instance of 'ice_management::TopicManagerException'
  what():  Error during creation 
src/Ice/Reference.cpp:1643: ::Ice::NoEndpointException:
no suitable endpoint available for proxy `IceStorm/TopicManager -t -e 1.0'
Aborted (core dumped)

and the IceGrid session outputs:

-- 08/01/19 17:25:46.771 icegridregistry: Network: accepted tcp connection
   local address = ::ffff:127.0.0.1:4061
   remote address = ::ffff:127.0.0.1:39938
-- 08/01/19 17:25:46.907 icegridregistry: Network: closed tcp connection
   local address = ::ffff:127.0.0.1:4061
   remote address = ::ffff:127.0.0.1:39938
   src/Ice/StreamSocket.cpp:249: ::Ice::ConnectionLostException:
   connection lost: recv() returned zero

xdm · August 2019

Can you enable IceGrid.Node.Trace.Activator=3 and IceGrid.Node.Trace.Adapter=3 in icegridnode, it is not clear where the -e 1.0 is coming from

ptriantd · August 2019

Ok, now that I enabled these, I see the error

-- 08/02/19 10:27:06.781 icegridregistry: Network: accepted tcp connection
   local address = ::ffff:127.0.0.1:4061
   remote address = ::ffff:127.0.0.1:43494
-- 08/02/19 10:27:06.781 icegridadmin: Network: established tcp connection
   local address = 127.0.0.1:43494
   remote address = 127.0.0.1:4061
-- 08/02/19 10:27:06.789 icegridregistry: Network: closed tcp connection
   local address = ::ffff:127.0.0.1:4061
   remote address = ::ffff:127.0.0.1:43494
-- 08/02/19 10:27:06.789 icegridadmin: Network: closed tcp connection
   local address = 127.0.0.1:43494
   remote address = 127.0.0.1:4061
-- 08/02/19 10:27:07.288 icegridnode: Activator: activating server `IceStorm'
   path = icebox
   pwd = /home/travis/IceManagement/Scripts/IceSetup
   uid/gid = 999/999
   args = icebox --Ice.Config=/home/travis/IceManagement/Scripts/IceSetup/data/servers/IceStorm/config/config
-- 08/02/19 10:27:07.801 icegridregistry: Network: accepted tcp connection
   local address = ::ffff:127.0.0.1:4061
   remote address = ::ffff:127.0.0.1:43496
-- 08/02/19 10:27:07.802 icegridregistry: Network: accepted tcp connection
   local address = ::ffff:172.17.0.2:34103
   remote address = ::ffff:172.17.0.2:53520
-- 08/02/19 10:27:07.802 icegridnode: Adapter: server `IceStorm' adapter `IceStorm.TopicManager' deactivated
-- 08/02/19 10:27:07.803 icegridnode: Adapter: server `IceStorm' adapter `IceStorm.Publish' deactivated
-- 08/02/19 10:27:07.803 icegridregistry: Network: closed tcp connection
   local address = ::ffff:172.17.0.2:34103
   remote address = ::ffff:172.17.0.2:53520
-- 08/02/19 10:27:07.803 icegridregistry: Network: closed tcp connection
   local address = ::ffff:127.0.0.1:4061
   remote address = ::ffff:127.0.0.1:43496
!! 08/02/19 10:27:07.804 IceStorm: error: exception while starting IceStorm service IceStorm:
   src/IceUtil/FileUtil.cpp:441: ::IceUtil::FileLockException:
   could not lock file: `IceStorm/icedb.lock'
   syscall exception: No such file or directory
-- 08/02/19 10:27:07.804 icegridnode: Activator: detected termination of server `IceStorm'
   exit code = 1
-- 08/02/19 10:27:07.805 icegridnode: Adapter: server `IceStorm' adapter `IceStorm.Publish' deactivated
-- 08/02/19 10:27:07.805 icegridnode: Adapter: server `IceStorm' adapter `IceStorm.TopicManager' deactivated

icedb.lock seems to not exist...

Just some more info about that... When we switched to Ice 3.7, we changed IceGrid.Registry.Data=registry to IceGrid.Registry.LMDB.Path=registry. Should we have done something more?

xdm · August 2019

Your IceStorm service template is missing LMDB configuration

<property name="${service}.LMDB.Path" value="${service.data}"/>

See https://github.com/zeroc-ice/ice/blob/3.7/cpp/config/templates.xml#L42

ptriantd · August 2019

Thanks for that!

When I added this property, the aforementioned error disappeared, but unfortunately I get a socket_exception now:

-- 08/02/19 11:48:17.119 icegridregistry: Network: accepted tcp connection
   local address = ::ffff:127.0.0.1:4061
   remote address = ::ffff:127.0.0.1:45154
-- 08/02/19 11:48:17.119 icegridadmin: Network: established tcp connection
   local address = 127.0.0.1:45154
   remote address = 127.0.0.1:4061
-- 08/02/19 11:48:17.126 icegridregistry: Network: closed tcp connection
   local address = ::ffff:127.0.0.1:4061
   remote address = ::ffff:127.0.0.1:45154
-- 08/02/19 11:48:17.126 icegridadmin: Network: closed tcp connection
   local address = 127.0.0.1:45154
   remote address = 127.0.0.1:4061
-- 08/02/19 11:48:17.625 icegridnode: Activator: activating server `IceStorm'
   path = icebox
   pwd = /home/travis/IceManagement/Scripts/IceSetup
   uid/gid = 999/999
   args = icebox --Ice.Config=/home/travis/IceManagement/Scripts/IceSetup/data/servers/IceStorm/config/config
-- 08/02/19 11:48:18.185 icegridregistry: Network: accepted tcp connection
   local address = ::ffff:127.0.0.1:4061
   remote address = ::ffff:127.0.0.1:45158
-- 08/02/19 11:48:18.186 icegridregistry: Network: accepted tcp connection
   local address = ::ffff:172.17.0.2:37765
   remote address = ::ffff:172.17.0.2:59036
-- 08/02/19 11:48:18.186 icegridnode: Adapter: server `IceStorm' adapter `IceStorm.TopicManager' activated: dummy -t -e 1.1:tcp -h 127.0.0.1 -p 45245 -t 60000
-- 08/02/19 11:48:18.187 icegridnode: Adapter: server `IceStorm' adapter `IceStorm.Publish' activated: dummy -t -e 1.1:tcp -h 127.0.0.1 -p 39857 -t 60000
-- 08/02/19 11:48:18.188 icegridnode: Adapter: server `IceStorm' adapter `IceStorm.TopicManager' deactivated
-- 08/02/19 11:48:18.189 icegridnode: Adapter: server `IceStorm' adapter `IceStorm.Publish' deactivated
-- 08/02/19 11:48:18.189 icegridregistry: Network: closed tcp connection
   local address = ::ffff:172.17.0.2:37765
   remote address = ::ffff:172.17.0.2:59036
-- 08/02/19 11:48:18.189 icegridregistry: Network: closed tcp connection
   local address = ::ffff:127.0.0.1:4061
   remote address = ::ffff:127.0.0.1:45158
!! 08/02/19 11:48:18.190 IceStorm: error: ServiceManager: src/Ice/Network.cpp:2368: ::Ice::SocketException:
   socket exception: Cannot assign requested address
-- 08/02/19 11:48:18.191 icegridnode: Activator: detected termination of server `IceStorm'
   exit code = 1
-- 08/02/19 11:48:18.191 icegridnode: Adapter: server `IceStorm' adapter `IceStorm.Publish' deactivated
-- 08/02/19 11:48:18.191 icegridnode: Adapter: server `IceStorm' adapter `IceStorm.TopicManager' deactivated

xdm · August 2019

Seems an attempt to bind is failing, can you enable network tracing in the service properties

<properties>
<property name="Ice.Trace.Network" value="2"/>
....

</properties>

ptriantd · August 2019

Sure!

Here is the output:

-- 08/02/19 15:10:09.065 icegridadmin: Network: trying to establish tcp connection to 127.0.0.1:4061
-- 08/02/19 15:10:09.065 icegridregistry: Network: trying to accept tcp connection
   local address = ::ffff:127.0.0.1:4061
   remote address = ::ffff:127.0.0.1:46650
-- 08/02/19 15:10:09.066 icegridregistry: Network: accepted tcp connection
   local address = ::ffff:127.0.0.1:4061
   remote address = ::ffff:127.0.0.1:46650-- 08/02/19 15:10:09.066 icegridadmin: Network: established tcp connection
   local address = 127.0.0.1:46650
   remote address = 127.0.0.1:4061

-- 08/02/19 15:10:09.074 icegridregistry: Network: closed tcp connection
   local address = ::ffff:127.0.0.1:4061
   remote address = ::ffff:127.0.0.1:46650
-- 08/02/19 15:10:09.074 icegridadmin: Network: closed tcp connection
   local address = 127.0.0.1:46650
   remote address = 127.0.0.1:4061
-- 08/02/19 15:10:09.573 icegridnode: Activator: activating server `IceStorm'
   path = icebox
   pwd = /home/travis/IceManagement/Scripts/IceSetup
   uid/gid = 999/999
   args = icebox --Ice.Config=/home/travis/IceManagement/Scripts/IceSetup/data/servers/IceStorm/config/config
-- 08/02/19 15:10:10.055 IceStorm-IceStorm: Network: attempting to bind to tcp socket :::0
-- 08/02/19 15:10:10.055 IceStorm-IceStorm: Network: listening for tcp connections
   local address = :::34547
   local interfaces = 127.0.0.1, 172.17.0.2
-- 08/02/19 15:10:10.055 IceStorm-IceStorm: Network: published endpoints for object adapter `IceStorm.TopicManager':
   tcp -h 172.17.0.2 -p 34547 -t 60000
-- 08/02/19 15:10:10.055 IceStorm-IceStorm: Network: attempting to bind to tcp socket :::0
-- 08/02/19 15:10:10.055 IceStorm-IceStorm: Network: listening for tcp connections
   local address = :::43465
   local interfaces = 127.0.0.1, 172.17.0.2
-- 08/02/19 15:10:10.055 IceStorm-IceStorm: Network: published endpoints for object adapter `IceStorm.Publish':
   tcp -h 172.17.0.2 -p 43465 -t 60000
-- 08/02/19 15:10:10.059 IceStorm-IceStorm: Network: trying to establish tcp connection to 127.0.0.1:4061
-- 08/02/19 15:10:10.059 icegridregistry: Network: trying to accept tcp connection
   local address = ::ffff:127.0.0.1:4061
   remote address = ::ffff:127.0.0.1:46652
-- 08/02/19 15:10:10.059 icegridregistry: Network: accepted tcp connection
   local address = ::ffff:127.0.0.1:4061
   remote address = ::ffff:127.0.0.1:46652
-- 08/02/19 15:10:10.059 IceStorm-IceStorm: Network: established tcp connection
   local address = 127.0.0.1:46652
   remote address = 127.0.0.1:4061
-- 08/02/19 15:10:10.059 IceStorm-IceStorm: Network: trying to establish tcp connection to 172.17.0.2:34841
-- 08/02/19 15:10:10.060 icegridregistry: Network: trying to accept tcp connection
   local address = ::ffff:172.17.0.2:34841
   remote address = ::ffff:172.17.0.2:53542
-- 08/02/19 15:10:10.060 IceStorm-IceStorm: Network: established tcp connection
   local address = 172.17.0.2:53542
   remote address = 172.17.0.2:34841-- 08/02/19 15:10:10.060 icegridregistry: Network: accepted tcp connection
   local address = ::ffff:172.17.0.2:34841
   remote address = ::ffff:172.17.0.2:53542

-- 08/02/19 15:10:10.060 icegridnode: Adapter: server `IceStorm' adapter `IceStorm.TopicManager' activated: dummy -t -e 1.1:tcp -h 172.17.0.2 -p 34547 -t 60000
-- 08/02/19 15:10:10.060 IceStorm-IceStorm: Network: accepting tcp connections at :::34547
-- 08/02/19 15:10:10.061 icegridnode: Adapter: server `IceStorm' adapter `IceStorm.Publish' activated: dummy -t -e 1.1:tcp -h 172.17.0.2 -p 43465 -t 60000
-- 08/02/19 15:10:10.061 IceStorm-IceStorm: Network: accepting tcp connections at :::43465
-- 08/02/19 15:10:10.062 icegridnode: Adapter: server `IceStorm' adapter `IceStorm.TopicManager' deactivated
-- 08/02/19 15:10:10.062 IceStorm-IceStorm: Network: stopping to accept tcp connections at :::34547
-- 08/02/19 15:10:10.062 icegridnode: Adapter: server `IceStorm' adapter `IceStorm.Publish' deactivated
-- 08/02/19 15:10:10.062 IceStorm-IceStorm: Network: stopping to accept tcp connections at :::43465
-- 08/02/19 15:10:10.063 icegridregistry: Network: closed tcp connection
   local address = ::ffff:172.17.0.2:34841
   remote address = ::ffff:172.17.0.2:53542
-- 08/02/19 15:10:10.063 icegridregistry: Network: closed tcp connection
   local address = ::ffff:127.0.0.1:4061
   remote address = ::ffff:127.0.0.1:46652
-- 08/02/19 15:10:10.063 IceStorm-IceStorm: Network: closed tcp connection
   local address = 172.17.0.2:53542
   remote address = 172.17.0.2:34841
-- 08/02/19 15:10:10.063 IceStorm-IceStorm: Network: closed tcp connection
   local address = 127.0.0.1:46652
   remote address = 127.0.0.1:4061
!! 08/02/19 15:10:10.063 IceStorm: error: ServiceManager: src/Ice/Network.cpp:2368: ::Ice::SocketException:
   socket exception: Cannot assign requested address
-- 08/02/19 15:10:10.064 icegridnode: Activator: detected termination of server `IceStorm'
   exit code = 1
-- 08/02/19 15:10:10.064 icegridnode: Adapter: server `IceStorm' adapter `IceStorm.Publish' deactivated
-- 08/02/19 15:10:10.064 icegridnode: Adapter: server `IceStorm' adapter `IceStorm.TopicManager' deactivated

xdm · August 2019

Can you paste or upload the configuration files used in you last attempt so that we can try with the same configuration.

ptriantd · August 2019

Of course!

I am attaching the application xml, the config files and the bash script I am using (I have added a .txt extension because I couldn't upload them otherwise).

xdm · August 2019

I tested your configuration files and worked fine in my box, I think it might be failing to bind to one of your interfaces.

probably the Ice.Admin adapter created by IceBox, can you try adding

 <icebox id="${instance-name}" exe="icebox" activation="always">
       <option>--Ice.Trace.Network=2</option>
       <property name="Ice.Admin.Endpoints" value="tcp -h 127.0.0.1"/>
....
</icebox>

ptriantd · August 2019

Thanks José!! It worked like a charm!

Could you briefly explain what this fix means?

xdm · August 2019

The default endpoint for Ice.Admin adapter is tcp -h localhost, if your system is properly configured for ipv6 localhost usually expands to 127.0.0.1, ::1 meaning /etc/hosts have something like:

127.0.0.1       localhost
# The following lines are desirable for IPv6 capable hosts
::1     localhost ip6-localhost ip6-loopback

In this case your lo interface should have both ipv4 and ipv6 addresses

ip addr show
1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN group default qlen 1000
    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
    inet 127.0.0.1/8 scope host lo
       valid_lft forever preferred_lft forever
    inet6 ::1/128 scope host 
       valid_lft forever preferred_lft forever

I assume that your Ubuntu machine has a missconfigured ipv6 for localhost and as result the bind of tcp -h localhost was failing, it will be good to fix the ipv6 configuration and use the default endpoint.

We have a issue open in github to improve the SocketException to help debugging this issues, see https://github.com/zeroc-ice/ice/issues/389

Then regarding your configuration a few things that you can cleanup:

IceGrid.Registry.DynamicRegistration=1 This doesn't seems useful in your case as your servers are not using dynamic registration, you are defining them in the xml descriptor.

Ice.MessageSizeMax=10000000 You shouldn't need that for the registry configuration as it doesn't send large requests

IceGrid.Node.CollocateRegistry This is mean to run the registry in the same process than the node, as you are running them as separate process doesn't make sense to set this.

<dbenv name="${service}"/> This is not required for IceStorm, it doesn't use Freeze anymore.

Cheers,
José

Archived

Communication via topics does not work after transitioning from Ice 3.5 to 3.7

Comments

Categories