Namenode服务挂

BUG修复：HDFS-13112

这两天排查了小集群Crash的问题，这里先总结下这两天排查的结果

一、查看日志

首先查看了Namenode Crash的时候的日志

（一）以下是patch hdfs-11306输出的日志：可以看出还保存在bufCurrent中的op是CancelDelegationTokenOp

2019-09-10 03:50:16,403 WARN org.apache.hadoop.hdfs.server.namenode.EditsDoubleBuffer: The edits buffer is 85 bytes long with 1 unflushed transactions. Below is the list of unflushed transactions:

2019-09-10 03:50:16,408 WARN org.apache.hadoop.hdfs.server.namenode.EditsDoubleBuffer: Unflushed op [0]: CancelDelegationTokenOp [token=token for yarn: HDFS_DELEGATION_TOKEN owner=yarn/chdd520.bigdata.pab.com.cn@PASC.COM, renewer=yarn, realUser=, issueDate=1567970236988, maxDate=1568575036988, sequenceNumber=621170591, masterKeyId=108, opCode=OP_CANCEL_DELEGATION_TOKEN, txid=5061382841]

2019-09-10 03:50:16,409 FATAL org.apache.hadoop.hdfs.server.namenode.FSEditLog: Error: finalize log segment 5060982535, 5061382841 failed for required journal (JournalAndStream(mgr=QJM to [10.0.67.216:8485, 10.0.67.217:8485, 10.0.67.218:8485], stream=QuorumOutputStream starting at txid 5060982535))

java.io.IOException: FSEditStream has 85 bytes still to be flushed and cannot be closed.

（二）以下是patch hdfs-11292输出的日志：

2019-09-10 03:46:03,830 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: logSyncAll toSyncToTxId=5060853010 lastSyncedTxid=5060853007 mostRecentTxid=5060853010

2019-09-10 03:46:03,864 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: Done logSyncAll lastWrittenTxId=5060853010 lastSyncedTxid=5060853010 mostRecentTxid=5060853010

2019-09-10 03:48:10,273 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: logSyncAll toSyncToTxId=5060982534 lastSyncedTxid=5060982511 mostRecentTxid=5060982534

2019-09-10 03:48:10,290 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: Done logSyncAll lastWrittenTxId=5060982534 lastSyncedTxid=5060982534 mostRecentTxid=5060982534

2019-09-10 03:50:16,323 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: logSyncAll toSyncToTxId=5061382825 lastSyncedTxid=5061371306 mostRecentTxid=5061382825

2019-09-10 03:50:16,402 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: Done logSyncAll lastWrittenTxId=5061382841 lastSyncedTxid=5061382840 mostRecentTxid=5061382841

以上每两行是一组操作，表示一次rolleditlog同步的日志，从日志中我们可以发现问题

正常情况下，第一行的toSyncToTxId（5060853010）是等于第二行的lastWrittenTxId（5060853010），toSyncToTxId（5060853010）表示OP_END_LOG_SEGMENT的txid，代表一个editlog文件最后一个操作

但是在出错的情况下，第一行的toSyncToTxId（5061382825）是不等于第二行的lastWrittenTxId（5061382841），表示在rolleditlog将OP_END_LOG_SEGMENT写入缓冲区后，还有其他线程在写，即rolleditlog和其他线程同时工作。这个现象从已有的认知是不可能发生，我们下面可以分析下。另外lastWrittenTxId（5061382841）与 lastSyncedTxid（5061382840）不等，也说明还有数据没持久化。

下面我们看下一般操作的流程：

可以看到处理setAcl 的Handler线程在logSync的flush阶段，处理setPermission的Handler线程是有机会把op写入缓冲区的

	SetAcl Thread	SetPermission Thread
	fslock.writerlock.lock	have not fslock.writerlock
	SetAcl operation
FSEditlog.logEdit()	FSEditLog synchronized enter
	txid++
	editLogStream.write(op)
	FSEditLog synchronized exit
	fslock.writerlock.unlock
FSEditLog.logSync()	FSEditLog synchronized enter	fslock.writerlock.lock
	while mytxid > synctxid && isSyncRunning -> wait mytxid <= synctxid return isSyncRunning=true	SetPermission operation
	FSEditLog synchronized exit
	editLogStream.flush()	FSEditLog synchronized enter
		txid++
		editLogStream.write(op)
		FSEditLog synchronized exit
	FSEditLog synchronized enter	fslock.writerlock.unlock
	isSyncRunning=false
	FSEditLog synchronized exit
	SetAcl Finished	FSEditLog synchronized enter
		while mytxid > synctxid && isSyncRunning -> wait mytxid <= synctxid return isSyncRunning=true
		FSEditLog synchronized exit
		editLogStream.flush()
		FSEditLog synchronized enter
		isSyncRunning=false
		FSEditLog synchronized exit

然后看下当发生rolleditlog时的情况

由于rolleditlog整个操作都在fslock内，所以处理setPermission的Handler线程是没有任何机会进行任何操作的

	rolleditlog Thread	SetPermission Thread
	fslock.writerlock.lock	have not fslock.writerlock
	FSEditLog synchronized enter
endCurrentLogSegment	logedit(OP_END_LOG_SEGMENT)
	logsync()
	finalizeLogSegment
startCurrentLogSegment	logedit(OP_START_LOG_SEGMENT)
	logsync()
	FSEditLog synchronized exit
	fslock.writerlock.unlock

二-查看监控

查看ganglia监控，发现在发生crash的时候，journalnode的每秒txid的写入量都很大

chdd374在9月8日的06:48左右

chdd374在9月10日的03:50左右

然后发现其实每隔一小时，都有这个高峰

登录服务器验证editlog文件大小，可以看到15:53和16:52的文件大小确实比其他文件大很多

使用edilog工具查看，发现OP_CANCEL_DELEGATION_TOKEN的操作有55W

查看服务端日志，namenode Crash的时候，并没有cancleDelegationToken RPC请求处理的相关日志，说明记录cancleDelegationToken操作还有其他地方

 

继续查看源码，终于发现产生这么多cancleDelegationToken的原因：

Namenode里有个DelegationTokenSecretManager，会每隔一小时删除过期的token，而删除过期token的操作，而调用logEdit将日志记录到缓冲区，而这个操作只获取了FSEditlog锁对象，但是没有获取FSLock的写锁，而rolleditlog操作在logedit和logsync都有可能释放锁，这样DelegationTokenSecretManager就有机会将删除token的操作写入缓冲区，从而导致最开始的日志错误

明天会先看下高版本hadoop代码中，这个流程是否还是这样；然后看下为什么会有这么多过期的delegationToken，基本一台机器对应的delegationToken有900多次操作，我们有490台，差不多总计55W。然后考虑下怎么修复这个问题