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..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 @@ -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,11 @@ 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", "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 +74,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(), serverIp, + System.currentTimeMillis() - startTime); + + startTime = System.currentTimeMillis(); String clientIp = NetworkUtils.getClientIp(request); + 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(), serverHostName, + System.currentTimeMillis() - startTime); + + startTime = System.currentTimeMillis(); String clientHostName = NetworkUtils.getHostName(clientIp); + LOGGER.info("Thread {} - client host name {} got in {} ms", Thread.currentThread().getId(), clientHostName, + System.currentTimeMillis() - startTime); + startTime = System.currentTimeMillis(); AuditAuthorizationEvent event = new AuditAuthorizationEvent( personModel.getPrnsId(), @@ -85,6 +111,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); + + IP_HEADERS.forEach(header -> LOGGER.info("Data from header: {} - {}", header, request.getHeader(header))); } @Override 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); } } 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..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 @@ -183,11 +183,15 @@ public class EsiaAuthService { } public void authEsiaTokensByCode(String esiaAuthCode, String state, HttpServletResponse response, HttpServletRequest request) { + long startReqTime = System.currentTimeMillis(); + 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"); @@ -203,9 +207,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(); @@ -221,7 +225,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)) @@ -231,7 +235,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 @@ -246,9 +250,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); } @@ -282,11 +286,17 @@ 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); } + 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); } }