Sequence of region should increase monotonically (1903 > 1903)

[killme2008]

Tried to open an exists database, but it panic:

2022-10-25T12:31:48.113516Z ERROR storage::region::writer: Sequence should not decrease during replay, found 1903 <= 1903, region_id: 4402341478400, region_name: 1025_0000000000, flushed_sequence: 0, num_requests: 1904
2022-10-25T12:31:49.564908Z ERROR greptime: Fatal error occurs! err.msg=Failed to start datanode, source: Failed to create catalog list, source: Failed to open table, table info: greptime.public.go_gc_duration_seconds, id: 1025, source: Failed to open region, region: 1025_0000000000, source: Sequence of region should increase monotonically (1903 > 1903) err.code=Unexpected err.source=Failed to create catalog list, source: Failed to open table, table info: greptime.public.go_gc_duration_seconds, id: 1025, source: Failed to open region, region: 1025_0000000000, source: Sequence of region should increase monotonically (1903 > 1903) err.source.sources=[Failed to open table, table info: greptime.public.go_gc_duration_seconds, id: 1025, source: Failed to open region, region: 1025_0000000000, source: Sequence of region should increase monotonically (1903 > 1903), Failed to open region, region: 1025_0000000000, source: Sequence of region should increase monotonically (1903 > 1903), Sequence of region should increase monotonically (1903 > 1903)] err.backtrace= 0 backtrace::backtrace::libunwind::trace::hcdfd8b20f85c976d
   /Users/dennis/.cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.66/src/backtrace/libunwind.rs:93
   backtrace::backtrace::trace_unsynchronized::h92cf28ac583400a8
   /Users/dennis/.cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.66/src/backtrace/mod.rs:66
 1 backtrace::backtrace::trace::h6b7004ab3cf91bc8
   /Users/dennis/.cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.66/src/backtrace/mod.rs:53
 2 backtrace::capture::Backtrace::create::h3c74948d4e1cf141
   /Users/dennis/.cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.66/src/capture.rs:176
 3 backtrace::capture::Backtrace::new::h7226af6750c0259f
   /Users/dennis/.cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.66/src/capture.rs:140
 4 <snafu::backtrace_shim::Backtrace as snafu::GenerateImplicitData>::generate::h56a4c240894038fb
   /Users/dennis/.cargo/registry/src/github.com-1ecc6299db9ec823/snafu-0.7.1/src/backtrace_shim.rs:15
   storage::error::SequenceNotMonotonicSnafu<__T0,__T1>::build::he212b5e137524da4
   /Users/dennis/programming/rust/greptimedb/src/storage/src/error.rs:15
 5 storage::error::SequenceNotMonotonicSnafu<__T0,__T1>::fail::h7e9dc6d85029898f
   /Users/dennis/programming/rust/greptimedb/src/storage/src/error.rs:15
 6 storage::region::writer::WriterInner::replay::{{closure}}::hd06006d5688ebe03
   /Users/dennis/programming/rust/greptimedb/src/storage/src/region/writer.rs:385
 7 <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll::h32bc86bee96a3618
   /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/core/src/future/mod.rs:91
 8 storage::region::writer::RegionWriter::replay::{{closure}}::h64ced6f1f2fbcd16
   /Users/dennis/programming/rust/greptimedb/src/storage/src/region/writer.rs:73
 9 <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll::h49d82205a88de535
   /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/core/src/future/mod.rs:91
10 storage::region::RegionImpl<S>::open::{{closure}}::hd9965ad7d5959109
   /Users/dennis/programming/rust/greptimedb/src/storage/src/region.rs:216
11 <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll::h6cfb17bb8581ba58
   /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/core/src/future/mod.rs:91
12 storage::engine::EngineInner<S>::open_region::{{closure}}::hd39751f583208422
   /Users/dennis/programming/rust/greptimedb/src/storage/src/engine.rs:250
13 <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll::hdf361977bbf579f6
   /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/core/src/future/mod.rs:91
14 <storage::engine::EngineImpl<S> as store_api::storage::engine::StorageEngine>::open_region::{{closure}}::hbaf088a633da9cf6
   /Users/dennis/programming/rust/greptimedb/src/storage/src/engine.rs:47
15 <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll::h030e05f2c40999a9
   /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/core/src/future/mod.rs:91
16 <core::pin::Pin<P> as core::future::future::Future>::poll::h3b73c1b552279e95
   /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/core/src/future/future.rs:124
17 table_engine::engine::MitoEngineInner<S>::open_table::{{closure}}::h2fc9401bcd033fb4
   /Users/dennis/programming/rust/greptimedb/src/table-engine/src/engine.rs:373
18 <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll::h419db477e792bfdc
   /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/core/src/future/mod.rs:91
19 <table_engine::engine::MitoEngine<S> as table::engine::TableEngine>::open_table::{{closure}}::hd99395761356523c
   /Users/dennis/programming/rust/greptimedb/src/table-engine/src/engine.rs:88
20 <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll::h11518346ba73a83e
   /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/core/src/future/mod.rs:91
21 <core::pin::Pin<P> as core::future::future::Future>::poll::h9ec76fc9a6c0684a
   /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/core/src/future/future.rs:124
22 catalog::manager::LocalCatalogManager::open_and_register_table::{{closure}}::he8feea306ad8cb95
   /Users/dennis/programming/rust/greptimedb/src/catalog/src/manager.rs:257
23 <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll::h451da3b629a9fc41
   /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/core/src/future/mod.rs:91
24 catalog::manager::LocalCatalogManager::handle_system_catalog_entries::{{closure}}::h5edd7ec8737fa160
   /Users/dennis/programming/rust/greptimedb/src/catalog/src/manager.rs:225
25 <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll::h829f8aa00643fb32
   /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/core/src/future/mod.rs:91
26 catalog::manager::LocalCatalogManager::init::{{closure}}::h522d0b4fd8bea804
   /Users/dennis/programming/rust/greptimedb/src/catalog/src/manager.rs:80
27 <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll::hacd7a41c8206735f
   /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/core/src/future/mod.rs:91
28 <catalog::manager::LocalCatalogManager as catalog::CatalogManager>::start::{{closure}}::hd30ff349fdc1d6fb
   /Users/dennis/programming/rust/greptimedb/src/catalog/src/manager.rs:310
29 <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll::ha467d35e96aada1d
   /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/core/src/future/mod.rs:91
30 <core::pin::Pin<P> as core::future::future::Future>::poll::h3252b13febde4f37
   /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/core/src/future/future.rs:124
31 datanode::instance::Instance::start::{{closure}}::h47cdec93948f1e6f
   /Users/dennis/programming/rust/greptimedb/src/datanode/src/instance.rs:70
32 <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll::hb318e1ff1f48935d
   /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/core/src/future/mod.rs:91
33 datanode::datanode::Datanode::start::{{closure}}::h8cb04f6f4281baec
   /Users/dennis/programming/rust/greptimedb/src/datanode/src/datanode.rs:69
34 <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll::h599b3bdca9a233e1
   /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/core/src/future/mod.rs:91
35 cmd::datanode::StartCommand::run::{{closure}}::h9147fb15cdb20128
   /Users/dennis/programming/rust/greptimedb/src/cmd/src/datanode.rs:59
36 <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll::h2c528aab76f82833
   /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/core/src/future/mod.rs:91
37 cmd::datanode::SubCommand::run::{{closure}}::h43c5689d912644d6
   /Users/dennis/programming/rust/greptimedb/src/cmd/src/datanode.rs:29
38 <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll::h4aa12bc27cef5788
   /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/core/src/future/mod.rs:91
39 cmd::datanode::Command::run::{{closure}}::h0c3ca6aaa220304d
   /Users/dennis/programming/rust/greptimedb/src/cmd/src/datanode.rs:17
40 <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll::h9f498a6ee39dc846
   /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/core/src/future/mod.rs:91
41 greptime::SubCommand::run::{{closure}}::h691d7fcb9f4979e5
   /Users/dennis/programming/rust/greptimedb/src/cmd/src/bin/greptime.rs:41
42 <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll::h4ae03271c7db2dc8
   /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/core/src/future/mod.rs:91
43 greptime::Command::run::{{closure}}::ha98ffbe3b1a41938
   /Users/dennis/programming/rust/greptimedb/src/cmd/src/bin/greptime.rs:24
44 <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll::h2c55a2aadb94cb94
   /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/core/src/future/mod.rs:91
45 greptime::main::{{closure}}::{{closure}}::h6c15e8b883103fb9
   /Users/dennis/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.21.1/src/macros/select.rs:507
46 <tokio::future::poll_fn::PollFn<F> as core::future::future::Future>::poll::hc17f315582591c22
   /Users/dennis/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.21.1/src/future/poll_fn.rs:38
47 greptime::main::{{closure}}::h28fef9abbd49c315
   /Users/dennis/programming/rust/greptimedb/src/cmd/src/bin/greptime.rs:71
48 <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll::h9fa25b1865b1f96f
   /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/core/src/future/mod.rs:91
49 tokio::park::thread::CachedParkThread::block_on::{{closure}}::he8aa47a7bbadad02
   /Users/dennis/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.21.1/src/park/thread.rs:267
50 tokio::coop::with_budget::{{closure}}::h2978bbc4ba903a47
   /Users/dennis/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.21.1/src/coop.rs:102
51 std::thread::local::LocalKey<T>::try_with::h8cd425050defab48
   /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/std/src/thread/local.rs:445
52 std::thread::local::LocalKey<T>::with::h089d8570a597f2d5
   /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/std/src/thread/local.rs:421
53 tokio::coop::with_budget::ha4da3acd2df364b1
   /Users/dennis/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.21.1/src/coop.rs:95
   tokio::coop::budget::h5c39ad55b2aad428
   /Users/dennis/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.21.1/src/coop.rs:72
   tokio::park::thread::CachedParkThread::block_on::hc2089b8120fd73ac
   /Users/dennis/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.21.1/src/park/thread.rs:267
54 tokio::runtime::enter::Enter::block_on::h999bb69a70d31403
   /Users/dennis/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.21.1/src/runtime/enter.rs:152
55 tokio::runtime::scheduler::multi_thread::MultiThread::block_on::hb9e1e6466961a9a4
   /Users/dennis/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.21.1/src/runtime/scheduler/multi_thread/mod.rs:79
56 tokio::runtime::Runtime::block_on::he6437fd379645eb1
   /Users/dennis/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.21.1/src/runtime/mod.rs:492
57 greptime::main::hc64632694245393d
   /Users/dennis/programming/rust/greptimedb/src/cmd/src/bin/greptime.rs:82
58 core::ops::function::FnOnce::call_once::haae51c6062d31fde
   /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/core/src/ops/function.rs:248
59 std::sys_common::backtrace::__rust_begin_short_backtrace::h54efa01ba6dd30c2
   /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/std/src/sys_common/backtrace.rs:122
60 std::rt::lang_start::{{closure}}::h94d93bd9b2c4c3df
   /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/std/src/rt.rs:145
61 core::ops::function::impls::<impl core::ops::function::FnOnce<A> for &F>::call_once::hed516d662f36277a
   /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/core/src/ops/function.rs:280
   std::panicking::try::do_call::h91daf232e24a6a7e
   /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/std/src/panicking.rs:492
   std::panicking::try::h2c57c968d638ad44
   /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/std/src/panicking.rs:456
   std::panic::catch_unwind::h025a44fc3d544096
   /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/std/src/panic.rs:137
   std::rt::lang_start_internal::{{closure}}::h82476584b98e23f5
   /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/std/src/rt.rs:128
   std::panicking::try::do_call::h1fb3106e2c2e2c17
   /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/std/src/panicking.rs:492
   std::panicking::try::h41dca1e11e9d8387
   /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/std/src/panicking.rs:456
   std::panic::catch_unwind::h22e1c738a7065c7a
   /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/std/src/panic.rs:137
   std::rt::lang_start_internal::h2eada4ac4f4ee168
   /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/std/src/rt.rs:128
62 std::rt::lang_start::h25596458f0e7b461
   /rustc/87588a2afd9ca903366f0deaf84d805f34469384/library/std/src/rt.rs:144
63 _main

[killme2008]

After adding some debug log, found two wal entries with the same sequence id:

2022-10-25T12:43:19.879477Z  INFO storage::region::writer: 1903 Some(WriteBatch { schema: Schema { column_schemas: [ColumnSchema { name: "instance", data_type: String(StringType), is_nullable: true, default_constraint: None, metadata: {} }, ColumnSchema { name: "job", data_type: String(StringType), is_nullable: true, default_constraint: None, metadata: {} }, ColumnSchema { name: "quantile", data_type: String(StringType), is_nullable: true, default_constraint: None, metadata: {} }, ColumnSchema { name: "greptime_timestamp", data_type: Timestamp(TimestampType { unit: Millisecond }), is_nullable: false, default_constraint: None, metadata: {} }, ColumnSchema { name: "greptime_value", data_type: Float64(Float64), is_nullable: true, default_constraint: None, metadata: {} }], name_to_index: {"greptime_timestamp": 3, "job": 1, "greptime_value": 4, "quantile": 2, "instance": 0}, arrow_schema: Schema { fields: [Field { name: "instance", data_type: Utf8, is_nullable: true, metadata: {} }, Field { name: "job", data_type: Utf8, is_nullable: true, metadata: {} }, Field { name: "quantile", data_type: Utf8, is_nullable: true, metadata: {} }, Field { name: "greptime_timestamp", data_type: Timestamp(Millisecond, None), is_nullable: false, metadata: {} }, Field { name: "greptime_value", data_type: Float64, is_nullable: true, metadata: {} }], metadata: {"greptime:timestamp_column": "greptime_timestamp", "greptime:version": "0"} }, timestamp_index: Some(3), version: 0 }, mutations: [Put(PutData { columns: {"quantile": StringVector { array: Utf8Array[0.25] }, "instance": StringVector { array: Utf8Array[localhost:9090] }, "job": StringVector { array: Utf8Array[prometheus] }, "greptime_timestamp": TimestampVector { array: PrimitiveVector { array: Timestamp(Millisecond, None)[2022-10-25 03:34:59.389] } }, "greptime_value": PrimitiveVector { array: Float64[0.000203625] }} })], num_rows: 1 })
2022-10-25T12:43:19.881808Z  INFO storage::region::writer: 1903 Some(WriteBatch { schema: Schema { column_schemas: [ColumnSchema { name: "instance", data_type: String(StringType), is_nullable: true, default_constraint: None, metadata: {} }, ColumnSchema { name: "job", data_type: String(StringType), is_nullable: true, default_constraint: None, metadata: {} }, ColumnSchema { name: "quantile", data_type: String(StringType), is_nullable: true, default_constraint: None, metadata: {} }, ColumnSchema { name: "greptime_timestamp", data_type: Timestamp(TimestampType { unit: Millisecond }), is_nullable: false, default_constraint: None, metadata: {} }, ColumnSchema { name: "greptime_value", data_type: Float64(Float64), is_nullable: true, default_constraint: None, metadata: {} }], name_to_index: {"greptime_timestamp": 3, "instance": 0, "job": 1, "quantile": 2, "greptime_value": 4}, arrow_schema: Schema { fields: [Field { name: "instance", data_type: Utf8, is_nullable: true, metadata: {} }, Field { name: "job", data_type: Utf8, is_nullable: true, metadata: {} }, Field { name: "quantile", data_type: Utf8, is_nullable: true, metadata: {} }, Field { name: "greptime_timestamp", data_type: Timestamp(Millisecond, None), is_nullable: false, metadata: {} }, Field { name: "greptime_value", data_type: Float64, is_nullable: true, metadata: {} }], metadata: {"greptime:timestamp_column": "greptime_timestamp", "greptime:version": "0"} }, timestamp_index: Some(3), version: 0 }, mutations: [Put(PutData { columns: {"quantile": StringVector { array: Utf8Array[0] }, "job": StringVector { array: Utf8Array[prometheus] }, "greptime_value": PrimitiveVector { array: Float64[0.000057083] }, "greptime_timestamp": TimestampVector { array: PrimitiveVector { array: Timestamp(Millisecond, None)[2022-10-25 03:20:14.403] } }, "instance": StringVector { array: Utf8Array[localhost:9090] }} })], num_rows: 1 })

[evenyag]

I'm able to reproduce this problem on my machine, after adding some debug logs, I find out that the RegionWriter

• attempted to write request with same sequence (execute block 1 in the code) twice
• block 2 also executed twice
• set_committed_sequence only been called once
• No error during executing write

Looks like one async task was dropped immediately after block 2.

async fn write<S: LogStore>(
    &mut self,
    version_mutex: &Mutex<()>,
    _ctx: &WriteContext,
    mut request: WriteBatch,
    writer_ctx: WriterContext<'_, S>,
) -> Result<WriteResponse> {
    let _lock = version_mutex.lock().await;

    // 1
    let committed_sequence = version_control.committed_sequence();
    let next_sequence = committed_sequence + 1;

    // 2
    writer_ctx
        .wal
        .write_to_wal(
            next_sequence,
            wal_header,
            Payload::WriteBatchArrow(&request),
        )
        .await
        .map_err(|e| error!("wtf: {:?}", e));

    // 3
    version_control.set_sequence(next_sequence);

    Ok(WriteResponse {})
}

We also added some logs to the AppendResponse::complete and find out the receiver sometimes would be dropped before notify.

The future task seems had been dropped, or cancelled after write_to_wal() done, which might caused by a timeout of the gRPC layer. I have simulated such case in the playground

use tokio::time::{sleep, Duration, timeout};

#[tokio::main]
async fn main() {
    let f = async {
        print(1).await;
        println!("1 is done");
        print(2).await;
        println!("2 is done");
        print(3).await;
        println!("3 is done");
    };

    if let Err(_) = timeout(Duration::from_millis(150), f).await {
        println!("timeout");
    }
    
    sleep(Duration::from_millis(300)).await;
    println!("exit")
}

async fn print(val: u32) {
    sleep(Duration::from_millis(100)).await;
    println!("val is {}", val);
}

Output

val is 1
1 is done
timeout
exit

Note that whether holding a mutex inside the async block doesn't affect the result.

[evenyag]

Some related logs

2022-11-01T09:02:09.799207Z  INFO storage::region::writer: write finish 4535485464576 to 2515
// Try to write 2516
2022-11-01T09:02:09.799302Z  INFO storage::region::writer: going set 4535485464576 to 2516

// On AppendResponse::complete, 4561255268352 is region id and 2516 is sequence
2022-11-01T09:02:09.818794Z ERROR log_store::fs::file: 4561255268352 complete err 126, 59838468
2022-11-01T09:02:09.837753Z ERROR log_store::fs::file: 4535485464576 complete err 2516, 59839386

// Write 2516 again
2022-11-01T09:02:10.427401Z  INFO storage::region::writer: going set 4535485464576 to 2516
// Set committed sequence to 2516
2022-11-01T09:02:10.466234Z  INFO storage::region::writer: write finish 4535485464576 to 2516
2022-11-01T09:02:10.467689Z  INFO storage::region::writer: going set 4535485464576 to 2517

Panics on restart

2022-11-01T09:02:51.187088Z ERROR storage::region::writer: Sequence should not decrease during replay, found 2516 <= 2516, region_id: 4535485464576, region_name: 1056_0000000000, flushed_sequence: 0, num_requests: 2517
2022-11-01T09:02:51.207635Z ERROR greptime: Fatal error occurs! err.msg=Failed to start datanode, source: Failed to create catalog list, source: Failed to open table, table info: greptime.public.net_conntrack_dialer_conn_failed_total, id: 1056, source: Failed to open region, region: 1056_0000000000, source: Sequence of region should increase monotonically (2516 > 2516) err.code=Unexpected err.source=Failed to create catalog list, source: Failed to open table, table info: greptime.public.net_conntrack_dialer_conn_failed_total, id: 1056, source: Failed to open region, region: 1056_0000000000, source: Sequence of region should increase monotonically (2516 > 2516) err.source.sources=[Failed to open table, table info: greptime.public.net_conntrack_dialer_conn_failed_total, id: 1056, source: Failed to open region, region: 1056_0000000000, source: Sequence of region should increase monotonically (2516 > 2516), Failed to open region, region: 1056_0000000000, source: Sequence of region should increase monotonically (2516 > 2516), Sequence of region should increase monotonically (2516 > 2516)]

Some logs with high latency in frontend, may not be relevant

2022-11-01T09:02:03.445236Z ERROR tower_http::trace::on_failure: response failed classification=Status code: 500 Internal Server Error latency=7 ms
2022-11-01T09:02:22.503718Z ERROR tower_http::trace::on_failure: response failed classification=Status code: 500 Internal Server Error latency=12680 ms
2022-11-01T09:02:22.506452Z ERROR tower_http::trace::on_failure: response failed classification=Status code: 500 Internal Server Error latency=12683 ms
2022-11-01T09:02:22.508444Z ERROR tower_http::trace::on_failure: response failed classification=Status code: 500 Internal Server Error latency=12685 ms

[evenyag]

Since the write process of the storage engine or even the table engine isn't cancellation safe, so maybe we need to spawn it to a runtime instead of executing it in the io runtime, like this demo and what #376 does

use tokio::time::{sleep, Duration, timeout};

#[tokio::main]
async fn main() {
    let f = tokio::spawn(async {
        print(1).await;
        println!("1 is done");
        print(2).await;
        println!("2 is done");
        print(3).await;
        println!("3 is done");
    });

    if let Err(_) = timeout(Duration::from_millis(150), f).await {
        println!("timeout");
    }
    
    sleep(Duration::from_millis(400)).await;
    println!("exit")
}

async fn print(val: u32) {
    sleep(Duration::from_millis(100)).await;
    println!("val is {}", val);
}