You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@zookeeper.apache.org by Steven Wu <st...@gmail.com> on 2014/08/23 06:32:10 UTC

zookeeper server close connection unexpected

I am writing a unit test to simulate a scenario where server changes IP,
which can happen in cloud env. During push, new instance can get a
different private IP.

As you can see from pasted code, I am running the test using zkclient.
ZooKeeper#updateServerList works well by forcing resolution to new IP
address that 2nd ZooKeeperServer object binds to. but the weird thing is
that after connection established, it seems that server closes connection
immediately. please see the log output in the end. I added some debug
System.out.

I am using zookeeper-3.5.0-rc1. Any help is appreciated!

Thanks,
Steven

###############################################
/**
 * To test this unit testing, the followings should be done first
 *
 * ====== pre-test setup ======
 * # bind 192.168.1.1 and 192.168.1.2 to lo0 interface as alias
 * sudo ifconfig lo0 192.168.1.1 alias
 * sudo ifconfig lo0 192.168.1.2 alias
 *
 * ====== manual test ======
 * - add mapping to /etc/hosts
 *    192.168.1.1 zkserver
 * - run test. it should stuck in the line of second
client.createEphemeral(...)
 * - change mapping in /etc/hosts
 *    192.168.1.2 zkserver
 * - test should proceed and finish
 */
@Ignore
public class TestServerIpChange {

    @Test
    public void test() throws InterruptedException, IOException {
        System.setProperty("log4j.logger.org.apache.zookeeper", "INFO");
        ZkServer _zkServer = TestUtil.startZkServer("Zk_SERVER_IP_Change",
"192.168.1.1", 2181);

        ZkClient client = new ZkClient("zkserver:2181", 10000, 5000);
        client.createEphemeral("/a");
        for (int i = 0; i < 5; ++i) {
            System.out.println("send and receive data: " + i);
            client.readData("/a");
            client.writeData("/a", Integer.toString(i));
            Thread.sleep(1000);
            System.out.println("sleeping..." + i);
        }
        _zkServer.shutdown();

        _zkServer = TestUtil.startZkServer("Zk_SERVER_IP_Change",
"192.168.1.2", 2181);
        // change /etc/hosts
        client.createEphemeral("/a");
        for (int i = 0; i < 5; ++i) {
            System.out.println("send and receive data: " + i);
            client.readData("/a");
            client.writeData("/a", Integer.toString(i));
            Thread.sleep(1000);
            System.out.println("sleeping..." + i);
        }
        _zkServer.shutdown();
    }

}

###########################################
14/08/22 21:17:46  INFO [main] (ZkServer.java:85) - Starting ZkServer on:
hostname = 192.168.1.1, port = 2181
14/08/22 21:17:46  INFO [main] (ZkServer.java:99) - Start single zookeeper
server...
14/08/22 21:17:46  INFO [main] (ZkServer.java:100) - data dir:
/Users/stevenwu/workspaces/github/stevenzwu/zkclient/./build/test/Zk_SERVER_IP_Change/data
14/08/22 21:17:46  INFO [main] (ZkServer.java:101) - data log dir:
/Users/stevenwu/workspaces/github/stevenzwu/zkclient/./build/test/Zk_SERVER_IP_Change/log
14/08/22 21:17:47  INFO [ZkClient-EventThread-17-zkserver:2181]
(ZkEventThread.java:64) - Starting ZkClient event thread.
connected to null
14/08/22 21:17:47  INFO [main-EventThread] (ZkClient.java:450) - zookeeper
state changed (SyncConnected)
send and receive data: 0
sleeping...0
send and receive data: 1
sleeping...1
send and receive data: 2
sleeping...2
send and receive data: 3
sleeping...3
send and receive data: 4
sleeping...4
14/08/22 21:17:52  INFO [main] (ZkServer.java:124) - Shutting down
ZkServer...
14/08/22 21:17:52  INFO [main] (ZkServer.java:143) - Shutting down
ZkServer...done
14/08/22 21:17:52  INFO [main] (ZkServer.java:85) - Starting ZkServer on:
hostname = 192.168.1.2, port = 2181
14/08/22 21:17:52  INFO [main] (ZkServer.java:99) - Start single zookeeper
server...
14/08/22 21:17:52  INFO [main] (ZkServer.java:100) - data dir:
/Users/stevenwu/workspaces/github/stevenzwu/zkclient/./build/test/Zk_SERVER_IP_Change/data
14/08/22 21:17:52  INFO [main] (ZkServer.java:101) - data log dir:
/Users/stevenwu/workspaces/github/stevenzwu/zkclient/./build/test/Zk_SERVER_IP_Change/log

EndOfStreamException: Unable to read additional data from server sessionid
0x14801159e240000, likely server has closed socket
at
org.apache.zookeeper.ClientCnxnSocketNIO.doIO(ClientCnxnSocketNIO.java:75)
at
org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:363)
at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1190)
14/08/22 21:17:52  INFO [main-EventThread] (ZkClient.java:450) - zookeeper
state changed (Disconnected)

...

java.net.ConnectException: Connection refused
at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:735)
at
org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:356)
at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1190)

...

java.net.ConnectException: Connection refused
at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:735)
at
org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:356)
at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1190)

...

connected to zkserver/192.168.1.2:2181
EndOfStreamException: Unable to read additional data from server sessionid
0x14801159e240000, likely server has closed socket
at
org.apache.zookeeper.ClientCnxnSocketNIO.doIO(ClientCnxnSocketNIO.java:75)
at
org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:363)
at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1190)

...

connected to zkserver/192.168.1.2:2181
EndOfStreamException: Unable to read additional data from server sessionid
0x14801159e240000, likely server has closed socket
at
org.apache.zookeeper.ClientCnxnSocketNIO.doIO(ClientCnxnSocketNIO.java:75)
at
org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:363)
at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1190)

Re: zookeeper server close connection unexpected

Posted by Steven Wu <st...@gmail.com>.
yes. new server is started from scratch. looks like this is an expected
behavior then. let me fix my test.

Michi/Alexander, thanks a lot for the help!

On Sat, Aug 23, 2014 at 8:43 PM, Alexander Shraer <sh...@gmail.com> wrote:

> > Refusing session request for client /192.168.1.2:52468 as it has seen
> zxid
> > 0x7 our last zxid is 0x0 client must try another server
>
> Looks like your new server is started from scratch. The client can't
> connect to it since it has seen data that is more up-to-date. This is not
> something we introduced in 3.5.0. When a client looses its current server
> it uses this rule to find a server who is at least as up-to-date as the
> client is, to avoid "going back in time" and loosing consistency.
>
>
>

Re: zookeeper server close connection unexpected

Posted by Alexander Shraer <sh...@gmail.com>.
> Refusing session request for client /192.168.1.2:52468 as it has seen zxid
> 0x7 our last zxid is 0x0 client must try another server

Looks like your new server is started from scratch. The client can't
connect to it since it has seen data that is more up-to-date. This is not
something we introduced in 3.5.0. When a client looses its current server
it uses this rule to find a server who is at least as up-to-date as the
client is, to avoid "going back in time" and loosing consistency.

Re: zookeeper server close connection unexpected

Posted by Steven Wu <st...@gmail.com>.
got logging works in my IDE. highlight'ed the reason (in red) why server
close/refuse session request. I don't have this problem with earlier
version of zookeeper (e.g. 3.3.1). note that I am testing with 3.5.0-rc1.

Thanks,
Steven

14/08/23 19:51:32  INFO [main-SendThread(zkserver:2181)]
(ClientCnxn.java:1091) - Opening socket connection to server zkserver/
192.168.1.2:2181. Will not attempt to authenticate using SASL (unknown
error)
14/08/23 19:51:32  INFO [NIOServerCxnFactory.AcceptThread:/192.168.1.2:2181]
(NIOServerCnxnFactory.java:296) - Accepted socket connection from /
192.168.1.2:52468
14/08/23 19:51:32  INFO [main-SendThread(zkserver:2181)]
(ClientCnxn.java:961) - Socket connection established to zkserver/
192.168.1.2:2181, initiating session
14/08/23 19:51:32 DEBUG [main-SendThread(zkserver:2181)]
(ClientCnxn.java:1001) - Session establishment request sent on zkserver/
192.168.1.2:2181
14/08/23 19:51:32 DEBUG [NIOWorkerThread-6] (ZooKeeperServer.java:822) -
Session establishment request from client /192.168.1.2:52468 client's
lastZxid is 0x7
14/08/23 19:51:32  INFO [NIOWorkerThread-6] (ZooKeeperServer.java:853) -
Refusing session request for client /192.168.1.2:52468 as it has seen zxid
0x7 our last zxid is 0x0 client must try another server
14/08/23 19:51:32  INFO [NIOWorkerThread-6] (NIOServerCnxn.java:1006) -
Closed socket connection for client /192.168.1.2:52468 (no session
established for client)
14/08/23 19:51:32  INFO [main-SendThread(zkserver:2181)]
(ClientCnxn.java:1208) - Unable to read additional data from server
sessionid 0x14805ec4abd0000, likely server has closed socket, closing
socket connection and attempting reconnect
EndOfStreamException: Unable to read additional data from server sessionid
0x14805ec4abd0000, likely server has closed socket
at
org.apache.zookeeper.ClientCnxnSocketNIO.doIO(ClientCnxnSocketNIO.java:75)
at
org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:363)
at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1190)


On Sat, Aug 23, 2014 at 4:16 PM, Michi Mutsuzaki <mi...@cs.stanford.edu>
wrote:

> Yes, it would be great if you can get the zookeeper server log at the
> DEBUG level.
>
> On Sat, Aug 23, 2014 at 2:54 PM, Steven Wu <st...@gmail.com> wrote:
> > It's a unit test. so I started the zookeeper server programmatically in
> > localhost. looks like I better get log4j to work so that I can see logs
> from
> > ZooKeeperServer.
> >
> >
> > On Sat, Aug 23, 2014 at 12:02 PM, Michi Mutsuzaki <michi@cs.stanford.edu
> >
> > wrote:
> >>
> >> It would be helpful if you have the zookeeper server log from
> >> 192.168.1.2:2181.
> >>
> >> On Sat, Aug 23, 2014 at 9:31 AM, Steven Wu <st...@gmail.com>
> wrote:
> >> > client got the connected NIO event to the 2nd server instance. I also
> >> > tried
> >> > telnet to 192.168.1.2:2181. for whatever reason (e.g. protocol/auth),
> >> > server decides to close the connection.
> >> >
> >> >
> >> > On Sat, Aug 23, 2014 at 7:49 AM, Alexander Shraer <sh...@gmail.com>
> >> > wrote:
> >> >
> >> >> is it possible that the new server isn't listening on the 2181 client
> >> >> port
> >> >> ?
> >> >> perhaps something is misconfigured on the server side.
> >> >>
> >> >>
> >> >> On Fri, Aug 22, 2014 at 9:32 PM, Steven Wu <st...@gmail.com>
> >> >> wrote:
> >> >>
> >> >> > I am writing a unit test to simulate a scenario where server
> changes
> >> >> > IP,
> >> >> > which can happen in cloud env. During push, new instance can get a
> >> >> > different private IP.
> >> >> >
> >> >> > As you can see from pasted code, I am running the test using
> >> >> > zkclient.
> >> >> > ZooKeeper#updateServerList works well by forcing resolution to new
> IP
> >> >> > address that 2nd ZooKeeperServer object binds to. but the weird
> thing
> >> >> > is
> >> >> > that after connection established, it seems that server closes
> >> >> > connection
> >> >> > immediately. please see the log output in the end. I added some
> debug
> >> >> > System.out.
> >> >> >
> >> >> > I am using zookeeper-3.5.0-rc1. Any help is appreciated!
> >> >> >
> >> >> > Thanks,
> >> >> > Steven
> >> >> >
> >> >> > ###############################################
> >> >> > /**
> >> >> >  * To test this unit testing, the followings should be done first
> >> >> >  *
> >> >> >  * ====== pre-test setup ======
> >> >> >  * # bind 192.168.1.1 and 192.168.1.2 to lo0 interface as alias
> >> >> >  * sudo ifconfig lo0 192.168.1.1 alias
> >> >> >  * sudo ifconfig lo0 192.168.1.2 alias
> >> >> >  *
> >> >> >  * ====== manual test ======
> >> >> >  * - add mapping to /etc/hosts
> >> >> >  *    192.168.1.1 zkserver
> >> >> >  * - run test. it should stuck in the line of second
> >> >> > client.createEphemeral(...)
> >> >> >  * - change mapping in /etc/hosts
> >> >> >  *    192.168.1.2 zkserver
> >> >> >  * - test should proceed and finish
> >> >> >  */
> >> >> > @Ignore
> >> >> > public class TestServerIpChange {
> >> >> >
> >> >> >     @Test
> >> >> >     public void test() throws InterruptedException, IOException {
> >> >> >         System.setProperty("log4j.logger.org.apache.zookeeper",
> >> >> > "INFO");
> >> >> >         ZkServer _zkServer =
> >> >> TestUtil.startZkServer("Zk_SERVER_IP_Change",
> >> >> > "192.168.1.1", 2181);
> >> >> >
> >> >> >         ZkClient client = new ZkClient("zkserver:2181", 10000,
> 5000);
> >> >> >         client.createEphemeral("/a");
> >> >> >         for (int i = 0; i < 5; ++i) {
> >> >> >             System.out.println("send and receive data: " + i);
> >> >> >             client.readData("/a");
> >> >> >             client.writeData("/a", Integer.toString(i));
> >> >> >             Thread.sleep(1000);
> >> >> >             System.out.println("sleeping..." + i);
> >> >> >         }
> >> >> >         _zkServer.shutdown();
> >> >> >
> >> >> >         _zkServer = TestUtil.startZkServer("Zk_SERVER_IP_Change",
> >> >> > "192.168.1.2", 2181);
> >> >> >         // change /etc/hosts
> >> >> >         client.createEphemeral("/a");
> >> >> >         for (int i = 0; i < 5; ++i) {
> >> >> >             System.out.println("send and receive data: " + i);
> >> >> >             client.readData("/a");
> >> >> >             client.writeData("/a", Integer.toString(i));
> >> >> >             Thread.sleep(1000);
> >> >> >             System.out.println("sleeping..." + i);
> >> >> >         }
> >> >> >         _zkServer.shutdown();
> >> >> >     }
> >> >> >
> >> >> > }
> >> >> >
> >> >> > ###########################################
> >> >> > 14/08/22 21:17:46  INFO [main] (ZkServer.java:85) - Starting
> ZkServer
> >> >> > on:
> >> >> > hostname = 192.168.1.1, port = 2181
> >> >> > 14/08/22 21:17:46  INFO [main] (ZkServer.java:99) - Start single
> >> >> zookeeper
> >> >> > server...
> >> >> > 14/08/22 21:17:46  INFO [main] (ZkServer.java:100) - data dir:
> >> >> >
> >> >> >
> >> >>
> >> >>
> /Users/stevenwu/workspaces/github/stevenzwu/zkclient/./build/test/Zk_SERVER_IP_Change/data
> >> >> > 14/08/22 21:17:46  INFO [main] (ZkServer.java:101) - data log dir:
> >> >> >
> >> >> >
> >> >>
> >> >>
> /Users/stevenwu/workspaces/github/stevenzwu/zkclient/./build/test/Zk_SERVER_IP_Change/log
> >> >> > 14/08/22 21:17:47  INFO [ZkClient-EventThread-17-zkserver:2181]
> >> >> > (ZkEventThread.java:64) - Starting ZkClient event thread.
> >> >> > connected to null
> >> >> > 14/08/22 21:17:47  INFO [main-EventThread] (ZkClient.java:450) -
> >> >> zookeeper
> >> >> > state changed (SyncConnected)
> >> >> > send and receive data: 0
> >> >> > sleeping...0
> >> >> > send and receive data: 1
> >> >> > sleeping...1
> >> >> > send and receive data: 2
> >> >> > sleeping...2
> >> >> > send and receive data: 3
> >> >> > sleeping...3
> >> >> > send and receive data: 4
> >> >> > sleeping...4
> >> >> > 14/08/22 21:17:52  INFO [main] (ZkServer.java:124) - Shutting down
> >> >> > ZkServer...
> >> >> > 14/08/22 21:17:52  INFO [main] (ZkServer.java:143) - Shutting down
> >> >> > ZkServer...done
> >> >> > 14/08/22 21:17:52  INFO [main] (ZkServer.java:85) - Starting
> ZkServer
> >> >> > on:
> >> >> > hostname = 192.168.1.2, port = 2181
> >> >> > 14/08/22 21:17:52  INFO [main] (ZkServer.java:99) - Start single
> >> >> zookeeper
> >> >> > server...
> >> >> > 14/08/22 21:17:52  INFO [main] (ZkServer.java:100) - data dir:
> >> >> >
> >> >> >
> >> >>
> >> >>
> /Users/stevenwu/workspaces/github/stevenzwu/zkclient/./build/test/Zk_SERVER_IP_Change/data
> >> >> > 14/08/22 21:17:52  INFO [main] (ZkServer.java:101) - data log dir:
> >> >> >
> >> >> >
> >> >>
> >> >>
> /Users/stevenwu/workspaces/github/stevenzwu/zkclient/./build/test/Zk_SERVER_IP_Change/log
> >> >> >
> >> >> > EndOfStreamException: Unable to read additional data from server
> >> >> sessionid
> >> >> > 0x14801159e240000, likely server has closed socket
> >> >> > at
> >> >> >
> >> >>
> >> >>
> org.apache.zookeeper.ClientCnxnSocketNIO.doIO(ClientCnxnSocketNIO.java:75)
> >> >> > at
> >> >> >
> >> >> >
> >> >>
> >> >>
> org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:363)
> >> >> > at
> >> >> >
> org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1190)
> >> >> > 14/08/22 21:17:52  INFO [main-EventThread] (ZkClient.java:450) -
> >> >> zookeeper
> >> >> > state changed (Disconnected)
> >> >> >
> >> >> > ...
> >> >> >
> >> >> > java.net.ConnectException: Connection refused
> >> >> > at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
> >> >> > at
> >> >> >
> sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:735)
> >> >> > at
> >> >> >
> >> >> >
> >> >>
> >> >>
> org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:356)
> >> >> > at
> >> >> >
> org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1190)
> >> >> >
> >> >> > ...
> >> >> >
> >> >> > java.net.ConnectException: Connection refused
> >> >> > at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
> >> >> > at
> >> >> >
> sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:735)
> >> >> > at
> >> >> >
> >> >> >
> >> >>
> >> >>
> org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:356)
> >> >> > at
> >> >> >
> org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1190)
> >> >> >
> >> >> > ...
> >> >> >
> >> >> > connected to zkserver/192.168.1.2:2181
> >> >> > EndOfStreamException: Unable to read additional data from server
> >> >> sessionid
> >> >> > 0x14801159e240000, likely server has closed socket
> >> >> > at
> >> >> >
> >> >>
> >> >>
> org.apache.zookeeper.ClientCnxnSocketNIO.doIO(ClientCnxnSocketNIO.java:75)
> >> >> > at
> >> >> >
> >> >> >
> >> >>
> >> >>
> org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:363)
> >> >> > at
> >> >> >
> org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1190)
> >> >> >
> >> >> > ...
> >> >> >
> >> >> > connected to zkserver/192.168.1.2:2181
> >> >> > EndOfStreamException: Unable to read additional data from server
> >> >> sessionid
> >> >> > 0x14801159e240000, likely server has closed socket
> >> >> > at
> >> >> >
> >> >>
> >> >>
> org.apache.zookeeper.ClientCnxnSocketNIO.doIO(ClientCnxnSocketNIO.java:75)
> >> >> > at
> >> >> >
> >> >> >
> >> >>
> >> >>
> org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:363)
> >> >> > at
> >> >> >
> org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1190)
> >> >> >
> >> >>
> >
> >
>

Re: zookeeper server close connection unexpected

Posted by Michi Mutsuzaki <mi...@cs.stanford.edu>.
Yes, it would be great if you can get the zookeeper server log at the
DEBUG level.

On Sat, Aug 23, 2014 at 2:54 PM, Steven Wu <st...@gmail.com> wrote:
> It's a unit test. so I started the zookeeper server programmatically in
> localhost. looks like I better get log4j to work so that I can see logs from
> ZooKeeperServer.
>
>
> On Sat, Aug 23, 2014 at 12:02 PM, Michi Mutsuzaki <mi...@cs.stanford.edu>
> wrote:
>>
>> It would be helpful if you have the zookeeper server log from
>> 192.168.1.2:2181.
>>
>> On Sat, Aug 23, 2014 at 9:31 AM, Steven Wu <st...@gmail.com> wrote:
>> > client got the connected NIO event to the 2nd server instance. I also
>> > tried
>> > telnet to 192.168.1.2:2181. for whatever reason (e.g. protocol/auth),
>> > server decides to close the connection.
>> >
>> >
>> > On Sat, Aug 23, 2014 at 7:49 AM, Alexander Shraer <sh...@gmail.com>
>> > wrote:
>> >
>> >> is it possible that the new server isn't listening on the 2181 client
>> >> port
>> >> ?
>> >> perhaps something is misconfigured on the server side.
>> >>
>> >>
>> >> On Fri, Aug 22, 2014 at 9:32 PM, Steven Wu <st...@gmail.com>
>> >> wrote:
>> >>
>> >> > I am writing a unit test to simulate a scenario where server changes
>> >> > IP,
>> >> > which can happen in cloud env. During push, new instance can get a
>> >> > different private IP.
>> >> >
>> >> > As you can see from pasted code, I am running the test using
>> >> > zkclient.
>> >> > ZooKeeper#updateServerList works well by forcing resolution to new IP
>> >> > address that 2nd ZooKeeperServer object binds to. but the weird thing
>> >> > is
>> >> > that after connection established, it seems that server closes
>> >> > connection
>> >> > immediately. please see the log output in the end. I added some debug
>> >> > System.out.
>> >> >
>> >> > I am using zookeeper-3.5.0-rc1. Any help is appreciated!
>> >> >
>> >> > Thanks,
>> >> > Steven
>> >> >
>> >> > ###############################################
>> >> > /**
>> >> >  * To test this unit testing, the followings should be done first
>> >> >  *
>> >> >  * ====== pre-test setup ======
>> >> >  * # bind 192.168.1.1 and 192.168.1.2 to lo0 interface as alias
>> >> >  * sudo ifconfig lo0 192.168.1.1 alias
>> >> >  * sudo ifconfig lo0 192.168.1.2 alias
>> >> >  *
>> >> >  * ====== manual test ======
>> >> >  * - add mapping to /etc/hosts
>> >> >  *    192.168.1.1 zkserver
>> >> >  * - run test. it should stuck in the line of second
>> >> > client.createEphemeral(...)
>> >> >  * - change mapping in /etc/hosts
>> >> >  *    192.168.1.2 zkserver
>> >> >  * - test should proceed and finish
>> >> >  */
>> >> > @Ignore
>> >> > public class TestServerIpChange {
>> >> >
>> >> >     @Test
>> >> >     public void test() throws InterruptedException, IOException {
>> >> >         System.setProperty("log4j.logger.org.apache.zookeeper",
>> >> > "INFO");
>> >> >         ZkServer _zkServer =
>> >> TestUtil.startZkServer("Zk_SERVER_IP_Change",
>> >> > "192.168.1.1", 2181);
>> >> >
>> >> >         ZkClient client = new ZkClient("zkserver:2181", 10000, 5000);
>> >> >         client.createEphemeral("/a");
>> >> >         for (int i = 0; i < 5; ++i) {
>> >> >             System.out.println("send and receive data: " + i);
>> >> >             client.readData("/a");
>> >> >             client.writeData("/a", Integer.toString(i));
>> >> >             Thread.sleep(1000);
>> >> >             System.out.println("sleeping..." + i);
>> >> >         }
>> >> >         _zkServer.shutdown();
>> >> >
>> >> >         _zkServer = TestUtil.startZkServer("Zk_SERVER_IP_Change",
>> >> > "192.168.1.2", 2181);
>> >> >         // change /etc/hosts
>> >> >         client.createEphemeral("/a");
>> >> >         for (int i = 0; i < 5; ++i) {
>> >> >             System.out.println("send and receive data: " + i);
>> >> >             client.readData("/a");
>> >> >             client.writeData("/a", Integer.toString(i));
>> >> >             Thread.sleep(1000);
>> >> >             System.out.println("sleeping..." + i);
>> >> >         }
>> >> >         _zkServer.shutdown();
>> >> >     }
>> >> >
>> >> > }
>> >> >
>> >> > ###########################################
>> >> > 14/08/22 21:17:46  INFO [main] (ZkServer.java:85) - Starting ZkServer
>> >> > on:
>> >> > hostname = 192.168.1.1, port = 2181
>> >> > 14/08/22 21:17:46  INFO [main] (ZkServer.java:99) - Start single
>> >> zookeeper
>> >> > server...
>> >> > 14/08/22 21:17:46  INFO [main] (ZkServer.java:100) - data dir:
>> >> >
>> >> >
>> >>
>> >> /Users/stevenwu/workspaces/github/stevenzwu/zkclient/./build/test/Zk_SERVER_IP_Change/data
>> >> > 14/08/22 21:17:46  INFO [main] (ZkServer.java:101) - data log dir:
>> >> >
>> >> >
>> >>
>> >> /Users/stevenwu/workspaces/github/stevenzwu/zkclient/./build/test/Zk_SERVER_IP_Change/log
>> >> > 14/08/22 21:17:47  INFO [ZkClient-EventThread-17-zkserver:2181]
>> >> > (ZkEventThread.java:64) - Starting ZkClient event thread.
>> >> > connected to null
>> >> > 14/08/22 21:17:47  INFO [main-EventThread] (ZkClient.java:450) -
>> >> zookeeper
>> >> > state changed (SyncConnected)
>> >> > send and receive data: 0
>> >> > sleeping...0
>> >> > send and receive data: 1
>> >> > sleeping...1
>> >> > send and receive data: 2
>> >> > sleeping...2
>> >> > send and receive data: 3
>> >> > sleeping...3
>> >> > send and receive data: 4
>> >> > sleeping...4
>> >> > 14/08/22 21:17:52  INFO [main] (ZkServer.java:124) - Shutting down
>> >> > ZkServer...
>> >> > 14/08/22 21:17:52  INFO [main] (ZkServer.java:143) - Shutting down
>> >> > ZkServer...done
>> >> > 14/08/22 21:17:52  INFO [main] (ZkServer.java:85) - Starting ZkServer
>> >> > on:
>> >> > hostname = 192.168.1.2, port = 2181
>> >> > 14/08/22 21:17:52  INFO [main] (ZkServer.java:99) - Start single
>> >> zookeeper
>> >> > server...
>> >> > 14/08/22 21:17:52  INFO [main] (ZkServer.java:100) - data dir:
>> >> >
>> >> >
>> >>
>> >> /Users/stevenwu/workspaces/github/stevenzwu/zkclient/./build/test/Zk_SERVER_IP_Change/data
>> >> > 14/08/22 21:17:52  INFO [main] (ZkServer.java:101) - data log dir:
>> >> >
>> >> >
>> >>
>> >> /Users/stevenwu/workspaces/github/stevenzwu/zkclient/./build/test/Zk_SERVER_IP_Change/log
>> >> >
>> >> > EndOfStreamException: Unable to read additional data from server
>> >> sessionid
>> >> > 0x14801159e240000, likely server has closed socket
>> >> > at
>> >> >
>> >>
>> >> org.apache.zookeeper.ClientCnxnSocketNIO.doIO(ClientCnxnSocketNIO.java:75)
>> >> > at
>> >> >
>> >> >
>> >>
>> >> org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:363)
>> >> > at
>> >> > org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1190)
>> >> > 14/08/22 21:17:52  INFO [main-EventThread] (ZkClient.java:450) -
>> >> zookeeper
>> >> > state changed (Disconnected)
>> >> >
>> >> > ...
>> >> >
>> >> > java.net.ConnectException: Connection refused
>> >> > at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>> >> > at
>> >> > sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:735)
>> >> > at
>> >> >
>> >> >
>> >>
>> >> org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:356)
>> >> > at
>> >> > org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1190)
>> >> >
>> >> > ...
>> >> >
>> >> > java.net.ConnectException: Connection refused
>> >> > at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>> >> > at
>> >> > sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:735)
>> >> > at
>> >> >
>> >> >
>> >>
>> >> org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:356)
>> >> > at
>> >> > org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1190)
>> >> >
>> >> > ...
>> >> >
>> >> > connected to zkserver/192.168.1.2:2181
>> >> > EndOfStreamException: Unable to read additional data from server
>> >> sessionid
>> >> > 0x14801159e240000, likely server has closed socket
>> >> > at
>> >> >
>> >>
>> >> org.apache.zookeeper.ClientCnxnSocketNIO.doIO(ClientCnxnSocketNIO.java:75)
>> >> > at
>> >> >
>> >> >
>> >>
>> >> org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:363)
>> >> > at
>> >> > org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1190)
>> >> >
>> >> > ...
>> >> >
>> >> > connected to zkserver/192.168.1.2:2181
>> >> > EndOfStreamException: Unable to read additional data from server
>> >> sessionid
>> >> > 0x14801159e240000, likely server has closed socket
>> >> > at
>> >> >
>> >>
>> >> org.apache.zookeeper.ClientCnxnSocketNIO.doIO(ClientCnxnSocketNIO.java:75)
>> >> > at
>> >> >
>> >> >
>> >>
>> >> org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:363)
>> >> > at
>> >> > org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1190)
>> >> >
>> >>
>
>

Re: zookeeper server close connection unexpected

Posted by Steven Wu <st...@gmail.com>.
It's a unit test. so I started the zookeeper server programmatically in
localhost. looks like I better get log4j to work so that I can see logs
from ZooKeeperServer.


On Sat, Aug 23, 2014 at 12:02 PM, Michi Mutsuzaki <mi...@cs.stanford.edu>
wrote:

> It would be helpful if you have the zookeeper server log from
> 192.168.1.2:2181.
>
> On Sat, Aug 23, 2014 at 9:31 AM, Steven Wu <st...@gmail.com> wrote:
> > client got the connected NIO event to the 2nd server instance. I also
> tried
> > telnet to 192.168.1.2:2181. for whatever reason (e.g. protocol/auth),
> > server decides to close the connection.
> >
> >
> > On Sat, Aug 23, 2014 at 7:49 AM, Alexander Shraer <sh...@gmail.com>
> wrote:
> >
> >> is it possible that the new server isn't listening on the 2181 client
> port
> >> ?
> >> perhaps something is misconfigured on the server side.
> >>
> >>
> >> On Fri, Aug 22, 2014 at 9:32 PM, Steven Wu <st...@gmail.com>
> wrote:
> >>
> >> > I am writing a unit test to simulate a scenario where server changes
> IP,
> >> > which can happen in cloud env. During push, new instance can get a
> >> > different private IP.
> >> >
> >> > As you can see from pasted code, I am running the test using zkclient.
> >> > ZooKeeper#updateServerList works well by forcing resolution to new IP
> >> > address that 2nd ZooKeeperServer object binds to. but the weird thing
> is
> >> > that after connection established, it seems that server closes
> connection
> >> > immediately. please see the log output in the end. I added some debug
> >> > System.out.
> >> >
> >> > I am using zookeeper-3.5.0-rc1. Any help is appreciated!
> >> >
> >> > Thanks,
> >> > Steven
> >> >
> >> > ###############################################
> >> > /**
> >> >  * To test this unit testing, the followings should be done first
> >> >  *
> >> >  * ====== pre-test setup ======
> >> >  * # bind 192.168.1.1 and 192.168.1.2 to lo0 interface as alias
> >> >  * sudo ifconfig lo0 192.168.1.1 alias
> >> >  * sudo ifconfig lo0 192.168.1.2 alias
> >> >  *
> >> >  * ====== manual test ======
> >> >  * - add mapping to /etc/hosts
> >> >  *    192.168.1.1 zkserver
> >> >  * - run test. it should stuck in the line of second
> >> > client.createEphemeral(...)
> >> >  * - change mapping in /etc/hosts
> >> >  *    192.168.1.2 zkserver
> >> >  * - test should proceed and finish
> >> >  */
> >> > @Ignore
> >> > public class TestServerIpChange {
> >> >
> >> >     @Test
> >> >     public void test() throws InterruptedException, IOException {
> >> >         System.setProperty("log4j.logger.org.apache.zookeeper",
> "INFO");
> >> >         ZkServer _zkServer =
> >> TestUtil.startZkServer("Zk_SERVER_IP_Change",
> >> > "192.168.1.1", 2181);
> >> >
> >> >         ZkClient client = new ZkClient("zkserver:2181", 10000, 5000);
> >> >         client.createEphemeral("/a");
> >> >         for (int i = 0; i < 5; ++i) {
> >> >             System.out.println("send and receive data: " + i);
> >> >             client.readData("/a");
> >> >             client.writeData("/a", Integer.toString(i));
> >> >             Thread.sleep(1000);
> >> >             System.out.println("sleeping..." + i);
> >> >         }
> >> >         _zkServer.shutdown();
> >> >
> >> >         _zkServer = TestUtil.startZkServer("Zk_SERVER_IP_Change",
> >> > "192.168.1.2", 2181);
> >> >         // change /etc/hosts
> >> >         client.createEphemeral("/a");
> >> >         for (int i = 0; i < 5; ++i) {
> >> >             System.out.println("send and receive data: " + i);
> >> >             client.readData("/a");
> >> >             client.writeData("/a", Integer.toString(i));
> >> >             Thread.sleep(1000);
> >> >             System.out.println("sleeping..." + i);
> >> >         }
> >> >         _zkServer.shutdown();
> >> >     }
> >> >
> >> > }
> >> >
> >> > ###########################################
> >> > 14/08/22 21:17:46  INFO [main] (ZkServer.java:85) - Starting ZkServer
> on:
> >> > hostname = 192.168.1.1, port = 2181
> >> > 14/08/22 21:17:46  INFO [main] (ZkServer.java:99) - Start single
> >> zookeeper
> >> > server...
> >> > 14/08/22 21:17:46  INFO [main] (ZkServer.java:100) - data dir:
> >> >
> >> >
> >>
> /Users/stevenwu/workspaces/github/stevenzwu/zkclient/./build/test/Zk_SERVER_IP_Change/data
> >> > 14/08/22 21:17:46  INFO [main] (ZkServer.java:101) - data log dir:
> >> >
> >> >
> >>
> /Users/stevenwu/workspaces/github/stevenzwu/zkclient/./build/test/Zk_SERVER_IP_Change/log
> >> > 14/08/22 21:17:47  INFO [ZkClient-EventThread-17-zkserver:2181]
> >> > (ZkEventThread.java:64) - Starting ZkClient event thread.
> >> > connected to null
> >> > 14/08/22 21:17:47  INFO [main-EventThread] (ZkClient.java:450) -
> >> zookeeper
> >> > state changed (SyncConnected)
> >> > send and receive data: 0
> >> > sleeping...0
> >> > send and receive data: 1
> >> > sleeping...1
> >> > send and receive data: 2
> >> > sleeping...2
> >> > send and receive data: 3
> >> > sleeping...3
> >> > send and receive data: 4
> >> > sleeping...4
> >> > 14/08/22 21:17:52  INFO [main] (ZkServer.java:124) - Shutting down
> >> > ZkServer...
> >> > 14/08/22 21:17:52  INFO [main] (ZkServer.java:143) - Shutting down
> >> > ZkServer...done
> >> > 14/08/22 21:17:52  INFO [main] (ZkServer.java:85) - Starting ZkServer
> on:
> >> > hostname = 192.168.1.2, port = 2181
> >> > 14/08/22 21:17:52  INFO [main] (ZkServer.java:99) - Start single
> >> zookeeper
> >> > server...
> >> > 14/08/22 21:17:52  INFO [main] (ZkServer.java:100) - data dir:
> >> >
> >> >
> >>
> /Users/stevenwu/workspaces/github/stevenzwu/zkclient/./build/test/Zk_SERVER_IP_Change/data
> >> > 14/08/22 21:17:52  INFO [main] (ZkServer.java:101) - data log dir:
> >> >
> >> >
> >>
> /Users/stevenwu/workspaces/github/stevenzwu/zkclient/./build/test/Zk_SERVER_IP_Change/log
> >> >
> >> > EndOfStreamException: Unable to read additional data from server
> >> sessionid
> >> > 0x14801159e240000, likely server has closed socket
> >> > at
> >> >
> >>
> org.apache.zookeeper.ClientCnxnSocketNIO.doIO(ClientCnxnSocketNIO.java:75)
> >> > at
> >> >
> >> >
> >>
> org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:363)
> >> > at
> org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1190)
> >> > 14/08/22 21:17:52  INFO [main-EventThread] (ZkClient.java:450) -
> >> zookeeper
> >> > state changed (Disconnected)
> >> >
> >> > ...
> >> >
> >> > java.net.ConnectException: Connection refused
> >> > at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
> >> > at
> sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:735)
> >> > at
> >> >
> >> >
> >>
> org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:356)
> >> > at
> org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1190)
> >> >
> >> > ...
> >> >
> >> > java.net.ConnectException: Connection refused
> >> > at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
> >> > at
> sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:735)
> >> > at
> >> >
> >> >
> >>
> org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:356)
> >> > at
> org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1190)
> >> >
> >> > ...
> >> >
> >> > connected to zkserver/192.168.1.2:2181
> >> > EndOfStreamException: Unable to read additional data from server
> >> sessionid
> >> > 0x14801159e240000, likely server has closed socket
> >> > at
> >> >
> >>
> org.apache.zookeeper.ClientCnxnSocketNIO.doIO(ClientCnxnSocketNIO.java:75)
> >> > at
> >> >
> >> >
> >>
> org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:363)
> >> > at
> org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1190)
> >> >
> >> > ...
> >> >
> >> > connected to zkserver/192.168.1.2:2181
> >> > EndOfStreamException: Unable to read additional data from server
> >> sessionid
> >> > 0x14801159e240000, likely server has closed socket
> >> > at
> >> >
> >>
> org.apache.zookeeper.ClientCnxnSocketNIO.doIO(ClientCnxnSocketNIO.java:75)
> >> > at
> >> >
> >> >
> >>
> org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:363)
> >> > at
> org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1190)
> >> >
> >>
>

Re: zookeeper server close connection unexpected

Posted by Michi Mutsuzaki <mi...@cs.stanford.edu>.
It would be helpful if you have the zookeeper server log from 192.168.1.2:2181.

On Sat, Aug 23, 2014 at 9:31 AM, Steven Wu <st...@gmail.com> wrote:
> client got the connected NIO event to the 2nd server instance. I also tried
> telnet to 192.168.1.2:2181. for whatever reason (e.g. protocol/auth),
> server decides to close the connection.
>
>
> On Sat, Aug 23, 2014 at 7:49 AM, Alexander Shraer <sh...@gmail.com> wrote:
>
>> is it possible that the new server isn't listening on the 2181 client port
>> ?
>> perhaps something is misconfigured on the server side.
>>
>>
>> On Fri, Aug 22, 2014 at 9:32 PM, Steven Wu <st...@gmail.com> wrote:
>>
>> > I am writing a unit test to simulate a scenario where server changes IP,
>> > which can happen in cloud env. During push, new instance can get a
>> > different private IP.
>> >
>> > As you can see from pasted code, I am running the test using zkclient.
>> > ZooKeeper#updateServerList works well by forcing resolution to new IP
>> > address that 2nd ZooKeeperServer object binds to. but the weird thing is
>> > that after connection established, it seems that server closes connection
>> > immediately. please see the log output in the end. I added some debug
>> > System.out.
>> >
>> > I am using zookeeper-3.5.0-rc1. Any help is appreciated!
>> >
>> > Thanks,
>> > Steven
>> >
>> > ###############################################
>> > /**
>> >  * To test this unit testing, the followings should be done first
>> >  *
>> >  * ====== pre-test setup ======
>> >  * # bind 192.168.1.1 and 192.168.1.2 to lo0 interface as alias
>> >  * sudo ifconfig lo0 192.168.1.1 alias
>> >  * sudo ifconfig lo0 192.168.1.2 alias
>> >  *
>> >  * ====== manual test ======
>> >  * - add mapping to /etc/hosts
>> >  *    192.168.1.1 zkserver
>> >  * - run test. it should stuck in the line of second
>> > client.createEphemeral(...)
>> >  * - change mapping in /etc/hosts
>> >  *    192.168.1.2 zkserver
>> >  * - test should proceed and finish
>> >  */
>> > @Ignore
>> > public class TestServerIpChange {
>> >
>> >     @Test
>> >     public void test() throws InterruptedException, IOException {
>> >         System.setProperty("log4j.logger.org.apache.zookeeper", "INFO");
>> >         ZkServer _zkServer =
>> TestUtil.startZkServer("Zk_SERVER_IP_Change",
>> > "192.168.1.1", 2181);
>> >
>> >         ZkClient client = new ZkClient("zkserver:2181", 10000, 5000);
>> >         client.createEphemeral("/a");
>> >         for (int i = 0; i < 5; ++i) {
>> >             System.out.println("send and receive data: " + i);
>> >             client.readData("/a");
>> >             client.writeData("/a", Integer.toString(i));
>> >             Thread.sleep(1000);
>> >             System.out.println("sleeping..." + i);
>> >         }
>> >         _zkServer.shutdown();
>> >
>> >         _zkServer = TestUtil.startZkServer("Zk_SERVER_IP_Change",
>> > "192.168.1.2", 2181);
>> >         // change /etc/hosts
>> >         client.createEphemeral("/a");
>> >         for (int i = 0; i < 5; ++i) {
>> >             System.out.println("send and receive data: " + i);
>> >             client.readData("/a");
>> >             client.writeData("/a", Integer.toString(i));
>> >             Thread.sleep(1000);
>> >             System.out.println("sleeping..." + i);
>> >         }
>> >         _zkServer.shutdown();
>> >     }
>> >
>> > }
>> >
>> > ###########################################
>> > 14/08/22 21:17:46  INFO [main] (ZkServer.java:85) - Starting ZkServer on:
>> > hostname = 192.168.1.1, port = 2181
>> > 14/08/22 21:17:46  INFO [main] (ZkServer.java:99) - Start single
>> zookeeper
>> > server...
>> > 14/08/22 21:17:46  INFO [main] (ZkServer.java:100) - data dir:
>> >
>> >
>> /Users/stevenwu/workspaces/github/stevenzwu/zkclient/./build/test/Zk_SERVER_IP_Change/data
>> > 14/08/22 21:17:46  INFO [main] (ZkServer.java:101) - data log dir:
>> >
>> >
>> /Users/stevenwu/workspaces/github/stevenzwu/zkclient/./build/test/Zk_SERVER_IP_Change/log
>> > 14/08/22 21:17:47  INFO [ZkClient-EventThread-17-zkserver:2181]
>> > (ZkEventThread.java:64) - Starting ZkClient event thread.
>> > connected to null
>> > 14/08/22 21:17:47  INFO [main-EventThread] (ZkClient.java:450) -
>> zookeeper
>> > state changed (SyncConnected)
>> > send and receive data: 0
>> > sleeping...0
>> > send and receive data: 1
>> > sleeping...1
>> > send and receive data: 2
>> > sleeping...2
>> > send and receive data: 3
>> > sleeping...3
>> > send and receive data: 4
>> > sleeping...4
>> > 14/08/22 21:17:52  INFO [main] (ZkServer.java:124) - Shutting down
>> > ZkServer...
>> > 14/08/22 21:17:52  INFO [main] (ZkServer.java:143) - Shutting down
>> > ZkServer...done
>> > 14/08/22 21:17:52  INFO [main] (ZkServer.java:85) - Starting ZkServer on:
>> > hostname = 192.168.1.2, port = 2181
>> > 14/08/22 21:17:52  INFO [main] (ZkServer.java:99) - Start single
>> zookeeper
>> > server...
>> > 14/08/22 21:17:52  INFO [main] (ZkServer.java:100) - data dir:
>> >
>> >
>> /Users/stevenwu/workspaces/github/stevenzwu/zkclient/./build/test/Zk_SERVER_IP_Change/data
>> > 14/08/22 21:17:52  INFO [main] (ZkServer.java:101) - data log dir:
>> >
>> >
>> /Users/stevenwu/workspaces/github/stevenzwu/zkclient/./build/test/Zk_SERVER_IP_Change/log
>> >
>> > EndOfStreamException: Unable to read additional data from server
>> sessionid
>> > 0x14801159e240000, likely server has closed socket
>> > at
>> >
>> org.apache.zookeeper.ClientCnxnSocketNIO.doIO(ClientCnxnSocketNIO.java:75)
>> > at
>> >
>> >
>> org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:363)
>> > at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1190)
>> > 14/08/22 21:17:52  INFO [main-EventThread] (ZkClient.java:450) -
>> zookeeper
>> > state changed (Disconnected)
>> >
>> > ...
>> >
>> > java.net.ConnectException: Connection refused
>> > at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>> > at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:735)
>> > at
>> >
>> >
>> org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:356)
>> > at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1190)
>> >
>> > ...
>> >
>> > java.net.ConnectException: Connection refused
>> > at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>> > at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:735)
>> > at
>> >
>> >
>> org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:356)
>> > at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1190)
>> >
>> > ...
>> >
>> > connected to zkserver/192.168.1.2:2181
>> > EndOfStreamException: Unable to read additional data from server
>> sessionid
>> > 0x14801159e240000, likely server has closed socket
>> > at
>> >
>> org.apache.zookeeper.ClientCnxnSocketNIO.doIO(ClientCnxnSocketNIO.java:75)
>> > at
>> >
>> >
>> org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:363)
>> > at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1190)
>> >
>> > ...
>> >
>> > connected to zkserver/192.168.1.2:2181
>> > EndOfStreamException: Unable to read additional data from server
>> sessionid
>> > 0x14801159e240000, likely server has closed socket
>> > at
>> >
>> org.apache.zookeeper.ClientCnxnSocketNIO.doIO(ClientCnxnSocketNIO.java:75)
>> > at
>> >
>> >
>> org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:363)
>> > at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1190)
>> >
>>

Re: zookeeper server close connection unexpected

Posted by Steven Wu <st...@gmail.com>.
client got the connected NIO event to the 2nd server instance. I also tried
telnet to 192.168.1.2:2181. for whatever reason (e.g. protocol/auth),
server decides to close the connection.


On Sat, Aug 23, 2014 at 7:49 AM, Alexander Shraer <sh...@gmail.com> wrote:

> is it possible that the new server isn't listening on the 2181 client port
> ?
> perhaps something is misconfigured on the server side.
>
>
> On Fri, Aug 22, 2014 at 9:32 PM, Steven Wu <st...@gmail.com> wrote:
>
> > I am writing a unit test to simulate a scenario where server changes IP,
> > which can happen in cloud env. During push, new instance can get a
> > different private IP.
> >
> > As you can see from pasted code, I am running the test using zkclient.
> > ZooKeeper#updateServerList works well by forcing resolution to new IP
> > address that 2nd ZooKeeperServer object binds to. but the weird thing is
> > that after connection established, it seems that server closes connection
> > immediately. please see the log output in the end. I added some debug
> > System.out.
> >
> > I am using zookeeper-3.5.0-rc1. Any help is appreciated!
> >
> > Thanks,
> > Steven
> >
> > ###############################################
> > /**
> >  * To test this unit testing, the followings should be done first
> >  *
> >  * ====== pre-test setup ======
> >  * # bind 192.168.1.1 and 192.168.1.2 to lo0 interface as alias
> >  * sudo ifconfig lo0 192.168.1.1 alias
> >  * sudo ifconfig lo0 192.168.1.2 alias
> >  *
> >  * ====== manual test ======
> >  * - add mapping to /etc/hosts
> >  *    192.168.1.1 zkserver
> >  * - run test. it should stuck in the line of second
> > client.createEphemeral(...)
> >  * - change mapping in /etc/hosts
> >  *    192.168.1.2 zkserver
> >  * - test should proceed and finish
> >  */
> > @Ignore
> > public class TestServerIpChange {
> >
> >     @Test
> >     public void test() throws InterruptedException, IOException {
> >         System.setProperty("log4j.logger.org.apache.zookeeper", "INFO");
> >         ZkServer _zkServer =
> TestUtil.startZkServer("Zk_SERVER_IP_Change",
> > "192.168.1.1", 2181);
> >
> >         ZkClient client = new ZkClient("zkserver:2181", 10000, 5000);
> >         client.createEphemeral("/a");
> >         for (int i = 0; i < 5; ++i) {
> >             System.out.println("send and receive data: " + i);
> >             client.readData("/a");
> >             client.writeData("/a", Integer.toString(i));
> >             Thread.sleep(1000);
> >             System.out.println("sleeping..." + i);
> >         }
> >         _zkServer.shutdown();
> >
> >         _zkServer = TestUtil.startZkServer("Zk_SERVER_IP_Change",
> > "192.168.1.2", 2181);
> >         // change /etc/hosts
> >         client.createEphemeral("/a");
> >         for (int i = 0; i < 5; ++i) {
> >             System.out.println("send and receive data: " + i);
> >             client.readData("/a");
> >             client.writeData("/a", Integer.toString(i));
> >             Thread.sleep(1000);
> >             System.out.println("sleeping..." + i);
> >         }
> >         _zkServer.shutdown();
> >     }
> >
> > }
> >
> > ###########################################
> > 14/08/22 21:17:46  INFO [main] (ZkServer.java:85) - Starting ZkServer on:
> > hostname = 192.168.1.1, port = 2181
> > 14/08/22 21:17:46  INFO [main] (ZkServer.java:99) - Start single
> zookeeper
> > server...
> > 14/08/22 21:17:46  INFO [main] (ZkServer.java:100) - data dir:
> >
> >
> /Users/stevenwu/workspaces/github/stevenzwu/zkclient/./build/test/Zk_SERVER_IP_Change/data
> > 14/08/22 21:17:46  INFO [main] (ZkServer.java:101) - data log dir:
> >
> >
> /Users/stevenwu/workspaces/github/stevenzwu/zkclient/./build/test/Zk_SERVER_IP_Change/log
> > 14/08/22 21:17:47  INFO [ZkClient-EventThread-17-zkserver:2181]
> > (ZkEventThread.java:64) - Starting ZkClient event thread.
> > connected to null
> > 14/08/22 21:17:47  INFO [main-EventThread] (ZkClient.java:450) -
> zookeeper
> > state changed (SyncConnected)
> > send and receive data: 0
> > sleeping...0
> > send and receive data: 1
> > sleeping...1
> > send and receive data: 2
> > sleeping...2
> > send and receive data: 3
> > sleeping...3
> > send and receive data: 4
> > sleeping...4
> > 14/08/22 21:17:52  INFO [main] (ZkServer.java:124) - Shutting down
> > ZkServer...
> > 14/08/22 21:17:52  INFO [main] (ZkServer.java:143) - Shutting down
> > ZkServer...done
> > 14/08/22 21:17:52  INFO [main] (ZkServer.java:85) - Starting ZkServer on:
> > hostname = 192.168.1.2, port = 2181
> > 14/08/22 21:17:52  INFO [main] (ZkServer.java:99) - Start single
> zookeeper
> > server...
> > 14/08/22 21:17:52  INFO [main] (ZkServer.java:100) - data dir:
> >
> >
> /Users/stevenwu/workspaces/github/stevenzwu/zkclient/./build/test/Zk_SERVER_IP_Change/data
> > 14/08/22 21:17:52  INFO [main] (ZkServer.java:101) - data log dir:
> >
> >
> /Users/stevenwu/workspaces/github/stevenzwu/zkclient/./build/test/Zk_SERVER_IP_Change/log
> >
> > EndOfStreamException: Unable to read additional data from server
> sessionid
> > 0x14801159e240000, likely server has closed socket
> > at
> >
> org.apache.zookeeper.ClientCnxnSocketNIO.doIO(ClientCnxnSocketNIO.java:75)
> > at
> >
> >
> org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:363)
> > at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1190)
> > 14/08/22 21:17:52  INFO [main-EventThread] (ZkClient.java:450) -
> zookeeper
> > state changed (Disconnected)
> >
> > ...
> >
> > java.net.ConnectException: Connection refused
> > at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
> > at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:735)
> > at
> >
> >
> org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:356)
> > at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1190)
> >
> > ...
> >
> > java.net.ConnectException: Connection refused
> > at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
> > at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:735)
> > at
> >
> >
> org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:356)
> > at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1190)
> >
> > ...
> >
> > connected to zkserver/192.168.1.2:2181
> > EndOfStreamException: Unable to read additional data from server
> sessionid
> > 0x14801159e240000, likely server has closed socket
> > at
> >
> org.apache.zookeeper.ClientCnxnSocketNIO.doIO(ClientCnxnSocketNIO.java:75)
> > at
> >
> >
> org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:363)
> > at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1190)
> >
> > ...
> >
> > connected to zkserver/192.168.1.2:2181
> > EndOfStreamException: Unable to read additional data from server
> sessionid
> > 0x14801159e240000, likely server has closed socket
> > at
> >
> org.apache.zookeeper.ClientCnxnSocketNIO.doIO(ClientCnxnSocketNIO.java:75)
> > at
> >
> >
> org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:363)
> > at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1190)
> >
>

Re: zookeeper server close connection unexpected

Posted by Alexander Shraer <sh...@gmail.com>.
is it possible that the new server isn't listening on the 2181 client port
?
perhaps something is misconfigured on the server side.


On Fri, Aug 22, 2014 at 9:32 PM, Steven Wu <st...@gmail.com> wrote:

> I am writing a unit test to simulate a scenario where server changes IP,
> which can happen in cloud env. During push, new instance can get a
> different private IP.
>
> As you can see from pasted code, I am running the test using zkclient.
> ZooKeeper#updateServerList works well by forcing resolution to new IP
> address that 2nd ZooKeeperServer object binds to. but the weird thing is
> that after connection established, it seems that server closes connection
> immediately. please see the log output in the end. I added some debug
> System.out.
>
> I am using zookeeper-3.5.0-rc1. Any help is appreciated!
>
> Thanks,
> Steven
>
> ###############################################
> /**
>  * To test this unit testing, the followings should be done first
>  *
>  * ====== pre-test setup ======
>  * # bind 192.168.1.1 and 192.168.1.2 to lo0 interface as alias
>  * sudo ifconfig lo0 192.168.1.1 alias
>  * sudo ifconfig lo0 192.168.1.2 alias
>  *
>  * ====== manual test ======
>  * - add mapping to /etc/hosts
>  *    192.168.1.1 zkserver
>  * - run test. it should stuck in the line of second
> client.createEphemeral(...)
>  * - change mapping in /etc/hosts
>  *    192.168.1.2 zkserver
>  * - test should proceed and finish
>  */
> @Ignore
> public class TestServerIpChange {
>
>     @Test
>     public void test() throws InterruptedException, IOException {
>         System.setProperty("log4j.logger.org.apache.zookeeper", "INFO");
>         ZkServer _zkServer = TestUtil.startZkServer("Zk_SERVER_IP_Change",
> "192.168.1.1", 2181);
>
>         ZkClient client = new ZkClient("zkserver:2181", 10000, 5000);
>         client.createEphemeral("/a");
>         for (int i = 0; i < 5; ++i) {
>             System.out.println("send and receive data: " + i);
>             client.readData("/a");
>             client.writeData("/a", Integer.toString(i));
>             Thread.sleep(1000);
>             System.out.println("sleeping..." + i);
>         }
>         _zkServer.shutdown();
>
>         _zkServer = TestUtil.startZkServer("Zk_SERVER_IP_Change",
> "192.168.1.2", 2181);
>         // change /etc/hosts
>         client.createEphemeral("/a");
>         for (int i = 0; i < 5; ++i) {
>             System.out.println("send and receive data: " + i);
>             client.readData("/a");
>             client.writeData("/a", Integer.toString(i));
>             Thread.sleep(1000);
>             System.out.println("sleeping..." + i);
>         }
>         _zkServer.shutdown();
>     }
>
> }
>
> ###########################################
> 14/08/22 21:17:46  INFO [main] (ZkServer.java:85) - Starting ZkServer on:
> hostname = 192.168.1.1, port = 2181
> 14/08/22 21:17:46  INFO [main] (ZkServer.java:99) - Start single zookeeper
> server...
> 14/08/22 21:17:46  INFO [main] (ZkServer.java:100) - data dir:
>
> /Users/stevenwu/workspaces/github/stevenzwu/zkclient/./build/test/Zk_SERVER_IP_Change/data
> 14/08/22 21:17:46  INFO [main] (ZkServer.java:101) - data log dir:
>
> /Users/stevenwu/workspaces/github/stevenzwu/zkclient/./build/test/Zk_SERVER_IP_Change/log
> 14/08/22 21:17:47  INFO [ZkClient-EventThread-17-zkserver:2181]
> (ZkEventThread.java:64) - Starting ZkClient event thread.
> connected to null
> 14/08/22 21:17:47  INFO [main-EventThread] (ZkClient.java:450) - zookeeper
> state changed (SyncConnected)
> send and receive data: 0
> sleeping...0
> send and receive data: 1
> sleeping...1
> send and receive data: 2
> sleeping...2
> send and receive data: 3
> sleeping...3
> send and receive data: 4
> sleeping...4
> 14/08/22 21:17:52  INFO [main] (ZkServer.java:124) - Shutting down
> ZkServer...
> 14/08/22 21:17:52  INFO [main] (ZkServer.java:143) - Shutting down
> ZkServer...done
> 14/08/22 21:17:52  INFO [main] (ZkServer.java:85) - Starting ZkServer on:
> hostname = 192.168.1.2, port = 2181
> 14/08/22 21:17:52  INFO [main] (ZkServer.java:99) - Start single zookeeper
> server...
> 14/08/22 21:17:52  INFO [main] (ZkServer.java:100) - data dir:
>
> /Users/stevenwu/workspaces/github/stevenzwu/zkclient/./build/test/Zk_SERVER_IP_Change/data
> 14/08/22 21:17:52  INFO [main] (ZkServer.java:101) - data log dir:
>
> /Users/stevenwu/workspaces/github/stevenzwu/zkclient/./build/test/Zk_SERVER_IP_Change/log
>
> EndOfStreamException: Unable to read additional data from server sessionid
> 0x14801159e240000, likely server has closed socket
> at
> org.apache.zookeeper.ClientCnxnSocketNIO.doIO(ClientCnxnSocketNIO.java:75)
> at
>
> org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:363)
> at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1190)
> 14/08/22 21:17:52  INFO [main-EventThread] (ZkClient.java:450) - zookeeper
> state changed (Disconnected)
>
> ...
>
> java.net.ConnectException: Connection refused
> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
> at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:735)
> at
>
> org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:356)
> at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1190)
>
> ...
>
> java.net.ConnectException: Connection refused
> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
> at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:735)
> at
>
> org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:356)
> at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1190)
>
> ...
>
> connected to zkserver/192.168.1.2:2181
> EndOfStreamException: Unable to read additional data from server sessionid
> 0x14801159e240000, likely server has closed socket
> at
> org.apache.zookeeper.ClientCnxnSocketNIO.doIO(ClientCnxnSocketNIO.java:75)
> at
>
> org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:363)
> at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1190)
>
> ...
>
> connected to zkserver/192.168.1.2:2181
> EndOfStreamException: Unable to read additional data from server sessionid
> 0x14801159e240000, likely server has closed socket
> at
> org.apache.zookeeper.ClientCnxnSocketNIO.doIO(ClientCnxnSocketNIO.java:75)
> at
>
> org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:363)
> at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1190)
>