WARN o.a.i.d.w.r.TsFileRecoverPerformer:171 - Cannot deserialize TsFileResource ... construct it using TsFileSequenceReader
- Dominant language
- Java
- Stars
- 6.4k
- Forks
- 1.2k
- Avg merge
- 1d 23h
- Merged PRs (30d)
- 115
Description
我们的系统很经常断电(相当于直接拔掉电源)。当插上电源时会自动重启并恢复系统
我们是使用 docker 部署 , iotdb 镜像是 **0.13.2-node** 就部署一个节点。
在一次恢复中,发现了如下异常
```
2022-11-09 14:54:26,705 [pool-10-IoTDB-Recovery-Thread-Pool-1] WARN o.a.i.d.w.r.TsFileRecoverPerformer:171 - Cannot deserialize TsFileResource /iotdb/sbin/../data/data/unsequence/root.tbt/0/0/1667973720009-30-0-0.tsfile, construct it using TsFileSequenceReader
java.io.IOException: Intend to read 4 bytes but -1 are actually returned
at org.apache.iotdb.tsfile.utils.ReadWriteIOUtils.readInt(ReadWriteIOUtils.java:512)
at org.apache.iotdb.db.engine.storagegroup.timeindex.V012FileTimeIndex.deserialize(V012FileTimeIndex.java:46)
at org.apache.iotdb.db.engine.storagegroup.timeindex.V012FileTimeIndex.deserialize(V012FileTimeIndex.java:33)
at org.apache.iotdb.db.engine.storagegroup.TsFileResource.deserialize(TsFileResource.java:259)
at org.apache.iotdb.db.writelog.recover.TsFileRecoverPerformer.recoverResourceFromFile(TsFileRecoverPerformer.java:169)
at org.apache.iotdb.db.writelog.recover.TsFileRecoverPerformer.recover(TsFileRecoverPerformer.java:108)
at org.apache.iotdb.db.engine.storagegroup.VirtualStorageGroupProcessor.recoverTsFiles(VirtualStorageGroupProcessor.java:785)
at org.apache.iotdb.db.engine.storagegroup.VirtualStorageGroupProcessor.recover(VirtualStorageGroupProcessor.java:529)
at org.apache.iotdb.db.engine.storagegroup.VirtualStorageGroupProcessor.(VirtualStorageGroupProcessor.java:404)
at org.apache.iotdb.db.engine.StorageEngine.buildNewStorageGroupProcessor(StorageEngine.java:784)
at org.apache.iotdb.db.engine.storagegroup.virtualSg.StorageGroupManager.lambda$asyncRecover$0(StorageGroupManager.java:245)
at java.base/java.util.concurrent.FutureTask.run(Unknown Source)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.base/java.lang.Thread.run(Unknown Source)
2022-11-09 14:54:26,707 [main] INFO o.a.i.d.c.IoTDBThreadPoolFactory:232 - new SynchronousQueue thread pool: RPC-Client
2022-11-09 14:54:26,708 [RPC] INFO o.a.i.d.s.t.ThriftServiceThread:241 - The RPC ServerService service thread begin to run...
2022-11-09 14:54:26,710 [Thread-1] ERROR o.a.i.d.c.IoTDBDefaultThreadExceptionHandler:31 - Exception in thread Thread-1-20
org.apache.iotdb.db.exception.runtime.StorageEngineFailureException: StorageEngine failed to recover.
at org.apache.iotdb.db.engine.StorageEngine.lambda$recover$1(StorageEngine.java:410)
at java.base/java.lang.Thread.run(Unknown Source)
Caused by: java.util.concurrent.ExecutionException: java.lang.IllegalArgumentException: Negative position
at java.base/java.util.concurrent.FutureTask.report(Unknown Source)
at java.base/java.util.concurrent.FutureTask.get(Unknown Source)
at org.apache.iotdb.db.engine.StorageEngine.lambda$recover$1(StorageEngine.java:408)
... 1 common frames omitted
Caused by: java.lang.IllegalArgumentException: Negative position
at java.base/sun.nio.ch.FileChannelImpl.read(Unknown Source)
at org.apache.iotdb.tsfile.read.reader.LocalTsFileInput.read(LocalTsFileInput.java:90)
at org.apache.iotdb.tsfile.read.TsFileSequenceReader.readTailMagic(TsFileSequenceReader.java:229)
at org.apache.iotdb.tsfile.read.TsFileSequenceReader.loadMetadataSize(TsFileSequenceReader.java:202)
at org.apache.iotdb.tsfile.read.TsFileSequenceReader.(TsFileSequenceReader.java:139)
at org.apache.iotdb.db.writelog.recover.TsFileRecoverPerformer.recoverResourceFromReader(TsFileRecoverPerformer.java:181)
at org.apache.iotdb.db.writelog.recover.TsFileRecoverPerformer.recoverResourceFromFile(TsFileRecoverPerformer.java:175)
at org.apache.iotdb.db.writelog.recover.TsFileRecoverPerformer.recover(TsFileRecoverPerformer.java:108)
at org.apache.iotdb.db.engine.storagegroup.VirtualStorageGroupProcessor.recoverTsFiles(VirtualStorageGroupProcessor.java:785)
at org.apache.iotdb.db.engine.storagegroup.VirtualStorageGroupProcessor.recover(VirtualStorageGroupProcessor.java:529)
at org.apache.iotdb.db.engine.storagegroup.VirtualStorageGroupProcessor.(VirtualStorageGroupProcessor.java:404)
at org.apache.iotdb.db.engine.StorageEngine.buildNewStorageGroupProcessor(StorageEngine.java:784)
at org.apache.iotdb.db.engine.storagegroup.virtualSg.StorageGroupManager.lambda$asyncRecover$0(StorageGroupManager.java:245)
at java.base/java.util.concurrent.FutureTask.run(Unknown Source)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
... 1 common frames omitted
2022-11-09 14:54:26,808 [main] INFO o.a.i.d.s.t.ThriftService:135 - IoTDB: start RPC ServerService successfully, listening on ip 0.0.0.0 port 6667
```
Contributor guide
Research direction
Start with the recovery path in TsFileRecoverPerformer, especially recoverResourceFromFile and recoverResourceFromReader, then inspect V012FileTimeIndex, TsFileResource, and TsFileSequenceReader at the stack-trace locations. Reproduce recovery after an abrupt shutdown with the Docker 0.13.2-node deployment. Done means recovery no longer ends in Negative position or StorageEngineFailureException for the affected TsFile.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- docker, java
- Domain
- databases
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Needs clarification
- Newbie friendliness
- 25/100