[HDDS-4018] Datanode log spammed by NPE

• Type: Bug
• Status: Resolved
• Priority: Blocker
• Resolution: Fixed
• Affects Version/s: 1.0.0
• Fix Version/s: 1.0.0, 1.1.0
• Component/s: Ozone Datanode
• Labels: pull-request-available
• Target Version/s: 1.0.0
• Assignee: Attila Doroszlai
• Reporter: Attila Doroszlai
• Created: 23/Jul/20 12:29
• Updated: 27/Jul/20 02:41
• Resolved: 24/Jul/20 06:00

Description

datanode_1  | 2020-07-22 13:11:47,845 [Datanode State Machine Thread - 0] WARN statemachine.StateContext: No available thread in pool for past 2 seconds.
datanode_1  | 2020-07-22 13:11:47,846 [Datanode State Machine Thread - 0] ERROR statemachine.DatanodeStateMachine: Unable to finish the execution.
datanode_1  | java.lang.NullPointerException
datanode_1  |   at org.apache.hadoop.ozone.container.common.states.datanode.RunningDatanodeState.await(RunningDatanodeState.java:218)
datanode_1  |   at org.apache.hadoop.ozone.container.common.states.datanode.RunningDatanodeState.await(RunningDatanodeState.java:50)
datanode_1  |   at org.apache.hadoop.ozone.container.common.statemachine.StateContext.execute(StateContext.java:451)
datanode_1  |   at org.apache.hadoop.ozone.container.common.statemachine.DatanodeStateMachine.start(DatanodeStateMachine.java:225)
datanode_1  |   at org.apache.hadoop.ozone.container.common.statemachine.DatanodeStateMachine.lambda$startDaemon$0(DatanodeStateMachine.java:396)
datanode_1  |   at java.base/java.lang.Thread.run(Thread.java:834)
datanode_1  | 2020-07-22 13:11:47,847 [Datanode State Machine Thread - 0] ERROR statemachine.DatanodeStateMachine: Unable to finish the execution.
datanode_1  | java.lang.NullPointerException
datanode_1  |   at org.apache.hadoop.ozone.container.common.states.datanode.RunningDatanodeState.await(RunningDatanodeState.java:218)
datanode_1  |   at org.apache.hadoop.ozone.container.common.states.datanode.RunningDatanodeState.await(RunningDatanodeState.java:50)
datanode_1  |   at org.apache.hadoop.ozone.container.common.statemachine.StateContext.execute(StateContext.java:451)
datanode_1  |   at org.apache.hadoop.ozone.container.common.statemachine.DatanodeStateMachine.start(DatanodeStateMachine.java:225)
datanode_1  |   at org.apache.hadoop.ozone.container.common.statemachine.DatanodeStateMachine.lambda$startDaemon$0(DatanodeStateMachine.java:396)
datanode_1  |   at java.base/java.lang.Thread.run(Thread.java:834)
datanode_1  | 2020-07-22 13:11:47,848 [Datanode State Machine Thread - 0] ERROR statemachine.DatanodeStateMachine: Unable to finish the execution.
datanode_1  | java.lang.NullPointerException
datanode_1  |   at org.apache.hadoop.ozone.container.common.states.datanode.RunningDatanodeState.await(RunningDatanodeState.java:218)
datanode_1  |   at org.apache.hadoop.ozone.container.common.states.datanode.RunningDatanodeState.await(RunningDatanodeState.java:50)
datanode_1  |   at org.apache.hadoop.ozone.container.common.statemachine.StateContext.execute(StateContext.java:451)
datanode_1  |   at org.apache.hadoop.ozone.container.common.statemachine.DatanodeStateMachine.start(DatanodeStateMachine.java:225)
datanode_1  |   at org.apache.hadoop.ozone.container.common.statemachine.DatanodeStateMachine.lambda$startDaemon$0(DatanodeStateMachine.java:396)
datanode_1  |   at java.base/java.lang.Thread.run(Thread.java:834)
datanode_1  | 2020-07-22 13:11:47,848 [Datanode State Machine Thread - 0] ERROR statemachine.DatanodeStateMachine: Unable to finish the execution.
datanode_1  | java.lang.NullPointerException
datanode_1  |   at org.apache.hadoop.ozone.container.common.states.datanode.RunningDatanodeState.await(RunningDatanodeState.java:218)
datanode_1  |   at org.apache.hadoop.ozone.container.common.states.datanode.RunningDatanodeState.await(RunningDatanodeState.java:50)
datanode_1  |   at org.apache.hadoop.ozone.container.common.statemachine.StateContext.execute(StateContext.java:451)
datanode_1  |   at org.apache.hadoop.ozone.container.common.statemachine.DatanodeStateMachine.start(DatanodeStateMachine.java:225)
datanode_1  |   at org.apache.hadoop.ozone.container.common.statemachine.DatanodeStateMachine.lambda$startDaemon$0(DatanodeStateMachine.java:396)
datanode_1  |   at java.base/java.lang.Thread.run(Thread.java:834)
datanode_1  | 2020-07-22 13:11:47,851 [Datanode State Machine Thread - 0] ERROR statemachine.DatanodeStateMachine: Unable to finish the execution.
datanode_1  | java.lang.NullPointerException
datanode_1  |   at org.apache.hadoop.ozone.container.common.states.datanode.RunningDatanodeState.await(RunningDatanodeState.java:218)
datanode_1  |   at org.apache.hadoop.ozone.container.common.states.datanode.RunningDatanodeState.await(RunningDatanodeState.java:50)
datanode_1  |   at org.apache.hadoop.ozone.container.common.statemachine.StateContext.execute(StateContext.java:451)
datanode_1  |   at org.apache.hadoop.ozone.container.common.statemachine.DatanodeStateMachine.start(DatanodeStateMachine.java:225)
datanode_1  |   at org.apache.hadoop.ozone.container.common.statemachine.DatanodeStateMachine.lambda$startDaemon$0(DatanodeStateMachine.java:396)
datanode_1  |   at java.base/java.lang.Thread.run(Thread.java:834)
...
thread in pool for past 22 seconds.
datanode_1  | 2020-07-22 13:11:47,854 [Datanode State Machine Thread - 0] ERROR statemachine.DatanodeStateMachine: Unable to finish the execution.
datanode_1  | java.lang.NullPointerException
datanode_1  |   at org.apache.hadoop.ozone.container.common.states.datanode.RunningDatanodeState.await(RunningDatanodeState.java:218)
datanode_1  |   at org.apache.hadoop.ozone.container.common.states.datanode.RunningDatanodeState.await(RunningDatanodeState.java:50)
datanode_1  |   at org.apache.hadoop.ozone.container.common.statemachine.StateContext.execute(StateContext.java:451)
datanode_1  |   at org.apache.hadoop.ozone.container.common.statemachine.DatanodeStateMachine.start(DatanodeStateMachine.java:225)
datanode_1  |   at org.apache.hadoop.ozone.container.common.statemachine.DatanodeStateMachine.lambda$startDaemon$0(DatanodeStateMachine.java:396)
datanode_1  |   at java.base/java.lang.Thread.run(Thread.java:834)

This increases acceptance test logs to several hundred MBs.

Issue Links

• is caused by: HDDS-3933 Fix memory leak because of too many Datanode State Machine Thread
• links to: GitHub Pull Request #1250