Mailing-List: contact user-help@zookeeper.apache.org; run by ezmlm
Precedence: bulk
Reply-To: user@zookeeper.apache.org
Received-SPF: pass (athena.apache.org: domain of dsetia@juniper.net designates
 216.32.180.187 as permitted sender)
Received-SPF: pass (mail48-co1: domain of juniper.net designates
 157.56.240.101 as permitted sender) client-ip=157.56.240.101;
 envelope-from=dsetia@juniper.net;
 helo=BL2PRD0510HT001.namprd05.prod.outlook.com ;.outlook.com ;
From: Deepinder Singh Setia <dsetia@juniper.net>
To: "user@zookeeper.apache.org" <user@zookeeper.apache.org>
Subject: OperationTimeoutException error
Thread-Topic: OperationTimeoutException error
Thread-Index: AQHOlRtecalBxIY5ukayaLkwGDBgOw==
Date: Fri, 9 Aug 2013 16:13:21 +0000
Message-ID: <A4CA82E1-C479-44B8-B78B-59E4DEB364CF@juniper.net>
Accept-Language: en-US
Content-Language: en-US
Content-Type: text/plain; charset="Windows-1252"
Content-ID: <0FE915C5F4991547A7139E3D6A3F2A3F@namprd05.prod.outlook.com>
Content-Transfer-Encoding: quoted-printable
MIME-Version: 1.0

I am using Kazoo client and see the following error:

Aug  9 07:07:20 a2s1 python[2085]: File "/usr/lib/python2.7/site-packages/k=
azoo/client.py", line 894, in set
Aug  9 07:07:20 a2s1 python[2085]: return self.set_async(path, data, versio=
n).get()
Aug  9 07:07:20 a2s1 python[2085]: File "/usr/lib64/python2.7/site-packages=
/gevent/event.py", line 223, in get
Aug  9 07:07:20 a2s1 python[2085]: raise self._exception=20
Aug  9 07:07:20 a2s1 python[2085]: OperationTimeoutException: operation tim=
eout

zookeeper logs around the error time:

2013-08-09 07:07:06,580 [myid:] - WARN  [SyncThread:0:FileTxnLog@321] - fsy=
nc-ing the write ahead log in SyncThread:0 took 2291ms which will adversely=
 effect operation latency. See the ZooKeeper troubleshooting guide
=85
2013-08-09 07:07:19,827 [myid:] - WARN  [NIOServerCxn.Factory:0.0.0.0/0.0.0=
.0:2181:NIOServerCnxn@349] - caught end of stream exception
EndOfStreamException: Unable to read additional data from client sessionid =
0x1406356c3bc0001, likely client has closed socket
        at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.jav=
a:220)
        at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCn=
xnFactory.java:224)
        at java.lang.Thread.run(Thread.java:722)
2013-08-09 07:07:19,828 [myid:] - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0=
.0:2181:NIOServerCnxn@1000] - Closed socket connection for client /127.0.0.=
1:54698 which had sessionid 0x1406356c3bc0001
2013-08-09 07:07:20,246 [myid:] - WARN  [NIOServerCxn.Factory:0.0.0.0/0.0.0=
.0:2181:NIOServerCnxn@349] - caught end of stream exception
EndOfStreamException: Unable to read additional data from client sessionid =
0x1406356c3bc0000, likely client has closed socket
        at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.jav=
a:220)
        at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCn=
xnFactory.java:224)
        at java.lang.Thread.run(Thread.java:722)
2013-08-09 07:07:20,246 [myid:] - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0=
.0:2181:NIOServerCnxn@1000] - Closed socket connection for client /127.0.0.=
1:54579 which had sessionid 0x1406356c3bc0000
2013-08-09 07:07:21,583 [myid:] - WARN  [SyncThread:0:FileTxnLog@321] - fsy=
nc-ing the write ahead log in SyncThread:0 took 8001ms which will adversely=
 effect operation latency. See the ZooKeeper troubleshooting guide
2013-08-09 07:07:21,680 [myid:] - ERROR [SyncThread:0:NIOServerCnxn@180] - =
Unexpected Exception:
java.nio.channels.CancelledKeyException

[root@a2s1 zookeeper]# grep fsync /var/log/zookeeper/zookeeper.out=20
2013-08-09 07:06:52,280 [myid:] - WARN  [SyncThread:0:FileTxnLog@321] - fsy=
nc-ing the write ahead log in SyncThread:0 took 1724ms which will adversely=
 effect operation latency. See the ZooKeeper troubleshooting guide
2013-08-09 07:06:58,315 [myid:] - WARN  [SyncThread:0:FileTxnLog@321] - fsy=
nc-ing the write ahead log in SyncThread:0 took 2378ms which will adversely=
 effect operation latency. See the ZooKeeper troubleshooting guide
2013-08-09 07:07:01,389 [myid:] - WARN  [SyncThread:0:FileTxnLog@321] - fsy=
nc-ing the write ahead log in SyncThread:0 took 1113ms which will adversely=
 effect operation latency. See the ZooKeeper troubleshooting guide
2013-08-09 07:07:06,580 [myid:] - WARN  [SyncThread:0:FileTxnLog@321] - fsy=
nc-ing the write ahead log in SyncThread:0 took 2291ms which will adversely=
 effect operation latency. See the ZooKeeper troubleshooting guide
2013-08-09 07:07:21,583 [myid:] - WARN  [SyncThread:0:FileTxnLog@321] - fsy=
nc-ing the write ahead log in SyncThread:0 took 8001ms which will adversely=
 effect operation latency. See the ZooKeeper troubleshooting guide
[

Could the client (Kazoo) be timing out because of fsync delay? What paramet=
er would control duration for OperationTimeoutException that I can perhaps =
increase to verify? There is only ZooKeeper client and the load isn't much =
- 1 read/sec and 2 writes/sec roughly. Zookeeper configuration is default. =
Kazoo client params are also default.=20

Thanks
Deepinder