[
https://issues.apache.org/jira/browse/HBASE-30346?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Aman Poonia updated HBASE-30346:
--------------------------------
Description:
*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.
was:
*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{}}}.
> 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
> Affects Versions: 3.0.0, 4.0.0-alpha-1, 2.6.7
> Reporter: Aman Poonia
> Assignee: Aman Poonia
> Priority: Major
>
> *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)
