hbase-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Sebastian Bauer <ad...@ugame.net.pl>
Subject Re: HBase exception after upgrading from hbase-0.90-branch to trunk
Date Fri, 19 Aug 2011 07:14:50 GMT
Full logs with DEBUG are here: http://s2.e-back.net/hbase_logs2.tar.gz

Sebastian Bauer


On 18.08.2011 21:19, Sebastian Bauer wrote:
> i'm running hbase and hadoop at my home on laptop and pc with atom 
> prosessor so hadoop is under replicated and there are lags because of 
> wifi connection.
> this is few lines from master log:
>
> 2011-08-18 21:09:30,128 DEBUG 
> org.apache.hadoop.hbase.zookeeper.ZKUtil: 
> master:60000-0x31de4bb6620000 Retrieved 48 byte(s) of data from znode 
> /hbase/unassigned/1028785192; data=region=.META.,,1, 
> origin=lala,60020,1313694551840, state=RS_ZK_REGION_OPENED
> 2011-08-18 21:09:30,138 DEBUG org.apache.zookeeper.ClientCnxn: Got 
> notification sessionid:0x31de4bb6620000
> 2011-08-18 21:09:30,139 DEBUG org.apache.zookeeper.ClientCnxn: Got 
> WatchedEvent state:SyncConnected type:NodeDeleted 
> path:/hbase/unassigned/1028785192 for sessionid 0x31de4bb6620000
> 2011-08-18 21:09:30,139 DEBUG 
> org.apache.hadoop.hbase.zookeeper.ZooKeeperWatcher: 
> master:60000-0x31de4bb6620000 Received ZooKeeper Event, 
> type=NodeDeleted, state=SyncConnected, path=/hbase/unassigned/1028785192
> 2011-08-18 21:09:30,139 WARN 
> org.apache.hadoop.hbase.master.AssignmentManager: Node deleted but 
> still in RIT: .META.,,1.1028785192 state=OPEN, ts=1313694570097, 
> server=lala,60020,1313694551840
> 2011-08-18 21:09:30,140 DEBUG org.apache.zookeeper.ClientCnxn: Reading 
> reply sessionid:0x31de4bb6620000, packet:: clientPath:null 
> serverPath:null finished:false header:: 74,2  replyHeader:: 
> 74,21474836511,0  request:: '/hbase/unassigned/1028785192,3  
> response:: null
> 2011-08-18 21:09:30,140 DEBUG 
> org.apache.hadoop.hbase.zookeeper.ZKAssign: 
> master:60000-0x31de4bb6620000 Successfully deleted unassigned node for 
> region 1028785192 in expected state RS_ZK_REGION_OPENED
> 2011-08-18 21:09:30,141 DEBUG 
> org.apache.hadoop.hbase.master.handler.OpenedRegionHandler: Opened 
> region .META.,,1.1028785192 on lala,60020,1313694551840
> 2011-08-18 21:09:30,143 DEBUG org.apache.zookeeper.ClientCnxn: Reading 
> reply sessionid:0x31de4bb6620000, packet:: clientPath:null 
> serverPath:null finished:false header:: 75,3  replyHeader:: 
> 75,-1,-101  request:: '/hbase/unassigned/1028785192,T  response::
> 2011-08-18 21:09:30,143 DEBUG 
> org.apache.hadoop.hbase.zookeeper.ZKUtil: 
> master:60000-0x31de4bb6620000 Set watcher on existing znode 
> /hbase/unassigned/1028785192
> 2011-08-18 21:09:30,143 INFO 
> org.apache.hadoop.hbase.zookeeper.MetaNodeTracker: Detected completed 
> assignment of META, notifying catalog tracker
> 2011-08-18 21:09:30,159 INFO org.apache.hadoop.hbase.master.HMaster: 
> .META. assigned=2, rit=false, location=lala,60020,1313694551840
> 2011-08-18 21:09:30,163 DEBUG org.apache.zookeeper.ClientCnxn: Reading 
> reply sessionid:0x31de4bb6620000, packet:: clientPath:null 
> serverPath:null finished:false header:: 76,3  replyHeader:: 76,-1,0  
> request:: '/hbase,F  response:: 
> s{4294967300,4294967300,1313691532307,1313691532307,0,32,0,0,0,8,21474836504}
> 2011-08-18 21:09:30,178 INFO org.apache.hadoop.hbase.master.HMaster: 
> metaUpdated = NULL.
> 2011-08-18 21:09:30,178 INFO org.apache.hadoop.hbase.master.HMaster: 
> Meta updated status = false
> 2011-08-18 21:09:30,179 INFO org.apache.hadoop.hbase.master.HMaster: 
> Meta has HRI with HTDs. Updating meta now.
> 2011-08-18 21:09:34,991 INFO 
> org.apache.hadoop.hbase.master.handler.ServerShutdownHandler: 
> Reassigning 732 region(s) that bacek,60020,1313693298967 was carrying 
> (skipping 0 regions(s) that are already in transition)
> 2011-08-18 21:09:34,991 DEBUG 
> org.apache.hadoop.hbase.zookeeper.ZKAssign: 
> master:60000-0x31de4bb6620000 Creating (or updating) unassigned node 
> for 4e36610aa00b7e8743c1816b12c2e698 with OFFLINE state
> 2011-08-18 21:09:34,992 DEBUG org.apache.zookeeper.ClientCnxn: Reading 
> reply sessionid:0x31de4bb6620000, packet:: clientPath:null 
> serverPath:null finished:false header:: 77,3  replyHeader:: 77,-1,0  
> request:: '/hbase,F  response:: 
> s{4294967300,4294967300,1313691532307,1313691532307,0,32,0,0,0,8,21474836504}
> 2011-08-18 21:09:34,995 DEBUG org.apache.zookeeper.ClientCnxn: Reading 
> reply sessionid:0x31de4bb6620000, packet:: 
> clientPath:/hbase/unassigned/4e36610aa00b7e8743c1816b12c2e698 
> serverPath:/hbase/unassigned/4e36610aa00b7e8743c1816b12c2e698 
> finished:false header:: 78,9  replyHeader:: 78,-1,0  request:: 
> '/hbase/unassigned
> /4e36610aa00b7e8743c1816b12c2e698  response:: 
> '/hbase/unassigned/4e36610aa00b7e8743c1816b12c2e698
> 2011-08-18 21:09:34,995 DEBUG org.apache.zookeeper.ClientCnxn: Reading 
> reply sessionid:0x31de4bb6620000, packet:: clientPath:null 
> serverPath:null finished:false header:: 79,3  replyHeader:: 
> 79,-1,-101  request:: 
> '/hbase/unassigned/4e36610aa00b7e8743c1816b12c2e698,F  response::
> 2011-08-18 21:09:34,997 INFO 
> org.apache.hadoop.hbase.catalog.MetaEditor: Updated -ROOT- row with 
> metaMigrated status = true
> 2011-08-18 21:09:34,997 INFO org.apache.hadoop.hbase.master.HMaster: 
> Meta updated with new HRI.
> 2011-08-18 21:09:35,039 DEBUG org.apache.zookeeper.ClientCnxn: Reading 
> reply sessionid:0x31de4bb6620000, packet:: clientPath:null 
> serverPath:null finished:false header:: 80,1  replyHeader:: 
> 80,21474836513,0  request:: 
> '/hbase/unassigned/4e36610aa00b7e8743c1816b12c2e698,#ffffffff000a3134323637406c616c6101300131ffffffde
> 4c69ffffff93374558545f41432c2c313239353533333533303436332e34653336363130616130306237653837343363313831366231326332653639382e10186c616c612c36303030302c313331333639343535303231310,v{s{31,s{'world,'anyone}}},0
 
> response:: '/hbase/unassigned/4e36610aa00b7e8743c1816b12c2e698
> 2011-08-18 21:09:35,040 DEBUG org.apache.zookeeper.ClientCnxn: Reading 
> reply sessionid:0x31de4bb6620000, packet:: clientPath:null 
> serverPath:null finished:false header:: 81,3  replyHeader:: 81,-1,0  
> request:: '/hbase/unassigned/4e36610aa00b7e8743c1816b12c2e698,T  
> response:: s{21474836513,21474836513,1313694574984,1313
> 694574984,0,0,0,0,109,0,21474836513}
> 2011-08-18 21:09:35,040 DEBUG 
> org.apache.hadoop.hbase.master.AssignmentManager: No previous 
> transition plan was found (or we are ignoring an existing plan) for 
> EXT_AC,,1295533530463.4e36610aa00b7e8743c1816b12c2e698. so generated a 
> random one; 
> hri=EXT_AC,,1295533530463.4e36610aa00b7e8743c1816b12c2e698., src=, 
> dest=lala
> ,60020,1313694551840; 2 (online=2, exclude=null) available servers
>
> Pozdrawiam
> Sebastian Bauer
> -----------------------------------------------------
> http://tikecik.pl
>
>
> On 18.08.2011 19:45, Stack wrote:
>> Can you redo with logs at DEBUG level?
>>
>> This seems like a migration issue -- i.e. migrating the catalog tables
>> from old format to new -- but from what I can see in the logs, its
>> more an issue w/ state transitions in zk... I need the DEBUG logging
>> to tell for sure.
>>
>> St.Ack
>>
>> On Thu, Aug 18, 2011 at 8:27 AM, Sebastian Bauer<admin@ugame.net.pl>  
>> wrote:
>>> Hi, comments inline:
>>>
>>> On 16.08.2011 06:42, Stack wrote:
>>>> Oh, are you running on hbase trunk?  If so, did you write all your
>>>> data with TRUNK or did you start up 0.92 on a data that was written w/
>>>> 0.90 (It should work but you may have hit an issue).
>>> I had branch-0.90 and after proper shutdown i had updated hbase to 
>>> trunk, it
>>> looks like -ROOT- table was migrated but .META. had problem with saving
>>> information about migration in logs i had informations:
>>>
>>> 2011-08-18 17:16:09,334 INFO org.apache.hadoop.hbase.master.HMaster: 
>>> .META.
>>> assigned=2, rit=false, location=lala.golden,60020,1313680556932
>>> 2011-08-18 17:16:09,340 INFO org.apache.hadoop.hbase.master.HMaster:
>>> metaUpdated = NULL.
>>> 2011-08-18 17:16:09,340 INFO org.apache.hadoop.hbase.master.HMaster: 
>>> Meta
>>> updated status = false
>>> 2011-08-18 17:16:09,340 INFO org.apache.hadoop.hbase.master.HMaster: 
>>> Meta
>>> has HRI with HTDs. Updating meta now.
>>> 2011-08-18 17:16:17,535 INFO 
>>> org.apache.hadoop.hbase.catalog.MetaEditor:
>>> Updated -ROOT- row with metaMigrated status = true
>>> 2011-08-18 17:16:17,536 INFO org.apache.hadoop.hbase.master.HMaster: 
>>> Meta
>>> updated with new HRI.
>>>
>>> and even after restarting i saw this in logs.
>>>
>>> ./hbase shell show all one regions, but any operation on tables show
>>> information that .META. table doesn't exist.
>>> Full logs from first and second run after upgrade are here:
>>>   http://s2.e-back.net/hbase_logs.tar.gz
>>>
>>> -ROOT- have this rows:
>>> hbase(main):005:0>  scan '-ROOT-'
>>> ROW
>>> COLUMN+CELL
>>>   -ROOT-,,0
>>>   column=info:metamigrated, timestamp=1313680577531, value=\xFF
>>>   .META.,,1
>>>   column=info:regioninfo, timestamp=1278560826938, value=REGION =>  
>>> {NAME =>
>>> '.META.,,1 TableName =>  ', STARTKEY =>  '', ENDKEY =>  '', ENCODED
=>
>>> 1028785192,}
>>>   .META.,,1
>>>   column=info:server, timestamp=1313680569288, value=lala.golden:60020
>>>   .META.,,1
>>>   column=info:serverstartcode, timestamp=1313680569288, 
>>> value=1313680556932
>>> 2 row(s) in 0.0500 seconds
>>>
>>>
>>> On 16.08.2011 06:40, Stack wrote:
>>>> What version of hbase is this Sebastian?
>>>>
>>>> What you mean by remove -ROOT- and .META. (that doesn't sound good but
>>>> you probably mean something else though looking at the exception
>>>> below, maybe this is what you did).
>>> Long time ago when i smashed my hbase instalation when i removed 
>>> .META. and
>>> -ROOT- (./bin/hadoop fs -rmr /hbase/.META.) and run add_table.rb 
>>> script all
>>> tables were online again.
>>>> St.Ack
>>>>
>>>> On Thu, Aug 11, 2011 at 11:54 AM, Sebastian Bauer<admin@ugame.net.pl>
>>>>   wrote:
>>>>> 2011-08-11 20:53:55,889 WARN
>>>>> org.apache.hadoop.hbase.master.AssignmentManager: Failed 
>>>>> assignment of
>>>>>
>>>>> Golden_ATU,m_ef06511a814155022686d50cebb0dba5_2010_9_40CC7C8170915ABC43432E524F0E6D2B,1301066006080.f656ca602b8638ad8329c36af85ae43e.

>>>>>
>>>>> to db2a.goldenline.pl,60020,1313088827048, trying to assign elsewhere
>>>>> instead; retry=
>>>>> org.apache.hadoop.ipc.RemoteException: java.io.IOException:
>>>>> java.lang.IllegalArgumentException: Can not create a Path from an 
>>>>> empty
>>>>> string
>>>>>         at org.apache.hadoop.fs.Path.checkPathArg(Path.java:82)
>>>>>         at org.apache.hadoop.fs.Path.<init>(Path.java:90)
>>>>>         at org.apache.hadoop.fs.Path.<init>(Path.java:50)
>>>>>         at
>>>>> org.apache.hadoop.hbase.util.FSUtils.getTablePath(FSUtils.java:845)
>>>>>         at
>>>>> org.apache.hadoop.hbase.util.FSUtils.getTableInfoPath(FSUtils.java:818)

>>>>>
>>>>>         at
>>>>>
>>>>> org.apache.hadoop.hbase.util.FSUtils.getTableInfoModtime(FSUtils.java:832)

>>>>>
>>>>>         at
>>>>>
>>>>> org.apache.hadoop.hbase.util.FSTableDescriptors.get(FSTableDescriptors.java:127)

>>>>>
>>>>>         at
>>>>>
>>>>> org.apache.hadoop.hbase.util.FSTableDescriptors.get(FSTableDescriptors.java:99)

>>>>>
>>>>>         at
>>>>>
>>>>> org.apache.hadoop.hbase.regionserver.HRegionServer.openRegion(HRegionServer.java:2329)

>>>>>
>>>>>         at sun.reflect.NativeMethodAccessorImpl.invoke0(Native 
>>>>> Method)
>>>>>         at
>>>>>
>>>>> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)

>>>>>
>>>>>         at
>>>>>
>>>>> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)

>>>>>
>>>>>         at java.lang.reflect.Method.invoke(Method.java:597)
>>>>>         at
>>>>>
>>>>> org.apache.hadoop.hbase.ipc.WritableRpcEngine$Server.call(WritableRpcEngine.java:312)

>>>>>
>>>>>         at
>>>>>
>>>>> org.apache.hadoop.hbase.ipc.HBaseServer$Handler.run(HBaseServer.java:1222)

>>>>>
>>>>>
>>>>>         at
>>>>> org.apache.hadoop.hbase.ipc.HBaseClient.call(HBaseClient.java:871)
>>>>>         at
>>>>>
>>>>> org.apache.hadoop.hbase.ipc.WritableRpcEngine$Invoker.invoke(WritableRpcEngine.java:141)

>>>>>
>>>>>         at $Proxy7.openRegion(Unknown Source)
>>>>>         at
>>>>>
>>>>> org.apache.hadoop.hbase.master.ServerManager.sendRegionOpen(ServerManager.java:404)

>>>>>
>>>>>         at
>>>>>
>>>>> org.apache.hadoop.hbase.master.AssignmentManager.assign(AssignmentManager.java:1239)

>>>>>
>>>>>         at
>>>>>
>>>>> org.apache.hadoop.hbase.master.AssignmentManager.assign(AssignmentManager.java:1034)

>>>>>
>>>>>         at
>>>>>
>>>>> org.apache.hadoop.hbase.master.AssignmentManager.assign(AssignmentManager.java:1014)

>>>>>
>>>>>         at
>>>>>
>>>>> org.apache.hadoop.hbase.master.handler.ClosedRegionHandler.process(ClosedRegionHandler.java:101)

>>>>>
>>>>>         at
>>>>>
>>>>> org.apache.hadoop.hbase.master.AssignmentManager.addToRITandCallClose(AssignmentManager.java:458)

>>>>>
>>>>>         at
>>>>>
>>>>> org.apache.hadoop.hbase.master.AssignmentManager.processRegionsInTransition(AssignmentManager.java:389)

>>>>>
>>>>>         at
>>>>>
>>>>> org.apache.hadoop.hbase.master.AssignmentManager.processRegionInTransition(AssignmentManager.java:355)

>>>>>
>>>>>         at
>>>>>
>>>>> org.apache.hadoop.hbase.master.AssignmentManager.processRegionsInTransition(AssignmentManager.java:296)

>>>>>
>>>>>         at
>>>>>
>>>>> org.apache.hadoop.hbase.master.AssignmentManager.joinCluster(AssignmentManager.java:243)

>>>>>
>>>>>         at
>>>>>
>>>>> org.apache.hadoop.hbase.master.HMaster.finishInitialization(HMaster.java:467)

>>>>>
>>>>>         at 
>>>>> org.apache.hadoop.hbase.master.HMaster.run(HMaster.java:300)
>>>>>
>>>>> 2011-08-11 20:53:55,895 WARN
>>>>> org.apache.hadoop.hbase.master.AssignmentManager: Failed 
>>>>> assignment of
>>>>>
>>>>> Golden_ATU,m_ef06511a814155022686d50cebb0dba5_2010_9_40CC7C8170915ABC43432E524F0E6D2B,1301066006080.f656ca602b8638ad8329c36af85ae43e.

>>>>>
>>>>> to db2b.goldenline.pl,60020,1313088826553, trying to assign elsewhere
>>>>> instead; retry=
>>>>> org.apache.hadoop.ipc.RemoteException: java.io.IOException:
>>>>> java.lang.IllegalArgumentException: Can not create a Path from an 
>>>>> empty
>>>>> string
>>>>>         at org.apache.hadoop.fs.Path.checkPathArg(Path.java:82)
>>>>>         at org.apache.hadoop.fs.Path.<init>(Path.java:90)
>>>>>         at org.apache.hadoop.fs.Path.<init>(Path.java:50)
>>>>>         at
>>>>> org.apache.hadoop.hbase.util.FSUtils.getTablePath(FSUtils.java:845)
>>>>>         at
>>>>> org.apache.hadoop.hbase.util.FSUtils.getTableInfoPath(FSUtils.java:818)

>>>>>
>>>>>         at
>>>>>
>>>>> org.apache.hadoop.hbase.util.FSUtils.getTableInfoModtime(FSUtils.java:832)

>>>>>
>>>>>         at
>>>>>
>>>>> org.apache.hadoop.hbase.util.FSTableDescriptors.get(FSTableDescriptors.java:127)

>>>>>
>>>>>         at
>>>>>
>>>>> org.apache.hadoop.hbase.util.FSTableDescriptors.get(FSTableDescriptors.java:99)

>>>>>
>>>>>         at
>>>>>
>>>>> org.apache.hadoop.hbase.regionserver.HRegionServer.openRegion(HRegionServer.java:2329)

>>>>>
>>>>>         at sun.reflect.NativeMethodAccessorImpl.invoke0(Native 
>>>>> Method)
>>>>>         at
>>>>>
>>>>> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)

>>>>>
>>>>>         at
>>>>>
>>>>> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)

>>>>>
>>>>>         at java.lang.reflect.Method.invoke(Method.java:597)
>>>>>         at
>>>>>
>>>>> org.apache.hadoop.hbase.ipc.WritableRpcEngine$Server.call(WritableRpcEngine.java:312)

>>>>>
>>>>>         at
>>>>>
>>>>> org.apache.hadoop.hbase.ipc.HBaseServer$Handler.run(HBaseServer.java:1222)

>>>>>
>>>>>
>>>>>         at
>>>>> org.apache.hadoop.hbase.ipc.HBaseClient.call(HBaseClient.java:871)
>>>>>         at
>>>>>
>>>>> org.apache.hadoop.hbase.ipc.WritableRpcEngine$Invoker.invoke(WritableRpcEngine.java:141)

>>>>>
>>>>>         at $Proxy7.openRegion(Unknown Source)
>>>>>         at
>>>>>
>>>>> org.apache.hadoop.hbase.master.ServerManager.sendRegionOpen(ServerManager.java:404)

>>>>>
>>>>>         at
>>>>>
>>>>> org.apache.hadoop.hbase.master.AssignmentManager.assign(AssignmentManager.java:1239)

>>>>>
>>>>>         at
>>>>>
>>>>> org.apache.hadoop.hbase.master.AssignmentManager.assign(AssignmentManager.java:1034)

>>>>>
>>>>>         at
>>>>>
>>>>> org.apache.hadoop.hbase.master.AssignmentManager.assign(AssignmentManager.java:1014)

>>>>>
>>>>>         at
>>>>>
>>>>> org.apache.hadoop.hbase.master.handler.ClosedRegionHandler.process(ClosedRegionHandler.java:101)

>>>>>
>>>>>         at
>>>>>
>>>>> org.apache.hadoop.hbase.master.AssignmentManager.addToRITandCallClose(AssignmentManager.java:458)

>>>>>
>>>>>         at
>>>>>
>>>>> org.apache.hadoop.hbase.master.AssignmentManager.processRegionsInTransition(AssignmentManager.java:389)

>>>>>
>>>>>         at
>>>>>
>>>>> org.apache.hadoop.hbase.master.AssignmentManager.processRegionInTransition(AssignmentManager.java:355)

>>>>>
>>>>>         at
>>>>>
>>>>> org.apache.hadoop.hbase.master.AssignmentManager.processRegionsInTransition(AssignmentManager.java:296)

>>>>>
>>>>>         at
>>>>>
>>>>> org.apache.hadoop.hbase.master.AssignmentManager.joinCluster(AssignmentManager.java:243)

>>>>>
>>>>>         at
>>>>>
>>>>> org.apache.hadoop.hbase.master.HMaster.finishInitialization(HMaster.java:467)

>>>>>
>>>>>         at 
>>>>> org.apache.hadoop.hbase.master.HMaster.run(HMaster.java:300)
>>>>>
>>>>> -- 
>>>>>
>>>>> Pozdrawiam
>>>>> Sebastian Bauer
>>>>> -----------------------------------------------------
>>>>> http://tikecik.pl
>>>>>
>>>>>
>

Mime
View raw message