hbase-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Adam Silberstein <silbe...@yahoo-inc.com>
Subject Re: Java client problem w/ zookeeper
Date Thu, 14 Jan 2010 06:48:54 GMT
OK, got the log4j stuff squared away.  I don't see any ZK errors after the
start, so perhaps that's not it.  Here's a sample of the Hbase Client
messages I'm seeing:

0/01/13 22:33:23 DEBUGipc.HbaseRPC: Call: getClosestRowBefore 11
10/01/13 22:33:23 DEBUGclient.HConnectionManager$TableServers: Cached
location address: 66.196.83.87:60020, regioninfo: REGION => {NAME =>
'usertable,user1029086433,1263433456604', STARTKEY => 'user1029086433',
ENDKEY => 'user1036327488', ENCODED => 266348591, TABLE => {{NAME =>
'usertable', FAMILIES => [{NAME => 'values', VERSIONS => '3', COMPRESSION =>
'NONE', TTL => '2147483647', BLOCKSIZE => '65536', IN_MEMORY => 'false',
BLOCKCACHE => 'true'}]}}
10/01/13 22:33:23 DEBUGipc.HBaseClient: IPC Client (47) connection to
/66.196.83.87:60020 from an unknown user sending #13
10/01/13 22:33:23 DEBUGipc.HBaseClient: IPC Client (47) connection to
/66.196.83.87:60020 from an unknown user got value #13
10/01/13 22:33:23 DEBUGipc.HbaseRPC: Call: put 9
10/01/13 22:33:23 DEBUGipc.HBaseClient: IPC Client (47) connection to
/66.196.83.85:60020 from an unknown user sending #14
10/01/13 22:33:23 DEBUGipc.HBaseClient: IPC Client (47) connection to
/66.196.83.85:60020 from an unknown user got value #14


And then, 5 seconds into it, I start seeing these:

10/01/13 22:33:27 DEBUGclient.HConnectionManager$TableServers: Reloading
region usertable,user263042644,1263431524192 location because regionserver
didn't accept updates; tries=0 of max=10, waiting=2000ms

But the region servers are all up, and none logged any messages during the
client run.  

Any thoughts?

Thanks,
Adam

On 1/13/10 9:40 PM, "stack" <stack@duboce.net> wrote:

> On Wed, Jan 13, 2010 at 7:40 PM, Adam Silberstein
> <silberst@yahoo-inc.com>wrote:
> 
>> Hi stack,
>> Having some trouble trying this.  I created a log4j.properties file and
>> tried different combinations of these, with the goal of seeing if I could
>> first adjust the log level at all from current INFO:
>> log4j.logger.org.apache.zookeeper=ERROR,stdout
>> zookeeper.root.logger=ERROR, stdout
>> log4j.rootLogger=ERROR, stdout
>> 
>> 
> Are you thinking that ERROR is finer-grained than DEBUG by chance?   If so,
> http://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/Level.html.
>  ERROR doesn't show DEBUG.
> 
> It looks like the shell is overriding the log4j setting if thats of any
> help.  If I disable that facility, it seems the shell does DEBUG level zk
> logging.
> 
> Index: bin/hirb.rb
> ===================================================================
> --- bin/hirb.rb (revision 899058)
> +++ bin/hirb.rb (working copy)
> @@ -36,7 +36,7 @@
>  format = 'console'
>  format_width = 110
>  script2run = nil
> -logLevel = org.apache.log4j.Level::ERROR
> +#logLevel = org.apache.log4j.Level::ERROR
>  for arg in ARGV
>    if arg =~ /^--format=(.+)/i
>      format = $1
> @@ -78,7 +78,7 @@
> 
>  # Set logging level to avoid verboseness
>  logger = org.apache.log4j.Logger.getLogger("org.apache.zookeeper")
> -logger.setLevel(logLevel);
> +#logger.setLevel(logLevel);
>  logger = org.apache.log4j.Logger.getLogger("org.apache.hadoop.hbase")
>  logger.setLevel(logLevel);
>  # Require HBase now after setting log levels
> 
> 
> 
>> But no effect.  Probably a dumb log4j error, but it's blocking me.
>> 
>> 
> If in log4j, I set zk to debug level:
> 
> pynchon:0.20 stack$ svn diff conf/
> Index: conf/log4j.properties
> ===================================================================
> --- conf/log4j.properties       (revision 898656)
> +++ conf/log4j.properties       (working copy)
> @@ -40,7 +40,7 @@
> 
>  # Custom Logging levels
> 
> -log4j.logger.org.apache.zookeeper=INFO
> +log4j.logger.org.apache.zookeeper=DEBUG
>  #log4j.logger.org.apache.hadoop.fs.FSNamesystem=DEBUG
>  log4j.logger.org.apache.hadoop.hbase=DEBUG
>  #log4j.logger.org.apache.hadoop.dfs=DEBUG
> 
> ... and run for example the PerformanceEvaluation client:
> 
> $ ./bin/hbase org.apache.hadoop.hbase.PerformanceEvaluation sequentialWrite
> 1
> 
> ... it seems to report zk at DEBUG level.
> 
> 
> 
>> Also, I moved to yet another Hbase deployment.  This time I was able to
>> insert about 20 million records from my client.  Then I encountered the
>> same
>> problem.  I can insert with the shell, but not from my client.
> 
> 
> For sure, your client is finding the same conf and the hbase shell?  I
> wonder why it was working, then stopped.  If you look in the zk  cluster
> member logs, anything happen at the 20M mark?
> 
> 
>> The only
>> Hbase-side thing I see are the NodeExistsException: KeeperErrorCode =
>> NodeExists in the zookeeper log, and there is one for each of my threads.
>> 
>> Also, I tried restarting Hbase/Hadoop, making sure the everything was idle
>> before I started again, but no luck.
>> 
>> And if you restart the zk cluster?
> 
> St.Ack
> 
> 
>> Thanks,
>> Adam
>> 
>> 
>> 
>> On 1/13/10 2:54 PM, "stack" <stack@duboce.net> wrote:
>> 
>>> I wonder what the 'node' is that its complaining about?  It doesn't say.
>>  I
>>> wonder if you did DEBUG for zk if you'd learn more?  Could enable it on
>> the
>>> problematic client only?
>>> 
>>> 
>>> St.Ack
>>> 
>>> On Wed, Jan 13, 2010 at 11:25 AM, Adam Silberstein
>>> <silberst@yahoo-inc.com>wrote:
>>> 
>>>> Hi,
>>>> I set up a new Hbase cluster and am seeing an error I haven't seen
>> before.
>>>> When I start up Hbase I have this NodeExists error in the zookeeper log:
>>>> 
>>>> org.apache.zookeeper.KeeperException$NodeExistsException:
>> KeeperErrorCode =
>>>> NodeExists
>>>>        at
>>>> 
>>>> 
>> org.apache.zookeeper.server.PrepRequestProcessor.pRequest(PrepRequestProcess
>>>> or.java:245)
>>>>        at
>>>> 
>>>> 
>> org.apache.zookeeper.server.PrepRequestProcessor.run(PrepRequestProcessor.ja
>>>> va:114)
>>>> 2010-01-13 11:10:47,503 WARN
>>>> org.apache.zookeeper.server.PrepRequestProcessor: Got exception when
>>>> processing sessionid:0x1262918396b0002 type:create cxid:0xc
>>>> zxid:0xfffffffffffffffe txntype:unknown n/a
>>>> org.apache.zookeeper.KeeperException$NodeExistsException:
>> KeeperErrorCode =
>>>> NodeExists
>>>>        at
>>>> 
>>>> 
>> org.apache.zookeeper.server.PrepRequestProcessor.pRequest(PrepRequestProcess
>>>> or.java:245)
>>>>        at
>>>> 
>>>> 
>> org.apache.zookeeper.server.PrepRequestProcessor.run(PrepRequestProcessor.ja
>>>> va:114)
>>>> 
>>>> I've read that may be harmless.  But then when I run the java client, it
>>>> cannot do any operations.  And I see a similar NodeExists error in the
>>>> zookeeper log.
>>>> 
>>>> 
>>>> 2010-01-13 11:11:24,661 INFO org.apache.zookeeper.server.NIOServerCnxn:
>>>> Connected to /203.104.21.210:36928 lastZxid 0
>>>> 2010-01-13 11:11:24,661 INFO org.apache.zookeeper.server.NIOServerCnxn:
>>>> Creating new session 0x1262918396b0004
>>>> 2010-01-13 11:11:24,664 INFO org.apache.zookeeper.server.NIOServerCnxn:
>>>> Finished init of 0x1262918396b0004 valid:true
>>>> 2010-01-13 11:11:24,973 WARN
>>>> org.apache.zookeeper.server.PrepRequestProcessor: Got exception when
>>>> processing sessionid:0x1262918396b0004 type:create cxid:0x2
>>>> zxid:0xfffffffffffffffe txntype:unknown n/a
>>>> org.apache.zookeeper.KeeperException$NodeExistsException:
>> KeeperErrorCode =
>>>> NodeExists
>>>>        at
>>>> 
>>>> 
>> org.apache.zookeeper.server.PrepRequestProcessor.pRequest(PrepRequestProcess
>>>> or.java:245)
>>>>        at
>>>> 
>>>> 
>> org.apache.zookeeper.server.PrepRequestProcessor.run(PrepRequestProcessor.ja
>>>> va:114)
>>>> 2010-01-13 11:11:33,088 WARN org.apache.zookeeper.server.NIOServerCnxn:
>>>> Exception causing close of session 0x1262918396b0004 due to
>>>> java.io.IOException: Read error
>>>> 2010-01-13 11:11:33,089 INFO org.apache.zookeeper.server.NIOServerCnxn:
>>>> closing session:0x1262918396b0004 NIOServerCnxn:
>>>> java.nio.channels.SocketChannel[connected local=/203.104.21.210:2181
>>>> remote=/203.104.21.210:36928]
>>>> 2010-01-13 11:11:42,709 INFO org.apache.zookeeper.server.NIOServerCnxn:
>>>> Connected to /203.104.21.212:54837 lastZxid 0
>>>> 2010-01-13 11:11:42,709 INFO org.apache.zookeeper.server.NIOServerCnxn:
>>>> Creating new session 0x1262918396b0005
>>>> 2010-01-13 11:11:42,711 INFO org.apache.zookeeper.server.NIOServerCnxn:
>>>> Finished init of 0x1262918396b0005 valid:true
>>>> 2010-01-13 11:11:42,711 WARN
>>>> org.apache.zookeeper.server.PrepRequestProcessor: Got exception when
>>>> processing sessionid:0x1262918396b0005 type:create cxid:0x1
>>>> zxid:0xfffffffffffffffe txntype:unknown n/a
>>>> org.apache.zookeeper.KeeperException$NodeExistsException:
>> KeeperErrorCode =
>>>> NodeExists
>>>>        at
>>>> 
>>>> 
>> org.apache.zookeeper.server.PrepRequestProcessor.pRequest(PrepRequestProcess
>>>> or.java:245)
>>>>        at
>>>> 
>>>> 
>> org.apache.zookeeper.server.PrepRequestProcessor.run(PrepRequestProcessor.ja
>>>> va:114)
>>>> 2010-01-13 11:12:06,002 INFO
>>>> org.apache.zookeeper.server.SessionTrackerImpl:
>>>> Expiring session 0x1262918396b0004
>>>> 2010-01-13 11:12:06,002 INFO
>> org.apache.zookeeper.server.ZooKeeperServer:
>>>> Expiring session 0x1262918396b0004
>>>> 2010-01-13 11:12:06,002 INFO
>>>> org.apache.zookeeper.server.PrepRequestProcessor: Processed session
>>>> termination request for id: 0x1262918396b0004
>>>> 
>>>> I've tried wiping the whole setup, including the zookeeper files that
>> Hbase
>>>> puts in /tmp and formatting HDFS.  But I get the same problem again.
>>  I'm
>>>> not seeing any exceptions on the client-side.
>>>> 
>>>> Thanks,
>>>> Adam
>>>> 
>>>> 
>> 
>> 


Mime
View raw message