From 40fecd062f14c287510bf85ae6bdaf93506ec548 Mon Sep 17 00:00:00 2001 From: gulnaz Date: Thu, 29 May 2025 10:47:08 +0300 Subject: [PATCH 1/5] SUPPORT-9182: log request time --- .../ru/micord/ervu/security/esia/service/EsiaAuthService.java | 2 ++ 1 file changed, 2 insertions(+) diff --git a/backend/src/main/java/ru/micord/ervu/security/esia/service/EsiaAuthService.java b/backend/src/main/java/ru/micord/ervu/security/esia/service/EsiaAuthService.java index 65fc895..d4054f0 100644 --- a/backend/src/main/java/ru/micord/ervu/security/esia/service/EsiaAuthService.java +++ b/backend/src/main/java/ru/micord/ervu/security/esia/service/EsiaAuthService.java @@ -183,6 +183,7 @@ public class EsiaAuthService { } public void authEsiaTokensByCode(String esiaAuthCode, String state, HttpServletResponse response, HttpServletRequest request) { + long startReqTime = System.currentTimeMillis(); String esiaAccessTokenStr = null; String prnOid = null; Long expiresIn = null; @@ -287,6 +288,7 @@ public class EsiaAuthService { ); } createTokenAndAddCookie(response, prnOid, ervuId, expiresIn); + LOGGER.info("Thread {} - Request time: {} ms", Thread.currentThread().getId(), System.currentTimeMillis() - startReqTime); } } From e846562f0cccba6b7103422155a530ad075936b6 Mon Sep 17 00:00:00 2001 From: gulnaz Date: Fri, 30 May 2025 12:33:09 +0300 Subject: [PATCH 2/5] SUPPORT-9182: add extra logs --- .../audit/service/impl/BaseAuditService.java | 39 +++++++++++++++++++ .../esia/service/EsiaAuthService.java | 15 ++++--- 2 files changed, 48 insertions(+), 6 deletions(-) diff --git a/backend/src/main/java/ru/micord/ervu/audit/service/impl/BaseAuditService.java b/backend/src/main/java/ru/micord/ervu/audit/service/impl/BaseAuditService.java index 94520ee..3df2fa1 100644 --- a/backend/src/main/java/ru/micord/ervu/audit/service/impl/BaseAuditService.java +++ b/backend/src/main/java/ru/micord/ervu/audit/service/impl/BaseAuditService.java @@ -1,9 +1,14 @@ package ru.micord.ervu.audit.service.impl; +import java.util.Arrays; +import java.util.List; +import java.util.Objects; import javax.servlet.http.HttpServletRequest; import com.fasterxml.jackson.core.JsonProcessingException; import com.fasterxml.jackson.databind.ObjectMapper; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; import org.springframework.beans.factory.annotation.Value; import org.springframework.context.annotation.Conditional; import org.springframework.stereotype.Service; @@ -26,6 +31,10 @@ import ru.micord.ervu.util.NetworkUtils; @Service @Conditional(AuditEnabledCondition.class) public class BaseAuditService implements AuditService { + private static final Logger LOGGER = LoggerFactory.getLogger(BaseAuditService.class); + private static final List IP_HEADERS = Arrays.asList("X-Forwarded-For", "Proxy-Client-IP", "WL-Proxy-Client-IP", "HTTP_CLIENT_IP", "HTTP_X_FORWARDED_FOR"); + + private final AuditKafkaPublisher auditPublisher; private final JwtTokenService jwtTokenService; private final ObjectMapper objectMapper; @@ -64,10 +73,26 @@ public class BaseAuditService implements AuditService { @Override public void processAuthEvent(HttpServletRequest request, PersonModel personModel, String status, String eventType) { + long startTime = System.currentTimeMillis(); String serverIp = NetworkUtils.getServerIp(); + LOGGER.info("Thread {} - server ip got in {} ms", Thread.currentThread().getId(), + System.currentTimeMillis() - startTime); + + startTime = System.currentTimeMillis(); String clientIp = NetworkUtils.getClientIp(request); + LOGGER.info("Thread {} - client ip got in {} ms", Thread.currentThread().getId(), + System.currentTimeMillis() - startTime); + + startTime = System.currentTimeMillis(); String serverHostName = NetworkUtils.getHostName(serverIp); + LOGGER.info("Thread {} - server host name got in {} ms", Thread.currentThread().getId(), + System.currentTimeMillis() - startTime); + + startTime = System.currentTimeMillis(); String clientHostName = NetworkUtils.getHostName(clientIp); + LOGGER.info("Thread {} - client host name got in {} ms", Thread.currentThread().getId(), + System.currentTimeMillis() - startTime); + startTime = System.currentTimeMillis(); AuditAuthorizationEvent event = new AuditAuthorizationEvent( personModel.getPrnsId(), @@ -85,6 +110,10 @@ public class BaseAuditService implements AuditService { ); String message = convertToMessage(event); auditPublisher.publishEvent(authorizationTopic, message); + LOGGER.info("Thread {} - event published in {} ms", Thread.currentThread().getId(), + System.currentTimeMillis() - startTime); + + LOGGER.info("client ip from header: {}", getClientIp(request)); } @Override @@ -114,4 +143,14 @@ public class BaseAuditService implements AuditService { throw new RuntimeException(e); } } + + public String getClientIp(HttpServletRequest request) { + IP_HEADERS.forEach(header -> LOGGER.info("Data from header: {} - {}", header, request.getHeader(header))); + return IP_HEADERS.stream() + .map(request::getHeader) + .filter(Objects::nonNull) + .filter(ip -> !ip.isEmpty() && !ip.equalsIgnoreCase("unknown")) + .findFirst() + .orElseGet(request::getRemoteAddr); + } } diff --git a/backend/src/main/java/ru/micord/ervu/security/esia/service/EsiaAuthService.java b/backend/src/main/java/ru/micord/ervu/security/esia/service/EsiaAuthService.java index d4054f0..f8793a0 100644 --- a/backend/src/main/java/ru/micord/ervu/security/esia/service/EsiaAuthService.java +++ b/backend/src/main/java/ru/micord/ervu/security/esia/service/EsiaAuthService.java @@ -184,6 +184,7 @@ public class EsiaAuthService { public void authEsiaTokensByCode(String esiaAuthCode, String state, HttpServletResponse response, HttpServletRequest request) { long startReqTime = System.currentTimeMillis(); + long startSubReqTime; String esiaAccessTokenStr = null; String prnOid = null; Long expiresIn = null; @@ -204,9 +205,9 @@ public class EsiaAuthService { parameters.put("state", "%s"); parameters.put("redirect_uri", redirectUrl); parameters.put("code", esiaAuthCode); - long startTime = System.currentTimeMillis(); + startSubReqTime = System.currentTimeMillis(); SignResponse signResponse = signMap(parameters); - signSecret = System.currentTimeMillis() - startTime; + signSecret = System.currentTimeMillis() - startSubReqTime; String newState = signResponse.getState(); String clientSecret = signResponse.getSignature(); String authUrl = esiaConfig.getEsiaBaseUri() + esiaConfig.getEsiaTokenUrl(); @@ -222,7 +223,7 @@ public class EsiaAuthService { .setParameter("token_type", "Bearer") .setParameter("client_certificate_hash", esiaConfig.getClientCertHash()) .toFormUrlencodedString(); - startTime = System.currentTimeMillis(); + startSubReqTime = System.currentTimeMillis(); HttpRequest postReq = HttpRequest.newBuilder(URI.create(authUrl)) .header(HttpHeaders.CONTENT_TYPE, "application/x-www-form-urlencoded") .POST(HttpRequest.BodyPublishers.ofString(postBody)) @@ -232,7 +233,7 @@ public class EsiaAuthService { .connectTimeout(Duration.ofSeconds(esiaConfig.getConnectionTimeout())) .build() .send(postReq, HttpResponse.BodyHandlers.ofString()); - requestAccessToken = System.currentTimeMillis() - startTime; + requestAccessToken = System.currentTimeMillis() - startSubReqTime; String responseString = postResp.body(); EsiaTokenResponse tokenResponse = objectMapper.readValue(responseString, EsiaTokenResponse.class @@ -247,9 +248,9 @@ public class EsiaAuthService { throw new EsiaException("Token invalid. State from request not equals with state from response."); } esiaAccessTokenStr = tokenResponse.getAccessToken(); - startTime = System.currentTimeMillis(); + startSubReqTime = System.currentTimeMillis(); String verifyResult = verifyToken(esiaAccessTokenStr); - verifySecret = System.currentTimeMillis() - startTime; + verifySecret = System.currentTimeMillis() - startSubReqTime; if (verifyResult != null) { throw new EsiaException(verifyResult); } @@ -283,9 +284,11 @@ public class EsiaAuthService { } finally { if (personModel != null) { + startSubReqTime = System.currentTimeMillis(); auditService.processAuthEvent( request, personModel, status, AuditConstants.LOGIN_EVENT_TYPE ); + LOGGER.info("Thread {} - Process auth event: {} ms", Thread.currentThread().getId(), System.currentTimeMillis() - startSubReqTime); } createTokenAndAddCookie(response, prnOid, ervuId, expiresIn); LOGGER.info("Thread {} - Request time: {} ms", Thread.currentThread().getId(), System.currentTimeMillis() - startReqTime); From a9a5ac9a2f2307f14d9da4cd344f991d33575614 Mon Sep 17 00:00:00 2001 From: gulnaz Date: Fri, 30 May 2025 13:36:05 +0300 Subject: [PATCH 3/5] SUPPORT-9182: add extra logs 2 --- .../ervu/audit/service/impl/BaseAuditService.java | 11 ++++++----- .../ervu/security/esia/service/EsiaAuthService.java | 3 +++ 2 files changed, 9 insertions(+), 5 deletions(-) diff --git a/backend/src/main/java/ru/micord/ervu/audit/service/impl/BaseAuditService.java b/backend/src/main/java/ru/micord/ervu/audit/service/impl/BaseAuditService.java index 3df2fa1..2cbcc0c 100644 --- a/backend/src/main/java/ru/micord/ervu/audit/service/impl/BaseAuditService.java +++ b/backend/src/main/java/ru/micord/ervu/audit/service/impl/BaseAuditService.java @@ -32,7 +32,8 @@ import ru.micord.ervu.util.NetworkUtils; @Conditional(AuditEnabledCondition.class) public class BaseAuditService implements AuditService { private static final Logger LOGGER = LoggerFactory.getLogger(BaseAuditService.class); - private static final List IP_HEADERS = Arrays.asList("X-Forwarded-For", "Proxy-Client-IP", "WL-Proxy-Client-IP", "HTTP_CLIENT_IP", "HTTP_X_FORWARDED_FOR"); + private static final List IP_HEADERS = + Arrays.asList("X-Forwarded-For", "Proxy-Client-IP", "WL-Proxy-Client-IP", "HTTP_CLIENT_IP", "HTTP_X_FORWARDED_FOR", "X-CLIENT-IP"); private final AuditKafkaPublisher auditPublisher; @@ -75,22 +76,22 @@ public class BaseAuditService implements AuditService { String eventType) { long startTime = System.currentTimeMillis(); String serverIp = NetworkUtils.getServerIp(); - LOGGER.info("Thread {} - server ip got in {} ms", Thread.currentThread().getId(), + LOGGER.info("Thread {} - server ip {} got in {} ms", Thread.currentThread().getId(), serverIp, System.currentTimeMillis() - startTime); startTime = System.currentTimeMillis(); String clientIp = NetworkUtils.getClientIp(request); - LOGGER.info("Thread {} - client ip got in {} ms", Thread.currentThread().getId(), + LOGGER.info("Thread {} - client ip {} got in {} ms", Thread.currentThread().getId(), clientIp, System.currentTimeMillis() - startTime); startTime = System.currentTimeMillis(); String serverHostName = NetworkUtils.getHostName(serverIp); - LOGGER.info("Thread {} - server host name got in {} ms", Thread.currentThread().getId(), + LOGGER.info("Thread {} - server host name {} got in {} ms", Thread.currentThread().getId(), serverHostName, System.currentTimeMillis() - startTime); startTime = System.currentTimeMillis(); String clientHostName = NetworkUtils.getHostName(clientIp); - LOGGER.info("Thread {} - client host name got in {} ms", Thread.currentThread().getId(), + LOGGER.info("Thread {} - client host name {} got in {} ms", Thread.currentThread().getId(), clientHostName, System.currentTimeMillis() - startTime); startTime = System.currentTimeMillis(); diff --git a/backend/src/main/java/ru/micord/ervu/security/esia/service/EsiaAuthService.java b/backend/src/main/java/ru/micord/ervu/security/esia/service/EsiaAuthService.java index f8793a0..5bcd921 100644 --- a/backend/src/main/java/ru/micord/ervu/security/esia/service/EsiaAuthService.java +++ b/backend/src/main/java/ru/micord/ervu/security/esia/service/EsiaAuthService.java @@ -290,7 +290,10 @@ public class EsiaAuthService { ); LOGGER.info("Thread {} - Process auth event: {} ms", Thread.currentThread().getId(), System.currentTimeMillis() - startSubReqTime); } + startSubReqTime = System.currentTimeMillis(); createTokenAndAddCookie(response, prnOid, ervuId, expiresIn); + LOGGER.info("Thread {} - Creating token and add cookie: {} ms", Thread.currentThread().getId(), System.currentTimeMillis() - startSubReqTime); + LOGGER.info("Thread {} - Request time: {} ms", Thread.currentThread().getId(), System.currentTimeMillis() - startReqTime); } } From c5ddacc405a123e960dbb9225e0656937ea361dd Mon Sep 17 00:00:00 2001 From: gulnaz Date: Fri, 30 May 2025 15:30:20 +0300 Subject: [PATCH 4/5] SUPPORT-9182: add extra logs 3 --- .../ru/micord/ervu/security/esia/service/EsiaAuthService.java | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/backend/src/main/java/ru/micord/ervu/security/esia/service/EsiaAuthService.java b/backend/src/main/java/ru/micord/ervu/security/esia/service/EsiaAuthService.java index 5bcd921..9c62b0d 100644 --- a/backend/src/main/java/ru/micord/ervu/security/esia/service/EsiaAuthService.java +++ b/backend/src/main/java/ru/micord/ervu/security/esia/service/EsiaAuthService.java @@ -184,12 +184,14 @@ public class EsiaAuthService { public void authEsiaTokensByCode(String esiaAuthCode, String state, HttpServletResponse response, HttpServletRequest request) { long startReqTime = System.currentTimeMillis(); - long startSubReqTime; + long startSubReqTime = startReqTime; String esiaAccessTokenStr = null; String prnOid = null; Long expiresIn = null; long signSecret = 0, requestAccessToken = 0, verifySecret = 0; verifyStateFromCookie(request, state, response); + LOGGER.info("Thread {} - Verify state from cookie: {} ms", Thread.currentThread().getId(), System.currentTimeMillis() - startSubReqTime); + try { String clientId = esiaConfig.getClientId(); DateTimeFormatter formatter = DateTimeFormatter.ofPattern("yyyy.MM.dd HH:mm:ss xx"); From e0b5d32cd0e987d6e2f0443b7050587bc4d7896d Mon Sep 17 00:00:00 2001 From: gulnaz Date: Thu, 5 Jun 2025 16:24:27 +0300 Subject: [PATCH 5/5] SUPPORT-9182: small fix in logs --- .../ervu/audit/service/impl/BaseAuditService.java | 14 ++------------ .../service/impl/BaseReplyingKafkaService.java | 8 ++++---- 2 files changed, 6 insertions(+), 16 deletions(-) diff --git a/backend/src/main/java/ru/micord/ervu/audit/service/impl/BaseAuditService.java b/backend/src/main/java/ru/micord/ervu/audit/service/impl/BaseAuditService.java index 2cbcc0c..090c7a6 100644 --- a/backend/src/main/java/ru/micord/ervu/audit/service/impl/BaseAuditService.java +++ b/backend/src/main/java/ru/micord/ervu/audit/service/impl/BaseAuditService.java @@ -33,7 +33,7 @@ import ru.micord.ervu.util.NetworkUtils; public class BaseAuditService implements AuditService { private static final Logger LOGGER = LoggerFactory.getLogger(BaseAuditService.class); private static final List IP_HEADERS = - Arrays.asList("X-Forwarded-For", "Proxy-Client-IP", "WL-Proxy-Client-IP", "HTTP_CLIENT_IP", "HTTP_X_FORWARDED_FOR", "X-CLIENT-IP"); + Arrays.asList("X-Forwarded-For", "WL-Proxy-Client-IP", "HTTP_CLIENT_IP", "HTTP_X_FORWARDED_FOR"); private final AuditKafkaPublisher auditPublisher; @@ -114,7 +114,7 @@ public class BaseAuditService implements AuditService { LOGGER.info("Thread {} - event published in {} ms", Thread.currentThread().getId(), System.currentTimeMillis() - startTime); - LOGGER.info("client ip from header: {}", getClientIp(request)); + IP_HEADERS.forEach(header -> LOGGER.info("Data from header: {} - {}", header, request.getHeader(header))); } @Override @@ -144,14 +144,4 @@ public class BaseAuditService implements AuditService { throw new RuntimeException(e); } } - - public String getClientIp(HttpServletRequest request) { - IP_HEADERS.forEach(header -> LOGGER.info("Data from header: {} - {}", header, request.getHeader(header))); - return IP_HEADERS.stream() - .map(request::getHeader) - .filter(Objects::nonNull) - .filter(ip -> !ip.isEmpty() && !ip.equalsIgnoreCase("unknown")) - .findFirst() - .orElseGet(request::getRemoteAddr); - } } diff --git a/backend/src/main/java/ru/micord/ervu/kafka/service/impl/BaseReplyingKafkaService.java b/backend/src/main/java/ru/micord/ervu/kafka/service/impl/BaseReplyingKafkaService.java index 96aacea..190ded5 100644 --- a/backend/src/main/java/ru/micord/ervu/kafka/service/impl/BaseReplyingKafkaService.java +++ b/backend/src/main/java/ru/micord/ervu/kafka/service/impl/BaseReplyingKafkaService.java @@ -29,13 +29,13 @@ public abstract class BaseReplyingKafkaService implements ReplyingKafkaSer try { ConsumerRecord result = Optional.ofNullable(replyFuture.get()) .orElseThrow(() -> new KafkaMessageException("Kafka return result is null")); - LOGGER.info("Thread {} - KafkaSendMessageAndGetReply: {} ms", - Thread.currentThread().getId(), System.currentTimeMillis() - startTime); + LOGGER.info("Thread {} - KafkaSendMessageAndGetReply: {} ms, replyTopic: {}", + Thread.currentThread().getId(), System.currentTimeMillis() - startTime, replyTopic); return result; } catch (InterruptedException | ExecutionException e) { - LOGGER.error("Thread {} - KafkaSendMessageAndGetReply: {} ms", - Thread.currentThread().getId(), System.currentTimeMillis() - startTime); + LOGGER.error("Thread {} - KafkaSendMessageAndGetReply: {} ms, replyTopic: {}", + Thread.currentThread().getId(), System.currentTimeMillis() - startTime, replyTopic); throw new KafkaMessageReplyTimeoutException(e); } }