Merge pull request #111 from ethscriptions-protocol/transient_validation_errors

Better handlng of transient validation errors

Author: RogerPodacter

app/jobs/validation_job.rb

@@ -1,26 +1,27 @@
 class ValidationJob < ApplicationJob
   queue_as :validation
 
-  # Retry up to 3 times with fixed delays to avoid the exponentially_longer issue
-  retry_on StandardError, wait: 5.seconds, attempts: 3
+  # Import TransientValidationError from BlockValidator
+  TransientValidationError = BlockValidator::TransientValidationError
+
+  # Only retry transient errors, not all StandardError
+  retry_on TransientValidationError,
+           wait: ENV.fetch('VALIDATION_RETRY_WAIT_SECONDS', 5).to_i.seconds,
+           attempts: ENV.fetch('VALIDATION_TRANSIENT_RETRIES', 5).to_i
 
   def perform(l1_block_number, l2_block_hashes)
     start_time = Time.current
 
-    begin
-      # Use the unified ValidationResult model to validate and save
-      validation_result = ValidationResult.validate_and_save(l1_block_number, l2_block_hashes)
-
-      elapsed_time = Time.current - start_time
-      Rails.logger.info "ValidationJob: Block #{l1_block_number} validation completed in #{elapsed_time.round(3)}s"
-
-    rescue => e
-      Rails.logger.error "ValidationJob: Validation failed for block #{l1_block_number}: #{e.message}"
+    # ValidationResult.validate_and_save will:
+    # 1. Create ValidationResult with success: true (job succeeds)
+    # 2. Create ValidationResult with success: false (job succeeds - real validation failure found)
+    # 3. Raise TransientValidationError (job retries via retry_on, then fails if exhausted)
+    ValidationResult.validate_and_save(l1_block_number, l2_block_hashes)
 
-      # Validation failure will be detected by import process via database query
+    elapsed_time = Time.current - start_time
+    Rails.logger.info "ValidationJob: Block #{l1_block_number} validation completed in #{elapsed_time.round(3)}s"
 
-      # Re-raise to trigger retry mechanism
-      raise e
-    end
+    # Job completes successfully for cases 1 & 2
+    # TransientValidationError will be handled by retry_on automatically
   end
-end
+end

app/models/validation_result.rb

@@ -32,6 +32,14 @@ def self.validation_gaps(start_block, end_block)
     connection.execute(sql, [start_block, end_block]).map { |row| row['missing_block'] }
   end
 
+  # Faster method that just counts gaps without listing them all
+  def self.validation_gap_count(start_block, end_block)
+    # Count how many blocks are missing in the range
+    expected_count = end_block - start_block + 1
+    validated_count = where(l1_block: start_block..end_block).count
+    expected_count - validated_count
+  end
+
   def self.validation_stats(since: 1.hour.ago)
     results = where('validated_at >= ?', since)
     total = results.count
@@ -60,16 +68,17 @@ def self.validate_and_save(l1_block_number, l2_block_hashes)
       start_time = Time.current
       block_result = validator.validate_l1_block(l1_block_number, l2_block_hashes)
 
-      # Store comprehensive validation result with full debugging data
-      validation_result = create_or_find_by(l1_block: l1_block_number) do |vr|
-        vr.success = block_result.success
-        vr.error_details = block_result.errors
-        vr.validation_stats = {
+      # Find or initialize - idempotent for re-runs
+      validation_result = find_or_initialize_by(l1_block: l1_block_number)
+
+      validation_result.assign_attributes(
+        success: block_result.success,
+        error_details: block_result.errors,
+        validation_stats: {
           # Basic stats
           success: block_result.success,
           l1_block: l1_block_number,
           l2_blocks: l2_block_hashes,
-          validated_at: Time.current,
 
           # Detailed comparison data
           validation_details: block_result.stats,
@@ -80,26 +89,41 @@ def self.validate_and_save(l1_block_number, l2_block_hashes)
 
           # Timing info
           validation_duration_ms: ((Time.current - start_time) * 1000).round(2)
-        }
-        vr.validated_at = Time.current
-      end
+        },
+        validated_at: Time.current
+      )
+
+      validation_result.save!
 
       # Log the result
       validation_result.log_summary
 
       validation_result
+    rescue BlockValidator::TransientValidationError => e
+      # Don't persist transient errors - let ValidationJob handle retries
+      Rails.logger.debug "ValidationResult: Transient error for block #{l1_block_number}: #{e.message}"
+      raise e
     rescue => e
       Rails.logger.error "ValidationResult: Exception validating block #{l1_block_number}: #{e.message}"
 
-      # Record the validation error
-      error_result = create_or_find_by(l1_block: l1_block_number) do |vr|
-        vr.success = false
-        vr.error_details = [e.message]
-        vr.validation_stats = { exception: true, exception_class: e.class.name }
-        vr.validated_at = Time.current
-      end
+      # Only persist non-transient validation errors - idempotent for re-runs
+      validation_result = find_or_initialize_by(l1_block: l1_block_number)
+
+      validation_result.assign_attributes(
+        success: false,
+        error_details: [e.message],
+        validation_stats: {
+          exception: true,
+          exception_class: e.class.name,
+          exception_message: e.message,
+          exception_backtrace: e.backtrace&.first(10)  # Store first 10 lines of backtrace
+        },
+        validated_at: Time.current
+      )
 
-      error_result.log_summary
+      validation_result.save!
+
+      validation_result.log_summary
       raise e
     end
   end

app/services/eth_block_importer.rb

@@ -8,6 +8,8 @@ class BlockNotReadyToImportError < StandardError; end
   class ReorgDetectedError < StandardError; end
   # Raised when validation failure is detected (should stop system permanently)
   class ValidationFailureError < StandardError; end
+  # Raised when validation is too far behind (should wait and retry)
+  class ValidationStalledError < StandardError; end
 
   attr_accessor :ethscriptions_block_cache, :ethereum_client, :eth_block_cache, :geth_driver, :prefetcher
 
@@ -196,13 +198,20 @@ def import_blocks_until_done
 
     begin
       loop do
-        # Check for validation failures before importing
-        if validation_failure_detected?
+        # Check for validation failures
+        if real_validation_failure_detected?
           failed_block = get_validation_failure_block
           logger.error "Import stopped due to validation failure at block #{failed_block}"
           raise ValidationFailureError.new("Validation failure detected at block #{failed_block}")
         end
 
+        # Check if validation is stalled
+        if validation_stalled?
+          current_position = current_max_eth_block_number
+          logger.warn "Import paused - validation is behind (current: #{current_position})"
+          raise ValidationStalledError.new("Validation stalled - waiting for validation to catch up")
+        end
+
         block_number = next_block_to_import
 
         if block_number.nil?
@@ -409,18 +418,42 @@ def geth_driver
     @geth_driver
   end
 
-  def validation_failure_detected?
-    # Only consider failures BEHIND current import position as critical
+  def get_validation_failure_block
+    # Get the earliest failed block that's behind current import (for real failures)
+    current_position = current_max_eth_block_number
+    ValidationResult.failed.where('l1_block <= ?', current_position).order(:l1_block).first&.l1_block
+  end
+
+  def real_validation_failure_detected?
+    # Only consider real validation failures BEHIND current import position as critical
     current_position = current_max_eth_block_number
     ValidationResult.failed.where('l1_block <= ?', current_position).exists?
   end
 
-  def get_validation_failure_block
-    # Get the earliest failed block that's behind current import
+  def validation_stalled?
+    return false unless ENV.fetch('VALIDATION_ENABLED').casecmp?('true')
+
     current_position = current_max_eth_block_number
-    ValidationResult.failed.where('l1_block <= ?', current_position).order(:l1_block).first&.l1_block
+    hard_limit = ENV.fetch('VALIDATION_LAG_HARD_LIMIT', 30).to_i
+
+    # Check for validation gaps in recent blocks
+    # This covers BOTH sequential lag and scattered gaps
+    check_range_start = [current_position - hard_limit + 1, 1].max  # Last N blocks
+    check_range_end = current_position
+
+    # Count ALL missing validations in critical range (includes both gaps and lag)
+    gap_count = ValidationResult.validation_gap_count(check_range_start, check_range_end)
+
+    if gap_count >= hard_limit
+      Rails.logger.error "Too many validation gaps: #{gap_count} unvalidated blocks in range #{check_range_start}-#{check_range_end} (limit: #{hard_limit})"
+      return true
+    end
+
+    false
   end
 
+  public
+
   def cleanup_stale_validation_records
     # Remove validation records AND pending jobs ahead of our starting position
     # These are from previous runs and may be stale due to reorgs

config/derive_ethscriptions_blocks.rb

@@ -187,6 +187,13 @@ module Clockwork
         puts "[#{Time.now}] Fix the validation issue and restart manually"
         exit 1
 
+      rescue EthBlockImporter::ValidationStalledError => e
+        # Validation is behind - wait longer and keep trying
+        Rails.logger.info "[#{Time.now}] ⏸️  VALIDATION BEHIND: #{e.message}"
+        puts "[#{Time.now}] ⏸️  Validation is behind - waiting #{import_interval * 2}s for validation to catch up..."
+        sleep import_interval * 2  # Wait longer when validation is behind
+        # Don't exit - continue the loop to retry
+
       rescue => e
         Rails.logger.error "Import error: #{e.class} - #{e.message}"
         Rails.logger.error e.backtrace.first(20).join("\n")

lib/block_validator.rb

@@ -1,6 +1,9 @@
 class BlockValidator
   attr_reader :errors, :stats
 
+  # Exception for transient errors that should trigger retries
+  class TransientValidationError < StandardError; end
+
   def initialize
     # Initialize validation state
     reset_validation_state
@@ -29,7 +32,7 @@ def validate_l1_block(l1_block_number, l2_block_hashes)
     verify_storage_state(expected, l1_block_number, historical_block_tag)
 
     # Build comprehensive result with full debugging data
-    success = @errors.empty? && !@incomplete_actual && !expected[:api_unavailable]
+    success = @errors.empty?
     validation_duration = Time.current - validation_start_time
 
     # Return comprehensive debugging information
@@ -45,8 +48,6 @@ def validate_l1_block(l1_block_number, l2_block_hashes)
         actual_transfers: Array(actual_events[:transfers]).size,
         storage_checks: @storage_checks_performed.value,
         errors_count: @errors.size,
-        api_unavailable: expected[:api_unavailable] ? true : false,
-        incomplete_actual: @incomplete_actual,
 
         # L1 to L2 block mapping
         l1_to_l2_mapping: {
@@ -64,8 +65,6 @@ def validate_l1_block(l1_block_number, l2_block_hashes)
         raw_expected_data: {
           creations: sanitize_for_json(expected[:creations] || []),
           transfers: sanitize_for_json(expected[:transfers] || []),
-          api_available: !expected[:api_unavailable],
-          api_error: expected[:api_error]
         },
 
         raw_actual_data: {
@@ -94,7 +93,6 @@ def validate_l1_block(l1_block_number, l2_block_hashes)
   def reset_validation_state
     @errors = Concurrent::Array.new
     @storage_checks_performed = Concurrent::AtomicFixnum.new(0)
-    @incomplete_actual = false
 
     # Reset debugging instrumentation
     @debug_data = {
@@ -119,10 +117,15 @@ def load_genesis_transaction_hashes
 
   def fetch_expected_data(l1_block_number)
     EthscriptionsApiClient.fetch_block_data(l1_block_number)
+  rescue EthscriptionsApiClient::ApiUnavailableError => e
+    # API unavailable after exhausting all retries - this is an infrastructure issue
+    Rails.logger.warn "API unavailable for block #{l1_block_number}: #{e.message}"
+    raise TransientValidationError, e.message
   rescue => e
-    message = "Failed to fetch API data: #{e.message}"
+    # Other unexpected errors - log and continue with empty data
+    message = "Unexpected error fetching API data: #{e.message}"
     @errors << message
-    {creations: [], transfers: [], api_unavailable: true, api_error: message}
+    {creations: [], transfers: []}
   end
 
   def aggregate_l2_events(block_hashes)
@@ -134,18 +137,24 @@ def aggregate_l2_events(block_hashes)
       begin
         receipts = EthRpcClient.l2.call('eth_getBlockReceipts', [block_hash])
         if receipts.nil?
-          @errors << "No receipts returned for L2 block #{block_hash}"
-          @incomplete_actual = true
-          raise "No receipts returned for L2 block #{block_hash}"
+          error_msg = "No receipts returned for L2 block #{block_hash}"
+          @errors << error_msg
+          # Treat missing receipts as potentially transient
+          raise TransientValidationError, error_msg
         end
 
         data = EventDecoder.decode_block_receipts(receipts)
         all_creations.concat(data[:creations])
         all_transfers.concat(data[:transfers])  # Ethscriptions protocol transfers
       rescue => e
-        @errors << "Failed to get receipts for block #{block_hash}: #{e.message}"
-        @incomplete_actual = true
-        raise "Failed to get receipts for block #{block_hash}: #{e.message}"
+        error_msg = "Failed to get receipts for block #{block_hash}: #{e.message}"
+        @errors << error_msg
+        # Classify L2 receipt fetch errors - network issues are transient
+        if transient_error?(e)
+          raise TransientValidationError, error_msg
+        else
+          raise
+        end
       end
     end
 
@@ -561,6 +570,21 @@ def safe_content_preview(content, length: 50)
     preview + (content.length > length ? "..." : "")
   end
 
+  # Classify L2 RPC errors as transient (infrastructure) vs permanent (logic)
+  def transient_error?(error)
+    case error
+    # L2 RPC network errors
+    when SocketError, Errno::ECONNREFUSED, Errno::ECONNRESET,
+         Net::OpenTimeout, Net::ReadTimeout, Net::TimeoutError
+      true
+    # L2 RPC errors that might be transient
+    when EthRpcClient::HttpError, EthRpcClient::ApiError
+      true
+    else
+      false
+    end
+  end
+
   # Sanitize data structures for JSON serialization
   def sanitize_for_json(data)
     case data