Bug Type:
crash
Seed:
11654694784361616086
Commit Hash:
01494c5
Parameters:
[info] (state_checker):
SEED=11654694784361616086
replicas=3
clients=4
request_probability=11%
idle_on_probability=18%
idle_off_probability=11%
one_way_delay_mean=9 ticks
one_way_delay_min=2 ticks
packet_loss_probability=25%
path_maximum_capacity=20 messages
path_clog_duration_mean=227 ticks
path_clog_probability=0%
packet_replay_probability=26%
partition_mode=PartitionMode.uniform_partition
partition_probability=0%
unpartition_probability=2%
partition_stability=176 ticks
unpartition_stability=9 ticks
read_latency_min=2
read_latency_mean=9
write_latency_min=0
write_latency_mean=66
read_fault_probability=6%
write_fault_probability=3%
crash_probability=0.01%
crash_stability=752 ticks
restart_probability=1%
restart_stability=966 ticks
Tail of Debug Logs:
556530337571515, .checksum_body = 85493199026511476387022115951477938651, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2381, .op = 68, .commit = 68, .timestamp = 2, .size = 4224, .replica = 0, .command = Command.do_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (network): send_message: Process{ .replica = 0 } > Process{ .replica = 2 }: Command.do_view_change
[debug] (vsr): 1: view_change_message_timeout fired
[debug] (vsr): 1: view_change_message_timeout reset
[debug] (replica): 1: sending start_view_change to replica 0: Header{ .checksum = 216442080330958390782706069435631874842, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2381, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 1, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (network): send_message: Process{ .replica = 1 } > Process{ .replica = 0 }: Command.start_view_change
[debug] (replica): 1: sending start_view_change to replica 2: Header{ .checksum = 216442080330958390782706069435631874842, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2381, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 1, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (network): send_message: Process{ .replica = 1 } > Process{ .replica = 2 }: Command.start_view_change
[debug] (journal): 1: copy_latest_headers_between: op_min=0 op_max=68 dest.len=32 copied=32
[debug] (replica): 1: sending do_view_change to replica 2: Header{ .checksum = 314762811721899295135296439442619662016, .checksum_body = 85493199026511476387022115951477938651, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2381, .op = 68, .commit = 68, .timestamp = 2, .size = 4224, .replica = 1, .command = Command.do_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (network): send_message: Process{ .replica = 1 } > Process{ .replica = 2 }: Command.do_view_change
[debug] (vsr): 2: view_change_message_timeout fired
[debug] (vsr): 2: view_change_message_timeout reset
[debug] (packet_simulator): delivering packet from=0 to=1
[debug] (network): deliver_message: Process{ .replica = 0 } > Process{ .replica = 1 }: Command.start_view_change
[debug] (replica): 1: on_message: view=2381 status=Status.view_change Header{ .checksum = 265406233045811921053519574710870372982, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2381, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 0, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (replica): 1: on_start_view_change: ignoring (duplicate message replica=0)
[debug] (packet_simulator): replayed packet from=1 to=2
[debug] (network): deliver_message: Process{ .replica = 1 } > Process{ .replica = 2 }: Command.do_view_change
[debug] (replica): 2: on_message: view=2381 status=Status.view_change Header{ .checksum = 314762811721899295135296439442619662016, .checksum_body = 85493199026511476387022115951477938651, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2381, .op = 68, .commit = 68, .timestamp = 2, .size = 4224, .replica = 1, .command = Command.do_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (replica): 2: on_do_view_change: ignoring (duplicate message)
[debug] (packet_simulator): replayed packet from=1 to=0
[debug] (network): deliver_message: Process{ .replica = 1 } > Process{ .replica = 0 }: Command.start_view_change
[debug] (replica): 0: on_message: view=2381 status=Status.view_change Header{ .checksum = 216442080330958390782706069435631874842, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2381, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 1, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (replica): 0: on_start_view_change: ignoring (duplicate message replica=1)
[err] (packet_simulator): dropped packet from=1 to=0.
[err] (packet_simulator): dropped packet from=1 to=2.
[err] (packet_simulator): dropped packet from=1 to=2.
[debug] (vsr): 2: repair_timeout fired
[debug] (vsr): 2: repair_timeout reset
[debug] (replica): 2: repair_prepare: op=26 checksum=330296907629322072566147740092185258661 (committed, faulty)
[debug] (replica): 2: sending request_prepare to replica 1: Header{ .checksum = 141751061205600343772700865275573114638, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 330296907629322072566147740092185258661, .request = 0, .cluster = 0, .epoch = 0, .view = 2381, .op = 26, .commit = 0, .timestamp = 1, .size = 128, .replica = 2, .command = Command.request_prepare, .operation = Operation.reserved, .version = 0 }
[debug] (network): send_message: Process{ .replica = 2 } > Process{ .replica = 1 }: Command.request_prepare
[err] (packet_simulator): dropped packet from=0 to=2.
[debug] (packet_simulator): delivering packet from=0 to=2
[debug] (network): deliver_message: Process{ .replica = 0 } > Process{ .replica = 2 }: Command.do_view_change
[debug] (replica): 2: on_message: view=2381 status=Status.view_change Header{ .checksum = 197544816351296270016908556530337571515, .checksum_body = 85493199026511476387022115951477938651, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2381, .op = 68, .commit = 68, .timestamp = 2, .size = 4224, .replica = 0, .command = Command.do_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (replica): 2: on_do_view_change: ignoring (duplicate message)
[err] (packet_simulator): dropped packet from=2 to=1.
[debug] (vsr): 0: view_change_message_timeout fired
[debug] (vsr): 0: view_change_message_timeout reset
[debug] (replica): 0: sending start_view_change to replica 1: Header{ .checksum = 265406233045811921053519574710870372982, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2381, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 0, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (network): send_message: Process{ .replica = 0 } > Process{ .replica = 1 }: Command.start_view_change
[debug] (replica): 0: sending start_view_change to replica 2: Header{ .checksum = 265406233045811921053519574710870372982, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2381, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 0, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (network): send_message: Process{ .replica = 0 } > Process{ .replica = 2 }: Command.start_view_change
[debug] (journal): 0: copy_latest_headers_between: op_min=0 op_max=68 dest.len=32 copied=32
[debug] (replica): 0: sending do_view_change to replica 2: Header{ .checksum = 197544816351296270016908556530337571515, .checksum_body = 85493199026511476387022115951477938651, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2381, .op = 68, .commit = 68, .timestamp = 2, .size = 4224, .replica = 0, .command = Command.do_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (network): send_message: Process{ .replica = 0 } > Process{ .replica = 2 }: Command.do_view_change
[debug] (vsr): 1: view_change_message_timeout fired
[debug] (vsr): 1: view_change_message_timeout reset
[debug] (replica): 1: sending start_view_change to replica 0: Header{ .checksum = 216442080330958390782706069435631874842, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2381, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 1, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (network): send_message: Process{ .replica = 1 } > Process{ .replica = 0 }: Command.start_view_change
[debug] (replica): 1: sending start_view_change to replica 2: Header{ .checksum = 216442080330958390782706069435631874842, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2381, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 1, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (network): send_message: Process{ .replica = 1 } > Process{ .replica = 2 }: Command.start_view_change
[debug] (journal): 1: copy_latest_headers_between: op_min=0 op_max=68 dest.len=32 copied=32
[debug] (replica): 1: sending do_view_change to replica 2: Header{ .checksum = 314762811721899295135296439442619662016, .checksum_body = 85493199026511476387022115951477938651, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2381, .op = 68, .commit = 68, .timestamp = 2, .size = 4224, .replica = 1, .command = Command.do_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (network): send_message: Process{ .replica = 1 } > Process{ .replica = 2 }: Command.do_view_change
[debug] (vsr): 2: view_change_message_timeout fired
[debug] (vsr): 2: view_change_message_timeout reset
[debug] (packet_simulator): delivering packet from=0 to=1
[debug] (network): deliver_message: Process{ .replica = 0 } > Process{ .replica = 1 }: Command.start_view_change
[debug] (replica): 1: on_message: view=2381 status=Status.view_change Header{ .checksum = 265406233045811921053519574710870372982, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2381, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 0, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (replica): 1: on_start_view_change: ignoring (duplicate message replica=0)
[debug] (packet_simulator): replayed packet from=1 to=2
[debug] (network): deliver_message: Process{ .replica = 1 } > Process{ .replica = 2 }: Command.start_view_change
[debug] (replica): 2: on_message: view=2381 status=Status.view_change Header{ .checksum = 216442080330958390782706069435631874842, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2381, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 1, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (replica): 2: on_start_view_change: ignoring (duplicate message replica=1)
[debug] (packet_simulator): delivering packet from=1 to=2
[debug] (network): deliver_message: Process{ .replica = 1 } > Process{ .replica = 2 }: Command.do_view_change
[debug] (replica): 2: on_message: view=2381 status=Status.view_change Header{ .checksum = 314762811721899295135296439442619662016, .checksum_body = 85493199026511476387022115951477938651, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2381, .op = 68, .commit = 68, .timestamp = 2, .size = 4224, .replica = 1, .command = Command.do_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (replica): 2: on_do_view_change: ignoring (duplicate message)
[debug] (packet_simulator): delivering packet from=0 to=2
[debug] (network): deliver_message: Process{ .replica = 0 } > Process{ .replica = 2 }: Command.start_view_change
[debug] (replica): 2: on_message: view=2381 status=Status.view_change Header{ .checksum = 265406233045811921053519574710870372982, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2381, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 0, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (replica): 2: on_start_view_change: ignoring (duplicate message replica=0)
[debug] (packet_simulator): delivering packet from=1 to=0
[debug] (network): deliver_message: Process{ .replica = 1 } > Process{ .replica = 0 }: Command.start_view_change
[debug] (replica): 0: on_message: view=2381 status=Status.view_change Header{ .checksum = 216442080330958390782706069435631874842, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2381, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 1, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (replica): 0: on_start_view_change: ignoring (duplicate message replica=1)
[debug] (packet_simulator): delivering packet from=0 to=2
[debug] (network): deliver_message: Process{ .replica = 0 } > Process{ .replica = 2 }: Command.do_view_change
[debug] (replica): 2: on_message: view=2381 status=Status.view_change Header{ .checksum = 197544816351296270016908556530337571515, .checksum_body = 85493199026511476387022115951477938651, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2381, .op = 68, .commit = 68, .timestamp = 2, .size = 4224, .replica = 0, .command = Command.do_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (replica): 2: on_do_view_change: ignoring (duplicate message)
[debug] (packet_simulator): delivering packet from=1 to=2
[debug] (network): deliver_message: Process{ .replica = 1 } > Process{ .replica = 2 }: Command.start_view_change
[debug] (replica): 2: on_message: view=2381 status=Status.view_change Header{ .checksum = 216442080330958390782706069435631874842, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2381, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 1, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (replica): 2: on_start_view_change: ignoring (duplicate message replica=1)
[debug] (vsr): 2: repair_timeout fired
[debug] (vsr): 2: repair_timeout reset
[debug] (replica): 2: repair_prepare: op=26 checksum=330296907629322072566147740092185258661 (committed, faulty)
[debug] (replica): 2: sending request_prepare to replica 0: Header{ .checksum = 141751061205600343772700865275573114638, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 330296907629322072566147740092185258661, .request = 0, .cluster = 0, .epoch = 0, .view = 2381, .op = 26, .commit = 0, .timestamp = 1, .size = 128, .replica = 2, .command = Command.request_prepare, .operation = Operation.reserved, .version = 0 }
[debug] (network): send_message: Process{ .replica = 2 } > Process{ .replica = 0 }: Command.request_prepare
[err] (packet_simulator): dropped packet from=2 to=0.
[debug] (vsr): 0: view_change_status_timeout fired
[debug] (replica): 0: transition_to_view_change_status: view=2381..2382
[debug] (vsr): 0: ping_timeout stopped
[debug] (vsr): 0: commit_timeout stopped
[debug] (vsr): 0: normal_status_timeout stopped
[debug] (vsr): 0: view_change_status_timeout started
[debug] (vsr): 0: view_change_message_timeout started
[debug] (vsr): 0: repair_timeout stopped
[debug] (vsr): 0: prepare_timeout stopped
[debug] (replica): 0: reset 0 do_view_change message(s) from view=null
[debug] (replica): 0: sending start_view_change to replica 1: Header{ .checksum = 324959638660945898287986245671188119283, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 0, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (network): send_message: Process{ .replica = 0 } > Process{ .replica = 1 }: Command.start_view_change
[debug] (replica): 0: sending start_view_change to replica 2: Header{ .checksum = 324959638660945898287986245671188119283, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 0, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (network): send_message: Process{ .replica = 0 } > Process{ .replica = 2 }: Command.start_view_change
[debug] (vsr): 1: view_change_status_timeout fired
[debug] (replica): 1: transition_to_view_change_status: view=2381..2382
[debug] (vsr): 1: ping_timeout stopped
[debug] (vsr): 1: commit_timeout stopped
[debug] (vsr): 1: normal_status_timeout stopped
[debug] (vsr): 1: view_change_status_timeout started
[debug] (vsr): 1: view_change_message_timeout started
[debug] (vsr): 1: repair_timeout stopped
[debug] (vsr): 1: prepare_timeout stopped
[debug] (replica): 1: reset 0 do_view_change message(s) from view=null
[debug] (replica): 1: sending start_view_change to replica 0: Header{ .checksum = 177911432912993993546198503214099478402, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 1, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (network): send_message: Process{ .replica = 1 } > Process{ .replica = 0 }: Command.start_view_change
[debug] (replica): 1: sending start_view_change to replica 2: Header{ .checksum = 177911432912993993546198503214099478402, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 1, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (network): send_message: Process{ .replica = 1 } > Process{ .replica = 2 }: Command.start_view_change
[debug] (vsr): 2: view_change_status_timeout fired
[debug] (replica): 2: transition_to_view_change_status: view=2381..2382
[debug] (vsr): 2: ping_timeout stopped
[debug] (vsr): 2: commit_timeout stopped
[debug] (vsr): 2: normal_status_timeout stopped
[debug] (vsr): 2: view_change_status_timeout started
[debug] (vsr): 2: view_change_message_timeout started
[debug] (vsr): 2: repair_timeout stopped
[debug] (vsr): 2: prepare_timeout stopped
[debug] (replica): 2: reset 3 do_view_change message(s) from view=2381
[debug] (replica): 2: sending start_view_change to replica 0: Header{ .checksum = 295802827437696205256588745679722478451, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 2, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (network): send_message: Process{ .replica = 2 } > Process{ .replica = 0 }: Command.start_view_change
[debug] (replica): 2: sending start_view_change to replica 1: Header{ .checksum = 295802827437696205256588745679722478451, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 2, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (network): send_message: Process{ .replica = 2 } > Process{ .replica = 1 }: Command.start_view_change
[debug] (packet_simulator): replayed packet from=2 to=0
[debug] (network): deliver_message: Process{ .replica = 2 } > Process{ .replica = 0 }: Command.start_view_change
[debug] (replica): 0: on_message: view=2382 status=Status.view_change Header{ .checksum = 295802827437696205256588745679722478451, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 2, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (replica): 0: on_start_view_change: 1 message(s)
[debug] (replica): 0: on_start_view_change: view=2382 quorum received
[debug] (journal): 0: copy_latest_headers_between: op_min=0 op_max=68 dest.len=32 copied=32
[debug] (replica): 0: sending do_view_change to replica 0: Header{ .checksum = 235617427791570318995208597014748332261, .checksum_body = 85493199026511476387022115951477938651, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 68, .commit = 68, .timestamp = 2, .size = 4224, .replica = 0, .command = Command.do_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (replica): 0: on_message: view=2382 status=Status.view_change Header{ .checksum = 235617427791570318995208597014748332261, .checksum_body = 85493199026511476387022115951477938651, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 68, .commit = 68, .timestamp = 2, .size = 4224, .replica = 0, .command = Command.do_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (replica): 0: on_do_view_change: 1 message(s)
[debug] (replica): 0: on_do_view_change: waiting for quorum
[err] (packet_simulator): dropped packet from=2 to=1.
[debug] (packet_simulator): delivering packet from=0 to=1
[debug] (network): deliver_message: Process{ .replica = 0 } > Process{ .replica = 1 }: Command.start_view_change
[debug] (replica): 1: on_message: view=2382 status=Status.view_change Header{ .checksum = 324959638660945898287986245671188119283, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 0, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (replica): 1: on_start_view_change: 1 message(s)
[debug] (replica): 1: on_start_view_change: view=2382 quorum received
[debug] (journal): 1: copy_latest_headers_between: op_min=0 op_max=68 dest.len=32 copied=32
[debug] (replica): 1: sending do_view_change to replica 0: Header{ .checksum = 298157826303812085379030874232707016109, .checksum_body = 85493199026511476387022115951477938651, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 68, .commit = 68, .timestamp = 2, .size = 4224, .replica = 1, .command = Command.do_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (network): send_message: Process{ .replica = 1 } > Process{ .replica = 0 }: Command.do_view_change
[debug] (packet_simulator): delivering packet from=0 to=2
[debug] (network): deliver_message: Process{ .replica = 0 } > Process{ .replica = 2 }: Command.start_view_change
[debug] (replica): 2: on_message: view=2382 status=Status.view_change Header{ .checksum = 324959638660945898287986245671188119283, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 0, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (replica): 2: on_start_view_change: 1 message(s)
[debug] (replica): 2: on_start_view_change: view=2382 quorum received
[debug] (journal): 2: copy_latest_headers_between: op_min=0 op_max=68 dest.len=32 copied=32
[debug] (replica): 2: sending do_view_change to replica 0: Header{ .checksum = 209168693276895636277850210138742452951, .checksum_body = 85493199026511476387022115951477938651, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 68, .commit = 68, .timestamp = 2, .size = 4224, .replica = 2, .command = Command.do_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (network): send_message: Process{ .replica = 2 } > Process{ .replica = 0 }: Command.do_view_change
[debug] (packet_simulator): replayed packet from=1 to=0
[debug] (network): deliver_message: Process{ .replica = 1 } > Process{ .replica = 0 }: Command.start_view_change
[debug] (replica): 0: on_message: view=2382 status=Status.view_change Header{ .checksum = 177911432912993993546198503214099478402, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 1, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (replica): 0: on_start_view_change: 2 message(s)
[debug] (replica): 0: on_start_view_change: ignoring (quorum received already)
[debug] (packet_simulator): delivering packet from=1 to=0
[debug] (network): deliver_message: Process{ .replica = 1 } > Process{ .replica = 0 }: Command.do_view_change
[debug] (replica): 0: on_message: view=2382 status=Status.view_change Header{ .checksum = 298157826303812085379030874232707016109, .checksum_body = 85493199026511476387022115951477938651, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 68, .commit = 68, .timestamp = 2, .size = 4224, .replica = 1, .command = Command.do_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (replica): 0: on_do_view_change: 2 message(s)
[debug] (replica): 0: on_do_view_change: view=2382 quorum received
[debug] (replica): 0: on_do_view_change: replica=0 v'=2 op=68 commit=68 latest=Header{ .checksum = 271408327367023641725539222960565597137, .checksum_body = 200511362828524740113934185482600390872, .parent = 281142446631901820053319140298981567249, .client = 337275728709412499007489779383344250735, .context = 67099398369097624982858333466227228509, .request = 18, .cluster = 0, .epoch = 0, .view = 2, .op = 68, .commit = 67, .timestamp = 260630000000, .size = 354528, .replica = 2, .command = Command.prepare, .operation = Operation(3), .version = 0 }
[debug] (replica): 0: on_do_view_change: replica=1 v'=2 op=68 commit=68 latest=Header{ .checksum = 271408327367023641725539222960565597137, .checksum_body = 200511362828524740113934185482600390872, .parent = 281142446631901820053319140298981567249, .client = 337275728709412499007489779383344250735, .context = 67099398369097624982858333466227228509, .request = 18, .cluster = 0, .epoch = 0, .view = 2, .op = 68, .commit = 67, .timestamp = 260630000000, .size = 354528, .replica = 2, .command = Command.prepare, .operation = Operation(3), .version = 0 }
[debug] (replica): 0: on_do_view_change: view=2382 op=68..68 commit=68..68 checksum=271408327367023641725539222960565597137
[debug] (replica): 0: on_do_view_change: latest op exists exactly
[debug] (journal): 0: remove_entries_from: op_min=69
[debug] (replica): 0: repair_header: op=68 false (checksum clean)
[debug] (replica): 0: repair_header: op=67 false (checksum clean)
[debug] (replica): 0: repair_header: op=66 false (checksum clean)
[debug] (replica): 0: repair_header: op=65 false (checksum clean)
[debug] (replica): 0: repair_header: op=64 false (checksum clean)
[debug] (replica): 0: repair_header: op=63 false (checksum clean)
[debug] (replica): 0: repair_header: op=62 false (checksum clean)
[debug] (replica): 0: repair_header: op=61 false (checksum clean)
[debug] (replica): 0: repair_header: op=60 false (checksum clean)
[debug] (replica): 0: repair_header: op=59 false (checksum clean)
[debug] (replica): 0: repair_header: op=58 false (checksum clean)
[debug] (replica): 0: repair_header: op=57 false (checksum clean)
[debug] (replica): 0: repair_header: op=56 false (checksum clean)
[debug] (replica): 0: repair_header: op=55 false (checksum clean)
[debug] (replica): 0: repair_header: op=54 false (checksum clean)
[debug] (replica): 0: repair_header: op=53 false (checksum clean)
[debug] (replica): 0: repair_header: op=52 false (checksum clean)
[debug] (replica): 0: repair_header: op=51 false (checksum clean)
[debug] (replica): 0: repair_header: op=50 false (checksum clean)
[debug] (replica): 0: repair_header: op=49 false (checksum clean)
[debug] (replica): 0: repair_header: op=48 false (checksum clean)
[debug] (replica): 0: repair_header: op=47 false (checksum clean)
[debug] (replica): 0: repair_header: op=46 false (checksum clean)
[debug] (replica): 0: repair_header: op=45 false (checksum clean)
[debug] (replica): 0: repair_header: op=44 false (checksum clean)
[debug] (replica): 0: repair_header: op=43 false (checksum clean)
[debug] (replica): 0: repair_header: op=42 false (checksum clean)
[debug] (replica): 0: repair_header: op=41 false (checksum clean)
[debug] (replica): 0: repair_header: op=40 false (checksum clean)
[debug] (replica): 0: repair_header: op=39 false (checksum clean)
[debug] (replica): 0: repair_header: op=38 false (checksum clean)
[debug] (replica): 0: repair_header: op=37 false (checksum clean)
[debug] (replica): 0: repair_header: op=68 false (checksum clean)
[debug] (replica): 0: repair_header: op=67 false (checksum clean)
[debug] (replica): 0: repair_header: op=66 false (checksum clean)
[debug] (replica): 0: repair_header: op=65 false (checksum clean)
[debug] (replica): 0: repair_header: op=64 false (checksum clean)
[debug] (replica): 0: repair_header: op=63 false (checksum clean)
[debug] (replica): 0: repair_header: op=62 false (checksum clean)
[debug] (replica): 0: repair_header: op=61 false (checksum clean)
[debug] (replica): 0: repair_header: op=60 false (checksum clean)
[debug] (replica): 0: repair_header: op=59 false (checksum clean)
[debug] (replica): 0: repair_header: op=58 false (checksum clean)
[debug] (replica): 0: repair_header: op=57 false (checksum clean)
[debug] (replica): 0: repair_header: op=56 false (checksum clean)
[debug] (replica): 0: repair_header: op=55 false (checksum clean)
[debug] (replica): 0: repair_header: op=54 false (checksum clean)
[debug] (replica): 0: repair_header: op=53 false (checksum clean)
[debug] (replica): 0: repair_header: op=52 false (checksum clean)
[debug] (replica): 0: repair_header: op=51 false (checksum clean)
[debug] (replica): 0: repair_header: op=50 false (checksum clean)
[debug] (replica): 0: repair_header: op=49 false (checksum clean)
[debug] (replica): 0: repair_header: op=48 false (checksum clean)
[debug] (replica): 0: repair_header: op=47 false (checksum clean)
[debug] (replica): 0: repair_header: op=46 false (checksum clean)
[debug] (replica): 0: repair_header: op=45 false (checksum clean)
[debug] (replica): 0: repair_header: op=44 false (checksum clean)
[debug] (replica): 0: repair_header: op=43 false (checksum clean)
[debug] (replica): 0: repair_header: op=42 false (checksum clean)
[debug] (replica): 0: repair_header: op=41 false (checksum clean)
[debug] (replica): 0: repair_header: op=40 false (checksum clean)
[debug] (replica): 0: repair_header: op=39 false (checksum clean)
[debug] (replica): 0: repair_header: op=38 false (checksum clean)
[debug] (replica): 0: repair_header: op=37 false (checksum clean)
[debug] (vsr): 0: repair_timeout started
[debug] (vsr): 0: repair_timeout reset
[debug] (replica): 0: repair_prepare: op=26 checksum=330296907629322072566147740092185258661 (committed, dirty)
[debug] (replica): 0: sending request_prepare to replica 2: Header{ .checksum = 255204168481056663064229495403465633312, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 330296907629322072566147740092185258661, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 26, .commit = 0, .timestamp = 1, .size = 128, .replica = 0, .command = Command.request_prepare, .operation = Operation.reserved, .version = 0 }
[debug] (network): send_message: Process{ .replica = 0 } > Process{ .replica = 2 }: Command.request_prepare
[debug] (packet_simulator): delivering packet from=1 to=2
[debug] (network): deliver_message: Process{ .replica = 1 } > Process{ .replica = 2 }: Command.start_view_change
[debug] (replica): 2: on_message: view=2382 status=Status.view_change Header{ .checksum = 177911432912993993546198503214099478402, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 1, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (replica): 2: on_start_view_change: 2 message(s)
[debug] (replica): 2: on_start_view_change: ignoring (quorum received already)
[err] (packet_simulator): dropped packet from=2 to=0.
[debug] (packet_simulator): delivering packet from=1 to=0
[debug] (network): deliver_message: Process{ .replica = 1 } > Process{ .replica = 0 }: Command.start_view_change
[debug] (replica): 0: on_message: view=2382 status=Status.view_change Header{ .checksum = 177911432912993993546198503214099478402, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 1, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (replica): 0: on_start_view_change: ignoring (duplicate message replica=1)
[debug] (packet_simulator): delivering packet from=0 to=2
[debug] (network): deliver_message: Process{ .replica = 0 } > Process{ .replica = 2 }: Command.request_prepare
[debug] (replica): 2: on_message: view=2382 status=Status.view_change Header{ .checksum = 255204168481056663064229495403465633312, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 330296907629322072566147740092185258661, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 26, .commit = 0, .timestamp = 1, .size = 128, .replica = 0, .command = Command.request_prepare, .operation = Operation.reserved, .version = 0 }
[debug] (replica): 2: on_request_prepare: op=26 checksum=330296907629322072566147740092185258661 reading
[info] (journal): 2: read_prepare: op=26 checksum=330296907629322072566147740092185258661: faulty
[debug] (replica): 2: on_request_prepare_read: prepare=null
[debug] (packet_simulator): replayed packet from=2 to=0
[debug] (network): deliver_message: Process{ .replica = 2 } > Process{ .replica = 0 }: Command.start_view_change
[debug] (replica): 0: on_message: view=2382 status=Status.view_change Header{ .checksum = 295802827437696205256588745679722478451, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 2, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (replica): 0: on_start_view_change: ignoring (duplicate message replica=2)
[debug] (packet_simulator): delivering packet from=2 to=0
[debug] (network): deliver_message: Process{ .replica = 2 } > Process{ .replica = 0 }: Command.start_view_change
[debug] (replica): 0: on_message: view=2382 status=Status.view_change Header{ .checksum = 295802827437696205256588745679722478451, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 2, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (replica): 0: on_start_view_change: ignoring (duplicate message replica=2)
[debug] (vsr): 0: view_change_message_timeout fired
[debug] (vsr): 0: view_change_message_timeout reset
[debug] (vsr): 1: view_change_message_timeout fired
[debug] (vsr): 1: view_change_message_timeout reset
[debug] (replica): 1: sending start_view_change to replica 0: Header{ .checksum = 177911432912993993546198503214099478402, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 1, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (network): send_message: Process{ .replica = 1 } > Process{ .replica = 0 }: Command.start_view_change
[debug] (replica): 1: sending start_view_change to replica 2: Header{ .checksum = 177911432912993993546198503214099478402, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 1, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (network): send_message: Process{ .replica = 1 } > Process{ .replica = 2 }: Command.start_view_change
[debug] (journal): 1: copy_latest_headers_between: op_min=0 op_max=68 dest.len=32 copied=32
[debug] (replica): 1: sending do_view_change to replica 0: Header{ .checksum = 298157826303812085379030874232707016109, .checksum_body = 85493199026511476387022115951477938651, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 68, .commit = 68, .timestamp = 2, .size = 4224, .replica = 1, .command = Command.do_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (network): send_message: Process{ .replica = 1 } > Process{ .replica = 0 }: Command.do_view_change
[debug] (vsr): 2: view_change_message_timeout fired
[debug] (vsr): 2: view_change_message_timeout reset
[debug] (replica): 2: sending start_view_change to replica 0: Header{ .checksum = 295802827437696205256588745679722478451, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 2, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (network): send_message: Process{ .replica = 2 } > Process{ .replica = 0 }: Command.start_view_change
[debug] (replica): 2: sending start_view_change to replica 1: Header{ .checksum = 295802827437696205256588745679722478451, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 2, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (network): send_message: Process{ .replica = 2 } > Process{ .replica = 1 }: Command.start_view_change
[debug] (journal): 2: copy_latest_headers_between: op_min=0 op_max=68 dest.len=32 copied=32
[debug] (replica): 2: sending do_view_change to replica 0: Header{ .checksum = 209168693276895636277850210138742452951, .checksum_body = 85493199026511476387022115951477938651, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 68, .commit = 68, .timestamp = 2, .size = 4224, .replica = 2, .command = Command.do_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (network): send_message: Process{ .replica = 2 } > Process{ .replica = 0 }: Command.do_view_change
[err] (packet_simulator): dropped packet from=2 to=0.
[debug] (packet_simulator): delivering packet from=2 to=1
[debug] (network): deliver_message: Process{ .replica = 2 } > Process{ .replica = 1 }: Command.start_view_change
[debug] (replica): 1: on_message: view=2382 status=Status.view_change Header{ .checksum = 295802827437696205256588745679722478451, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 2, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (replica): 1: on_start_view_change: 2 message(s)
[debug] (replica): 1: on_start_view_change: ignoring (quorum received already)
[debug] (packet_simulator): replayed packet from=1 to=0
[debug] (network): deliver_message: Process{ .replica = 1 } > Process{ .replica = 0 }: Command.do_view_change
[debug] (replica): 0: on_message: view=2382 status=Status.view_change Header{ .checksum = 298157826303812085379030874232707016109, .checksum_body = 85493199026511476387022115951477938651, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 68, .commit = 68, .timestamp = 2, .size = 4224, .replica = 1, .command = Command.do_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (replica): 0: on_do_view_change: ignoring (duplicate message)
[debug] (packet_simulator): replayed packet from=2 to=0
[debug] (network): deliver_message: Process{ .replica = 2 } > Process{ .replica = 0 }: Command.start_view_change
[debug] (replica): 0: on_message: view=2382 status=Status.view_change Header{ .checksum = 295802827437696205256588745679722478451, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 2, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (replica): 0: on_start_view_change: ignoring (duplicate message replica=2)
[debug] (vsr): 0: repair_timeout fired
[debug] (vsr): 0: repair_timeout reset
[debug] (replica): 0: repair_prepare: op=26 checksum=330296907629322072566147740092185258661 (committed, dirty)
[debug] (replica): 0: sending request_prepare to replica 1: Header{ .checksum = 255204168481056663064229495403465633312, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 330296907629322072566147740092185258661, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 26, .commit = 0, .timestamp = 1, .size = 128, .replica = 0, .command = Command.request_prepare, .operation = Operation.reserved, .version = 0 }
[debug] (network): send_message: Process{ .replica = 0 } > Process{ .replica = 1 }: Command.request_prepare
[debug] (packet_simulator): delivering packet from=1 to=0
[debug] (network): deliver_message: Process{ .replica = 1 } > Process{ .replica = 0 }: Command.start_view_change
[debug] (replica): 0: on_message: view=2382 status=Status.view_change Header{ .checksum = 177911432912993993546198503214099478402, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 1, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (replica): 0: on_start_view_change: ignoring (duplicate message replica=1)
[err] (packet_simulator): dropped packet from=1 to=0.
[debug] (packet_simulator): replayed packet from=1 to=2
[debug] (network): deliver_message: Process{ .replica = 1 } > Process{ .replica = 2 }: Command.start_view_change
[debug] (replica): 2: on_message: view=2382 status=Status.view_change Header{ .checksum = 177911432912993993546198503214099478402, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 1, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (replica): 2: on_start_view_change: ignoring (duplicate message replica=1)
[debug] (packet_simulator): delivering packet from=2 to=0
[debug] (network): deliver_message: Process{ .replica = 2 } > Process{ .replica = 0 }: Command.start_view_change
[debug] (replica): 0: on_message: view=2382 status=Status.view_change Header{ .checksum = 295802827437696205256588745679722478451, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 2, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (replica): 0: on_start_view_change: ignoring (duplicate message replica=2)
[debug] (packet_simulator): delivering packet from=1 to=2
[debug] (network): deliver_message: Process{ .replica = 1 } > Process{ .replica = 2 }: Command.start_view_change
[debug] (replica): 2: on_message: view=2382 status=Status.view_change Header{ .checksum = 177911432912993993546198503214099478402, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 1, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (replica): 2: on_start_view_change: ignoring (duplicate message replica=1)
[err] (packet_simulator): dropped packet from=0 to=1.
[debug] (vsr): 0: view_change_message_timeout fired
[debug] (vsr): 0: view_change_message_timeout reset
[debug] (vsr): 1: view_change_message_timeout fired
[debug] (vsr): 1: view_change_message_timeout reset
[debug] (replica): 1: sending start_view_change to replica 0: Header{ .checksum = 177911432912993993546198503214099478402, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 1, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (network): send_message: Process{ .replica = 1 } > Process{ .replica = 0 }: Command.start_view_change
[debug] (replica): 1: sending start_view_change to replica 2: Header{ .checksum = 177911432912993993546198503214099478402, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 1, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (network): send_message: Process{ .replica = 1 } > Process{ .replica = 2 }: Command.start_view_change
[debug] (journal): 1: copy_latest_headers_between: op_min=0 op_max=68 dest.len=32 copied=32
[debug] (replica): 1: sending do_view_change to replica 0: Header{ .checksum = 298157826303812085379030874232707016109, .checksum_body = 85493199026511476387022115951477938651, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 68, .commit = 68, .timestamp = 2, .size = 4224, .replica = 1, .command = Command.do_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (network): send_message: Process{ .replica = 1 } > Process{ .replica = 0 }: Command.do_view_change
[debug] (vsr): 2: view_change_message_timeout fired
[debug] (vsr): 2: view_change_message_timeout reset
[debug] (replica): 2: sending start_view_change to replica 0: Header{ .checksum = 295802827437696205256588745679722478451, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 2, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (network): send_message: Process{ .replica = 2 } > Process{ .replica = 0 }: Command.start_view_change
[debug] (replica): 2: sending start_view_change to replica 1: Header{ .checksum = 295802827437696205256588745679722478451, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 2, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (network): send_message: Process{ .replica = 2 } > Process{ .replica = 1 }: Command.start_view_change
[debug] (journal): 2: copy_latest_headers_between: op_min=0 op_max=68 dest.len=32 copied=32
[debug] (replica): 2: sending do_view_change to replica 0: Header{ .checksum = 209168693276895636277850210138742452951, .checksum_body = 85493199026511476387022115951477938651, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 68, .commit = 68, .timestamp = 2, .size = 4224, .replica = 2, .command = Command.do_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (network): send_message: Process{ .replica = 2 } > Process{ .replica = 0 }: Command.do_view_change
[debug] (packet_simulator): delivering packet from=1 to=0
[debug] (network): deliver_message: Process{ .replica = 1 } > Process{ .replica = 0 }: Command.start_view_change
[debug] (replica): 0: on_message: view=2382 status=Status.view_change Header{ .checksum = 177911432912993993546198503214099478402, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 1, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (replica): 0: on_start_view_change: ignoring (duplicate message replica=1)
[err] (packet_simulator): dropped packet from=2 to=1.
[err] (packet_simulator): dropped packet from=2 to=0.
[debug] (vsr): 0: repair_timeout fired
[debug] (vsr): 0: repair_timeout reset
[debug] (replica): 0: repair_prepare: op=26 checksum=330296907629322072566147740092185258661 (committed, dirty)
[debug] (replica): 0: sending request_prepare to replica 2: Header{ .checksum = 255204168481056663064229495403465633312, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 330296907629322072566147740092185258661, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 26, .commit = 0, .timestamp = 1, .size = 128, .replica = 0, .command = Command.request_prepare, .operation = Operation.reserved, .version = 0 }
[debug] (network): send_message: Process{ .replica = 0 } > Process{ .replica = 2 }: Command.request_prepare
[err] (packet_simulator): dropped packet from=2 to=0.
[debug] (packet_simulator): delivering packet from=1 to=2
[debug] (network): deliver_message: Process{ .replica = 1 } > Process{ .replica = 2 }: Command.start_view_change
[debug] (replica): 2: on_message: view=2382 status=Status.view_change Header{ .checksum = 177911432912993993546198503214099478402, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 1, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (replica): 2: on_start_view_change: ignoring (duplicate message replica=1)
[debug] (packet_simulator): delivering packet from=1 to=0
[debug] (network): deliver_message: Process{ .replica = 1 } > Process{ .replica = 0 }: Command.do_view_change
[debug] (replica): 0: on_message: view=2382 status=Status.view_change Header{ .checksum = 298157826303812085379030874232707016109, .checksum_body = 85493199026511476387022115951477938651, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 68, .commit = 68, .timestamp = 2, .size = 4224, .replica = 1, .command = Command.do_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (replica): 0: on_do_view_change: ignoring (duplicate message)
[debug] (packet_simulator): delivering packet from=0 to=2
[debug] (network): deliver_message: Process{ .replica = 0 } > Process{ .replica = 2 }: Command.request_prepare
[debug] (replica): 2: on_message: view=2382 status=Status.view_change Header{ .checksum = 255204168481056663064229495403465633312, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 330296907629322072566147740092185258661, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 26, .commit = 0, .timestamp = 1, .size = 128, .replica = 0, .command = Command.request_prepare, .operation = Operation.reserved, .version = 0 }
[debug] (replica): 2: on_request_prepare: op=26 checksum=330296907629322072566147740092185258661 reading
[info] (journal): 2: read_prepare: op=26 checksum=330296907629322072566147740092185258661: faulty
[debug] (replica): 2: on_request_prepare_read: prepare=null
[debug] (vsr): 0: view_change_message_timeout fired
[debug] (vsr): 0: view_change_message_timeout reset
[debug] (vsr): 1: view_change_message_timeout fired
[debug] (vsr): 1: view_change_message_timeout reset
[debug] (replica): 1: sending start_view_change to replica 0: Header{ .checksum = 177911432912993993546198503214099478402, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 1, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (network): send_message: Process{ .replica = 1 } > Process{ .replica = 0 }: Command.start_view_change
[debug] (replica): 1: sending start_view_change to replica 2: Header{ .checksum = 177911432912993993546198503214099478402, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 1, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (network): send_message: Process{ .replica = 1 } > Process{ .replica = 2 }: Command.start_view_change
[debug] (journal): 1: copy_latest_headers_between: op_min=0 op_max=68 dest.len=32 copied=32
[debug] (replica): 1: sending do_view_change to replica 0: Header{ .checksum = 298157826303812085379030874232707016109, .checksum_body = 85493199026511476387022115951477938651, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 68, .commit = 68, .timestamp = 2, .size = 4224, .replica = 1, .command = Command.do_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (network): send_message: Process{ .replica = 1 } > Process{ .replica = 0 }: Command.do_view_change
[debug] (vsr): 2: view_change_message_timeout fired
[debug] (vsr): 2: view_change_message_timeout reset
[debug] (replica): 2: sending start_view_change to replica 0: Header{ .checksum = 295802827437696205256588745679722478451, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 2, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (network): send_message: Process{ .replica = 2 } > Process{ .replica = 0 }: Command.start_view_change
[debug] (replica): 2: sending start_view_change to replica 1: Header{ .checksum = 295802827437696205256588745679722478451, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 2, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (network): send_message: Process{ .replica = 2 } > Process{ .replica = 1 }: Command.start_view_change
[debug] (journal): 2: copy_latest_headers_between: op_min=0 op_max=68 dest.len=32 copied=32
[debug] (replica): 2: sending do_view_change to replica 0: Header{ .checksum = 209168693276895636277850210138742452951, .checksum_body = 85493199026511476387022115951477938651, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 68, .commit = 68, .timestamp = 2, .size = 4224, .replica = 2, .command = Command.do_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (network): send_message: Process{ .replica = 2 } > Process{ .replica = 0 }: Command.do_view_change
[err] (packet_simulator): dropped packet from=2 to=0.
[debug] (packet_simulator): delivering packet from=2 to=0
[debug] (network): deliver_message: Process{ .replica = 2 } > Process{ .replica = 0 }: Command.do_view_change
[debug] (replica): 0: on_message: view=2382 status=Status.view_change Header{ .checksum = 209168693276895636277850210138742452951, .checksum_body = 85493199026511476387022115951477938651, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 68, .commit = 68, .timestamp = 2, .size = 4224, .replica = 2, .command = Command.do_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (replica): 0: on_do_view_change: 3 message(s)
[debug] (replica): 0: on_do_view_change: ignoring (quorum received already)
[debug] (packet_simulator): delivering packet from=1 to=0
[debug] (network): deliver_message: Process{ .replica = 1 } > Process{ .replica = 0 }: Command.start_view_change
[debug] (replica): 0: on_message: view=2382 status=Status.view_change Header{ .checksum = 177911432912993993546198503214099478402, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 0, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 0, .commit = 0, .timestamp = 0, .size = 128, .replica = 1, .command = Command.start_view_change, .operation = Operation.reserved, .version = 0 }
[debug] (replica): 0: on_start_view_change: ignoring (duplicate message replica=1)
[debug] (vsr): 0: repair_timeout fired
[debug] (vsr): 0: repair_timeout reset
[debug] (replica): 0: repair_prepare: op=26 checksum=330296907629322072566147740092185258661 (committed, dirty)
[debug] (replica): 0: sending request_prepare to replica 1: Header{ .checksum = 255204168481056663064229495403465633312, .checksum_body = 98081761841810822994326224503485043631, .parent = 0, .client = 0, .context = 330296907629322072566147740092185258661, .request = 0, .cluster = 0, .epoch = 0, .view = 2382, .op = 26, .commit = 0, .timestamp = 1, .size = 128, .replica = 0, .command = Command.request_prepare, .o
Time:
2022-07-12 15:35:27.421150085 +0000 UTC