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

["Duo Zhang (Jira)" <ji...@apache.org>]

     [ https://issues.apache.org/jira/browse/HBASE-30346?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Duo Zhang resolved HBASE-30346.
-------------------------------
    Fix Version/s: 4.0.0-alpha-1
                   2.7.0
                   3.1.0
                   3.0.1
                   2.6.8
                   2.5.17
     Hadoop Flags: Reviewed
       Resolution: Fixed

Pushed to all active branches.

Thanks [~mnpoonia] for contributing and others for reviewing!

> 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
>          Components: regionserver, wal
>    Affects Versions: 3.0.0, 4.0.0-alpha-1, 2.6.7
>            Reporter: Aman Poonia
>            Assignee: Aman Poonia
>            Priority: Major
>              Labels: pull-request-available
>             Fix For: 4.0.0-alpha-1, 2.7.0, 3.1.0, 3.0.1, 2.6.8, 2.5.17
>
>
>   *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:950)
>         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):
>   {code:java}
>   if (LOG.isDebugEnabled()) {
>     LOG.debug("Create new " + implClassName + " writer with pipeline: "
>       + FanOutOneBlockAsyncDFSOutputHelper
>         .getDataNodeInfo(Arrays.stream(getPipeline()).collect(Collectors.toList())));
>   }
>   {code}
>   {{getPipeline()}} on the sync WAL path ({{FSHLog#getPipeline()}}) delegates directly to Hadoop's {{DFSOutputStream#getPipeline()}}, which can legitimately return {{null}}:
>   {code:java}
>   // 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;
>     }
>     ...
>   }
>   {code}
>   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}}.
>   *Scope / why the fix is safe*
>   Audited every consumer of {{WAL#getPipeline()}}:
>   * All logging call sites in {{AbstractFSWAL}}/{{FSHLog}} except the one above already use {{Arrays.toString(getPipeline())}}, which is null-tolerant.
>   * The only functional (non-logging) consumer, {{AsyncFSWAL#getLogReplication()}}, already calls through {{AsyncFSWAL#getPipeline()}}, which already null-guards its output
>   ({{output != null ? output.getPipeline() : new DatanodeInfo[0]}}).
>   * {{FSHLog#getPipeline()}} is the only implementation that still propagates Hadoop's null, and it is the only call site ({{AbstractFSWAL.java:926}}) that is null-intolerant.
>   It is a pure logging feed with no functional consumer on the sync path.
>   *Note:* the abort-on-roll-failure design itself ({{AbstractWALRoller}}, HBASE-1132) is correct and intentionally not touched by this fix — a genuine roll failure should still
>   abort the RS so its WALs can be split and recovered.
>   *Proposed fix*
>   Normalize {{FSHLog#getPipeline()}} to never return null, matching the contract {{AsyncFSWAL}} already honors:
>   {code:java}
>   DatanodeInfo[] getPipeline() {
>     if (this.hdfs_out != null) {
>       if (this.hdfs_out.getWrappedStream() instanceof DFSOutputStream) {
>         DatanodeInfo[] pipeline =
>           ((DFSOutputStream) this.hdfs_out.getWrappedStream()).getPipeline();
>         if (pipeline != null) {
>           return pipeline;
>         }
>       }
>     }
>     return new DatanodeInfo[0];
>   }
>   {code}
>   This fixes the defect at its source for every current and future caller, rather than patching only the one call site that happens to be null-intolerant today.
>   *Test plan*
>   Added {{TestFSHLog#testGetPipelineDoesNotReturnNullWhenUnderlyingStreamerHasNone}}: mocks {{DFSOutputStream#getPipeline()}} to return null, injects it as {{FSHLog#hdfs_out}},
>   and asserts {{FSHLog#getPipeline()}} returns a non-null, empty array instead of propagating the null. Verified this test fails against the pre-fix code with
>   {{AssertionError: getPipeline() must never return null}} and passes with the fix.



--
This message was sent by Atlassian Jira
(v8.20.10#820010)