diff --git a/src/lib_shell/prevalidator.ml b/src/lib_shell/prevalidator.ml index f2a717e2ed659c40a2c9bcda5fb81cfad9d5e489..e2348168176b3a8c24727e94a7982a6cb2d8c408 100644 --- a/src/lib_shell/prevalidator.ml +++ b/src/lib_shell/prevalidator.ml @@ -725,11 +725,15 @@ module Make_s pv.shell.live_blocks) then failwith - "Operation %a is branched on a block %a which is too old" + "Operation %a is branched on either:\n\ + \ - a block %a which is too old (%d blocks in the past)\n\ + \ - a predecessor block from an alternative branch which is \ + now unknown" Operation_hash.pp oph Block_hash.pp op.Operation.shell.branch + (Block_hash.Set.cardinal pv.shell.live_blocks) else let notifier = mk_notifier pv.operation_stream in let*! validation_state, validated_operation, to_handle = diff --git a/src/proto_019_PtParisB/lib_delegate/operation_worker.ml b/src/proto_019_PtParisB/lib_delegate/operation_worker.ml index 42d91d24e545094991f557546a7a17f9bfdd0ecc..345b3ce63d81141850472ddc482c334113981855 100644 --- a/src/proto_019_PtParisB/lib_delegate/operation_worker.ml +++ b/src/proto_019_PtParisB/lib_delegate/operation_worker.ml @@ -55,7 +55,7 @@ module Events = struct declare_2 ~section ~name:"pqc_reached" - ~level:Debug + ~level:Info ~msg: "prequorum reached (voting power: {voting_power}, {preattestations} \ preattestations)" @@ -85,7 +85,7 @@ module Events = struct declare_2 ~section ~name:"qc_reached" - ~level:Debug + ~level:Info ~msg: "quorum reached (voting power: {voting_power}, {attestations} \ attestations)" @@ -119,6 +119,14 @@ module Events = struct ~msg:"starting new monitoring" () + let resetting_monitoring = + declare_0 + ~section + ~name:"resetting_monitoring" + ~level:Debug + ~msg:"resetting monitoring after a mempool flush" + () + let end_of_stream = declare_0 ~section @@ -300,19 +308,21 @@ let is_valid_consensus_content (candidate : candidate) consensus_content = let cancel_monitoring state = state.proposal_watched <- None let reset_monitoring state = + let open Lwt_syntax in Lwt_mutex.with_lock state.lock @@ fun () -> + let* () = Events.(emit resetting_monitoring ()) in match state.proposal_watched with - | None -> Lwt.return_unit + | None -> return_unit | Some (Pqc_watch pqc_watched) -> pqc_watched.current_voting_power <- 0 ; pqc_watched.preattestations_count <- 0 ; pqc_watched.preattestations_received <- Preattestation_set.empty ; - Lwt.return_unit + return_unit | Some (Qc_watch qc_watched) -> qc_watched.current_voting_power <- 0 ; qc_watched.attestations_count <- 0 ; qc_watched.attestations_received <- Attestation_set.empty ; - Lwt.return_unit + return_unit let update_monitoring ?(should_lock = true) state ops = let open Lwt_syntax in diff --git a/src/proto_020_PsParisC/lib_delegate/operation_worker.ml b/src/proto_020_PsParisC/lib_delegate/operation_worker.ml index 42d91d24e545094991f557546a7a17f9bfdd0ecc..345b3ce63d81141850472ddc482c334113981855 100644 --- a/src/proto_020_PsParisC/lib_delegate/operation_worker.ml +++ b/src/proto_020_PsParisC/lib_delegate/operation_worker.ml @@ -55,7 +55,7 @@ module Events = struct declare_2 ~section ~name:"pqc_reached" - ~level:Debug + ~level:Info ~msg: "prequorum reached (voting power: {voting_power}, {preattestations} \ preattestations)" @@ -85,7 +85,7 @@ module Events = struct declare_2 ~section ~name:"qc_reached" - ~level:Debug + ~level:Info ~msg: "quorum reached (voting power: {voting_power}, {attestations} \ attestations)" @@ -119,6 +119,14 @@ module Events = struct ~msg:"starting new monitoring" () + let resetting_monitoring = + declare_0 + ~section + ~name:"resetting_monitoring" + ~level:Debug + ~msg:"resetting monitoring after a mempool flush" + () + let end_of_stream = declare_0 ~section @@ -300,19 +308,21 @@ let is_valid_consensus_content (candidate : candidate) consensus_content = let cancel_monitoring state = state.proposal_watched <- None let reset_monitoring state = + let open Lwt_syntax in Lwt_mutex.with_lock state.lock @@ fun () -> + let* () = Events.(emit resetting_monitoring ()) in match state.proposal_watched with - | None -> Lwt.return_unit + | None -> return_unit | Some (Pqc_watch pqc_watched) -> pqc_watched.current_voting_power <- 0 ; pqc_watched.preattestations_count <- 0 ; pqc_watched.preattestations_received <- Preattestation_set.empty ; - Lwt.return_unit + return_unit | Some (Qc_watch qc_watched) -> qc_watched.current_voting_power <- 0 ; qc_watched.attestations_count <- 0 ; qc_watched.attestations_received <- Attestation_set.empty ; - Lwt.return_unit + return_unit let update_monitoring ?(should_lock = true) state ops = let open Lwt_syntax in diff --git a/tezt/lib_tezos/operation_core.ml b/tezt/lib_tezos/operation_core.ml index 7385662ad5c5605edda4a5b5240ecafaa3d8e922..d3ee0f4b45dc97ae75b97363cdab2c31229f5a1c 100644 --- a/tezt/lib_tezos/operation_core.ml +++ b/tezt/lib_tezos/operation_core.ml @@ -169,6 +169,18 @@ let inject ?(request = `Inject) ?force ?protocol ?signature ?error t client : let* () = Process.check_error ~msg process in hash t client +let inject_and_capture1_stderr ~rex ?force ?protocol ?signature t client = + let* runnable = spawn_inject ?force ?protocol ?signature t client in + let*? process = runnable in + let* stderr = Process.check_and_read_stderr ~expect_failure:true process in + match stderr =~* rex with + | None -> + Test.fail + "Injection was expected to fail with:\n%s\nbut instead failed with:\n%s" + (show_rex rex) + stderr + | Some groups -> return groups + let inject_and_capture2_stderr ~rex ?force ?protocol ?signature t client = let* runnable = spawn_inject ?force ?protocol ?signature t client in let*? process = runnable in @@ -892,3 +904,6 @@ let already_denounced = let outdated_denunciation = rex {|A double-([\w]+) denunciation is outdated \(last acceptable cycle: ([\d]+), given level: ([\d]+)\).|} + +let injection_error_unknown_branch = + rex {|Operation ([\w\d]+) is branched on either:|} diff --git a/tezt/lib_tezos/operation_core.mli b/tezt/lib_tezos/operation_core.mli index bd5d563e5398bca745752592603fba691b908d08..36c17899db652a91a140c3b94e6700114dc81a2f 100644 --- a/tezt/lib_tezos/operation_core.mli +++ b/tezt/lib_tezos/operation_core.mli @@ -132,6 +132,9 @@ val byte_size : injection fails. If the injection succeeds, the hash of the operation is returned. + @param dont_wait If [true], the operation is injected without waiting + on some node event. Making [request] ignore. Default is [false]. + @param request If [`Inject], we do not wait the [prevalidator] to classify the operation. This can create some flakyness in the test but is needed to test corner cases. If [`Notify], the function @@ -171,6 +174,16 @@ val spawn_inject : Client.t -> JSON.t Runnable.process Lwt.t +(** Run [spawn_inject] then capture one group on stderr with [rex]. *) +val inject_and_capture1_stderr : + rex:rex -> + ?force:bool -> + ?protocol:Protocol.t -> + ?signature:Tezos_crypto.Signature.t -> + t -> + Client.t -> + string Lwt.t + (** Run [spawn_inject] then capture two groups on stderr with [rex]. *) val inject_and_capture2_stderr : rex:rex -> @@ -719,3 +732,10 @@ val already_denounced : rex Captures [kind], [last_cycle], [level]. *) val outdated_denunciation : rex + +(** Matches the message + [Operation %a is branched on either:] + from [src/lib_shell/prevalidator.ml]. + + Captures [hash]. *) +val injection_error_unknown_branch : rex diff --git a/tezt/tests/operations_liveness.ml b/tezt/tests/operations_liveness.ml index d3672f06cda4799dec1f6df07259456bb3b59e22..9b9040e2b48fb9f124617b2197c2d67c9ad0cdc2 100644 --- a/tezt/tests/operations_liveness.ml +++ b/tezt/tests/operations_liveness.ml @@ -123,11 +123,9 @@ let operation_liveness_reorg = client1 in Log.info "Injecting op targeting a non-liveblock (expected to fail)" ; - let* _, _ = - Operation.inject_and_capture2_stderr - ~rex: - (rex - {|Operation ([\w\d]+) is branched on a block ([\w\d]+) which is too old|}) + let* _ = + Operation.inject_and_capture1_stderr + ~rex:Operation_core.injection_error_unknown_branch non_live_op client1 in @@ -218,11 +216,9 @@ let operation_liveness_reorg = in Log.info "Injecting op targeting a non-liveblock" ; - let* _, _ = - Operation.inject_and_capture2_stderr - ~rex: - (rex - {|Operation ([\w\d]+) is branched on a block ([\w\d]+) which is too old|}) + let* _ = + Operation.inject_and_capture1_stderr + ~rex:Operation_core.injection_error_unknown_branch non_live_op client1 in @@ -278,11 +274,9 @@ let operation_liveness = client1 in Log.info "Injecting op targeting a non-liveblock (expected to fail)" ; - let* _, _ = - Operation.inject_and_capture2_stderr - ~rex: - (rex - {|Operation ([\w\d]+) is branched on a block ([\w\d]+) which is too old|}) + let* _ = + Operation.inject_and_capture1_stderr + ~rex:Operation_core.injection_error_unknown_branch non_live_op client1 in diff --git a/tezt/tests/prevalidator.ml b/tezt/tests/prevalidator.ml index ce5ff26c838d82c88f890aa94881ea269cca1476..7936955a409a048208c81a798d0ce2a178363fed 100644 --- a/tezt/tests/prevalidator.ml +++ b/tezt/tests/prevalidator.ml @@ -3766,14 +3766,7 @@ let injecting_old_operation_fails = Client.RPC.spawn client @@ RPC.post_injection_operation (Data (`String (op_str_hex ^ signature))) in - let injection_error_rex = - rex - ~opts:[`Dotall] - "Fatal error:\n\ - \ Command failed: Operation .* is branched on a block .* which is too \ - old" - in - Process.check_error ~msg:injection_error_rex process + Process.check_error ~msg:Operation_core.injection_error_unknown_branch process let test_request_operations_peer = let step1_msg = "Step 1: Connect and initialise two nodes " in