Merge branch 'develop' of 10.10.31.70:/ervu-lkrp-fl into develop

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<String> 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

backend/src/main/java/ru/micord/ervu/kafka/service/impl/BaseReplyingKafkaService.java

@@ -29,13 +29,13 @@ public abstract class BaseReplyingKafkaService<T, V> implements ReplyingKafkaSer
     try {
       ConsumerRecord<String, V> result = Optional.ofNullable(replyFuture.get())
           .orElseThrow(() -> new KafkaMessageException("Kafka return result is null"));
-      LOGGER.info("Thread {} - KafkaSendMessageAndGetReply: {} ms",
+      LOGGER.info("Thread {} - KafkaSendMessageAndGetReply: {} ms, replyTopic: {}",
-          Thread.currentThread().getId(), System.currentTimeMillis() - startTime);
+          Thread.currentThread().getId(), System.currentTimeMillis() - startTime, replyTopic);
       return result;
     }
     catch (InterruptedException | ExecutionException e) {
-      LOGGER.error("Thread {} - KafkaSendMessageAndGetReply: {} ms",
+      LOGGER.error("Thread {} - KafkaSendMessageAndGetReply: {} ms, replyTopic: {}",
-          Thread.currentThread().getId(), System.currentTimeMillis() - startTime);
+          Thread.currentThread().getId(), System.currentTimeMillis() - startTime, replyTopic);
       throw new KafkaMessageReplyTimeoutException(e);
     }
   }

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);
     }
   }