Slow EDC Contract Negotiation initiation

[ds-jhartmann]

AC

• [x] Investigation
• [x] Create reproducible environment to reproduce this behavior
• [x] Communication with EDC team +
• [x] Create a pbi when fix is known

Out of scope

• [ ] Fix the issue

Description

• When starting a IRS Job, the some contract negotiations take up to 5 Minutes. EDC logs state, that the contract negotiation had to be retried.

  DEBUG 2024-05-13T17:07:46.586381097 DSP: Incoming ContractAgreementMessage for class org.eclipse.edc.connector.controlplane.contract.spi.types.negotiation.ContractNegotiation process: 5f66801f-3f03-4747-97be-9230d56b53a3
  DEBUG 2024-05-13T17:07:46.955841716 Unauthorized: Presentation Query failed: HTTP 400, message: {"timestamp":"Mon, 13 May 2024 17:07:46 GMT","status":400,"message":"Presentation Query: The provided AccessToken could not be validated.","error":"BAD_REQUEST","path":"/api/v1.0.0/iatp/presentations/query"}
  DEBUG 2024-05-13T17:07:46.955911915 Verification Failed: Unauthorized
  DEBUG 2024-05-13T17:07:46.956305311 DSP: Service call failed: Unauthorized
  DEBUG 2024-05-13T17:07:59.811349585 Entity 5f66801f-3f03-4747-97be-9230d56b53a3 ContractNegotiation retry #1 will not be attempted before 1790 ms.
  DEBUG 2024-05-13T17:08:00.840535247 Entity 5f66801f-3f03-4747-97be-9230d56b53a3 ContractNegotiation retry #1 will not be attempted before 761 ms.
  DEBUG 2024-05-13T17:08:18.204713212 Entity 5f66801f-3f03-4747-97be-9230d56b53a3 ContractNegotiation retry #2 will not be attempted before 3110 ms.
  DEBUG 2024-05-13T17:08:19.237275085 Entity 5f66801f-3f03-4747-97be-9230d56b53a3 ContractNegotiation retry #2 will not be attempted before 2077 ms.
  DEBUG 2024-05-13T17:08:20.265114603 Entity 5f66801f-3f03-4747-97be-9230d56b53a3 ContractNegotiation retry #2 will not be attempted before 1049 ms.
  DEBUG 2024-05-13T17:08:21.292610626 Entity 5f66801f-3f03-4747-97be-9230d56b53a3 ContractNegotiation retry #2 will not be attempted before 22 ms.
  DEBUG 2024-05-13T17:08:37.64111872 Entity 5f66801f-3f03-4747-97be-9230d56b53a3 ContractNegotiation retry #3 will not be attempted before 7485 ms.
  DEBUG 2024-05-13T17:08:38.675749972 Entity 5f66801f-3f03-4747-97be-9230d56b53a3 ContractNegotiation retry #3 will not be attempted before 6451 ms.
  DEBUG 2024-05-13T17:08:39.705201476 Entity 5f66801f-3f03-4747-97be-9230d56b53a3 ContractNegotiation retry #3 will not be attempted before 5421 ms.
  DEBUG 2024-05-13T17:08:40.739961226 Entity 5f66801f-3f03-4747-97be-9230d56b53a3 ContractNegotiation retry #3 will not be attempted before 4387 ms.
  DEBUG 2024-05-13T17:08:41.774839675 Entity 5f66801f-3f03-4747-97be-9230d56b53a3 ContractNegotiation retry #3 will not be attempted before 3352 ms.
  DEBUG 2024-05-13T17:08:42.804002282 Entity 5f66801f-3f03-4747-97be-9230d56b53a3 ContractNegotiation retry #3 will not be attempted before 2323 ms.
  DEBUG 2024-05-13T17:08:43.836331767 Entity 5f66801f-3f03-4747-97be-9230d56b53a3 ContractNegotiation retry #3 will not be attempted before 1290 ms.
  DEBUG 2024-05-13T17:08:44.864593601 Entity 5f66801f-3f03-4747-97be-9230d56b53a3 ContractNegotiation retry #3 will not be attempted before 262 ms.
  DEBUG 2024-05-13T17:09:01.191764612 Entity 5f66801f-3f03-4747-97be-9230d56b53a3 ContractNegotiation retry #4 will not be attempted before 15972 ms.
  DEBUG 2024-05-13T17:09:02.226953748 Entity 5f66801f-3f03-4747-97be-9230d56b53a3 ContractNegotiation retry #4 will not be attempted before 14937 ms.
  DEBUG 2024-05-13T17:09:03.258651418 Entity 5f66801f-3f03-4747-97be-9230d56b53a3 ContractNegotiation retry #4 will not be attempted before 13905 ms.
  DEBUG 2024-05-13T17:09:04.293760454 Entity 5f66801f-3f03-4747-97be-9230d56b53a3 ContractNegotiation retry #4 will not be attempted before 12870 ms.
  DEBUG 2024-05-13T17:09:05.327217407 Entity 5f66801f-3f03-4747-97be-9230d56b53a3 ContractNegotiation retry #4 will not be attempted before 11836 ms.
  DEBUG 2024-05-13T17:09:06.357884487 Entity 5f66801f-3f03-4747-97be-9230d56b53a3 ContractNegotiation retry #4 will not be attempted before 10806 ms.
  DEBUG 2024-05-13T17:09:07.389220961 Entity 5f66801f-3f03-4747-97be-9230d56b53a3 ContractNegotiation retry #4 will not be attempted before 9774 ms.
  DEBUG 2024-05-13T17:09:08.434932986 Entity 5f66801f-3f03-4747-97be-9230d56b53a3 ContractNegotiation retry #4 will not be attempted before 8729 ms.
  DEBUG 2024-05-13T17:09:09.470856009 Entity 5f66801f-3f03-4747-97be-9230d56b53a3 ContractNegotiation retry #4 will not be attempted before 7693 ms.
  DEBUG 2024-05-13T17:09:10.502840471 Entity 5f66801f-3f03-4747-97be-9230d56b53a3 ContractNegotiation retry #4 will not be attempted before 6661 ms.
  DEBUG 2024-05-13T17:09:11.541597066 Entity 5f66801f-3f03-4747-97be-9230d56b53a3 ContractNegotiation retry #4 will not be attempted before 5622 ms.
  DEBUG 2024-05-13T17:09:12.572800036 Entity 5f66801f-3f03-4747-97be-9230d56b53a3 ContractNegotiation retry #4 will not be attempted before 4591 ms.
  DEBUG 2024-05-13T17:09:13.611689829 Entity 5f66801f-3f03-4747-97be-9230d56b53a3 ContractNegotiation retry #4 will not be attempted before 3552 ms.
  DEBUG 2024-05-13T17:09:14.643782891 Entity 5f66801f-3f03-4747-97be-9230d56b53a3 ContractNegotiation retry #4 will not be attempted before 2520 ms.
  DEBUG 2024-05-13T17:09:15.675941951 Entity 5f66801f-3f03-4747-97be-9230d56b53a3 ContractNegotiation retry #4 will not be attempted before 1488 ms.
  DEBUG 2024-05-13T17:09:16.712056069 Entity 5f66801f-3f03-4747-97be-9230d56b53a3 ContractNegotiation retry #4 will not be attempted before 451 ms.

Current behaviour

Expected behavior

Steps to reproduce the Bug

[dsmf]

if the situation appears again it might be helpful to try out the experimental branch from #538 in order to (maybe) get more details in tombstones, see draft PR https://github.com/catenax-ng/tx-item-relationship-service/pull/870 of branch https://github.com/catenax-ng/tx-item-relationship-service/tree/538-propagate-exceptions-via-Either-and-addSuppressed

[dsmf]

currently not reproducible

seems to have been fixed by #616 and #648, the cucumber tests run fast again:

• https://jira.catena-x.net/projects/TRI/issues/TRI-2023?filter=allissues
• before the tests took over 1,5 hours (due to retries, timeouts) e.g. here https://github.com/catenax-ng/tx-item-relationship-service/actions/runs/9081702679
• now 12 min https://github.com/catenax-ng/tx-item-relationship-service/actions/runs/9113868528
• execution after the causes for the failing tests were fixed: https://jira.catena-x.net/projects/TRI/issues/TRI-2025?filter=allissues

[dsmf]

@ds-kgassner -> ready for test

[ds-kgassner]

Last successful run took almost 30 min. It's less than 1,5 hour therefore its approved from my side.

[mkanal]

LGFM. PO acceptance in behalf of @jzbmw