[
https://issues.apache.org/jira/browse/HDDS-16982?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Siyao Meng updated HDDS-16982:
------------------------------
Description:
When another test runs after
{{TestFailureHandlingByClient#testBlockWritesWithDnFailures}}, the forked test
JVM often exits while {{restartDownDataNodes}} restarts one of the datanodes
that test shut down:
{code}
[ERROR] ExecutionException The forked VM terminated without properly saying
goodbye. VM crash or System.exit called?
[ERROR] Crashed tests:
[ERROR] org.apache.hadoop.ozone.client.rpc.TestFailureHandlingByClient
{code}
{code}
ERROR ozoneimpl.OzoneContainer (HddsVolumeUtil.java:loadVolume(114)) - Load db
store for HddsVolume .../datanode-7/data-0/hdds failed
java.io.IOException: Can't init db instance under path
.../datanode-7/data-0/hdds/<clusterId>/DS-.../container.db for volume DS-...
Caused by: org.rocksdb.RocksDBException: lock hold by current process, acquire
time 1791878330 acquiring thread 140218196805312: .../container.db/LOCK: No
locks available
ERROR volume.HddsVolume (HddsVolume.java:check(289)) - Volume
.../datanode-7/data-0/hdds failed to access RocksDB: RocksDB parent directory
is null, the volume might not have been loaded properly.
ERROR statemachine.DatanodeStateMachine
(DatanodeStateMachine.java:handleFatalVolumeFailures(410)) -
DatanodeStateMachine Shutdown due to too many bad volumes, ...
INFO util.ExitUtil (ExitUtil.java:terminate(241)) - Exiting with status 1:
ExitException
{code}
h3. Root cause
HDDS-16224 changed {{testBlockCountOnFailures}} to read block data through
{{waitForBlockContainer}}, which polls every datanode in
{{cluster.getHddsDatanodes()}} and calls {{BlockUtils.getDB}} on each replica.
That list still contains the two datanodes {{testBlockWritesWithDnFailures}}
has just shut down. Their in memory {{ContainerSet}} still has the container,
but their per volume RocksDB was already closed and removed from
{{DatanodeStoreCache}} during shutdown. {{DatanodeStoreCache.getDB}} silently
opens a new instance on a cache miss and keeps it in the static cache, so the
test reopens the stopped datanode's {{container.db}} and holds its {{LOCK}}.
When {{restartDownDataNodes}} then restarts that datanode,
{{HddsVolume.loadDbStore}} opens the same DB uncached, fails with {{lock hold
by current process}}, and sets {{dbLoadFailure}}. The following volume check
fails the only data volume, and
{{DatanodeStateMachine.handleFatalVolumeFailures}} calls
{{ExitUtil.terminate}}, which exits the test JVM.
Evidence from 200 iterations of the class (two flaky test check runs, with and
without HDDS-16967): all 145 crashes show this lock error, every one right
after {{testBlockWritesWithDnFailures}}, and the RocksDB lock holder's acquire
time is within one second of the failed open in every case, i.e. the lock is
taken during the test, not by the old datanode instance.
The full integration split rarely hits it, because
{{testBlockWritesWithDnFailures}} is the last test it runs in this class, so no
restart follows. But since HDDS-15749, CI for a PR that changes this class runs
it by name, which also includes the {{@Flaky}}
{{testDatanodeExclusionWithMajorityCommit}} after
{{testBlockWritesWithDnFailures}}, so the crash now fails CI for any such PR
(e.g. https://github.com/apache/ozone/actions/runs/38507001821/job/115669813106
for HDDS-16967). The flaky test check workflow runs the class the same way, and
about 73 of 100 iterations crash on master.
h3. Fix
Skip stopped datanodes in {{waitForBlockContainer}} ({{if (dn.isStopped())
continue;}}), so the test never reopens the DB of a datanode it has shut down.
- https://github.com/smengcl/hadoop-ozone/actions/runs/38376787117 (master)
- https://github.com/smengcl/hadoop-ozone/actions/runs/38362647581 (with
HDDS-16967)
was:
When another test runs after
{{TestFailureHandlingByClient#testBlockWritesWithDnFailures}}, the forked test
JVM often exits while {{restartDownDataNodes}} restarts one of the datanodes
that test shut down:
{code}
[ERROR] ExecutionException The forked VM terminated without properly saying
goodbye. VM crash or System.exit called?
[ERROR] Crashed tests:
[ERROR] org.apache.hadoop.ozone.client.rpc.TestFailureHandlingByClient
{code}
{code}
ERROR ozoneimpl.OzoneContainer (HddsVolumeUtil.java:loadVolume(114)) - Load db
store for HddsVolume .../datanode-7/data-0/hdds failed
java.io.IOException: Can't init db instance under path
.../datanode-7/data-0/hdds/<clusterId>/DS-.../container.db for volume DS-...
Caused by: org.rocksdb.RocksDBException: lock hold by current process, acquire
time 1791878330 acquiring thread 140218196805312: .../container.db/LOCK: No
locks available
ERROR volume.HddsVolume (HddsVolume.java:check(289)) - Volume
.../datanode-7/data-0/hdds failed to access RocksDB: RocksDB parent directory
is null, the volume might not have been loaded properly.
ERROR statemachine.DatanodeStateMachine
(DatanodeStateMachine.java:handleFatalVolumeFailures(410)) -
DatanodeStateMachine Shutdown due to too many bad volumes, ...
INFO util.ExitUtil (ExitUtil.java:terminate(241)) - Exiting with status 1:
ExitException
{code}
h3. Root cause
HDDS-16224 changed {{testBlockCountOnFailures}} to read block data through
{{waitForBlockContainer}}, which polls every datanode in
{{cluster.getHddsDatanodes()}} and calls {{BlockUtils.getDB}} on each replica.
That list still contains the two datanodes {{testBlockWritesWithDnFailures}}
has just shut down. Their in memory {{ContainerSet}} still has the container,
but their per volume RocksDB was already closed and removed from
{{DatanodeStoreCache}} during shutdown. {{DatanodeStoreCache.getDB}} silently
opens a new instance on a cache miss and keeps it in the static cache, so the
test reopens the stopped datanode's {{container.db}} and holds its {{LOCK}}.
When {{restartDownDataNodes}} then restarts that datanode,
{{HddsVolume.loadDbStore}} opens the same DB uncached, fails with {{lock hold
by current process}}, and sets {{dbLoadFailure}}. The following volume check
fails the only data volume, and
{{DatanodeStateMachine.handleFatalVolumeFailures}} calls
{{ExitUtil.terminate}}, which exits the test JVM.
Evidence from 200 iterations of the class (two flaky test check runs, with and
without HDDS-16967): all 145 crashes show this lock error, every one right
after {{testBlockWritesWithDnFailures}}, and the RocksDB lock holder's acquire
time is within one second of the failed open in every case, i.e. the lock is
taken during the test, not by the old datanode instance.
The regular integration split rarely hits it because
{{testBlockWritesWithDnFailures}} is the last test it runs in this class, so no
restart follows. It shows up whenever the whole class runs with {{-Dtest}},
which also includes the {{@Flaky}} {{testDatanodeExclusionWithMajorityCommit}},
e.g. in the flaky test check workflow (about 73 of 100 iterations crash on
master).
h3. Fix
Skip stopped datanodes in {{waitForBlockContainer}} ({{if (dn.isStopped())
continue;}}), so the test never reopens the DB of a datanode it has shut down.
- https://github.com/smengcl/hadoop-ozone/actions/runs/38376787117 (master)
- https://github.com/smengcl/hadoop-ozone/actions/runs/38362647581 (with
HDDS-16967)
> TestFailureHandlingByClient crashes the test JVM when a test runs after
> testBlockWritesWithDnFailures
> -----------------------------------------------------------------------------------------------------
>
> Key: HDDS-16982
> URL: https://issues.apache.org/jira/browse/HDDS-16982
> Project: Apache Ozone
> Issue Type: Sub-task
> Components: test
> Reporter: Siyao Meng
> Assignee: Siyao Meng
> Priority: Major
>
> When another test runs after
> {{TestFailureHandlingByClient#testBlockWritesWithDnFailures}}, the forked
> test JVM often exits while {{restartDownDataNodes}} restarts one of the
> datanodes that test shut down:
> {code}
> [ERROR] ExecutionException The forked VM terminated without properly saying
> goodbye. VM crash or System.exit called?
> [ERROR] Crashed tests:
> [ERROR] org.apache.hadoop.ozone.client.rpc.TestFailureHandlingByClient
> {code}
> {code}
> ERROR ozoneimpl.OzoneContainer (HddsVolumeUtil.java:loadVolume(114)) - Load
> db store for HddsVolume .../datanode-7/data-0/hdds failed
> java.io.IOException: Can't init db instance under path
> .../datanode-7/data-0/hdds/<clusterId>/DS-.../container.db for volume DS-...
> Caused by: org.rocksdb.RocksDBException: lock hold by current process,
> acquire time 1791878330 acquiring thread 140218196805312:
> .../container.db/LOCK: No locks available
> ERROR volume.HddsVolume (HddsVolume.java:check(289)) - Volume
> .../datanode-7/data-0/hdds failed to access RocksDB: RocksDB parent directory
> is null, the volume might not have been loaded properly.
> ERROR statemachine.DatanodeStateMachine
> (DatanodeStateMachine.java:handleFatalVolumeFailures(410)) -
> DatanodeStateMachine Shutdown due to too many bad volumes, ...
> INFO util.ExitUtil (ExitUtil.java:terminate(241)) - Exiting with status 1:
> ExitException
> {code}
> h3. Root cause
> HDDS-16224 changed {{testBlockCountOnFailures}} to read block data through
> {{waitForBlockContainer}}, which polls every datanode in
> {{cluster.getHddsDatanodes()}} and calls {{BlockUtils.getDB}} on each
> replica. That list still contains the two datanodes
> {{testBlockWritesWithDnFailures}} has just shut down. Their in memory
> {{ContainerSet}} still has the container, but their per volume RocksDB was
> already closed and removed from {{DatanodeStoreCache}} during shutdown.
> {{DatanodeStoreCache.getDB}} silently opens a new instance on a cache miss
> and keeps it in the static cache, so the test reopens the stopped datanode's
> {{container.db}} and holds its {{LOCK}}.
> When {{restartDownDataNodes}} then restarts that datanode,
> {{HddsVolume.loadDbStore}} opens the same DB uncached, fails with {{lock hold
> by current process}}, and sets {{dbLoadFailure}}. The following volume check
> fails the only data volume, and
> {{DatanodeStateMachine.handleFatalVolumeFailures}} calls
> {{ExitUtil.terminate}}, which exits the test JVM.
> Evidence from 200 iterations of the class (two flaky test check runs, with
> and without HDDS-16967): all 145 crashes show this lock error, every one
> right after {{testBlockWritesWithDnFailures}}, and the RocksDB lock holder's
> acquire time is within one second of the failed open in every case, i.e. the
> lock is taken during the test, not by the old datanode instance.
> The full integration split rarely hits it, because
> {{testBlockWritesWithDnFailures}} is the last test it runs in this class, so
> no restart follows. But since HDDS-15749, CI for a PR that changes this class
> runs it by name, which also includes the {{@Flaky}}
> {{testDatanodeExclusionWithMajorityCommit}} after
> {{testBlockWritesWithDnFailures}}, so the crash now fails CI for any such PR
> (e.g.
> https://github.com/apache/ozone/actions/runs/38507001821/job/115669813106 for
> HDDS-16967). The flaky test check workflow runs the class the same way, and
> about 73 of 100 iterations crash on master.
> h3. Fix
> Skip stopped datanodes in {{waitForBlockContainer}} ({{if (dn.isStopped())
> continue;}}), so the test never reopens the DB of a datanode it has shut down.
> - https://github.com/smengcl/hadoop-ozone/actions/runs/38376787117 (master)
> - https://github.com/smengcl/hadoop-ozone/actions/runs/38362647581 (with
> HDDS-16967)
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
