Aman Poonia created HBASE-30346:
-----------------------------------
Summary: NPE in AbstractFSWAL WAL-roll debug logging aborts
RegionServer when DFSOutputStream#getPipeline() legitimately returns null
Key: HBASE-30346
URL: https://issues.apache.org/jira/browse/HBASE-30346
Project: HBase
Issue Type: Bug
Reporter: Aman Poonia
*Symptom*
RegionServers abort during WAL log rolling with:
{{}}
{code:java}
java.lang.NullPointerException: Cannot read the array length because "array" is
null at java.base/java.util.Arrays.stream(Arrays.java:5533) at
org.apache.hadoop.hbase.regionserver.wal.AbstractFSWAL.rollWriterInternal(AbstractFSWAL.java:926)
at
org.apache.hadoop.hbase.regionserver.wal.AbstractFSWAL.rollWriter(AbstractFSWAL.java:...)
at
org.apache.hadoop.hbase.wal.AbstractWALRoller$RollController.rollWal(AbstractWALRoller.java:305)
at
org.apache.hadoop.hbase.wal.AbstractWALRoller.run(AbstractWALRoller.java:211)
{code}
followed by {{AbstractWALRoller}} catching the exception, logging {{{}"Log
rolling failed"{}}}, and calling {{abort(...)}} on the RegionServer — a full RS
self-abort, WAL splitting, and reassignment of every region the RS was
carrying. Observed 9 times over a 68.8h window on a production cluster carrying
300–450+ regions per affected RS, driving the two longest region-in-transition
episodes in that window.
*Root cause*
{{AbstractFSWAL.rollWriterInternal(boolean force)}} logs the newly-rolled WAL's
DataNode pipeline for debugging, _after_ the roll has already succeeded
({{{}replaceWriter{}}} has already installed the new writer):
if (LOG.isDebugEnabled()) \{
LOG.debug("Create new " + implClassName + " writer with pipeline: "
+ FanOutOneBlockAsyncDFSOutputHelper
.getDataNodeInfo(Arrays.stream(getPipeline()).collect(Collectors.toList())));
}
{{}}
{{getPipeline()}} on the sync WAL path ({{{}FSHLog#getPipeline(){}}}) delegates
directly to Hadoop's {{{}DFSOutputStream#getPipeline(){}}}, which can
legitimately return {{{}null{}}}:
// returns the list of targets, if any, that is being currently used.
@VisibleForTesting
public synchronized DatanodeInfo[] getPipeline() \{
if (getStreamer().streamerClosed()) {
return null;
}
DatanodeInfo[] currentNodes = getStreamer().getNodes();
if (currentNodes == null) \{
return null;
}
...
}
{{{}{}}}This is a documented, expected condition ("if any"), not an error: the
underlying {{DataStreamer}} has no current pipeline before the first block is
allocated, between blocks ({{{}DataStreamer#endBlock(){}}} resets {{nodes}} to
{{{}null{}}}), or on a transient failed block-create retry. There is no
non-null alternative accessor on {{{}DFSOutputStream{}}}/{{{}DataStreamer{}}}.
{{Arrays.stream(null)}} throws NPE (unlike {{{}Arrays.toString(null){}}}, which
returns the string {{{}"null"{}}}). Because the debug-log statement sits inside
a try block explicitly commented "Any exception from here on is catastrophic,
non-recoverable, so we currently abort," the NPE is treated as a genuine roll
failure and propagates to {{{}AbstractWALRoller{}}}, which aborts the
RegionServer — even though the roll itself had already succeeded and only the
diagnostic log line failed to format.
*Regression*
Introduced by HBASE-28775 ("Change the output of DatanodeInfo in the log to the
hostname of the datanode", commit 53944cfc930a), which replaced the previously
null-tolerant {{Arrays.toString(getPipeline())}} with the null-intolerant
{{Arrays.stream(getPipeline()).collect(Collectors.toList())}} fed into
{{{}FanOutOneBlockAsyncDFSOutputHelper#getDataNodeInfo{}}}. Confirmed present,
unfixed, on {{master}} and {{{}branch-3{}}}.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
