Re: HBase exception after upgrading from hbase-0.90-branch to trunk

Thu, 18 Aug 2011 12:19:51 -0700

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<[email protected]>  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<[email protected]>
  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

Reply via email to