From 824d1d9bc965e8c69a5c33e0136e63d354ef53a2 Mon Sep 17 00:00:00 2001 From: Matthias Fischer Date: Wed, 24 Jan 2024 11:32:22 +0100 Subject: [PATCH] feat(imp):[#214] debug logging (to be removed/adapted after debugging) switch log.debug to info because debug does not seem to get logged and add special marker "#214@" to filter the logs for debugging the story --- .../common/util/concurrent/ResultFinder.java | 25 ++++--- .../DecentralDigitalTwinRegistryService.java | 75 ++++++++++--------- .../EndpointDataForConnectorsService.java | 15 ++-- 3 files changed, 59 insertions(+), 56 deletions(-) diff --git a/irs-common/src/main/java/org/eclipse/tractusx/irs/common/util/concurrent/ResultFinder.java b/irs-common/src/main/java/org/eclipse/tractusx/irs/common/util/concurrent/ResultFinder.java index 04d1020e7e..bedc992554 100644 --- a/irs-common/src/main/java/org/eclipse/tractusx/irs/common/util/concurrent/ResultFinder.java +++ b/irs-common/src/main/java/org/eclipse/tractusx/irs/common/util/concurrent/ResultFinder.java @@ -54,11 +54,11 @@ public class ResultFinder { public CompletableFuture getFastestResult(final List> futures) { if (futures == null || futures.isEmpty()) { - log.warn("getFastestResult#0 Called getFastestResult with empty list of futures"); + log.warn("#214@getFastestResult#0 Called getFastestResult with empty list of futures"); return CompletableFuture.completedFuture(null); } - log.debug("getFastestResult#1 Trying to get fastest result from list of futures"); + log.info("#214@getFastestResult#1 Trying to get fastest result from list of futures"); final CompletableFuture fastestResultPromise = new CompletableFuture<>(); @@ -69,19 +69,19 @@ public CompletableFuture getFastestResult(final List .handle(completingOnFirstSuccessful(fastestResultPromise))) .toList(); - log.debug("getFastestResult#2"); + log.info("#214@getFastestResult#2"); allOf(toArray(futuresList)).whenComplete((value, ex) -> { - log.debug("getFastestResult#3 List of futures completed"); + log.info("#214@getFastestResult#3 List of futures completed"); if (ex != null) { - log.error("getFastestResult#4 Exception occurred: " + ex.getMessage(), ex); + log.error("g#214@etFastestResult#4 Exception occurred: " + ex.getMessage(), ex); fastestResultPromise.completeExceptionally(new CompletionExceptions(exceptions)); } else if (fastestResultPromise.isDone()) { - log.debug("getFastestResult#5 Fastest result already found, ignoring the others"); + log.info("#214@getFastestResult#5 Fastest result already found, ignoring the others"); } else { - log.debug("getFastestResult#6 Completing"); + log.info("#214@getFastestResult#6 Completing"); fastestResultPromise.complete(null); } }); @@ -98,26 +98,27 @@ private static BiFunction completingOnFirstSuccessful return (value, throwable) -> { - log.debug("completingOnFirstSuccessful#1 value: {}, throwable: {}", value, throwable); + log.info("#214@completingOnFirstSuccessful#1 value: {}, throwable: {}", value, throwable); final boolean notFinishedByOtherFuture = !resultPromise.isDone(); - log.debug("completingOnFirstSuccessful#2 notFinishedByOtherFuture {} ", notFinishedByOtherFuture); + log.info("#214@completingOnFirstSuccessful#2 notFinishedByOtherFuture {} ", notFinishedByOtherFuture); final boolean currentFutureSuccessful = throwable == null && value != null; if (notFinishedByOtherFuture && currentFutureSuccessful) { // first future that completes successfully completes the overall future - log.debug("completingOnFirstSuccessful#3 First future that completed successfully"); + log.info("#214@completingOnFirstSuccessful#3 First future that completed successfully"); resultPromise.complete(value); return true; } else { if (throwable != null) { - log.warn("completingOnFirstSuccessful#4 Exception occurred: " + throwable.getMessage(), throwable); + log.warn("#214@completingOnFirstSuccessful#4 Exception occurred: " + throwable.getMessage(), + throwable); throw new CompletionException(throwable.getMessage(), throwable); } else { - log.debug("completingOnFirstSuccessful#5 log just for debugging"); + log.info("#214@completingOnFirstSuccessful#5 log just for debugging"); } return false; } diff --git a/irs-registry-client/src/main/java/org/eclipse/tractusx/irs/registryclient/decentral/DecentralDigitalTwinRegistryService.java b/irs-registry-client/src/main/java/org/eclipse/tractusx/irs/registryclient/decentral/DecentralDigitalTwinRegistryService.java index b3a22e3759..4517823598 100644 --- a/irs-registry-client/src/main/java/org/eclipse/tractusx/irs/registryclient/decentral/DecentralDigitalTwinRegistryService.java +++ b/irs-registry-client/src/main/java/org/eclipse/tractusx/irs/registryclient/decentral/DecentralDigitalTwinRegistryService.java @@ -83,7 +83,7 @@ public Collection fetchShells(final Collecti try { - log.info("fetchShells#1 Fetching shell(s) for {} key(s)", keys.size()); + log.info("#214@fetchShells#1 Fetching shell(s) for {} key(s)", keys.size()); final var calledEndpoints = new HashSet(); final var collectedShells = groupKeysByBpn(keys).flatMap( @@ -91,15 +91,15 @@ public Collection fetchShells(final Collecti .toList(); if (collectedShells.isEmpty()) { - log.debug("fetchShells#2 no shells found"); + log.info("#214@fetchShells#2 no shells found"); throw new ShellNotFoundException("Unable to find any of the requested shells", calledEndpoints); } else { - log.info("fetchShells#3 Found {} shell(s) for {} key(s)", collectedShells.size(), keys.size()); + log.info("#214@fetchShells#3 Found {} shell(s) for {} key(s)", collectedShells.size(), keys.size()); return collectedShells; } } finally { - log.debug("fetchShells#4 finally"); + log.info("#214@fetchShells#4 finally"); } } @@ -107,11 +107,12 @@ public Collection fetchShells(final Collecti private List fetchShellDescriptors(final Set calledEndpoints, final String bpn, final List keys) { - log.info("fetchShellDescriptors#1 Fetching {} shells for bpn {}", keys.size(), bpn); + log.info("#214@fetchShellDescriptors#1 Fetching {} shells for bpn {}", keys.size(), bpn); final var connectorEndpoints = connectorEndpointsService.fetchConnectorEndpoints(bpn); - log.debug("fetchShellDescriptors#2 Found {} connector endpoints for bpn {}", connectorEndpoints.size(), bpn); + log.info("#214@fetchShellDescriptors#2 Found {} connector endpoints for bpn {}", connectorEndpoints.size(), + bpn); calledEndpoints.addAll(connectorEndpoints); @@ -121,7 +122,7 @@ private List fetchShellDescriptors(final Set private List fetchShellDescriptorsForConnectorEndpoints(final String bpn, final List keys, final List connectorEndpoints) { - log.debug("fetchShellDescriptorsForConnectorEndpoints#1"); + log.info("#214@fetchShellDescriptorsForConnectorEndpoints#1"); final EndpointDataForConnectorsService service = endpointDataForConnectorsService; try { @@ -131,33 +132,33 @@ private List fetchShellDescriptorsForConnect edr -> supplyAsync(() -> fetchShellDescriptorsForKey(keys, edr)))) .toList(); - log.debug("fetchShellDescriptorsForConnectorEndpoints#2"); + log.info("#214@fetchShellDescriptorsForConnectorEndpoints#2"); return resultFinder.getFastestResult(futures).get(); } catch (InterruptedException e) { - log.debug( - "fetchShellDescriptorsForConnectorEndpoints#3 InterruptedException occurred while fetching shells for bpn '%s'".formatted( + log.warn( + "#214@fetchShellDescriptorsForConnectorEndpoints#3 InterruptedException occurred while fetching shells for bpn '%s'".formatted( bpn), e); Thread.currentThread().interrupt(); return emptyList(); } catch (ResultFinder.CompletionExceptions e) { - log.debug("fetchShellDescriptorsForConnectorEndpoints#4 " + e.getMessage(), e); - e.getCauses().forEach(ex -> log.debug("fetchShellDescriptorsForConnectorEndpoints#5 " // + log.warn("#214@fetchShellDescriptorsForConnectorEndpoints#4 " + e.getMessage(), e); + e.getCauses().forEach(ex -> log.warn("#214@fetchShellDescriptorsForConnectorEndpoints#5 " // + ex.getMessage(), ex)); throw new RegistryServiceRuntimeException( - "Exception occurred while fetching shells for bpn '%s'".formatted(bpn), e); + "#214@ Exception occurred while fetching shells for bpn '%s'".formatted(bpn), e); } catch (ExecutionException e) { - log.error("fetchShellDescriptorsForConnectorEndpoints#6 " + e.getMessage(), e); + log.error("#214@fetchShellDescriptorsForConnectorEndpoints#6 " + e.getMessage(), e); throw new RegistryServiceRuntimeException( - "Exception occurred while fetching shells for bpn '%s'".formatted(bpn), e); + "#214@ Exception occurred while fetching shells for bpn '%s'".formatted(bpn), e); } finally { - log.debug("fetchShellDescriptorsForConnectorEndpoints#7 finally"); + log.info("#214@fetchShellDescriptorsForConnectorEndpoints#7 finally"); } } @@ -170,13 +171,13 @@ private List fetchShellDescriptorsForKey( private AssetAdministrationShellDescriptor fetchShellDescriptor(final EndpointDataReference endpointDataReference, final DigitalTwinRegistryKey key) { try { - log.info("fetchShellDescriptor#1 Retrieving AAS Identification for DigitalTwinRegistryKey: {}", key); + log.info("#214@fetchShellDescriptor#1 Retrieving AAS Identification for DigitalTwinRegistryKey: {}", key); final String aaShellIdentification = mapToShellId(endpointDataReference, key.shellId()); - log.debug("fetchShellDescriptor#2 aaShellIdentification: {}", aaShellIdentification); + log.info("#214@fetchShellDescriptor#2 aaShellIdentification: {}", aaShellIdentification); return decentralDigitalTwinRegistryClient.getAssetAdministrationShellDescriptor(endpointDataReference, aaShellIdentification); } finally { - log.debug("fetchShellDescriptor#3 finally"); + log.info("#214@fetchShellDescriptor#3 finally"); } } @@ -192,7 +193,7 @@ private AssetAdministrationShellDescriptor fetchShellDescriptor(final EndpointDa @NotNull private String mapToShellId(final EndpointDataReference endpointDataReference, final String key) { - log.debug("mapToShellId#1"); + log.info("#214@mapToShellId#1"); try { @@ -207,30 +208,30 @@ private String mapToShellId(final EndpointDataReference endpointDataReference, f .findFirst() .orElse(key); - log.debug("mapToShellId#2"); + log.info("#214@mapToShellId#2"); if (key.equals(aaShellIdentification)) { - log.info("mapToShellId#3 Found shell with shellId {} in registry", aaShellIdentification); + log.info("#214@mapToShellId#3 Found shell with shellId {} in registry", aaShellIdentification); } else { - log.info("mapToShellId#4 Retrieved shellId {} for globalAssetId {}", aaShellIdentification, key); + log.info("#214@mapToShellId#4 Retrieved shellId {} for globalAssetId {}", aaShellIdentification, key); } return aaShellIdentification; } finally { - log.debug("mapToShellId#5 finally"); + log.info("#214@mapToShellId#5 finally"); } } private Collection lookupShellIds(final String bpn) { - log.info("lookupShellIds#1 Looking up shell ids for bpn {}", bpn); + log.info("#214@lookupShellIds#1 Looking up shell ids for bpn {}", bpn); final var connectorEndpoints = connectorEndpointsService.fetchConnectorEndpoints(bpn); - log.debug("lookupShellIds#2 Looking up shell ids for bpn {} with connector endpoints {}", bpn, + log.info("#214@lookupShellIds#2 Looking up shell ids for bpn {} with connector endpoints {}", bpn, connectorEndpoints); final var endpointDataReferenceFutures = endpointDataForConnectorsService.createFindEndpointDataForConnectorsFutures( connectorEndpoints); - log.debug("lookupShellIds#3 created futures"); + log.info("#214@lookupShellIds#3 created futures"); try { final var futures = endpointDataReferenceFutures.stream() @@ -239,39 +240,39 @@ private Collection lookupShellIds(final String bpn) { .toList(); final var shellIds = resultFinder.getFastestResult(futures).get(); - log.info("lookupShellIds#4 Found {} shell id(s) in total", shellIds.size()); + log.info("#214@lookupShellIds#4 Found {} shell id(s) in total", shellIds.size()); return shellIds; } catch (InterruptedException e) { - log.debug( - "lookupShellIds#5 InterruptedException occurred while looking up shells ids for bpn '%s'".formatted( + log.info( + "#214@lookupShellIds#5 InterruptedException occurred while looking up shells ids for bpn '%s'".formatted( bpn), e); Thread.currentThread().interrupt(); return emptyList(); } catch (ResultFinder.CompletionExceptions e) { - log.debug("lookupShellIds#6" + e.getMessage(), e); - e.getCauses().forEach(ex -> log.debug("lookupShellIds#7 " + ex.getMessage(), ex)); + log.warn("#214@lookupShellIds#6" + e.getMessage(), e); + e.getCauses().forEach(ex -> log.warn("lookupShellIds#7 " + ex.getMessage(), ex)); throw new RegistryServiceRuntimeException( - "Exception occurred while looking up shell ids for bpn '%s'".formatted(bpn), e); + "#214@ Exception occurred while looking up shell ids for bpn '%s'".formatted(bpn), e); } catch (ExecutionException e) { - log.error("lookupShellIds#8 " + e.getMessage(), e); + log.error("#214@lookupShellIds#8 " + e.getMessage(), e); throw new RegistryServiceRuntimeException( - "Exception occurred while looking up shell ids for bpn '%s'".formatted(bpn), e); + "#214@ Exception occurred while looking up shell ids for bpn '%s'".formatted(bpn), e); } } private List lookupShellIds(final String bpn, final EndpointDataReference endpointDataReference) { - log.debug("lookupShellIds#1 look up shell IDs for bpn {} with endpointDataReference {}", bpn, + log.info("#214@lookupShellIds#1 look up shell IDs for bpn {} with endpointDataReference {}", bpn, endpointDataReference); try { return decentralDigitalTwinRegistryClient.getAllAssetAdministrationShellIdsByAssetLink( endpointDataReference, List.of(IdentifierKeyValuePair.builder().name("manufacturerId").value(bpn).build())).getResult(); } finally { - log.debug("lookupShellIds#2 finally"); + log.info("#214@lookupShellIds#2 finally"); } } diff --git a/irs-registry-client/src/main/java/org/eclipse/tractusx/irs/registryclient/decentral/EndpointDataForConnectorsService.java b/irs-registry-client/src/main/java/org/eclipse/tractusx/irs/registryclient/decentral/EndpointDataForConnectorsService.java index 28a7edd321..95183596da 100644 --- a/irs-registry-client/src/main/java/org/eclipse/tractusx/irs/registryclient/decentral/EndpointDataForConnectorsService.java +++ b/irs-registry-client/src/main/java/org/eclipse/tractusx/irs/registryclient/decentral/EndpointDataForConnectorsService.java @@ -52,8 +52,8 @@ public List> createFindEndpointDataForC List> futures = Collections.emptyList(); try { - log.debug( - "createFindEndpointDataForConnectorsFutures#1 creating futures to get EndpointDataReferences for endpoints: {}", + log.info( + "#214#createFindEndpointDataForConnectorsFutures#1 creating futures to get EndpointDataReferences for endpoints: {}", connectorEndpoints); futures = connectorEndpoints.stream() .map(connectorEndpoint -> supplyAsync( @@ -61,26 +61,27 @@ public List> createFindEndpointDataForC .toList(); return futures; } finally { - log.debug("createFindEndpointDataForConnectorsFutures#2 created {} futures", futures.size()); + log.info("#214@createFindEndpointDataForConnectorsFutures#2 created {} futures", futures.size()); } } private EndpointDataReference getEndpointReferenceForAsset(final String connector) { - log.info("getEndpointReferenceForAsset#1 Trying to retrieve EndpointDataReference for connector {}", connector); + log.info("#214@getEndpointReferenceForAsset#1 Trying to retrieve EndpointDataReference for connector {}", + connector); try { final var endpointDataReference = edcSubmodelFacade.getEndpointReferenceForAsset(connector, DT_REGISTRY_ASSET_TYPE, DT_REGISTRY_ASSET_VALUE); - log.debug("getEndpointReferenceForAsset#2 Got EndpointDataReference for connector {}", connector); + log.info("#214@getEndpointReferenceForAsset#2 Got EndpointDataReference for connector {}", connector); return endpointDataReference; } catch (EdcRetrieverException e) { log.warn( - "getEndpointReferenceForAsset#3 Exception occurred when retrieving EndpointDataReference from connector {}", + "#214@getEndpointReferenceForAsset#3 Exception occurred when retrieving EndpointDataReference from connector {}", connector, e); throw new CompletionException(e.getMessage(), e); } finally { - log.debug("getEndpointReferenceForAsset#4 finally"); + log.info("#214@getEndpointReferenceForAsset#4 finally"); } }