Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Altering cluster configuration leads to orientdb node deadlock #8298

Closed
CyprienGottstein opened this issue May 29, 2018 · 3 comments
Closed
Assignees

Comments

@CyprienGottstein
Copy link

OrientDB Version: 2.2.30

Java Version: 1.8.0_171

OS: Ubuntu 16.04

Hi,

I am facing an issue where my OrientDB cluster fails to properly synchronize and never ever gets up. I created a whole bunch of class to prepare for my application to run, OrientDB build automatically 8 clusters for those classes as each of the nodes of my cluster have 8 cores.

Everything is fine at this point, then i added some configuration into the default-distributed-db-config.json in order to reduce the clusters replication because i wanted to scale up on writes, the file looks like this :

{
"autoDeploy": true,
"readQuorum": 1,
"writeQuorum": "majority",
"executionMode": "asynchronous",
"readYourWrites": true,
"newNodeStrategy": "static",
"servers": {
"": "master"
},
"clusters": {
"internal": {
},
"myclass" : {
"servers" : ["instance1", "instance2"]
},
"myclass_1" : {
"servers" : ["instance1", "instance2"]
},
"myclass_2" : {
"servers" : ["instance2", "instance3"]
},
"myclass_3" : {
"servers" : ["instance3", "instance1"]
},
"myclass_4" : {
"servers" : ["instance1", "instance2"]
},
"myclass_5" : {
"servers" : ["instance2", "instance3"]
},
"myclass_6" : {
"servers" : ["instance3", "instance1"]
},
"myclass_7" : {
"servers" : ["instance2", "instance3"]
},
"
": {
"servers": ["<NEW_NODE>"]
}
}
}

To make sure the new clusters configuration is used by all of the nodes, i shut off the orientdb service on each of the instances of the cluster, removed the file distributed-config.json (again on each of the instances of the cluster) and the rebooted orientdb.

The file distributed-config.json has been regenerated and looks like so (Mind that its incomplete, i can't show the whole file as it reveals sensitive information regarding our data model) :

{
"clusters":{
"@type":"d",
"@Version":0,
"internal":{
"@type":"d",
"@Version":0
},
"myclass":{
"@type":"d",
"@Version":0,
"servers":[
"instance1",
"instance2"
]
},
"myclass_1":{
"@type":"d",
"@Version":0,
"servers":[
"instance1",
"instance2"
]
},
"myclass_2":{
"@type":"d",
"@Version":0,
"servers":[
"instance2",
"instance3"
]
},
"myclass_3":{
"@type":"d",
"@Version":0,
"servers":[
"instance1",
"instance3"
]
},
"myclass_4":{
"@type":"d",
"@Version":0,
"servers":[
"instance1",
"instance2"
]
},
"myclass_5":{
"@type":"d",
"@Version":0,
"servers":[
"instance3",
"instance2"
]
},
"myclass_6":{
"@type":"d",
"@Version":0,
"servers":[
"instance1",
"instance3"
]
},
"myclass_7":{
"@type":"d",
"@Version":0,
"servers":[
"instance2",
"instance3"
]
}
}
}

Two of the nodes of the cluster managed to come ONLINE but the last one is stuck transferring chunks... Instance2 is blocked at STARTING , endlessly receiving the same chunk from instance3.

Expected behavior

Instance2 moving from STARTING to ONLINE

Actual behavior

The node instance3 is blocked into transferring chunk.

log of instance3 :

2018-05-29 09:38:36:332 INFO [instance3]->[instance2] - transferring chunk #179443 offset=741652 size=8388608... [OCopyDatabaseChunkTask]
2018-05-29 09:38:36:358 INFO [instance3]->[instance2] - transferring chunk #179444 offset=741652 size=8388608... [OCopyDatabaseChunkTask]
2018-05-29 09:38:36:380 INFO [instance3]->[instance2] - transferring chunk #179445 offset=741652 size=8388608... [OCopyDatabaseChunkTask]
2018-05-29 09:38:36:402 INFO [instance3]->[instance2] - transferring chunk #179446 offset=741652 size=8388608... [OCopyDatabaseChunkTask]
2018-05-29 09:38:36:424 INFO [instance3]->[instance2] - transferring chunk #179447 offset=741652 size=8388608... [OCopyDatabaseChunkTask]
2018-05-29 09:38:36:448 INFO [instance3]->[instance2] - transferring chunk #179448 offset=741652 size=8388608... [OCopyDatabaseChunkTask]
2018-05-29 09:38:36:471 INFO [instance3]->[instance2] - transferring chunk #179449 offset=741652 size=8388608... [OCopyDatabaseChunkTask]
2018-05-29 09:38:36:494 INFO [instance3]->[instance2] - transferring chunk #179450 offset=741652 size=8388608... [OCopyDatabaseChunkTask]
2018-05-29 09:38:36:516 INFO [instance3]->[instance2] - transferring chunk #179451 offset=741652 size=8388608... [OCopyDatabaseChunkTask]
2018-05-29 09:38:36:538 INFO [instance3]->[instance2] - transferring chunk #179452 offset=741652 size=8388608... [OCopyDatabaseChunkTask]
2018-05-29 09:38:36:561 INFO [instance3]->[instance2] - transferring chunk #179453 offset=741652 size=8388608... [OCopyDatabaseChunkTask]
2018-05-29 09:38:36:584 INFO [instance3]->[instance2] - transferring chunk #179454 offset=741652 size=8388608... [OCopyDatabaseChunkTask]
2018-05-29 09:38:36:606 INFO [instance3]->[instance2] - transferring chunk #179455 offset=741652 size=8388608... [OCopyDatabaseChunkTask]
2018-05-29 09:38:36:628 INFO [instance3]->[instance2] - transferring chunk #179456 offset=741652 size=8388608... [OCopyDatabaseChunkTask]
2018-05-29 09:38:36:650 INFO [instance3]->[instance2] - transferring chunk #179457 offset=741652 size=8388608... [OCopyDatabaseChunkTask]
2018-05-29 09:38:36:673 INFO [instance3]->[instance2] - transferring chunk #179458 offset=741652 size=8388608... [OCopyDatabaseChunkTask]
2018-05-29 09:38:36:695 INFO [instance3]->[instance2] - transferring chunk #179459 offset=741652 size=8388608... [OCopyDatabaseChunkTask]
2018-05-29 09:38:36:725 INFO [instance3]->[instance2] - transferring chunk #179460 offset=741652 size=8388608... [OCopyDatabaseChunkTask]
2018-05-29 09:38:36:748 INFO [instance3]->[instance2] - transferring chunk #179461 offset=741652 size=8388608... [OCopyDatabaseChunkTask]
2018-05-29 09:38:36:770 INFO [instance3]->[instance2] - transferring chunk #179462 offset=741652 size=8388608... [OCopyDatabaseChunkTask]
2018-05-29 09:38:36:792 INFO [instance3]->[instance2] - transferring chunk #179463 offset=741652 size=8388608... [OCopyDatabaseChunkTask]
2018-05-29 09:38:36:819 INFO [instance3]->[instance2] - transferring chunk #179464 offset=741652 size=8388608... [OCopyDatabaseChunkTask]
2018-05-29 09:38:36:844 INFO [instance3]->[instance2] - transferring chunk #179465 offset=741652 size=8388608... [OCopyDatabaseChunkTask]
2018-05-29 09:38:36:875 INFO [instance3]->[instance2] - transferring chunk #179466 offset=741652 size=8388608... [OCopyDatabaseChunkTask]
2018-05-29 09:38:36:901 INFO [instance3]->[instance2] - transferring chunk #179467 offset=741652 size=8388608... [OCopyDatabaseChunkTask]
2018-05-29 09:38:36:924 INFO [instance3]->[instance2] - transferring chunk #179468 offset=741652 size=8388608... [OCopyDatabaseChunkTask]
2018-05-29 09:38:36:946 INFO [instance3]->[instance2] - transferring chunk #179469 offset=741652 size=8388608... [OCopyDatabaseChunkTask]
2018-05-29 09:38:36:968 INFO [instance3]->[instance2] - transferring chunk #179470 offset=741652 size=8388608... [OCopyDatabaseChunkTask]

log of instance2:

2018-05-29 09:52:14:100 INFO [instance2] Node is not online yet (status=STARTING), blocking the command until it is online (retry=2550, queue=1 worker=-4 firstMsg=id=0.162 task=gossip timestamp: 1527582456752 lockManagerServer: thingin1) [ODistributedWorker]
2018-05-29 09:52:16:101 INFO [instance2] Node is not online yet (status=STARTING), blocking the command until it is online (retry=2551, queue=1 worker=-4 firstMsg=id=0.162 task=gossip timestamp: 1527582456752 lockManagerServer: thingin1) [ODistributedWorker]
2018-05-29 09:52:18:102 INFO [instance2] Node is not online yet (status=STARTING), blocking the command until it is online (retry=2552, queue=1 worker=-4 firstMsg=id=0.162 task=gossip timestamp: 1527582456752 lockManagerServer: thingin1) [ODistributedWorker]
2018-05-29 09:52:20:103 INFO [instance2] Node is not online yet (status=STARTING), blocking the command until it is online (retry=2553, queue=1 worker=-4 firstMsg=id=0.162 task=gossip timestamp: 1527582456752 lockManagerServer: thingin1) [ODistributedWorker]

log of instance1:

2018-05-29 09:52:32:065 WARNI [instance1] Timeout (10007ms) on waiting for synchronous responses from nodes=[instance2, instance3] responsesSoFar=[instance3] request=(id=0.669 task=gossip timestamp: 1527587542057 lockManagerServer: instance1) [ODistributedDatabaseImpl]
2018-05-29 09:52:32:066 WARNI [instance1]->[instance2] Server 'instance2' did not respond to the gossip message (db=mydb-dev, timeout=10000ms), but cannot be set OFFLINE by configuration [OClusterHealthChecker]
2018-05-29 09:52:42:075 WARNI [instance1]->[instance2] Server 'instance2' did not respond to the gossip message (db=GratefulDeadConcerts, timeout=10000ms), but cannot be set OFFLINE by configuration [OClusterHealthChecker]
2018-05-29 09:52:52:079 WARNI [instance1]->[instance2] Server 'instance2' did not respond to the gossip message (db=mydb-dev, timeout=10000ms), but cannot be set OFFLINE by configuration [OClusterHealthChecker]
2018-05-29 09:53:02:093 WARNI [instance1]->[instance2] Server 'instance2' did not respond to the gossip message (db=GratefulDeadConcerts, timeout=10000ms), but cannot be set OFFLINE by configuration [OClusterHealthChecker]
2018-05-29 09:53:12:099 WARNI [instance1]->[instance2] Server 'instance2' did not respond to the gossip message (db=mydb-dev, timeout=10000ms), but cannot be set OFFLINE by configuration [OClusterHealthChecker]
2018-05-29 09:53:22:116 WARNI [instance1]->[

And when i log to the database it shows me that :
CONFIGURED SERVERS

+----+--------+--------+-----------+-------------------+----------------+----------------+-----------------+---------------+---------+
|# |Name |Status |Connections|StartedOn |Binary |HTTP |UsedMemory |FreeMemory |MaxMemory|
+----+--------+--------+-----------+-------------------+----------------+----------------+-----------------+---------------+---------+
|0 |instance2|STARTING|0 |2018-05-29 08:26:49|x.x.x.x:2424|x.x.x.x:2480|292.62MB (7.45%) |3.55GB (92.55%)|3.83GB |
|1 |instance1|ONLINE |5 |2018-05-29 08:01:14|x.x.x.x:2424|x.x.x.x:2480|467.69MB (11.68%)|3.45GB (88.32%)|3.91GB |
|2 |instance3|ONLINE |4 |2018-05-29 08:01:30|x.x.x.x:2424|x.x.x.x:2480|1.42GB (35.55%) |2.58GB (64.45%)|4.00GB |
+----+--------+--------+-----------+-------------------+----------------+----------------+-----------------+---------------+---------+

Steps to reproduce

Hard to reproduce for now, all i can say is that it kind of managed to make it work with an empty database, once the database had a minimum of data to work with, it crashed. We currently have around 7.5 millions records (vertex and edges) into this OrientDB database, i did the same on a tinier database with around 300k records, it also crashed.

I also tried before that with an other database to change a cluster name using the command
alter cluster cluster name
but it hanged forever, corrupted the dabatase and i had no choice but to purge it by hand from the disks.

The server was running "fine" before that, we already had problems but no concerns with the current issue. Everything is okay in our network, the ports are all open, otherwise we wouldn't have been able to make anything work at all. Its all was triggered because we changed something in the cluster configuration.

Now i have several questions :

  • What is doing instance3 sending over and over the same data chunk ?
  • Why is there network traffic between instance3 and instance2 if its to be blocked on the same chunk all day long ? We only have 3 GB of data to work with, given the size of our machines with each 8 core and 16GB, how come we have this kind of result ?
  • Why is there no errors shown in the logs instance2 ?

Best Regards,

Cyprien Gottstein.

@CyprienGottstein
Copy link
Author

CyprienGottstein commented May 29, 2018

I managed to reproduce the scenario, one of node was blocked in the same manner as described above and this is the corresponding logs.

IMPORTANT : I removed the configuration used for the cluster assignment. Didn't helped much.

blocked node

2018-05-29 13:14:28:987 INFO [instance3] - writing chunk #151 offset=419417370 size=742b [OHazelcastPlugin]
2018-05-29 13:14:28:996 INFO [instance3] - writing chunk #152 offset=419418112 size=1.77MB [OHazelcastPlugin]
2018-05-29 13:14:29:029 INFO [instance3] - writing chunk #153 offset=421269504 size=6.23MB [OHazelcastPlugin]
2018-05-29 13:14:30:627 INFO [instance3] Node is not online yet (status=STARTING), blocking the command until it is online (retry=80, queue=15 worker=-4 firstMsg=id=0.11 task=gossip timestamp: 15275995294
66 lockManagerServer: instance1) [ODistributedWorker]
2018-05-29 13:14:30:812 INFO [instance3] - writing chunk #154 offset=427805804 size=916b [OHazelcastPlugin]
2018-05-29 13:14:30:825 INFO [instance3] - writing chunk #155 offset=427806720 size=2.26MB [OHazelcastPlugin]
2018-05-29 13:14:30:849 INFO [instance3] - writing chunk #156 offset=430178304 size=3.94MB [OHazelcastPlugin]
2018-05-29 13:14:30:861 INFO [instance3] Database copied correctly, size=414.19MB [ODistributedAbstractPlugin$5]
2018-05-29 13:14:31:263 WARNI {db=mydb} Storage 'mydb' was not closed properly. Will try to recover from write ahead log... [OLocalPaginatedStorage]
2018-05-29 13:14:31:263 WARNI {db=mydb} Restore is not possible because write ahead log is empty. [OLocalPaginatedStorage]
2018-05-29 13:14:31:370 INFO {db=mydb} Storage data recover was completed [OLocalPaginatedStorage]

node sending chunks into the void

2018-05-29 13:14:23:039 INFO [instance2]->[instance3] - transferring chunk #1 offset=0 size=721629... [OSyncClusterTask]
2018-05-29 13:14:23:039 INFO [instance2]->[instance3] Deploy cluster myclass_7 task completed [OSyncClusterTask]
2018-05-29 13:14:23:059 INFO [instance2]->[instance3] - transferring chunk #2 offset=721629 size=99403... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:062 INFO [instance2]->[instance3] - transferring chunk #3 offset=721629 size=119584... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:065 INFO [instance2]->[instance3] - transferring chunk #4 offset=721629 size=139320... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:069 INFO [instance2]->[instance3] - transferring chunk #5 offset=721629 size=139320... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:071 INFO [instance2]->[instance3] - transferring chunk #6 offset=721629 size=159425... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:074 INFO [instance2]->[instance3] - transferring chunk #7 offset=721629 size=159425... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:077 INFO [instance2]->[instance3] - transferring chunk #8 offset=721629 size=179243... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:079 INFO [instance2]->[instance3] - transferring chunk #9 offset=721629 size=199278... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:082 INFO [instance2]->[instance3] - transferring chunk #10 offset=721629 size=199278... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:085 INFO [instance2]->[instance3] - transferring chunk #11 offset=721629 size=219350... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:089 INFO [instance2]->[instance3] - transferring chunk #12 offset=721629 size=239093... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:092 INFO [instance2]->[instance3] - transferring chunk #13 offset=721629 size=239093... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:096 INFO [instance2]->[instance3] - transferring chunk #14 offset=721629 size=258989... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:099 INFO [instance2]->[instance3] - transferring chunk #15 offset=721629 size=278940... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:102 INFO [instance2]->[instance3] - transferring chunk #16 offset=721629 size=298761... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:106 INFO [instance2]->[instance3] - transferring chunk #17 offset=721629 size=298761... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:110 INFO [instance2]->[instance3] - transferring chunk #18 offset=721629 size=319008... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:114 INFO [instance2]->[instance3] - transferring chunk #19 offset=721629 size=339011... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:117 INFO [instance2]->[instance3] - transferring chunk #20 offset=721629 size=358907... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:121 INFO [instance2]->[instance3] - transferring chunk #21 offset=721629 size=378904... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:133 INFO [instance2]->[instance3] - transferring chunk #22 offset=721629 size=438272... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:136 INFO [instance2]->[instance3] - transferring chunk #23 offset=721629 size=438639... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:141 INFO [instance2]->[instance3] - transferring chunk #24 offset=721629 size=458704... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:145 INFO [instance2]->[instance3] - transferring chunk #25 offset=721629 size=478785... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:150 INFO [instance2]->[instance3] - transferring chunk #26 offset=721629 size=498743... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:154 INFO [instance2]->[instance3] - transferring chunk #27 offset=721629 size=518736... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:158 INFO [instance2]->[instance3] - transferring chunk #28 offset=721629 size=538528... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:162 INFO [instance2]->[instance3] - transferring chunk #29 offset=721629 size=558441... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:167 INFO [instance2]->[instance3] - transferring chunk #30 offset=721629 size=578271... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:171 INFO [instance2]->[instance3] - transferring chunk #31 offset=721629 size=597989... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:176 INFO [instance2]->[instance3] - transferring chunk #32 offset=721629 size=618128... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:181 INFO [instance2]->[instance3] - transferring chunk #33 offset=721629 size=637893... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:185 INFO [instance2]->[instance3] - transferring chunk #34 offset=721629 size=657886... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:191 INFO [instance2]->[instance3] - transferring chunk #35 offset=721629 size=677785... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:195 INFO [instance2]->[instance3] - transferring chunk #36 offset=721629 size=697722... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:201 INFO [instance2]->[instance3] - transferring chunk #37 offset=721629 size=737935... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:206 INFO [instance2]->[instance3] - transferring chunk #38 offset=721629 size=758001... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:210 INFO [instance2]->[instance3] - transferring chunk #39 offset=721629 size=778012... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:215 INFO [instance2]->[instance3] - transferring chunk #40 offset=721629 size=797816... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:220 INFO [instance2]->[instance3] - transferring chunk #41 offset=721629 size=817810... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:226 INFO [instance2]->[instance3] - transferring chunk #42 offset=721629 size=837719... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:231 INFO [instance2]->[instance3] - transferring chunk #43 offset=721629 size=857641... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:236 INFO [instance2]->[instance3] - transferring chunk #44 offset=721629 size=877707... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:240 INFO [instance2]->[instance3] - transferring chunk #45 offset=721629 size=897427... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:245 INFO [instance2]->[instance3] - transferring chunk #46 offset=721629 size=917469... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:250 INFO [instance2]->[instance3] - transferring chunk #47 offset=721629 size=937507... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:255 INFO [instance2]->[instance3] - transferring chunk #48 offset=721629 size=957394... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:261 INFO [instance2]->[instance3] - transferring chunk #49 offset=721629 size=996944... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:267 INFO [instance2]->[instance3] - transferring chunk #50 offset=721629 size=1017432... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:272 INFO [instance2]->[instance3] - transferring chunk #51 offset=721629 size=1037249... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:278 INFO [instance2]->[instance3] - transferring chunk #52 offset=721629 size=1057085... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:283 INFO [instance2]->[instance3] - transferring chunk #53 offset=721629 size=1096556... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:287 INFO [instance2]->[instance3] - transferring chunk #54 offset=721629 size=1117015... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:293 INFO [instance2]->[instance3] - transferring chunk #55 offset=721629 size=1136996... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:299 INFO [instance2]->[instance3] - transferring chunk #56 offset=721629 size=1156804... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:304 INFO [instance2]->[instance3] - transferring chunk #57 offset=721629 size=1176849... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:310 INFO [instance2]->[instance3] - transferring chunk #58 offset=721629 size=1216692... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:316 INFO [instance2]->[instance3] - transferring chunk #59 offset=721629 size=1236573... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:322 INFO [instance2]->[instance3] - transferring chunk #60 offset=721629 size=1256513... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:329 INFO [instance2]->[instance3] - transferring chunk #61 offset=721629 size=1296394... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:335 INFO [instance2]->[instance3] - transferring chunk #62 offset=721629 size=1316347... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:343 INFO [instance2]->[instance3] - transferring chunk #63 offset=721629 size=1356117... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:351 INFO [instance2]->[instance3] - transferring chunk #64 offset=721629 size=1396048... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:358 INFO [instance2]->[instance3] - transferring chunk #65 offset=721629 size=1416128... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:365 INFO [instance2]->[instance3] - transferring chunk #66 offset=721629 size=1456092... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:373 INFO [instance2]->[instance3] - transferring chunk #67 offset=721629 size=1495953... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:380 INFO [instance2]->[instance3] - transferring chunk #68 offset=721629 size=1516204... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:387 INFO [instance2]->[instance3] - transferring chunk #69 offset=721629 size=1555989... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:394 INFO [instance2]->[instance3] - transferring chunk #70 offset=721629 size=1595313... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:400 INFO [instance2]->[instance3] - transferring chunk #71 offset=721629 size=1615673... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:407 INFO [instance2]->[instance3] - transferring chunk #72 offset=721629 size=1655460... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:415 INFO [instance2]->[instance3] - transferring chunk #73 offset=721629 size=1675395... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:422 INFO [instance2]->[instance3] - transferring chunk #74 offset=721629 size=1715383... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:430 INFO [instance2]->[instance3] - transferring chunk #75 offset=721629 size=1755251... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:438 INFO [instance2]->[instance3] - transferring chunk #76 offset=721629 size=1795237... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:445 INFO [instance2]->[instance3] - transferring chunk #77 offset=721629 size=1815107... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:453 INFO [instance2]->[instance3] - transferring chunk #78 offset=721629 size=1854831... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:460 INFO [instance2]->[instance3] - transferring chunk #79 offset=721629 size=1894721... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:468 INFO [instance2]->[instance3] - transferring chunk #80 offset=721629 size=1934234... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:475 INFO [instance2]->[instance3] - transferring chunk #81 offset=721629 size=1954687... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:486 INFO [instance2]->[instance3] - transferring chunk #82 offset=721629 size=1994828... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:495 INFO [instance2]->[instance3] - transferring chunk #83 offset=721629 size=2034855... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:503 INFO [instance2]->[instance3] - transferring chunk #84 offset=721629 size=2074776... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:512 INFO [instance2]->[instance3] - transferring chunk #85 offset=721629 size=2094899... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:521 INFO [instance2]->[instance3] - transferring chunk #86 offset=721629 size=2154761... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:532 INFO [instance2]->[instance3] - transferring chunk #87 offset=721629 size=2194895... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:540 INFO [instance2]->[instance3] - transferring chunk #88 offset=721629 size=2234813... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:549 INFO [instance2]->[instance3] - transferring chunk #89 offset=721629 size=2274788... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:561 INFO [instance2]->[instance3] - transferring chunk #90 offset=721629 size=2314604... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:572 INFO [instance2]->[instance3] - transferring chunk #91 offset=721629 size=2354764... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:582 INFO [instance2]->[instance3] - transferring chunk #92 offset=721629 size=2414638... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:594 INFO [instance2]->[instance3] - transferring chunk #93 offset=721629 size=2454639... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:603 INFO [instance2]->[instance3] - transferring chunk #94 offset=721629 size=2494468... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:613 INFO [instance2]->[instance3] - transferring chunk #95 offset=721629 size=2534427... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:624 INFO [instance2]->[instance3] - transferring chunk #96 offset=721629 size=2594446... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:636 INFO [instance2]->[instance3] - transferring chunk #97 offset=721629 size=2634541... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:651 INFO [instance2]->[instance3] - transferring chunk #98 offset=721629 size=2694376... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:667 INFO [instance2]->[instance3] - transferring chunk #99 offset=721629 size=2754294... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:683 INFO [instance2]->[instance3] - transferring chunk #100 offset=721629 size=2833403... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:697 INFO [instance2]->[instance3] - transferring chunk #101 offset=721629 size=2893844... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:713 INFO [instance2]->[instance3] - transferring chunk #102 offset=721629 size=2953755... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:728 INFO [instance2]->[instance3] - transferring chunk #103 offset=721629 size=3013395... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:746 INFO [instance2]->[instance3] - transferring chunk #104 offset=721629 size=3093161... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:765 INFO [instance2]->[instance3] - transferring chunk #105 offset=721629 size=3172929... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:783 INFO [instance2]->[instance3] - transferring chunk #106 offset=721629 size=3252876... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:801 INFO [instance2]->[instance3] - transferring chunk #107 offset=721629 size=3333083... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:817 INFO [instance2]->[instance3] - transferring chunk #108 offset=721629 size=3392915... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:832 INFO [instance2]->[instance3] - transferring chunk #109 offset=721629 size=3472727... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:846 INFO [instance2]->[instance3] - transferring chunk #110 offset=721629 size=3532496... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:860 INFO [instance2]->[instance3] - transferring chunk #111 offset=721629 size=3592282... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:876 INFO [instance2]->[instance3] - transferring chunk #112 offset=721629 size=3655271... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:892 INFO [instance2]->[instance3] - transferring chunk #113 offset=721629 size=3732523... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:907 INFO [instance2]->[instance3] - transferring chunk #114 offset=721629 size=3792582... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:919 INFO [instance2]->[instance3] - transferring chunk #115 offset=721629 size=3852639... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:933 INFO [instance2]->[instance3] - transferring chunk #116 offset=721629 size=3912657... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:949 INFO [instance2]->[instance3] - transferring chunk #117 offset=721629 size=3972665... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:964 INFO [instance2]->[instance3] - transferring chunk #118 offset=721629 size=4052751... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:979 INFO [instance2]->[instance3] - transferring chunk #119 offset=721629 size=4112621... [OCopyDatabaseChunkTask]
2018-05-29 13:14:23:997 INFO [instance2]->[instance3] - transferring chunk #120 offset=721629 size=4192301... [OCopyDatabaseChunkTask]
2018-05-29 13:14:24:012 INFO [instance2]->[instance3] - transferring chunk #121 offset=721629 size=4252164... [OCopyDatabaseChunkTask]
2018-05-29 13:14:24:029 INFO [instance2]->[instance3] - transferring chunk #122 offset=721629 size=4319415... [OCopyDatabaseChunkTask]
2018-05-29 13:14:24:045 INFO [instance2]->[instance3] - transferring chunk #123 offset=721629 size=4392163... [OCopyDatabaseChunkTask]
2018-05-29 13:14:24:060 INFO [instance2]->[instance3] - transferring chunk #124 offset=721629 size=4452545... [OCopyDatabaseChunkTask]
2018-05-29 13:14:24:076 INFO [instance2]->[instance3] - transferring chunk #125 offset=721629 size=4532590... [OCopyDatabaseChunkTask]
2018-05-29 13:14:24:095 INFO [instance2]->[instance3] - transferring chunk #126 offset=721629 size=4612650... [OCopyDatabaseChunkTask]
2018-05-29 13:14:24:113 INFO [instance2]->[instance3] - transferring chunk #127 offset=721629 size=4692608... [OCopyDatabaseChunkTask]
2018-05-29 13:14:24:130 INFO [instance2]->[instance3] - transferring chunk #128 offset=721629 size=4752555... [OCopyDatabaseChunkTask]
2018-05-29 13:14:24:149 INFO [instance2]->[instance3] - transferring chunk #129 offset=721629 size=4832386... [OCopyDatabaseChunkTask]
2018-05-29 13:14:24:167 INFO [instance2]->[instance3] - transferring chunk #130 offset=721629 size=4912299... [OCopyDatabaseChunkTask]
2018-05-29 13:14:24:186 INFO [instance2]->[instance3] - transferring chunk #131 offset=721629 size=4992274... [OCopyDatabaseChunkTask]
2018-05-29 13:14:24:205 INFO [instance2]->[instance3] - transferring chunk #132 offset=721629 size=5072225... [OCopyDatabaseChunkTask]
2018-05-29 13:14:24:230 INFO [instance2]->[instance3] - transferring chunk #133 offset=721629 size=5187825... [OCopyDatabaseChunkTask]
2018-05-29 13:14:24:251 INFO [instance2]->[instance3] - transferring chunk #134 offset=721629 size=5302520... [OCopyDatabaseChunkTask]
2018-05-29 13:14:24:274 INFO [instance2]->[instance3] - transferring chunk #135 offset=721629 size=5420279... [OCopyDatabaseChunkTask]
2018-05-29 13:14:24:294 INFO [instance2]->[instance3] - transferring chunk #136 offset=721629 size=5497662... [OCopyDatabaseChunkTask]
2018-05-29 13:14:24:319 INFO [instance2]->[instance3] - transferring chunk #137 offset=721629 size=5594913... [OCopyDatabaseChunkTask]
2018-05-29 13:14:24:346 INFO [instance2]->[instance3] - transferring chunk #138 offset=721629 size=5714617... [OCopyDatabaseChunkTask]
2018-05-29 13:14:24:374 INFO [instance2]->[instance3] - transferring chunk #139 offset=721629 size=5834304... [OCopyDatabaseChunkTask]
2018-05-29 13:14:24:401 INFO [instance2]->[instance3] - transferring chunk #140 offset=721629 size=5953776... [OCopyDatabaseChunkTask]
2018-05-29 13:14:24:431 INFO [instance2]->[instance3] - transferring chunk #141 offset=721629 size=6093524... [OCopyDatabaseChunkTask]
2018-05-29 13:14:24:467 INFO [instance2]->[instance3] - transferring chunk #142 offset=721629 size=6232904... [OCopyDatabaseChunkTask]
2018-05-29 13:14:24:498 INFO [instance2]->[instance3] - transferring chunk #143 offset=721629 size=6392344... [OCopyDatabaseChunkTask]
2018-05-29 13:14:24:525 INFO [instance2]->[instance3] - transferring chunk #144 offset=721629 size=6531634... [OCopyDatabaseChunkTask]
2018-05-29 13:14:24:554 INFO [instance2]->[instance3] - transferring chunk #145 offset=721629 size=6651383... [OCopyDatabaseChunkTask]
2018-05-29 13:14:24:587 INFO [instance2]->[instance3] - transferring chunk #146 offset=721629 size=6790230... [OCopyDatabaseChunkTask]
2018-05-29 13:14:24:615 INFO [instance2]->[instance3] - transferring chunk #147 offset=721629 size=6929839... [OCopyDatabaseChunkTask]
2018-05-29 13:14:24:644 INFO [instance2]->[instance3] - transferring chunk #148 offset=721629 size=7049478... [OCopyDatabaseChunkTask]
2018-05-29 13:14:24:676 INFO [instance2]->[instance3] - transferring chunk #149 offset=721629 size=7189469... [OCopyDatabaseChunkTask]
2018-05-29 13:14:24:704 INFO [instance2]->[instance3] - transferring chunk #150 offset=721629 size=7329038... [OCopyDatabaseChunkTask]
2018-05-29 13:14:24:732 INFO [instance2]->[instance3] - transferring chunk #151 offset=721629 size=7468308... [OCopyDatabaseChunkTask]
2018-05-29 13:14:24:764 INFO [instance2]->[instance3] - transferring chunk #152 offset=721629 size=7588455... [OCopyDatabaseChunkTask]
2018-05-29 13:14:24:792 INFO [instance2]->[instance3] - transferring chunk #153 offset=721629 size=7728102... [OCopyDatabaseChunkTask]
2018-05-29 13:14:24:829 INFO [instance2]->[instance3] - transferring chunk #154 offset=721629 size=7868124... [OCopyDatabaseChunkTask]
2018-05-29 13:14:24:864 INFO [instance2]->[instance3] - transferring chunk #155 offset=721629 size=8020975... [OCopyDatabaseChunkTask]
2018-05-29 13:14:24:901 INFO [instance2]->[instance3] - transferring chunk #156 offset=721629 size=8127370... [OCopyDatabaseChunkTask]
2018-05-29 13:14:24:940 INFO [instance2]->[instance3] - transferring chunk #157 offset=721629 size=8306996... [OCopyDatabaseChunkTask]
2018-05-29 13:14:24:977 INFO [instance2]->[instance3] - transferring chunk #158 offset=721629 size=8388608... [OCopyDatabaseChunkTask]
2018-05-29 13:14:25:013 INFO [instance2]->[instance3] - transferring chunk #159 offset=721629 size=8388608... [OCopyDatabaseChunkTask]
2018-05-29 13:14:25:045 INFO [instance2]->[instance3] - transferring chunk #160 offset=721629 size=8388608... [OCopyDatabaseChunkTask]
2018-05-29 13:14:25:086 INFO [instance2]->[instance3] - transferring chunk #161 offset=721629 size=8388608... [OCopyDatabaseChunkTask]
2018-05-29 13:14:25:125 INFO [instance2]->[instance3] - transferring chunk #162 offset=721629 size=8388608... [OCopyDatabaseChunkTask]
2018-05-29 13:14:25:157 INFO [instance2]->[instance3] - transferring chunk #163 offset=721629 size=8388608... [OCopyDatabaseChunkTask]
2018-05-29 13:14:25:193 INFO [instance2]->[instance3] - transferring chunk #164 offset=721629 size=8388608... [OCopyDatabaseChunkTask]

Note that the last chunk written by the starting node was the chunk #156 whereas the transferring process went crazy for the other node at #158 . It seems there is an offset between the two nodes, it may be hint. I hope.

Also, i tried to remove everything related to this database in order to cleanup the system, couldn't manage to do it either from the system or in manual. I don't know where you hid them, but there are still temporary files which forces OrientDB to try recover the database i want to delete.

I've checked the directory where orientdb is installed, checked /var/run, /var/lib, /tmp/orientdb, i'm running out of ideas..

Best Regards,

Cyprien Gottstein.

@CyprienGottstein
Copy link
Author

Well, i've found what was going wrong.

I wanted to start from scratch, without any database already there so i hid the old database inside a repository, the idea was "OrientDB won't do a recursive look up into the file tree of the database repository" and damn was i wrong.

I had the following configuration $ORIENTDB_HOME/databases/backup/my/database.ocf... OrientDB was still able to detect the db even hidden. Unfortunately, it could detect it but not truly access the data, and thus was endlessly running into errors until i finally had an hint. I tried to change (just for my curiosity), the name of the repository storing the db and the name changed also into the log, that gave me the hint about the db being still detected.

I still have other issues, and i've yet to make clusters work, but a part of the problem has been solved at least.

@tglman
Copy link
Member

tglman commented Jun 6, 2018

Hi @CyprienGottstein,

A deadlock while syncing the database was fixed in 3.0.2, that is going to be relased soon, feel free to update and retry on that release.

Regards

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Development

No branches or pull requests

3 participants