Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Brief network partitions can cause all ingress requests to time out even after network is healed #2565

Closed
pcholakov opened this issue Jan 28, 2025 · 7 comments
Closed

Brief network partitions can cause all ingress requests to time out even after network is healed #2565

pcholakov opened this issue Jan 28, 2025 · 7 comments

Comments

@pcholakov
Copy link
Contributor

Noted the stuck state that I can consistently replicate when running the Jepsen virtual object workloads against a 3-node cluster that experiences intermittent network partitions.

Build: Restate Server (ad4e5ee x86_64-unknown-linux-gnu 2025-01-28)

lein run test --nodes-file nodes-3.txt --username admin --ssh-private-key ... \
  --image ghcr.io/restatedev/restate@sha256:727254566e53170b9fc099ff8761ec0451c27d3b4b63eeccffc77384ad0a5d4c \
  --workload set-vo --time-limit 60 --rate 10 --concurrency 10 --leave-db-running true --nemesis partition-random-node

Here is a visual representation of what's going on - the grey shaded areas are periods when a random single node is isolated from the others:

Image

The yellow datapoints are ingress request timeouts, blue - successfully completed.

Cluster state after the end of test:

CONTAINER ID   IMAGE                        COMMAND                  CREATED         STATUS         PORTS     NAMES
e5ad5e1c3b7e   ghcr.io/restatedev/restate   "/usr/local/bin/rest…"   4 minutes ago   Up 4 minutes             restate

Node Configuration (v9)
 NODE  GEN  NAME  ADDRESS                                                          ROLES
 N1    2    n1    http://ec2-13-247-62-130.af-south-1.compute.amazonaws.com:5122/  admin | log-server | metadata-server | worker
 N2    1    n2    http://ec2-13-246-9-133.af-south-1.compute.amazonaws.com:5122/   admin | log-server | metadata-server | worker
 N3    1    n3    http://ec2-13-246-7-188.af-south-1.compute.amazonaws.com:5122/   admin | log-server | metadata-server | worker

Log Configuration (v4)
Default Provider Config: Replicated(ReplicatedLogletConfig { replication_property: ReplicationProperty({Node: 2}), target_nodeset_size: 0 })
 L-ID  FROM-LSN  KIND        LOGLET-ID  REPLICATION  SEQUENCER  NODESET
 0     566       Replicated  0_2        {node: 2}    N1:2       [N1, N2, N3]

Alive partition processors (nodes config v9, partition table v16)
 P-ID  NODE  MODE              STATUS              LEADER  EPOCH  SEQUENCER  APPLIED-LSN  PERSISTED-LSN  SKIPPED-RECORDS  ARCHIVED-LSN  LAST-UPDATE
 0     N1:2  Follower->Leader  Active              -       -                 1010         -              0                -             355 ms ago
 0     N2:1  Follower->Leader  Catching Up (1011)  -       -                 942          -              0                -             842 ms ago
 0     N3:1  Follower->Leader  Active              N1:2    e2                1010         -              0                -             589 ms ago

 NODE  STATUS  VERSION  LEADER   MEMBERS                    APPLIED  COMMITTED  TERM  LOG-LENGTH  SNAP-INDEX  SNAP-SIZE
 N3    Member  v3       N1:6b42  [N2:4a0a,N1:6b42,N3:e422]  50       50         11    34          16          5.5 kiB
 N1    Member  v3       N1:6b42  [N1:6b42,N2:4a0a,N3:e422]  50       50         11    34          16          5.5 kiB
 N2    Member  v3       N1:6b42  [N2:4a0a,N1:6b42,N3:e422]  50       50         11    34          16          5.5 kiB

It appears to be Bifrost related as the latest entries in the logs on all three servers indicate a pending seal that isn't finished.

Details

n1

2025-01-28T12:38:18.319071Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=207.67372525s log_version=v4 partition_id=0 leader_epoch=e7 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:19.448716Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=208.803370414s log_version=v4 partition_id=0 leader_epoch=e7 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:20.564364Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=209.91901904s log_version=v4 partition_id=0 leader_epoch=e7 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:21.810517Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=211.165172031s log_version=v4 partition_id=0 leader_epoch=e7 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:22.926086Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=212.28074114s log_version=v4 partition_id=0 leader_epoch=e7 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:24.210977Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=213.565632186s log_version=v4 partition_id=0 leader_epoch=e7 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:25.330746Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=214.68540075s log_version=v4 partition_id=0 leader_epoch=e7 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:26.366720Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=215.721374747s log_version=v4 partition_id=0 leader_epoch=e7 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:27.519982Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=216.874637345s log_version=v4 partition_id=0 leader_epoch=e7 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:28.542364Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=217.897018187s log_version=v4 partition_id=0 leader_epoch=e7 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:29.478764Z DEBUG run: restate_bifrost::providers::replicated_loglet::provider: Creating a replicated loglet client log_id=0 segment_index=3 loglet_id=0_3 nodeset=[N1, N3, N2] sequencer=N1:2 replication={node: 2} partition_id=0 is_leader=false
2025-01-28T12:38:29.478782Z DEBUG run: restate_bifrost::providers::replicated_loglet::loglet: We are the sequencer node for this loglet loglet_id=0_3 partition_id=0 is_leader=false
2025-01-28T12:38:29.479072Z DEBUG restate_bifrost::providers::replicated_loglet::tasks::periodic_tail_checker: Starting a background periodic tail checker for this loglet loglet_id=0_3
2025-01-28T12:38:29.648035Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Found an unsealed segment 3 after 219.002689389s partition_id=0 is_leader=false leader_epoch=e7 log_id=LogId(0) sealed_segment=SegmentIndex(2)

n2

2025-01-28T12:38:11.823001Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=205.612866777s log_version=v4 partition_id=0 leader_epoch=e6 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:13.115330Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=206.905195992s log_version=v4 partition_id=0 leader_epoch=e6 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:14.215922Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=208.005788015s log_version=v4 partition_id=0 leader_epoch=e6 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:15.307549Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=209.097415261s log_version=v4 partition_id=0 leader_epoch=e6 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:16.424950Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=210.214815854s log_version=v4 partition_id=0 leader_epoch=e6 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:17.677183Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=211.467049241s log_version=v4 partition_id=0 leader_epoch=e6 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:18.906418Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=212.696282896s log_version=v4 partition_id=0 leader_epoch=e6 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:20.100600Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=213.890465898s log_version=v4 partition_id=0 leader_epoch=e6 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:21.235042Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=215.024908052s log_version=v4 partition_id=0 leader_epoch=e6 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:22.410162Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=216.200027838s log_version=v4 partition_id=0 leader_epoch=e6 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:23.530194Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=217.320059729s log_version=v4 partition_id=0 leader_epoch=e6 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:24.576519Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=218.366385494s log_version=v4 partition_id=0 leader_epoch=e6 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:25.709756Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=219.499621464s log_version=v4 partition_id=0 leader_epoch=e6 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:26.981831Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=220.771695946s log_version=v4 partition_id=0 leader_epoch=e6 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:28.058175Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=221.848041087s log_version=v4 partition_id=0 leader_epoch=e6 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:29.070547Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=222.8604137s log_version=v4 partition_id=0 leader_epoch=e6 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:30.176405Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=223.966270714s log_version=v4 partition_id=0 leader_epoch=e6 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:31.304205Z DEBUG run: restate_bifrost::providers::replicated_loglet::provider: Creating a replicated loglet client log_id=0 segment_index=3 loglet_id=0_3 nodeset=[N1, N3, N2] sequencer=N1:2 replication={node: 2} partition_id=0 is_leader=false
2025-01-28T12:38:31.304430Z DEBUG restate_bifrost::providers::replicated_loglet::tasks::periodic_tail_checker: Starting a background periodic tail checker for this loglet loglet_id=0_3
2025-01-28T12:38:31.452519Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Found an unsealed segment 3 after 225.242382209s partition_id=0 is_leader=false is_leader=false leader_epoch=e6 log_id=LogId(0) sealed_segment=SegmentIndex(2)

n3

2025-01-28T12:38:10.905492Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=246.77066496s log_version=v4 partition_id=0 is_leader=true is_leader=false leader_epoch=e3 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:12.173541Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=248.038714585s log_version=v4 partition_id=0 is_leader=true is_leader=false leader_epoch=e3 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:13.467102Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=249.332276043s log_version=v4 partition_id=0 is_leader=true is_leader=false leader_epoch=e3 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:14.630850Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=250.496024159s log_version=v4 partition_id=0 is_leader=true is_leader=false leader_epoch=e3 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:15.812886Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=251.678059463s log_version=v4 partition_id=0 is_leader=true is_leader=false leader_epoch=e3 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:16.868720Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=252.733893765s log_version=v4 partition_id=0 is_leader=true is_leader=false leader_epoch=e3 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:18.117234Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=253.982407909s log_version=v4 partition_id=0 is_leader=true is_leader=false leader_epoch=e3 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:19.403126Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=255.268299645s log_version=v4 partition_id=0 is_leader=true is_leader=false leader_epoch=e3 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:20.590621Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=256.455794559s log_version=v4 partition_id=0 is_leader=true is_leader=false leader_epoch=e3 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:21.880909Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=257.746082593s log_version=v4 partition_id=0 is_leader=true is_leader=false leader_epoch=e3 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:22.961393Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=258.826566741s log_version=v4 partition_id=0 is_leader=true is_leader=false leader_epoch=e3 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:24.179085Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=260.044259312s log_version=v4 partition_id=0 is_leader=true is_leader=false leader_epoch=e3 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:25.448761Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=261.313934675s log_version=v4 partition_id=0 is_leader=true is_leader=false leader_epoch=e3 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:26.500196Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=262.365369218s log_version=v4 partition_id=0 is_leader=true is_leader=false leader_epoch=e3 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:27.605728Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=263.470901312s log_version=v4 partition_id=0 is_leader=true is_leader=false leader_epoch=e3 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:28.667895Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=264.533069852s log_version=v4 partition_id=0 is_leader=true is_leader=false leader_epoch=e3 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:29.693272Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=265.558446456s log_version=v4 partition_id=0 is_leader=true is_leader=false leader_epoch=e3 log_id=LogId(0) sealed_segment=SegmentIndex(2)
2025-01-28T12:38:30.200176Z DEBUG run: restate_bifrost::providers::replicated_loglet::provider: Creating a replicated loglet client log_id=0 segment_index=3 loglet_id=0_3 nodeset=[N1, N3, N2] sequencer=N1:2 replication={node: 2} partition_id=0 is_leader=true is_leader=false is_leader=true
2025-01-28T12:38:30.201786Z DEBUG restate_bifrost::providers::replicated_loglet::tasks::periodic_tail_checker: Starting a background periodic tail checker for this loglet loglet_id=0_3
2025-01-28T12:38:30.801061Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Found an unsealed segment 3 after 266.666235003s partition_id=0 is_leader=true is_leader=false is_leader=true is_leader=false leader_epoch=e3 log_id=LogId(0) sealed_segment=SegmentIndex(2)

Restarting the restate-server processes gets the cluster unstuck.
@pcholakov
Copy link
Contributor Author

The Bifrost config looks completely normal - I didn't capture the output from the initial run, but here's another run where the cluster got into a bad state from the second partitioning event:

root@ip-172-31-1-45:~# rc meta get -k bifrost_config
{
  "version": 2,
  "config": {
    "default_provider": {
      "replicated": {
        "replication_property": "{node: 2}",
        "target_nodeset_size": 0
      }
    }
  },
  "logs": [
    [
      0,
      {
        "chain": [
          [
            1,
            {
              "index": 0,
              "kind": "replicated",
              "params": "{\"loglet_id\":0,\"sequencer\":\"N2:1\",\"replication\":{\"node\":2},\"nodeset\":[2,3,1]}"
            }
          ]
        ]
      }
    ]
  ]
}

On this occasion, the cluster recovered without external intervention a short while (about 4 minutes) after the end of the test run.

Logs from sequencer (n2):

root@ip-172-31-13-61:~# docker logs restate 2>&1 | grep bifrost | grep -v TRACE | head -100
2025-01-28T12:56:34.316651Z DEBUG restate_bifrost::providers::local_loglet::provider: Started a bifrost local loglet provider
2025-01-28T12:56:34.316840Z DEBUG restate_bifrost::service: All loglet providers started successfully!
2025-01-28T12:56:34.316844Z DEBUG restate_bifrost::providers::local_loglet::log_store_writer: Start running LogStoreWriter
2025-01-28T12:56:35.998366Z DEBUG restate_bifrost::providers::replicated_loglet::provider: Creating a replicated loglet client log_id=0 segment_index=0 loglet_id=0_0 nodeset=[N2, N3, N1] sequencer=N2:1 replication={node: 2}
2025-01-28T12:56:35.998446Z DEBUG restate_bifrost::providers::replicated_loglet::loglet: We are the sequencer node for this loglet loglet_id=0_0
2025-01-28T12:56:35.998598Z DEBUG restate_bifrost::providers::replicated_loglet::tasks::periodic_tail_checker: Starting a background periodic tail checker for this loglet loglet_id=0_0
2025-01-28T12:56:48.343221Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N3, N2, N1] responses={PlainNodeId(1): NodeAttributes { committed: true, sealed: false }, PlainNodeId(2): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=297 to_offset=297 length=1 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:48.356206Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N2, N1, N3] responses={PlainNodeId(1): NodeAttributes { committed: true, sealed: false }, PlainNodeId(2): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=298 to_offset=299 length=2 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:48.359406Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N3, N1, N2] responses={PlainNodeId(1): NodeAttributes { committed: true, sealed: false }, PlainNodeId(2): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=300 to_offset=302 length=3 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:48.381589Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N1, N2, N3] responses={PlainNodeId(2): NodeAttributes { committed: true, sealed: false }, PlainNodeId(1): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=303 to_offset=303 length=1 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:48.392783Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N2, N3, N1] responses={PlainNodeId(2): NodeAttributes { committed: true, sealed: false }, PlainNodeId(1): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=304 to_offset=305 length=2 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:48.399981Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N2, N3, N1] responses={PlainNodeId(2): NodeAttributes { committed: true, sealed: false }, PlainNodeId(1): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=306 to_offset=308 length=3 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:48.534509Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N1, N3, N2] responses={PlainNodeId(2): NodeAttributes { committed: true, sealed: false }, PlainNodeId(1): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=309 to_offset=309 length=1 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:48.543776Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N2, N1, N3] responses={PlainNodeId(2): NodeAttributes { committed: true, sealed: false }, PlainNodeId(1): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=310 to_offset=310 length=1 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:48.551108Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N3, N2, N1] responses={PlainNodeId(1): NodeAttributes { committed: true, sealed: false }, PlainNodeId(2): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=311 to_offset=314 length=4 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:48.563425Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N2, N1, N3] responses={PlainNodeId(2): NodeAttributes { committed: true, sealed: false }, PlainNodeId(1): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=315 to_offset=315 length=1 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:48.569134Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N3, N2, N1] responses={PlainNodeId(2): NodeAttributes { committed: true, sealed: false }, PlainNodeId(1): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=316 to_offset=319 length=4 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:48.581764Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N1, N3, N2] responses={PlainNodeId(2): NodeAttributes { committed: true, sealed: false }, PlainNodeId(1): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=320 to_offset=324 length=5 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:48.674204Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N1, N2, N3] responses={PlainNodeId(2): NodeAttributes { committed: true, sealed: false }, PlainNodeId(1): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=325 to_offset=325 length=1 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:48.690046Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N1, N2, N3] responses={PlainNodeId(2): NodeAttributes { committed: true, sealed: false }, PlainNodeId(1): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=326 to_offset=330 length=5 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:48.801156Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N3, N2, N1] responses={PlainNodeId(1): NodeAttributes { committed: true, sealed: false }, PlainNodeId(2): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=331 to_offset=331 length=1 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:48.809356Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N2, N3, N1] responses={PlainNodeId(1): NodeAttributes { committed: true, sealed: false }, PlainNodeId(2): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=332 to_offset=333 length=2 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:48.814522Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N3, N2, N1] responses={PlainNodeId(2): NodeAttributes { committed: true, sealed: false }, PlainNodeId(1): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=334 to_offset=336 length=3 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:48.963943Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N1, N3, N2] responses={PlainNodeId(1): NodeAttributes { committed: true, sealed: false }, PlainNodeId(2): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=337 to_offset=337 length=1 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:48.972148Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N1, N2, N3] responses={PlainNodeId(2): NodeAttributes { committed: true, sealed: false }, PlainNodeId(1): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=338 to_offset=339 length=2 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:48.979396Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N3, N1, N2] responses={PlainNodeId(1): NodeAttributes { committed: true, sealed: false }, PlainNodeId(2): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=340 to_offset=342 length=3 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:49.024502Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N1, N3, N2] responses={PlainNodeId(1): NodeAttributes { committed: true, sealed: false }, PlainNodeId(2): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=343 to_offset=343 length=1 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:49.032198Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N2, N3, N1] responses={PlainNodeId(1): NodeAttributes { committed: true, sealed: false }, PlainNodeId(2): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=344 to_offset=345 length=2 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:49.039384Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N2, N1, N3] responses={PlainNodeId(1): NodeAttributes { committed: true, sealed: false }, PlainNodeId(2): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=346 to_offset=347 length=2 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:49.068782Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N3, N1, N2] responses={PlainNodeId(2): NodeAttributes { committed: true, sealed: false }, PlainNodeId(1): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=348 to_offset=348 length=1 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:49.081211Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N1, N2, N3] responses={PlainNodeId(2): NodeAttributes { committed: true, sealed: false }, PlainNodeId(1): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=349 to_offset=353 length=5 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:49.153018Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N1, N3, N2] responses={PlainNodeId(2): NodeAttributes { committed: true, sealed: false }, PlainNodeId(1): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=354 to_offset=354 length=1 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:49.163483Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N2, N1, N3] responses={PlainNodeId(1): NodeAttributes { committed: true, sealed: false }, PlainNodeId(2): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=355 to_offset=356 length=2 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:49.174810Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N3, N2, N1] responses={PlainNodeId(2): NodeAttributes { committed: true, sealed: false }, PlainNodeId(1): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=357 to_offset=359 length=3 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:49.426784Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N2, N3, N1] responses={PlainNodeId(2): NodeAttributes { committed: true, sealed: false }, PlainNodeId(1): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=360 to_offset=360 length=1 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:49.437089Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N2, N3, N1] responses={PlainNodeId(1): NodeAttributes { committed: true, sealed: false }, PlainNodeId(2): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=361 to_offset=362 length=2 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:49.443553Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N2, N3, N1] responses={PlainNodeId(2): NodeAttributes { committed: true, sealed: false }, PlainNodeId(1): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=363 to_offset=364 length=2 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:49.535577Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N3, N1, N2] responses={PlainNodeId(1): NodeAttributes { committed: true, sealed: false }, PlainNodeId(2): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=365 to_offset=365 length=1 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:49.545867Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N1, N2, N3] responses={PlainNodeId(1): NodeAttributes { committed: true, sealed: false }, PlainNodeId(2): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=366 to_offset=367 length=2 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:49.553669Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N3, N2, N1] responses={PlainNodeId(2): NodeAttributes { committed: true, sealed: false }, PlainNodeId(1): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=368 to_offset=369 length=2 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:49.640149Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N1, N3, N2] responses={PlainNodeId(2): NodeAttributes { committed: true, sealed: false }, PlainNodeId(1): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=370 to_offset=370 length=1 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:49.657027Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N1, N3, N2] responses={PlainNodeId(2): NodeAttributes { committed: true, sealed: false }, PlainNodeId(1): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=371 to_offset=372 length=2 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:49.660349Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N3, N1, N2] responses={PlainNodeId(1): NodeAttributes { committed: true, sealed: false }, PlainNodeId(2): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=373 to_offset=375 length=3 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:49.724249Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N2, N3, N1] responses={PlainNodeId(1): NodeAttributes { committed: true, sealed: false }, PlainNodeId(2): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=376 to_offset=376 length=1 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:49.729540Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N1, N3, N2] responses={PlainNodeId(1): NodeAttributes { committed: true, sealed: false }, PlainNodeId(2): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=377 to_offset=378 length=2 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:49.738948Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N3, N1, N2] responses={PlainNodeId(1): NodeAttributes { committed: true, sealed: false }, PlainNodeId(2): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=379 to_offset=380 length=2 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:49.825281Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N2, N3, N1] responses={PlainNodeId(1): NodeAttributes { committed: true, sealed: false }, PlainNodeId(2): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=381 to_offset=381 length=1 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:49.835663Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N1, N2, N3] responses={PlainNodeId(1): NodeAttributes { committed: true, sealed: false }, PlainNodeId(2): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=382 to_offset=383 length=2 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:49.839852Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N3, N1, N2] responses={PlainNodeId(1): NodeAttributes { committed: true, sealed: false }, PlainNodeId(2): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=384 to_offset=385 length=2 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:49.974752Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N1, N2, N3] responses={PlainNodeId(1): NodeAttributes { committed: true, sealed: false }, PlainNodeId(2): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=386 to_offset=386 length=1 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:50.008241Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N2, N3, N1] responses={PlainNodeId(1): NodeAttributes { committed: true, sealed: false }, PlainNodeId(2): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=387 to_offset=391 length=5 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:50.041765Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N2, N1, N3] responses={PlainNodeId(1): NodeAttributes { committed: true, sealed: false }, PlainNodeId(2): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=392 to_offset=392 length=1 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:50.052318Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N2, N3, N1] responses={PlainNodeId(1): NodeAttributes { committed: true, sealed: false }, PlainNodeId(2): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=393 to_offset=394 length=2 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:50.058198Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N1, N3, N2] responses={PlainNodeId(1): NodeAttributes { committed: true, sealed: false }, PlainNodeId(2): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=395 to_offset=396 length=2 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:50.240053Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N2, N1, N3] responses={PlainNodeId(2): NodeAttributes { committed: true, sealed: false }, PlainNodeId(1): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=397 to_offset=397 length=1 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:50.252447Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N1, N3, N2] responses={PlainNodeId(1): NodeAttributes { committed: true, sealed: false }, PlainNodeId(2): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=398 to_offset=399 length=2 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:50.256627Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Some servers didn't store this batch, but append was committed, giving up pending_servers=[N3] wave=1 spread=[N1, N2, N3] responses={PlainNodeId(1): NodeAttributes { committed: true, sealed: false }, PlainNodeId(2): NodeAttributes { committed: true, sealed: false }} partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=400 to_offset=401 length=2 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:50.278814Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Store task cancelled, the node is sealed peer=N2 partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=577 to_offset=577 length=1 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:50.284399Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Store task cancelled, the node is sealed peer=N3 partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=402 to_offset=402 length=1 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:50.284469Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Store task cancelled, the node is sealed peer=N3 partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=403 to_offset=404 length=2 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:50.284498Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Store task cancelled, the node is sealed peer=N3 partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=405 to_offset=407 length=3 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:50.284514Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Store task cancelled, the node is sealed peer=N3 partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=408 to_offset=408 length=1 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:50.284529Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Store task cancelled, the node is sealed peer=N3 partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=409 to_offset=410 length=2 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:50.284544Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Store task cancelled, the node is sealed peer=N3 partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=411 to_offset=412 length=2 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:50.284557Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Store task cancelled, the node is sealed peer=N3 partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=413 to_offset=413 length=1 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:50.284572Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Store task cancelled, the node is sealed peer=N3 partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=414 to_offset=415 length=2 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:50.284586Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Store task cancelled, the node is sealed peer=N3 partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=416 to_offset=417 length=2 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:50.284846Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Store task cancelled, the node is sealed peer=N3 partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=418 to_offset=418 length=1 otel.name="replicated_loglet::sequencer::appender: run"
2025-01-28T12:56:50.284879Z DEBUG run:run_for_leader:run: restate_bifrost::providers::replicated_loglet::sequencer::appender: Store task cancelled, the node is sealed peer=N3 partition_id=0 is_leader=true leader_epoch=e1 loglet_id=0_0 first_offset=419 to_offset=420 length=2 otel.name="replicated_loglet::sequencer::appender: run"
...
2025-01-28T13:01:25.936487Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=250.995929138s log_version=v2 partition_id=0 leader_epoch=e4 log_id=LogId(0) sealed_segment=SegmentIndex(0)
2025-01-28T13:01:27.118701Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=252.178142746s log_version=v2 partition_id=0 leader_epoch=e4 log_id=LogId(0) sealed_segment=SegmentIndex(0)
2025-01-28T13:01:28.418899Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=253.478340407s log_version=v2 partition_id=0 leader_epoch=e4 log_id=LogId(0) sealed_segment=SegmentIndex(0)
2025-01-28T13:01:29.700359Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=254.759800353s log_version=v2 partition_id=0 leader_epoch=e4 log_id=LogId(0) sealed_segment=SegmentIndex(0)
2025-01-28T13:01:30.923302Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=255.98274297s log_version=v2 partition_id=0 leader_epoch=e4 log_id=LogId(0) sealed_segment=SegmentIndex(0)
2025-01-28T13:01:32.037017Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=257.096457785s log_version=v2 partition_id=0 leader_epoch=e4 log_id=LogId(0) sealed_segment=SegmentIndex(0)
2025-01-28T13:01:33.076586Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=258.136027745s log_version=v2 partition_id=0 leader_epoch=e4 log_id=LogId(0) sealed_segment=SegmentIndex(0)
2025-01-28T13:01:34.092157Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=259.151598162s log_version=v2 partition_id=0 leader_epoch=e4 log_id=LogId(0) sealed_segment=SegmentIndex(0)
2025-01-28T13:01:35.162670Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=260.222112214s log_version=v2 partition_id=0 leader_epoch=e4 log_id=LogId(0) sealed_segment=SegmentIndex(0)
2025-01-28T13:01:36.240975Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=261.30041578s log_version=v2 partition_id=0 leader_epoch=e4 log_id=LogId(0) sealed_segment=SegmentIndex(0)
2025-01-28T13:01:37.047324Z DEBUG run: restate_bifrost::providers::replicated_loglet::provider: Creating a replicated loglet client log_id=0 segment_index=1 loglet_id=0_1 nodeset=[N2, N3, N1] sequencer=N2:1 replication={node: 2} partition_id=0
2025-01-28T13:01:37.047356Z DEBUG run: restate_bifrost::providers::replicated_loglet::loglet: We are the sequencer node for this loglet loglet_id=0_1 partition_id=0
2025-01-28T13:01:37.047574Z DEBUG restate_bifrost::providers::replicated_loglet::tasks::periodic_tail_checker: Starting a background periodic tail checker for this loglet loglet_id=0_1
2025-01-28T13:01:37.529137Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Found an unsealed segment 1 after 262.588576553s partition_id=0 leader_epoch=e4 log_id=LogId(0) sealed_segment=SegmentIndex(0)

Bifrost config at end state:

root@ip-172-31-13-61:~# rc meta get -k bifrost_config
{
  "version": 3,
  "config": {
    "default_provider": {
      "replicated": {
        "replication_property": "{node: 2}",
        "target_nodeset_size": 0
      }
    }
  },
  "logs": [
    [
      0,
      {
        "chain": [
          [
            1,
            {
              "index": 0,
              "kind": "replicated",
              "params": "{\"loglet_id\":0,\"sequencer\":\"N2:1\",\"replication\":{\"node\":2},\"nodeset\":[2,3,1]}"
            }
          ],
          [
            577,
            {
              "index": 1,
              "kind": "replicated",
              "params": "{\"loglet_id\":1,\"sequencer\":\"N2:1\",\"replication\":{\"node\":2},\"nodeset\":[2,3,1]}"
            }
          ]
        ]
      }
    ]
  ]
}

@pcholakov
Copy link
Contributor Author

Complete node logs from the last run in my earlier comment:

restate-20250128T145623.085+0200.tar.gz

@pcholakov
Copy link
Contributor Author

Tested against #2570 to similar results - with 5 and 15 second partitions respectively:

Image

Image

Full Jepsen output from the second example:

restate-set-vo-20250128T222741.019+0200.tar.gz

This is the log configuration at the end of the test:

root@ip-172-31-1-45:~# rc meta get -k bifrost_config
{
  "version": 4,
  "config": {
    "default_provider": {
      "replicated": {
        "replication_property": "{node: 2}",
        "target_nodeset_size": 0
      }
    }
  },
  "logs": [
    [
      0,
      {
        "chain": [
          [
            1,
            {
              "index": 0,
              "kind": "replicated",
              "params": "{\"loglet_id\":0,\"sequencer\":\"N1:2\",\"replication\":{\"node\":2},\"nodeset\":[1,3,2]}"
            }
          ],
          [
            793,
            {
              "index": 1,
              "kind": "replicated",
              "params": "{\"loglet_id\":1,\"sequencer\":\"N3:1\",\"replication\":{\"node\":2},\"nodeset\":[3,1,2]}"
            }
          ],
          [
            800,
            {
              "index": 2,
              "kind": "replicated",
              "params": "{\"loglet_id\":2,\"sequencer\":\"N3:1\",\"replication\":{\"node\":2},\"nodeset\":[3,1,2]}"
            }
          ]
        ]
      }
    ]
  ]
}

@pcholakov
Copy link
Contributor Author

Cluster state:

root@ip-172-31-1-45:~# rc st
Node Configuration (v9)
 NODE  GEN  NAME  ADDRESS                                                          ROLES
 N1    2    n1    http://ec2-13-247-62-130.af-south-1.compute.amazonaws.com:5122/  admin | log-server | metadata-server | worker
 N2    1    n2    http://ec2-13-246-9-133.af-south-1.compute.amazonaws.com:5122/   admin | log-server | metadata-server | worker
 N3    1    n3    http://ec2-13-246-7-188.af-south-1.compute.amazonaws.com:5122/   admin | log-server | metadata-server | worker

Log Configuration (v4)
Default Provider Config: Replicated(ReplicatedLogletConfig { replication_property: ReplicationProperty({Node: 2}), target_nodeset_size: 0 })
 L-ID  FROM-LSN  KIND        LOGLET-ID  REPLICATION  SEQUENCER  NODESET
 0     800       Replicated  0_2        {node: 2}    N3:1       [N1, N2, N3]

Alive partition processors (nodes config v9, partition table v21)
 P-ID  NODE  MODE              STATUS  LEADER  EPOCH  SEQUENCER  APPLIED-LSN  PERSISTED-LSN  SKIPPED-RECORDS  ARCHIVED-LSN  LAST-UPDATE
 0     N1:2  Follower          Active  -       -                 791          -              0                -             486 ms ago
 0     N2:1  Follower          Active  N2:1    e6     N3:1       800          -              0                -             928 ms ago
 0     N3:1  Follower->Leader  Active  -       -                 791          -              0                -             809 ms ago

All the ingresses are apparently stuck:

❯ curl http://ec2-13-246-9-133.af-south-1.compute.amazonaws.com:8080/Set/jepsen-set/get -m 2
curl: (28) Operation timed out after 2001 milliseconds with 0 bytes received
❯ curl http://ec2-13-246-7-188.af-south-1.compute.amazonaws.com:8080/Set/jepsen-set/get -m 2
curl: (28) Operation timed out after 2005 milliseconds with 0 bytes received
❯ curl http://ec2-13-247-62-130.af-south-1.compute.amazonaws.com:8080/Set/jepsen-set/get -m 2
curl: (28) Operation timed out after 2002 milliseconds with 0 bytes received

All three nodes are just emitting this to the log every second:

2025-01-28T20:40:51.373105Z DEBUG restate_admin::cluster_controller::cluster_state_refresher: Refreshing cluster state
2025-01-28T20:40:51.375368Z DEBUG restate_admin::cluster_controller::cluster_state_refresher: New cluster state is acquired, publishing
2025-01-28T20:40:51.375412Z DEBUG restate_admin::cluster_controller::service: Observed cluster state updated

@pcholakov pcholakov mentioned this issue Jan 28, 2025
Merged
@pcholakov
Copy link
Contributor Author

pcholakov commented Jan 29, 2025 •
edited
Loading

Also possibly relevant:

root@ip-172-31-1-45:~# rc meta get -k partition_table
{
  "version": 21,
  "num_partitions": 1,
  "partitions": [
    [
      0,
      {
        "cf_name": null,
        "db_name": null,
        "key_range": {
          "end": 18446744073709551615,
          "start": 0
        },
        "log_id": null,
        "placement": [
          2
        ]
      }
    ]
  ],
  "replication": "everywhere"
}

root@ip-172-31-1-45:~# rc part ls
Alive partition processors (nodes config v9, partition table v21)
 P-ID  NODE  MODE              STATUS  LEADER  EPOCH  SEQUENCER  APPLIED-LSN  PERSISTED-LSN  SKIPPED-RECORDS  ARCHIVED-LSN  LAST-UPDATE
 0     N1:2  Follower          Active  -       -                 791          -              0                -             295 ms ago
 0     N2:1  Follower          Active  N2:1    e6     N3:1       800          -              0                -             654 ms ago
 0     N3:1  Follower->Leader  Active  -       -                 791          -              0                -             348 ms ago

root@ip-172-31-1-45:~# rc logs desc 0
Log Id: 0 (v4)
  IDX  FROM-LSN  KIND        LOGLET-ID  REPLICATION  SEQUENCER  EFF-NODESET
  0    1         Replicated  0_0        {node: 2}    N1:2       [N1, N2, N3]
  1    793       Replicated  0_1        {node: 2}    N3:1       [N1, N2, N3]
▶︎ 2    800       Replicated  0_2        {node: 2}    N3:1       [N1, N2, N3]
---
3/3 segments shown.

The log from N2 (ec2-13-246-9-133 ) ends at 2025-01-28T20:31:11.930589Z but there's more that was logged after the test ended:

2025-01-28T20:31:17.978983Z DEBUG restate_core::partitions: Failed to sync routing information: failed syncing with metadata store: internal error: status: Unknown, message: "h2 protocol error: erro
r reading a body from connection", details: [], metadata: MetadataMap { headers: {"content-type": "application/grpc", "grpc-encoding": "gzip", "date": "Tue, 28 Jan 2025 20:30:50 GMT"} }
2025-01-28T20:31:17.979210Z DEBUG restate_admin::cluster_controller::scheduler: Will attempt to write partition table v20 to metadata store
2025-01-28T20:31:17.979175Z  WARN restate_admin::cluster_controller::service: Failed to handle observed cluster state. This can impair the overall cluster operations err=failed writing to metadata s
tore: internal error: status: Unknown, message: "transport error", details: [], metadata: MetadataMap { headers: {} }
2025-01-28T20:31:18.046325Z  INFO restate_admin::cluster_controller::scheduler: Write partition table to metadata store was rejected due to version conflict, this is benign unless it's happening rep
eatedly. In such case, we might be in a tight race with another admin node err="expected version 'v19' but found version 'Some(Version(20))'"
2025-01-28T20:31:18.134904Z  WARN trim_logs: restate_admin::cluster_controller::service::state: Log trimming is suspended until we can determine the processor state on all known cluster nodes. This
may result in increased log usage. Prune permanently decommissioned nodes and/or enable partition snapshotting to unblock trimming. blocking_nodes={PlainNodeId(1), PlainNodeId(3)} partition_table_ve
rsion=v20 logs_metadata_version=v3
2025-01-28T20:31:18.137269Z DEBUG run: restate_worker::partition: Shutting partition processor down because it was cancelled. partition_id=0 is_leader=false is_leader=true is_leader=false
2025-01-28T20:31:18.137290Z DEBUG run: restate_worker::partition::leadership: Stepping down. Being a role model for Joe. partition_id=0 is_leader=false is_leader=true is_leader=false
2025-01-28T20:31:18.137307Z DEBUG restate_core::task_center: Runtime pp-0 completed
2025-01-28T20:31:18.137313Z DEBUG restate_core::task_center: Runtime pp-0 completed
2025-01-28T20:31:18.139944Z DEBUG restate_admin::cluster_controller::scheduler: Will attempt to write partition table v21 to metadata store
2025-01-28T20:31:18.140063Z DEBUG on_asynchronous_event: restate_worker::partition_processor_manager: Partition processor stopped: Ok(()) partition_id=0 event=Stopped
2025-01-28T20:31:18.140088Z DEBUG restate_admin::cluster_controller::cluster_state_refresher: Refreshing cluster state
2025-01-28T20:31:18.143837Z DEBUG restate_admin::cluster_controller::cluster_state_refresher: New cluster state is acquired, publishing
2025-01-28T20:31:18.158743Z DEBUG restate_admin::cluster_controller::scheduler: Partition table v21 has been written to metadata store
2025-01-28T20:31:18.241702Z  INFO ingress: restate_ingress_http::handler::service_handler: Processing ingress request restate.invocation.id=inv_1gBNQzB6wIRK2k3QNOMUG6cJ92RvJ1rpjH restate.invocation.
target=Set/{key}/get
2025-01-28T20:31:18.250562Z DEBUG restate_admin::cluster_controller::service: Observed cluster state updated
2025-01-28T20:31:18.251306Z DEBUG on_asynchronous_event: restate_worker::partition_processor_manager: Partition processor was successfully created. target_run_mode=Leader partition_id=0 event=Starte
d
2025-01-28T20:31:18.251504Z  INFO restate_admin::cluster_controller::service::state: Cluster controller switching to follower mode, I think the leader is N1:2
2025-01-28T20:31:18.254745Z  INFO run: restate_worker::partition: Starting the partition processor. partition_id=0
2025-01-28T20:31:18.255458Z DEBUG restate_invoker_impl: Starting the invoker
2025-01-28T20:31:18.255775Z DEBUG run: restate_worker::partition: PartitionProcessor creating log reader last_applied_lsn=799 current_log_tail=800 (S) partition_id=0
2025-01-28T20:31:18.255921Z DEBUG run: restate_worker::partition: Processor has caught up with the log tail. last_applied_lsn=799 partition_id=0
2025-01-28T20:31:18.256016Z  INFO run: restate_worker::partition: PartitionProcessor starting event loop. partition_id=0
2025-01-28T20:31:18.308756Z DEBUG run:run_for_leader: restate_worker::partition::leadership: Running for leadership. partition_id=0 leader_epoch=e6
2025-01-28T20:31:18.308800Z  INFO run:run_for_leader: restate_bifrost::appender: Append batch will be retried (loglet is being sealed), waiting for tail to be determined attempt=1 segment_index=1 pa
rtition_id=0 leader_epoch=e6
2025-01-28T20:31:18.309468Z DEBUG on_asynchronous_event: restate_worker::partition_processor_manager::processor_state: Instruct partition processor to run as leader. leader_epoch=e6 partition_id=0 e
vent=NewLeaderEpoch
2025-01-28T20:31:18.322999Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=14.185223ms log_version=v3 partition_id=0 le
ader_epoch=e6 log_id=LogId(0) sealed_segment=SegmentIndex(1)
2025-01-28T20:31:18.349145Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=40.330546ms log_version=v3 partition_id=0 le
ader_epoch=e6 log_id=LogId(0) sealed_segment=SegmentIndex(1)
2025-01-28T20:31:18.401238Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=92.424033ms log_version=v3 partition_id=0 le
ader_epoch=e6 log_id=LogId(0) sealed_segment=SegmentIndex(1)
2025-01-28T20:31:18.501822Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=193.00796ms log_version=v3 partition_id=0 le
ader_epoch=e6 log_id=LogId(0) sealed_segment=SegmentIndex(1)
2025-01-28T20:31:18.678360Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=369.546135ms log_version=v3 partition_id=0 l
eader_epoch=e6 log_id=LogId(0) sealed_segment=SegmentIndex(1)
2025-01-28T20:31:19.078905Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=770.091277ms log_version=v3 partition_id=0 l
eader_epoch=e6 log_id=LogId(0) sealed_segment=SegmentIndex(1)
2025-01-28T20:31:19.136672Z DEBUG restate_admin::cluster_controller::cluster_state_refresher: Refreshing cluster state
2025-01-28T20:31:19.138140Z DEBUG restate_admin::cluster_controller::cluster_state_refresher: New cluster state is acquired, publishing
2025-01-28T20:31:19.138300Z DEBUG restate_admin::cluster_controller::service: Observed cluster state updated
2025-01-28T20:31:19.837382Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=1.528567143s log_version=v3 partition_id=0 l
eader_epoch=e6 log_id=LogId(0) sealed_segment=SegmentIndex(1)
2025-01-28T20:31:20.136487Z DEBUG restate_admin::cluster_controller::cluster_state_refresher: Refreshing cluster state
2025-01-28T20:31:20.137230Z DEBUG restate_admin::cluster_controller::cluster_state_refresher: New cluster state is acquired, publishing
2025-01-28T20:31:20.137322Z DEBUG restate_admin::cluster_controller::service: Observed cluster state updated
2025-01-28T20:31:20.235009Z  WARN restate_ingress_http::server: Error when serving the connection: hyper::Error(IncompleteMessage)
2025-01-28T20:31:20.885050Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=2.576235297s log_version=v3 partition_id=0 l
eader_epoch=e6 log_id=LogId(0) sealed_segment=SegmentIndex(1)
...

2025-01-28T20:32:54.009179Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Still waiting for sealing to complete. Elapsed=95.700365068s log_version=v3 partition_id=0
leader_epoch=e6 log_id=LogId(0) sealed_segment=SegmentIndex(1)
2025-01-28T20:32:54.147263Z DEBUG restate_admin::cluster_controller::cluster_state_refresher: Refreshing cluster state
2025-01-28T20:32:54.148236Z DEBUG restate_admin::cluster_controller::cluster_state_refresher: New cluster state is acquired, publishing
2025-01-28T20:32:54.148302Z DEBUG restate_admin::cluster_controller::service: Observed cluster state updated
2025-01-28T20:32:54.256233Z DEBUG network-reactor: restate_core::metadata::manager: Received metadata update from peer kind=Logs version=v4 peer=N1:2 peer_node_id=N1:2 protocol_version=1 task_id=579
6
2025-01-28T20:32:54.256329Z DEBUG run: restate_bifrost::providers::replicated_loglet::provider: Creating a replicated loglet client log_id=0 segment_index=2 loglet_id=0_2 nodeset=[N3, N1, N2] sequen
cer=N3:1 replication={node: 2} partition_id=0
2025-01-28T20:32:54.256644Z DEBUG restate_bifrost::providers::replicated_loglet::tasks::periodic_tail_checker: Starting a background periodic tail checker for this loglet loglet_id=0_2
2025-01-28T20:32:55.082009Z DEBUG run:run_for_leader:wait_next_unsealed_loglet: restate_bifrost::appender: Found an unsealed segment 2 after 96.773166148s partition_id=0 leader_epoch=e6 log_id=LogId
(0) sealed_segment=SegmentIndex(1)
2025-01-28T20:32:55.094067Z DEBUG run:on_announce_leader: restate_worker::partition::leadership: Won the leadership campaign. Becoming the strong leader now. partition_id=0 leader_epoch=e6
2025-01-28T20:32:55.094490Z DEBUG run:on_announce_leader: restate_worker::partition::leadership: Leader partition resumed 0 invocations partition_id=0 leader_epoch=e6
2025-01-28T20:32:55.094924Z DEBUG run:on_announce_leader: restate_worker::partition::shuffle: Running shuffle restate.node=N2:1 restate.partition.id=0 partition_id=0 is_leader=true leader_epoch=e6
2025-01-28T20:32:55.095073Z DEBUG run:on_announce_leader:run: restate_worker::partition::cleaner: Running cleaner partition_id=0 is_leader=true leader_epoch=e6 restate.partition.id=0
2025-01-28T20:32:55.096236Z DEBUG run:on_announce_leader:run: restate_worker::partition::cleaner: Executing completed invocations cleanup partition_id=0 is_leader=true leader_epoch=e6 restate.partit
ion.id=0
2025-01-28T20:32:55.144153Z DEBUG restate_admin::cluster_controller::cluster_state_refresher: Refreshing cluster state
2025-01-28T20:32:55.144984Z DEBUG restate_admin::cluster_controller::cluster_state_refresher: New cluster state is acquired, publishing
2025-01-28T20:32:55.145023Z DEBUG restate_admin::cluster_controller::service: Observed cluster state updated
2025-01-28T20:32:56.144226Z DEBUG restate_admin::cluster_controller::cluster_state_refresher: Refreshing cluster state
2025-01-28T20:32:56.145287Z DEBUG restate_admin::cluster_controller::cluster_state_refresher: New cluster state is acquired, publishing
2025-01-28T20:32:56.145423Z DEBUG restate_admin::cluster_controller::service: Observed cluster state updated
2025-01-28T20:32:56.307451Z DEBUG run: restate_worker::partition::leadership: Stepping down. Being a role model for Joe. partition_id=0 is_leader=true
2025-01-28T20:32:56.307487Z DEBUG run:on_announce_leader: restate_worker::partition::shuffle: Stopping shuffle restate.node=N2:1 partition_id=0 is_leader=true leader_epoch=e6
2025-01-28T20:32:56.307641Z DEBUG run:on_announce_leader:run: restate_worker::partition::cleaner: Stopping cleaner partition_id=0 is_leader=true leader_epoch=e6 restate.partition.id=0
2025-01-28T20:32:57.144019Z DEBUG restate_admin::cluster_controller::cluster_state_refresher: Refreshing cluster state
2025-01-28T20:32:57.145468Z DEBUG restate_admin::cluster_controller::cluster_state_refresher: New cluster state is acquired, publishing
2025-01-28T20:32:57.145510Z DEBUG restate_admin::cluster_controller::service: Observed cluster state updated

So it assumed leadership for the partition but about 1s later decided to step down? And then nobody else is attempting to grab the leadership since, explaining why ingress requests just hang.

@tillrohrmann
Copy link
Contributor

We might have fixed this issue with the latest batch of fixes. @pcholakov what do you think, should we close this issue?

@pcholakov
Copy link
Contributor Author

I am convinced that we've solved all the known issues - and with more aggressive keepalive settings, we can probably shrink the downtime windows even further. Calling this done!

Image

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@pcholakov @tillrohrmann