Strange verification behavior

[Xopek]

Hello!

I discovered this project and tried to go through Getting Started. I noticed, that when i run verification process i have this 3 weird lines (i highlighted them), which i don't understand:

INFO    Using config file: .witness.yaml             
INFO    Starting verify attestors stage...           
INFO    Starting policyverify attestor...            
INFO    policy signature verified                    
INFO    Finished policyverify attestor... (0.001980459s) 
INFO    Completed verify attestors stage...          
INFO    Verification succeeded                       
INFO    Evidence:                                    
INFO    Step: build                                  
INFO    0: test-att.json  <-- what is it? why it is duplicated 3 times?                            
INFO    1: test-att.json                             
INFO    2: test-att.json  

Then i tried to modify policy to include requirement for attestation in order to see how verification will fail, well error is very misleading and also duplicated 3 times:

ERROR   Verification failed                          
ERROR   Evidence:                                    
ERROR   Step: build                                  
ERROR   verification failure: Reason: collection validation failed:
 - collection verification failed: no collections found for step build,
 - collection verification failed: no verifiers present to validate against collection verifiers,
 - missing attestation in collection for step build: https://witness.dev/attestations/material/v0.1,
 - missing attestation in collection for step build: https://witness.dev/attestations/command-run/v0.1,
 - missing attestation in collection for step build: https://witness.dev/attestations/gitlab/v0.1 
ERROR   verification failure: Reason: collection validation failed:
 - collection verification failed: no collections found for step build,
 - collection verification failed: no verifiers present to validate against collection verifiers,
 - missing attestation in collection for step build: https://witness.dev/attestations/material/v0.1,
 - missing attestation in collection for step build: https://witness.dev/attestations/command-run/v0.1,
 - missing attestation in collection for step build: https://witness.dev/attestations/gitlab/v0.1 
ERROR   verification failure: Reason: collection validation failed:
 - collection verification failed: no collections found for step build,
 - collection verification failed: no verifiers present to validate against collection verifiers,
 - missing attestation in collection for step build: https://witness.dev/attestations/material/v0.1,
 - missing attestation in collection for step build: https://witness.dev/attestations/command-run/v0.1,
 - missing attestation in collection for step build: https://witness.dev/attestations/gitlab/v0.1 
ERROR   verification failure: Reason: failed to verify artifacts for step build: no passed collections present 
ERROR   failed to verify policy: policy verification failed 

Actually only gitlab attestation should be mentioned in error, others are present. And why error just duplicated 3 times? I started digging into code and found this piece of code in https://github.com/in-toto/go-witness/blob/main/policy/policy.go

func (p Policy) Verify(ctx context.Context, opts ...VerifyOption) (bool, map[string]StepResult, error) {
	vo := &verifyOptions{
		searchDepth: 3,
	}

Looks like because of this magic number 3, verification is done 3 times with mostly the same parameters, thats why i see error and success 3 times. Is it expected behavior?

[ChaosInTheCRD]

Hi @Xopek! Sorry for being so quiet but I have been working on this quietly since yesterday (thank you for pointing it out!).

The verification failure feedback is a relatively new piece of logic in the tool (before it simply told you pass or fail, no rhyme or reason).

After having a dig into the code, I am happy to say that I have figured a lot of this out and I currently have the following failure logs working in a branch:

ERROR   Verification failed                          
ERROR   Evidence:                                    
ERROR   Step: test                                   
ERROR   collection rejected: test, reference: fed400c33ef9ffec99fa5dffc7545a8ce4568d0eed423a36366324b7478a214f, reason: collection validation failed:
 - rego policy evaluation failed for attestor type https://witness.dev/attestations/command-run/v0.1: policy was denied due to: unexpected cmd
 - missing attestation in collection for step test: https://witness.dev/attestations/gitlab/v0.1  
ERROR   verification failure: reason: failed to verify artifacts for step test: no passed collections present 
ERROR   failed to verify policy: policy verification failed 

Hopefully I'm right in saying that something like this is what you were expecting to see? I am going about cleaning up this so I can raise it in a PR. Once it's ready it would be awesome if you could give it a review and a test!

[Xopek]

Hi, @ChaosInTheCRD! Thanks for answer, yeah this output looks much better and thats what i was expecting, thank you very much! I will definitely test it and review, when it its ready, thank you!

[ChaosInTheCRD]

Both witness and go-witness changes are ready to be tested 😄

One other thing to chime in on with you @Xopek, in the nature of how the verification flow works, it does evaluate "matching" collections based on some parameters (either by query to archivista or from the specified --attestation-files flag.

Given that multiple collections can be found during a verification, this leads to still getting the experience you're seeing where you see more than 1 verification failure line (multiple collections failing for the same reasons). For now I have mitigated the confusion by adding a Reference: descriptor to the verify error log line:

ERROR   Verification failed                          
ERROR   Evidence:                                    
ERROR   Step: package                                
ERROR   verification failure: no collections found   
ERROR   Step: test                                   
ERROR   collection rejected: test, reference: test.json, reason: collection validation failed:
 - rego policy evaluation failed for attestor type https://witness.dev/attestations/command-run/v0.1: policy was denied due to: unexpected cmd
 - missing attestation in collection for step test: https://witness.dev/attestations/gitlab/v0.1  
ERROR   collection rejected: test, reference: 67f0d6a703e110dead7510bb19458ff496eed8ef49281ad103115d69a9035314, reason: collection validation failed:
 - rego policy evaluation failed for attestor type https://witness.dev/attestations/command-run/v0.1: policy was denied due to: unexpected cmd
 - missing attestation in collection for step test: https://witness.dev/attestations/gitlab/v0.1  
ERROR   collection rejected: test, reference: d20c4d44abee223b260aa093b6cbfa3444fbc9dcec61746c1f54f739ae6e7608, reason: collection validation failed:
 - rego policy evaluation failed for attestor type https://witness.dev/attestations/command-run/v0.1: policy was denied due to: unexpected cmd
 - missing attestation in collection for step test: https://witness.dev/attestations/gitlab/v0.1  
ERROR   collection rejected: test, reference: fed400c33ef9ffec99fa5dffc7545a8ce4568d0eed423a36366324b7478a214f, reason: collection validation failed:
 - rego policy evaluation failed for attestor type https://witness.dev/attestations/command-run/v0.1: policy was denied due to: unexpected cmd
 - missing attestation in collection for step test: https://witness.dev/attestations/gitlab/v0.1  
ERROR   failed to verify policy: policy verification failed 

So you know more about which collection it is talking about. Hopefully that makes sense.

Thank you for trying out Witness!

[Xopek]

Wow, thanks, i will try to test it today

[Xopek]

left comment here in-toto/witness#485