Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Sent ContractRequestMessage despite failing presentation verification #1145

Closed
juliapampus opened this issue Mar 19, 2024 · 5 comments
Closed

Sent ContractRequestMessage despite failing presentation verification #1145

juliapampus opened this issue Mar 19, 2024 · 5 comments
Labels
bug Something isn't working stale triage all new issues awaiting classification

Comments

@juliapampus
Copy link

juliapampus commented Mar 19, 2024 •
edited

Describe the bug

We observed an unexpected behavior during a contract negotiation with failing MIW communication: The ContractRequestMessage is sent although an "MIW verification failed" issue occured.

Can anyone confirm my assumptions or hint to possible issues?

Observed behavior

Consumer-side:

  • The logs are showing an “MIW verification failed” (401) error.
  • The negotiation transitions from REQUESTING to TERMINATED.
  • The logs are showing "Cannot transition from state TERMINATED to AGREED".

Provider-side:

  • The logs are showing multiple attempts to send a ContractAgreementMessage failing due to a 500 (7x in sum).
  • The negotiation transitions from AGREEING to TERMINATING.
  • Rejection details are sent to the consumer; failing due to a 403 Forbidden.
  • The negotiation transitions from TERMINATING to TERMINATED.

My assumptions:

  • The consumer connector successfully (1) retrieves the credentials and (2) creates the presentation but (3) fails to verify the presentation (as “MIW verification failed” is created in MiwApiClientImpl.handleVerifyResult()). Nevertheless, the connector sends a ContractRequestMessage as we can see that the negotiation got started on provider-side (?)
  • Because of the failing verification, on consumer-side, the negotiation transitions to TERMINATED.
  • The provider connector successfully processes the contract request and creates an agreement. The attempts to send this agreement fail due to a 500 causing the "Cannot transition from state TERMINATED to AGREED" on consumer-side (expected as the process is already in TERMINATED).
  • The 403 Forbidden occurs because the connector does not process any further messages for a TERMINATED process (?)

Further comments:

Please note that we already identified the issue leading to the 401 by MIW. This is the root cause of the errors above and only occuring temporarily. Thus, we are facing the observed behavior only temporarily.

Nevertheless, I am trying to understand the sequence of errors and how a ContractRequestMessage can be sent while the process transitions to TERMINATED.

Expected behavior

No initiated negotiation process on provider-side.

Screenshots/Error Messages

Logs from provider-side:

DEBUG 2024-03-12T13:02:55.478941636 [PROVIDER] ContractNegotiation ... is now in state REQUESTED.
DEBUG 2024-03-12T13:02:56.470000461 [PROVIDER] ContractNegotiation ... is now in state AGREEING.
DEBUG 2024-03-12T13:02:56.681791401 ContractNegotiation: ID ... [Provider] send agreement
DEBUG 2024-03-12T13:03:13.10433539 ContractNegotiation: ID ... Attempt #1 failed to [Provider] send agreement. Cause: org.eclipse.edc.spi.http.EdcHttpClientException: Server response to Request{method=POST, url= .../api/v1/dsp/negotiations/.../agreement, headers=[Content-Type:application/json, ...} was not successful but was 500: <html> <head> <meta http-equiv="Content-Type" content="text/html

[...]

DEBUG 2024-03-12T13:09:26.180263331 [PROVIDER] ContractNegotiation ... is now in state TERMINATING.
DEBUG 2024-03-12T13:09:26.264973457 ContractNegotiation: ID ... [Provider] send rejection
DEBUG 2024-03-12T13:09:26.483024771 ContractNegotiation: ID ... [Provider] send rejection
SEVERE 2024-03-12T13:09:26.483075605 ContractNegotiation: ID ... Fatal error while [Provider] send rejection. Error details: <html>  <head><title>403 Forbidden</title></head>  <body>  <center><h1>403 Forbidden</h1></center>  </body>  </html>  
DEBUG 2024-03-12T13:09:26.593206056 [PROVIDER] ContractNegotiation ... is now in state TERMINATED.

I removed paths and IDs for confidentiality. The logs are correlated to the same negotiation process.

Context Information

  • Used version: 0.5.3 / 0.5.4
@juliapampus juliapampus added bug Something isn't working triage all new issues awaiting classification labels Mar 19, 2024
@wolf4ood
Copy link
Contributor

Hi @juliapampus

thanks for raising this, not sure what are the events that leads to

The logs are showing "Cannot transition from state TERMINATED to AGREED".

We should have a way to reproduce this and analyze.

But I am not sure that the first assumption is not correct. On a ContractRequestMessage from the consumer only 1 and 2 happens on the consumer (egress). The verification of the presentation 3 ("MIW verification failed") only happens on the ingress calls when verifying the counterparty presentation in JWT format.

That's probably why the ContractRequestMessage is sent because the validation does not happen on the consumer when requesting a contract negotiation.

Let me know if this helps with your findings
Thanks

@juliapampus
Copy link
Author

Hi @wolf4ood thanks for the quick response.

On a ContractRequestMessage from the consumer only 1 and 2 happens on the consumer (egress). The verification of the presentation 3 ("MIW verification failed") only happens on the ingress calls when verifying the counterparty presentation in JWT format.

Okay, this makes sense. Thanks! This changes the subject of this issue. So, then we have:

  1. Consumer is able to initiate the negotiation sending a ContractRequestMessage
  2. Provider processes the request and initiates the sending of a ContractAgreementMessage
  3. Consumer verifies the token of the incoming message --> fails
  4. Provider receives error, not a 4** but a 500. I assume this must be because of the "Cannot transition from state TERMINATED to AGREED"

Now, as you said, the question is how we end up in this situation:

The logs are showing "Cannot transition from state TERMINATED to AGREED".

I could understand if this happened on the 2nd attempt, assuming that the consumer's negotiation transitions to TERMINATED after a failing presentation verification. But as far as I remember the consumer logs, its negotiation never ended up in REQUESTED and I can read from the provider logs that the ContractAgreementMessage fails at the 1st attempt. I guess this was the main reason why I came to the wrong conclusions in the end...

I will check the consumer logs and come back to you asap :)

@juliapampus
Copy link
Author

juliapampus commented Mar 21, 2024 •
edited

Here the consumer logs:

DEBUG ContractNegotiation: ID ... [Consumer] Send ContractRequestMessage message
SEVERE ContractNegotiation: IDS ... Fatal error while [Consumer] Send ContractRequestMessage message. Error details:
{
   "@type": "dspace:ContractNegotiationError",
   "dspace:code": "401",
   "dspace:reason": "MIW verification failed",
   "@context": { ... }
}
DEBUG Resolving secret ... 
DEBUG [CONSUMER] ContractNegotiation ... is now in state TERMINATED.
SEVERE Invalid name. Must be a valid name containing alphanumeric characters, or any of the following ... (Service: SecretsManager, Status Code: 400, ...
...

Not sure whether the errors regarding the secrets belong to the negotiation.. but the other prompts are correlated to the same negotiation than the one on the provider side.

@github-actions GitHub Actions
Copy link
Contributor

This issue is stale because it has been open for 4 weeks with no activity.

@github-actions github-actions bot added the stale label Apr 23, 2024
@github-actions GitHub Actions
Copy link
Contributor

github-actions bot commented May 7, 2024

This issue was closed because it has been inactive for 14 days since being marked as stale.

@github-actions github-actions bot closed this as not planned Won't fix, can't repro, duplicate, stale May 7, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working stale triage all new issues awaiting classification
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@wolf4ood @juliapampus