[jira] [Created] (HBASE-30346) NPE in AbstractFSWAL WAL-roll debug logging aborts RegionServer when DFSOutputStream#getPipeline() legitimately returns null

["Aman Poonia (Jira)" <ji...@apache.org>]

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)