[ https://issues.apache.org/jira/browse/HDDS-543?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16642083#comment-16642083 ]
Mukul Kumar Singh commented on HDDS-543: ---------------------------------------- This is happening because on Datanode restart, the Ratis tries to applies logs to the state machine from the start. Re-applying these log entries will result in the above exception. > datanode service start throwing NullPointerException > ---------------------------------------------------- > > Key: HDDS-543 > URL: https://issues.apache.org/jira/browse/HDDS-543 > Project: Hadoop Distributed Data Store > Issue Type: Bug > Reporter: Nilotpal Nandi > Assignee: Mukul Kumar Singh > Priority: Critical > Attachments: all-node-ozone-logs-1537784799.tar.gz > > > steps taken : > ------------------- > # Stopped one of the nodes in 6 node cluster while write operation was > running. > # Tried to start datanode after sometime. Datanode failed to start > > ozone version : > --------------------- > > {noformat} > Source code repository g...@github.com:apache/hadoop.git -r > 968082ffa5d9e50ed8538f653c375edd1b8feea5 > Compiled by elek on 2018-09-19T20:57Z > Compiled with protoc 2.5.0 > From source with checksum efbdeabb5670d69d9efde85846e4ee98 > Using HDDS 0.2.1-alpha > Source code repository g...@github.com:apache/hadoop.git -r > 968082ffa5d9e50ed8538f653c375edd1b8feea5 > Compiled by elek on 2018-09-19T20:56Z > Compiled with protoc 2.5.0 > From source with checksum 8bf78cff4b73c95d486da5b21053ef > > {noformat} > > console log : > -------------------- > > {noformat} > 2018-09-24 09:53:54,913 INFO impl.RaftServerImpl: > 9348f4cb-0bd3-41e7-b1c6-c22463a20c09: set configuration 0: > [0ba4abe0-c8d1-4d6c-8d28-ebfa08fb84c9:172.27.18.18:9858, > 3d6c8b2c-f1d2-4425-a577-b9ef5dc7c634:172.27.80.23:9858, > 9348f4cb-0bd3-41e7-b1c6-c22463a20c09:172.27.23.161:9858], old=null at 0 > Sep 24, 2018 9:53:55 AM > com.sun.jersey.server.impl.application.WebApplicationImpl _initiate > INFO: Initiating Jersey application, version 'Jersey: 1.19 02/11/2015 03:25 > AM' > 2018-09-24 09:53:55,968 [main] INFO - Listening HDDS REST traffic on > /0.0.0.0:9880 > 2018-09-24 09:53:55,969 [main] INFO - Started plug-in > org.apache.hadoop.ozone.web.OzoneHddsDatanodeService@2fa3be26 > 2018-09-24 09:53:55,975 [Datanode State Machine Thread - 0] INFO - Attempting > to start container services. > 2018-09-24 09:53:56,171 [Datanode State Machine Thread - 0] INFO - Starting > XceiverServerRatis 9348f4cb-0bd3-41e7-b1c6-c22463a20c09 at port 9858 > 2018-09-24 09:53:56,193 [Datanode State Machine Thread - 0] ERROR - Unable to > start the DatanodeState Machine > java.io.IOException: Premature EOF from inputStream > at org.apache.ratis.util.IOUtils.readFully(IOUtils.java:100) > at org.apache.ratis.server.storage.LogReader.decodeEntry(LogReader.java:250) > at org.apache.ratis.server.storage.LogReader.readEntry(LogReader.java:155) > at > org.apache.ratis.server.storage.LogInputStream.nextEntry(LogInputStream.java:128) > at > org.apache.ratis.server.storage.LogSegment.readSegmentFile(LogSegment.java:110) > at > org.apache.ratis.server.storage.LogSegment.loadSegment(LogSegment.java:132) > at > org.apache.ratis.server.storage.RaftLogCache.loadSegment(RaftLogCache.java:110) > at > org.apache.ratis.server.storage.SegmentedRaftLog.loadLogSegments(SegmentedRaftLog.java:155) > at > org.apache.ratis.server.storage.SegmentedRaftLog.open(SegmentedRaftLog.java:123) > at org.apache.ratis.server.impl.ServerState.initLog(ServerState.java:162) > at org.apache.ratis.server.impl.ServerState.<init>(ServerState.java:110) > at > org.apache.ratis.server.impl.RaftServerImpl.<init>(RaftServerImpl.java:106) > at > org.apache.ratis.server.impl.RaftServerProxy.lambda$newRaftServerImpl$0(RaftServerProxy.java:191) > at > java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1590) > at > java.util.concurrent.CompletableFuture$AsyncSupply.exec(CompletableFuture.java:1582) > at java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:289) > at > java.util.concurrent.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1056) > at java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1692) > at > java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:157) > 2018-09-24 09:53:56,195 [main] ERROR - Exception in HddsDatanodeService. > java.lang.NullPointerException > at > org.apache.hadoop.ozone.container.common.statemachine.DatanodeStateMachine.join(DatanodeStateMachine.java:332) > at > org.apache.hadoop.ozone.HddsDatanodeService.join(HddsDatanodeService.java:191) > at > org.apache.hadoop.ozone.HddsDatanodeService.main(HddsDatanodeService.java:250) > 2018-09-24 09:53:56,198 INFO util.ExitUtil: Exiting with status 1: > java.lang.NullPointerException > 2018-09-24 09:53:56,201 WARN fs.CachingGetSpaceUsed: Thread Interrupted > waiting to refresh disk information: sleep interrupted > 2018-09-24 09:53:56,201 [shutdown-hook-0] INFO - SHUTDOWN_MSG: > /************************************************************ > SHUTDOWN_MSG: Shutting down HddsDatanodeService at > ctr-e138-1518143905142-468367-01-000003.hwx.site/172.27.23.161 > > {noformat} > > datanode.log > ---------------------- > {noformat} > 2018-09-24 09:42:41,305 ERROR org.apache.ratis.server.impl.RaftServerImpl: > 9348f4cb-0bd3-41e7-b1c6-c22463a20c09: applyTransaction failed for index:2 > proto:(t:2, i:2)SMLOGENTRY, client-DBCE827E62E6, cid=1 > 2018-09-24 09:42:41,307 ERROR > org.apache.ratis.server.impl.StateMachineUpdater: Terminating with exit > status 2: StateMachineUpdater-9348f4cb-0bd3-41e7-b1c6-c22463a20c09: the > StateMachineUpdater hits Throwable > java.lang.NullPointerException > at > org.apache.hadoop.ozone.container.common.transport.server.ratis.ContainerStateMachine$StateMachineHelper.handleChunkCommit(ContainerStateMachine.java:561) > at > org.apache.hadoop.ozone.container.common.transport.server.ratis.ContainerStateMachine$StateMachineHelper.executeContainerCommand(ContainerStateMachine.java:615) > at > org.apache.hadoop.ozone.container.common.transport.server.ratis.ContainerStateMachine.applyTransaction(ContainerStateMachine.java:394) > at > org.apache.ratis.server.impl.RaftServerImpl.applyLogToStateMachine(RaftServerImpl.java:1150) > at > org.apache.ratis.server.impl.StateMachineUpdater.run(StateMachineUpdater.java:148) > at java.lang.Thread.run(Thread.java:745) > 2018-09-24 09:42:41,312 WARN org.apache.hadoop.fs.CachingGetSpaceUsed: Thread > Interrupted waiting to refresh disk information: sleep interrupted > 2018-09-24 09:53:38,901 INFO org.apache.hadoop.metrics2.impl.MetricsConfig: > Loaded properties from hadoop-metrics2.properties > 2018-09-24 09:53:39,013 INFO > org.apache.hadoop.metrics2.impl.MetricsSystemImpl: Scheduled Metric snapshot > period at 10 second(s). > 2018-09-24 09:53:39,013 INFO > org.apache.hadoop.metrics2.impl.MetricsSystemImpl: HddsDatanode metrics > system started > 2018-09-24 09:53:39,056 INFO > org.apache.hadoop.conf.Configuration.deprecation: No unit for > ozone.scm.heartbeat.rpc-timeout(1000) assuming MILLISECONDS > 2018-09-24 09:53:39,069 INFO > org.apache.hadoop.conf.Configuration.deprecation: No unit for > hdds.write.lock.reporting.threshold.ms(5000) assuming MILLISECONDS > 2018-09-24 09:53:39,069 INFO > org.apache.hadoop.conf.Configuration.deprecation: No unit for > hdds.lock.suppress.warning.interval.ms(10000) assuming MILLISECONDS > 2018-09-24 09:53:39,751 WARN org.apache.hadoop.hdds.scm.HddsServerUtil: > Storage directory for Ratis is not configured.Mapping Ratis storage under > /data/disk1/ozone/meta/ratis. It is a good idea to map this to an SSD disk. > 2018-09-24 09:53:39,783 INFO org.apache.ratis.server.impl.RaftServerProxy: > raft.rpc.type = GRPC (default) > 2018-09-24 09:53:39,793 INFO org.apache.ratis.grpc.GrpcConfigKeys$Server: > raft.grpc.server.port = 9858 (custom) > 2018-09-24 09:53:39,793 INFO org.apache.ratis.grpc.RaftGRpcService: > raft.grpc.message.size.max = 167772160 (custom) > 2018-09-24 09:53:39,795 INFO org.apache.ratis.server.RaftServerConfigKeys: > raft.server.log.appender.buffer.capacity = 134217728 (custom) > 2018-09-24 09:53:39,795 INFO org.apache.ratis.grpc.RaftGRpcService: > raft.grpc.flow.control.window = 1MB (=1048576) (default) > 2018-09-24 09:53:39,796 INFO org.apache.ratis.server.RaftServerConfigKeys: > raft.server.rpc.request.timeout = 3000 ms (custom) > 2018-09-24 09:53:39,835 INFO org.apache.ratis.server.RaftServerConfigKeys: > raft.server.storage.dir = /data/disk1/ozone/meta/ratis (custom) > 2018-09-24 09:53:39,836 INFO org.apache.ratis.server.impl.RaftServerProxy: > 9348f4cb-0bd3-41e7-b1c6-c22463a20c09: found a subdirectory > /data/disk1/ozone/meta/ratis/6ff6479b-11f4-456f-b46e-85804b25606d > 2018-09-24 09:53:39,838 INFO org.apache.ratis.server.impl.RaftServerProxy: > 9348f4cb-0bd3-41e7-b1c6-c22463a20c09: addNew group-85804B25606D:[] returns > group-85804B25606D:java.util.concurrent.CompletableFuture@74e28667[Not > completed] > 2018-09-24 09:53:39,850 INFO org.apache.ratis.server.RaftServerConfigKeys: > raft.server.rpc.timeout.min = 1 s (custom) > 2018-09-24 09:53:39,850 INFO org.apache.ratis.server.RaftServerConfigKeys: > raft.server.rpc.timeout.max = 1200 ms (custom) > 2018-09-24 09:53:39,850 INFO org.apache.ratis.server.RaftServerConfigKeys: > raft.server.rpcslowness.timeout = 120 s (custom) > 2018-09-24 09:53:39,868 INFO org.apache.ratis.server.impl.RaftServerImpl: > 9348f4cb-0bd3-41e7-b1c6-c22463a20c09: ConfigurationManager, init=-1: [], > old=null, confs=<EMPTY_MAP> > 2018-09-24 09:53:39,868 INFO org.apache.ratis.server.RaftServerConfigKeys: > raft.server.storage.dir = /data/disk1/ozone/meta/ratis (custom) > 2018-09-24 09:53:39,873 INFO > org.apache.ratis.server.storage.RaftStorageDirectory: Lock on > /data/disk1/ozone/meta/ratis/6ff6479b-11f4-456f-b46e-85804b25606d/in_use.lock > acquired by nodename 3792...@ctr-e138-1518143905142-468367-01-000003.hwx.site > 2018-09-24 09:53:39,878 INFO org.apache.ratis.server.RaftServerConfigKeys: > raft.server.leader.election.timeout = 120 s (custom) > 2018-09-24 09:53:39,881 INFO org.apache.ratis.server.RaftServerConfigKeys: > raft.server.log.use.memory = false (default) > 2018-09-24 09:53:39,882 INFO org.apache.ratis.server.RaftServerConfigKeys: > raft.server.log.appender.buffer.capacity = 134217728 (custom) > 2018-09-24 09:53:39,883 INFO org.apache.ratis.server.RaftServerConfigKeys: > raft.server.log.segment.size.max = 1073741824 (custom) > 2018-09-24 09:53:39,886 INFO org.apache.ratis.server.RaftServerConfigKeys: > raft.server.log.segment.cache.num.max = 2 (custom) > 2018-09-24 09:53:39,889 INFO org.apache.ratis.server.storage.RaftLogWorker: > new 9348f4cb-0bd3-41e7-b1c6-c22463a20c09-RaftLogWorker for Storage Directory > /data/disk1/ozone/meta/ratis/6ff6479b-11f4-456f-b46e-85804b25606d > 2018-09-24 09:53:39,889 INFO org.apache.ratis.server.RaftServerConfigKeys: > raft.server.log.segment.size.max = 1073741824 (custom) > 2018-09-24 09:53:39,889 INFO org.apache.ratis.server.RaftServerConfigKeys: > raft.server.log.preallocated.size = 134217728 (custom) > 2018-09-24 09:53:39,890 INFO org.apache.ratis.server.RaftServerConfigKeys: > raft.server.log.write.buffer.size = 33554432 (custom) > 2018-09-24 09:53:39,890 INFO org.apache.ratis.server.RaftServerConfigKeys: > raft.server.log.force.sync.num = 128 (default) > 2018-09-24 09:53:39,925 INFO org.apache.ratis.server.impl.RaftServerImpl: > 9348f4cb-0bd3-41e7-b1c6-c22463a20c09: set configuration 0: > [0ba4abe0-c8d1-4d6c-8d28-ebfa08fb84c9:172.27.18.18:9858, > 3d6c8b2c-f1d2-4425-a577-b9ef5dc7c634:172.27.80.23:9858, > 9348f4cb-0bd3-41e7-b1c6-c22463a20c09:172.27.23.161:9858], old=null at 0 > 2018-09-24 09:53:41,058 INFO org.apache.hadoop.util.ExitUtil: Exiting with > status 1: java.lang.NullPointerException > 2018-09-24 09:53:41,065 WARN org.apache.hadoop.fs.CachingGetSpaceUsed: Thread > Interrupted waiting to refresh disk information: sleep interrupted{noformat} -- This message was sent by Atlassian JIRA (v7.6.3#76005) --------------------------------------------------------------------- To unsubscribe, e-mail: hdfs-issues-unsubscr...@hadoop.apache.org For additional commands, e-mail: hdfs-issues-h...@hadoop.apache.org