TSA verification

Depends on ruby/openssl#770

Rakefile

@@ -14,19 +14,21 @@ RuboCop::RakeTask.new
 
 task default: %i[test conformance conformance_staging conformance_tuf rubocop]
 
+require "openssl"
+# Checks for https://github.com/ruby/openssl/pull/770
+xfail = OpenSSL::X509::Store.new.instance_variable_defined?(:@time) ? "test_verify_rejects_bad_tsa_timestamp" : ""
+
 desc "Run the conformance tests"
 task conformance: %w[conformance:setup] do
-  sh({ "GHA_SIGSTORE_CONFORMANCE_XFAIL" =>
-       "test_verify_rejects_bad_tsa_timestamp" },
+  sh({ "GHA_SIGSTORE_CONFORMANCE_XFAIL" => xfail },
      File.expand_path("test/sigstore-conformance/env/bin/pytest"), "test",
      "--entrypoint=#{File.join(__dir__, "bin", "conformance-entrypoint")}", "--skip-signing",
      chdir: "test/sigstore-conformance")
 end
 
 desc "Run the conformance tests against staging"
 task conformance_staging: %w[conformance:setup] do
-  sh({ "GHA_SIGSTORE_CONFORMANCE_XFAIL" =>
-       "test_verify_rejects_bad_tsa_timestamp" },
+  sh({ "GHA_SIGSTORE_CONFORMANCE_XFAIL" => xfail },
      File.expand_path("test/sigstore-conformance/env/bin/pytest"), "test",
      "--entrypoint=#{File.join(__dir__, "bin", "conformance-entrypoint")}", "--skip-signing",
      "--staging",

lib/rubygems/commands/sigstore_tuf_refresh_command.rb

@@ -15,6 +15,7 @@
 # limitations under the License.
 
 require "rubygems/command"
+require_relative "../../sigstore"
 require_relative "../../sigstore/tuf"
 
 module Gem

lib/rubygems/commands/sigstore_verify_command.rb

@@ -23,6 +23,7 @@ class SigstoreVerifyCommand < Gem::Command
       include Sigstore::CommandOptions
 
       def initialize
+        require "sigstore"
         require "sigstore/rekor/client"
         require "sigstore/trusted_root"
 

lib/sigstore/internal/debug.rb → lib/sigstore.rb

@@ -15,12 +15,29 @@
 # limitations under the License.
 
 module Sigstore
-  module Internal
-    module Debug
-      def debug(*args, **kwargs)
-        return unless ENV["SIGSTORE_DEBUG"]
+  class << self
+    attr_writer :logger
 
-        puts(*args, **kwargs)
+    def logger
+      @logger ||= begin
+        require "logger"
+        Logger.new($stderr)
+      end
+    end
+  end
+
+  module Loggable
+    def logger
+      self.class.logger
+    end
+
+    def self.included(base)
+      base.extend(ClassMethods)
+    end
+
+    module ClassMethods
+      def logger
+        Sigstore.logger
       end
     end
   end

lib/sigstore/internal/json.rb

@@ -37,6 +37,8 @@ def self.canonical_generate(data)
           k.encode("utf-16").codepoints
         end
         contents.map! do |k, v|
+          raise ArgumentError, "Non-string key in hash" unless k.is_a?(String)
+
           "#{canonical_generate(k)}:#{canonical_generate(v)}"
         end
         "{#{contents.join(",")}}"

lib/sigstore/internal/key.rb

@@ -17,6 +17,8 @@
 module Sigstore
   module Internal
     class Key
+      include Loggable
+
       def self.read(key_type, schema, key_bytes, key_id: nil)
         case key_type
         when "ecdsa", "ecdsa-sha2-nistp256"
@@ -55,7 +57,8 @@ def to_der
 
       def verify(algo, signature, data)
         @key.verify(algo, signature, data)
-      rescue OpenSSL::PKey::PKeyError
+      rescue OpenSSL::PKey::PKeyError => e
+        logger.debug { "Verification failed: #{e}" }
         false
       end
 

lib/sigstore/models.rb

@@ -69,6 +69,7 @@ def self.from_media_type(media_type)
   VerificationMaterials = Struct.new(:hashed_input, :certificate, :signature, :offline, :rekor_entry, :input_bytes,
                                      :dsse_envelope, :timestamp_verification_data,
                                      keyword_init: true) do
+    include Loggable
     # @implements VerificationMaterials
 
     def initialize(input:, cert_pem:, **kwargs)
@@ -80,18 +81,24 @@ def initialize(input:, cert_pem:, **kwargs)
 
       super(hashed_input: hashed_input, certificate: certificate, input_bytes: input_bytes, offline: offline, **kwargs)
 
-      raise ArgumentError, "offline verification requires a rekor entry" if offline && !rekor_entry?
+      return unless offline && !rekor_entry?
+
+      raise ArgumentError,
+            "offline verification requires a rekor entry"
     end
 
     def rekor_entry?
       !!rekor_entry
     end
 
     def find_rekor_entry(rekor_client)
-      _has_inclusion_promise = rekor_entry? && rekor_entry.inclusion_promise
+      has_inclusion_promise = rekor_entry? && rekor_entry.inclusion_promise
       has_inclusion_proof = rekor_entry? && rekor_entry.inclusion_proof && rekor_entry.inclusion_proof.checkpoint
 
-      # debug
+      logger.debug do
+        "Looking for rekor entry, " \
+          "has_inclusion_promise=#{!!has_inclusion_promise} has_inclusion_proof=#{!!has_inclusion_proof}" # rubocop:disable Style/DoubleNegation
+      end
 
       if signature
         expected_entry = {
@@ -144,18 +151,19 @@ def find_rekor_entry(rekor_client)
       end
 
       entry = if offline
-                # debug
+                logger.debug { "Offline verification, skipping rekor" }
                 rekor_entry
               elsif !has_inclusion_proof
-                # debug
+                logger.debug { "No inclusion proof, searching rekor" }
                 rekor_client.log.entries.retrieve.post(expected_entry)
-              else # rubocop:disable Lint/DuplicateBranch
+              else
+                logger.debug { "Using rekor entry in sigstore bundle" }
                 rekor_entry
               end
 
       raise Error::MissingRekorEntry, "Rekor entry not found" unless entry
 
-      # debug
+      logger.debug { "Found rekor entry: #{entry}" }
 
       actual_body = JSON.parse(entry.body.unpack1("m0"))
       if dsse_envelope
@@ -250,13 +258,23 @@ def self.from_bundle(input:, bundle:, offline:)
       tlog_entry = tlog_entries.first
 
       if media_type == BundleType::BUNDLE_0_1
-        raise Error::InvalidBundle, "bundle v0.1 requires an inclusion promise" unless tlog_entry.inclusion_promise
+        unless tlog_entry.inclusion_promise
+          raise Error::InvalidBundle,
+                "bundle v0.1 requires an inclusion promise"
+        end
         if tlog_entry.inclusion_proof && !tlog_entry.inclusion_proof.checkpoint.envelope
-          raise Error::InvalidBundle, "0.1 bundle contains an inclusion proof without checkpoint"
+          raise Error::InvalidBundle,
+                "0.1 bundle contains an inclusion proof without checkpoint"
         end
       else
-        raise Error::InvalidBundle, "must contain an inclusion proof" unless tlog_entry.inclusion_proof
-        raise Error::InvalidBundle, "must contain a checkpoint" unless tlog_entry.inclusion_proof.checkpoint.envelope
+        unless tlog_entry.inclusion_proof
+          raise Error::InvalidBundle,
+                "must contain an inclusion proof"
+        end
+        unless tlog_entry.inclusion_proof.checkpoint.envelope
+          raise Error::InvalidBundle,
+                "must contain a checkpoint"
+        end
       end
 
       if tlog_entry.inclusion_proof&.checkpoint&.envelope

lib/sigstore/tuf.rb

@@ -30,6 +30,8 @@ module TUF
     STAGING_TUF_URL = "https://tuf-repo-cdn.sigstage.dev"
 
     class TrustUpdater
+      include Loggable
+
       attr_reader :updater
 
       def initialize(metadata_url, offline, metadata_dir: nil, targets_dir: nil, target_base_url: nil)
@@ -117,7 +119,7 @@ def encode_uri_component(str)
 
       def trusted_root_path
         unless @updater
-          # debug
+          logger.info { "Offline mode: using cached trusted root" }
           return File.join(@targets_dir, "trusted_root.json")
         end
 
@@ -127,12 +129,13 @@ def trusted_root_path
         path = @updater.find_cached_target(root_info)
         path ||= @updater.download_target(root_info)
 
-        # debug
         path
       end
     end
 
     class Updater
+      include Loggable
+
       def initialize(metadata_dir:, metadata_base_url:, target_base_url:, target_dir:, fetcher:,
                      config: UpdaterConfig.new)
         @dir = metadata_dir
@@ -205,14 +208,12 @@ def download_target(target_info, filepath = nil, target_base_url = nil)
           raise "Failed to download target #{target_info.inspect} #{target_filepath.inspect} from #{full_url}: " \
                 "#{e.message}"
         end
-        # debug
+        logger.info { "Downloaded #{target_filepath} to #{filepath}" }
         filepath
       end
 
       private
 
-      def debug(*_args, **_kwargs); end
-
       def load_local_metadata(role_name)
         encoded_name = URI.encode_www_form_component(role_name)
 
@@ -238,7 +239,7 @@ def load_timestamp
         begin
           data = load_local_metadata(Timestamp::TYPE)
         rescue Errno::ENOENT => e
-          debug "Local timestamp not valid as final: #{e.class} #{e.message}"
+          logger.debug "Local timestamp not valid as final: #{e.class} #{e.message}"
         else
           @trusted_set.timestamp = data
         end
@@ -257,9 +258,9 @@ def load_timestamp
       def load_snapshot
         data = load_local_metadata(Snapshot::TYPE)
         @trusted_set.snapshot = data
-        debug "Loaded snapshot from local metadata"
+        logger.debug "Loaded snapshot from local metadata"
       rescue Errno::ENOENT => e
-        debug "Local snapshot not valid as final: #{e.class} #{e.message}"
+        logger.debug "Local snapshot not valid as final: #{e.class} #{e.message}"
 
         snapshot_meta = @trusted_set.timestamp.snapshot_meta
         version = snapshot_meta.version if @trusted_set.root.consistent_snapshot
@@ -274,11 +275,11 @@ def load_targets(role, parent_role)
 
         begin
           data = load_local_metadata(role)
-          @trusted_set.update_delegated_targets(data, role, parent_role)
-
-          # debug
+          @trusted_set.update_delegated_targets(data, role, parent_role).tap do
+            logger.debug { "Loaded targets for #{role} from local metadata" }
+          end
         rescue Errno::ENOENT
-          # debug
+          logger.debug { "No local targets for #{role}, fetching" }
 
           snapshot = @trusted_set.snapshot
           metainfo = snapshot.meta.fetch("#{role}.json")
@@ -342,17 +343,15 @@ def preorder_depth_first_walk(target_path)
             child_roles_to_visit << [child_name, role_name]
             next unless terminating
 
-            # debug
+            logger.debug { "Terminating delegation found for #{child_name}" }
             delegations_to_visit.clear
             break
           end
 
           delegations_to_visit.concat child_roles_to_visit.reverse
         end
 
-        if delegations_to_visit.any?
-          # debug
-        end
+        logger.warn { "Max delegations reached, stopping search" } if delegations_to_visit.any?
 
         nil
       end

lib/sigstore/tuf/trusted_metadata_set.rb

@@ -23,6 +23,8 @@ class EqualVersionNumberError < StandardError; end
   class BadVersionNumberError < StandardError; end
 
   class TrustedMetadataSet
+    include Sigstore::Loggable
+
     def initialize(root_data, envelope_type, reference_time: Time.now.utc)
       @trusted_set = {}
       @reference_time = reference_time
@@ -94,7 +96,7 @@ def snapshot=(data, trusted: false)
       raise "snapshot version incr" if include?(Snapshot::TYPE) && (new_snapshot.version < snapshot.version)
 
       @trusted_set["snapshot"] = new_snapshot
-      # debug "Updated snapshot v#{new_snapshot.version}"
+      logger.debug { "Updated snapshot v#{new_snapshot.version}" }
       check_final_snapshot
     end
 
@@ -114,7 +116,7 @@ def update_delegated_targets(data, role, parent_role)
       delegator = @trusted_set.fetch(parent_role)
       raise "cannot load targets before delegator" unless delegator
 
-      # debug "Updating #{role} delegated by #{parent_role}"
+      logger.debug { "Updating #{role} delegated by #{parent_role}" }
 
       meta = snapshot.meta.fetch("#{role}.json")
       raise "No metadata for role: #{role}" unless meta
@@ -128,7 +130,7 @@ def update_delegated_targets(data, role, parent_role)
       raise "expired delegated targets" if new_delegate.expired?(@reference_time)
 
       @trusted_set[role] = new_delegate
-      # debug "Updated #{role} v#{version}"
+      logger.debug { "Updated #{role} v#{version}" }
       new_delegate
     end