2023-08-30T19:08:57.488522Z WARN sqld: No authentication specified, the server will not require authentication
2023-08-30T19:08:57.488574Z WARN sqld: No authentication specified, the server will not require authentication
2023-08-30T19:08:57.488750Z WARN sqld: No server heartbeat configured
2023-08-30T19:08:57.488775Z INFO sqld::http: listening for HTTP requests on 127.0.0.1:8080
2023-08-30T19:09:00.405920Z DEBUG request{method=GET uri=/v2 version=HTTP/1.1}: sqld::http: got request: GET /v2
2023-08-30T19:09:00.406080Z DEBUG request{method=GET uri=/v2 version=HTTP/1.1}: tower_http::trace::on_response: finished processing request latency=250 μs status=200
2023-08-30T19:09:00.408028Z DEBUG request{method=POST uri=/v2/pipeline version=HTTP/1.1}: sqld::http: got request: POST /v2/pipeline
2023-08-30T19:09:00.408666Z INFO request{method=POST uri=/v2/pipeline version=HTTP/1.1}: sqld::replication::primary::logger: SQLite autocheckpoint: 1000
2023-08-30T19:09:00.409469Z DEBUG sqld_libsql_bindings::wal_hook: Opening WAL /home/lucio/code/sqld/data.sqld/dbs/default/data-wal
2023-08-30T19:09:00.410204Z DEBUG sqld_libsql_bindings::wal_hook: Opening WAL /home/lucio/code/sqld/data.sqld/dbs/default/data-wal
2023-08-30T19:09:00.410423Z DEBUG request{method=POST uri=/v2/pipeline version=HTTP/1.1}: sqld::hrana::http::stream: Stream 11807148810473912899 was created with baton seq 10982089918573982282
2023-08-30T19:09:00.410461Z DEBUG request{method=POST uri=/v2/pipeline version=HTTP/1.1}: sqld::hrana::http: pipeline:{ Hrana2, Execute(ExecuteStreamReq { stmt: Stmt { sql: Some("SELECT 1"), sql_id: None, args: [], named_args: [], want_rows: Some(false) } }) }
2023-08-30T19:09:00.411035Z DEBUG request{method=POST uri=/v2/pipeline version=HTTP/1.1}: sqld::hrana::http::stream: Stream 11807148810473912899 was released for further use
2023-08-30T19:09:00.411116Z DEBUG request{method=POST uri=/v2/pipeline version=HTTP/1.1}: tower_http::trace::on_response: finished processing request latency=3111 μs status=200
2023-08-30T19:09:10.489277Z DEBUG sqld::hrana::http::stream: Stream 11807148810473912899 was expired
2023-08-30T19:09:15.712858Z DEBUG request{method=POST uri=/v2/pipeline version=HTTP/1.1}: sqld::http: got request: POST /v2/pipeline
2023-08-30T19:09:15.713090Z ERROR request{method=POST uri=/v2/pipeline version=HTTP/1.1}: sqld::hrana::http: hrana server: Stream handle for 11807148810473912899 is expired
2023-08-30T19:09:15.713198Z DEBUG request{method=POST uri=/v2/pipeline version=HTTP/1.1}: tower_http::trace::on_response: finished processing request latency=426 μs status=500
2023-08-30T19:09:15.713233Z ERROR request{method=POST uri=/v2/pipeline version=HTTP/1.1}: tower_http::trace::on_failure: response failed classification=Status code: 500 Internal Server Error latency=0 ms
2023-08-30T19:09:15.714163Z DEBUG request{method=GET uri=/v2 version=HTTP/1.1}: sqld::http: got request: GET /v2
2023-08-30T19:09:15.714231Z DEBUG request{method=GET uri=/v2 version=HTTP/1.1}: tower_http::trace::on_response: finished processing request latency=89 μs status=200
2023-08-30T19:09:15.714965Z DEBUG request{method=POST uri=/v2/pipeline version=HTTP/1.1}: sqld::http: got request: POST /v2/pipeline
2023-08-30T19:09:15.715207Z DEBUG sqld_libsql_bindings::wal_hook: Opening WAL /home/lucio/code/sqld/data.sqld/dbs/default/data-wal
2023-08-30T19:09:15.715410Z DEBUG request{method=POST uri=/v2/pipeline version=HTTP/1.1}: sqld::hrana::http::stream: Stream 16474977572153495726 was created with baton seq 4530602480787678093
2023-08-30T19:09:15.715443Z DEBUG request{method=POST uri=/v2/pipeline version=HTTP/1.1}: sqld::hrana::http: pipeline:{ Hrana2, Execute(ExecuteStreamReq { stmt: Stmt { sql: Some("select * from sqlite_master"), sql_id: None, args: [], named_args: [], want_rows: Some(true) } }) }
2023-08-30T19:09:15.716078Z DEBUG request{method=POST uri=/v2/pipeline version=HTTP/1.1}: sqld::hrana::http::stream: Stream 16474977572153495726 was released for further use
2023-08-30T19:09:15.716180Z DEBUG request{method=POST uri=/v2/pipeline version=HTTP/1.1}: tower_http::trace::on_response: finished processing request latency=1234 μs status=200
2023-08-30T19:09:26.489536Z DEBUG sqld::hrana::http::stream: Stream 16474977572153495726 was expired
2023-08-30T19:09:29.149532Z DEBUG request{method=POST uri=/v2/pipeline version=HTTP/1.1}: sqld::http: got request: POST /v2/pipeline
2023-08-30T19:09:29.149738Z ERROR request{method=POST uri=/v2/pipeline version=HTTP/1.1}: sqld::hrana::http: hrana server: Stream handle for 16474977572153495726 is expired
2023-08-30T19:09:29.149824Z DEBUG request{method=POST uri=/v2/pipeline version=HTTP/1.1}: tower_http::trace::on_response: finished processing request latency=355 μs status=500
2023-08-30T19:09:29.149859Z ERROR request{method=POST uri=/v2/pipeline version=HTTP/1.1}: tower_http::trace::on_failure: response failed classification=Status code: 500 Internal Server Error latency=0 ms
2023-08-30T19:09:29.150611Z DEBUG request{method=GET uri=/v2 version=HTTP/1.1}: sqld::http: got request: GET /v2
2023-08-30T19:09:29.150703Z DEBUG request{method=GET uri=/v2 version=HTTP/1.1}: tower_http::trace::on_response: finished processing request latency=125 μs status=200
2023-08-30T19:09:29.151768Z DEBUG request{method=POST uri=/v2/pipeline version=HTTP/1.1}: sqld::http: got request: POST /v2/pipeline
2023-08-30T19:09:29.152276Z DEBUG sqld_libsql_bindings::wal_hook: Opening WAL /home/lucio/code/sqld/data.sqld/dbs/default/data-wal
2023-08-30T19:09:29.152504Z DEBUG request{method=POST uri=/v2/pipeline version=HTTP/1.1}: sqld::hrana::http::stream: Stream 2594905872403293941 was created with baton seq 6929030302953878511
2023-08-30T19:09:29.152538Z DEBUG request{method=POST uri=/v2/pipeline version=HTTP/1.1}: sqld::hrana::http: pipeline:{ Hrana2, Execute(ExecuteStreamReq { stmt: Stmt { sql: Some("select * from sqlite_master"), sql_id: None, args: [], named_args: [], want_rows: Some(true) } }) }
2023-08-30T19:09:29.153144Z DEBUG request{method=POST uri=/v2/pipeline version=HTTP/1.1}: sqld::hrana::http::stream: Stream 2594905872403293941 was released for further use
2023-08-30T19:09:29.153246Z DEBUG request{method=POST uri=/v2/pipeline version=HTTP/1.1}: tower_http::trace::on_response: finished processing request latency=1497 μs status=200
2023-08-30T19:09:39.489057Z DEBUG sqld::hrana::http::stream: Stream 2594905872403293941 was expired
The shell seems to reuse stream expiration tokens and they keep expiring returning a 500 which is incorrect. We should investigate why this is happening and fix the error code.
To reproduce:
RUST_LOG=tower_http=debug,sqld=debug,info cargo run
and then turso db shell http://localhost:8080 and let it sit for a bit to let the stream expire and send requests.
The shell seems to reuse stream expiration tokens and they keep expiring returning a 500 which is incorrect. We should investigate why this is happening and fix the error code.
To reproduce:
RUST_LOG=tower_http=debug,sqld=debug,info cargo runand then
turso db shell http://localhost:8080and let it sit for a bit to let the stream expire and send requests.