Error on registering local node on cluster

[Rucchao]

OrientDB Version, operating system, or hardware.

• v2.2.14

Operating System

• Linux

Expected behavior and actual behavior

Starting node in cluster for the first time
./dserver.sh (default configuration)

Steps to reproduce the problem

Error on publishing local server configuration [OHazelcastPlugin]

2017-01-05 12:35:36:350 SEVER [node1483612532316] Error on publishing local server configuration [OHazelcastPlugin]
2017-01-05 12:35:36:350 SEVER [node1483612532316] Error on registering local node on cluster [OHazelcastPlugin][node1483612532316] Error on starting distributed plugin
com.orientechnologies.orient.server.distributed.ODistributedStartupException: Error on registering local node on cluster
        at com.orientechnologies.orient.server.hazelcast.OHazelcastPlugin.startup(OHazelcastPlugin.java:213)
        at com.orientechnologies.orient.server.OServer.registerPlugins(OServer.java:1242)
        at com.orientechnologies.orient.server.OServer.activate(OServer.java:397)
        at com.orientechnologies.orient.server.OServerMain$1.run(OServerMain.java:46)
com.orientechnologies.orient.server.distributed.ODistributedStartupException: Error on starting distributed plugin
        at com.orientechnologies.orient.server.hazelcast.OHazelcastPlugin.startup(OHazelcastPlugin.java:262)
        at com.orientechnologies.orient.server.OServer.registerPlugins(OServer.java:1242)
        at com.orientechnologies.orient.server.OServer.activate(OServer.java:397)
        at com.orientechnologies.orient.server.OServerMain$1.run(OServerMain.java:46)
Caused by: com.orientechnologies.orient.server.distributed.ODistributedStartupException: Error on registering local node on cluster
        at com.orientechnologies.orient.server.hazelcast.OHazelcastPlugin.startup(OHazelcastPlugin.java:213)
        ... 3 more
 Error on publishing local server configuration [OHazelcastPlugin]

Any help would be appreciate ! Thanks !

[lvca]

We'd need the entire log, please.

[Rucchao]

2017-01-05 12:41:55:794 INFO  Loading configuration from: /chzhang/orientdb/orientdb-community-2.2.14/config/orientdb-server-config.xml... [OServerConfigurationLoaderXml]
2017-01-05 12:41:56:133 INFO  OrientDB Server v2.2.14 (build 2.2.x@r483093384e4fdbe825e2de0950f007776ee27a84; 2016-12-22 14:57:07+0000) is starting up... [OServer]
2017-01-05 12:41:56:140 INFO  Databases directory: /chzhang/orientdb/orientdb-community-2.2.14/databases [OServer]
2017-01-05 12:41:56:193 INFO  OrientDB auto-config DISKCACHE=26����188MB (heap=3����926MB direct=524����288MB os=32����162MB) [orientechnologies]
2017-01-05 12:41:56:372 INFO  Listening binary connections on 0.0.0.0:2424 (protocol v.36, socket=default) [OServerNetworkListener]
2017-01-05 12:41:56:376 INFO  Listening http connections on 0.0.0.0:2480 (protocol v.10, socket=default) [OServerNetworkListener]
2017-01-05 12:41:56:386 INFO  Installing dynamic plugin 'studio-2.2.zip'... [OServerPluginManager]
2017-01-05 12:41:56:390 INFO  ODefaultPasswordAuthenticator is active [ODefaultPasswordAuthenticator]
2017-01-05 12:41:56:391 INFO  OServerConfigAuthenticator is active [OServerConfigAuthenticator]
2017-01-05 12:41:56:392 INFO  OSystemUserAuthenticator is active [OSystemUserAuthenticator]
2017-01-05 12:41:56:416 INFO  Installed GREMLIN language v.2.6.0 - graph.pool.max=50 [OGraphServerHandler]
2017-01-05 12:41:56:531 WARNI {db=OSystem} Storage 'OSystem' was not closed properly. Will try to recover from write ahead log [OLocalPaginatedStorage]
2017-01-05 12:41:56:531 INFO  {db=OSystem} Looking for last checkpoint... [OLocalPaginatedStorage]
2017-01-05 12:41:57:010 INFO  {db=OSystem} FULL checkpoint found. [OLocalPaginatedStorage]
2017-01-05 12:41:57:011 INFO  {db=OSystem} Data restore procedure from full checkpoint is started. Restore is performed from LSN LSN{segment=0, position=129759} [OLocalPaginatedStorage]
2017-01-05 12:41:57:014 WARNI {db=OSystem} Record com.orientechnologies.orient.core.storage.impl.local.paginated.wal.OCheckpointEndRecord{lsn=LSN{segment=0, position=129783}} will be skipped during data restore [OLocalPaginatedStorage]
2017-01-05 12:41:57:015 INFO  {db=OSystem} 1 operations were processed, current LSN is LSN{segment=0, position=129783} last LSN is LSN{segment=0, position=367251} [OLocalPaginatedStorage]
2017-01-05 12:41:57:017 WARNI {db=OSystem} Non tx operation was used during data modification we will need index rebuild. [OLocalPaginatedStorage]
2017-01-05 12:41:57:066 INFO  {db=OSystem} Storage data recover was completed [OLocalPaginatedStorage]
2017-01-05 12:41:57:601 INFO  {db=OSystem} Wait till indexes restore after crash was finished. [OIndexManagerShared]
2017-01-05 12:41:57:727 INFO  {db=OSystem} Start creation of index 'ORole.name' [OIndexManagerShared$RecreateIndexesTask]
2017-01-05 12:41:57:945 INFO  {db=OSystem} Index 'ORole.name' was successfully created and rebuild is going to be started [OIndexManagerShared$RecreateIndexesTask]
2017-01-05 12:41:58:294 INFO  {db=OSystem} - Rebuilding index OSystem.ORole.name (estimated 3 items)... [OIndexRebuildOutputListener]
2017-01-05 12:41:58:303 INFO  {db=OSystem} --> OK, indexed 3 items in 9 ms [OIndexRebuildOutputListener]
2017-01-05 12:41:58:311 INFO  {db=OSystem} Rebuild of 'ORole.name index was successfully finished [OIndexManagerShared$RecreateIndexesTask]
2017-01-05 12:41:58:402 INFO  {db=OSystem} Start creation of index 'OUser.name' [OIndexManagerShared$RecreateIndexesTask]
2017-01-05 12:41:58:594 INFO  {db=OSystem} Index 'OUser.name' was successfully created and rebuild is going to be started [OIndexManagerShared$RecreateIndexesTask]
2017-01-05 12:41:58:886 INFO  {db=OSystem} Rebuild of 'OUser.name index was successfully finished [OIndexManagerShared$RecreateIndexesTask]
2017-01-05 12:41:58:889 INFO  {db=OSystem} Index 'dictionary' is not automatic index and will be added as is [OIndexManagerShared$RecreateIndexesTask]
2017-01-05 12:41:58:889 INFO  {db=OSystem} Index 'dictionary' was added in DB index list [OIndexManagerShared$RecreateIndexesTask]
2017-01-05 12:41:59:077 INFO  {db=OSystem} Start creation of index 'OFunction.name' [OIndexManagerShared$RecreateIndexesTask]
2017-01-05 12:41:59:512 INFO  {db=OSystem} Index 'OFunction.name' was successfully created and rebuild is going to be started [OIndexManagerShared$RecreateIndexesTask]
2017-01-05 12:42:00:137 INFO  {db=OSystem} Rebuild of 'OFunction.name index was successfully finished [OIndexManagerShared$RecreateIndexesTask]
2017-01-05 12:42:00:147 INFO  {db=OSystem} 4 indexes were restored successfully, 0 errors [OIndexManagerShared$RecreateIndexesTask]
2017-01-05 12:42:00:911 INFO  {db=OSystem} Indexes restore after crash was finished. [OIndexManagerShared]
2017-01-05 12:42:01:062 INFO  Configuring Hazelcast from '/chzhang/orientdb/orientdb-community-2.2.14/config/hazelcast.xml'. [FileSystemXmlConfig]
2017-01-05 12:42:01:123 WARNI Name of the hazelcast schema location incorrect using default [AbstractXmlConfigHelper]
2017-01-05 12:42:01:397 INFO  [LOCAL] [orientdb] [3.6.5] Prefer IPv4 stack is true. [DefaultAddressPicker]
2017-01-05 12:42:01:407 INFO  [LOCAL] [orientdb] [3.6.5] Picked Address[x]:2434, using socket ServerSocket[addr=/0:0:0:0:0:0:0:0,localport=2434], bind any local is true [DefaultAddressPicker]
2017-01-05 12:42:01:421 INFO  [x]:2434 [orientdb] [3.6.5] Hazelcast 3.6.5 (20160823 - e4af3d9) starting at Address[x]:2434 [system]
2017-01-05 12:42:01:421 INFO  [x]:2434 [orientdb] [3.6.5] Copyright (c) 2008-2016, Hazelcast, Inc. All Rights Reserved. [system]
2017-01-05 12:42:01:421 INFO  [x]:2434 [orientdb] [3.6.5] Configured Hazelcast Serialization version : 1 [system]
2017-01-05 12:42:01:629 INFO  [x]:2434 [orientdb] [3.6.5] Backpressure is disabled [OperationService]
2017-01-05 12:42:01:656 INFO  [x]:2434 [orientdb] [3.6.5] Starting with 1 generic operation threads and 1 partition operation threads. [ClassicOperationExecutor]
2017-01-05 12:42:02:061 INFO  [x]:2434 [orientdb] [3.6.5] Creating MulticastJoiner [Node]
2017-01-05 12:42:02:065 INFO  [x]:2434 [orientdb] [3.6.5] Address[x]:2434 is STARTING [LifecycleService]
2017-01-05 12:42:02:158 INFO  [x]:2434 [orientdb] [3.6.5] TcpIpConnectionManager configured with Non Blocking IO-threading model: 3 input threads and 3 output threads [NonBlockingIOThreadingModel]
2017-01-05 12:42:04:309 INFO  [x]:2434 [orientdb] [3.6.5] 


Members [1] {
	Member [x]:2434 this
}
 [MulticastJoiner]
2017-01-05 12:42:04:340 INFO  [x]:2434 [orientdb] [3.6.5] Address[x]:2434 is STARTED [LifecycleService]
2017-01-05 12:42:04:340 INFO  Starting distributed server 'node1483612532316' (hzID=c3840337-7990-4f49-bbf7-54d5a2e351c0)... [OHazelcastPlugin]
2017-01-05 12:42:04:344 INFO  Distributed cluster time=Thu Jan 05 12:42:04 EET 2017 (delta from local node=0)... [OHazelcastPlugin]
2017-01-05 12:42:04:384 INFO  [x]:2434 [orientdb] [3.6.5] Initializing cluster partition table arrangement... [InternalPartitionService]
2017-01-05 12:42:04:438 INFO  [x]:2434 [orientdb] [3.6.5] Partition assignments changed while executing query: TruePredicate{} [MapQueryEngineImpl]
2017-01-05 12:42:04:475 INFO  [node1483612532316] Loaded configuration for database 'OSystem' from disk: /chzhang/orientdb/orientdb-community-2.2.14/config/default-distributed-db-config.json [ODistributedStorage]
2017-01-05 12:42:04:485 WARNI [node1483612532316] Servers in cluster: [node1483612532316] [OHazelcastPlugin]
2017-01-05 12:42:04:492 SEVER [node1483612532316] Error on publishing local server configuration [OHazelcastPlugin]
2017-01-05 12:42:04:493 SEVER [node1483612532316] Error on registering local node on cluster [OHazelcastPlugin][node1483612532316] Error on starting distributed plugin
com.orientechnologies.orient.server.distributed.ODistributedStartupException: Error on registering local node on cluster
	at com.orientechnologies.orient.server.hazelcast.OHazelcastPlugin.startup(OHazelcastPlugin.java:213)
	at com.orientechnologies.orient.server.OServer.registerPlugins(OServer.java:1242)
	at com.orientechnologies.orient.server.OServer.activate(OServer.java:397)
	at com.orientechnologies.orient.server.OServerMain$1.run(OServerMain.java:46)

[Rucchao]

I am wondering if it is caused by any files which need read or wirte rights ?

[lvca]

It looks like the starting node is unable to register on Hazelcast cluster. Could you try to replace x with your actual ip address? Try with 127.0.0.1 first.

[Rucchao]

Could you please tell me in which file should i configure this ip ? Thanks.

[Rucchao]

Hi, lvca:
I changed the hazelcast.html to this:

<network>
	<port auto-increment="true">2434</port>
	<join>
		<multicast enabled="false">
			<multicast-group>235.1.1.1</multicast-group>
			<multicast-port>2434</multicast-port>
		</multicast>
  <tcp-ip enabled="true">
    <member>127.0.0.1:2434</member>
  </tcp-ip>
</join>
</network>
<executor-service>
	<pool-size>16</pool-size>
</executor-service>

The problem remains.

[Rucchao]

Now I have no ideas, the log is as follows:

2017-01-05 13:21:10:264 INFO  Loading configuration from: /chzhang/orientdb/orientdb-community-2.2.14/config/orientdb-server-config.xml... [OServerConfigurationLoaderXml]
2017-01-05 13:21:10:603 INFO  OrientDB Server v2.2.14 (build 2.2.x@r483093384e4fdbe825e2de0950f007776ee27a84; 2016-12-22 14:57:07+0000) is starting up... [OServer]
2017-01-05 13:21:10:610 INFO  Databases directory: /chzhang/orientdb/orientdb-community-2.2.14/databases [OServer]
2017-01-05 13:21:10:663 INFO  OrientDB auto-config DISKCACHE=26����188MB (heap=3����926MB direct=524����288MB os=32����162MB) [orientechnologies]
2017-01-05 13:21:10:842 WARNI Port 0.0.0.0:2424 busy, trying the next available... [OServerNetworkListener]
2017-01-05 13:21:10:842 WARNI Port 0.0.0.0:2425 busy, trying the next available... [OServerNetworkListener]
2017-01-05 13:21:10:843 WARNI Port 0.0.0.0:2426 busy, trying the next available... [OServerNetworkListener]
2017-01-05 13:21:10:844 INFO  Listening binary connections on 0.0.0.0:2427 (protocol v.36, socket=default) [OServerNetworkListener]
2017-01-05 13:21:10:847 WARNI Port 0.0.0.0:2480 busy, trying the next available... [OServerNetworkListener]
2017-01-05 13:21:10:848 WARNI Port 0.0.0.0:2481 busy, trying the next available... [OServerNetworkListener]
2017-01-05 13:21:10:849 WARNI Port 0.0.0.0:2482 busy, trying the next available... [OServerNetworkListener]
2017-01-05 13:21:10:849 INFO  Listening http connections on 0.0.0.0:2483 (protocol v.10, socket=default) [OServerNetworkListener]
2017-01-05 13:21:10:859 INFO  Installing dynamic plugin 'studio-2.2.zip'... [OServerPluginManager]
2017-01-05 13:21:10:863 INFO  ODefaultPasswordAuthenticator is active [ODefaultPasswordAuthenticator]
2017-01-05 13:21:10:864 INFO  OServerConfigAuthenticator is active [OServerConfigAuthenticator]
2017-01-05 13:21:10:865 INFO  OSystemUserAuthenticator is active [OSystemUserAuthenticator]
2017-01-05 13:21:10:889 INFO  Installed GREMLIN language v.2.6.0 - graph.pool.max=50 [OGraphServerHandler]
2017-01-05 13:21:10:968 SEVER {db=OSystem} File lock is null , file lock is not released [OPaginatedStorageDirtyFlag]
2017-01-05 13:21:10:968 SEVER getUser() Exception: Cannot open local storage '/chzhang/orientdb/orientdb-community-2.2.14/databases/OSystem' with mode=rw
	DB name="OSystem" [OSystemUserAuthenticator]
2017-01-05 13:21:11:042 INFO  Configuring Hazelcast from '/chzhang/orientdb/orientdb-community-2.2.14/config/hazelcast.xml'. [FileSystemXmlConfig]
2017-01-05 13:21:11:101 WARNI Name of the hazelcast schema location incorrect using default [AbstractXmlConfigHelper]
2017-01-05 13:21:11:374 INFO  [LOCAL] [orientdb] [3.6.5] Interfaces is disabled, trying to pick one address from TCP-IP config addresses: [127.0.0.1] [DefaultAddressPicker]
2017-01-05 13:21:11:380 INFO  [LOCAL] [orientdb] [3.6.5] Picked Address[127.0.0.1]:2436, using socket ServerSocket[addr=/0:0:0:0:0:0:0:0,localport=2436], bind any local is true [DefaultAddressPicker]
2017-01-05 13:21:11:394 INFO  [127.0.0.1]:2436 [orientdb] [3.6.5] Hazelcast 3.6.5 (20160823 - e4af3d9) starting at Address[127.0.0.1]:2436 [system]
2017-01-05 13:21:11:394 INFO  [127.0.0.1]:2436 [orientdb] [3.6.5] Copyright (c) 2008-2016, Hazelcast, Inc. All Rights Reserved. [system]
2017-01-05 13:21:11:394 INFO  [127.0.0.1]:2436 [orientdb] [3.6.5] Configured Hazelcast Serialization version : 1 [system]
2017-01-05 13:21:11:611 INFO  [127.0.0.1]:2436 [orientdb] [3.6.5] Backpressure is disabled [OperationService]
2017-01-05 13:21:11:640 INFO  [127.0.0.1]:2436 [orientdb] [3.6.5] Starting with 1 generic operation threads and 1 partition operation threads. [ClassicOperationExecutor]
2017-01-05 13:21:12:050 INFO  [127.0.0.1]:2436 [orientdb] [3.6.5] Creating TcpIpJoiner [Node]
2017-01-05 13:21:12:052 INFO  [127.0.0.1]:2436 [orientdb] [3.6.5] Address[127.0.0.1]:2436 is STARTING [LifecycleService]
2017-01-05 13:21:12:142 INFO  [127.0.0.1]:2436 [orientdb] [3.6.5] TcpIpConnectionManager configured with Non Blocking IO-threading model: 3 input threads and 3 output threads [NonBlockingIOThreadingModel]
2017-01-05 13:21:12:161 INFO  [127.0.0.1]:2436 [orientdb] [3.6.5] Connecting to /127.0.0.1:2434, timeout: 0, bind-any: true [InitConnectionTask]
2017-01-05 13:21:12:168 INFO  [127.0.0.1]:2436 [orientdb] [3.6.5] Established socket connection between /127.0.0.1:35170 and /127.0.0.1:2434 [TcpIpConnectionManager]
2017-01-05 13:21:17:160 INFO  [127.0.0.1]:2436 [orientdb] [3.6.5] 


Members [1] {
	Member [127.0.0.1]:2436 this
}
 [TcpIpJoiner]
2017-01-05 13:21:17:161 WARNI [127.0.0.1]:2436 [orientdb] [3.6.5] Config seed port is 2434 and cluster size is 1. Some of the ports seem occupied! [Node]
2017-01-05 13:21:17:190 INFO  [127.0.0.1]:2436 [orientdb] [3.6.5] Address[127.0.0.1]:2436 is STARTED [LifecycleService]
2017-01-05 13:21:17:191 INFO  Starting distributed server 'node1483612532316' (hzID=20eec784-5a73-4e40-ad9e-c50b4e6d4ce2)... [OHazelcastPlugin]
2017-01-05 13:21:17:195 INFO  Distributed cluster time=Thu Jan 05 13:21:17 EET 2017 (delta from local node=0)... [OHazelcastPlugin]
2017-01-05 13:21:17:232 INFO  [127.0.0.1]:2436 [orientdb] [3.6.5] Initializing cluster partition table arrangement... [InternalPartitionService]
2017-01-05 13:21:17:289 INFO  [127.0.0.1]:2436 [orientdb] [3.6.5] Partition assignments changed while executing query: TruePredicate{} [MapQueryEngineImpl]
2017-01-05 13:21:17:329 INFO  [node1483612532316] Loaded configuration for database 'OSystem' from disk: /chzhang/orientdb/orientdb-community-2.2.14/config/default-distributed-db-config.json [ODistributedStorage]
2017-01-05 13:21:17:339 WARNI [node1483612532316] Servers in cluster: [node1483612532316] [OHazelcastPlugin]
2017-01-05 13:21:17:353 SEVER [node1483612532316] Error on publishing local server configuration [OHazelcastPlugin]
2017-01-05 13:21:17:353 SEVER [node1483612532316] Error on registering local node on cluster [OHazelcastPlugin][node1483612532316] Error on starting distributed plugin
com.orientechnologies.orient.server.distributed.ODistributedStartupException: Error on registering local node on cluster
	at com.orientechnologies.orient.server.hazelcast.OHazelcastPlugin.startup(OHazelcastPlugin.java:213)
	at com.orientechnologies.orient.server.OServer.registerPlugins(OServer.java:1242)
	at com.orientechnologies.orient.server.OServer.activate(OServer.java:397)
	at com.orientechnologies.orient.server.OServerMain$1.run(OServerMain.java:46)

[Rucchao]

I also try my own ip, the issue remains.

[CrazyBeeline]

Dear friend
I have the same problems
if you save the problem
Please tell me the solution

[Rucchao]

Hi, @CrazyBeeline , I still have this problem, even the different nodes can established the socket connection, maybe @lvca can fix it and make it more steady later.

[lvca]

Hi guys, I'm unable to reproduce it. Could you please try with last version on 2.2.x branch?

[CrazyBeeline]

Dear friend
This problem is solved when I use a low version (2.2.13)
But my colleagues have successfully installed the 2.2.14 version
In view of the fact that we installed on different machines all should feel server environment problems
I hope my experience can help you