Integrated in Hadoop-Hdfs-HAbranch-build #80 (See https://builds.apache.org/job/Hadoop-Hdfs-HAbranch-build/80/)
HDFS-2955. IllegalStateException during standby startup in getCurSegmentTxId. Contributed by Hari Mankude. (Revision 1245230)

Result = FAILURE
atm : http://svn.apache.org/viewcvs.cgi/?root=Apache-SVN&view=rev&rev=1245230
Files :

• /hadoop/common/branches/HDFS-1623/hadoop-hdfs-project/hadoop-hdfs/CHANGES.HDFS-1623.txt
• /hadoop/common/branches/HDFS-1623/hadoop-hdfs-project/hadoop-hdfs/src/main/java/org/apache/hadoop/hdfs/server/namenode/FSNamesystem.java
• /hadoop/common/branches/HDFS-1623/hadoop-hdfs-project/hadoop-hdfs/src/test/java/org/apache/hadoop/hdfs/server/namenode/ha/TestHASafeMode.java

I've just committed this to the HA branch. Thanks a lot, Hari.

+1, the latest patch looks good to me. I'll commit this momentarily.

Thanks a lot for addressing all my feedback, Hari.

patch attached

Looks like a few unintended whitespace changes snuck in to the patch. Otherwise the patch looks good to me. +1 once those are addressed.

One more patch added

@aaron - can you please add the test - which should have been part of HDFS-2943.

HDFS-2943 was done on trunk/0.23, where there is no Standby NN.

I believe this patch is good to go without tests, because it is a simple change.

The patch outputs the wrong value for the metric in the case of the standby NN. Since there are no tests, I only discovered this upon manual inspection.

I can add a test if necessary. Also, will upload a patch with zero return for standby so that this patch can be committed.

@aaron - can you please add the test - which should have been part of HDFS-2943.

I believe this patch is good to go without tests, because it is a simple change. Should we open another jira related to 2943 or perhaps reopen 2943.

What is the behavior by standby, with this patch, if it has completely read the last segment and is waiting for the new segment to be completed? I believe in that case it would anyway return zero.

Not quite. With this patch, if the standby NN has never been in the active state, the metric will always output 18179, probably because of some oddity with the way metrics output negative values (since curSegmentTxId is initially set to HdfsConstants.INVALID_TXID, which is -12345.) This is obviously incorrect. If the standby NN has previously been in the active state, this metric will always output 2, which is also incorrect.

We will end up reading from in_progress log for automatic failover to reduce the failover times.

Maybe. I strongly suspect that the time for automatic failover will be greatly dominated by the time to detect failure of the active and fence it, not the time it takes to read the most recent edit log segment once we've decided to fail over, in which case this optimization of reading in-progress edit logs will provide little benefit.

Regardless, this isn't how it's implemented now.

This would be one less place to change when standby starts reading from in_progress.

Except that we should write a test that this metric outputs the correct values, in which case this code might change anyway. We don't yet know how reading in-progress edit logs will be implemented.

Regarding testing, any HA test will run into it. I have a 100% hit rate on the actual cluster

Sure, but none of the tests will fail because of this error, will they? You'll see an error in the NN log if you look, but only if. And even if tests were failing without this patch, there's still no test asserting that the metric outputs the correct value in the case of the standby NN.

What is the behavior by standby, with this patch, if it has completely read the last segment and is waiting for the new segment to be completed? I believe in that case it would anyway return zero. Then we don't need a special handling to return zero. If it happens to be called while a segment was being read, it still semantically makes sense to return the actual value since last roll.

@Aaron,

Yes, looks tests started failing due to this. Thanks Hari, for filing the JIRA.

Uma, I'd be pretty surprised if this test failure were due to this change. This change should only cause an error to be logged to the NN log, and cause the metric not to be output. Also, TestQuotasWithHA passes for me locally on the HA branch.

Yes Aaron, you are right. That trace should not be the cause for that test failure( logically also should not have relation). Sorry for the confusion. I did not digg into it.
I just gave clean update. It is passing for me as well now. Also i can still see IllegalStateException from getTransactionsSinceLastLogRoll. So, no issue with that test failure.

@Aaron,

We will end up reading from in_progress log for automatic failover to reduce the failover times. This would be one less place to change when standby starts reading from in_progress.

If you feel strongly, I can change patch to return 0 for now.

Regarding testing, any HA test will run into it. I have a 100% hit rate on the actual cluster

Yes, looks tests started failing due to this. Thanks Hari, for filing the JIRA.

Uma, I'd be pretty surprised if this test failure were due to this change. This change should only cause an error to be logged to the NN log, and cause the metric not to be output. Also, TestQuotasWithHA passes for me locally on the HA branch.

Hari, rather than push down the standby state into FSEditLog, why not just make the TransactionsSinceLastLogRoll metric always output 0 in the case of the standby? This seems correct, since the Standby doesn't read from in-progress edit logs, and wil fix this bug as well.

Also, it should be pretty easy to write a simple test for this. See TestNameNodeMetrics for an example.

patch attached.

Yes, looks tests started failing due to this. Thanks Hari, for filing the JIRA.

java.lang.Exception: test timed out after 60000 milliseconds
	at java.lang.Object.wait(Native Method)
	at org.apache.hadoop.hdfs.DFSOutputStream.waitForAckedSeqno(DFSOutputStream.java:1584)
	at org.apache.hadoop.hdfs.DFSOutputStream.flushInternal(DFSOutputStream.java:1570)
	at org.apache.hadoop.hdfs.DFSOutputStream.close(DFSOutputStream.java:1653)
	at org.apache.hadoop.fs.FSDataOutputStream$PositionCache.close(FSDataOutputStream.java:66)
	at org.apache.hadoop.fs.FSDataOutputStream.close(FSDataOutputStream.java:99)
	at org.apache.hadoop.io.IOUtils.cleanup(IOUtils.java:204)
	at org.apache.hadoop.io.IOUtils.closeStream(IOUtils.java:221)
	at org.apache.hadoop.hdfs.server.namenode.ha.TestQuotasWithHA.testQuotasTrackedOnStandby(TestQuotasWithHA.java:111)

cause is same:

Caused by: java.lang.IllegalStateException: Bad state: OPEN_FOR_READING
	at com.google.common.base.Preconditions.checkState(Preconditions.java:172)
	at org.apache.hadoop.hdfs.server.namenode.FSEditLog.getCurSegmentTxId(FSEditLog.java:417)
	at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.getTransactionsSinceLastLogRoll(FSNamesystem.java:3171)
	... 57 more

Good catch, Hari. We should probably just disable both of the "transactionsSince..." metrics introduced in HDFS-2943 in the case of the standby NN.

The reported blocks 0 needs additional 16889 blocks to reach the threshold 0.9990 of total blocks 16905. Safe mode will be turned off automatically.2012-02-15 22:45:28,943 ERROR lib.MethodMetric (MethodMetric.java:snapshot(118)) - Error invoking method getTransactionsSinceLastLogRolljava.lang.reflect.InvocationTargetException
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.metrics2.lib.MethodMetric$2.snapshot(MethodMetric.java:111)
at org.apache.hadoop.metrics2.lib.MethodMetric.snapshot(MethodMetric.java:144) at org.apache.hadoop.metrics2.lib.MetricsRegistry.snapshot(MetricsRegistry.java:
369) at org.apache.hadoop.metrics2.lib.MetricsSourceBuilder$1.getMetrics(MetricsSourc
eBuilder.java:78)
at org.apache.hadoop.metrics2.impl.MetricsSourceAdapter.getMetrics(MetricsSource
Adapter.java:173) at org.apache.hadoop.metrics2.impl.MetricsSourceAdapter.updateJmxCache(MetricsSourceAdapter.java:152)
at org.apache.hadoop.metrics2.impl.MetricsSourceAdapter.getMBeanInfo(MetricsSourceAdapter.java:144)
at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.getNewMBeanClassName(DefaultMBeanServerInterceptor.java:321) at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerMBean(DefaultMB
eanServerInterceptor.java:307)
at com.sun.jmx.mbeanserver.JmxMBeanServer.registerMBean(JmxMBeanServer.java:482) at org.apache.hadoop.metrics2.util.MBeans.register(MBeans.java:55)
at org.apache.hadoop.metrics2.impl.MetricsSourceAdapter.startMBeans(MetricsSourceAdapter.java:199)
at org.apache.hadoop.metrics2.impl.MetricsSourceAdapter.start(MetricsSourceAdapter.java:93)
at org.apache.hadoop.metrics2.impl.MetricsSystemImpl.registerSource(MetricsSystemImpl.java:243)
at org.apache.hadoop.metrics2.impl.MetricsSystemImpl.register(MetricsSystemImpl.java:221)
at org.apache.hadoop.metrics2.MetricsSystem.register(MetricsSystem.java:54)
at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.startCommonServices(FSNamesystem.java:505)
at org.apache.hadoop.hdfs.server.namenode.NameNode.startCommonServices(NameNode.java:434)
at org.apache.hadoop.hdfs.server.namenode.NameNode.initialize(NameNode.java:398)
at org.apache.hadoop.hdfs.server.namenode.NameNode.<init>(NameNode.java:547)
at org.apache.hadoop.hdfs.server.namenode.NameNode.<init>(NameNode.java:528)
at org.apache.hadoop.hdfs.server.namenode.NameNode.createNameNode(NameNode.java:838)
at org.apache.hadoop.hdfs.server.namenode.NameNode.main(NameNode.java:896)
Caused by: java.lang.IllegalStateException: Bad state: OPEN_FOR_READING
at com.google.common.base.Preconditions.checkState(Preconditions.java:172)
at org.apache.hadoop.hdfs.server.namenode.FSEditLog.getCurSegmentTxId(FSEditLog.java:417)
at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.getTransactionsSinceLastLogRoll(FSNamesystem.java:3173)
... 27 more