[HDDS-3894] Noisy log at OM when the requested sequence is not written into DB

• Type: Bug
• Status: Resolved
• Priority: Minor
• Resolution: Won't Fix
• Component/s: Ozone Manager, Ozone Recon
• Assignee: Mohammad Arafat Khan
• Reporter: Rakesh Radhakrishnan
• Created: 29/Jun/20 05:21
• Updated: 13/Dec/22 18:14
• Resolved: 13/Dec/22 18:14

Description

Too many logs at OM, which is noisy. It looks like Recon is making this call to OM to update the delta info. OM can ignore this exception and reduce the log priority to DEBUG or so.

Ozone-om.log

2020-06-26 10:02:52,963 INFO org.apache.ratis.server.raftlog.segmented.SegmentedRaftLogWorker: 5dca58f5-6231-4858-9589-4e64b1435aa4@group-C5BA1605619E-SegmentedRaftLogWorker: Rolled log segment from /data/3/jun27_new1/hadoop-ozone/om/ratis2/bf265839-605b-3f16-9796-c5ba1605619e/current/log_inprogress_106536 to /data/3/jun27_new1/hadoop-ozone/om/ratis2/bf265839-605b-3f16-9796-c5ba1605619e/current/log_106536-106603
2020-06-26 10:02:52,982 INFO org.apache.ratis.server.raftlog.segmented.SegmentedRaftLogWorker: 5dca58f5-6231-4858-9589-4e64b1435aa4@group-C5BA1605619E-SegmentedRaftLogWorker: created new log segment /data/3/jun27_new1/hadoop-ozone/om/ratis2/bf265839-605b-3f16-9796-c5ba1605619e/current/log_inprogress_106604
2020-06-26 10:09:54,828 ERROR org.apache.hadoop.hdds.utils.db.RDBStore: Unable to get delta updates since sequenceNumber 11268864
org.rocksdb.RocksDBException: Requested sequence not yet written in the db
        at org.rocksdb.RocksDB.getUpdatesSince(Native Method)
        at org.rocksdb.RocksDB.getUpdatesSince(RocksDB.java:3588)
        at org.apache.hadoop.hdds.utils.db.RDBStore.getUpdatesSince(RDBStore.java:339)
        at org.apache.hadoop.ozone.om.OzoneManager.getDBUpdates(OzoneManager.java:3422)
        at org.apache.hadoop.ozone.protocolPB.OzoneManagerRequestHandler.getOMDBUpdates(OzoneManagerRequestHandler.java:257)
        at org.apache.hadoop.ozone.protocolPB.OzoneManagerRequestHandler.handleReadRequest(OzoneManagerRequestHandler.java:194)
        at org.apache.hadoop.ozone.protocolPB.OzoneManagerProtocolServerSideTranslatorPB.submitReadRequestToOM(OzoneManagerProtocolServerSideTranslatorPB.java:171)
        at org.apache.hadoop.ozone.protocolPB.OzoneManagerProtocolServerSideTranslatorPB.processRequest(OzoneManagerProtocolServerSideTranslatorPB.java:109)
        at org.apache.hadoop.hdds.server.OzoneProtocolMessageDispatcher.processRequest(OzoneProtocolMessageDispatcher.java:74)
        at org.apache.hadoop.ozone.protocolPB.OzoneManagerProtocolServerSideTranslatorPB.submitRequest(OzoneManagerProtocolServerSideTranslatorPB.java:99)
        at org.apache.hadoop.ozone.protocol.proto.OzoneManagerProtocolProtos$OzoneManagerService$2.callBlockingMethod(OzoneManagerProtocolProtos.java)
        at org.apache.hadoop.ipc.ProtobufRpcEngine$Server$ProtoBufRpcInvoker.call(ProtobufRpcEngine.java:528)
        at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:1070)
        at org.apache.hadoop.ipc.Server$RpcCall.run(Server.java:985)
        at org.apache.hadoop.ipc.Server$RpcCall.run(Server.java:913)
        at java.security.AccessController.doPrivileged(Native Method)
        at javax.security.auth.Subject.doAs(Subject.java:422)
        at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1876)
        at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2882)
2020-06-26 10:11:08,442 INFO org.apache.ratis.server.raftlog.segmented.SegmentedRaftLogWorker: 5dca58f5-6231-4858-9589-4e64b1435aa4@group-C5BA1605619E-SegmentedRaftLogWorker: Rolling segment log-106604_106637 to index:106637
2020-06-26 10:11:08,443 INFO org.apache.ratis.server.raftlog.segmented.SegmentedRaftLogWorker: 5dca58f5-6231-4858-9589-4e64b1435aa4@group-C5BA1605619E-SegmentedRaftLogWorker: Rolling segment log-106638_106654 to index:106654
2020-06-26 10:11:08,444 INFO org.apache.ratis.server.raftlog.segmented.SegmentedRaftLogWorker: 5dca58f5-6231-4858-9589-4e64b1435aa4@group-C5BA1605619E-SegmentedRaftLogWorker: Rolling segment log-106655_106671 to index:106671

Recon.log

2020-06-26 10:08:55,883 INFO org.apache.hadoop.ozone.recon.fsck.MissingContainerTask: Missing Container task Thread took 88 milliseconds for processing 0 containers.
2020-06-26 10:09:54,824 INFO org.apache.hadoop.ozone.recon.spi.impl.OzoneManagerServiceProviderImpl: Syncing data from Ozone Manager.
2020-06-26 10:09:54,824 INFO org.apache.hadoop.ozone.recon.spi.impl.OzoneManagerServiceProviderImpl: Obtaining delta updates from Ozone Manager
2020-06-26 10:09:54,828 INFO org.apache.hadoop.ozone.recon.spi.impl.OzoneManagerServiceProviderImpl: Number of updates received from OM : 0