duties: log more details #2419
Open
duties: log more details #2419
Conversation
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
![greptile-apps[bot]](https://avatars.githubusercontent.com/in/867647?s=60&v=4){kind=small}
There was a problem hiding this comment.
Your free trial has ended. If you'd like to continue receiving code reviews, you can add a payment method here.
Codecov Report❌ Patch coverage is ☔ View full report in Codecov by Sentry. 🚀 New features to boost your workflow:
|
iurii-ssv
force-pushed
the
logs-log-more-details-per-validator-slot-epoch
branch
from
a194343 to
b71146e
Compare
iurii-ssv
changed the title
iurii-ssv
force-pushed
the
logs-log-more-details-per-validator-slot-epoch
branch
3 times, most recently
from
d1d37a7 to
70c9e81
Compare
iurii-ssv
force-pushed
the
logs-log-more-details-per-validator-slot-epoch
branch
3 times, most recently
from
8f3e8d6 to
33107aa
Compare
iurii-ssv
commented
Aug 27, 2025
operator/duties/scheduler.go
Outdated
Comment on lines
426
to
425
| go func(ctx context.Context) { | ||
| if duty.Type == spectypes.BNRoleAttester || duty.Type == spectypes.BNRoleSyncCommittee { | ||
| s.waitOneThirdOrValidBlock(duty.Slot) | ||
| } | ||
| recordDutyExecuted(ctx, duty.RunnerRole()) | ||
| s.dutyExecutor.ExecuteDuty(ctx, duty) | ||
| }(ctx) |
There was a problem hiding this comment.
Removing this if here because ExecuteDuties manages validator-based duties while BNRoleAttester and BNRoleSyncCommittee are committee-based duties (managed by ExecuteCommitteeDuties), so this is a dead code effectively at this point
There was a problem hiding this comment.
Greptile Summary
This PR implements comprehensive logging improvements across the SSV codebase to provide more granular and consistent duty tracing capabilities. The changes focus on two main areas:
Logging Enhancements:
- Added logger parameters to base message processing methods (
basePreConsensusMsgProcessing,baseConsensusMsgProcessing,basePostConsensusMsgProcessing) to enable structured logging with proper context throughout duty execution - Implemented detailed timing measurements across duty phases (pre-consensus, consensus, post-consensus) with new fields like
Tookreplacing genericSubmissionTime - Added comprehensive duty completion logging with timing breakdowns for all runner types (proposer, aggregator, committee, sync committee)
- Enhanced event logging with more specific descriptions and validator-specific information to enable filtering by slot + validator index
- Standardized logging patterns across different duty types, preparing the foundation for duty trace ID implementation (issue #1828)
Code Organization:
- Consolidated storage interfaces by moving QBFT storage functionality from
protocol/v2/qbft/storagetoibft/storage, updating imports throughout the codebase - Reorganized spec test files and moved testing utilities to reduce inter-package dependencies
- Inlined event message processing in validator components, replacing abstract
handleEventMessagecalls with explicit type-specific handling - Exported
ParticipantStoragestruct and moved utility functions likeGetSpecDirto more appropriate packages
The changes maintain backward compatibility while establishing consistent logging infrastructure that will support future duty tracing improvements. The timing enhancements and validator-specific logging enable operators to debug specific duty failures by filtering logs with precise criteria.
Confidence score: 4/5
- This PR introduces significant logging improvements with minimal risk to core functionality, though some timing logic changes require attention
- Score reflects mostly safe refactoring with well-structured logging enhancements, but includes one behavioral change that could affect duty execution timing
- Pay close attention to
operator/duties/scheduler.gowhere duty waiting logic was moved and could impact validator performance
Context used:
Rule - Prefer shorter, clearer names for methods and constants. If one condition implies another (e.g., attesting implies participating), use the more specific name rather than combining both concepts. (link)
46 files reviewed, 2 comments
iurii-ssv
force-pushed
the
logs-log-more-details-per-validator-slot-epoch
branch
from
0ced541 to
80f51e5
Compare
iurii-ssv
force-pushed
the
logs-log-more-details-per-validator-slot-epoch
branch
from
20ccfa3 to
8adc3ec
Compare
There was a problem hiding this comment.
Greptile Overview
Summary
This PR enhances logging throughout the SSV duty execution pipeline to improve observability and debugging capabilities. The changes focus on three main areas:
Consistency Improvements:
- Standardizes logging patterns across all duty types (proposer, aggregator, committee, sync committee contribution, validator registration, voluntary exit)
- Introduces consistent event naming conventions using
constdeclarations for log messages and span events - Adds structured fields through the
fieldspackage for better log parsing and filtering
Granular Timing Measurements:
- Implements detailed timing measurements for pre-consensus, consensus, and post-consensus phases
- Adds duration tracking for beacon API calls, block fetching, and submission operations
- Provides comprehensive duty lifecycle timing from start to completion
Enhanced Debugging Support:
- Adds more detailed logging at key decision points in the duty execution flow
- Includes timing information (
fields.Took()) for operations that could impact performance - Maintains consistent logging structure to support the planned duty trace ID feature (#1828)
The changes are well-structured and follow existing patterns in the codebase. All modifications maintain the current logging levels and don't introduce performance overhead. The PR also includes minor spec test file reorganization to simplify dependencies, though this doesn't affect the main functionality.
Confidence Score: 5/5
- This PR is safe to merge with no risk
- Score of 5 reflects that this is a purely observability enhancement with no functional changes to core logic. All modifications are additive logging improvements that follow established patterns and don't alter execution paths or introduce new dependencies.
- No files require special attention
Important Files Changed
File Analysis
| Filename | Score | Overview |
|---|---|---|
| protocol/v2/ssv/runner/sync_committee_contribution.go | 5/5 | Enhanced logging with timing measurements and granular duty processing steps. No logical issues detected. |
| protocol/v2/ssv/runner/runner.go | 5/5 | Base runner improvements with consistent event naming and improved observability spans. Code is well-structured. |
| protocol/v2/ssv/runner/proposer.go | 5/5 | Improved logging with timing measurements and more detailed event tracking for block proposal process. Changes look solid. |
| protocol/v2/ssv/runner/aggregator.go | 5/5 | Enhanced logging consistency with detailed timing measurements and improved event descriptions. Implementation is clean. |
| observability/log/fields/fields.go | 5/5 | Adds consistent field definitions for structured logging across duty types. No issues with field implementations. |
| protocol/v2/ssv/runner/committee.go | 5/5 | Committee runner enhanced with detailed logging and measurement tracking for better observability. Code quality is good. |
| protocol/v2/ssv/validator/validator.go | 5/5 | Enhanced event logging for duty processing with improved observability spans and timing measurements. |
Sequence Diagram
sequenceDiagram
participant Scheduler as Duty Scheduler
participant Runner as Duty Runner
participant Logger as Enhanced Logger
participant Beacon as Beacon Node
participant Network as P2P Network
Note over Scheduler,Network: Enhanced Logging Flow for Duty Processing
Scheduler->>Runner: StartNewDuty(duty, quorum)
Runner->>Logger: Log "starting duty processing" with timing
Note over Runner,Logger: Pre-Consensus Phase
Runner->>Runner: StartPreConsensus() measurement
Runner->>Network: Broadcast partial signature
Runner->>Logger: Log signature broadcast with event details
Network->>Runner: Receive partial signatures from peers
Runner->>Logger: Log "got partial signatures" with signer info
Runner->>Runner: Check for quorum
alt Quorum achieved
Runner->>Logger: Log "got pre consensus quorum" event
Runner->>Runner: EndPreConsensus() measurement
Runner->>Logger: Log timing with fields.PreConsensusTime()
end
Note over Runner,Beacon: Beacon Node Interaction (Proposer Example)
Runner->>Beacon: GetBeaconBlock() with timing
Beacon->>Runner: Return block data
Runner->>Logger: Log block details (hash, fee_recipient, took duration)
Note over Runner,Logger: Consensus Phase
Runner->>Runner: StartConsensus() measurement
Runner->>Runner: QBFT consensus processing
alt Consensus decided
Runner->>Logger: Log "QBFT instance is decided" event
Runner->>Runner: EndConsensus() measurement
Runner->>Logger: Log consensus timing
end
Note over Runner,Logger: Post-Consensus Phase
Runner->>Runner: StartPostConsensus() measurement
Runner->>Network: Broadcast post-consensus partial sig
Network->>Runner: Receive post-consensus signatures
alt Quorum achieved
Runner->>Logger: Log "got post consensus quorum"
Runner->>Runner: EndPostConsensus() measurement
Runner->>Beacon: Submit to beacon chain with timing
alt Submission successful
Runner->>Logger: Log "successfully submitted" with took duration
Runner->>Runner: EndDutyFlow() measurement
Runner->>Logger: Log final duty summary with all phase timings
else Submission failed
Runner->>Logger: Log error with took duration and error details
end
end
Note over Runner,Logger: Comprehensive Timing Output
Runner->>Logger: Final log with PreConsensusTime, ConsensusTime, PostConsensusTime, TotalDutyTime
54 files reviewed, no comments
iurii-ssv
force-pushed
the
logs-log-more-details-per-validator-slot-epoch
branch
from
8adc3ec to
a3d6730
Compare
iurii-ssv
commented
Sep 27, 2025
Comment on lines
73
to
96
| // Start is an interface implementation | ||
| func (i *Instance) Start(ctx context.Context, logger *zap.Logger, value []byte, height specqbft.Height) { | ||
| i.startOnce.Do(func() { | ||
| _, span := tracer.Start(ctx, | ||
| observability.InstrumentName(observabilityNamespace, "qbft.instance.start"), | ||
| trace.WithAttributes(observability.BeaconSlotAttribute(phase0.Slot(height)))) | ||
| defer span.End() | ||
|
|
||
| i.StartValue = value | ||
| i.bumpToRound(specqbft.FirstRound) | ||
| i.State.Height = height | ||
| i.metrics.Start() | ||
| i.config.GetTimer().TimeoutForRound(height, specqbft.FirstRound) |
There was a problem hiding this comment.
We don't need a startOnce thingy because we only start the Instance in Controller.StartNewInstance which checks whether or not the instance already exists before creating & starting it (which is how it actually should be done, using sync.Once is a hacky way to go about it)
|
/test |
|
/test |
🔴 Test run for PR #2419Branch: logs-log-more-details-per-validator-slot-epoch Status
Result - 🔴 FailureClick to expand executor logs═══════════════════════════════════════════════════════════════════════════════════════════════════════
🧪 WELCOME TO Executor - SSV's Distributed Test Automation Execution Layer 🧪
___ __ __ ___ ___ _ _ _____ ___ ___
| __|\ \/ /| __|/ __|| | | ||_ _|/ _ \ | _ \
| _| > < | _|| (__ | |_| | | | | (_) || /
|___|/_/\_\|___|\___| \___/ |_| \___/ |_|_\
═══════════════════════════════════════════════════════════════════════════════════════════════════════
{"time":"2025-09-29T07:57:27.918808004Z","level":"INFO","msg":"🐳 Docker mode: Using environment variables for config generation"}
{"time":"2025-09-29T07:57:27.931700675Z","level":"INFO","msg":"🌐 Orchestrator API Client initialized","endpoint":"http://aetheria-orchestrator.aetheria.svc:8080"}
{"time":"2025-09-29T07:57:27.931778603Z","level":"INFO","msg":"📝 Requesting configuration generation from orchestrator API","network":"hoodi_stage","clusters":[300,301,302,303],"tests":"(sanity)"}
{"time":"2025-09-29T07:57:27.991115778Z","level":"INFO","msg":"✅ Configuration generated successfully via API","resource_usage_id":"4bb68d1fcf69c5830c352e60a66d0f6e"}
{"time":"2025-09-29T07:57:27.991868386Z","level":"INFO","msg":"🚀 EXECUTOR Initialized Successfully"}
{"time":"2025-09-29T07:57:27.991916456Z","level":"INFO","msg":"⚙️ Test configuration loaded","network":"hoodi_stage","nodes":[300,301,302,303],"test_type":{"Sanity":{"ShouldRun":true,"E2M":false,"BulkAmount":0},"Bulk":{"ShouldRun":false,"E2M":false,"BulkAmount":0},"Isolated":{"Tests":null}}}
{"time":"2025-09-29T07:57:32.676389468Z","level":"INFO","msg":"Generated operator pubkeys file","module":"scanner","path":"/app/shared/data/operators/operator-pubkeys-hoodi_stage.json"}
{"time":"2025-09-29T07:57:32.676741551Z","level":"INFO","msg":"Registered parser","module":"main","component":"parser-client","parser_type":"consensus"}
{"time":"2025-09-29T07:57:32.676815789Z","level":"INFO","msg":"Registered parser","module":"main","component":"parser-client","parser_type":"flow-emits"}
{"time":"2025-09-29T07:57:32.676897483Z","level":"INFO","msg":"Validation client initialized","module":"main","loki_enabled":true,"e2m_enabled":false}
{"time":"2025-09-29T07:57:32.67697777Z","level":"INFO","msg":"🔑 KEY STEP: Starting Isolated Tests Concurrently if exists...","module":"main"}
{"time":"2025-09-29T07:57:32.677114098Z","level":"INFO","msg":"🔑 KEY STEP: Starting Sanity Test Suite","module":"main"}
{"time":"2025-09-29T07:57:32.677497884Z","level":"INFO","msg":"No isolated tests configured, skipping","module":"main"}
{"time":"2025-09-29T07:57:32.756190508Z","level":"INFO","msg":"Getting available slots","test":"sanity","node":300}
{"time":"2025-09-29T07:57:32.773398029Z","level":"INFO","msg":"Available slots","test":"sanity","node":300,"slots":3000}
{"time":"2025-09-29T07:57:32.773512281Z","level":"INFO","msg":"Getting available slots","test":"sanity","node":301}
{"time":"2025-09-29T07:57:32.78334526Z","level":"INFO","msg":"Available slots","test":"sanity","node":301,"slots":398}
{"time":"2025-09-29T07:57:32.783436531Z","level":"INFO","msg":"Getting available slots","test":"sanity","node":302}
{"time":"2025-09-29T07:57:32.792266226Z","level":"INFO","msg":"Available slots","test":"sanity","node":302,"slots":297}
{"time":"2025-09-29T07:57:32.792352255Z","level":"INFO","msg":"Getting available slots","test":"sanity","node":303}
{"time":"2025-09-29T07:57:32.79989561Z","level":"INFO","msg":"Available slots","test":"sanity","node":303,"slots":716}
{"time":"2025-09-29T07:58:02.892450877Z","level":"ERROR","msg":"❌ FAILURE: Sanity Test Suite Failed","module":"main","error":"nonce not found in output"}
{"time":"2025-09-29T07:58:02.892564876Z","level":"INFO","msg":"⏳ PROGRESS: Waiting for all tests to finish","module":"main"}
{"time":"2025-09-29T07:58:02.892666147Z","level":"ERROR","msg":"❌ FAILURE: Test Execution Completed with Failures","module":"main","passed_suites":null,"failed_suites":["sanity"],"skipped_suites":["isolated"]}
{"time":"2025-09-29T07:58:02.892717556Z","level":"ERROR","msg":"❌ FAILURE: Suite Failure Details","module":"main","suite":"sanity","error":"nonce not found in output"}
{"time":"2025-09-29T07:58:02.892764154Z","level":"INFO","msg":"🔑 KEY STEP: Starting resource teardown...","module":"main","usage_id":"4bb68d1fcf69c5830c352e60a66d0f6e"}
{"time":"2025-09-29T07:58:02.898488573Z","level":"INFO","msg":"🌐 Orchestrator API Client initialized","module":"main","endpoint":"http://aetheria-orchestrator.aetheria.svc:8080"}
{"time":"2025-09-29T07:58:02.898588259Z","level":"INFO","msg":"🧹 Requesting resource teardown","module":"main","usage_id":"4bb68d1fcf69c5830c352e60a66d0f6e"}
{"time":"2025-09-29T07:58:02.922077667Z","level":"INFO","msg":"✅ SUCCESS: Completed resource teardown successfully","module":"main","usage_id":"4bb68d1fcf69c5830c352e60a66d0f6e"}
|
|
/test cluster=304,305,306,307 tests=(sanity) |
🔴 Test run for PR #2419Branch: logs-log-more-details-per-validator-slot-epoch Status
Click to expand executor logs═══════════════════════════════════════════════════════════════════════════════════════════════════════
🧪 WELCOME TO Executor - SSV's Distributed Test Automation Execution Layer 🧪
___ __ __ ___ ___ _ _ _____ ___ ___
| __|\\ \\/ /| __|/ __|| | | ||_ _|/ _ \\ | _ \\
| _| > < | _|| (__ | |_| | | | | (_) || /
|___|/_/\\_\\|___|\\___| \\___/ |_| \\___/ |_|_\\
═══════════════════════════════════════════════════════════════════════════════════════════════════════
{"time":"2025-09-29T13:00:31.976832772Z","level":"INFO","msg":"🐳 Docker mode: Using environment variables for config generation"}
{"time":"2025-09-29T13:00:31.984419708Z","level":"INFO","msg":"🌐 Orchestrator API Client initialized","endpoint":"http://aetheria-orchestrator.aetheria.svc:8080"}
{"time":"2025-09-29T13:00:31.984586485Z","level":"INFO","msg":"📝 Requesting configuration generation from orchestrator API","network":"hoodi_stage","clusters":[304,305,306,307],"tests":"(sanity)"}
{"time":"2025-09-29T13:00:32.09314453Z","level":"INFO","msg":"✅ Configuration generated successfully via API","resource_usage_id":"9dcffe4fd858017b85d552c67714acaa"}
{"time":"2025-09-29T13:00:32.094949634Z","level":"INFO","msg":"🚀 EXECUTOR Initialized Successfully"}
{"time":"2025-09-29T13:00:32.095087283Z","level":"INFO","msg":"⚙️ Test configuration loaded","network":"hoodi_stage","nodes":[304,305,306,307],"test_type":{"Sanity":{"ShouldRun":true,"E2M":false,"BulkAmount":0},"Bulk":{"ShouldRun":false,"E2M":false,"BulkAmount":0},"Isolated":{"Tests":null}}}
{"time":"2025-09-29T13:00:36.453404375Z","level":"INFO","msg":"Generated operator pubkeys file","module":"scanner","path":"/app/shared/data/operators/operator-pubkeys-hoodi_stage.json"}
{"time":"2025-09-29T13:00:36.453663202Z","level":"INFO","msg":"Registered parser","module":"main","component":"parser-client","parser_type":"consensus"}
{"time":"2025-09-29T13:00:36.453727895Z","level":"INFO","msg":"Registered parser","module":"main","component":"parser-client","parser_type":"flow-emits"}
{"time":"2025-09-29T13:00:36.453790113Z","level":"INFO","msg":"Validation client initialized","module":"main","loki_enabled":true,"e2m_enabled":false}
{"time":"2025-09-29T13:00:36.453831032Z","level":"INFO","msg":"🔑 KEY STEP: Starting Isolated Tests Concurrently if exists...","module":"main"}
{"time":"2025-09-29T13:00:36.453916943Z","level":"INFO","msg":"🔑 KEY STEP: Starting Sanity Test Suite","module":"main"}
{"time":"2025-09-29T13:00:36.454030599Z","level":"INFO","msg":"No isolated tests configured, skipping","module":"main"}
{"time":"2025-09-29T13:00:36.509674899Z","level":"INFO","msg":"Getting available slots","test":"sanity","node":304}
{"time":"2025-09-29T13:00:36.531903154Z","level":"INFO","msg":"Available slots","test":"sanity","node":304,"slots":3000}
{"time":"2025-09-29T13:00:36.531953812Z","level":"INFO","msg":"Getting available slots","test":"sanity","node":305}
{"time":"2025-09-29T13:00:36.538802847Z","level":"INFO","msg":"Available slots","test":"sanity","node":305,"slots":398}
{"time":"2025-09-29T13:00:36.53883486Z","level":"INFO","msg":"Getting available slots","test":"sanity","node":306}
{"time":"2025-09-29T13:00:36.544715969Z","level":"INFO","msg":"Available slots","test":"sanity","node":306,"slots":297}
{"time":"2025-09-29T13:00:36.544748149Z","level":"INFO","msg":"Getting available slots","test":"sanity","node":307}
{"time":"2025-09-29T13:00:36.55072545Z","level":"INFO","msg":"Available slots","test":"sanity","node":307,"slots":716}
{"time":"2025-09-29T13:02:34.91292522Z","level":"ERROR","msg":"❌ FAILURE: Sanity Test Suite Failed","module":"main","error":"nonce not found in output"}
{"time":"2025-09-29T13:02:34.913015014Z","level":"INFO","msg":"⏳ PROGRESS: Waiting for all tests to finish","module":"main"}
{"time":"2025-09-29T13:02:34.913166101Z","level":"ERROR","msg":"❌ FAILURE: Test Execution Completed with Failures","module":"main","passed_suites":null,"failed_suites":["sanity"],"skipped_suites":["isolated"]}
{"time":"2025-09-29T13:02:34.913194425Z","level":"ERROR","msg":"❌ FAILURE: Suite Failure Details","module":"main","suite":"sanity","error":"nonce not found in output"}
{"time":"2025-09-29T13:02:34.913209708Z","level":"INFO","msg":"🔑 KEY STEP: Starting resource teardown...","module":"main","usage_id":"9dcffe4fd858017b85d552c67714acaa"}
{"time":"2025-09-29T13:02:34.920263618Z","level":"INFO","msg":"🌐 Orchestrator API Client initialized","module":"main","endpoint":"http://aetheria-orchestrator.aetheria.svc:8080"}
{"time":"2025-09-29T13:02:34.920422905Z","level":"INFO","msg":"🧹 Requesting resource teardown","module":"main","usage_id":"9dcffe4fd858017b85d552c67714acaa"}
{"time":"2025-09-29T13:02:34.966689241Z","level":"INFO","msg":"✅ SUCCESS: Completed resource teardown successfully","module":"main","usage_id":"9dcffe4fd858017b85d552c67714acaa"}
Result - 🔴 Failure |
|
/test cluster=304,305,306,307 tests=(sanity) |
|
/test |
|
/test |
🟢 Test run for PR #2419Branch: logs-log-more-details-per-validator-slot-epoch Status
Click to expand executor logs═══════════════════════════════════════════════════════════════════════════════════════════════════════
🧪 WELCOME TO Executor - SSV's Distributed Test Automation Execution Layer 🧪
___ __ __ ___ ___ _ _ _____ ___ ___
| __|\\ \\/ /| __|/ __|| | | ||_ _|/ _ \\ | _ \\
{"time":"2025-09-30T10:11:45.683449781Z","level":"INFO","msg":"🐳 Docker mode: Using environment variables for config generation"}
| _| > < | _|| (__ | |_| | | | | (_) || /
|___|/_/\\_\\|___|\\___| \\___/ |_| \\___/ |_|_\\
═══════════════════════════════════════════════════════════════════════════════════════════════════════
{"time":"2025-09-30T10:11:45.693386362Z","level":"INFO","msg":"🌐 Orchestrator API Client initialized","endpoint":"http://aetheria-orchestrator.aetheria.svc:8080"}
{"time":"2025-09-30T10:11:45.693509304Z","level":"INFO","msg":"📝 Requesting configuration generation from orchestrator API","network":"hoodi_stage","clusters":[300,301,302,303],"tests":"(sanity)"}
{"time":"2025-09-30T10:11:45.729389475Z","level":"INFO","msg":"✅ Configuration generated successfully via API","resource_usage_id":"ba92a3ff3d1ad392af58aef54b9e61ef"}
{"time":"2025-09-30T10:11:45.731491564Z","level":"INFO","msg":"🚀 EXECUTOR Initialized Successfully"}
{"time":"2025-09-30T10:11:45.731573328Z","level":"INFO","msg":"⚙️ Test configuration loaded","network":"hoodi_stage","nodes":[300,301,302,303],"test_type":{"Sanity":{"ShouldRun":true,"E2M":false,"BulkAmount":0},"Bulk":{"ShouldRun":false,"E2M":false,"BulkAmount":0},"Isolated":{"Tests":null}}}
{"time":"2025-09-30T10:11:50.114418669Z","level":"INFO","msg":"Generated operator pubkeys file","module":"scanner","path":"/app/shared/data/operators/operator-pubkeys-hoodi_stage.json"}
{"time":"2025-09-30T10:11:50.114600848Z","level":"INFO","msg":"Registered parser","module":"main","component":"parser-client","parser_type":"consensus"}
{"time":"2025-09-30T10:11:50.114628691Z","level":"INFO","msg":"Registered parser","module":"main","component":"parser-client","parser_type":"flow-emits"}
{"time":"2025-09-30T10:11:50.114652906Z","level":"INFO","msg":"Validation client initialized","module":"main","loki_enabled":true,"e2m_enabled":false}
{"time":"2025-09-30T10:11:50.114699801Z","level":"INFO","msg":"🔑 KEY STEP: Starting Isolated Tests Concurrently if exists...","module":"main"}
{"time":"2025-09-30T10:11:50.114776648Z","level":"INFO","msg":"🔑 KEY STEP: Starting Sanity Test Suite","module":"main"}
{"time":"2025-09-30T10:11:50.115080946Z","level":"INFO","msg":"No isolated tests configured, skipping","module":"main"}
{"time":"2025-09-30T10:11:50.16126737Z","level":"INFO","msg":"Getting available slots","test":"sanity","node":300}
{"time":"2025-09-30T10:11:50.173233923Z","level":"INFO","msg":"Available slots","test":"sanity","node":300,"slots":3000}
{"time":"2025-09-30T10:11:50.173293574Z","level":"INFO","msg":"Getting available slots","test":"sanity","node":301}
{"time":"2025-09-30T10:11:50.182964829Z","level":"INFO","msg":"Available slots","test":"sanity","node":301,"slots":398}
{"time":"2025-09-30T10:11:50.183049627Z","level":"INFO","msg":"Getting available slots","test":"sanity","node":302}
{"time":"2025-09-30T10:11:50.189542398Z","level":"INFO","msg":"Available slots","test":"sanity","node":302,"slots":297}
{"time":"2025-09-30T10:11:50.189623608Z","level":"INFO","msg":"Getting available slots","test":"sanity","node":303}
{"time":"2025-09-30T10:11:50.19614365Z","level":"INFO","msg":"Available slots","test":"sanity","node":303,"slots":716}
{"time":"2025-09-30T10:12:27.134347184Z","level":"INFO","msg":"Extracted keyshares path","test":"sanity","module":"keys","path":"/app/shared/data/keyshares/0x88e97e72ea3a862b12b44028e65f2af490b8cc19d4b6f1915f1f80325cff9f02d8f5c6fd79f127c5fde7a90fcaa43b8d.json"}
{"time":"2025-09-30T10:12:27.134454677Z","level":"INFO","msg":"Key shares file generated successfully","test":"sanity","keyshare_path":"/app/shared/data/keyshares/0x88e97e72ea3a862b12b44028e65f2af490b8cc19d4b6f1915f1f80325cff9f02d8f5c6fd79f127c5fde7a90fcaa43b8d.json"}
{"time":"2025-09-30T10:12:29.22581702Z","level":"INFO","msg":"Allowance fetched successfully","test":"sanity","module":"contract","account":"0x91e32efb8139cd88cae0df30d2bf471294c6ed27","allowance":"99312359999200282400000000"}
{"time":"2025-09-30T10:12:29.226016768Z","level":"INFO","msg":"Threshold value","test":"sanity","module":"contract","threshold":"9000000000000000000000"}
{"time":"2025-09-30T10:12:29.226153949Z","level":"INFO","msg":"Sufficient allowance","test":"sanity","module":"contract","allowance margin":"6561000000000000000000000000000000000000000000000000000000000000000000000000000000000000"}
{"time":"2025-09-30T10:12:29.232399472Z","level":"INFO","msg":"Allowance fetched successfully","test":"sanity","module":"contract","account":"0x91e32efb8139cd88cae0df30d2bf471294c6ed27","allowance":"99312359999200282400000000"}
{"time":"2025-09-30T10:12:29.232511353Z","level":"INFO","msg":"Allowance","test":"sanity","module":"contract","allowance":"99312359999200282400000000"}
{"time":"2025-09-30T10:12:29.50376921Z","level":"INFO","msg":"Registering validator","test":"sanity","module":"contract","tx_hash":"0x58b5d7dd7e039ba8c9a00367461a8a105c95b0d42c95ef5863db8418c9d236cf"}
{"time":"2025-09-30T10:12:29.510020658Z","level":"INFO","msg":"Waiting for transaction receipt, retrying...","test":"sanity","module":"contract","attempt":1,"sleep":10,"tx_hash":"0x58b5d7dd7e039ba8c9a00367461a8a105c95b0d42c95ef5863db8418c9d236cf"}
{"time":"2025-09-30T10:12:39.517458988Z","level":"INFO","msg":"Transaction receipt received","test":"sanity","module":"contract","tx_hash":"0x58b5d7dd7e039ba8c9a00367461a8a105c95b0d42c95ef5863db8418c9d236cf"}
{"time":"2025-09-30T10:12:39.517579636Z","level":"INFO","msg":"✅ SUCCESS: Contract Register Successful","test":"sanity","txHash":"0x58b5d7dd7e039ba8c9a00367461a8a105c95b0d42c95ef5863db8418c9d236cf","block_hash":"0x134c87dba009d1412d9cc50d26acdb7ee4fb9badc592631d2c3664d61c2e987d"}
{"time":"2025-09-30T10:12:39.533996425Z","level":"INFO","msg":"Failed to get data for validator from exporter - retrying...","test":"sanity","module":"helpers","pubkey":"0x88e97e72ea3a862b12b44028e65f2af490b8cc19d4b6f1915f1f80325cff9f02d8f5c6fd79f127c5fde7a90fcaa43b8d","timeToSleep":10,"attempt":1}
{"time":"2025-09-30T10:12:49.544841862Z","level":"INFO","msg":"Failed to get data for validator from exporter - retrying...","test":"sanity","module":"helpers","pubkey":"0x88e97e72ea3a862b12b44028e65f2af490b8cc19d4b6f1915f1f80325cff9f02d8f5c6fd79f127c5fde7a90fcaa43b8d","timeToSleep":20,"attempt":2}
{"time":"2025-09-30T10:13:09.567599382Z","level":"INFO","msg":"Failed to get data for validator from exporter - retrying...","test":"sanity","module":"helpers","pubkey":"0x88e97e72ea3a862b12b44028e65f2af490b8cc19d4b6f1915f1f80325cff9f02d8f5c6fd79f127c5fde7a90fcaa43b8d","timeToSleep":40,"attempt":3}
{"time":"2025-09-30T10:13:49.607457374Z","level":"INFO","msg":"Failed to get data for validator from exporter - retrying...","test":"sanity","module":"helpers","pubkey":"0x88e97e72ea3a862b12b44028e65f2af490b8cc19d4b6f1915f1f80325cff9f02d8f5c6fd79f127c5fde7a90fcaa43b8d","timeToSleep":80,"attempt":4}
{"time":"2025-09-30T10:15:09.62418252Z","level":"INFO","msg":"Successfully retrieved validator index from exporter","test":"sanity","module":"helpers","pubkey":"0x88e97e72ea3a862b12b44028e65f2af490b8cc19d4b6f1915f1f80325cff9f02d8f5c6fd79f127c5fde7a90fcaa43b8d"}
{"time":"2025-09-30T10:15:17.747788335Z","level":"INFO","msg":"Validator event validation successful","module":"main","module":"loki-validator","validated_validators":1,"event":"ValidatorAdded"}
{"time":"2025-09-30T10:15:17.748003Z","level":"INFO","msg":"SSV node log validation successful","test":"sanity","indices":["1092460"],"validators":1,"validate-type":"registration"}
{"time":"2025-09-30T10:15:20.069322498Z","level":"INFO","msg":"Liquidating cluster","test":"sanity","module":"contract","tx_hash":"0xfe0575e973b8ca16af2b456da35ccf2f9da6662e731c5f27fd053a91c1f8606d"}
{"time":"2025-09-30T10:15:20.072207331Z","level":"INFO","msg":"Waiting for transaction receipt, retrying...","test":"sanity","module":"contract","attempt":1,"sleep":10,"tx_hash":"0xfe0575e973b8ca16af2b456da35ccf2f9da6662e731c5f27fd053a91c1f8606d"}
{"time":"2025-09-30T10:15:30.084231719Z","level":"INFO","msg":"Transaction receipt received","test":"sanity","module":"contract","tx_hash":"0xfe0575e973b8ca16af2b456da35ccf2f9da6662e731c5f27fd053a91c1f8606d"}
{"time":"2025-09-30T10:15:30.084347746Z","level":"INFO","msg":"✅ SUCCESS: Cluster Liquidation Successful","test":"sanity","txHash":"0xfe0575e973b8ca16af2b456da35ccf2f9da6662e731c5f27fd053a91c1f8606d","block_hash":"0x3cb52afa574ee72b5bc3dab20acd50501662bbef3f425884d56c826f772c0924"}
{"time":"2025-09-30T10:15:30.084488037Z","level":"INFO","msg":"Querying Loki for transaction hash validation","module":"main","module":"loki-validator","query":"{container=~\\"ssv-node-300|ssv-node-301|ssv-node-302|ssv-node-303\\"} |= \\"0xfe0575e973b8ca16af2b456da35ccf2f9da6662e731c5f27fd053a91c1f8606d\\"","tx_hash":"0xfe0575e973b8ca16af2b456da35ccf2f9da6662e731c5f27fd053a91c1f8606d"}
{"time":"2025-09-30T10:15:30.283726075Z","level":"INFO","msg":"No logs found, retrying after delay (nodes may still be processing)","module":"main","module":"loki-validator","attempt":1,"max_retries":5,"delay_seconds":30,"start_unix":1759216530,"end_unix":1759227330}
{"time":"2025-09-30T10:16:00.33524579Z","level":"INFO","msg":"No logs found, retrying after delay (nodes may still be processing)","module":"main","module":"loki-validator","attempt":2,"max_retries":5,"delay_seconds":60,"start_unix":1759216530,"end_unix":1759227360}
{"time":"2025-09-30T10:17:00.442277813Z","level":"INFO","msg":"No logs found, retrying after delay (nodes may still be processing)","module":"main","module":"loki-validator","attempt":3,"max_retries":5,"delay_seconds":90,"start_unix":1759216530,"end_unix":1759227420}
{"time":"2025-09-30T10:18:30.570313348Z","level":"INFO","msg":"Event validation successful","module":"main","module":"loki-validator","valid_entries":4,"event":"ClusterLiquidated"}
{"time":"2025-09-30T10:18:30.570479918Z","level":"INFO","msg":"SSV node log validation successful","test":"sanity","indices":["1092460"],"validators":1,"validate-type":"liquidation"}
{"time":"2025-09-30T10:18:32.686007517Z","level":"INFO","msg":"Allowance fetched successfully","test":"sanity","module":"contract","account":"0x91e32efb8139cd88cae0df30d2bf471294c6ed27","allowance":"99312359999200282400000000"}
{"time":"2025-09-30T10:18:32.686105889Z","level":"INFO","msg":"Threshold value","test":"sanity","module":"contract","threshold":"9000000000000000000000"}
{"time":"2025-09-30T10:18:32.686146412Z","level":"INFO","msg":"Sufficient allowance","test":"sanity","module":"contract","allowance margin":"6561000000000000000000000000000000000000000000000000000000000000000000000000000000000000"}
{"time":"2025-09-30T10:18:32.76700472Z","level":"INFO","msg":"Reactivating cluster","test":"sanity","module":"contract","tx_hash":"0x6fff74d0c74258e55a1f7fc3bb8cc39dcd775555193021da93809b72c07bbcf0"}
{"time":"2025-09-30T10:18:32.772238946Z","level":"INFO","msg":"Waiting for transaction receipt, retrying...","test":"sanity","module":"contract","attempt":1,"sleep":10,"tx_hash":"0x6fff74d0c74258e55a1f7fc3bb8cc39dcd775555193021da93809b72c07bbcf0"}
{"time":"2025-09-30T10:18:42.799383168Z","level":"INFO","msg":"Transaction receipt received","test":"sanity","module":"contract","tx_hash":"0x6fff74d0c74258e55a1f7fc3bb8cc39dcd775555193021da93809b72c07bbcf0"}
{"time":"2025-09-30T10:18:42.799460629Z","level":"INFO","msg":"✅ SUCCESS: Cluster Reactivation Successful","test":"sanity","txHash":"0x6fff74d0c74258e55a1f7fc3bb8cc39dcd775555193021da93809b72c07bbcf0","block_hash":"0xac283eba124cb7eece7bbcfa3522fb3db61f7c207ec7b17e85b92ad0f6e25e16"}
{"time":"2025-09-30T10:18:42.799546897Z","level":"INFO","msg":"Querying Loki for transaction hash validation","module":"main","module":"loki-validator","query":"{container=~\\"ssv-node-300|ssv-node-301|ssv-node-302|ssv-node-303\\"} |= \\"0x6fff74d0c74258e55a1f7fc3bb8cc39dcd775555193021da93809b72c07bbcf0\\"","tx_hash":"0x6fff74d0c74258e55a1f7fc3bb8cc39dcd775555193021da93809b72c07bbcf0"}
{"time":"2025-09-30T10:18:43.089367031Z","level":"INFO","msg":"No logs found, retrying after delay (nodes may still be processing)","module":"main","module":"loki-validator","attempt":1,"max_retries":5,"delay_seconds":30,"start_unix":1759216722,"end_unix":1759227522}
{"time":"2025-09-30T10:19:13.156863528Z","level":"INFO","msg":"No logs found, retrying after delay (nodes may still be processing)","module":"main","module":"loki-validator","attempt":2,"max_retries":5,"delay_seconds":60,"start_unix":1759216722,"end_unix":1759227553}
{"time":"2025-09-30T10:20:13.224018956Z","level":"INFO","msg":"Event validation successful","module":"main","module":"loki-validator","valid_entries":2,"event":"ClusterReactivated"}
{"time":"2025-09-30T10:20:13.224093692Z","level":"INFO","msg":"SSV node log validation successful","test":"sanity","indices":["1092460"],"validators":1,"validate-type":"reactivation"}
{"time":"2025-09-30T10:20:15.366427552Z","level":"INFO","msg":"Allowance fetched successfully","test":"sanity","module":"contract","account":"0x91e32efb8139cd88cae0df30d2bf471294c6ed27","allowance":"99303359999200282400000000"}
{"time":"2025-09-30T10:20:15.366539524Z","level":"INFO","msg":"Threshold value","test":"sanity","module":"contract","threshold":"9000000000000000000000"}
{"time":"2025-09-30T10:20:15.366611456Z","level":"INFO","msg":"Sufficient allowance","test":"sanity","module":"contract","allowance margin":"6561000000000000000000000000000000000000000000000000000000000000000000000000000000000000"}
{"time":"2025-09-30T10:20:15.5079868Z","level":"INFO","msg":"Removing validator","test":"sanity","module":"contract","tx_hash":"0x1abb9582c61e838d6dfcc8047bf4f2b84e529b6b1afc3ae83b88b38a3869c3f0"}
{"time":"2025-09-30T10:20:15.512410035Z","level":"INFO","msg":"Waiting for transaction receipt, retrying...","test":"sanity","module":"contract","attempt":1,"sleep":10,"tx_hash":"0x1abb9582c61e838d6dfcc8047bf4f2b84e529b6b1afc3ae83b88b38a3869c3f0"}
{"time":"2025-09-30T10:20:25.522777056Z","level":"INFO","msg":"Transaction receipt received","test":"sanity","module":"contract","tx_hash":"0x1abb9582c61e838d6dfcc8047bf4f2b84e529b6b1afc3ae83b88b38a3869c3f0"}
{"time":"2025-09-30T10:20:25.522843909Z","level":"INFO","msg":"✅ SUCCESS: Contract Removal Successful","test":"sanity","blockHash":"0xb6b34bdccb0dc1d56d2e7d9dedfb4e66d87bfee34cc572f66eb5d00aaac73160"}
{"time":"2025-09-30T10:20:25.925119886Z","level":"INFO","msg":"No logs found, retrying after delay (nodes may still be processing)","module":"main","module":"loki-validator","attempt":1,"max_retries":5,"delay_seconds":30,"start_unix":1759216825,"end_unix":1759227625}
{"time":"2025-09-30T10:20:55.993269586Z","level":"INFO","msg":"No logs found, retrying after delay (nodes may still be processing)","module":"main","module":"loki-validator","attempt":2,"max_retries":5,"delay_seconds":60,"start_unix":1759216825,"end_unix":1759227655}
{"time":"2025-09-30T10:21:56.050211868Z","level":"INFO","msg":"No logs found, retrying after delay (nodes may still be processing)","module":"main","module":"loki-validator","attempt":3,"max_retries":5,"delay_seconds":90,"start_unix":1759216825,"end_unix":1759227715}
{"time":"2025-09-30T10:23:26.163011605Z","level":"INFO","msg":"Validator event validation successful","module":"main","module":"loki-validator","validated_validators":1,"event":"ValidatorRemoved"}
{"time":"2025-09-30T10:23:26.16308339Z","level":"INFO","msg":"SSV node log validation successful","test":"sanity","indices":["1092460"],"validators":1,"validate-type":"removal"}
{"time":"2025-09-30T10:23:26.163170915Z","level":"INFO","msg":"✅ SUCCESS: Sanity Test Suite Completed Successfully","module":"main","register":{"Contract":true,"E2M":false,"Loki":true},"liquidate":{"Contract":true,"E2M":false,"Loki":true},"reactivate":{"Contract":true,"E2M":false,"Loki":true},"remove":{"Contract":true,"E2M":false,"Loki":true}}
{"time":"2025-09-30T10:23:26.163202098Z","level":"INFO","msg":"⏳ PROGRESS: Waiting for all tests to finish","module":"main"}
{"time":"2025-09-30T10:23:26.163242618Z","level":"INFO","msg":"✅ SUCCESS: All Test Suites Completed Successfully","module":"main","passed_suites":["sanity"],"skipped_suites":["isolated"]}
{"time":"2025-09-30T10:23:26.163263328Z","level":"INFO","msg":"🔑 KEY STEP: Starting resource teardown...","module":"main","usage_id":"ba92a3ff3d1ad392af58aef54b9e61ef"}
{"time":"2025-09-30T10:23:26.189958836Z","level":"INFO","msg":"🌐 Orchestrator API Client initialized","module":"main","endpoint":"http://aetheria-orchestrator.aetheria.svc:8080"}
{"time":"2025-09-30T10:23:26.190020945Z","level":"INFO","msg":"🧹 Requesting resource teardown","module":"main","usage_id":"ba92a3ff3d1ad392af58aef54b9e61ef"}
{"time":"2025-09-30T10:23:31.215668235Z","level":"INFO","msg":"✅ SUCCESS: Completed resource teardown successfully","module":"main","usage_id":"ba92a3ff3d1ad392af58aef54b9e61ef"}
Result - 🟢 Success |
|
/test cluster=85,86,87,88 |
|
Invalid cluster sequence: cluster number 85 is out of valid range (300-333) |
|
/test help |
|
❓ Help Available Commands
|
y0sher
previously approved these changes
Oct 19, 2025
There was a problem hiding this comment.
@iurii-ssv this look good but also breaks spec alignment badly, so I'm wondering if we should do similar changes in spec or just diverge from their code entirely.
@y0sher I think our runner's code has diverged from what we have in ssv-spec repo so much that it's no longer practical to try and keep it "similar" at this point, as long as spec-tests pass ofc :) |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
This PR is meant to improve logs so that they contain more complete data, as well as make logging more consistent across different duty types, for example:
I've also re-arranged some spec-test files in this PR a bit to simplify the dependancies between them (not super relevant to logging, but I thought I might need that for some functionality in this PR to work ... ended up removing that functionality but keeping the re-arrangement of the file structure ... could move it to a separate PR but since it only affects tests there probably is no need).