search

tursodatabase / libsql

libSQL is a fork of SQLite that is both Open Source, and Open Contributions.
https://turso.tech/libsql
MIT License
9.54k stars 252 forks source link

Schema migrations fail when run on a client connected to a replica #1589

Closed haaawk closed 2 months ago

haaawk commented 2 months ago 
2024-07-22T18:24:12.169 app[0801e45b637318] ord [info] 9: core::ops::function::FnOnce::call_once{{vtable.shim}}

2024-07-22T18:24:12.169 app[0801e45b637318] ord [info] 10: std::sys::pal::unix::thread::Thread::new::thread_start

2024-07-22T18:24:12.169 app[0801e45b637318] ord [info] 11: start_thread

2024-07-22T18:24:12.169 app[0801e45b637318] ord [info] 12: clone

2024-07-22T18:24:12.221 app[0801e45b637318] ord [info] 2024-07-22T18:24:12.221159Z INFO libsql_server::hrana::ws: Received HTTP upgrade connection #9

2024-07-22T18:24:12.270 app[e7843293ce3248] iad [info] thread 'tokio-runtime-worker' panicked at libsql-server/src/rpc/proxy.rs:583:22:

2024-07-22T18:24:12.270 app[e7843293ce3248] iad [info] invalid call to stream_exec: not a primary

2024-07-22T18:24:12.270 app[e7843293ce3248] iad [info] stack backtrace:

2024-07-22T18:24:12.271 app[e7843293ce3248] iad [info] 0: 0x5588a116cd52 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::hffecb437d922f988

2024-07-22T18:24:12.271 app[e7843293ce3248] iad [info] 1: 0x5588a119aebc - core::fmt::write::hd9a8d7d029f9ea1a

2024-07-22T18:24:12.272 app[e7843293ce3248] iad [info] 2: 0x5588a116973f - std::io::Write::write_fmt::h0e1226b2b8d973fe

2024-07-22T18:24:12.272 app[e7843293ce3248] iad [info] 3: 0x5588a116cb24 - std::sys_common::backtrace::print::he907f6ad7eee41cb

2024-07-22T18:24:12.272 app[e7843293ce3248] iad [info] 4: 0x5588a116e15b - std::panicking::default_hook::{{closure}}::h3926193b61c9ca9b

2024-07-22T18:24:12.272 app[e7843293ce3248] iad [info] 5: 0x5588a116deb3 - std::panicking::default_hook::h25ba2457dea68e65

2024-07-22T18:24:12.272 app[e7843293ce3248] iad [info] 6: 0x5588a116e5fd - std::panicking::rust_panic_with_hook::h0ad14d90dcf5224f

2024-07-22T18:24:12.272 app[e7843293ce3248] iad [info] 7: 0x5588a116e4d2 - std::panicking::begin_panic_handler::{{closure}}::h4a1838a06f542647

2024-07-22T18:24:12.272 app[e7843293ce3248] iad [info] 8: 0x5588a116d226 - std::sys_common::backtrace::__rust_end_short_backtrace::h77cc4dc3567ca904

2024-07-22T18:24:12.272 app[e7843293ce3248] iad [info] 9: 0x5588a116e204 - rust_begin_unwind

2024-07-22T18:24:12.272 app[e7843293ce3248] iad [info] 10: 0x55889fe06d05 - core::panicking::panic_fmt::h940d4fd01a4b4fd1

2024-07-22T18:24:12.272 app[e7843293ce3248] iad [info] 11: 0x5588a1198cd1 - core::panicking::panic_display::h277de99b44f66bbb

2024-07-22T18:24:12.272 app[e7843293ce3248] iad [info] 12: 0x55889fe06ccb - core::option::expect_failed::h9d76e63e47b0f089

2024-07-22T18:24:12.272 app[e7843293ce3248] iad [info] 13: 0x5588a0829bf9 - <libsql_server::rpc::proxy::ProxyService as libsql_replication::rpc::proxy::proxy_server::Proxy>::stream_exec::{{closure}}::h83291f509c71af67

2024-07-22T18:24:12.272 app[e7843293ce3248] iad [info] 14: 0x5588a006cdff - <<libsql_replication::rpc::proxy::proxy_server::ProxyServer<T> as tower_service::Service<http::request::Request<B>>>::call::StreamExecSvc<T> as tonic::server::service::StreamingService<libsql_replication::rpc::proxy::ExecReq>>::call::{{closure}}::h797ee083c0178815

2024-07-22T18:24:12.272 app[e7843293ce3248] iad [info] 15: 0x5588a002bf97 - <libsql_replication::rpc::proxy::proxy_server::ProxyServer<T> as tower_service::Service<http::request::Request<B>>>::call::{{closure}}::h90181def7e332d8e

2024-07-22T18:24:12.272 app[e7843293ce3248] iad [info] 16: 0x55889fe3f98f - <tower::util::map_response::MapResponseFuture<F,N> as core::future::future::Future>::poll::h7a0e359bf8fc0a5c

2024-07-22T18:24:12.272 app[e7843293ce3248] iad [info] 17: 0x5588a03fe065 - <axum::routing::route::RouteFuture<B,E> as core::future::future::Future>::poll::h829c87c85f510ac1

2024-07-22T18:24:12.272 app[e7843293ce3248] iad [info] 18: 0x5588a002f125 - <tower_http::trace::future::ResponseFuture<Fut,C,OnResponseT,OnBodyChunkT,OnEosT,OnFailureT> as core::future::future::Future>::poll::h5dcf601c8dde0faf

2024-07-22T18:24:12.272 app[e7843293ce3248] iad [info] 19: 0x5588a001d480 - <libsql_server::h2c::H2c<S,B> as tower_service::Service<http::request::Request<hyper::body::body::Body>>>::call::{{closure}}::h861874e968d2f8e8

2024-07-22T18:24:12.272 app[e7843293ce3248] iad [info] 20: 0x5588a040185e - <hyper::proto::h2::server::H2Stream<F,B> as core::future::future::Future>::poll::h2bb6bcfc8a1c35a1

2024-07-22T18:24:12.272 app[e7843293ce3248] iad [info] 21: 0x5588a02aeaff - tokio::runtime::task::raw::poll::hb9319f35ad42efa4

2024-07-22T18:24:12.272 app[e7843293ce3248] iad [info] 22: 0x5588a10cdfce - tokio::runtime::scheduler::multi_thread::worker::Context::run_task::h2b4c035a69dac5ca

2024-07-22T18:24:12.272 app[e7843293ce3248] iad [info] 23: 0x5588a10cc868 - tokio::runtime::scheduler::multi_thread::worker::run::h2b133ff658bc00b2

2024-07-22T18:24:12.272 app[e7843293ce3248] iad [info] 24: 0x5588a10d9a52 - tokio::runtime::task::raw::poll::h1aa3706d4411d526

2024-07-22T18:24:12.272 app[e7843293ce3248] iad [info] 25: 0x5588a10b6cbb - std::sys_common::backtrace::__rust_begin_short_backtrace::hb8067cdfb502752e

2024-07-22T18:24:12.272 app[e7843293ce3248] iad [info] 26: 0x5588a10b8100 - core::ops::function::FnOnce::call_once{{vtable.shim}}::hc25a17b31c557b13

2024-07-22T18:24:12.272 app[e7843293ce3248] iad [info] 27: 0x5588a1173ab5 - std::sys::pal::unix::thread::Thread::new::thread_start::h420dad5cf01a9f35

2024-07-22T18:24:12.272 app[e7843293ce3248] iad [info] 28: 0x7f333a0abea7 - start_thread

2024-07-22T18:24:12.272 app[e7843293ce3248] iad [info] 29: 0x7f3339e81a6f - clone

2024-07-22T18:24:12.272 app[e7843293ce3248] iad [info] 30: 0x0 - <unknown>

2024-07-22T18:24:12.283 app[0801e45b637318] ord [info] 2024-07-22T18:24:12.283492Z ERROR libsql_server::hrana::ws: HTTP upgrade connection #9 failed: Failed to execute queries via RPC protocol: `status: Cancelled, message: "h2 protocol error: http2 error: stream error received: stream no longer needed", details: [], metadata: MetadataMap { headers: {} }`

2024-07-22T18:24:12.283 app[0801e45b637318] ord [info] Caused by:

2024-07-22T18:24:12.283 app[0801e45b637318] ord [info] 0: status: Cancelled, message: "h2 protocol error: http2 error: stream error received: stream no longer needed", details: [], metadata: MetadataMap { headers: {} }

2024-07-22T18:24:12.283 app[0801e45b637318] ord [info] 1: transport error

2024-07-22T18:24:12.283 app[0801e45b637318] ord [info] 2: http2 error: stream error received: stream no longer needed

2024-07-22T18:24:12.283 app[0801e45b637318] ord [info] 3: stream error received: stream no longer needed

2024-07-22T18:24:12.283 app[0801e45b637318] ord [info] Stack backtrace:

2024-07-22T18:24:12.283 app[0801e45b637318] ord [info] 0: anyhow::error::<impl core::convert::From<E> for anyhow::Error>::from

2024-07-22T18:24:12.283 app[0801e45b637318] ord [info] 1: libsql_server::hrana::ws::session::catch_stmt_error

2024-07-22T18:24:12.283 app[0801e45b637318] ord [info] 2: libsql_server::hrana::ws::session::handle_request::{{closure}}::{{closure}}::{{closure}}

2024-07-22T18:24:12.283 app[0801e45b637318] ord [info] 3: libsql_server::hrana::ws::session::stream_spawn::{{closure}}

2024-07-22T18:24:12.283 app[0801e45b637318] ord [info] 4: tokio::runtime::task::raw::poll

2024-07-22T18:24:12.283 app[0801e45b637318] ord [info] 5: tokio::runtime::scheduler::multi_thread::worker::Context::run_task

2024-07-22T18:24:12.283 app[0801e45b637318] ord [info] 6: tokio::runtime::scheduler::multi_thread::worker::run

2024-07-22T18:24:12.283 app[0801e45b637318] ord [info] 7: tokio::runtime::task::raw::poll

2024-07-22T18:24:12.283 app[0801e45b637318] ord [info] 8: std::sys_common::backtrace::__rust_begin_short_backtrace

2024-07-22T18:24:12.283 app[0801e45b637318] ord [info] 9: core::ops::function::FnOnce::call_once{{vtable.shim}}

2024-07-22T18:24:12.283 app[0801e45b637318] ord [info] 10: std::sys::pal::unix::thread::Thread::new::thread_start

2024-07-22T18:24:12.283 app[0801e45b637318] ord [info] 11: start_thread

2024-07-22T18:24:12.283 app[0801e45b637318] ord [info] 12: clone

2024-07-22T18:24:31.099 app[0801e45b637318] ord [info] 2024-07-22T18:24:31.099483Z INFO libsql_server::hrana::ws: Received HTTP upgrade connection #10

2024-07-22T18:24:31.138 app[0801e45b637318] ord [info] 2024-07-22T18:24:31.138206Z ERROR sqlite3Parser: near ID, "Token(Some("LIST"))": syntax error

2024-07-22T18:27:51.131 app[0801e45b637318] ord [info] 2024-07-22T18:27:51.131233Z WARN libsql_server::hrana::ws::conn: Could not send close frame to WebSocket of connection #10: Protocol(SendAfterClosing)

2024-07-22T18:27:51.131 app[0801e45b637318] ord [info] 2024-07-22T18:27:51.131310Z INFO libsql_server::hrana::ws: HTTP upgrade connection #10 was terminated

2024-07-22T18:28:15.278 app[0801e45b637318] ord [info] 2024-07-22T18:28:15.277874Z ERROR libsql_server::hrana::http: hrana server: Stream handle for 7481654112219484941 is expired

2024-07-22T18:28:15.292 app[e7843293ce3248] iad [info] thread 'tokio-runtime-worker' panicked at libsql-server/src/rpc/proxy.rs:583:22:

2024-07-22T18:28:15.292 app[e7843293ce3248] iad [info] invalid call to stream_exec: not a primary

2024-07-22T18:28:15.292 app[e7843293ce3248] iad [info] stack backtrace:

2024-07-22T18:28:15.293 app[e7843293ce3248] iad [info] 0: 0x5588a116cd52 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::hffecb437d922f988

2024-07-22T18:28:15.293 app[e7843293ce3248] iad [info] 1: 0x5588a119aebc - core::fmt::write::hd9a8d7d029f9ea1a

2024-07-22T18:28:15.294 app[e7843293ce3248] iad [info] 2: 0x5588a116973f - std::io::Write::write_fmt::h0e1226b2b8d973fe

2024-07-22T18:28:15.294 app[e7843293ce3248] iad [info] 3: 0x5588a116cb24 - std::sys_common::backtrace::print::he907f6ad7eee41cb

2024-07-22T18:28:15.295 app[e7843293ce3248] iad [info] 4: 0x5588a116e15b - std::panicking::default_hook::{{closure}}::h3926193b61c9ca9b

2024-07-22T18:28:15.296 app[e7843293ce3248] iad [info] 5: 0x5588a116deb3 - std::panicking::default_hook::h25ba2457dea68e65

2024-07-22T18:28:15.296 app[e7843293ce3248] iad [info] 6: 0x5588a116e5fd - std::panicking::rust_panic_with_hook::h0ad14d90dcf5224f

2024-07-22T18:28:15.297 app[e7843293ce3248] iad [info] 7: 0x5588a116e4d2 - std::panicking::begin_panic_handler::{{closure}}::h4a1838a06f542647

2024-07-22T18:28:15.297 app[e7843293ce3248] iad [info] 8: 0x5588a116d226 - std::sys_common::backtrace::__rust_end_short_backtrace::h77cc4dc3567ca904

2024-07-22T18:28:15.297 app[e7843293ce3248] iad [info] 9: 0x5588a116e204 - rust_begin_unwind

2024-07-22T18:28:15.297 app[e7843293ce3248] iad [info] 10: 0x55889fe06d05 - core::panicking::panic_fmt::h940d4fd01a4b4fd1

2024-07-22T18:28:15.297 app[e7843293ce3248] iad [info] 11: 0x5588a1198cd1 - core::panicking::panic_display::h277de99b44f66bbb

2024-07-22T18:28:15.298 app[e7843293ce3248] iad [info] 12: 0x55889fe06ccb - core::option::expect_failed::h9d76e63e47b0f089

2024-07-22T18:28:15.298 app[e7843293ce3248] iad [info] 13: 0x5588a0829bf9 - <libsql_server::rpc::proxy::ProxyService as libsql_replication::rpc::proxy::proxy_server::Proxy>::stream_exec::{{closure}}::h83291f509c71af67

2024-07-22T18:28:15.299 app[e7843293ce3248] iad [info] 14: 0x5588a006cdff - <<libsql_replication::rpc::proxy::proxy_server::ProxyServer<T> as tower_service::Service<http::request::Request<B>>>::call::StreamExecSvc<T> as tonic::server::service::StreamingService<libsql_replication::rpc::proxy::ExecReq>>::call::{{closure}}::h797ee083c0178815

2024-07-22T18:28:15.299 app[e7843293ce3248] iad [info] 15: 0x5588a002bf97 - <libsql_replication::rpc::proxy::proxy_server::ProxyServer<T> as tower_service::Service<http::request::Request<B>>>::call::{{closure}}::h90181def7e332d8e

2024-07-22T18:28:15.299 app[e7843293ce3248] iad [info] 16: 0x55889fe3f98f - <tower::util::map_response::MapResponseFuture<F,N> as core::future::future::Future>::poll::h7a0e359bf8fc0a5c

2024-07-22T18:28:15.299 app[e7843293ce3248] iad [info] 17: 0x5588a03fe065 - <axum::routing::route::RouteFuture<B,E> as core::future::future::Future>::poll::h829c87c85f510ac1

2024-07-22T18:28:15.299 app[e7843293ce3248] iad [info] 18: 0x5588a002f125 - <tower_http::trace::future::ResponseFuture<Fut,C,OnResponseT,OnBodyChunkT,OnEosT,OnFailureT> as core::future::future::Future>::poll::h5dcf601c8dde0faf

2024-07-22T18:28:15.299 app[e7843293ce3248] iad [info] 19: 0x5588a001d480 - <libsql_server::h2c::H2c<S,B> as tower_service::Service<http::request::Request<hyper::body::body::Body>>>::call::{{closure}}::h861874e968d2f8e8

2024-07-22T18:28:15.299 app[e7843293ce3248] iad [info] 20: 0x5588a040185e - <hyper::proto::h2::server::H2Stream<F,B> as core::future::future::Future>::poll::h2bb6bcfc8a1c35a1

2024-07-22T18:28:15.299 app[e7843293ce3248] iad [info] 21: 0x5588a02aeaff - tokio::runtime::task::raw::poll::hb9319f35ad42efa4

2024-07-22T18:28:15.299 app[e7843293ce3248] iad [info] 22: 0x5588a10cdfce - tokio::runtime::scheduler::multi_thread::worker::Context::run_task::h2b4c035a69dac5ca

2024-07-22T18:28:15.299 app[e7843293ce3248] iad [info] 23: 0x5588a10cc868 - tokio::runtime::scheduler::multi_thread::worker::run::h2b133ff658bc00b2

2024-07-22T18:28:15.299 app[e7843293ce3248] iad [info] 24: 0x5588a10d9a52 - tokio::runtime::task::raw::poll::h1aa3706d4411d526

2024-07-22T18:28:15.299 app[e7843293ce3248] iad [info] 25: 0x5588a10b6cbb - std::sys_common::backtrace::__rust_begin_short_backtrace::hb8067cdfb502752e

2024-07-22T18:28:15.299 app[e7843293ce3248] iad [info] 26: 0x5588a10b8100 - core::ops::function::FnOnce::call_once{{vtable.shim}}::hc25a17b31c557b13

2024-07-22T18:28:15.299 app[e7843293ce3248] iad [info] 27: 0x5588a1173ab5 - std::sys::pal::unix::thread::Thread::new::thread_start::h420dad5cf01a9f35

2024-07-22T18:28:15.299 app[e7843293ce3248] iad [info] 28: 0x7f333a0abea7 - start_thread

2024-07-22T18:28:15.299 app[e7843293ce3248] iad [info] 29: 0x7f3339e81a6f - clone

2024-07-22T18:28:15.299 app[e7843293ce3248] iad [info] 30: 0x0 - <unknown>

2024-07-22T18:28:15.310 app[0801e45b637318] ord [info] 2024-07-22T18:28:15.310734Z ERROR libsql_server::hrana::http: hrana server: Failed to execute queries via RPC protocol: `status: Cancelled, message: "h2 protocol error: http2 error: stream error received: stream no longer needed", details: [], metadata: MetadataMap { headers: {} }`

2024-07-22T18:28:15.311 app[0801e45b637318] ord [info] 2024-07-22T18:28:15.310861Z ERROR libsql_server::error: HTTP API: 500 Internal Server Error, RpcQueryExecutionError(Status { code: Cancelled, message: "h2 protocol error: http2 error: stream error received: stream no longer needed", source: Some(tonic::transport::Error(Transport, hyper::Error(Http2, Error { kind: Reset(StreamId(2047), CANCEL, Remote) }))) })
haaawk commented 2 months ago

CC @MarinPostma @LucioFranco

LucioFranco commented 2 months ago

fixed in v0.24.18 that I just released

LucioFranco commented 2 months ago

Related PR https://github.com/tursodatabase/libsql/pull/1572