[IOTDB-2693] [compaction] org.apache.commons.io.FileExistsException: File element in parameter 'null' already exists

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 0.13.0-SNAPSHOT
• Fix Version/s: 0.13.0
• Component/s: Core/Compaction
• Labels: pull-request-available
• Sprint: 2022-3-Dragon
• Assignee: 周沛辰
• Reporter: 刘珍
• Due: 09/Mar/22
• Created: 07/Mar/22 07:35
• Updated: 10/Mar/22 09:25
• Resolved: 09/Mar/22 06:00

Description

被测iotdb信息，是个分支版本：
https://github.com/choubenson/iotdb/tree/formatCompactionLog
测试内容：0.12合并中断 ( 有delete操作)，然后0.13恢复的正确性。
问题描述：
*问题1：合并过程中有异常org.apache.commons.io.FileExistsException: File element in parameter 'null' already exists:
问题2：0.12的备份日志compaction.log 在0.13没有被删除
问题3：0.12 deleted的2条记录，在0.13能查询到。
实际查询结果，所有的设备的count值为200000000。
期望结果是，每个设备的记录数为：199,999,998。
问题4：0.13的data中还有0.12的merge.mods文件。
问题5：java.nio.BufferUnderflowException: null。*
复现流程：
1. 0.12.5-pre4 关合并，生成数据，记作备份1（在/data/liuzhen_test/1205_pre4/data_bk_close-comp）。
在192.168.10.68 /data/liuzhen_test/1205_pre4/data_bk_close-comp路径。
共10sg/100设备 /100 序列，每个序列2亿点。

unseq tsfile个数：50064
seq tsfile个数：50076

2. 0.12 0305版本3154faf。copy 备份1 到此iotdb （68机器/data/liuzhen_test/12_0305_3154faf下）。
merge_thread_num=2
2022-03-07 09:49:42 启动iotdb成功。
2022-03-07 11:10:26 ：（启动数据库1小时20分钟）执行delete操作，脚本为：
#!/bin/bash
base_db_dir="/data/liuzhen_test/1205_pre4"
out_dev="dev_name.txt"
function expDevNameToFile()
{
${base_db_dir}/sbin/start-cli.sh -e "set max_display_num=0 ;show devices;"|grep root|awk -F '|' '

{print $2}

'>${out_dev}
}

expDevNameToFile

1. delete 2 row 1 of seq ,1 of unseq
   function del2rows()
   {
   while read LINE
   do
   ${base_db_dir}/sbin/start-cli.sh -e " select s_0 from "$LINE" where time=2024-05-24T18:00:05.000+08:00 or time=2034-01-24T18:53:22.000+08:00" >> sel_del_sel.out
   ${base_db_dir}/sbin/start-cli.sh -e " delete from "$LINE" where time=2034-01-24T18:53:22.000+08:00" >> sel_del_sel.out
   ${base_db_dir}/sbin/start-cli.sh -e " delete from "$LINE" where time=2024-05-24T18:00:05.000+08:00" >> sel_del_sel.out
   ${base_db_dir}/sbin/start-cli.sh -e " select s_0 from "$LINE" where time=2024-05-24T18:00:05.000+08:00 or time=2034-01-24T18:53:22.000+08:00" >> sel_del_sel.out
   echo $LINE

done < ${out_dev}
}
del2rows

执行脚本完成后，killall -u liuzhen

删除iotdb进程，当前的合并情况和mods情况：
342个mods文件。
2个merge，4个compaction：

备份此数据，记作备份2。
备份2 在：/data/liuzhen_test/12_0305_3154faf/data_0307_stop-merge2-comp3_del2rows

3. 被测分支：在68机器
/data/liuzhen_test/pr_0304_formatCompactionLog
copy备份2 到此路径。
启动数据库。
启动数据库后，执行脚本：
nohup sh -x r.sh > r.log &
这个脚本串行调用2个脚本：
sh -x ./select_del-2rows.sh > s.log
sh -x ./q.sh > q.log
这3个脚本见附件。
问题1：
2022-03-07 11:37:49 iotdb启动成功。2小时18分钟后有异常：
2022-03-07 13:55:51,443 [pool-7-IoTDB-Compaction-5] ERROR o.a.i.t.f.f.LocalFSFactory:118 - Failed to move file from /data/liuzhen_test/pr_0304_formatCompactionLog/./sbin/../data/data/sequence/root.ip5.ip53/0/0/1645065803917-37-1-1.inner to /data/liuzhen_test/pr_0304_formatCompactionLog/./sbin/../data/data/sequence/root.ip5.ip53/0/0/1645065803917-37-1-1.tsfile.
org.apache.commons.io.FileExistsException: File element in parameter 'null' already exists: '/data/liuzhen_test/pr_0304_formatCompactionLog/./sbin/../data/data/sequence/root.ip5.ip53/0/0/1645065803917-37-1-1.tsfile'
at org.apache.commons.io.FileUtils.requireAbsent(FileUtils.java:2587)
at org.apache.commons.io.FileUtils.moveFile(FileUtils.java:2305)
at org.apache.commons.io.FileUtils.moveFile(FileUtils.java:2283)
at org.apache.iotdb.tsfile.fileSystem.fsFactory.LocalFSFactory.moveFile(LocalFSFactory.java:116)
at org.apache.iotdb.db.engine.compaction.inner.utils.InnerSpaceCompactionUtils.moveTargetFile(InnerSpaceCompactionUtils.java:285)
at org.apache.iotdb.db.engine.compaction.inner.sizetiered.SizeTieredCompactionTask.doCompaction(SizeTieredCompactionTask.java:127)
at org.apache.iotdb.db.engine.compaction.task.AbstractCompactionTask.call(AbstractCompactionTask.java:66)
at org.apache.iotdb.db.engine.compaction.task.AbstractCompactionTask.call(AbstractCompactionTask.java:45)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)

问题2：0.12的备份日志compaction.log 在0.13没有被删除。

问题3：0.12 deleted的2条记录，在0.13能查询到。
所有的设备的count值为200000000。
期望记录数为：199,999,998
问题4：被测pr的data中还有0.12的merge.mods

问题5：java.nio.BufferUnderflowException: null
2022-03-07 15:35:57,958 [pool-7-IoTDB-Compaction-2] ERROR o.a.i.d.e.c.i.s.SizeTieredCompactionTask:196 - root.ip5.ip59-0 [Compaction] Throwable is caught during execution of SizeTieredCompaction, {}
java.nio.BufferUnderflowException: null
at java.nio.Buffer.nextGetIndex(Buffer.java:506)
at java.nio.HeapByteBuffer.getLong(HeapByteBuffer.java:412)
at org.apache.iotdb.tsfile.utils.ReadWriteIOUtils.readLong(ReadWriteIOUtils.java:546)
at org.apache.iotdb.tsfile.file.metadata.MetadataIndexNode.deserializeFrom(MetadataIndexNode.java:105)
at org.apache.iotdb.tsfile.file.metadata.TsFileMetadata.deserializeFrom(TsFileMetadata.java:55)
at org.apache.iotdb.tsfile.read.TsFileSequenceReader.readFileMetadata(TsFileSequenceReader.java:274)
at org.apache.iotdb.tsfile.read.TsFileSequenceReader.getAllDevicesIteratorWithIsAligned(TsFileSequenceReader.java:628)
at org.apache.iotdb.db.engine.compaction.inner.utils.MultiTsFileDeviceIterator.<init>(MultiTsFileDeviceIterator.java:63)
at org.apache.iotdb.db.engine.compaction.inner.utils.InnerSpaceCompactionUtils.compact(InnerSpaceCompactionUtils.java:67)
at org.apache.iotdb.db.engine.compaction.inner.sizetiered.SizeTieredCompactionTask.doCompaction(SizeTieredCompactionTask.java:119)
at org.apache.iotdb.db.engine.compaction.task.AbstractCompactionTask.call(AbstractCompactionTask.java:66)
at org.apache.iotdb.db.engine.compaction.task.AbstractCompactionTask.call(AbstractCompactionTask.java:45)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)

Issue Links

• links to: GitHub Pull Request #5178