Eran: You didn't run hbck during the enabling of gs_raw_events table, right ?
I saw: 2011-06-29 16:43:50,395 DEBUG org.apache.hadoop.hbase.regionserver.CompactSplitThread: Compaction (major) requested for gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309. because User-triggered major compaction; priority=1, compaction queue size=1248 The above might be related to: >> 2011-06-29 16:43:57,880 INFO org.apache.hadoop.hbase. master.AssignmentManager: Region has been PENDING_OPEN for too long, reassigning region=gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309. Thanks On Tue, Jul 5, 2011 at 7:19 AM, Ted Yu <yuzhih...@gmail.com> wrote: > Eran: > I logged https://issues.apache.org/jira/browse/HBASE-4060 for you. > > > On Mon, Jul 4, 2011 at 2:30 AM, Ted Yu <yuzhih...@gmail.com> wrote: > >> Thanks for the understanding. >> >> Can you log a JIRA and put your ideas below in it ? >> >> >> >> On Jul 4, 2011, at 12:42 AM, Eran Kutner <e...@gigya.com> wrote: >> >> > Thanks for the explanation Ted, >> > >> > I will try to apply HBASE-3789 and hope for the best but my >> understanding is >> > that it doesn't really solve the problem, it only reduces the >> probability of >> > it happening, at least in one particular scenario. I would hope for a >> more >> > robust solution. >> > My concern is that the region allocation process seems to rely too much >> on >> > timing considerations and doesn't seem to take enough measures to >> guarantee >> > conflicts do not occur. I understand that in a distributed environment, >> when >> > you don't get a timely response from a remote machine you can't know for >> > sure if it did or did not receive the request, however there are things >> that >> > can be done to mitigate this and reduce the conflict time significantly. >> For >> > example, when I run dbck it knows that some regions are multiply >> assigned, >> > the master could do the same and try to resolve the conflict. Another >> > approach would be to handle late responses, even if the response from >> the >> > remote machine arrives after it was assumed to be dead the master should >> > have enough information to know it had created a conflict by assigning >> the >> > region to another server. An even better solution, I think, is for the >> RS to >> > periodically test that it is indeed the rightful owner of every region >> it >> > holds and relinquish control over the region if it's not. >> > Obviously a state where two RSs hold the same region is pathological and >> can >> > lead to data loss, as demonstrated in my case. The system should be able >> to >> > actively protect itself against such a scenario. It probably doesn't >> need >> > saying but there is really nothing worse for a data storage system than >> data >> > loss. >> > >> > In my case the problem didn't happen in the initial phase but after >> > disabling and enabling a table with about 12K regions. >> > >> > -eran >> > >> > >> > >> > On Sun, Jul 3, 2011 at 23:49, Ted Yu <yuzhih...@gmail.com> wrote: >> > >> >> Let me try to answer some of your questions. >> >> The two paragraphs below were written along my reasoning which is in >> >> reverse >> >> order of the actual call sequence. >> >> >> >> For #4 below, the log indicates that the following was executed: >> >> private void assign(final RegionState state, final boolean >> setOfflineInZK, >> >> final boolean forceNewPlan) { >> >> for (int i = 0; i < this.maximumAssignmentAttempts; i++) { >> >> if (setOfflineInZK && !*setOfflineInZooKeeper*(state)) return; >> >> >> >> The above was due to the timeout which you noted in #2 which would have >> >> caused >> >> TimeoutMonitor.chore() to run this code (line 1787) >> >> >> >> for (Map.Entry<HRegionInfo, Boolean> e: assigns.entrySet()){ >> >> assign(e.getKey(), false, e.getValue()); >> >> } >> >> >> >> This means there is lack of coordination between >> >> assignmentManager.TimeoutMonitor and OpenedRegionHandler >> >> >> >> The reason I mention HBASE-3789 is that it is marked as Incompatible >> change >> >> and is in TRUNK already. >> >> The application of HBASE-3789 to 0.90 branch would change the behavior >> >> (timing) of region assignment. >> >> >> >> I think it makes sense to evaluate the effect of HBASE-3789 in 0.90.4 >> >> >> >> BTW were the incorrect region assignments observed for a table with >> >> multiple >> >> initial regions ? >> >> If so, I have HBASE-4010 in TRUNK which speeds up initial region >> assignment >> >> by about 50%. >> >> >> >> Cheers >> >> >> >> On Sun, Jul 3, 2011 at 12:02 PM, Eran Kutner <e...@gigya.com> wrote: >> >> >> >>> Ted, >> >>> So if I understand correctly the the theory is that because of the >> issue >> >>> fixed in HBASE-3789 the master took too long to detect that the region >> >> was >> >>> successfully opened by the first server so it forced closed it and >> >>> transitioned to a second server, but there are a few things about this >> >>> scenario I don't understand, probably because I don't know enough >> about >> >> the >> >>> inner workings of the region transition process and would appreciate >> it >> >> if >> >>> you can help me understand: >> >>> 1. The RS opened the region at 16:37:49. >> >>> 2. The master started handling the opened event at 16:39:54 - this >> delay >> >>> can >> >>> probably be explained by HBASE-3789 >> >>> 3. At 16:39:54 the master log says: Opened region gs_raw_events,..... >> on >> >>> hadoop1-s05.farm-ny.gigya.com >> >>> 4. Then at 16:40:00 the master log says: >> master:60000-0x13004a31d7804c4 >> >>> Creating (or updating) unassigned node for >> 584dac5cc70d8682f71c4675a843c3 >> >>> 09 with OFFLINE state - why did it decide to take the region offline >> >> after >> >>> learning it was successfully opened? >> >>> 5. Then it tries to reopen the region on hadoop1-s05, which indicates >> in >> >>> its >> >>> log that the open request failed because the region was already open - >> >> why >> >>> didn't the master use that information to learn that the region was >> >> already >> >>> open? >> >>> 6. At 16:43:57 the master decides the region transition timed out and >> >>> starts >> >>> forcing the transition - HBASE-3789 again? >> >>> 7. Now the master forces the transition of the region to hadoop1-s02 >> but >> >>> there is no sign of that on hadoop1-s05 - why doesn't the old RS >> >>> (hadoop1-s05) detect that it is no longer the master and relinquishes >> >>> control of the region? >> >>> >> >>> Thanks. >> >>> >> >>> -eran >> >>> >> >>> >> >>> >> >>> On Sun, Jul 3, 2011 at 20:09, Ted Yu <yuzhih...@gmail.com> wrote: >> >>> >> >>>> HBASE-3789 should have sped up region assignment. >> >>>> The patch for 0.90 is attached to that JIRA. >> >>>> >> >>>> You may prudently apply that patch. >> >>>> >> >>>> Regards >> >>>> >> >>>> On Sun, Jul 3, 2011 at 10:01 AM, Eran Kutner <e...@gigya.com> wrote: >> >>>> >> >>>>> Thanks Ted, but, as stated before, I'm already using 0.90.3, so >> >> either >> >>>> it's >> >>>>> not fixed or it's not the same thing. >> >>>>> >> >>>>> -eran >> >>>>> >> >>>>> >> >>>>> >> >>>>> On Sun, Jul 3, 2011 at 17:27, Ted Yu <yuzhih...@gmail.com> wrote: >> >>>>> >> >>>>>> Eran: >> >>>>>> I was thinking of this: >> >>>>>> HBASE-3789 Cleanup the locking contention in the master >> >>>>>> >> >>>>>> though it doesn't directly handle 'PENDING_OPEN for too long' case. >> >>>>>> >> >>>>>> https://issues.apache.org/jira/browse/HBASE-3741 is in 0.90.3 and >> >>>>> actually >> >>>>>> close to the symptom you described. >> >>>>>> >> >>>>>> On Sun, Jul 3, 2011 at 12:00 AM, Eran Kutner <e...@gigya.com> >> >> wrote: >> >>>>>> >> >>>>>>> It does seem that both servers opened the same region around the >> >>> same >> >>>>>> time. >> >>>>>>> The region was offline because I disabled the table so I can >> >> change >> >>>> its >> >>>>>>> TTL. >> >>>>>>> >> >>>>>>> Here is the log from haddop1-s05 : >> >>>>>>> 2011-06-29 16:37:12,576 INFO >> >>>>>>> org.apache.hadoop.hbase.regionserver.HRegionServer: Received >> >>> request >> >>>> to >> >>>>>>> open >> >>>>>>> region: >> >>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309. >> >>>>>>> 2011-06-29 16:37:12,680 DEBUG >> >>>>>>> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: >> >>>>>> Processing >> >>>>>>> open of >> >>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309. >> >>>>>>> 2011-06-29 16:37:12,680 DEBUG >> >>>>> org.apache.hadoop.hbase.zookeeper.ZKAssign: >> >>>>>>> regionserver:60020-0x33004a38816050b Attempting to transition >> >> node >> >>>>>>> 584dac5cc70d8682f71c4675a843c309 from M_ZK_REGION_OFFLINE to >> >>>>>>> RS_ZK_REGION_OPENING >> >>>>>>> 2011-06-29 16:37:12,711 DEBUG >> >>>>> org.apache.hadoop.hbase.zookeeper.ZKAssign: >> >>>>>>> regionserver:60020-0x33004a38816050b Successfully transitioned >> >> node >> >>>>>>> 584dac5cc70d8682f71c4675a843c309 from M_ZK_REGION_OFFLINE to >> >>>>>>> RS_ZK_REGION_OPENING >> >>>>>>> 2011-06-29 16:37:12,711 DEBUG >> >>>>>> org.apache.hadoop.hbase.regionserver.HRegion: >> >>>>>>> Opening region: REGION => {NAME => >> >>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> 'gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309.', >> >>>>>>> STARTKEY => 'GSLoad_1308518553_168_WEB204', ENDKEY => >> >>>>>>> 'GSLoad_1308518810_1249_WEB204', ENCODED => >> >>>>>>> 584dac5cc70d8682f71c4675a843c309, TABLE => {{NAME => >> >>> 'gs_raw_events', >> >>>>>>> FAMILIES => [{NAME => 'events', BLOOMFILTER => 'NONE', >> >>>>> REPLICATION_SCOPE >> >>>>>> => >> >>>>>>> '1', VERSIONS => '3', COMPRESSION => 'LZO', TTL => '604800', >> >>>> BLOCKSIZE >> >>>>> => >> >>>>>>> '65536', IN_MEMORY => 'false', BLOCKCACHE => 'true'}]}} >> >>>>>>> 2011-06-29 16:37:12,711 DEBUG >> >>>>>> org.apache.hadoop.hbase.regionserver.HRegion: >> >>>>>>> Instantiated >> >>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309. >> >>>>>>> 2011-06-29 16:37:12,847 DEBUG >> >>>>> org.apache.hadoop.hbase.regionserver.Store: >> >>>>>>> loaded >> >>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> hdfs://hadoop1-m1:8020/hbase/gs_raw_events/584dac5cc70d8682f71c4675a843c309/events/1971818821800304360, >> >>>>>>> isReference=false, isBulkLoadResult=false, seqid=1162228062, >> >>>>>>> majorCompaction=false >> >>>>>>> 2011-06-29 16:37:12,848 INFO >> >>>>>> org.apache.hadoop.hbase.regionserver.HRegion: >> >>>>>>> Onlined >> >>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309.; >> >>>>>>> next sequenceid=1162228063 >> >>>>>>> 2011-06-29 16:37:12,849 DEBUG >> >>>>> org.apache.hadoop.hbase.zookeeper.ZKAssign: >> >>>>>>> regionserver:60020-0x33004a38816050b Attempting to transition >> >> node >> >>>>>>> 584dac5cc70d8682f71c4675a843c309 from RS_ZK_REGION_OPENING to >> >>>>>>> RS_ZK_REGION_OPENING >> >>>>>>> 2011-06-29 16:37:12,875 DEBUG >> >>>>> org.apache.hadoop.hbase.zookeeper.ZKAssign: >> >>>>>>> regionserver:60020-0x33004a38816050b Successfully transitioned >> >> node >> >>>>>>> 584dac5cc70d8682f71c4675a843c309 from RS_ZK_REGION_OPENING to >> >>>>>>> RS_ZK_REGION_OPENING >> >>>>>>> 2011-06-29 16:37:12,951 INFO >> >>>>> org.apache.hadoop.hbase.catalog.MetaEditor: >> >>>>>>> Updated row >> >>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309. >> >>>>>>> in region .META.,,1 with server= >> >>> hadoop1-s05.farm-ny.gigya.com:60020, >> >>>>>>> startcode=1307349217076 >> >>>>>>> 2011-06-29 16:37:12,951 DEBUG >> >>>>> org.apache.hadoop.hbase.zookeeper.ZKAssign: >> >>>>>>> regionserver:60020-0x33004a38816050b Attempting to transition >> >> node >> >>>>>>> 584dac5cc70d8682f71c4675a843c309 from RS_ZK_REGION_OPENING to >> >>>>>>> RS_ZK_REGION_OPENED >> >>>>>>> 2011-06-29 16:37:12,964 DEBUG >> >>>>> org.apache.hadoop.hbase.zookeeper.ZKAssign: >> >>>>>>> regionserver:60020-0x33004a38816050b Successfully transitioned >> >> node >> >>>>>>> 584dac5cc70d8682f71c4675a843c309 from RS_ZK_REGION_OPENING to >> >>>>>>> RS_ZK_REGION_OPENED >> >>>>>>> 2011-06-29 16:37:12,964 DEBUG >> >>>>>>> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: >> >>>> Opened >> >>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309. >> >>>>>>> 2011-06-29 16:40:00,878 INFO >> >>>>>>> org.apache.hadoop.hbase.regionserver.HRegionServer: Received >> >>> request >> >>>> to >> >>>>>>> open >> >>>>>>> region: >> >>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309. >> >>>>>>> 2011-06-29 16:40:00,878 DEBUG >> >>>>>>> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: >> >>>>>> Processing >> >>>>>>> open of >> >>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309. >> >>>>>>> 2011-06-29 16:40:01,079 WARN >> >>>>>>> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: >> >>>>> Attempted >> >>>>>>> open of >> >>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309. >> >>>>>>> but already online on this server >> >>>>>>> 2011-06-29 16:43:50,395 DEBUG >> >>>>>>> org.apache.hadoop.hbase.regionserver.CompactSplitThread: >> >> Compaction >> >>>>>> (major) >> >>>>>>> requested for >> >>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309. >> >>>>>>> because User-triggered major compaction; priority=1, compaction >> >>> queue >> >>>>>>> size=1248 >> >>>>>>> 2011-06-29 20:19:49,906 INFO >> >>>>>> org.apache.hadoop.hbase.regionserver.HRegion: >> >>>>>>> Starting major compaction on region >> >>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309. >> >>>>>>> 2011-06-29 20:19:49,906 INFO >> >>>>> org.apache.hadoop.hbase.regionserver.Store: >> >>>>>>> Started compaction of 1 file(s) in cf=events into >> >>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> hdfs://hadoop1-m1:8020/hbase/gs_raw_events/584dac5cc70d8682f71c4675a843c309/.tmp, >> >>>>>>> seqid=1162228062, totalSize=98.3m >> >>>>>>> 2011-06-29 20:19:49,906 DEBUG >> >>>>> org.apache.hadoop.hbase.regionserver.Store: >> >>>>>>> Compacting >> >>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> hdfs://hadoop1-m1:8020/hbase/gs_raw_events/584dac5cc70d8682f71c4675a843c309/events/1971818821800304360, >> >>>>>>> keycount=6882816, bloomtype=NONE, size=98.3m >> >>>>>>> 2011-06-29 20:19:59,920 INFO >> >>>>>> org.apache.hadoop.hbase.regionserver.HRegion: >> >>>>>>> completed compaction on region >> >>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309. >> >>>>>>> after 10sec >> >>>>>>> >> >>>>>>> And here is the one from hadoop1-s02: >> >>>>>>> 2011-06-29 16:43:57,935 INFO >> >>>>>>> org.apache.hadoop.hbase.regionserver.HRegionServer: Received >> >>> request >> >>>> to >> >>>>>>> open >> >>>>>>> region: >> >>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309. >> >>>>>>> 2011-06-29 16:43:58,990 DEBUG >> >>>>>>> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: >> >>>>>> Processing >> >>>>>>> open of >> >>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309. >> >>>>>>> 2011-06-29 16:43:58,990 DEBUG >> >>>>> org.apache.hadoop.hbase.zookeeper.ZKAssign: >> >>>>>>> regionserver:60020-0x23004a31d8904de Attempting to transition >> >> node >> >>>>>>> 584dac5cc70d8682f71c4675a843c309 from M_ZK_REGION_OFFLINE to >> >>>>>>> RS_ZK_REGION_OPENING >> >>>>>>> 2011-06-29 16:43:59,002 DEBUG >> >>>>> org.apache.hadoop.hbase.zookeeper.ZKAssign: >> >>>>>>> regionserver:60020-0x23004a31d8904de Successfully transitioned >> >> node >> >>>>>>> 584dac5cc70d8682f71c4675a843c309 from M_ZK_REGION_OFFLINE to >> >>>>>>> RS_ZK_REGION_OPENING >> >>>>>>> 2011-06-29 16:43:59,002 DEBUG >> >>>>>> org.apache.hadoop.hbase.regionserver.HRegion: >> >>>>>>> Opening region: REGION => {NAME => >> >>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> 'gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309.', >> >>>>>>> STARTKEY => 'GSLoad_1308518553_168_WEB204', ENDKEY => >> >>>>>>> 'GSLoad_1308518810_1249_WEB204', ENCODED => >> >>>>>>> 584dac5cc70d8682f71c4675a843c309, TABLE => {{NAME => >> >>> 'gs_raw_events', >> >>>>>>> FAMILIES => [{NAME => 'events', BLOOMFILTER => 'NONE', >> >>>>> REPLICATION_SCOPE >> >>>>>> => >> >>>>>>> '1', VERSIONS => '3', COMPRESSION => 'LZO', TTL => '604800', >> >>>> BLOCKSIZE >> >>>>> => >> >>>>>>> '65536', IN_MEMORY => 'false', BLOCKCACHE => 'true'}]}} >> >>>>>>> 2011-06-29 16:43:59,003 DEBUG >> >>>>>> org.apache.hadoop.hbase.regionserver.HRegion: >> >>>>>>> Instantiated >> >>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309. >> >>>>>>> 2011-06-29 16:43:59,204 DEBUG >> >>>>> org.apache.hadoop.hbase.regionserver.Store: >> >>>>>>> loaded >> >>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> hdfs://hadoop1-m1:8020/hbase/gs_raw_events/584dac5cc70d8682f71c4675a843c309/events/1971818821800304360, >> >>>>>>> isReference=false, isBulkLoadResult=false, seqid=1162228062, >> >>>>>>> majorCompaction=false >> >>>>>>> 2011-06-29 16:43:59,205 INFO >> >>>>>> org.apache.hadoop.hbase.regionserver.HRegion: >> >>>>>>> Onlined >> >>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309.; >> >>>>>>> next sequenceid=1162228063 >> >>>>>>> 2011-06-29 16:43:59,205 DEBUG >> >>>>> org.apache.hadoop.hbase.zookeeper.ZKAssign: >> >>>>>>> regionserver:60020-0x23004a31d8904de Attempting to transition >> >> node >> >>>>>>> 584dac5cc70d8682f71c4675a843c309 from RS_ZK_REGION_OPENING to >> >>>>>>> RS_ZK_REGION_OPENING >> >>>>>>> 2011-06-29 16:43:59,212 DEBUG >> >>>>> org.apache.hadoop.hbase.zookeeper.ZKAssign: >> >>>>>>> regionserver:60020-0x23004a31d8904de Successfully transitioned >> >> node >> >>>>>>> 584dac5cc70d8682f71c4675a843c309 from RS_ZK_REGION_OPENING to >> >>>>>>> RS_ZK_REGION_OPENING >> >>>>>>> 2011-06-29 16:43:59,214 INFO >> >>>>> org.apache.hadoop.hbase.catalog.MetaEditor: >> >>>>>>> Updated row >> >>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309. >> >>>>>>> in region .META.,,1 with server= >> >>> hadoop1-s02.farm-ny.gigya.com:60020, >> >>>>>>> startcode=1306919627544 >> >>>>>>> 2011-06-29 16:43:59,214 DEBUG >> >>>>> org.apache.hadoop.hbase.zookeeper.ZKAssign: >> >>>>>>> regionserver:60020-0x23004a31d8904de Attempting to transition >> >> node >> >>>>>>> 584dac5cc70d8682f71c4675a843c309 from RS_ZK_REGION_OPENING to >> >>>>>>> RS_ZK_REGION_OPENED >> >>>>>>> 2011-06-29 16:43:59,224 DEBUG >> >>>>> org.apache.hadoop.hbase.zookeeper.ZKAssign: >> >>>>>>> regionserver:60020-0x23004a31d8904de Successfully transitioned >> >> node >> >>>>>>> 584dac5cc70d8682f71c4675a843c309 from RS_ZK_REGION_OPENING to >> >>>>>>> RS_ZK_REGION_OPENED >> >>>>>>> 2011-06-29 16:43:59,224 DEBUG >> >>>>>>> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: >> >>>> Opened >> >>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309. >> >>>>>>> java.io.IOException: Got error in response to OP_READ_BLOCK >> >> self=/ >> >>>>>>> 10.1.104.2:33356, remote=/10.1.104.2:50010 for file >> >>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> /hbase/gs_raw_events/584dac5cc70d8682f71c4675a843c309/events/1971818821800304360 >> >>>>>>> for block 3674866614142268536_674205 >> >>>>>>> >> >>>>>>> >> >>>>>>> Ted, can you please point me to J-D's bug fix you mentioned? Are >> >>> you >> >>>>>>> positive it's the same scenario - data loss is a very serious >> >>> problem >> >>>>> for >> >>>>>> a >> >>>>>>> DB. >> >>>>>>> I'd really like to apply that patch ASAP, because when I run hbck >> >> I >> >>>> get >> >>>>>>> over >> >>>>>>> 400 regions which are multiply assigned. >> >>>>>>> Last question, I understand the region's data is lost but is >> >> there >> >>> a >> >>>>> way >> >>>>>> to >> >>>>>>> at least make the table consistent again by some how removing the >> >>>> lost >> >>>>>>> region? >> >>>>>>> >> >>>>>>> Thanks. >> >>>>>>> >> >>>>>>> -eran >> >>>>>>> >> >>>>>>> >> >>>>>>> >> >>>>>>> On Sat, Jul 2, 2011 at 01:46, Ted Yu <yuzhih...@gmail.com> >> >> wrote: >> >>>>>>> >> >>>>>>>>>> 2011-06-29 16:43:57,880 INFO >> >>>>>>>> org.apache.hadoop.hbase. >> >>>>>>>> master.AssignmentManager: Region has been >> >>>>>>>> PENDING_OPEN for too long, reassigning >> >>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> region=gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309. >> >>>>>>>> >> >>>>>>>> The double assignment should have been fixed by J-D's recent >> >>>> checkin. >> >>>>>>>> >> >>>>>>>> On Fri, Jul 1, 2011 at 3:14 PM, Stack <st...@duboce.net> >> >> wrote: >> >>>>>>>> >> >>>>>>>>> Is >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309. >> >>>>>>>>> the region that was having the issue? If so, if you looked >> >> in >> >>>>>>>>> hadoop1-s05's logs, was this region opened around 2011-06-29 >> >>>>>> 16:43:57? >> >>>>>>>>> Was it also opened hadoop1-s02 not long after? Did you say >> >>> what >> >>>>>>>>> version of hbase you are on? >> >>>>>>>>> >> >>>>>>>>> St.Ack >> >>>>>>>>> >> >>>>>>>>> On Fri, Jul 1, 2011 at 5:08 AM, Eran Kutner <e...@gigya.com> >> >>>>> wrote: >> >>>>>>>>>> Hi Stack, >> >>>>>>>>>> I'm not sure what the log means. I do see references to two >> >>>>>> different >> >>>>>>>>>> servers, but that would probably happen if there was normal >> >>>>>>> transition >> >>>>>>>> I >> >>>>>>>>>> assume. I'm using version 0.90.3 >> >>>>>>>>>> Here are the relevant lines from the master logs: >> >>>>>>>>>> >> >>>>>>>>>> 2011-06-19 21:39:37,164 INFO >> >>>>>>>>> org.apache.hadoop.hbase.master.ServerManager: >> >>>>>>>>>> Received REGION_SPLIT: >> >>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> gs_raw_events,GSLoad_1308518553_168_WEB204,1308533691659.9000a5d8df9502efc90d2c23567e4658.: >> >>>>>>>>>> Daughters; >> >>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309., >> >>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> gs_raw_events,GSLoad_1308518810_1249_WEB204,1308533970928.46f876a4e97be04edb35eb8f8959d482. >> >>>>>>>>>> from hadoop1-s05.farm-ny.gigya.com,60020,1307349217076 >> >>>>>>>>>> 2011-06-19 21:43:12,983 INFO >> >>>>>>>> org.apache.hadoop.hbase.catalog.MetaEditor: >> >>>>>>>>>> Deleted daughter reference >> >>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309., >> >>>>>>>>>> qualifier=splitA, from parent >> >>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> gs_raw_events,GSLoad_1308518553_168_WEB204,1308533691659.9000a5d8df9502efc90d2c23567e4658. >> >>>>>>>>>> 2011-06-29 16:29:36,143 DEBUG >> >>>>>>>>>> org.apache.hadoop.hbase.master.AssignmentManager: Starting >> >>>>>>> unassignment >> >>>>>>>>> of >> >>>>>>>>>> region >> >>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309. >> >>>>>>>>>> (offlining) >> >>>>>>>>>> 2011-06-29 16:29:36,146 DEBUG >> >>>>>>>>>> org.apache.hadoop.hbase.master.AssignmentManager: Sent >> >> CLOSE >> >>> to >> >>>>>>>>> serverName= >> >>>>>>>>>> hadoop1-s05.farm-ny.gigya.com,60020,1307349217076, >> >>>>>> load=(requests=0, >> >>>>>>>>>> regions=1654, usedHeap=1870, maxHeap=12483) for region >> >>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309. >> >>>>>>>>>> 2011-06-29 16:29:38,327 DEBUG >> >>>>>>>>>> org.apache.hadoop.hbase.master.AssignmentManager: Handling >> >>> new >> >>>>>>>> unassigned >> >>>>>>>>>> node: /hbase/unassigned/584dac5cc70d8682f71c4675a843c309 >> >>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> (region=gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309., >> >>>>>>>>>> server=hadoop1-s05.farm-ny.gigya.com,60020,1307349217076, >> >>>>>>>>>> state=RS_ZK_REGION_CLOSED) >> >>>>>>>>>> 2011-06-29 16:29:38,327 DEBUG >> >>>>>>>>>> org.apache.hadoop.hbase.master.AssignmentManager: Handling >> >>>>>>>>>> transition=RS_ZK_REGION_CLOSED, >> >>>>>>>>>> server=hadoop1-s05.farm-ny.gigya.com,60020,1307349217076, >> >>>>>>>>>> region=584dac5cc70d8682f71c4675a843c309 >> >>>>>>>>>> 2011-06-29 16:30:53,742 DEBUG >> >>>>>>>>>> org.apache.hadoop.hbase.master.handler.ClosedRegionHandler: >> >>>>>> Handling >> >>>>>>>>> CLOSED >> >>>>>>>>>> event for 584dac5cc70d8682f71c4675a843c309 >> >>>>>>>>>> 2011-06-29 16:30:53,742 DEBUG >> >>>>>>>>>> org.apache.hadoop.hbase.master.AssignmentManager: Table >> >> being >> >>>>>>> disabled >> >>>>>>>> so >> >>>>>>>>>> deleting ZK node and removing from regions in transition, >> >>>>> skipping >> >>>>>>>>>> assignment of region >> >>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309. >> >>>>>>>>>> 2011-06-29 16:30:53,742 DEBUG >> >>>>>>>> org.apache.hadoop.hbase.zookeeper.ZKAssign: >> >>>>>>>>>> master:60000-0x13004a31d7804c4 Deleting existing unassigned >> >>>> node >> >>>>>> for >> >>>>>>>>>> 584dac5cc70d8682f71c4675a843c309 that is in expected state >> >>>>>>>>>> RS_ZK_REGION_CLOSED >> >>>>>>>>>> 2011-06-29 16:30:53,801 DEBUG >> >>>>>>>> org.apache.hadoop.hbase.zookeeper.ZKAssign: >> >>>>>>>>>> master:60000-0x13004a31d7804c4 Successfully deleted >> >>> unassigned >> >>>>> node >> >>>>>>> for >> >>>>>>>>>> region 584dac5cc70d8682f71c4675a843c309 in expected state >> >>>>>>>>>> RS_ZK_REGION_CLOSED >> >>>>>>>>>> 2011-06-29 16:34:01,453 INFO >> >>>>>>>> org.apache.hadoop.hbase.catalog.MetaEditor: >> >>>>>>>>>> Updated region >> >>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309. >> >>>>>>>>>> in META >> >>>>>>>>>> 2011-06-29 16:37:12,247 DEBUG >> >>>>>>>> org.apache.hadoop.hbase.zookeeper.ZKAssign: >> >>>>>>>>>> master:60000-0x13004a31d7804c4 Creating (or updating) >> >>>> unassigned >> >>>>>> node >> >>>>>>>> for >> >>>>>>>>>> 584dac5cc70d8682f71c4675a843c309 with OFFLINE state >> >>>>>>>>>> 2011-06-29 16:37:12,576 DEBUG >> >>>>>>>>>> org.apache.hadoop.hbase.master.AssignmentManager: No >> >> previous >> >>>>>>>> transition >> >>>>>>>>>> plan was found (or we are ignoring an existing plan) for >> >>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309. >> >>>>>>>>>> so generated a random one; >> >>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> hri=gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309., >> >>>>>>>>>> src=, dest=hadoop1-s05.farm-ny.gigya.com >> >>> ,60020,1307349217076; >> >>>> 5 >> >>>>>>>>> (online=5, >> >>>>>>>>>> exclude=null) available servers >> >>>>>>>>>> 2011-06-29 16:37:12,576 DEBUG >> >>>>>>>>>> org.apache.hadoop.hbase.master.AssignmentManager: Assigning >> >>>>> region >> >>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309. >> >>>>>>>>>> to hadoop1-s05.farm-ny.gigya.com,60020,1307349217076 >> >>>>>>>>>> 2011-06-29 16:37:13,102 DEBUG >> >>>>>>>>>> org.apache.hadoop.hbase.master.AssignmentManager: Handling >> >>>>>>>>>> transition=RS_ZK_REGION_OPENED, >> >>>>>>>>>> server=hadoop1-s05.farm-ny.gigya.com,60020,1307349217076, >> >>>>>>>>>> region=584dac5cc70d8682f71c4675a843c309 >> >>>>>>>>>> 2011-06-29 16:39:54,075 DEBUG >> >>>>>>>>>> org.apache.hadoop.hbase.master.handler.OpenedRegionHandler: >> >>>>>> Handling >> >>>>>>>>> OPENED >> >>>>>>>>>> event for 584dac5cc70d8682f71c4675a843c309; deleting >> >>> unassigned >> >>>>>> node >> >>>>>>>>>> 2011-06-29 16:39:54,075 DEBUG >> >>>>>>>> org.apache.hadoop.hbase.zookeeper.ZKAssign: >> >>>>>>>>>> master:60000-0x13004a31d7804c4 Deleting existing unassigned >> >>>> node >> >>>>>> for >> >>>>>>>>>> 584dac5cc70d8682f71c4675a843c309 that is in expected state >> >>>>>>>>>> RS_ZK_REGION_OPENED >> >>>>>>>>>> 2011-06-29 16:39:54,192 DEBUG >> >>>>>>>> org.apache.hadoop.hbase.zookeeper.ZKAssign: >> >>>>>>>>>> master:60000-0x13004a31d7804c4 Successfully deleted >> >>> unassigned >> >>>>> node >> >>>>>>> for >> >>>>>>>>>> region 584dac5cc70d8682f71c4675a843c309 in expected state >> >>>>>>>>>> RS_ZK_REGION_OPENED >> >>>>>>>>>> 2011-06-29 16:39:54,326 DEBUG >> >>>>>>>>>> org.apache.hadoop.hbase.master.handler.OpenedRegionHandler: >> >>>>> Opened >> >>>>>>>> region >> >>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309. >> >>>>>>>>>> on hadoop1-s05.farm-ny.gigya.com,60020,1307349217076 >> >>>>>>>>>> 2011-06-29 16:40:00,598 DEBUG >> >>>>>>>> org.apache.hadoop.hbase.zookeeper.ZKAssign: >> >>>>>>>>>> master:60000-0x13004a31d7804c4 Creating (or updating) >> >>>> unassigned >> >>>>>> node >> >>>>>>>> for >> >>>>>>>>>> 584dac5cc70d8682f71c4675a843c309 with OFFLINE state >> >>>>>>>>>> 2011-06-29 16:40:00,877 DEBUG >> >>>>>>>>>> org.apache.hadoop.hbase.master.AssignmentManager: No >> >> previous >> >>>>>>>> transition >> >>>>>>>>>> plan was found (or we are ignoring an existing plan) for >> >>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309. >> >>>>>>>>>> so generated a random one; >> >>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> hri=gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309., >> >>>>>>>>>> src=, dest=hadoop1-s05.farm-ny.gigya.com >> >>> ,60020,1307349217076; >> >>>> 5 >> >>>>>>>>> (online=5, >> >>>>>>>>>> exclude=null) available servers >> >>>>>>>>>> 2011-06-29 16:40:00,877 DEBUG >> >>>>>>>>>> org.apache.hadoop.hbase.master.AssignmentManager: Assigning >> >>>>> region >> >>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309. >> >>>>>>>>>> to hadoop1-s05.farm-ny.gigya.com,60020,1307349217076 >> >>>>>>>>>> 2011-06-29 16:43:57,879 INFO >> >>>>>>>>>> org.apache.hadoop.hbase.master.AssignmentManager: Regions >> >> in >> >>>>>>> transition >> >>>>>>>>>> timed out: >> >>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309. >> >>>>>>>>>> state=PENDING_OPEN, ts=1309380052723 >> >>>>>>>>>> 2011-06-29 16:43:57,880 INFO >> >>>>>>>>>> org.apache.hadoop.hbase.master.AssignmentManager: Region >> >> has >> >>>> been >> >>>>>>>>>> PENDING_OPEN for too long, reassigning >> >>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> region=gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309. >> >>>>>>>>>> 2011-06-29 16:43:57,936 DEBUG >> >>>>>>>>>> org.apache.hadoop.hbase.master.AssignmentManager: Forcing >> >>>>> OFFLINE; >> >>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> was=gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309. >> >>>>>>>>>> state=PENDING_OPEN, ts=1309380052723 >> >>>>>>>>>> 2011-06-29 16:43:57,936 DEBUG >> >>>>>>>>>> org.apache.hadoop.hbase.master.AssignmentManager: No >> >> previous >> >>>>>>>> transition >> >>>>>>>>>> plan was found (or we are ignoring an existing plan) for >> >>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309. >> >>>>>>>>>> so generated a random one; >> >>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> hri=gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309., >> >>>>>>>>>> src=, dest=hadoop1-s02.farm-ny.gigya.com >> >>> ,60020,1306919627544; >> >>>> 5 >> >>>>>>>>> (online=5, >> >>>>>>>>>> exclude=null) available servers >> >>>>>>>>>> 2011-06-29 16:43:57,936 DEBUG >> >>>>>>>>>> org.apache.hadoop.hbase.master.AssignmentManager: Assigning >> >>>>> region >> >>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309. >> >>>>>>>>>> to hadoop1-s02.farm-ny.gigya.com,60020,1306919627544 >> >>>>>>>>>> 2011-06-29 16:43:59,022 DEBUG >> >>>>>>>>>> org.apache.hadoop.hbase.master.AssignmentManager: Handling >> >>>>>>>>>> transition=RS_ZK_REGION_OPENING, >> >>>>>>>>>> server=hadoop1-s02.farm-ny.gigya.com,60020,1306919627544, >> >>>>>>>>>> region=584dac5cc70d8682f71c4675a843c309 >> >>>>>>>>>> 2011-06-29 16:43:59,221 DEBUG >> >>>>>>>>>> org.apache.hadoop.hbase.master.AssignmentManager: Handling >> >>>>>>>>>> transition=RS_ZK_REGION_OPENING, >> >>>>>>>>>> server=hadoop1-s02.farm-ny.gigya.com,60020,1306919627544, >> >>>>>>>>>> region=584dac5cc70d8682f71c4675a843c309 >> >>>>>>>>>> 2011-06-29 16:43:59,226 DEBUG >> >>>>>>>>>> org.apache.hadoop.hbase.master.AssignmentManager: Handling >> >>>>>>>>>> transition=RS_ZK_REGION_OPENED, >> >>>>>>>>>> server=hadoop1-s02.farm-ny.gigya.com,60020,1306919627544, >> >>>>>>>>>> region=584dac5cc70d8682f71c4675a843c309 >> >>>>>>>>>> 2011-06-29 16:43:59,274 DEBUG >> >>>>>>>>>> org.apache.hadoop.hbase.master.handler.OpenedRegionHandler: >> >>>>>> Handling >> >>>>>>>>> OPENED >> >>>>>>>>>> event for 584dac5cc70d8682f71c4675a843c309; deleting >> >>> unassigned >> >>>>>> node >> >>>>>>>>>> 2011-06-29 16:43:59,274 DEBUG >> >>>>>>>> org.apache.hadoop.hbase.zookeeper.ZKAssign: >> >>>>>>>>>> master:60000-0x13004a31d7804c4 Deleting existing unassigned >> >>>> node >> >>>>>> for >> >>>>>>>>>> 584dac5cc70d8682f71c4675a843c309 that is in expected state >> >>>>>>>>>> RS_ZK_REGION_OPENED >> >>>>>>>>>> 2011-06-29 16:43:59,296 DEBUG >> >>>>>>>> org.apache.hadoop.hbase.zookeeper.ZKAssign: >> >>>>>>>>>> master:60000-0x13004a31d7804c4 Successfully deleted >> >>> unassigned >> >>>>> node >> >>>>>>> for >> >>>>>>>>>> region 584dac5cc70d8682f71c4675a843c309 in expected state >> >>>>>>>>>> RS_ZK_REGION_OPENED >> >>>>>>>>>> 2011-06-29 16:43:59,375 WARN >> >>>>>>>>>> org.apache.hadoop.hbase.master.AssignmentManager: >> >> Overwriting >> >>>>>>>>>> 584dac5cc70d8682f71c4675a843c309 on >> >>>>>>>>>> serverName=hadoop1-s05.farm-ny.gigya.com >> >>> ,60020,1307349217076, >> >>>>>>>>>> load=(requests=0, regions=1273, usedHeap=2676, >> >> maxHeap=12483) >> >>>>>>>>>> 2011-06-29 16:43:59,375 DEBUG >> >>>>>>>>>> org.apache.hadoop.hbase.master.handler.OpenedRegionHandler: >> >>>>> Opened >> >>>>>>>> region >> >>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> gs_raw_events,GSLoad_1308518553_168_WEB204,1308533970928.584dac5cc70d8682f71c4675a843c309. >> >>>>>>>>>> on hadoop1-s02.farm-ny.gigya.com,60020,1306919627544 >> >>>>>>>>>> >> >>>>>>>>>> Thanks. >> >>>>>>>>>> >> >>>>>>>>>> -eran >> >>>>>>>>>> >> >>>>>>>>>> >> >>>>>>>>>> >> >>>>>>>>>> On Fri, Jul 1, 2011 at 09:05, Stack <st...@duboce.net> >> >>> wrote: >> >>>>>>>>>> >> >>>>>>>>>>> So, Eran, it seems as though two RegionServers were >> >> carrying >> >>>> the >> >>>>>>>>>>> region? One deleted a file (compaction on its side)? Can >> >>> you >> >>>>>>> figure >> >>>>>>>>>>> if indeed two servers had same region? (Check master logs >> >>> for >> >>>>>> this >> >>>>>>>>>>> regions assignments). >> >>>>>>>>>>> >> >>>>>>>>>>> What version of hbase? >> >>>>>>>>>>> >> >>>>>>>>>>> St.Ack >> >>>>>>>>>>> >> >>>>>>>>>>> >> >>>>>>>>>>> On Thu, Jun 30, 2011 at 3:58 AM, Eran Kutner < >> >>> e...@gigya.com> >> >>>>>>> wrote: >> >>>>>>>>>>>> Hi, >> >>>>>>>>>>>> I have a cluster of 5 nodes with one large table that >> >>>>> currently >> >>>>>>> has >> >>>>>>>>>>> around >> >>>>>>>>>>>> 12000 regions. Everything was working fine for >> >> relatively >> >>>> long >> >>>>>>> time, >> >>>>>>>>>>> until >> >>>>>>>>>>>> now. >> >>>>>>>>>>>> Yesterday I significantly reduced the TTL on the table >> >> and >> >>>>>>> initiated >> >>>>>>>>>>> major >> >>>>>>>>>>>> compaction. This should have reduced the table size to >> >>> about >> >>>>> 20% >> >>>>>>> of >> >>>>>>>>> its >> >>>>>>>>>>>> original size. >> >>>>>>>>>>>> Today, I'm getting errors of inaccessible files on HDFS, >> >>> for >> >>>>>>>> example: >> >>>>>>>>>>>> java.io.IOException: Got error in response to >> >>> OP_READ_BLOCK >> >>>>>> self=/ >> >>>>>>>>>>>> 10.1.104.2:58047, remote=/10.1.104.2:50010 for file >> >>>>>>>>>>>> >> >>>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> /hbase/gs_raw_events/584dac5cc70d8682f71c4675a843c309/events/1971818821800304360 >> >>>>>>>>>>>> for block 3674866614142268536_674205 >> >>>>>>>>>>>> at >> >>>>>>>>>>>> >> >>>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> org.apache.hadoop.hdfs.DFSClient$BlockReader.newBlockReader(DFSClient.java:1487) >> >>>>>>>>>>>> at >> >>>>>>>>>>>> >> >>>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> org.apache.hadoop.hdfs.DFSClient$DFSInputStream.blockSeekTo(DFSClient.java:1811) >> >>>>>>>>>>>> at >> >>>>>>>>>>>> >> >>>>>>>>> >> >>>>>>> >> >>>>> >> >>> >> org.apache.hadoop.hdfs.DFSClient$DFSInputStream.read(DFSClient.java:1948) >> >>>>>>>>>>>> at >> >>>>> java.io.DataInputStream.read(DataInputStream.java:132) >> >>>>>>>>>>>> at >> >>>>>>>>>>>> >> >>>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> org.apache.hadoop.hbase.io.hfile.BoundedRangeFileInputStream.read(BoundedRangeFileInputStream.java:105) >> >>>>>>>>>>>> at >> >>>>>>>>> >> >> java.io.BufferedInputStream.fill(BufferedInputStream.java:218) >> >>>>>>>>>>>> at >> >>>>>>>>> >> >> java.io.BufferedInputStream.read(BufferedInputStream.java:237) >> >>>>>>>>>>>> at >> >>>>>>>>>>>> >> >>>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> org.apache.hadoop.io.compress.BlockDecompressorStream.rawReadInt(BlockDecompressorStream.java:128) >> >>>>>>>>>>>> at >> >>>>>>>>>>>> >> >>>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> org.apache.hadoop.io.compress.BlockDecompressorStream.decompress(BlockDecompressorStream.java:68) >> >>>>>>>>>>>> at >> >>>>>>>>>>>> >> >>>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> org.apache.hadoop.io.compress.DecompressorStream.read(DecompressorStream.java:75) >> >>>>>>>>>>>> at >> >>>>>>>>> >> >> java.io.BufferedInputStream.read1(BufferedInputStream.java:256) >> >>>>>>>>>>>> at >> >>>>>>>>> >> >> java.io.BufferedInputStream.read(BufferedInputStream.java:317) >> >>>>>>>>>>>> at >> >>>>>> org.apache.hadoop.io.IOUtils.readFully(IOUtils.java:102) >> >>>>>>>>>>>> at >> >>>>>>>>>>>> >> >>>>>>>>> >> >>>>>>> >> >>>>> >> >>> >> org.apache.hadoop.hbase.io.hfile.HFile$Reader.decompress(HFile.java:1094) >> >>>>>>>>>>>> at >> >>>>>>>>>>>> >> >>>>>>>>> >> >>>>>>> >> >>>>> >> >>> >> org.apache.hadoop.hbase.io.hfile.HFile$Reader.readBlock(HFile.java:1036) >> >>>>>>>>>>>> at >> >>>>>>>>>>>> >> >>>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> org.apache.hadoop.hbase.io.hfile.HFile$Reader$Scanner.seekTo(HFile.java:1433) >> >>>>>>>>>>>> at >> >>>>>>>>>>>> >> >>>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> org.apache.hadoop.hbase.regionserver.StoreFileScanner.seekAtOrAfter(StoreFileScanner.java:139) >> >>>>>>>>>>>> at >> >>>>>>>>>>>> >> >>>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> org.apache.hadoop.hbase.regionserver.StoreFileScanner.seek(StoreFileScanner.java:96) >> >>>>>>>>>>>> at >> >>>>>>>>>>>> >> >>>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> org.apache.hadoop.hbase.regionserver.StoreScanner.<init>(StoreScanner.java:77) >> >>>>>>>>>>>> at >> >>>>>>>>>>>> >> >>>>>>>> >> >>>>> >> >> org.apache.hadoop.hbase.regionserver.Store.getScanner(Store.java:1341) >> >>>>>>>>>>>> at >> >>>>>>>>>>>> >> >>>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> org.apache.hadoop.hbase.regionserver.HRegion$RegionScanner.<init>(HRegion.java:2269) >> >>>>>>>>>>>> at >> >>>>>>>>>>>> >> >>>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> org.apache.hadoop.hbase.regionserver.HRegion.instantiateInternalScanner(HRegion.java:1126) >> >>>>>>>>>>>> at >> >>>>>>>>>>>> >> >>>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> org.apache.hadoop.hbase.regionserver.HRegion.getScanner(HRegion.java:1118) >> >>>>>>>>>>>> at >> >>>>>>>>>>>> >> >>>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> org.apache.hadoop.hbase.regionserver.HRegion.getScanner(HRegion.java:1102) >> >>>>>>>>>>>> at >> >>>>>>>>>>>> >> >>>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> org.apache.hadoop.hbase.regionserver.HRegionServer.openScanner(HRegionServer.java:1781) >> >>>>>>>>>>>> at >> >>>> sun.reflect.GeneratedMethodAccessor46.invoke(Unknown >> >>>>>>>> Source) >> >>>>>>>>>>>> at >> >>>>>>>>>>>> >> >>>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) >> >>>>>>>>>>>> at >> >> java.lang.reflect.Method.invoke(Method.java:597) >> >>>>>>>>>>>> at >> >>>>>>>>>>>> >> >>>>>>> >> >> org.apache.hadoop.hbase.ipc.HBaseRPC$Server.call(HBaseRPC.java:570) >> >>>>>>>>>>>> at >> >>>>>>>>>>>> >> >>>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> org.apache.hadoop.hbase.ipc.HBaseServer$Handler.run(HBaseServer.java:1039) >> >>>>>>>>>>>> >> >>>>>>>>>>>> I checked and the file, indeed doesn't exist on HDFS, >> >> here >> >>>> is >> >>>>>> the >> >>>>>>>> name >> >>>>>>>>>>> node >> >>>>>>>>>>>> logs for this block, apparently because it was deleted: >> >>>>>>>>>>>> 2011-06-19 21:39:36,651 INFO >> >>>>> org.apache.hadoop.hdfs.StateChange: >> >>>>>>>>> BLOCK* >> >>>>>>>>>>>> NameSystem.allocateBlock: >> >>>>>>>>>>>> >> >>>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> /hbase/gs_raw_events/584dac5cc70d8682f71c4675a843c309/.tmp/2096863423111131624. >> >>>>>>>>>>>> blk_3674866614142268536_674205 >> >>>>>>>>>>>> 2011-06-19 21:40:11,954 INFO >> >>>>> org.apache.hadoop.hdfs.StateChange: >> >>>>>>>>> BLOCK* >> >>>>>>>>>>>> NameSystem.addStoredBlock: blockMap updated: >> >>>> 10.1.104.2:50010 >> >>>>> is >> >>>>>>>>> added >> >>>>>>>>>>> to >> >>>>>>>>>>>> blk_3674866614142268536_674205 size 67108864 >> >>>>>>>>>>>> 2011-06-19 21:40:11,954 INFO >> >>>>> org.apache.hadoop.hdfs.StateChange: >> >>>>>>>>> BLOCK* >> >>>>>>>>>>>> NameSystem.addStoredBlock: blockMap updated: >> >>>> 10.1.104.3:50010 >> >>>>> is >> >>>>>>>>> added >> >>>>>>>>>>> to >> >>>>>>>>>>>> blk_3674866614142268536_674205 size 67108864 >> >>>>>>>>>>>> 2011-06-19 21:40:11,955 INFO >> >>>>> org.apache.hadoop.hdfs.StateChange: >> >>>>>>>>> BLOCK* >> >>>>>>>>>>>> NameSystem.addStoredBlock: blockMap updated: >> >>>> 10.1.104.5:50010 >> >>>>> is >> >>>>>>>>> added >> >>>>>>>>>>> to >> >>>>>>>>>>>> blk_3674866614142268536_674205 size 67108864 >> >>>>>>>>>>>> 2011-06-29 20:20:01,662 INFO >> >>>>> org.apache.hadoop.hdfs.StateChange: >> >>>>>>>>> BLOCK* >> >>>>>>>>>>> ask >> >>>>>>>>>>>> 10.1.104.2:50010 to delete >> >>> blk_3674866614142268536_674205 >> >>>>>>>>>>>> 2011-06-29 20:20:13,671 INFO >> >>>>> org.apache.hadoop.hdfs.StateChange: >> >>>>>>>>> BLOCK* >> >>>>>>>>>>> ask >> >>>>>>>>>>>> 10.1.104.5:50010 to delete >> >>> blk_-4056387895369608597_675174 >> >>>>>>>>>>>> blk_-5017882805850873821_672281 >> >>>> blk_702373987100607684_672288 >> >>>>>>>>>>>> blk_-5357157478043290010_668506 >> >>>> blk_7118175133735412789_674903 >> >>>>>>>>>>>> blk_-3569812563715986384_675231 >> >>>> blk_8296855057240604851_669285 >> >>>>>>>>>>>> blk_-6483679172530609101_674268 >> >>>> blk_8738539715363739108_673682 >> >>>>>>>>>>>> blk_1744841904626813502_675238 >> >>>> blk_-6035315106100051103_674266 >> >>>>>>>>>>>> blk_-1789501623010070237_674908 >> >>>> blk_1944054629336265129_673689 >> >>>>>>>>>>>> blk_3674866614142268536_674205 >> >>>> blk_7930425446738143892_647410 >> >>>>>>>>>>>> blk_-3007186753042268449_669296 >> >>>>> blk_-5482302621772778061_647416 >> >>>>>>>>>>>> blk_-3765735404924932181_672004 >> >>>> blk_7476090998956811081_675169 >> >>>>>>>>>>>> blk_7862291659285127712_646890 >> >>>> blk_-2666244746343584727_672013 >> >>>>>>>>>>>> blk_6039172613960915602_674206 >> >>>> blk_-8470884397893086564_646899 >> >>>>>>>>>>>> blk_4558230221166712802_668510 >> >>>>>>>>>>>> 2011-06-29 20:20:46,698 INFO >> >>>>> org.apache.hadoop.hdfs.StateChange: >> >>>>>>>>> BLOCK* >> >>>>>>>>>>> ask >> >>>>>>>>>>>> 10.1.104.3:50010 to delete >> >>> blk_-7851606440036350812_671552 >> >>>>>>>>>>>> blk_9214649160203453845_647566 >> >>> blk_702373987100607684_672288 >> >>>>>>>>>>>> blk_5958099369749234073_668143 >> >>>> blk_-5172218034084903173_673109 >> >>>>>>>>>>>> blk_-2934555181472719276_646476 >> >>>>> blk_-1409986679370073931_672552 >> >>>>>>>>>>>> blk_-2786034325506235869_669086 >> >>>> blk_3674866614142268536_674205 >> >>>>>>>>>>>> blk_510158930393283118_673225 >> >>> blk_916244738216205237_677068 >> >>>>>>>>>>>> blk_-4317027806407316617_670379 >> >>>> blk_8555705688850972639_673485 >> >>>>>>>>>>>> blk_-3765735404924932181_672004 >> >>>>> blk_-5482302621772778061_647416 >> >>>>>>>>>>>> blk_-2461801145731752623_674605 >> >>>>> blk_-8737702908048998927_672549 >> >>>>>>>>>>>> blk_-8470884397893086564_646899 >> >>>> blk_4558230221166712802_668510 >> >>>>>>>>>>>> blk_-4056387895369608597_675174 >> >>>>> blk_-8675430610673886073_647695 >> >>>>>>>>>>>> blk_-6642870230256028318_668211 >> >>>>> blk_-3890408516362176771_677483 >> >>>>>>>>>>>> blk_-3569812563715986384_675231 >> >>>>> blk_-5007142629771321873_674548 >> >>>>>>>>>>>> blk_-3345355191863431669_667066 >> >>>> blk_8296855057240604851_669285 >> >>>>>>>>>>>> blk_-6595462308187757470_672420 >> >>>>> blk_-2583945228783203947_674607 >> >>>>>>>>>>>> blk_-346988625120916345_677063 >> >>>> blk_4449525876338684218_674496 >> >>>>>>>>>>>> blk_2617172363857549730_668201 >> >>>> blk_8738539715363739108_673682 >> >>>>>>>>>>>> blk_-208904675456598428_679286 >> >>>> blk_-497549341281882641_646477 >> >>>>>>>>>>>> blk_-6035315106100051103_674266 >> >>>>> blk_-2356539038067297411_672388 >> >>>>>>>>>>>> blk_-3881703084497103249_668137 >> >>>> blk_2214397881104950315_646643 >> >>>>>>>>>>>> blk_-5907671443455357710_673223 >> >>>>> blk_-2431880309956605679_669204 >> >>>>>>>>>>>> blk_6039172613960915602_674206 >> >>>> blk_5053643911633142711_669194 >> >>>>>>>>>>>> blk_-2636977729205236686_674664 >> >>>>>>>>>>>> >> >>>>>>>>>>>> I assume the file loss is somehow related to this change >> >>> and >> >>>>> the >> >>>>>>>> major >> >>>>>>>>>>>> compaction that followed because the same scan that is >> >>>> failing >> >>>>>> now >> >>>>>>>> was >> >>>>>>>>>>>> working fine yesterday and that is the only changed that >> >>>>>> happened >> >>>>>>> on >> >>>>>>>>> the >> >>>>>>>>>>>> cluster. Any suggestions what to do now? >> >>>>>>>>>>>> >> >>>>>>>>>>>> Thanks. >> >>>>>>>>>>>> >> >>>>>>>>>>>> -eran >> >>>>>>>>>>>> >> >>>>>>>>>>> >> >>>>>>>>>> >> >>>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>> >> >>>>> >> >>>> >> >>> >> >> >> > >
