Uploaded image for project: 'WiredTiger'
  1. WiredTiger
  2. WT-6423

Salvage testing fails after setting stable timestamp in test format

    • Type: Icon: Bug Bug
    • Resolution: Duplicate
    • Priority: Icon: Major - P3 Major - P3
    • None
    • Affects Version/s: None
    • Component/s: None
    • Labels:

      WT-6263 sets the stable timestamp in test format, however, salvage test starts to fail:

      [2020/06/15 03:57:58.685]     t: process 6817 running
       [2020/06/15 03:57:58.685]     [1592193477:859129][6817:0x7f87ce8ef7c0], file:wt.wt, txn rollback_to_stable: __desc_read, 380: wt.wt does not appear to be a WiredTiger file: WT_ERROR: non-specific WiredTiger error
       [2020/06/15 03:57:58.685]     [1592193477:859228][6817:0x7f87ce8ef7c0], txn-recover: __wt_txn_recover, 852: Recovery failed: WT_ERROR: non-specific WiredTiger error
       [2020/06/15 03:57:58.685]     [1592193477:861411][6817:0x7f87ce8ef7c0], connection: __wt_cache_destroy, 350: cache server: exiting with 3 pages in memory and 0 pages evicted
       [2020/06/15 03:57:58.685]     [1592193477:861437][6817:0x7f87ce8ef7c0], connection: __wt_cache_destroy, 355: cache server: exiting with 2573 image bytes in memory
       [2020/06/15 03:57:58.685]     [1592193477:861449][6817:0x7f87ce8ef7c0], connection: __wt_cache_destroy, 358: cache server: exiting with 3214 bytes in memory
       [2020/06/15 03:57:58.685]     t: run FAILED
       [2020/06/15 03:57:58.685]     ############################################
       [2020/06/15 03:57:58.685]     #  RUN PARAMETERS: V2
       [2020/06/15 03:57:58.685]     ############################################
       [2020/06/15 03:57:58.685]     assert.commit_timestamp=0
       [2020/06/15 03:57:58.685]     assert.read_timestamp=0
       [2020/06/15 03:57:58.685]     backup=0
       [2020/06/15 03:57:58.685]     backup.incremental=off
       [2020/06/15 03:57:58.685]     backup.incr_granularity=4210
       [2020/06/15 03:57:58.685]     btree.bitcnt=4
       [2020/06/15 03:57:58.685]     btree.compression=none
       [2020/06/15 03:57:58.685]     btree.dictionary=0
       [2020/06/15 03:57:58.686]     btree.huffman_key=0
       [2020/06/15 03:57:58.686]     btree.huffman_value=0
       [2020/06/15 03:57:58.686]     btree.internal_key_truncation=1
       [2020/06/15 03:57:58.686]     btree.internal_page_max=9
       [2020/06/15 03:57:58.686]     btree.key_gap=3
       [2020/06/15 03:57:58.686]     btree.key_max=256
       [2020/06/15 03:57:58.686]     btree.key_min=256
       [2020/06/15 03:57:58.686]     btree.leaf_page_max=9
       [2020/06/15 03:57:58.686]     btree.memory_page_max=6
       [2020/06/15 03:57:58.686]     btree.prefix_compression=1
       [2020/06/15 03:57:58.686]     btree.prefix_compression_min=1
       [2020/06/15 03:57:58.686]     btree.repeat_data_pct=67
       [2020/06/15 03:57:58.686]     btree.reverse=0
       [2020/06/15 03:57:58.686]     btree.split_pct=80
       [2020/06/15 03:57:58.686]     btree.value_max=2048
       [2020/06/15 03:57:58.686]     btree.value_min=7
       [2020/06/15 03:57:58.686]     cache=72
       [2020/06/15 03:57:58.686]     cache.evict_max=4
       [2020/06/15 03:57:58.686]     cache.minimum=20
       [2020/06/15 03:57:58.686]     checkpoint=on
       [2020/06/15 03:57:58.686]     checkpoint.log_size=88
       [2020/06/15 03:57:58.686]     checkpoint.wait=68
       [2020/06/15 03:57:58.686]     disk.checksum=uncompressed
       [2020/06/15 03:57:58.686]     disk.data_extend=1
       [2020/06/15 03:57:58.686]     disk.direct_io=0
       [2020/06/15 03:57:58.686]     disk.encryption=rotn-7
       [2020/06/15 03:57:58.686]     disk.firstfit=0
       [2020/06/15 03:57:58.686]     disk.mmap=0
       [2020/06/15 03:57:58.686]     disk.mmap_all=0
       [2020/06/15 03:57:58.686]     format.abort=0
       [2020/06/15 03:57:58.686]     format.independent_thread_rng=1
       [2020/06/15 03:57:58.686]     format.major_timeout=0
       [2020/06/15 03:57:58.686]     logging=0
       [2020/06/15 03:57:58.686]     logging.archive=0
       [2020/06/15 03:57:58.686]     logging.compression=none
       [2020/06/15 03:57:58.686]     logging.file_max=323484
       [2020/06/15 03:57:58.686]     logging.prealloc=0
       [2020/06/15 03:57:58.686]     lsm.auto_throttle=1
       [2020/06/15 03:57:58.686]     lsm.bloom=1
       [2020/06/15 03:57:58.686]     lsm.bloom_bit_count=38
       [2020/06/15 03:57:58.686]     lsm.bloom_hash_count=18
       [2020/06/15 03:57:58.686]     lsm.bloom_oldest=0
       [2020/06/15 03:57:58.686]     lsm.chunk_size=7
       [2020/06/15 03:57:58.686]     lsm.merge_max=15
       [2020/06/15 03:57:58.686]     lsm.worker_threads=3
       [2020/06/15 03:57:58.686]     ops.alter=1
       [2020/06/15 03:57:58.686]     ops.compaction=0
       [2020/06/15 03:57:58.686]     ops.hs_cursor=0
       [2020/06/15 03:57:58.686]     ops.pct.delete=95
       [2020/06/15 03:57:58.686]     ops.pct.insert=0
       [2020/06/15 03:57:58.686]     ops.pct.modify=3
       [2020/06/15 03:57:58.686]     ops.pct.read=2
       [2020/06/15 03:57:58.686]     ops.pct.write=0
       [2020/06/15 03:57:58.686]     ops.prepare=0
       [2020/06/15 03:57:58.686]     ops.random_cursor=0
       [2020/06/15 03:57:58.686]     ops.rebalance=0
       [2020/06/15 03:57:58.686]     ops.salvage=1
       [2020/06/15 03:57:58.686]     ops.truncate=1
       [2020/06/15 03:57:58.686]     ops.verify=1
       [2020/06/15 03:57:58.686]     quiet=1
       [2020/06/15 03:57:58.686]     runs=1
       [2020/06/15 03:57:58.686]     runs.in_memory=0
       [2020/06/15 03:57:58.686]     runs.ops=0
       [2020/06/15 03:57:58.686]     runs.rows=100000
       [2020/06/15 03:57:58.686]     runs.source=table
       [2020/06/15 03:57:58.686]     runs.threads=6
       [2020/06/15 03:57:58.686]     runs.timer=4
       [2020/06/15 03:57:58.686]     runs.type=row-store
       [2020/06/15 03:57:58.686]     runs.verify_failure_dump=0
       [2020/06/15 03:57:58.686]     statistics=0
       [2020/06/15 03:57:58.686]     statistics.server=0
       [2020/06/15 03:57:58.686]     stress.aggressive_sweep=0
       [2020/06/15 03:57:58.686]     stress.checkpoint=0
       [2020/06/15 03:57:58.686]     stress.hs_checkpoint_delay=0
       [2020/06/15 03:57:58.686]     stress.hs_sweep=0
       [2020/06/15 03:57:58.686]     stress.split_1=0
       [2020/06/15 03:57:58.686]     stress.split_2=0
       [2020/06/15 03:57:58.686]     stress.split_3=0
       [2020/06/15 03:57:58.686]     stress.split_4=0
       [2020/06/15 03:57:58.686]     stress.split_5=0
       [2020/06/15 03:57:58.686]     stress.split_6=0
       [2020/06/15 03:57:58.686]     stress.split_7=1
       [2020/06/15 03:57:58.686]     stress.split_8=0
       [2020/06/15 03:57:58.686]     transaction.frequency=100
       [2020/06/15 03:57:58.686]     transaction.isolation=snapshot
       [2020/06/15 03:57:58.686]     transaction.timestamps=1
       [2020/06/15 03:57:58.686]     wiredtiger.config=
       [2020/06/15 03:57:58.686]     wiredtiger.rwlock=1
       [2020/06/15 03:57:58.686]     wiredtiger.leak_memory=0
       [2020/06/15 03:57:58.686]     ############################################
       [2020/06/15 03:57:58.686]     t: FAILED: wts_open/457: wiredtiger_open(home, &event_handler, config, &conn): /data/mci/1eefb1ed0e64db55824b944c7b10a081/wiredtiger/test/format/RUNDIR.4: WT_PANIC: WiredTiger library panic
       [2020/06/15 03:57:58.686]     process aborting
       [2020/06/15 03:57:58.686] format.sh: /data/mci/1eefb1ed0e64db55824b944c7b10a081/wiredtiger/test/format/RUNDIR.4/CONFIG:
       [2020/06/15 03:57:58.686]     ############################################
       [2020/06/15 03:57:58.686]     #  RUN PARAMETERS: V2
       [2020/06/15 03:57:58.686]     ############################################
       [2020/06/15 03:57:58.686]     assert.commit_timestamp=0
       [2020/06/15 03:57:58.686]     assert.read_timestamp=0
       [2020/06/15 03:57:58.686]     backup=0
       [2020/06/15 03:57:58.687]     backup.incremental=off
       [2020/06/15 03:57:58.687]     backup.incr_granularity=4210
       [2020/06/15 03:57:58.687]     btree.bitcnt=4
       [2020/06/15 03:57:58.687]     btree.compression=none
       [2020/06/15 03:57:58.687]     btree.dictionary=0
       [2020/06/15 03:57:58.687]     btree.huffman_key=0
       [2020/06/15 03:57:58.687]     btree.huffman_value=0
       [2020/06/15 03:57:58.687]     btree.internal_key_truncation=1
       [2020/06/15 03:57:58.687]     btree.internal_page_max=9
       [2020/06/15 03:57:58.687]     btree.key_gap=3
       [2020/06/15 03:57:58.687]     btree.key_max=256
       [2020/06/15 03:57:58.687]     btree.key_min=256
       [2020/06/15 03:57:58.687]     btree.leaf_page_max=9
       [2020/06/15 03:57:58.687]     btree.memory_page_max=6
       [2020/06/15 03:57:58.687]     btree.prefix_compression=1
       [2020/06/15 03:57:58.687]     btree.prefix_compression_min=1
       [2020/06/15 03:57:58.687]     btree.repeat_data_pct=67
       [2020/06/15 03:57:58.687]     btree.reverse=0
       [2020/06/15 03:57:58.687]     btree.split_pct=80
       [2020/06/15 03:57:58.687]     btree.value_max=2048
       [2020/06/15 03:57:58.687]     btree.value_min=7
       [2020/06/15 03:57:58.687]     cache=72
       [2020/06/15 03:57:58.687]     cache.evict_max=4
       [2020/06/15 03:57:58.687]     cache.minimum=20
       [2020/06/15 03:57:58.687]     checkpoint=on
       [2020/06/15 03:57:58.687]     checkpoint.log_size=88
       [2020/06/15 03:57:58.687]     checkpoint.wait=68
       [2020/06/15 03:57:58.687]     disk.checksum=uncompressed
       [2020/06/15 03:57:58.687]     disk.data_extend=1
       [2020/06/15 03:57:58.687]     disk.direct_io=0
       [2020/06/15 03:57:58.687]     disk.encryption=rotn-7
       [2020/06/15 03:57:58.687]     disk.firstfit=0
       [2020/06/15 03:57:58.687]     disk.mmap=0
       [2020/06/15 03:57:58.687]     disk.mmap_all=0
       [2020/06/15 03:57:58.687]     format.abort=0
       [2020/06/15 03:57:58.687]     format.independent_thread_rng=1
       [2020/06/15 03:57:58.687]     format.major_timeout=0
       [2020/06/15 03:57:58.687]     logging=0
       [2020/06/15 03:57:58.687]     logging.archive=0
       [2020/06/15 03:57:58.687]     logging.compression=none
       [2020/06/15 03:57:58.687]     logging.file_max=323484
       [2020/06/15 03:57:58.687]     logging.prealloc=0
       [2020/06/15 03:57:58.687]     lsm.auto_throttle=1
       [2020/06/15 03:57:58.687]     lsm.bloom=1
       [2020/06/15 03:57:58.687]     lsm.bloom_bit_count=38
       [2020/06/15 03:57:58.687]     lsm.bloom_hash_count=18
       [2020/06/15 03:57:58.687]     lsm.bloom_oldest=0
       [2020/06/15 03:57:58.687]     lsm.chunk_size=7
       [2020/06/15 03:57:58.687]     lsm.merge_max=15
       [2020/06/15 03:57:58.687]     lsm.worker_threads=3
       [2020/06/15 03:57:58.687]     ops.alter=1
       [2020/06/15 03:57:58.687]     ops.compaction=0
       [2020/06/15 03:57:58.687]     ops.hs_cursor=0
       [2020/06/15 03:57:58.687]     ops.pct.delete=95
       [2020/06/15 03:57:58.687]     ops.pct.insert=0
       [2020/06/15 03:57:58.687]     ops.pct.modify=3
       [2020/06/15 03:57:58.687]     ops.pct.read=2
       [2020/06/15 03:57:58.687]     ops.pct.write=0
       [2020/06/15 03:57:58.687]     ops.prepare=0
       [2020/06/15 03:57:58.687]     ops.random_cursor=0
       [2020/06/15 03:57:58.687]     ops.rebalance=0
       [2020/06/15 03:57:58.687]     ops.salvage=1
       [2020/06/15 03:57:58.687]     ops.truncate=1
       [2020/06/15 03:57:58.687]     ops.verify=1
       [2020/06/15 03:57:58.687]     quiet=1
       [2020/06/15 03:57:58.687]     runs=1
       [2020/06/15 03:57:58.687]     runs.in_memory=0
       [2020/06/15 03:57:58.687]     runs.ops=0
       [2020/06/15 03:57:58.687]     runs.rows=100000
       [2020/06/15 03:57:58.687]     runs.source=table
       [2020/06/15 03:57:58.687]     runs.threads=6
       [2020/06/15 03:57:58.687]     runs.timer=4
       [2020/06/15 03:57:58.687]     runs.type=row-store
       [2020/06/15 03:57:58.687]     runs.verify_failure_dump=0
       [2020/06/15 03:57:58.687]     statistics=0
       [2020/06/15 03:57:58.687]     statistics.server=0
       [2020/06/15 03:57:58.687]     stress.aggressive_sweep=0
       [2020/06/15 03:57:58.687]     stress.checkpoint=0
       [2020/06/15 03:57:58.687]     stress.hs_checkpoint_delay=0
       [2020/06/15 03:57:58.687]     stress.hs_sweep=0
       [2020/06/15 03:57:58.687]     stress.split_1=0
       [2020/06/15 03:57:58.687]     stress.split_2=0
       [2020/06/15 03:57:58.687]     stress.split_3=0
       [2020/06/15 03:57:58.687]     stress.split_4=0
       [2020/06/15 03:57:58.687]     stress.split_5=0
       [2020/06/15 03:57:58.687]     stress.split_6=0
       [2020/06/15 03:57:58.687]     stress.split_7=1
       [2020/06/15 03:57:58.687]     stress.split_8=0
       [2020/06/15 03:57:58.687]     transaction.frequency=100
       [2020/06/15 03:57:58.687]     transaction.isolation=snapshot
       [2020/06/15 03:57:58.687]     transaction.timestamps=1
       [2020/06/15 03:57:58.687]     wiredtiger.config=
       [2020/06/15 03:57:58.687]     wiredtiger.rwlock=1
       [2020/06/15 03:57:58.687]     wiredtiger.leak_memory=0
       [2020/06/15 03:57:58.687]     ############################################
       [2020/06/15 04:01:25.493] format.sh: 2 successful jobs, 1 failed jobs
       [2020/06/15 04:01:25.493] format.sh: 3 successful jobs, 1 failed jobs
       [2020/06/15 04:01:25.495] format.sh: 3 successful jobs, 1 failed jobs
      

      There is a known problem in rebalance (WT-6410) that it fails because we can't do a single file checkpoint with timestamp. This may be related to that as well. In the case of salvage, I find what we do in the test is that we intentionally corrupt some data, do a salvage, and reopen it. However, with WT-6263, we fail to reopen.

            Assignee:
            keith.bostic@mongodb.com Keith Bostic (Inactive)
            Reporter:
            chenhao.qu@mongodb.com Chenhao Qu
            Votes:
            0 Vote for this issue
            Watchers:
            5 Start watching this issue

              Created:
              Updated:
              Resolved: