We're having some trouble with the Flume & the HbaseSink working. Seems we
cannot hang on to zookeeper sessions. The flume list recommended I cross
post here as this seems to be something up with the hbaseclient &/or
zookeeper. In all honesty I am probably just doing something dumb and not
seeing it.

Using latest flume-ng 1.3.0, hbase 0.94.0. Hbase & ZK both look fine and
are in normal prod use. I don't think we are hitting our
hbase.zookeeper.property.maxClientCnxns as we only have about 95 sessions
in ZK DUMP and I believe it defaults to 2k. I can establish new sessions
using the CLI from the same server and idle there for 10 minutes without
getting dropped. When I start up flume I see the session show up in the ZK
DUMP, see active TCP connection on the port etc., it just keeps
dropping/reconnecting.

Flume & zookeeper logs below, using rsync'd copies of our hadoop & hbase
directories from one of our datanode+regionserver's.

*Searched the flume list, this user appeared to have the same problem, not
sure how he fixed it though:*
http://mail-archives.apache.org/mod_mbox/flume-user/201207.mbox/%[EMAIL PROTECTED]%3E

*startup cmd
*/app/apache-flume-1.3.0-SNAPSHOT/bin/flume-ng agent -n agent1 -c ./conf -f
conf/brian.properties  -Dflume.root.logger=INFO,console*
*
*flume-env.sh*
$ cat conf/flume-env.sh

# Licensed to the Apache Software Foundation (ASF) under one
# or more contributor license agreements.  See the NOTICE file
# distributed with this work for additional information
# regarding copyright ownership.  The ASF licenses this file
# to you under the Apache License, Version 2.0 (the
# "License"); you may not use this file except in compliance
# with the License.  You may obtain a copy of the License at
#
#     http://www.apache.org/licenses/LICENSE-2.0
#
# Unless required by applicable law or agreed to in writing, software
# distributed under the License is distributed on an "AS IS" BASIS,
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
# See the License for the specific language governing permissions and
# limitations under the License.

# If this file is placed at FLUME_CONF_DIR/flume-env.sh, it will be sourced
# during Flume startup.

# Enviroment variables can be set here.

#JAVA_HOME=/usr/lib/jvm/java-6-sun

# Give Flume more memory and pre-allocate, enable remote monitoring via JMX
#JAVA_OPTS="-Xms100m -Xmx200m -Dcom.sun.management.jmxremote"

# Note that the Flume conf directory is always included in the classpath.
#FLUME_CLASSPATH="/app/flume/lib"

FLUME_CLASSPATH="/app/apache-flume-1.3.0-SNAPSHOT/lib"

HBASE_HOME="/app/hbase-0.94.0"

HADOOP_HOME="/app/hadoop-1.0.1"
*config*
$ cat conf/brian.properties
#example.conf: A single-node Flume configuration

# Name the components on this agent
agent1.sources = source1
agent1.sinks = sink1
agent1.channels = channel1

# Describe/configure source1
agent1.sources.source1.type = exec
agent1.sources.source1.command = tail -F /tank/log_dev.log
agent1.sources.source1.batchSize = 1
# Describe sink1
#agent1.sinks.sink1.type = logger
agent1.sinks.sink1.type = org.apache.flume.sink.hbase.HBaseSink
agent1.sinks.sink1.table = brian_test
agent1.sinks.sink1.columnFamily = f1
#agent1.sinks.sink1.serializer org.apache.flume.sink.hbase.SimpleHBaseEventSerializer
#agent1.sinks.sink1.serializer org.apache.flume.sink.hbase.SimpleHbaseEventSerializer
# Use a channel which buffers events in memory
agent1.channels.channel1.type = memory
agent1.channels.channel1.capacity = 1000
agent1.channels.channel1.transactionCapactiy = 100

# Bind the source and sink to the channel
agent1.sources.source1.channels = channel1
agent1.sinks.sink1.channel = channel1
*flume console log*
2012-10-08 12:06:19,007 (lifecycleSupervisor-1-1) [INFO -
org.apache.zookeeper.Environment.logEnv(Environment.java:100)] Client
environment:java.library.path=:/app/hadoop-1.0.1/libexec/../lib/native/FreeBSD-amd64-64:/app/hbase-0.94.0/bin/../lib/native/FreeBSD-amd64-64
2012-10-08 12:06:19,008 (lifecycleSupervisor-1-1) [INFO -
org.apache.zookeeper.Environment.logEnv(Environment.java:100)] Client
environment:java.io.tmpdir=/var/tmp/
2012-10-08 12:06:19,008 (lifecycleSupervisor-1-1) [INFO -
org.apache.zookeeper.Environment.logEnv(Environment.java:100)] Client
environment:java.compiler=<NA>
2012-10-08 12:06:19,008 (lifecycleSupervisor-1-1) [INFO -
org.apache.zookeeper.Environment.logEnv(Environment.java:100)] Client
environment:os.name=FreeBSD
2012-10-08 12:06:19,008 (lifecycleSupervisor-1-1) [INFO -
org.apache.zookeeper.Environment.logEnv(Environment.java:100)] Client
environment:os.arch=amd64
2012-10-08 12:06:19,008 (lifecycleSupervisor-1-1) [INFO -
org.apache.zookeeper.Environment.logEnv(Environment.java:100)] Client
environment:os.version=9.0-RELEASE
2012-10-08 12:06:19,009 (lifecycleSupervisor-1-1) [INFO -
org.apache.zookeeper.Environment.logEnv(Environment.java:100)] Client
environment:user.name=czhang
2012-10-08 12:06:19,009 (lifecycleSupervisor-1-1) [INFO -
org.apache.zookeeper.Environment.logEnv(Environment.java:100)] Client
environment:user.home=/users/czhang
2012-10-08 12:06:19,009 (lifecycleSupervisor-1-1) [INFO -
org.apache.zookeeper.Environment.logEnv(Environment.java:100)] Client
environment:user.dir=/app/apache-flume-1.3.0-SNAPSHOT
2012-10-08 12:06:19,010 (lifecycleSupervisor-1-1) [INFO -
org.apache.zookeeper.ZooKeeper.<init>(ZooKeeper.java:433)] Initiating
client connection,
connectString=hbasemaster0.hadoop.domain.com:2181sessionTimeout=180000
watcher=hconnection
2012-10-08 12:06:19,036 (lifecycleSupervisor-1-1) [INFO -
org.apache.hadoop.hbase.zookeeper.RecoverableZooKeeper.<init>(RecoverableZooKeeper.java:97)]
The identifier of this process is [EMAIL PROTECTED]
2012-10-08 12:06:19,041 (lifecycleSupervisor-1-1-SendThread(
hbasemaster0.hadoop.domain.com:2181)) [INFO -
org.apache.zookeeper.ClientCnxn$SendThread.logStartConnect(ClientCnxn.java:966)]
Opening socket connection to server
hbase

Below is a debug level log of flume trying to connect. Could we
experiencing this bug: https://issues.apache.org/jira/browse/ZOOKEEPER-1550

We are using openjdk version "1.7.0_02"
OpenJDK Runtime Environment (build 1.7.0_02-b13)
OpenJDK 64-Bit Server VM (build 22.0-b10, mixed mode)

debug log:

2012-10-08 15:28:01,324 (lifecycleSupervisor-1-0-EventThread) [DEBUG -
org.hbase.async.HBaseClient$ZKClient.process(HBaseClient.java:2293)] Got
ZooKeeper event: WatchedEvent state:SyncConnected type:None path:null

2012-10-08 15:28:01,325 (lifecycleSupervisor-1-0-SendThread(
hbasemaster0.hadoop.telescope.tv:2181)) [DEBUG -
org.apache.zookeeper.ClientCnxnSocketNIO.findSendablePacket(ClientCnxnSocketNIO.java:164)]
deferring non-priming packet: clientPath:/hbase/root-region-server
serverPath:/hbase/root-region-server finished:false header:: 0,4
replyHeader:: 0,0,0  request:: '/hbase/root-region-server,T  response::
until SASL authentication completes.

2012-10-08 15:28:01,326 (lifecycleSupervisor-1-0-SendThread(
hbasemaster0.hadoop.telescope.tv:2181)) [DEBUG -
org.apache.zookeeper.ClientCnxnSocketNIO.findSendablePacket(ClientCnxnSocketNIO.java:164)]
deferring non-priming packet: clientPath:null serverPath:null
finished:false header:: 0,-11  replyHeader:: 0,0,0  request:: null
response:: nulluntil SASL authentication completes.

2012-10-08 15:28:01,327 (lifecycleSupervisor-1-0-SendThread(
hbasemaster0.hadoop.telescope.tv:2181)) [DEBUG -
org.apache.zookeeper.ClientCnxnSocketNIO.findSendablePacket(ClientCnxnSocketNIO.java:164)]
deferring non-priming packet: clientPath:/hbase/root-region-server
serverPath:/hbase/root-region-server finished:false header:: 0,4
replyHeader:: 0,0,0  request:: '/hbase/root-region-server,T  response::
until SASL authentication completes.

2012-10-08 15:28:01,328 (lifecycleSupervisor-1-0-SendThread(
hbasemaster0.hadoop.telescope.tv:2181)) [DEBUG -
org.apache.zookeeper.ClientCnxnSocketNIO.findSendablePacket(ClientCnxnSocketNIO.java:164)]
deferring non-priming packet: clientPath:null serverPath:null
finished:false header:: 0,-11  replyHeader:: 0,0,0  request:: null
response:: nulluntil SASL authentication completes.

2012-10-08 15:28:03,322 (lifecycleSupervisor-1-0-SendThread(
hbasemaster0.hadoop.telescope.tv:2181)) [DEBUG -
org.apache.zookeeper.ClientCnxnSocketNIO.findSendablePacket(ClientCnxnSocketNIO.java:164)]
deferring non-priming packet: clientPath:/hbase/root-region-server
serverPath:/hbase/root-region-server finished:false header:: 0,4
replyHeader:: 0,0,0  request:: '/hbase/root-region-server,T  response::
until SASL authentication completes.

2012-10-08 15:28:03,323 (lifecycleSupervisor-1-0-SendThread(
hbasemaster0.hadoop.telescope.tv:2181)) [DEBUG -
org.apache.zookeeper.ClientCnxnSocketNIO.findSendablePacket(ClientCnxnSocketNIO.java:164)]
deferring non-priming packet: clientPath:null serverPath:null
finished:false header:: 0,-11  replyHeader:: 0,0,0  request:: null
response:: nulluntil SASL authentication completes.

2012-10-08 15:28:03,332 (lifecycleSupervisor-1-0-SendThread(
hbasemaster0.hadoop.telescope.tv:2181)) [DEBUG -
org.apache.zookeeper.ClientCnxnSocketNIO.findSendablePacket(ClientCnxnSocketNIO.java:164)]
deferring non-priming packet: clientPath:/hbase/root-region-server
serverPath:/hbase/root-region-server finished:false header:: 0,4
replyHeader:: 0,0,0  request:: '/hbase/root-region-server,T  response::
until SASL authentication completes.

2012-10-08 15:28:03,334 (lifecycleSupervisor-1-0-SendThread(
hbasemaster0.hadoop.telescope.tv:2181)) [DEBUG -
org.apache.zookeeper.ClientCnxnSocketNIO.findSendablePacket(ClientCnxnSocketNIO.java:164)]
deferring non-priming packet: clientPath:null serverPath:null
finished:false header:: 0,-11  replyHeader:: 0,0,0  request:: null
response:: nulluntil SASL authentication completes.

2012-10-08 15:28:05,333 (lifecycleSupervisor-1-0-SendThread(
hbasemaster0.hadoop.telescope.tv:2181)) [DEBUG -
org.apache.zookeeper.ClientCnxnSocketNIO.findSendablePacket(ClientCnxnSocketNIO.java:164)]
deferring non-priming packet: clientPath:/hbase/root-region-server
serverPath:/hbase/root-region-server finished:false header:: 0,4
replyHeader:: 0,0,0  request:: '/hbase/root-region-server,T  response::
until SASL authentication completes.

2012-10-08 15:28:05,334 (lifecycleSupervisor-1-0-SendThread(
hbasemaster0.hadoop.telescope.tv:2181)) [DEBUG -
org.apache.zookeeper.ClientCnxnSocketNIO.findSendablePacket(ClientCnxnSocketNIO.java:164)]
deferring non-priming packet: clientPath:null serverPath:null
finished:false header:: 0,-11  replyHeader:: 0,0,0  request:: null
response:: nulluntil SASL authentication completes.

2012-10-08 15:28:05,334 (lifecycleSupervisor-1-0-SendThread(
hbasemaster0.hadoop.telescope.tv:2181)) [DEBUG -
org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1073)] An
exception was thrown while closing send thread for session
0x138a0620045bf8f : Client session timed out, have not heard from server in
4009ms for sessionid 0x138a0620045bf8f

2012-10-08 15:28:05,410 (conf-file-poller-0) [DEBUG -
org.apache.flume.conf.file.AbstractFileConfigurationProvider$FileWatcherRunnable.run(AbstractFileConfigurationProvider.java:188)]
Checking file:conf/brian.properties for changes

2012-10-08 15:28:05,435 (lifecycleSupervisor-1-0-EventThread) [DEBUG -
org.apache.zookeeper.ClientCnxn.disconnect(ClientCnxn.java:1257)]
Disconnecting client for session: 0x138a0620045bf8f

2012-10-08 15:28:05,436 (lifecycleSupervisor-1-0-EventThread) [INFO -
org.apache.zookeeper.ZooKeeper.close(ZooKeeper.java:679)] Session:
0x138a0620045bf8f closed

2012-10-08 15:28:05,436 (lifecycleSupervisor-1-0-EventThread) [DEBUG -
org.hbase.async.HBaseClient$ZKClient.disconnectZK(HBaseClient.java:2365)]
ZooKeeper#close completed in 4123621708ns

2012-10-08 15:28:05,436 (lifecycleSupervisor-1-0-EventThread) [INFO -
org.apache.zookeeper.ZooKeeper.<init>(ZooKeeper.java:433)] Initiating
client connection,
connectString=hbasemaster0.hadoop.telescope.tvsessionTimeout=5000
w

My 2 cents:

In past when i have used OpenJDK, i ran into a DNS resolution trouble with
Hadoop/HBase. The problem was resolved when i started using Sun Jdk. I
would suggest you to try the preferred version of Sun Java 1.6. You can
find this info on HBase website. It's worth a try although i am not sure
that this is the problem.

HTH,
Anil Gupta

On Mon, Oct 8, 2012 at 3:56 PM, iain wright <[EMAIL PROTECTED]> wrote:

> Below is a debug level log of flume trying to connect. Could we
> experiencing this bug:
> https://issues.apache.org/jira/browse/ZOOKEEPER-1550
>
> We are using openjdk version "1.7.0_02"
> OpenJDK Runtime Environment (build 1.7.0_02-b13)
> OpenJDK 64-Bit Server VM (build 22.0-b10, mixed mode)
>
> debug log:
>
> 2012-10-08 15:28:01,324 (lifecycleSupervisor-1-0-EventThread) [DEBUG -
> org.hbase.async.HBaseClient$ZKClient.process(HBaseClient.java:2293)] Got
> ZooKeeper event: WatchedEvent state:SyncConnected type:None path:null
>
> 2012-10-08 15:28:01,325 (lifecycleSupervisor-1-0-SendThread(
> hbasemaster0.hadoop.telescope.tv:2181)) [DEBUG -
>
> org.apache.zookeeper.ClientCnxnSocketNIO.findSendablePacket(ClientCnxnSocketNIO.java:164)]
> deferring non-priming packet: clientPath:/hbase/root-region-server
> serverPath:/hbase/root-region-server finished:false header:: 0,4
> replyHeader:: 0,0,0  request:: '/hbase/root-region-server,T  response::
> until SASL authentication completes.
>
> 2012-10-08 15:28:01,326 (lifecycleSupervisor-1-0-SendThread(
> hbasemaster0.hadoop.telescope.tv:2181)) [DEBUG -
>
> org.apache.zookeeper.ClientCnxnSocketNIO.findSendablePacket(ClientCnxnSocketNIO.java:164)]
> deferring non-priming packet: clientPath:null serverPath:null
> finished:false header:: 0,-11  replyHeader:: 0,0,0  request:: null
> response:: nulluntil SASL authentication completes.
>
> 2012-10-08 15:28:01,327 (lifecycleSupervisor-1-0-SendThread(
> hbasemaster0.hadoop.telescope.tv:2181)) [DEBUG -
>
> org.apache.zookeeper.ClientCnxnSocketNIO.findSendablePacket(ClientCnxnSocketNIO.java:164)]
> deferring non-priming packet: clientPath:/hbase/root-region-server
> serverPath:/hbase/root-region-server finished:false header:: 0,4
> replyHeader:: 0,0,0  request:: '/hbase/root-region-server,T  response::
> until SASL authentication completes.
>
> 2012-10-08 15:28:01,328 (lifecycleSupervisor-1-0-SendThread(
> hbasemaster0.hadoop.telescope.tv:2181)) [DEBUG -
>
> org.apache.zookeeper.ClientCnxnSocketNIO.findSendablePacket(ClientCnxnSocketNIO.java:164)]
> deferring non-priming packet: clientPath:null serverPath:null
> finished:false header:: 0,-11  replyHeader:: 0,0,0  request:: null
> response:: nulluntil SASL authentication completes.
>
> 2012-10-08 15:28:03,322 (lifecycleSupervisor-1-0-SendThread(
> hbasemaster0.hadoop.telescope.tv:2181)) [DEBUG -
>
> org.apache.zookeeper.ClientCnxnSocketNIO.findSendablePacket(ClientCnxnSocketNIO.java:164)]
> deferring non-priming packet: clientPath:/hbase/root-region-server
> serverPath:/hbase/root-region-server finished:false header:: 0,4
> replyHeader:: 0,0,0  request:: '/hbase/root-region-server,T  response::
> until SASL authentication completes.
>
> 2012-10-08 15:28:03,323 (lifecycleSupervisor-1-0-SendThread(
> hbasemaster0.hadoop.telescope.tv:2181)) [DEBUG -
>
> org.apache.zookeeper.ClientCnxnSocketNIO.findSendablePacket(ClientCnxnSocketNIO.java:164)]
> deferring non-priming packet: clientPath:null serverPath:null
> finished:false header:: 0,-11  replyHeader:: 0,0,0  request:: null
> response:: nulluntil SASL authentication completes.
>
> 2012-10-08 15:28:03,332 (lifecycleSupervisor-1-0-SendThread(
> hbasemaster0.hadoop.telescope.tv:2181)) [DEBUG -
>
> org.apache.zookeeper.ClientCnxnSocketNIO.findSendablePacket(ClientCnxnSocketNIO.java:164)]
> deferring non-priming packet: clientPath:/hbase/root-region-server
> serverPath:/hbase/root-region-server finished:false header:: 0,4
> replyHeader:: 0,0,0  request:: '/hbase/root-region-server,T  response::
> until SASL authentication completes.
>
> 2012-10-08 15:28:03,334 (lifecycleSupervisor-1-0-SendThread(

Thanks & Regards,
Anil Gupta