[KUDU-3268] Crash in TabletServerDiskErrorTest.TestRandomOpSequence

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Fix Version/s: 1.15.0
• Component/s: test, tserver
• Assignee: Unassigned
• Reporter: Andrew Wong
• Created: 23/Mar/21 19:30
• Updated: 12/Apr/21 17:04
• Resolved: 09/Apr/21 00:39

Description

A pre-commit failed with the following crash when attempting to launch an op after stopping a replica:

I0323 18:15:01.078991 23854 maintenance_manager.cc:373] P c8a93089db0041f5930b9fb1832714ed: Scheduling CompactRowSetsOp(ffffffffffffffffffffffffffffffff): perf score=1.012452
I0323 18:15:01.079111 21067 tablet_server-test.cc:852] Tablet server responded with: timestamp: 6621279441214984192
I0323 18:15:01.079317 23789 maintenance_manager.cc:594] P c8a93089db0041f5930b9fb1832714ed: UndoDeltaBlockGCOp(ffffffffffffffffffffffffffffffff) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4}
E0323 18:15:01.080865 23788 cfile_reader.cc:591] Encountered corrupted CFile in filesystem block: 4124746176525068430
I0323 18:15:01.080960 23788 ts_tablet_manager.cc:1774] T ffffffffffffffffffffffffffffffff P c8a93089db0041f5930b9fb1832714ed: failing tablet
I0323 18:15:01.080950 21067 tablet_server-test.cc:852] Tablet server responded with: timestamp: 6621279441223315456
I0323 18:15:01.081243 24138 tablet_replica.cc:324] T ffffffffffffffffffffffffffffffff P c8a93089db0041f5930b9fb1832714ed: stopping tablet replica
I0323 18:15:01.081670 21067 tablet_server-test.cc:852] Tablet server responded with: error {
  code: TABLET_NOT_RUNNING
  status {
    code: ILLEGAL_STATE
    message: "Tablet not RUNNING: STOPPING"
  }
}
I0323 18:15:01.081777 21067 tablet_server-test.cc:890] Failure was caught by an op!
W0323 18:15:01.082907 23788 tablet_mm_ops.cc:176] T ffffffffffffffffffffffffffffffff P c8a93089db0041f5930b9fb1832714ed: Compaction failed on ffffffffffffffffffffffffffffffff: Corruption: Flush to disk failed: checksum error on CFile block 4124746176525068430 at offset=1006 size=24: Checksum does not match: 3582029077 vs expected 3582029077
I0323 18:15:01.082957 23788 maintenance_manager.cc:594] P c8a93089db0041f5930b9fb1832714ed: CompactRowSetsOp(ffffffffffffffffffffffffffffffff) complete. Timing: real 0.004s	user 0.003s	sys 0.000s Metrics: {"cfile_cache_miss":3,"cfile_cache_miss_bytes":92,"delta_iterators_relevant":2,"dirs.queue_time_us":630,"dirs.run_cpu_time_us":368,"dirs.run_wall_time_us":2220,"lbm_read_time_us":54,"lbm_reads_lt_1ms":3,"lbm_write_time_us":168,"lbm_writes_lt_1ms":6,"num_input_rowsets":2,"spinlock_wait_cycles":1792,"tablet-open.queue_time_us":135,"thread_start_us":382,"threads_started":5}
I0323 18:15:01.083369 23854 maintenance_manager.cc:373] P c8a93089db0041f5930b9fb1832714ed: Scheduling CompactRowSetsOp(ffffffffffffffffffffffffffffffff): perf score=1.012452
*** Aborted at 1616523301 (unix time) try "date -d @1616523301" if you are using GNU date ***
I0323 18:15:01.083519 24138 raft_consensus.cc:2226] T ffffffffffffffffffffffffffffffff P c8a93089db0041f5930b9fb1832714ed [term 1 LEADER]: Raft consensus shutting down.
I0323 18:15:01.083653 24138 raft_consensus.cc:2255] T ffffffffffffffffffffffffffffffff P c8a93089db0041f5930b9fb1832714ed [term 1 FOLLOWER]: Raft consensus is shut down!
I0323 18:15:01.085090 21067 tablet_server-test.cc:894] Tablet was successfully failed
I0323 18:15:01.085439 21067 tablet_server.cc:166] TabletServer@127.0.0.1:0 shutting down...
PC: @     0x7ff97596de0d kudu::MaintenanceManager::LaunchOp()
*** SIGSEGV (@0x30) received by PID 21067 (TID 0x7ff96343b700) from PID 48; stack trace: ***
    @     0x7ff976846980 (unknown) at ??:0
    @     0x7ff97596de0d kudu::MaintenanceManager::LaunchOp() at ??:0
    @     0x7ff97596b538 _ZZN4kudu18MaintenanceManager18RunSchedulerThreadEvENKUlvE_clEv at ??:0
    @     0x7ff97596f124 _ZNSt17_Function_handlerIFvvEZN4kudu18MaintenanceManager18RunSchedulerThreadEvEUlvE_E9_M_invokeERKSt9_Any_data at ??:0
    @     0x7ff977e2bcf4 std::function<>::operator()() at ??:0
    @     0x7ff975a05e6e kudu::ThreadPool::DispatchThread() at ??:0
    @     0x7ff975a06757 _ZZN4kudu10ThreadPool12CreateThreadEvENKUlvE_clEv at ??:0
    @     0x7ff975a07e7b _ZNSt17_Function_handlerIFvvEZN4kudu10ThreadPool12CreateThreadEvEUlvE_E9_M_invokeERKSt9_Any_data at ??:0
    @     0x7ff977e2bcf4 std::function<>::operator()() at ??:0
    @     0x7ff9759f8913 kudu::Thread::SuperviseThread() at ??:0
    @     0x7ff97683b6db start_thread at ??:0
    @     0x7ff97388e71f clone at ??:0

Attached the full logs – seems there's something unsafe about how we unregister ops (maybe from the fix for KUDU-3149?) when racing with the scheduler thread.