Repository: sebadob/rauthy (language: rust)

Issue:
Upgrade to 0.27.x - Database Error: ColumnDecode
I'm trying to upgrade from `0.26.2-lite` to `0.27.3`. On the first start, I set `MIGRATE_DB_FROM=sqlite:data/rauthy.db` which then fails with:

```
...
2024-12-31T15:07:00.561021Z  WARN rauthy_models::database: 

    Migrating data from 'MIGRATE_DB_FROM'
    This will overwrite possibly existing data in the current database!
    Make sure, that the 'MIGRATE_DB_FROM' was created with the same rauthy verion

    Proceeding in 10 seconds...

                
2024-12-31T15:07:00.561076Z  INFO hiqlite::network::api: Emptying buffered Client Stream responses
2024-12-31T15:07:00.561108Z  INFO hiqlite::network::api: Emptying buffered Client Stream responses
2024-12-31T15:07:00.561134Z  INFO hiqlite::client::stream: Client API WebSocket to localhost:8200 opened successfully
2024-12-31T15:07:00.561145Z  INFO hiqlite::client::stream: Client API WebSocket to localhost:8200 opened successfully
2024-12-31T15:07:01.055796Z  INFO rauthy_models::email: Successfully connected to smtp.example.com via TLS
2024-12-31T15:07:10.567282Z  INFO rauthy_models::migration::db_migrate: Starting migration to another DB
2024-12-31T15:07:10.567652Z ERROR rauthy_error::error_impls: Database Error: ColumnDecode { index: "\"data\"", source: "mismatched types; Rust type `alloc::vec::Vec<u8>` (as SQL type `BLOB`) is not compatible with SQL type `INTEGER`" }
thread 'main' panicked at /work/src/models/src/database.rs:208:25:
Error during db migration: ErrorResponse { timestamp: 1735657630, error: Internal, message: "Internal error, please try again" }
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
```

I'm unsure what I'm doing wrong.


Discussion / hints:
Hey,

this should not happen.
Can you please set `LOG_LEVEL=debug` and try again, so I know which table produces this error?
Before each one, you will get a debug log like `Migrating table: password_policy`.

Edit:

I assume it's about the password policy. There was a bug in past versions which actually corrupted the `data` for it. The only problem currently is, that the auto-fix for this runs after database migrations.
When setting `LOG_LEVEL=debug` it doesn't even start properly and does not try to migrate, it just crashes:

```
2025-01-01T11:19:11.094918Z  INFO rauthy: 2025-01-01 11:19:11.094878213 UTC - Starting Rauthy v0.27.3
2025-01-01T11:19:11.094977Z  INFO rauthy: Log Level set to 'DEBUG'
2025-01-01T11:19:11.095098Z DEBUG rauthy: Starting the persistence layer
2025-01-01T11:19:11.095176Z  WARN hiqlite::dashboard: HQL_PASSWORD_DASHBOARD has not been set and the dashboard will be disabled
2025-01-01T11:19:11.095220Z DEBUG hiqlite::s3: CryptrError::Keys(EncKeys::init() has already been called before)
2025-01-01T11:19:11.113941Z  INFO hiqlite::store::state_machine::sqlite::state_machine: db_exists in stage_machine::new(): true
2025-01-01T11:19:11.114305Z  WARN hiqlite::store::state_machine::sqlite::state_machine: Lock file already exists: data/state_machine/lock
Node did not shut down gracefully - auto-rebuilding State Machine
2025-01-01T11:19:11.123484Z  WARN hiqlite::store::state_machine::sqlite::writer: No metadata exists inside the DB yet
2025-01-01T11:19:11.123531Z  INFO hiqlite::store::state_machine::sqlite::state_machine: applied_state: StateMachineData { last_applied_log_id: None, last_membership: StoredMembership { log_id: None, membership: Membership { configs: [], nodes: {} } }, last_snapshot_id: None }
2025-01-01T11:19:11.123584Z  INFO openraft::storage::helper: get_initial_state vote=T1-N1:committed last_purged_log_id=None last_applied=None committed=None last_log_id=T1-N1-120
2025-01-01T11:19:11.123631Z  WARN hiqlite::store::state_machine::sqlite::writer: No metadata exists inside the DB yet
2025-01-01T11:19:11.123668Z  INFO hiqlite::store::state_machine::sqlite::state_machine: applied_state: StateMachineData { last_applied_log_id: None, last_membership: StoredMembership { log_id: None, membership: Membership { configs: [], nodes: {} } }, last_snapshot_id: None }
2025-01-01T11:19:11.123895Z  INFO openraft::storage::helper: load membership from log: [0..121)
2025-01-01T11:19:11.127236Z  INFO openraft::storage::helper: load key log ids from (None,T1-N1-120]
2025-01-01T11:19:11.128021Z  INFO openraft::engine::engine_impl: startup begin: state: RaftState { vote: UTime { data: Vote { leader_id: LeaderId { term: 1, node_id: 1 }, committed: true }, utime: Some(Instant { tv_sec: 1134238, tv_nsec: 419392512 }) }, committed: None, purged_next: 0, log_ids: LogIdList { key_log_ids: [LogId { leader_id: LeaderId { term: 0, node_id: 0 }, index: 0 }, LogId { leader_id: LeaderId { term: 1, node_id: 1 }, index: 1 }, LogId { leader_id: LeaderId { term: 1, node_id: 1 }, index: 120 }] }, membership_state: MembershipState { committed: EffectiveMembership { log_id: None, membership: Membership { configs: [], nodes: {} }, voter_ids: {} }, effective: EffectiveMembership { log_id: Some(LogId { leader_id: LeaderId { term: 0, node_id: 0 }, index: 0 }), membership: Membership { configs: [{1}], nodes: {1: Node { id: 1, addr_raft: "localhost:8100", addr_api: "localhost:8200" }} }, voter_ids: {1} } }, snapshot_meta: SnapshotMeta { last_log_id: None, last_membership: StoredMembership { log_id: None, membership: Membership { configs: [], nodes: {} } }, snapshot_id: "" }, server_state: Learner, accepted: Accepted { leader_id: LeaderId { term: 0, node_id: 0 }, log_id: None }, io_state: IOState { building_snapshot: false, vote: Vote { leader_id: LeaderId { term: 1, node_id: 1 }, committed: true }, flushed: LogIOId { committed_leader_id: LeaderId { term: 0, node_id: 0 }, log_id: None }, applied: None, snapshot: None, purged: None }, purge_upto: None }, is_leader: true, is_voter: true
2025-01-01T11:19:11.128229Z  INFO openraft::engine::handler::server_state_handler: become leader id=1
2025-01-01T11:19:11.128285Z  INFO openraft::core::raft_core: remove all replication
2025-01-01T11:19:11.132499Z  INFO hiqlite::init: node 1 raft is already initialized
2025-01-01T11:19:11.132565Z  INFO hiqlite::store::state_machine::memory::kv_handler: Cache App running on Thread ThreadId(2)
2025-01-01T11:19:11.132582Z  INFO openraft::storage::helper: get_initial_state vote=T0-N0:uncommitted last_purged_log_id=None last_applied=None committed=None last_log_id=None
2025-01-01T11:19:11.132591Z  INFO hiqlite::store::state_machine::memory::kv_handler: Cache AuthCode running on Thread ThreadId(2)
2025-01-01T11:19:11.132591Z  INFO openraft::storage::helper: load membership from log: [0..0)
2025-01-01T11:19:11.132598Z  INFO openraft::storage::helper: load key log ids from (None,None]
2025-01-01T11:19:11.132599Z  INFO hiqlite::store::state_machine::memory::kv_handler: Cache DeviceCode running on Thread ThreadId(2)
2025-01-01T11:19:11.132603Z  INFO hiqlite::store::state_machine::memory::kv_handler: Cache AuthProviderCallback running on Thread ThreadId(2)
2025-01-01T11:19:11.132606Z  INFO hiqlite::store::state_machine::memory::kv_handler: Cache ClientDynamic running on Thread ThreadId(2)
2025-01-01T11:19:11.132628Z  INFO hiqlite::store::state_machine::memory::kv_handler: Cache ClientEphemeral running on Thread ThreadId(2)
2025-01-01T11:19:11.132632Z  INFO hiqlite::store::state_machine::memory::kv_handler: Cache DPoPNonce running on Thread ThreadId(2)
2025-01-01T11:19:11.132635Z  INFO hiqlite::store::state_machine::memory::kv_handler: Cache IPRateLimit running on Thread ThreadId(2)
2025-01-01T11:19:11.132638Z  INFO hiqlite::store::state_machine::memory::kv_handler: Cache Session running on Thread ThreadId(2)
2025-01-01T11:19:11.132641Z  INFO hiqlite::store::state_machine::memory::kv_handler: Cache PoW running on Thread ThreadId(2)
2025-01-01T11:19:11.132647Z  INFO hiqlite::store::state_machine::memory::kv_handler: Cache User running on Thread ThreadId(2)
2025-01-01T11:19:11.132651Z  INFO hiqlite::store::state_machine::memory::kv_handler: Cache Webauthn running on Thread ThreadId(2)
2025-01-01T11:19:11.132654Z  INFO hiqlite::store::state_machine::sqlite::writer: Applying database migrations
2025-01-01T11:19:11.132673Z  INFO openraft::engine::engine_impl: startup begin: state: RaftState { vote: UTime { data: Vote { leader_id: LeaderId { term: 0, node_id: 0 }, committed: false }, utime: Some(Instant { tv_sec: 1134238, tv_nsec: 424163980 }) }, committed: None, purged_next: 0, log_ids: LogIdList { key_log_ids: [] }, membership_state: MembershipState { committed: EffectiveMembership { log_id: None, membership: Membership { configs: [], nodes: {} }, voter_ids: {} }, effective: EffectiveMembership { log_id: None, membership: Membership { configs: [], nodes: {} }, voter_ids: {} } }, snapshot_meta: SnapshotMeta { last_log_id: None, last_membership: StoredMembership { log_id: None, membership: Membership { configs: [], nodes: {} } }, snapshot_id: "" }, server_state: Learner, accepted: Accepted { leader_id: LeaderId { term: 0, node_id: 0 }, log_id: None }, io_state: IOState { building_snapshot: false, vote: Vote { leader_id: LeaderId { term: 0, node_id: 0 }, committed: false }, flushed: LogIOId { committed_leader_id: LeaderId { term: 0, node_id: 0 }, log_id: None }, applied: None, snapshot: None, purged: None }, purge_upto: None }, is_leader: false, is_voter: false
2025-01-01T11:19:11.132701Z  INFO openraft::engine::engine_impl: startup done: id=1 target_state: Learner
2025-01-01T11:19:11.132733Z  INFO openraft::core::raft_core: received RaftMsg::Initialize: openraft::core::raft_core::RaftCore<_, _, _, _>::handle_api_msg members={1: Node { id: 1, addr_raft: "localhost:8100", addr_api: "localhost:8200" }}
2025-01-01T11:19:11.132757Z  INFO openraft::engine::engine_impl: openraft::engine::engine_impl::Engine<_>::elect, new candidate: {T1-N1:uncommitted@11:19:11.132752, last_log_id:T0-N0-0 progress:{1: false}}
2025-01-01T11:19:11.132864Z  INFO openraft::engine::handler::vote_handler: vote is changing from T0-N0:uncommitted to T1-N1:uncommitted
2025-01-01T11:19:11.132910Z  INFO openraft::core::raft_core: received Notify::VoteResponse: openraft::core::raft_core::RaftCore<_, _, _, _>::handle_notify now=11:19:11.132901 resp={T1-N1:uncommitted, last_log:None}
2025-01-01T11:19:11.132937Z  INFO openraft::engine::engine_impl: openraft::engine::engine_impl::Engine<_>::handle_vote_resp resp={T1-N1:uncommitted, last_log:None} target=1 my_vote=T1-N1:uncommitted my_last_log_id=Some(T0-N0-0)
2025-01-01T11:19:11.132953Z  INFO openraft::proposer::candidate: openraft::proposer::candidate::Candidate<_, _>::grant_by voting={T1-N1:uncommitted@11:19:11.132753, last_log_id:T0-N0-0 progress:{1: true}}
2025-01-01T11:19:11.132958Z  INFO openraft::engine::engine_impl: a quorum granted my vote
2025-01-01T11:19:11.132961Z  INFO openraft::engine::engine_impl: openraft::engine::engine_impl::Engine<_>::establish_leader
2025-01-01T11:19:11.132968Z  INFO openraft::engine::handler::vote_handler: vote is changing from T1-N1:uncommitted to T1-N1:committed
2025-01-01T11:19:11.132971Z  INFO openraft::engine::handler::server_state_handler: become leader id=1
2025-01-01T11:19:11.132979Z  INFO openraft::core::raft_core: remove all replication
2025-01-01T11:19:11.132984Z  INFO hiqlite::start: rpc internal listening on 0.0.0.0:8100
2025-01-01T11:19:11.132998Z  INFO openraft::core::raft_core: received Notify::VoteResponse: openraft::core::raft_core::RaftCore<_, _, _, _>::handle_notify now=11:19:11.132997 resp={T1-N1:committed, last_log:None}
2025-01-01T11:19:11.133004Z DEBUG hiqlite::store::state_machine::sqlite::writer: Last applied migration: 0
2025-01-01T11:19:11.133012Z  INFO openraft::engine::engine_impl: openraft::engine::engine_impl::Engine<_>::handle_vote_resp resp={T1-N1:committed, last_log:None} target=1 my_vote=T1-N1:committed my_last_log_id=Some(T1-N1-1)
2025-01-01T11:19:11.133033Z  INFO hiqlite::start: api external listening on 0.0.0.0:8200
2025-01-01T11:19:11.133171Z  INFO become_cluster_member{raft_type=Sqlite this_node=1 is_pristine_cache_node_1=false election_timeout_max=1500}: hiqlite::init: sqlite raft is already initialized - skipping become_cluster_member()
2025-01-01T11:19:11.133198Z  INFO become_cluster_member{raft_type=Cache this_node=1 is_pristine_cache_node_1=true election_timeout_max=1500}: hiqlite::init: cache raft is already initialized - skipping become_cluster_member()
2025-01-01T11:19:11.133237Z DEBUG rauthy: Starting E-Mail handler
2025-01-01T11:19:11.133247Z DEBUG rauthy: Initializing AppState
2025-01-01T11:19:11.133275Z  INFO hiqlite::client::stream: Client API WebSocket trying to connect to: http://localhost:8200/stream/cache
2025-01-01T11:19:11.133279Z DEBUG rauthy_models::app_state: New AppState on ThreadId(1)
2025-01-01T11:19:11.133283Z  INFO rauthy_models::app_state: Listen URL: http://0.0.0.0:8080
2025-01-01T11:19:11.133286Z  INFO rauthy_models::app_state: Public URL: id.example.com
2025-01-01T11:19:11.133289Z DEBUG rauthy_models::app_state: Argon2id Params: m_cost: 32768, t_cost: 3, p_cost: 2
2025-01-01T11:19:11.133300Z DEBUG rauthy_models::app_state: Issuer: https://id.example.com/auth/v1
2025-01-01T11:19:11.133320Z  INFO hiqlite::client::stream: Client API WebSocket trying to connect to: http://localhost:8200/stream/sqlite
2025-01-01T11:19:11.133351Z DEBUG rauthy: Applying database migrations
2025-01-01T11:19:11.133403Z DEBUG rauthy_models::entity::db_version: Current Rauthy Version: Version { major: 0, minor: 27, patch: 3 }
2025-01-01T11:19:11.133479Z DEBUG rauthy_models::email: E-Mail sender started
```

```
...
Containers:
  rauthy:
    Container ID:   containerd://ff509e85ee32ae4795de2eeda7d94eb7828694d81b2dc4765146f5699a29fbc9
    Image:          ghcr.io/sebadob/rauthy:0.27.3
    Image ID:       ghcr.io/sebadob/rauthy@sha256:92525c2911c8d04a7e47647cca792187609be37340fce2fd61c22f23f3f97909
    Ports:          8000/TCP, 8080/TCP, 8443/TCP
    Host Ports:     0/TCP, 0/TCP, 0/TCP
    State:          Terminated
      Reason:       Error
      Exit Code:    139
      Started:      Wed, 01 Jan 2025 12:19:47 +0100
      Finished:     Wed, 01 Jan 2025 12:19:57 +0100
    Last State:     Terminated
      Reason:       Error
      Exit Code:    139
      Started:      Wed, 01 Jan 2025 12:19:11 +0100
      Finished:     Wed, 01 Jan 2025 12:19:21 +0100
    Ready:          False
    Restart Count:  3
...
```
The `LOG_LEVEL` does not affect migrations, startup, or anything else. I also don't see a crash in the logs. Is K8s killing it beforehand for some reason that is not logged? What do the the events provide as information when you `describe pod` ?

If it's not trying to migrate from another DB, are you sure you still have `MIGRATE_DB_FROM` set? Or, does it get stuck at that point and just don't go on, so K8s kills it after some longer timeout because it can't do a successful liveness check? 

What's werid about the logs is that I only see the `hiqlite::client::stream: Client API WebSocket trying to connect to: ...` but no confirmation that the connection has been established.

I guess you are running a single replica setup, right? In this case it should not matter because it tries to connect via localhost, but you could try to add the new Hiqlite ports to the service definition and make sure you don't have any network policies in place which restrict ports 8100 + 8200. You can also get rid of port 8000 in the service definition which is a left-over from `redhac` before v0.26.

```yaml
apiVersion: v1
kind: Service
metadata:
  name: rauthy
  namespace: rauthy
spec:
  selector:
    app: rauthy
  ports:
    # Ports 8100 and 8200 (by default) are used for the Hiqlite internal communication.
    - name: hiqlite-raft
      protocol: TCP
      port: 8100
      targetPort: 8100
    - name: hiqlite-api
      protocol: TCP
      port: 8200
      targetPort: 8200
    # Assuming that this example file will run behind a Kubernetes ingress and does
    # use HTTP internally.
    - name: http
      port: 8080
      targetPort: 8080
    # Uncomment, if you change to direct HTTPS without a reverse proxy
    #- name: https
    #  port: 8443
    #  targetPort: 8443
```

It should not use the WebSocket connections for a single node "cluster", but I am not sure if it could get stuck if these connections can't be established properly, I would need to test this, but it's probably possible if the leader is not set fast enough internally, so the very first request would try to use the internal network.

We do see

```
2025-01-01T11:19:11.132654Z  INFO hiqlite::store::state_machine::sqlite::writer: Applying database migrations
```

which means it has the logs from your first tries, which include the migrations. In this case it makes sense that you don't see another `Applying database migrations` at the bottom. What's very weird though is, that you should see an `info` log with `All migrations have been applied already - nothing to migrate` instead.

If the whole process crashed in the middle of the migrations beforehand, the database could be in a weird state, that it should never reach. So please do another thing as well and add `HQL_LOG_STATEMENTS=true` so we can see, which statements are actually executed and where exactly it gets stuck.

**Important:**  
If this is not only a test instance, before you post the logs, please check that they don't show any sensitive information which could happen with logged statements, since they include the params as well. 
I'm a bit lost. I tried your suggestions, but to no success getting anything meaningful out. Out of interest, I tried 0.27.0 which did behave a bit different:

```
2025-01-01T17:00:00.978759Z  INFO rauthy: 2025-01-01 17:00:00.978726815 UTC - Starting Rauthy v0.27.0
2025-01-01T17:00:00.978792Z  INFO rauthy: Log Level set to 'INFO'
2025-01-01T17:00:00.978930Z  WARN hiqlite::dashboard: HQL_PASSWORD_DASHBOARD has not been set and the dashboard will be disabled
2025-01-01T17:00:01.011944Z  INFO hiqlite::store::state_machine::sqlite::state_machine: db_exists in stage_machine::new(): true
2025-01-01T17:00:01.012393Z  WARN hiqlite::store::state_machine::sqlite::state_machine: Lock file already exists: data/state_machine/lock
Node did not shut down gracefully - auto-rebuilding State Machine
2025-01-01T17:00:01.028486Z  WARN hiqlite::store::state_machine::sqlite::writer: No metadata exists inside the DB yet
2025-01-01T17:00:01.028545Z  INFO hiqlite::store::state_machine::sqlite::state_machine: applied_state: StateMachineData { last_applied_log_id: None, last_membership: StoredMembership { log_id: None, membership: Membership { configs: [], nodes: {} } }, last_snapshot_id: None }
2025-01-01T17:00:01.028601Z  INFO openraft::storage::helper: get_initial_state vote=T1-N1:committed last_purged_log_id=None last_applied=None committed=None last_log_id=T1-N1-146
2025-01-01T17:00:01.028688Z  WARN hiqlite::store::state_machine::sqlite::writer: No metadata exists inside the DB yet
2025-01-01T17:00:01.028765Z  INFO hiqlite::store::state_machine::sqlite::state_machine: applied_state: StateMachineData { last_applied_log_id: None, last_membership: StoredMembership { log_id: None, membership: Membership { configs: [], nodes: {} } }, last_snapshot_id: None }
2025-01-01T17:00:01.028957Z  INFO openraft::storage::helper: load membership from log: [0..147)
2025-01-01T17:00:01.041329Z  INFO openraft::storage::helper: load key log ids from (None,T1-N1-146]
2025-01-01T17:00:01.042077Z  INFO openraft::engine::engine_impl: startup begin: state: RaftState { vote: UTime { data: Vote { leader_id: LeaderId { term: 1, node_id: 1 }, committed: true }, utime: Some(Instant { tv_sec: 1154688, tv_nsec: 333484809 }) }, committed: None, purged_next: 0, log_ids: LogIdList { key_log_ids: [LogId { leader_id: LeaderId { term: 0, node_id: 0 }, index: 0 }, LogId { leader_id: LeaderId { term: 1, node_id: 1 }, index: 1 }, LogId { leader_id: LeaderId { term: 1, node_id: 1 }, index: 146 }] }, membership_state: MembershipState { committed: EffectiveMembership { log_id: None, membership: Membership { configs: [], nodes: {} }, voter_ids: {} }, effective: EffectiveMembership { log_id: Some(LogId { leader_id: LeaderId { term: 0, node_id: 0 }, index: 0 }), membership: Membership { configs: [{1}], nodes: {1: Node { id: 1, addr_raft: "localhost:8100", addr_api: "localhost:8200" }} }, voter_ids: {1} } }, snapshot_meta: SnapshotMeta { last_log_id: None, last_membership: StoredMembership { log_id: None, membership: Membership { configs: [], nodes: {} } }, snapshot_id: "" }, server_state: Learner, accepted: Accepted { leader_id: LeaderId { term: 0, node_id: 0 }, log_id: None }, io_state: IOState { building_snapshot: false, vote: Vote { leader_id: LeaderId { term: 1, node_id: 1 }, committed: true }, flushed: LogIOId { committed_leader_id: LeaderId { term: 0, node_id: 0 }, log_id: None }, applied: None, snapshot: None, purged: None }, purge_upto: None }, is_leader: true, is_voter: true
2025-01-01T17:00:01.042224Z  INFO openraft::engine::handler::server_state_handler: become leader id=1
2025-01-01T17:00:01.042267Z  INFO openraft::core::raft_core: remove all replication
2025-01-01T17:00:01.047722Z  INFO hiqlite::init: node 1 raft is already initialized
2025-01-01T17:00:01.047793Z  INFO openraft::storage::helper: get_initial_state vote=T0-N0:uncommitted last_purged_log_id=None last_applied=None committed=None last_log_id=None
2025-01-01T17:00:01.047804Z  INFO openraft::storage::helper: load membership from log: [0..0)
2025-01-01T17:00:01.047845Z  INFO hiqlite::store::state_machine::memory::kv_handler: Cache App running on Thread ThreadId(2)
2025-01-01T17:00:01.047869Z  INFO hiqlite::store::state_machine::memory::kv_handler: Cache AuthCode running on Thread ThreadId(2)
2025-01-01T17:00:01.047810Z  INFO openraft::storage::helper: load key log ids from (None,None]
2025-01-01T17:00:01.047891Z  INFO hiqlite::store::state_machine::memory::kv_handler: Cache DeviceCode running on Thread ThreadId(2)
2025-01-01T17:00:01.047901Z  INFO hiqlite::store::state_machine::memory::kv_handler: Cache AuthProviderCallback running on Thread ThreadId(2)
2025-01-01T17:00:01.047904Z  INFO hiqlite::store::state_machine::memory::kv_handler: Cache ClientDynamic running on Thread ThreadId(2)
2025-01-01T17:00:01.047907Z  INFO hiqlite::store::state_machine::memory::kv_handler: Cache ClientEphemeral running on Thread ThreadId(2)
2025-01-01T17:00:01.047910Z  INFO hiqlite::store::state_machine::memory::kv_handler: Cache DPoPNonce running on Thread ThreadId(2)
2025-01-01T17:00:01.047914Z  INFO hiqlite::store::state_machine::memory::kv_handler: Cache IPRateLimit running on Thread ThreadId(2)
2025-01-01T17:00:01.047919Z  INFO openraft::engine::engine_impl: startup begin: state: RaftState { vote: UTime { data: Vote { leader_id: LeaderId { term: 0, node_id: 0 }, committed: false }, utime: Some(Instant { tv_sec: 1154688, tv_nsec: 339437486 }) }, committed: None, purged_next: 0, log_ids: LogIdList { key_log_ids: [] }, membership_state: MembershipState { committed: EffectiveMembership { log_id: None, membership: Membership { configs: [], nodes: {} }, voter_ids: {} }, effective: EffectiveMembership { log_id: None, membership: Membership { configs: [], nodes: {} }, voter_ids: {} } }, snapshot_meta: SnapshotMeta { last_log_id: None, last_membership: StoredMembership { log_id: None, membership: Membership { configs: [], nodes: {} } }, snapshot_id: "" }, server_state: Learner, accepted: Accepted { leader_id: LeaderId { term: 0, node_id: 0 }, log_id: None }, io_state: IOState { building_snapshot: false, vote: Vote { leader_id: LeaderId { term: 0, node_id: 0 }, committed: false }, flushed: LogIOId { committed_leader_id: LeaderId { term: 0, node_id: 0 }, log_id: None }, applied: None, snapshot: None, purged: None }, purge_upto: None }, is_leader: false, is_voter: false
2025-01-01T17:00:01.047935Z  INFO hiqlite::store::state_machine::sqlite::writer: Applying database migrations
2025-01-01T17:00:01.047943Z  INFO openraft::engine::engine_impl: startup done: id=1 target_state: Learner
2025-01-01T17:00:01.047999Z  INFO openraft::core::raft_core: received RaftMsg::Initialize: openraft::core::raft_core::RaftCore<_, _, _, _>::handle_api_msg members={1: Node { id: 1, addr_raft: "localhost:8100", addr_api: "localhost:8200" }}
2025-01-01T17:00:01.048019Z  INFO openraft::engine::engine_impl: openraft::engine::engine_impl::Engine<_>::elect, new candidate: {T1-N1:uncommitted@17:00:01.048017, last_log_id:T0-N0-0 progress:{1: false}}
2025-01-01T17:00:01.048133Z  INFO openraft::engine::handler::vote_handler: vote is changing from T0-N0:uncommitted to T1-N1:uncommitted
2025-01-01T17:00:01.048173Z  INFO openraft::core::raft_core: received Notify::VoteResponse: openraft::core::raft_core::RaftCore<_, _, _, _>::handle_notify now=17:00:01.048171 resp={T1-N1:uncommitted, last_log:None}
2025-01-01T17:00:01.048189Z  INFO openraft::engine::engine_impl: openraft::engine::engine_impl::Engine<_>::handle_vote_resp resp={T1-N1:uncommitted, last_log:None} target=1 my_vote=T1-N1:uncommitted my_last_log_id=Some(T0-N0-0)
2025-01-01T17:00:01.048195Z  INFO openraft::proposer::candidate: openraft::proposer::candidate::Candidate<_, _>::grant_by voting={T1-N1:uncommitted@17:00:01.048017, last_log_id:T0-N0-0 progress:{1: true}}
2025-01-01T17:00:01.048199Z  INFO openraft::engine::engine_impl: a quorum granted my vote
2025-01-01T17:00:01.048202Z  INFO openraft::engine::engine_impl: openraft::engine::engine_impl::Engine<_>::establish_leader
2025-01-01T17:00:01.048207Z  INFO openraft::engine::handler::vote_handler: vote is changing from T1-N1:uncommitted to T1-N1:committed
2025-01-01T17:00:01.048209Z  INFO openraft::engine::handler::server_state_handler: become leader id=1
2025-01-01T17:00:01.048214Z  INFO openraft::core::raft_core: remove all replication
2025-01-01T17:00:01.048216Z  INFO hiqlite::store::state_machine::sqlite::writer: Applying database migration 1 init_schema
2025-01-01T17:00:01.048233Z  INFO openraft::core::raft_core: received Notify::VoteResponse: openraft::core::raft_core::RaftCore<_, _, _, _>::handle_notify now=17:00:01.048233 resp={T1-N1:committed, last_log:None}
2025-01-01T17:00:01.048238Z  INFO openraft::engine::engine_impl: openraft::engine::engine_impl::Engine<_>::handle_vote_resp resp={T1-N1:committed, last_log:None} target=1 my_vote=T1-N1:committed my_last_log_id=Some(T1-N1-1)
2025-01-01T17:00:01.048251Z  INFO hiqlite::store::state_machine::memory::kv_handler: Cache Session running on Thread ThreadId(2)
2025-01-01T17:00:01.048254Z  INFO hiqlite::store::state_machine::memory::kv_handler: Cache PoW running on Thread ThreadId(2)
2025-01-01T17:00:01.048260Z  INFO hiqlite::store::state_machine::memory::kv_handler: Cache User running on Thread ThreadId(2)
2025-01-01T17:00:01.048265Z  INFO hiqlite::store::state_machine::memory::kv_handler: Cache Webauthn running on Thread ThreadId(2)
2025-01-01T17:00:01.048306Z  INFO hiqlite::start: rpc internal listening on 0.0.0.0:8100
2025-01-01T17:00:01.048388Z  INFO hiqlite::start: api external listening on 0.0.0.0:8200
2025-01-01T17:00:01.048532Z  INFO become_cluster_member{raft_type=Sqlite this_node=1 election_timeout_max=1500}: hiqlite::init: sqlite raft is already initialized - skipping become_cluster_member()
2025-01-01T17:00:01.048566Z  INFO become_cluster_member{raft_type=Cache this_node=1 election_timeout_max=1500}: hiqlite::init: cache raft is already initialized - skipping become_cluster_member()
2025-01-01T17:00:01.048621Z  INFO hiqlite::client::stream: Client API WebSocket trying to connect to: http://localhost:8200/stream/cache
2025-01-01T17:00:01.048650Z  INFO rauthy_models::app_state: Listen URL: http://0.0.0.0:8080
2025-01-01T17:00:01.048656Z  INFO rauthy_models::app_state: Public URL: id.example.com
2025-01-01T17:00:01.048682Z  INFO hiqlite::client::stream: Client API WebSocket trying to connect to: http://localhost:8200/stream/sqlite
2025-01-01T17:00:01.050498Z  INFO hiqlite::network::api: Emptying buffered Client Stream responses
2025-01-01T17:00:01.050531Z  INFO hiqlite::network::api: Emptying buffered Client Stream responses
2025-01-01T17:00:01.050549Z  INFO hiqlite::client::stream: Client API WebSocket to localhost:8200 opened successfully
2025-01-01T17:00:01.050568Z  INFO hiqlite::client::stream: Client API WebSocket to localhost:8200 opened successfully
2025-01-01T17:00:01.051815Z  INFO hiqlite::store::state_machine::sqlite::writer: Applying database migration 2 init_data
2025-01-01T17:00:01.052277Z  INFO hiqlite::store::state_machine::sqlite::writer: Applying database migration 3 client_auth_methods
2025-01-01T17:00:01.055638Z  INFO hiqlite::store::state_machine::sqlite::writer: Applying database migrations
2025-01-01T17:00:01.056060Z  INFO hiqlite::store::state_machine::sqlite::writer: Applying database migrations
2025-01-01T17:00:01.056262Z  INFO hiqlite::store::state_machine::sqlite::writer: Applying database migrations
2025-01-01T17:00:01.063913Z  INFO hiqlite::store::state_machine::sqlite::writer: Applying database migrations
2025-01-01T17:00:01.064164Z  INFO hiqlite::store::state_machine::sqlite::writer: Applying database migrations
2025-01-01T17:00:01.064219Z  INFO hiqlite::store::state_machine::sqlite::writer: Applying database migrations
2025-01-01T17:00:01.064794Z  INFO hiqlite::store::state_machine::sqlite::writer: Applying database migrations
2025-01-01T17:00:01.064854Z  INFO hiqlite::store::state_machine::sqlite::writer: Applying database migrations
2025-01-01T17:00:01.064898Z  INFO hiqlite::store::state_machine::sqlite::writer: Applying database migrations
2025-01-01T17:00:01.064940Z  INFO hiqlite::store::state_machine::sqlite::writer: Applying database migrations
2025-01-01T17:00:01.064979Z  INFO hiqlite::store::state_machine::sqlite::writer: Applying database migrations
2025-01-01T17:00:01.065020Z  INFO hiqlite::store::state_machine::sqlite::writer: Applying database migrations
2025-01-01T17:00:01.065060Z  INFO hiqlite::store::state_machine::sqlite::writer: Applying database migrations
2025-01-01T17:00:01.065101Z  INFO hiqlite::store::state_machine::sqlite::writer: Applying database migrations
2025-01-01T17:00:01.065140Z  INFO hiqlite::store::state_machine::sqlite::writer: Applying database migrations
2025-01-01T17:00:01.065180Z  INFO hiqlite::store::state_machine::sqlite::writer: Applying database migrations
2025-01-01T17:00:01.065224Z  INFO hiqlite::store::state_machine::sqlite::writer: Applying database migrations
2025-01-01T17:00:01.065268Z  INFO hiqlite::store::state_machine::sqlite::writer: Applying database migrations
2025-01-01T17:00:01.065311Z  INFO hiqlite::store::state_machine::sqlite::writer: Applying database migrations
2025-01-01T17:00:01.065351Z  INFO hiqlite::store::state_machine::sqlite::writer: Applying database migrations
2025-01-01T17:00:01.065389Z  INFO hiqlite::store::state_machine::sqlite::writer: Applying database migrations
2025-01-01T17:00:01.065428Z  INFO hiqlite::store::state_machine::sqlite::writer: Applying database migrations
thread 'tokio-runtime-worker' panicked at /usr/local/cargo/registry/src/index.crates.io-6f17d22bba15001f/hiqlite-0.3.1/src/store/state_machine/sqlite/writer.rs:743:21:
Missing migration with id 3
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
2025-01-01T17:00:01.065489Z  INFO hiqlite::store::state_machine::sqlite::writer: Applying database migrations
2025-01-01T17:00:01.065531Z  INFO hiqlite::store::state_machine::sqlite::writer: Applying database migrations
2025-01-01T17:00:01.065570Z  INFO hiqlite::store::state_machine::sqlite::writer: Applying database migrations
2025-01-01T17:00:01.065611Z  INFO hiqlite::store::state_machine::sqlite::writer: Applying database migrations
2025-01-01T17:00:01.065654Z  INFO hiqlite::store::state_machine::sqlite::writer: Applying database migrations
```

I am not sure if this helps, though. At least I get a different error message...

I just replace `DATABASE_URL` with `MIGRATE_DB_FROM` when setting the new image tag and then let rauthy start.

This is my current deployment configuration:

```
apiVersion: apps/v1
kind: StatefulSet
metadata:
  name: rauthy
  namespace: rauthy
spec:
  replicas: 1
  revisionHistoryLimit: 10
  selector:
    matchLabels:
      app: rauthy
  serviceName: rauthy
  template:
    metadata:
      labels:
        app: rauthy
    spec:
      containers:
      - env:
        - name: DATABASE_URL
          value: sqlite:data/rauthy.db
        - name: LOG_LEVEL
          value: info
        - name: ENC_KEYS
          valueFrom:
            secretKeyRef:
              key: ENC_KEYS
              name: rauthy-secrets
        - name: SMTP_USERNAME
          valueFrom:
            secretKeyRef:
              key: SMTP_USERNAME
              name: rauthy-secrets
        - name: SMTP_PASSWORD
          valueFrom:
            secretKeyRef:
              key: SMTP_PASSWORD
              name: rauthy-secrets
        - name: HQL_SECRET_RAFT
          valueFrom:
            secretKeyRef:
              key: HQL_SECRET_RAFT
              name: rauthy-secrets
        - name: HQL_SECRET_API
          valueFrom:
            secretKeyRef:
              key: HQL_SECRET_API
              name: rauthy-secrets
        image: ghcr.io/sebadob/rauthy:0.26.2-lite
        imagePullPolicy: IfNotPresent
        name: rauthy
        ports:
        - containerPort: 8080
          protocol: TCP
        - containerPort: 8443
          protocol: TCP
        - containerPort: 8100
          protocol: TCP
        - containerPort: 8200
          protocol: TCP
        resources:
          limits:
            cpu: "1"
          requests:
            cpu: 100m
            memory: 100Mi
        securityContext:
          allowPrivilegeEscalation: false
          runAsGroup: 10001
          runAsUser: 10001
        terminationMessagePath: /dev/termination-log
        terminationMessagePolicy: File
        volumeMounts:
        - mountPath: /app/data
          name: rauthy-data
        - mountPath: /app/rauthy.cfg
          name: rauthy-config
          readOnly: true
          subPath: rauthy.cfg
      dnsPolicy: ClusterFirst
      restartPolicy: Always
      securityContext:
        fsGroup: 10001
      terminationGracePeriodSeconds: 30
      volumes:
      - configMap:
          defaultMode: 420
          name: rauthy-config
        name: rauthy-config
  updateStrategy:
    rollingUpdate:
      partition: 0
    type: RollingUpdate
  volumeClaimTemplates:
  - apiVersion: v1
    kind: PersistentVolumeClaim
    metadata:
      creationTimestamp: null
      name: rauthy-data
    spec:
      accessModes:
      - ReadWriteOnce
      resources:
        requests:
          storage: 128Mi
      volumeMode: Filesystem
    status:
      phase: Pending
```

And the rauthy config:

```
apiVersion: v1
kind: ConfigMap
metadata:
  name: rauthy-config
  namespace: rauthy
data:
  rauthy.cfg: |+
    SESSION_VALIDATE_IP=true
    EMAIL_SUB_PREFIX="example ID"
    SMTP_FROM="example ID <id@example.com>"
    SMTP_URL=smtp.eu.mailgun.org

    ENC_KEY_ACTIVE=HIDDEN

    ARGON2_M_COST=32768
    ARGON2_T_COST=3
    ARGON2_P_COST=2
    MAX_HASH_THREADS=2

    ENABLE_WEB_ID=true

    EVENT_EMAIL=hidden@example.com

    LOG_LEVEL=info
    LISTEN_SCHEME=http

    PUB_URL=id.example.com

    PROXY_MODE=true
    TRUSTED_PROXIES="10.0.0.0/8"

    RP_ID=id.example.com
    RP_ORIGIN=https://id.example.com:443

    # Doesnt work with the current version of rauthy
    # HQL_NODE_ID_FROM=k8s
    HQL_NODE_ID=1
    HQL_NODES="
    1 localhost:8100 localhost:8200
    "
```
The first important thing is that `0.27.0` had a bug which made it possible to end up with a `NULL` value for the password policy when using Hiqlite. From `0.27.1` on there is an auto-fix for this during startup, which will reset it to the default value, if tis error exists in the DB, so you should use at least `0.27.1`.

In the versions before `0.27.3`, hiqlite had some minor issues as well and they should all be fixed with `0.27.3`, at least I am not aware of issues currently with the latest version `0.3.3`.

The panic you are getting with `0.27.0` is popping up because you already have migrations from the `0.27.3` release, which modify the DB in a way that `0.27.0` complains about it. As I am thinking about it, it would have been better to bump the version to `0.28` when I added this tiny migration.

In the logs for the `0.27.0` version though, it actually behaves like it should - the internal WebSocket connections have been established successfully and we see the `Applying database migrations` logs. They are applied multiple times because this is an earlier hiqlite version but I may need to revisit the latest optimizations regarding migrations, I can do that tomorrow. It only crashed because of the migration mismatch - Hiqlite migration `3` did not exist in `0.27.0`, and it should crash, because otherwise the application might run on a database assuming it is in a different state than it should be.

The `HQL_LOG_STATEMENTS=true` I mentioned will log each executed DB statement to the console. This would help in finding out where exactly it gets stuck.

However, what I would do, since something was super weird about the error with the Column Decode in the first place, maybe your database got corrupted for some weird reason. It would probably be a good idea to scale down the replicas to 0, mount the k8s volume and delete:

- `data/logs`
- `data/state_machine`

This will clean up all the stuff from the many failed startups. Maybe I can add a config option to do that automatically in the future. Then try another one with `MIGRATE_DB_FROM`, preferrably together with `LOG_LEVEL=debug` and `HQL_LOG_STATEMENTS=true`. If there is any bug in the hiqlite logic, this will help identifying the problematic section in the code.

You could also try the cleanup, then start `0.27.0` once, and `0.27.3` afterward. If I added any logic bug with the optimizations for hiqlite with the latest version, this would fix it, because I migrated quite a few Rauthy instances from `0.26` to `0.27.0` and all of them were fine so far.
So...

I recreated your setup and tested a few combinations:

Create a fresh Rauthy instance with `v0.26.2-lite`, make sure everything works, create an Event which actually creates a value inside the `data` colum. The `events` table is the only one having a `data` column with an `INTEGER` type, which could somehow match the error you posted in the beginning. At the same time, Rauthy would never try to map this to a `Vec<u8>` which makes it weird. It tries however to map the `data` column from the `config` table to a `Vec<u8>`, meaning the password policy for instance, but this column is not and has never been an `INTEGER`.

I have then shut it down and tested a `MIGRATE_DB_FROM` with `v0.27.0` -> everything went fine. Starting `v0.27.3` after the `0.27.0` migration was fine as well.

The next thing I did was a test with a migration from `v0.26.2` to a fresh Hiqlite instance with no prior data or migrations with a direct `MIGRATE_DB_FROM`, skipping `0.27.0` and everything in between completely, so `v0.26.2 -> v0.27.3`, which went fine without any errors as well.

Is it possible, that you connected to the Sqlite of your deployment manually at some point, or did it crash badly because of maybe something like an immediate host poweroff without a shutdown or force-kill, which could have corrupted the `sqlite_master` table or the volume itself?
Thanks for your help so far, that's greatly appreciated. I could now retrieve the following errors:

```
...
2025-01-01T18:50:47.580152Z DEBUG sqlx::query: summary="PRAGMA auto_vacuum = INCREMENTAL; …" db.statement="\n\nPRAGMA auto_vacuum = INCREMENTAL;\nPRAGMA journal_mode = WAL;\nPRAGMA foreign_keys = ON;\nPRAGMA synchronous = NORMAL;\n" rows_affected=0 rows_returned=1 elapsed=5.972413ms elapsed_secs=0.005972413
2025-01-01T18:50:47.580318Z  INFO rauthy_models::migration::db_migrate: Starting migration to another DB
2025-01-01T18:50:47.580331Z DEBUG rauthy_models::migration::db_migrate: Migrating table: config
2025-01-01T18:50:47.580630Z DEBUG rauthy_error::error_impls: From<sqlx::Error>: ColumnDecode { index: "\"data\"", source: "mismatched types; Rust type `alloc::vec::Vec<u8>` (as SQL type `BLOB`) is not compatible with SQL type `INTEGER`" }
2025-01-01T18:50:47.580656Z ERROR rauthy_error::error_impls: Database Error: ColumnDecode { index: "\"data\"", source: "mismatched types; Rust type `alloc::vec::Vec<u8>` (as SQL type `BLOB`) is not compatible with SQL type `INTEGER`" }
2025-01-01T18:50:47.580613Z DEBUG sqlx::query: summary="SELECT * FROM config" db.statement="" rows_affected=0 rows_returned=4 elapsed=175.179µs elapsed_secs=0.000175179
thread 'main' panicked at /work/src/models/src/database.rs:208:25:
Error during db migration: ErrorResponse { timestamp: 1735757447, error: Internal, message: "Internal error, please try again" }
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
```

It looks like there is some garbage in the database, which now lets the migration fail.
> It looks like there is some garbage in the database, which now lets the migration fail.

Oh yes, it looks like this is the case somehow. Usually, the `config` table should have 3 rows:

- password_policy
- db_version
- latest_version

And the `latest_version` might not even exist for a fresh instance.

Out of curiosity, which was the first version of Rauthy you used, which would be the one that initialized the Sqlite?
From `v0.27.0` on, Rauthy intializes all Sqlite tables as `STRICT` which makes situations like this impossible in future versions. I am thinking if maybe some older version did "bad stuff" and inserted an integer in the `config` table by accident, and Sqlite being like Javascript by default in the way "whatever you give me, I will take it and ask no further questions" could have inserted an INTEGER, but I don't know how and why atm.

The easiest way to solve this issue would be, if you have the possibility to connect to that database manually via a shell, is that possible for you? Like, mount the volume to some underlying k8s host and use a local `sqlite` CLI to get into the DB?
The `config` table is super simple, it just has the above values as `id` and a 2nd `data` column with raw bytes, that's it.

If this is not easily possible, I could maybe build a nightly version which tries to clean up that table for you. As soon as you are on hiqlite, you have the included dashboard to solve such issues.
Mystery solved:

```
sqlite> select * from config;
id|data
password_policy|
cryptr_migration|1
db_version|
latest_version|��lg
sqlite> delete from config where id == "latest_version";
sqlite> delete from config where id == "cryptr_migration";
sqlite> select * from config;
password_policy|
db_version|
sqlite>
```

With that, the migration went ahead without issues, 0.27.3 is now running just fine.

> Out of curiosity, which was the first version of Rauthy you used, which would be the one that initialized the Sqlite?

According to my GitOps history, it was `0.19.1-lite` (https://git.tbrnt.ch/tobru/gitops-zurrli/commits/branch/main/apps/zurrli/rauthy/statefulset.yaml).

Thanks for rauthy! It's great to see it funded by NGI Zero Core.
Ohh, it was the `cryptr_migration`. That is quite some time ago. Apparently I did not clean that up properly, good to know.

Thanks a lot for the information, that helps if something like that might occur to someone else in the future.

>  It's great to see it funded by NGI Zero Core.

Oh yes it is. I applied quite some time ago, but they had lots of requests that it just took a while. The best thing about it is, that I will get an independent security review in the future, which was a missing piece for me before considering a `v1.0.0-rc1`. 

Fix patch:
diff --git a/src/models/src/migration/db_migrate.rs b/src/models/src/migration/db_migrate.rs
index b1fdb2375..257d07e97 100644
--- a/src/models/src/migration/db_migrate.rs
+++ b/src/models/src/migration/db_migrate.rs
@@ -32,9 +32,10 @@ pub async fn migrate_from_sqlite(db_from: sqlx::SqlitePool) -> Result<(), ErrorR
 
     // CONFIG
     debug!("Migrating table: config");
-    let before = sqlx::query_as::<_, ConfigEntity>("SELECT * FROM config")
-        .fetch_all(&db_from)
-        .await?;
+    let before =
+        sqlx::query_as::<_, ConfigEntity>("SELECT * FROM config WHERE id = 'password_policy'")
+            .fetch_all(&db_from)
+            .await?;
     inserts::config(before).await?;
 
     // API KEYS
@@ -227,9 +228,10 @@ pub async fn migrate_from_postgres(db_from: sqlx::PgPool) -> Result<(), ErrorRes
 
     // CONFIG
     debug!("Migrating table: config");
-    let before = sqlx::query_as::<_, ConfigEntity>("SELECT * FROM config")
-        .fetch_all(&db_from)
-        .await?;
+    let before =
+        sqlx::query_as::<_, ConfigEntity>("SELECT * FROM config WHERE id = 'password_policy'")
+            .fetch_all(&db_from)
+            .await?;
     inserts::config(before).await?;
 
     // API KEYS


Test patch: