I probably wasn't clear on this in the previous message. There are NO
exceptions reported in the log file. It appears as though the master is
attempting to do the log splits (see below 21 of 36 at 2010-10-03
18:13:28,187), and then immediately transitions into the "Closed" messages,
again with NO exceptions being reported - it just stops doing the log
splitting. After the "Closed" messages start there are no further log
splitting messages in the log file. It just does a series of those, and then
moves on to reporting 0 region servers again. Again, NO other messages are
being sent to the log file.
-Matthew
On Oct 3, 2010, at 12:33 PM, Matthew LeMieux wrote:
> It think it is a bit more serious than that. Waiting doesn't appear to do
> much.
>
> After a series of log messages that appear to be doing the splitting, the
> "Closed", messages appear:
>
> 2010-10-03 18:13:26,664 INFO org.apache.hadoop.hbase.util.FSUtils: Recovering
> filehdfs://domU-12-31-39-03-44-F1.compute-1.internal:9000/hbase/.logs/domU-12-31-39-18-12-05.compute-1.internal,60020,1284222361677/10.104.37.247%3A60020.1284820404595
> 2010-10-03 18:13:26,701 INFO org.apache.hadoop.hbase.master.ServerManager: 0
> region servers, 0 dead, average load NaN
> 2010-10-03 18:13:26,872 INFO org.apache.hadoop.hbase.util.FSUtils: Finished
> lease recover attempt for
> hdfs://domU-12-31-39-03-44-F1.compute-1.internal:9000/hbase/.logs/domU-12-31-39-18-12-05.compute-1.internal,60020,1284222361677/10.104.37.247%3A60020.128482040459
> 5
> 2010-10-03 18:13:27,500 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLog:
> Pushed=5211 entries from
> hdfs://domU-12-31-39-03-44-F1.compute-1.internal:9000/hbase/.logs/domU-12-31-39-18-12-05.compute-1.internal,60020,1284222361677/10.104.37.247%3A60020.128482040459
> 5
> 2010-10-03 18:13:27,500 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLog:
> Splitting hlog 20 of 36:
> hdfs://domU-12-31-39-03-44-F1.compute-1.internal:9000/hbase/.logs/domU-12-31-39-18-12-05.compute-1.internal,60020,1284222361677/10.104.37.247%3A60020.128482041398
> 9, length=64550958
> 2010-10-03 18:13:27,500 INFO org.apache.hadoop.hbase.util.FSUtils: Recovering
> filehdfs://domU-12-31-39-03-44-F1.compute-1.internal:9000/hbase/.logs/domU-12-31-39-18-12-05.compute-1.internal,60020,1284222361677/10.104.37.247%3A60020.1284820413989
> 2010-10-03 18:13:27,721 INFO org.apache.hadoop.hbase.util.FSUtils: Finished
> lease recover attempt for
> hdfs://domU-12-31-39-03-44-F1.compute-1.internal:9000/hbase/.logs/domU-12-31-39-18-12-05.compute-1.internal,60020,1284222361677/10.104.37.247%3A60020.128482041398
> 9
> 2010-10-03 18:13:28,187 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLog:
> Pushed=4555 entries from
> hdfs://domU-12-31-39-03-44-F1.compute-1.internal:9000/hbase/.logs/domU-12-31-39-18-12-05.compute-1.internal,60020,1284222361677/10.104.37.247%3A60020.128482041398
> 9
> 2010-10-03 18:13:28,187 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLog:
> Splitting hlog 21 of 36:
> hdfs://domU-12-31-39-03-44-F1.compute-1.internal:9000/hbase/.logs/domU-12-31-39-18-12-05.compute-1.internal,60020,1284222361677/10.104.37.247%3A60020.1284820433464,
> length=2373620705
> 2010-10-03 18:13:28,187 INFO org.apache.hadoop.hbase.util.FSUtils: Recovering
> filehdfs://domU-12-31-39-03-44-F1.compute-1.internal:9000/hbase/.logs/domU-12-31-39-18-12-05.compute-1.internal,60020,1284222361677/10.104.37.247%3A60020.1284820433464
> 2010-10-03 18:13:28,391 INFO org.apache.hadoop.hbase.util.FSUtils: Finished
> lease recover attempt for
> hdfs://domU-12-31-39-03-44-F1.compute-1.internal:9000/hbase/.logs/domU-12-31-39-18-12-05.compute-1.internal,60020,1284222361677/10.104.37.247%3A60020.1284820433464
> 2010-10-03 18:13:42,141 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLog:
> Pushed=65522 entries from
> hdfs://domU-12-31-39-03-44-F1.compute-1.internal:9000/hbase/.logs/domU-12-31-39-18-12-05.compute-1.internal,60020,1284222361677/10.104.37.247%3A60020.1284820433464
> 2010-10-03 18:13:42,533 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLog:
> Closed
> hdfs://domU-12-31-39-03-44-F1.compute-1.internal:9000/hbase/dirgraph/e2a8b3352d84523be7f43f966bde6ef1/recovered.edits/0000000000075378488
> 2010-10-03 18:13:42,539 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLog:
> Closed
> hdfs://domU-12-31-39-03-44-F1.compute-1.internal:9000/hbase/dirgraph/e3a7a269aa9f1b32de6b3add53cc5a30/recovered.edits/0000000000075400136
> 2010-10-03 18:13:42,546 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLog:
> Closed
> hdfs://domU-12-31-39-03-44-F1.compute-1.internal:9000/hbase/dirgraph/32d50d0d37a5ed3f89f17772678c4c20/recovered.edits/0000000000075400152
> 2010-10-03 18:13:42,550 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLog:
> Closed
> hdfs://domU-12-31-39-03-44-F1.compute-1.internal:9000/hbase/dirgraph/182719f8ad5c2c7da56bdd3987a4559c/recovered.edits/0000000000075471128
> 2010-10-03 18:13:42,555 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLog:
> Closed
> hdfs://domU-12-31-39-03-44-F1.compute-1.internal:9000/hbase/dirgraph/4148aa42cf9ac956c0e048b83ca6f186/recovered.edits/0000000000075463238
> 2010-10-03 18:13:42,560 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLog:
> Closed
> hdfs://domU-12-31-39-03-44-F1.compute-1.internal:9000/hbase/dirgraph/9d4edffd841fb66c37ab5944f12ef911/recovered.edits/0000000000075393635
> 2
>
> Then the ONLY messages that are appear in the master's log file are these:
>
> 2010-10-03 18:55:27,130 INFO org.apache.hadoop.hbase.master.ServerManager: 0
> region servers, 0 dead, average load NaN
> 2010-10-03 18:56:27,140 INFO org.apache.hadoop.hbase.master.ServerManager: 0
> region servers, 0 dead, average load NaN
> 2010-10-03 18:57:27,150 INFO org.apache.hadoop.hbase.master.ServerManager: 0
> region servers, 0 dead, average load NaN
> 2010-10-03 18:58:27,160 INFO org.apache.hadoop.hbase.master.ServerManager: 0
> region servers, 0 dead, average load NaN
> 2010-10-03 18:59:27,170 INFO org.apache.hadoop.hbase.master.ServerManager: 0
> region servers, 0 dead, average load NaN
> 2010-10-03 19:00:27,180 INFO org.apache.hadoop.hbase.master.ServerManager: 0
> region servers, 0 dead, average load NaN
> 2010-10-03 19:01:27,190 INFO org.apache.hadoop.hbase.master.ServerManager: 0
> region servers, 0 dead, average load NaN
> 2010-10-03 19:02:27,200 INFO org.apache.hadoop.hbase.master.ServerManager: 0
> region servers, 0 dead, average load NaN
> 2010-10-03 19:03:27,215 INFO org.apache.hadoop.hbase.master.ServerManager: 0
> region servers, 0 dead, average load NaN
> 2010-10-03 19:04:27,225 INFO org.apache.hadoop.hbase.master.ServerManager: 0
> region servers, 0 dead, average load NaN
> 2010-10-03 19:05:27,235 INFO org.apache.hadoop.hbase.master.ServerManager: 0
> region servers, 0 dead, average load NaN
> 2010-10-03 19:06:27,245 INFO org.apache.hadoop.hbase.master.ServerManager: 0
> region servers, 0 dead, average load NaN
> 2010-10-03 19:07:27,255 INFO org.apache.hadoop.hbase.master.ServerManager: 0
> region servers, 0 dead, average load NaN
> 2010-10-03 19:08:27,265 INFO org.apache.hadoop.hbase.master.ServerManager: 0
> region servers, 0 dead, average load NaN
> 2010-10-03 19:09:27,275 INFO org.apache.hadoop.hbase.master.ServerManager: 0
> region servers, 0 dead, average load NaN
> 2010-10-03 19:10:27,285 INFO org.apache.hadoop.hbase.master.ServerManager: 0
> region servers, 0 dead, average load NaN
> 2010-10-03 19:11:27,295 INFO org.apache.hadoop.hbase.master.ServerManager: 0
> region servers, 0 dead, average load NaN
> 2010-10-03 19:12:27,305 INFO org.apache.hadoop.hbase.master.ServerManager: 0
> region servers, 0 dead, average load NaN
> 2010-10-03 19:13:27,315 INFO org.apache.hadoop.hbase.master.ServerManager: 0
> region servers, 0 dead, average load NaN
> 2010-10-03 19:14:27,325 INFO org.apache.hadoop.hbase.master.ServerManager: 0
> region servers, 0 dead, average load NaN
> 2010-10-03 19:15:27,335 INFO org.apache.hadoop.hbase.master.ServerManager: 0
> region servers, 0 dead, average load NaN
> 2010-10-03 19:16:27,348 INFO org.apache.hadoop.hbase.master.ServerManager: 0
> region servers, 0 dead, average load NaN
> 2010-10-03 19:17:27,358 INFO org.apache.hadoop.hbase.master.ServerManager: 0
> region servers, 0 dead, average load NaN
> 2010-10-03 19:18:27,368 INFO org.apache.hadoop.hbase.master.ServerManager: 0
> region servers, 0 dead, average load NaN
> 2010-10-03 19:19:27,378 INFO org.apache.hadoop.hbase.master.ServerManager: 0
> region servers, 0 dead, average load NaN
> 2010-10-03 19:20:27,388 INFO org.apache.hadoop.hbase.master.ServerManager: 0
> region servers, 0 dead, average load NaN
> 2010-10-03 19:21:27,388 INFO org.apache.hadoop.hbase.master.ServerManager: 0
> region servers, 0 dead, average load NaN
> 2010-10-03 19:22:27,388 INFO org.apache.hadoop.hbase.master.ServerManager: 0
> region servers, 0 dead, average load NaN
> 2010-10-03 19:23:27,388 INFO org.apache.hadoop.hbase.master.ServerManager: 0
> region servers, 0 dead, average load NaN
> 2010-10-03 19:24:27,388 INFO org.apache.hadoop.hbase.master.ServerManager: 0
> region servers, 0 dead, average load NaN
> 2010-10-03 19:25:27,388 INFO org.apache.hadoop.hbase.master.ServerManager: 0
> region servers, 0 dead, average load NaN
> 2010-10-03 19:26:27,388 INFO org.apache.hadoop.hbase.master.ServerManager: 0
> region servers, 0 dead, average load NaN
>
> I'm not pulling any lines out, ALL regions servers are just waiting for the
> master, with NO lines being written to the log file. I tried killing the
> master, and restarting, clearly the region servers are aware of the master,
> but the master persists in not recognizing them:
>
> 2010-10-03 18:11:35,888 INFO
> org.apache.hadoop.hbase.regionserver.HRegionServer: Got ZooKeeper event,
> state: SyncConnected, type: NodeDeleted, path: /hbase/master
> 2010-10-03 18:11:35,891 DEBUG
> org.apache.hadoop.hbase.zookeeper.ZooKeeperWrapper:
> <10.249.70.255:/hbase,domU-12-31-39-18-1B-05.compute-1.internal,60020,1286127632413>Set
> watcher on master address ZNode /hbase/master
> 2010-10-03 18:12:26,697 INFO
> org.apache.hadoop.hbase.regionserver.HRegionServer: Got ZooKeeper event,
> state: SyncConnected, type: NodeCreated, path: /hbase/master
> 2010-10-03 18:12:26,698 DEBUG
> org.apache.hadoop.hbase.zookeeper.ZooKeeperWrapper:
> <10.249.70.255:/hbase,domU-12-31-39-18-1B-05.compute-1.internal,60020,1286127632413>Read
> ZNode /hbase/master got 10.104.37.247:60000
> 2010-10-03 18:12:26,698 INFO
> org.apache.hadoop.hbase.regionserver.HRegionServer: Telling master at
> 10.104.37.247:60000 that we are up
>
> This is clearly a not a situation of just waiting it out. A region server
> killed itself, restarting the region server didn't get the cluster back up
> and running. I restarted everything from scratch, and that brings us to the
> current state. The machines are not doing anything, they have a load average
> of 0.00 and cpu idle of more than 99%.
>
> What would cause the cluster to completely lock up and refuse to do anything?
>
> Thank you for your help,
>
> Matthew
>
> On Oct 3, 2010, at 12:02 PM, Jean-Daniel Cryans wrote:
>
>> From the brief looks of it, it seems that the master is splitting the
>> log files from the dead region server. It will do that while the
>> cluster is running and will keep answering the other region servers,
>> but if you restart HBase then when the master starts it will split
>> everything before starting to take region server checkins. Just let
>> the master finish it's job. Look for this message that tells you which
>> region server's hlogs are being split:
>>
>> LOG.info("Splitting " + logfiles.length + " hlog(s) in " +
>> srcDir.toString());
>>
>> Then this message will show when it's done:
>>
>> LOG.info("hlog file splitting completed in " + (endMillis - millis) +
>> " millis for " + srcDir.toString());
>>
>> J-D
>>
>> On Sun, Oct 3, 2010 at 10:56 AM, Matthew LeMieux <[email protected]> wrote:
>>> I've recently had a region server suicide, and am not able to recover from
>>> it. I've tried completely stopping the entire cluster and restarting it
>>> (including dfs and zk), but the master refuses to recognize the
>>> regionservers.
>>>
>>> The region servers appear to just be waiting for the master with this in
>>> their log file:
>>>
>>> 2010-10-03 17:40:32,748 DEBUG
>>> org.apache.hadoop.hbase.zookeeper.ZooKeeperWrapper:
>>> <10.249.70.255:/hbase,domU-12-31-39-18-1B-05.compute-1.internal,60020,1286127632413>Read
>>> ZNode /hbase/master got 10.104.37.247:60000
>>> 2010-10-03 17:40:32,749 INFO
>>> org.apache.hadoop.hbase.regionserver.HRegionServer: Telling master at
>>> 10.104.37.247:60000 that we are up
>>> 2010-10-03 17:40:32,862 INFO
>>> org.apache.hadoop.hbase.regionserver.ShutdownHook: Installed shutdown hook
>>> thread: Shutdownhook:regionserver60020
>>>
>>> ... and the the master log file just keeps repeating this:
>>>
>>> 2010-10-03 17:42:15,531 INFO org.apache.hadoop.hbase.master.ServerManager:
>>> 0 region servers, 0 dead, average load NaN
>>> 2010-10-03 17:43:15,541 INFO org.apache.hadoop.hbase.master.ServerManager:
>>> 0 region servers, 0 dead, average load NaN
>>>
>>> After many lines of this sort of thing:
>>>
>>> 2010-10-03 17:41:05,179 DEBUG
>>> org.apache.hadoop.hbase.regionserver.wal.HLog: Split writer thread for
>>> region
>>> user,\x01\x88\xFB\xCA,1281914437530.3901f9eb92c049a295aeec3a7e739fe2. got
>>> 11 to process
>>> 2010-10-03 17:41:05,180 DEBUG
>>> org.apache.hadoop.hbase.regionserver.wal.HLog: Split writer thread for
>>> region
>>> user,\x01\x88\xFB\xCA,1281914437530.3901f9eb92c049a295aeec3a7e739fe2.
>>> Applied 11 total edits to
>>> user,\x01\x88\xFB\xCA,1281914437530.3901f9eb92c049a295ae
>>>
>>> Followed by many lines of this:
>>>
>>> 2010-10-03 17:41:24,719 DEBUG
>>> org.apache.hadoop.hbase.regionserver.wal.HLog: Closed
>>> hdfs://domU-12-31-39-03-44-F1.compute-1.internal:9000/hbase/user/7b49d357be708d07e6f01843a35286a7/recovered.edits/0000000000075377494
>>> 2010-10-03 17:41:24,724 DEBUG
>>> org.apache.hadoop.hbase.regionserver.wal.HLog: Closed
>>> hdfs://domU-12-31-39-03-44-F1.compute-1.internal:9000/hbase/user/3a58b7adcf049800be83425e75288eeb/recovered.edits/0000000000075377495
>>>
>>> As one might expect, attempts to achbase hang, for example:
>>>
>>> HBase Shell; enter 'help<RETURN>' for list of supported commands.
>>> Type "exit<RETURN>" to leave the HBase Shell
>>> Version: 0.89.20100924, r1001068, Fri Sep 24 13:55:42 PDT 2010
>>>
>>> hbase(main):001:0> list
>>> TABLE
>>>
>>>
>>> I'm using CDH3b2 for hdfs and the version of hbase from here:
>>> http://people.apache.org/~jdcryans/hbase-0.89.20100924-candidate-1
>>>
>>> Any ideas on how I can get the master to recognize the region servers? I'm
>>> really just concerned with how to get back up and running.
>>>
>>> Thank you
>>>
>>> Matthew
>>>
>>>
>
