hbase-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "stack (JIRA)" <j...@apache.org>
Subject [jira] Commented: (HBASE-1439) race between master and regionserver after missed heartbeat
Date Wed, 20 May 2009 20:34:45 GMT

    [ https://issues.apache.org/jira/browse/HBASE-1439?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12711322#action_12711322
] 

stack commented on HBASE-1439:
------------------------------

I took a look at the regionserver log (provided by andrew lee).

This machine is under heavy write load.  Its expiring client leases.  Some client is confused
thinking it hosting .META.

I see this in log from about five minutes earlier:

2009-05-17 04:00:09,506 WARN org.apache.hadoop.hbase.util.Sleeper: We slept 128679ms, ten
times longer than scheduled: 3000
2009-05-17 04:00:09,507 WARN org.apache.hadoop.hbase.regionserver.HRegionServer: unable to
report to master for 128680 milliseconds - retrying
2009-05-17 04:00:09,508 WARN org.apache.hadoop.hbase.util.Sleeper: We slept 127641ms, ten
times longer than scheduled: 1000
2009-05-17 04:00:09,526 INFO org.apache.hadoop.hbase.regionserver.HRegionServer: MSG_CALL_SERVER_STARTUP:
safeMode=false

We get the MSG_CALL_SERVER_STARTUP because master thinks we're showing up new though what
seems to have happened, as apurtell speculated, was that we just went too sleep for too long.

In the src we do this on above message in regionserver:

              case MSG_CALL_SERVER_STARTUP:
                // We the MSG_CALL_SERVER_STARTUP on startup but we can also
                // get it when the master is panicing because for instance
                // the HDFS has been yanked out from under it.  Be wary of
                // this message.
                if (checkFileSystem()) {
                  closeAllRegions();
                  try {
                    log.closeAndDelete();
                  } catch (Exception e) {
                    LOG.error("error closing and deleting HLog", e);
                  }
                  try {
                    serverInfo.setStartCode(System.currentTimeMillis());
                    log = setupHLog();
                    this.logFlusher.setHLog(log);
                  } catch (IOException e) {
                    this.abortRequested = true;
                    this.stopRequested.set(true);
                    e = RemoteExceptionHandler.checkIOException(e);
                    LOG.fatal("error restarting server", e);
                    break;
                  }
                  reportForDuty(sleeper);
                  restart = true;
                } else {
                  LOG.fatal("file system available check failed. " +
                  "Shutting down server.");
                }
                break;

We shut all regions then call close and delete on the hlog.  This is likely what pulled log
out from under regionserver (as per apurtell speculation).

This is bad.

Can commit log ownership be mediated by zk?  When the hosting regionserver's lease expires,
can the lease on the commit log expire too so regionserver doesn't remove logs being worked
on by another?

> race between master and regionserver after missed heartbeat
> -----------------------------------------------------------
>
>                 Key: HBASE-1439
>                 URL: https://issues.apache.org/jira/browse/HBASE-1439
>             Project: Hadoop HBase
>          Issue Type: Bug
>    Affects Versions: 0.19.1
>         Environment: CentOS 5.2 x86_64, HBase 0.19.1, Hadoop 0.19.1
>            Reporter: Andrew Purtell
>
> Seen on one of our 0.19.1 clusters:
> {code}
> java.io.FileNotFoundException: File does not exist: hdfs://jdc2-atr-dc-2.atr.trendmicro.com:50000
> /data/hbase/log_10.3.134.207_1242286427894_60020/hlog.dat.1242528291898
>  at org.apache.hadoop.hdfs.DistributedFileSystem.getFileStatus(DistributedFileSystem.java:415)
>  at org.apache.hadoop.fs.FileSystem.getLength(FileSystem.java:679)
>  at org.apache.hadoop.hbase.io.SequenceFile$Reader.<init>(SequenceFile.java:1431)
>  at org.apache.hadoop.hbase.io.SequenceFile$Reader.<init>(SequenceFile.java:1426)
>  at org.apache.hadoop.hbase.regionserver.HLog.splitLog(HLog.java:753)
>  at org.apache.hadoop.hbase.regionserver.HLog.splitLog(HLog.java:716)
>  at org.apache.hadoop.hbase.master.ProcessServerShutdown.process(ProcessServerShutdown.java:249)
>  at org.apache.hadoop.hbase.master.HMaster.processToDoQueue(HMaster.java:442)
>  at org.apache.hadoop.hbase.master.HMaster.run(HMaster.java:377)
> 2009-05-17 04:05:55,481 INFO org.apache.hadoop.hbase.master.RegionServerOperation: process
> shutdown of server 10.3.134.207:60020: logSplit: false, rootRescanned: false, numberOfMetaRegions:
1,
> onlineMetaRegions.size(): 1
> {code}
> I do not have the region server log yet, but here is my conjecture:
> Here, the write ahead log for 10.3.134.207 is missing in DFS: java.io.FileNotFoundException:
hdfs://jdc2-atr-dc-2.atr.trendmicro.com:50000/data/hbase/log_10.3.134.207_1242286427894_60020/hlog.dat.1242528291898
when the master tries to split it after declaring the region server crashed. There have been
recent trouble reports on this cluster that indicate severe memory stress, e.g. kernel panics
due to OOM. Based on that I think it is likely that the region server here missed a heartbeat
so the master declared it crashed and began to split the log. But, the log was then deleted
out from underneath the master's split thread. I think the region server was actually still
running but partially swapped out or the node was otherwise overloaded so it missed its heartbeat.
Then, when the region server came back after being swapped in, it realized it missed its heartbeat
and shut down, deleting the log as is normally done. 
> Even if the above is not the actual cause in this case, I think the scenario is plausible.
What do you think?

-- 
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.


Mime
View raw message