[TIL] 2021.11.27 최종 프로젝트 진행중 - 로그 파일 월별로 남기기 / 또 일어난 이슈 / DB 데이터 복제

[로그 파일 월별로 남기기]

로그 파일을 남기는게 어려운 일인줄 알았는데 의외로 간단했다

Spring Boot / InteliJ / Java 11

 

 

 

build.gradle

dependencies {
    ...
    //로그 파일 남기기
    implementation (
            'ch.qos.logback:logback-classic:1.2.3',
            'ch.qos.logback:logback-core:1.2.3',
    )
}

 

 

 

logback-spring.xml 생성

- 아래 블로그에서는 logback.xml로 만들라고 하지만 난 되지 않았다 

  이 블로그(https://hermeslog.tistory.com/451)에서 logback-spring.xml으로 하길래 따라해봤더니 됐다

  '-spring'을 붙이면 아마 스프링이 자동으로 인식할 것이다

 

 

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true" scanPeriod="30 seconds">

    <appender name="ROLLING" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <!-- rollover daily -->
            <fileNamePattern>
                /home/ubuntu/logback/%d{yyyy,aux}/%d{MM,aux}/logback-%d{yyyy-MM-dd}.%i.log
            </fileNamePattern>
            <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <!-- or whenever the file size reaches 100MB -->
                <maxFileSize>100MB</maxFileSize>
            </timeBasedFileNamingAndTriggeringPolicy>
        </rollingPolicy>
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} %-5level %logger{36} - %msg%n</pattern>
        </encoder>
    </appender>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <layout class="ch.qos.logback.classic.PatternLayout">
            <Pattern>%d{HH:mm:ss.SSS} [%-5level] - %msg%n</Pattern>
        </layout>
    </appender>

    <!-- Loggers -->
    <!-- <logger name="org.apache.catalina" level="ERROR">
    </logger>

    <logger name="org.apache.commons" level="ERROR">
    </logger>

    <logger name="org.springframework" level="DEBUG" >
    </logger>

    <logger name="egovframework.*" level="DEBUG">
    </logger>

    <logger name="java.sql" level="DEBUG">
    </logger>

    <logger name="org.mybatis.spring" level="DEBUG">
    </logger>

    <logger name="egovframework.sqlmappers" level="TRACE">
    </logger> -->

    <root level="INFO">
        <appender-ref ref="ROLLING"/>
        <appender-ref ref="STDOUT" />
    </root>
</configuration>

 

 

 

여기서 중요한 설정은 '경로'다

            <fileNamePattern>
                /home/ubuntu/logback/%d{yyyy,aux}/%d{MM,aux}/logback-%d{yyyy-MM-dd}.%i.log
            </fileNamePattern>

 

이건 로그 파일이 100MB가 넘으면 로그파일을 새로 나눠서 만든다

<maxFileSize>100MB</maxFileSize>

 

 

이건 로그가 남는 형식을 정의해주는 것이다

        <layout class="ch.qos.logback.classic.PatternLayout">
            <Pattern>%d{HH:mm:ss.SSS} [%-5level] - %msg%n</Pattern>
        </layout>

이런 형식으로 남겨진다

13:13:49.991 INFO  p6spy - #1638018829991 | took 1ms | statement | connection 1940| url jdbc:mysql://ecafedb.ccjwneaxxse3.ap-northeast-2.rds.amazonaws.com:3306/ecafedb?serverTimezone=Asia/Seoul

 

이렇게 설정해주면 EC2에 년도/월별로 로그가 만들어진다

현재 2021/11 폴더에 11월 27일에 대한 로그가 쌓여있다

 

 

 

 

https://velog.io/@rivernine/Spring-boot-Logback%EC%9D%84-%ED%99%9C%EC%9A%A9%ED%95%9C-%EB%A1%9C%EA%B7%B8%EC%A0%80%EC%9E%A5

Spring-boot Logback을 활용한 로그저장

 

 

년도별로 남기기: %d{yyyy.aux} / 월별로 남기기: %d{MM.aux}

https://wizardee.tistory.com/177

[logback] rolling 시 날짜별로 디렉토리 생성해 보자~

---

[이슈]

팀원분이 카카오로 로그인한 계정을 평소처럼 잘 사용하시다가 카페 후기 목록을 보는 화면으로 이동했을 때 아무것도 뜨지 않는 상황이 일어났다

정상 화면 / 에러 화면

 

 

로그파일을 미리 남겨뒀기 때문에 로그를 확인할 수 있었다

wow...

에러를 검색해보면

https://okky.kr/article/948524?note=2354765 

OKKY | Jpa 쿼리 오류

한 건만 조회되어야하는 쿼리인데 2건 이상 조회되었기 때문이라고 한다

????????????????????왜???

또 머리가 멈췄다

대체 어떻게 찾아야하는건지...

카카오로 로그인했기 때문에 로컬에서 테스트해볼 수도 없는 상황이었다

오로지 이 로그파일 가지고 찾아내야했다

 

가장 먼저 어떤 쿼리가 실행되어야 했길래 그럴까? 라는 생각이 들었다

에러난 내용 바로 위에 실행된 쿼리를 봤다

select cafelike0_.cafe_like_id as cafe_lik1_10_, cafelike0_.moddate as moddate2_10_, cafelike0_.reg_date as reg_date3_10_, cafelike0_.cafe_id as cafe_id4_10_, cafelike0_.user_id as user_id5_10_ from cafe_like cafelike0_ left outer join cafe cafe1_ on cafelike0_.cafe_id=cafe1_.cafe_id left outer join user user2_ on cafelike0_.user_id=user2_.user_id where cafe1_.cafe_id=3 and user2_.user_id=22;

이 쿼리가 실행되려면 그 전에 어떤 쿼리를 실행해야하는거지?

분명히 쿼리가 실행되는 일정한 패턴이 있을 것이다

게시물을 조회하는 API이기 때문에 각 게시물마다 가져와야하는 데이터는 똑같기 때문이다

바로 위 쿼리를 봤다

select cafelikeli0_.cafe_id as cafe_id4_10_0_, cafelikeli0_.cafe_like_id as cafe_lik1_10_0_, cafelikeli0_.cafe_like_id as cafe_lik1_10_1_, cafelikeli0_.moddate as moddate2_10_1_, cafelikeli0_.reg_date as reg_date3_10_1_, cafelikeli0_.cafe_id as cafe_id4_10_1_, cafelikeli0_.user_id as user_id5_10_1_ from cafe_like cafelikeli0_ where cafelikeli0_.cafe_id=3;

이 쿼리는 여기 말고 또 어디서 실행되었을까?하면서

이 쿼리가 실행될 때 쓰였던 데이터를 봤다(where절에서 쓰이는 데이터)

 

...
select cafelikeli0_.cafe_id as cafe_id4_10_0_, cafelikeli0_.cafe_like_id as cafe_lik1_10_0_, cafelikeli0_.cafe_like_id as cafe_lik1_10_1_, cafelikeli0_.moddate as moddate2_10_1_, cafelikeli0_.reg_date as reg_date3_10_1_, cafelikeli0_.cafe_id as cafe_id4_10_1_, cafelikeli0_.user_id as user_id5_10_1_ from cafe_like cafelikeli0_ where cafelikeli0_.cafe_id=8;
...
select cafelikeli0_.cafe_id as cafe_id4_10_0_, cafelikeli0_.cafe_like_id as cafe_lik1_10_0_, cafelikeli0_.cafe_like_id as cafe_lik1_10_1_, cafelikeli0_.moddate as moddate2_10_1_, cafelikeli0_.reg_date as reg_date3_10_1_, cafelikeli0_.cafe_id as cafe_id4_10_1_, cafelikeli0_.user_id as user_id5_10_1_ from cafe_like cafelikeli0_ where cafelikeli0_.cafe_id=7;
...
select cafelikeli0_.cafe_id as cafe_id4_10_0_, cafelikeli0_.cafe_like_id as cafe_lik1_10_0_, cafelikeli0_.cafe_like_id as cafe_lik1_10_1_, cafelikeli0_.moddate as moddate2_10_1_, cafelikeli0_.reg_date as reg_date3_10_1_, cafelikeli0_.cafe_id as cafe_id4_10_1_, cafelikeli0_.user_id as user_id5_10_1_ from cafe_like cafelikeli0_ where cafelikeli0_.cafe_id=3;
...
select cafelike0_.cafe_like_id as cafe_lik1_10_, cafelike0_.moddate as moddate2_10_, cafelike0_.reg_date as reg_date3_10_, cafelike0_.cafe_id as cafe_id4_10_, cafelike0_.user_id as user_id5_10_ from cafe_like cafelike0_ left outer join cafe cafe1_ on cafelike0_.cafe_id=cafe1_.cafe_id left outer join user user2_ on cafelike0_.user_id=user2_.user_id where cafe1_.cafe_id=3 and user2_.user_id=22;
13:13:49.995 ERROR o.a.c.c.C.[.[.[.[dispatcherServlet] - Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is org.springframework.dao.IncorrectResultSizeDataAccessException: query did not return a unique result: 2; nested exception is javax.persistence.NonUniqueResultException: query did not return a unique result: 2] with root cause
javax.persistence.NonUniqueResultException: query did not return a unique result: 2
	at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:128)
	at org.hibernate.query.internal.AbstractProducedQuery.getSingleResult(AbstractProducedQuery.java:1659)
...

... -> 게시물 8번(제목: 노티드) -> 게시물 7번(제목: 아너 (Honor))

   -> 게시물 3번(제목: 오피셜 커피) -> 게시물 3번에 대한 정보를 가져오는 중 에러

이 순서대로 게시물이 조회된 것이다

 

 

정상인 화면을 보면 노티드 -> 아너 -> 오피셜 커피 -> 메모아 순서이다

그럼 '오피셜 커피'에 대한 데이터를 가져올 때 문제가 생겼구나 라는 감을 잡았다

 

 

 

에러가 나기 바로 직전에 실행된 쿼리를 봤다

...
select cafelike0_.cafe_like_id as cafe_lik1_10_, cafelike0_.moddate as moddate2_10_, cafelike0_.reg_date as reg_date3_10_, cafelike0_.cafe_id as cafe_id4_10_, cafelike0_.user_id as user_id5_10_ from cafe_like cafelike0_ left outer join cafe cafe1_ on cafelike0_.cafe_id=cafe1_.cafe_id left outer join user user2_ on cafelike0_.user_id=user2_.user_id where cafe1_.cafe_id=3 and user2_.user_id=22;
13:13:49.995 ERROR o.a.c.c.C.[.[.[.[dispatcherServlet] - Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is org.springframework.dao.IncorrectResultSizeDataAccessException: query did not return a unique result: 2; nested exception is javax.persistence.NonUniqueResultException: query did not return a unique result: 2] with root cause
javax.persistence.NonUniqueResultException: query did not return a unique result: 2
	at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:128)
	at org.hibernate.query.internal.AbstractProducedQuery.getSingleResult(AbstractProducedQuery.java:1659)
...

게시물 좋아요와 관련된 테이블에서 에러가 난 것 같았다

특히 'where cafe1_.cafe_id=3 and user2_.user_id=22;' 여기가 의심스러웠다

cafe_like 테이블을 봤다

가장 먼저 cafe_id=3 이고 user_id=22인 데이터에서 moddate가 null이였다!!

혹시 이게 문제였을까??하고 생각이 들어 비어있는 데이터를 넣어줬다

그런 다음 다시 팀원분께 확인해달라고 했다

여전히 안된다고 하셨다..

 

 

 

이 테이블을 계속 봤다

cafe_id=3 이고 user_id=22인 데이터가 또 있는거다!!!!!

로직상 cafe_id=3 이고 user_id=22인 데이터가 2개 이상 있을 수가 없다

사용자가 게시물에 대해 좋아요를 누르면 데이터가 Insert되고,

게시물 좋아요를 취소하면 데이터가 Delete되도록 했다

그래서 무조건 하나만 있어야하지만, 두개가 있었다

왜 이렇게 된건지는 전혀 모르겠다

있을 수 없는 일이다

DB에서 Delete할 때 인터넷 상태가 안 좋아 순간 Delete가 안되었다고 생각이 들 수밖에 없다

둘 중 하나를 삭제했더니 정삭적으로 동작했다

 

 

---

[DB 데이터 복제]

어제 새벽에, 서버를 재기동했을 때 alter가 실행되면서 DB 테이블이 다 날라갔었다..

급했기 때문에 원인을 모른 채 넘어갔다

이렇게 갑자기 DB가 날라갈 수도 있기 때문에 이 상황을 대비하기 위해

DB를 복제할 수 있는 방법을 찾아봤다

그런데 AWS에 DB를 복제하는 기능이 있더라!!

읽기 전용 복제본 생성!!!

'읽기 전용 복제본 생성'을 누르니 DB 정보를 입력하는 화면이 나왔다

DB를 그대로 복제하는 거였다

필요한 세팅 정보를 입력하고 DB를 생성했더니

두 DB가 연동되었다!

이전에 만든 DB에서 Insert Update Delete가 이뤄지면 그대로 새로 만든 DB에도 Insert Update Delete가 된다!!!

다행이다!데이터를 지켰다!

근데 여기서 의문인건

이렇게 그대로 상태가 반영된다면, DB가 갑자기 통째로 날라갔을 때도 상태가 반영되는 것인가...??

이건 더 알아봐야할 것 같다