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" <[email protected]> wrote:
> On Wed, Jan 13, 2010 at 7:40 PM, Adam Silberstein
> <[email protected]>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" <[email protected]> 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
>>> <[email protected]>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
>>>>
>>>>
>>
>>
