Unable to replicate using HA Servers over a VPN

John Russell

unread,

Aug 9, 2012, 3:07:03 AM8/9/12

to ne...@googlegroups.com, John W Russell

I am having problems setting up a simple master-slave relationship between two computers over a vpn. I understand that 3 computers are a recommended minimum, but I believe this is not the issue I am facing.

Any advice on what I am doing wrong is very much appreciated!

Step 0)

Master(1) can ping Slave(2) on 10.0.0.2

Slave(2) can ping Master(1) on 10.0.0.1

Step 1) I start Zookeeper on the Master(1) using this configuration:

===conf/coord.cfg===

tickTime=3000

initLimit=20

syncLimit=10

server.1=127.0.0.1:2888:3888

server.2=10.0.0.2:2889:3889

dataDir=data/coordinator/

clientPort=2181

===data/coordinator/myid===

1

Step 2) I start Zookeeper on the Slave(2) using this configuration:

===conf/coord.cfg===

tickTime=3000

initLimit=20

syncLimit=10

server.1=10.0.0.1:2888:3888

server.2=127.0.0.1:2889:3889

dataDir=data/coordinator/

clientPort=2182

===data/coordinator/myid===

2

Step 3) I confirm that Zookeeper is communicating correctly:

Master(1):

===data/log/neo4j-zookeeper.log===

08-08-2012 23:42:21,771 PDT INFO QuorumPeer:/0:0:0:0:0:0:0:0:2181 org.apache.zookeeper.server.ZooKeeperServer - Created server with tickTime 3000 minSessionTimeout 6000 maxSessionTimeout 60000 datadir data/coordinator/version-2 snapdir data/coordinator/version-2

08-08-2012 23:42:21,782 PDT INFO WorkerReceiver Thread org.apache.zookeeper.server.quorum.FastLeaderElection - Notification: 2 (n.leader), 0 (n.zxid), 1 (n.round), LEADING (n.state), 2 (n.sid), FOLLOWING (my state)

08-08-2012 23:42:21,875 PDT INFO QuorumPeer:/0:0:0:0:0:0:0:0:2181 org.apache.zookeeper.server.quorum.Learner - Getting a snapshot from leader

08-08-2012 23:42:21,878 PDT INFO QuorumPeer:/0:0:0:0:0:0:0:0:2181 org.apache.zookeeper.server.quorum.Learner - Setting leader epoch 1

08-08-2012 23:42:21,891 PDT INFO QuorumPeer:/0:0:0:0:0:0:0:0:2181 org.apache.zookeeper.server.persistence.FileTxnSnapLog - Snapshotting: 100000000

Slave(2):

===data/log/neo4j-zookeeper.log===

09-08-2012 01:42:17,813 CDT INFO QuorumPeer:/0:0:0:0:0:0:0:0:2182 org.apache.zookeeper.server.ZooKeeperServer - Created server with tickTime 3000 minSessionTimeout 6000 maxSessionTimeout 60000 datadir data/coordinator/version-2 snapdir data/coordinator/version-2

09-08-2012 01:42:17,817 CDT INFO QuorumPeer:/0:0:0:0:0:0:0:0:2182 org.apache.zookeeper.server.persistence.FileTxnSnapLog - Snapshotting: 0

09-08-2012 01:42:17,886 CDT INFO LearnerHandler-/10.0.0.1:43712 org.apache.zookeeper.server.quorum.LearnerHandler - Follower sid: 1 : info : org.apache.zookeeper.server.quorum.QuorumPeer$QuorumServer@594bfbf1

09-08-2012 01:42:17,887 CDT WARN LearnerHandler-/10.0.0.1:43712 org.apache.zookeeper.server.quorum.LearnerHandler - Sending snapshot last zxid of peer is 0x0 zxid of leader is 0x100000000

09-08-2012 01:42:17,936 CDT WARN LearnerHandler-/10.0.0.1:43712 org.apache.zookeeper.server.quorum.Leader - Commiting zxid 0x100000000 from /10.0.0.2:2889 not first!

09-08-2012 01:42:17,936 CDT WARN LearnerHandler-/10.0.0.1:43712 org.apache.zookeeper.server.quorum.Leader - First is 0

09-08-2012 01:42:17,936 CDT INFO LearnerHandler-/10.0.0.1:43712 org.apache.zookeeper.server.quorum.Leader - Have quorum of supporters; starting up and setting last processed zxid: 4294967296

Step 4) I start the Neo4j (Embedded!) server on the Master using this configuration:

===neo4j.properties===

enable_online_backup=true

ha.server_id=1

ha.coordinators=127.0.0.1:2181,10.0.0.2:2182

ha.cluster_name = blockviewer.cluster

ha.pull_interval = 10

enable_remote_shell=true

Step 5) I attempt to start the Neo4j (Stand-Alone!) server on the Slave(2) using this configuration. Please note I have forced this node to be a slave:

===conf/neo4j.properties===

enable_online_backup=true

ha.server_id=2

ha.coordinators=127.0.0.1:2182,10.0.0.1:2181

ha.slave_coordinator_update_mode=none

ha.cluster_name = blockviewer.cluster

ha.pull_interval = 10

Step 6) After trying to start this Slave(2), both the Master(1) and the Slave(2) fail to start.

Slave(2):

===data/log/neo4j.0.0.log===

Aug 09, 2012 1:23:32 AM org.neo4j.server.logging.Logger log

SEVERE:

java.lang.RuntimeException: Tried to join the cluster, but was unable to

at org.neo4j.kernel.HighlyAvailableGraphDatabase.start(HighlyAvailableGraphDatabase.java:603)

at org.neo4j.kernel.HighlyAvailableGraphDatabase.<init>(HighlyAvailableGraphDatabase.java:265)

at org.neo4j.kernel.HighlyAvailableGraphDatabase.<init>(HighlyAvailableGraphDatabase.java:185)

at org.neo4j.server.enterprise.EnterpriseNeoServerBootstrapper$DatabaseMode$2.createDatabase(EnterpriseNeoServerBootstrapper.java:54)

at org.neo4j.server.database.Database.createDatabase(Database.java:81)

at org.neo4j.server.database.Database.<init>(Database.java:64)

at org.neo4j.server.NeoServerWithEmbeddedWebServer.startDatabase(NeoServerWithEmbeddedWebServer.java:175)

at org.neo4j.server.NeoServerWithEmbeddedWebServer.start(NeoServerWithEmbeddedWebServer.java:93)

at org.neo4j.server.Bootstrapper.start(Bootstrapper.java:87)

at org.neo4j.server.advanced.AdvancedNeoServerBootstrapper.start(AdvancedNeoServerBootstrapper.java:37)

at org.neo4j.server.Bootstrapper.main(Bootstrapper.java:52)

Caused by: java.lang.RuntimeException: Gave up trying to copy store from master

at org.neo4j.kernel.HighlyAvailableGraphDatabase.getFreshDatabaseFromMaster(HighlyAvailableGraphDatabase.java:493)

at org.neo4j.kernel.HighlyAvailableGraphDatabase.start(HighlyAvailableGraphDatabase.java:578)

... 10 more

Caused by: org.neo4j.kernel.ha.zookeeper.NoMasterException: No master

at org.neo4j.kernel.ha.zookeeper.AbstractZooKeeperManager$1.noMasterException(AbstractZooKeeperManager.java:474)

at org.neo4j.kernel.ha.zookeeper.AbstractZooKeeperManager$1.copyStore(AbstractZooKeeperManager.java:504)

at org.neo4j.kernel.HighlyAvailableGraphDatabase.copyStoreFromMaster(HighlyAvailableGraphDatabase.java:776)

at org.neo4j.kernel.HighlyAvailableGraphDatabase.getFreshDatabaseFromMaster(HighlyAvailableGraphDatabase.java:478)

... 11 more

Aug 09, 2012 1:23:32 AM org.neo4j.server.logging.Logger log

SEVERE: Failed to start Neo Server on port [7474]

Aug 09, 2012 1:24:30 AM org.neo4j.server.logging.Logger log

INFO: Store files missing, or not in suitable state for upgrade. Leaving this problem for main server process to resolve.

Aug 09, 2012 1:24:31 AM org.neo4j.server.logging.Logger log

INFO: Starting Neo Server on port [7474] with [80] threads available

Aug 09, 2012 1:24:31 AM org.neo4j.server.logging.Logger log

INFO: Enabling HTTPS on port [7473]

Aug 09, 2012 1:24:31 AM org.mortbay.log.Slf4jLog info

INFO: Logging to org.slf4j.impl.JDK14LoggerAdapter(org.mortbay.log) via org.mortbay.log.Slf4jLog

Aug 09, 2012 1:24:31 AM org.neo4j.server.logging.Logger log

INFO: Using database at /opt/neo4j-enterprise-1.7.2/data/graph.db

Master(1):

(Printed to console)

java.nio.channels.ClosedChannelException

at org.jboss.netty.channel.socket.nio.NioWorker.cleanUpWriteBuffer(NioWorker.java:623)

at org.jboss.netty.channel.socket.nio.NioWorker.close(NioWorker.java:599)

at org.jboss.netty.channel.socket.nio.NioServerSocketPipelineSink.handleAcceptedSocket(NioServerSocketPipelineSink.java:119)

at org.jboss.netty.channel.socket.nio.NioServerSocketPipelineSink.eventSunk(NioServerSocketPipelineSink.java:76)

at org.jboss.netty.handler.codec.oneone.OneToOneEncoder.handleDownstream(OneToOneEncoder.java:60)

at org.jboss.netty.channel.Channels.close(Channels.java:720)

at org.jboss.netty.channel.AbstractChannel.close(AbstractChannel.java:200)

at org.neo4j.com.Server$ServerHandler.exceptionCaught(Server.java:237)

at org.jboss.netty.handler.codec.frame.FrameDecoder.exceptionCaught(FrameDecoder.java:238)

at org.jboss.netty.channel.Channels.fireExceptionCaught(Channels.java:432)

at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:331)

at org.jboss.netty.channel.socket.nio.NioWorker.processSelectedKeys(NioWorker.java:280)

at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:200)

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)

at java.lang.Thread.run(Thread.java:722)

java.io.IOException: Connection reset by peer

at sun.nio.ch.FileDispatcherImpl.read0(Native Method)

at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)

at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:218)

at sun.nio.ch.IOUtil.read(IOUtil.java:186)

at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:359)

at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:321)

at org.jboss.netty.channel.socket.nio.NioWorker.processSelectedKeys(NioWorker.java:280)

at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:200)

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)

at java.lang.Thread.run(Thread.java:722)

The Slave(2) fails to start (BAD) and the Master(1) throws that error. Any thoughts would be very much appreciated!

John Russell

unread,

Aug 9, 2012, 3:16:54 AM8/9/12

to ne...@googlegroups.com, John W Russell

Typo:

Step 6) After trying to start this Slave(2), Master(1) throws an error and the Slave(2) fail to start. **

John Russell

unread,

Aug 9, 2012, 3:25:02 AM8/9/12

to ne...@googlegroups.com, John W Russell

I ran this test again, and the Slave server did NOT throw the "NoMasterException" at all. I double checked the process and it throws absolutely no error (however, the Master continues to throw the same IOException):

Slave(2):

===data/log/neo4j.0.0.log===

Aug 09, 2012 2:22:00 AM org.neo4j.server.logging.Logger log

INFO: Store files missing, or not in suitable state for upgrade. Leaving this problem for main server process to resolve.

Aug 09, 2012 2:22:01 AM org.neo4j.server.logging.Logger log

INFO: Starting Neo Server on port [7474] with [80] threads available

Aug 09, 2012 2:22:01 AM org.neo4j.server.logging.Logger log

INFO: Enabling HTTPS on port [7473]

Aug 09, 2012 2:22:01 AM org.mortbay.log.Slf4jLog info

INFO: Logging to org.slf4j.impl.JDK14LoggerAdapter(org.mortbay.log) via org.mortbay.log.Slf4jLog

Aug 09, 2012 2:22:01 AM org.neo4j.server.logging.Logger log

INFO: Using database at /opt/neo4j-enterprise-1.7.2/data/graph.db

Starting Neo4j Server...WARNING: not changing user

process [23653]... waiting for server to be ready......................................................................................................................... BAD.

Michael Hunger

unread,

Aug 9, 2012, 3:25:08 AM8/9/12

to ne...@googlegroups.com, John W Russell

John is there anything in between that filters ports?

Michael

Michael Hunger

unread,

Aug 9, 2012, 3:30:57 AM8/9/12

to ne...@googlegroups.com, John W Russell

Can you run the slave with : bin/neo4j console instead?

and please share the relevant content of data/graph.db/messages.log of slave and master.

Michael

John Russell

unread,

Aug 9, 2012, 3:31:30 AM8/9/12

to ne...@googlegroups.com, John W Russell

Admitedly, I am somewhat of a VPN noob, but I don't believe so! I am using a very simple config using OpenVPN.

===Master===

dev tun

ifconfig 10.0.0.1 10.0.0.2

secret /etc/openvpn/static.key

===Slave===

remote XXX.XXX.XXX.XXX

dev tun

ifconfig 10.0.0.2 10.0.0.1

John Russell

unread,

Aug 9, 2012, 3:48:37 AM8/9/12

to ne...@googlegroups.com, John W Russell

Can you run the slave with : bin/neo4j console instead?

Slave:

8/9/12 2:36:04 AM org.neo4j.server.NeoServerWithEmbeddedWebServer INFO: Starting Neo Server on port [7474] with [80] threads available

8/9/12 2:36:04 AM org.neo4j.server.NeoServerWithEmbeddedWebServer INFO: Enabling HTTPS on port [7473]

8/9/12 2:36:04 AM org.neo4j.server.database.Database INFO: Using database at /opt/neo4j-enterprise-1.7.2/data/graph.db

(I waited 5 minutes without a response... should I wait longer??)

please share the relevant content of data/graph.db/messages.log of slave and master.

Master:

(See attached: messages.log.master)

Slave:

(See attached: messages.log.slave)

Thanks so much for looking at this!

messages.log.slave

messages.log.master

Michael Hunger

unread,

Aug 9, 2012, 7:14:21 AM8/9/12

to ne...@googlegroups.com, John W Russell

John,

the Zookeerp config seems to be messed up.

2012-08-09 07:36:04.863+0000: Error in ZooClient.process StoreId in database doesn't match that of the ZK cluster

org.neo4j.kernel.ha.zookeeper.ZooKeeperException: StoreId in database doesn't match that of the ZK cluster

Can you stop the cluster and zookeeper and then wipe:

the slave's data/graph.db directory

for all zookeeper isntances the data/coordinator/version-2 directories

then start zookeeper (btw. there are also separate zk-logs)

and start the master then the slave

Michael

<messages.log.slave><messages.log.master>

杨军

unread,

Aug 9, 2012, 8:08:59 AM8/9/12

to ne...@googlegroups.com

ip address used host name replace.

2012/8/9 Michael Hunger <michael...@neotechnology.com>

--

Best regards,
yang jun
Tel:  028-85126877
Mob:  18608027881 <mailto:yangjun...@gmail.com>
Chat: yangjun...@gmail.com(gtalk)

330.gif

John Russell

unread,

Aug 9, 2012, 4:51:07 PM8/9/12

to ne...@googlegroups.com, John W Russell

Hi Michael,

After performing the operation, the Slave still failed to start, but with different results. What is strange though, is that the logs on the Slave all look good for the first time executing it without a graph.db/ folder! However, the second time I run it, I get interesting errors. Here are some logs:

Slave (First Run)

===data/graph.db/messages.log===

2012-08-09 19:42:28.198+0000: Starting up highly available graph database '/opt/neo4j-enterprise-1.7.2/data/graph.db'

2012-08-09 19:42:28.409+0000: org.neo4j.kernel.ha.zookeeper.ZooClient$WatcherImpl@2a03803, Thu Aug 09 14:42:28 CDT 2012 Got event: WatchedEvent state:SyncConnected type:None path:null (path=null)

2012-08-09 19:42:28.803+0000: Read HA server:199.48.69.236:6361 (for machineID 1) from zoo keeper

2012-08-09 19:42:28.803+0000: getMaster 1 based on [MachineInfo[ID:1, sequence:1, last tx:193208, server:(199.48.69.236, 6361), master for last tx:1]]

2012-08-09 19:42:28.896+0000: Get master before write:(NO_MASTER, MachineInfo[ID:-1, sequence:-1, last tx:1, server:null, master for last tx:-1])

2012-08-09 19:42:28.896+0000: Didn't do setup due to told not to write

2012-08-09 19:42:29.136+0000: getMaster 1 based on [MachineInfo[ID:1, sequence:1, last tx:193208, server:(199.48.69.236, 6361), master for last tx:1]]

2012-08-09 19:42:29.271+0000: MasterClient communication started and bound to 199.48.69.236:6361

===data/log/neo4j.0.0.log===

Aug 09, 2012 2:22:00 AM org.neo4j.server.logging.Logger log

INFO: Store files missing, or not in suitable state for upgrade. Leaving this problem for main server process to resolve.

Aug 09, 2012 2:22:01 AM org.neo4j.server.logging.Logger log

INFO: Starting Neo Server on port [7474] with [80] threads available

Aug 09, 2012 2:22:01 AM org.neo4j.server.logging.Logger log

INFO: Enabling HTTPS on port [7473]

Aug 09, 2012 2:22:01 AM org.mortbay.log.Slf4jLog info

INFO: Logging to org.slf4j.impl.JDK14LoggerAdapter(org.mortbay.log) via org.mortbay.log.Slf4jLog

Aug 09, 2012 2:22:01 AM org.neo4j.server.logging.Logger log

INFO: Using database at /opt/neo4j-enterprise-1.7.2/data/graph.db

Aug 09, 2012 2:36:04 AM org.neo4j.server.logging.Logger log

INFO: Starting Neo Server on port [7474] with [80] threads available

Aug 09, 2012 2:36:04 AM org.neo4j.server.logging.Logger log

INFO: Enabling HTTPS on port [7473]

Aug 09, 2012 2:36:04 AM org.mortbay.log.Slf4jLog info

INFO: Logging to org.slf4j.impl.JDK14LoggerAdapter(org.mortbay.log) via org.mortbay.log.Slf4jLog

Aug 09, 2012 2:36:04 AM org.neo4j.server.logging.Logger log

INFO: Using database at /opt/neo4j-enterprise-1.7.2/data/graph.db

Aug 09, 2012 2:42:27 PM org.neo4j.server.logging.Logger log

INFO: Store files missing, or not in suitable state for upgrade. Leaving this problem for main server process to resolve.

Aug 09, 2012 2:42:27 PM org.neo4j.server.logging.Logger log

INFO: Starting Neo Server on port [7474] with [80] threads available

Aug 09, 2012 2:42:27 PM org.neo4j.server.logging.Logger log

INFO: Enabling HTTPS on port [7473]

Aug 09, 2012 2:42:27 PM org.mortbay.log.Slf4jLog info

INFO: Logging to org.slf4j.impl.JDK14LoggerAdapter(org.mortbay.log) via org.mortbay.log.Slf4jLog

Aug 09, 2012 2:42:28 PM org.neo4j.server.logging.Logger log

INFO: Using database at /opt/neo4j-enterprise-1.7.2/data/graph.db

john@blockviewer:/opt/neo4j-enterprise-1.7.2/bin$ ./neo4j start

Starting Neo4j Server...WARNING: not changing user

process [25750]... waiting for server to be ready............................... ................................................................................ .......... BAD.

After this, I simply ran it again (So it had a brand new graph.db/ created), and I got a new error in the logs:

Slave (Second Run)

===data/log/neo4j.0.0.log===

INFO: Starting Neo Server on port [7474] with [80] threads available

Aug 09, 2012 2:36:04 AM org.neo4j.server.logging.Logger log

INFO: Enabling HTTPS on port [7473]

Aug 09, 2012 2:36:04 AM org.mortbay.log.Slf4jLog info

INFO: Logging to org.slf4j.impl.JDK14LoggerAdapter(org.mortbay.log) via org.mortbay.log.Slf4jLog

Aug 09, 2012 2:36:04 AM org.neo4j.server.logging.Logger log

INFO: Using database at /opt/neo4j-enterprise-1.7.2/data/graph.db

Aug 09, 2012 2:42:27 PM org.neo4j.server.logging.Logger log

INFO: Store files missing, or not in suitable state for upgrade. Leaving this problem for main server process to resolve.

Aug 09, 2012 2:42:27 PM org.neo4j.server.logging.Logger log

INFO: Starting Neo Server on port [7474] with [80] threads available

Aug 09, 2012 2:42:27 PM org.neo4j.server.logging.Logger log

INFO: Enabling HTTPS on port [7473]

Aug 09, 2012 2:42:27 PM org.mortbay.log.Slf4jLog info

INFO: Logging to org.slf4j.impl.JDK14LoggerAdapter(org.mortbay.log) via org.mortbay.log.Slf4jLog

Aug 09, 2012 2:42:28 PM org.neo4j.server.logging.Logger log

INFO: Using database at /opt/neo4j-enterprise-1.7.2/data/graph.db

Aug 09, 2012 2:52:19 PM org.neo4j.server.logging.Logger log

INFO: Store files missing, or not in suitable state for upgrade. Leaving this problem for main server process to resolve.

Aug 09, 2012 2:52:19 PM org.neo4j.server.logging.Logger log

INFO: Starting Neo Server on port [7474] with [80] threads available

Aug 09, 2012 2:52:19 PM org.neo4j.server.logging.Logger log

INFO: Enabling HTTPS on port [7473]

Aug 09, 2012 2:52:19 PM org.mortbay.log.Slf4jLog info

INFO: Logging to org.slf4j.impl.JDK14LoggerAdapter(org.mortbay.log) via org.mortbay.log.Slf4jLog

Aug 09, 2012 2:52:19 PM org.neo4j.server.logging.Logger log

INFO: Using database at /opt/neo4j-enterprise-1.7.2/data/graph.db

Aug 09, 2012 2:52:20 PM org.neo4j.server.logging.Logger log

SEVERE:

java.lang.NullPointerException

at org.neo4j.kernel.impl.nioneo.store.CommonAbstractStore.nextId(CommonAbstractStore.java:359)

at org.neo4j.kernel.impl.nioneo.store.StoreFactory.createNodeStore(StoreFactory.java:191)

at org.neo4j.kernel.impl.nioneo.store.StoreFactory.createNeoStore(StoreFactory.java:152)

at org.neo4j.kernel.impl.nioneo.store.StoreFactory.createNeoStore(StoreFactory.java:146)

at org.neo4j.kernel.impl.nioneo.xa.NeoStoreXaDataSource.<init>(NeoStoreXaDataSource.java:200)

at org.neo4j.kernel.AbstractGraphDatabase.create(AbstractGraphDatabase.java:437)

at org.neo4j.kernel.AbstractGraphDatabase.run(AbstractGraphDatabase.java:220)

at org.neo4j.kernel.ha.SlaveGraphDatabase.<init>(SlaveGraphDatabase.java:73)

at org.neo4j.kernel.HighlyAvailableGraphDatabase.startAsSlave(HighlyAvailableGraphDatabase.java:1168)

at org.neo4j.kernel.HighlyAvailableGraphDatabase.reevaluateMyself(HighlyAvailableGraphDatabase.java:1094)

at org.neo4j.kernel.HighlyAvailableGraphDatabase.newMaster(HighlyAvailableGraphDatabase.java:1477)

at org.neo4j.kernel.HighlyAvailableGraphDatabase.start(HighlyAvailableGraphDatabase.java:607)