로깅의 필요성
그동안 2번의 협업 프로젝트를 진행하면서 프로젝트에 대한 기능을 하나씩 완성해가며 잘 수행되는지 여부를 판단하기 위해서는 상태값과 잘 수행되어 데이터를 받았는지 뿐만 아니라 다양한 부분을 고려해봐야 한다. 내가 프로젝트를 수행하면서 로그로 필요했던 부분은 아래와 같았다.
- 메서드 수행 시간
- 받아오는 데이터와 반환되는 데이터
- request header, request body
- response header, response body, response status code
- 로그 수행 중 변환되는 데이터 값에 대한 추적
- 예외가 발생하는 위치 출력
- 각 레이어 정상 작동 여부
로그 수집이 필요한 이유
우선 예를 들어 AWS EC2에 접근하여 우리가 저장해둔 로그를 콘솔이나 파일로 들어가서 확인한다고 하자.
서버에는 이미 몇 달 동안 동작한 로그들이 저장되어 있다.
--- [ main] com.zaxxer.hikari.HikariDataSource : HikariPool-2 - Starting...
[2025-02-08 11:01:22.578] INFO 1
--- [ main] com.zaxxer.hikari.pool.HikariPool : HikariPool-2 - Added connection com.mysql.cj.jdbc.ConnectionImpl@36b6802f
[2025-02-08 11:01:22.579] INFO 1
--- [ main] com.zaxxer.hikari.HikariDataSource : HikariPool-2 - Start completed.
[2025-02-08 11:01:24.082] INFO 1
--- [ main] ibernate.validator.internal.util.Version : HV000001: Hibernate Validator 8.0.1.Final
[2025-02-08 11:01:26.643] INFO 1
--- [ main] a.platform.internal.JtaPlatformInitiator : HHH000489: No JTA platform available (set 'hibernate.transaction.jta.platform' to enable JTA platform integration)
[2025-02-08 11:01:27.178] INFO 1
--- [ main] a.LocalContainerEntityManagerFactoryBean : Initialized JPA EntityManagerFactory for persistence unit 'default'
[2025-02-08 11:01:29.552] INFO 1
--- [ main] pa.repository.query.QueryEnhancerFactory : Hibernate is in classpath; If applicable, HQL parser will be used.
Hibernate: select be1_0.board_id,be1_0.board_type,be1_0.content,be1_0.created_at,be1_0.is_deleted,be1_0.title,be1_0.updated_at,be1_0.view_count,be1_0.users_id from board be1_0 where (be1_0.is_deleted = 0)
[2025-02-08 11:01:34.028] WARN 1
--- [ main] JpaBaseConfiguration$JpaWebConfiguration : spring.jpa.open-in-view is enabled by default. Therefore, database queries may be performed during view rendering. Explicitly configure spring.jpa.open-in-view to disable this warning
[2025-02-08 11:01:34.135] INFO 1
--- [ main] r$InitializeUserDetailsManagerConfigurer : Global AuthenticationManager configured with UserDetailsService bean with name loginService
[2025-02-08 11:01:37.029] INFO 1
--- [ main] g.apache.coyote.http11.Http11NioProtocol : Starting ProtocolHandler ["http-nio-8080"]
[2025-02-08 11:01:37.070] INFO 1
--- [ main] boot.web.embedded.tomcat.TomcatWebServer : Tomcat started on port 8080 (http) with context path '/'
[2025-02-08 11:01:37.118] INFO 1
--- [ main] com.mentit.mento.MentoAppApplication : Started MentoAppApplication in 27.04 seconds (process running for 30.667)아래처럼 배포한 application을 배포하기만해도 벌써 몇십줄이 생성된다. 이렇게 누적되는 log가 하루, 일주일, 한달이 누적된다고 했을때 과연 개발자가 그걸 일일히 다 찾아들어갈 수 있을까? 그리고 그게 과연 효율적일까? 라는 의문이 들게 되었고, 로그를 조금 더 효과적이고 가독성 좋은 방식으로 확인할 수 있는 모니터링 방식이 있을까?생각하며 찾아보던 중 ElasticSearch라는 기술을 찾게 되었다.
엘라스틱 서치를 사용하면 어떤 점이 편리할까?
우선 엘라스틱 서치에 대해 간단히 알고 싶다면 아래 포스팅을 먼저 읽어보기 바란다.
해당 방식으로 변경하게 되면 우리가 직접 ssh에 접근해서 로그를 일일이 살펴보는게 아닌 로그를 검색하고 시각화하여 분석할 수 있는 기능을 수행할 수 있다. 백문이 불여일견 로그를 logstash를 통해 수집하고 ElasticSearch를 통해 조회하며 Kibana로 시각화 하는 방식을 알아보자.
Docker로 logback, ElastiSearch, Kibana 실행하기
아래 내용은 Docker를 사용한 진행방식이기에 미리 Docker와 Docker Desktop을 설치하고 실행해야 한다.
1. ElasticSearch 실행
- 맥북 애플 실리콘(M1, M2)는 --platform linux/amd64 파라미터를 추가해야 한다.
- -d : daemon 환경으로 실행
- -p : 포트 설정(9200번)
- -e : 환경변수 설정
- 노드 및 ssl 적용 설정등을 다루고 있으나 지금은 가볍게 학습하므로 나중에 더 알아보려고 한다!
- --name : elasticsearch라는 이름 설정
docker run -d --name elasticsearch -p 9200:9200 -e "discovery.type=single-node" -e "xpack.security.enabled=false" -e "xpack.security.http.ssl.enabled=false" docker.elastic.co/elasticsearch/elasticsearch:8.10.0
2. LogStash 환경 설정
1. 의존성 추가
// https://mvnrepository.com/artifact/net.logstash.logback/logstash-logback-encoder
implementation 'net.logstash.logback:logstash-logback-encoder:7.4'
2. logback.xml 추가
logging에 대한 설명은 별도의 포스팅에서 하겠지만 아래 설정에서는 Logstash에 대한 appender와 root level의 내용만 숙지하고 있으면 된다.
localhost:5044로 목적지를 설정하여 로그를 전송하며 root level에서 info레벨 이상의 내용만 전달되도록 설정하였다.
<configuration>
<property name="LOG_FILE" value="application.log"/>
<!-- Logstash로 전송할 Appender -->
<appender name="LOGSTASH" class="net.logstash.logback.appender.LogstashTcpSocketAppender">
<destination>localhost:5044</destination>
<encoder class="net.logstash.logback.encoder.LogstashEncoder" />
</appender>
<!-- 콘솔 출력 -->
<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%d{yyyy-MM-dd HH:mm:ss} %-5level [%thread] %logger{36} - %msg%n</pattern>
</encoder>
</appender>
<!-- 파일 출력 -->
<appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>${LOG_FILE}</file>
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<fileNamePattern>application.%d{yyyy-MM-dd_HH-mm}.log.gz</fileNamePattern>
<maxHistory>5</maxHistory>
</rollingPolicy>
<encoder>
<pattern>%d{yyyy-MM-dd HH:mm:ss} %-5level [%thread] %logger{36} - %msg%n</pattern>
</encoder>
</appender>
<!-- Logger 설정 -->
<root level="info">
<appender-ref ref="CONSOLE" />
<appender-ref ref="FILE" />
<appender-ref ref="LOGSTASH" />
</root>
</configuration>
3. Logstash input/output 설정하기
- 5044번 포트로 json타입으로 인코딩되어 logstash 서버에 전달된다.
- Elasticsearch의 호스트로 로그가 전달되며 인덱스는 아래와 같은 양식으로 정렬된다. 이후 검색시 인덱스 양식에 맞춰서 검색을 할 수 있다.
input {
tcp {
port => 5044
codec => json
}
}
output {
elasticsearch {
hosts => ["http://elasticsearch:9200"]
index => "application-logs-%{+YYYY.MM.dd}"
}
}4. logstash 실행하기
명령어는 위에서 설명한 옵션과 동일하니 넘어가겠다.
5044번 포트와 9600번 포트를 사용하여 실행하고 해당 실행 컨테이너는 logstash란 이름을 갖는다.
docker run -d --name logstash -p 5044:5044 -p 9600:9600 -v .\logstash.conf:/usr/share/logstash/pipeline/logstash.conf docker.elastic.co/logstash/logstash:8.10.0
5. 컨테이너 간 통신을 위한 네트워크 설정
하나의 네트워크를 만들어서 같은 네트워크 그룹에서 통신할 수 있도록 설정해준다.
- docker network create [네트워크 명]
- docker network connect [네트워크 명] [컨테이너 이름]
docker network create elastic-network
docker network connect elastic-network elasticsearch
docker network connect elastic-network logstash
6. 실행 확인
- docker ps -a 를 사용해서 현재 실행중인 컨테이너의 상태를 확인할 수 있다.
만약 실행이 잘 안 된다면 docker logs [컨테이너명] 을 통해 실행시 출력된 로그와 에러가 발생한 원인등을 찾을 수 있다.
Sunro1994@macui-MacBookPro Documents % docker ps
CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES
c450a30522a9 kibana:8.10.1 "/bin/tini -- /usr/l…" 4 hours ago Up 3 seconds 0.0.0.0:5601->5601/tcp kibana
34fd706510d5 docker.elastic.co/logstash/logstash:8.10.0 "/usr/local/bin/dock…" 4 hours ago Up 19 seconds 0.0.0.0:5044->5044/tcp, 0.0.0.0:9600->9600/tcp logstash
4ec54244e1e3 docker.elastic.co/elasticsearch/elasticsearch:8.10.0 "/bin/tini -- /usr/l…" 4 hours ago Up 23 seconds 0.0.0.0:9200->9200/tcp, 9300/tcp elasticsearch
모두 잘 작동되고 있다면
http://localhost:9200/_cat/indices?v
이 주소를 입력하여 진입해보자. 만약 내용이 아무것도 없다면 프로젝트를 다시 실행시키고 요청을 보내보기 바란다.
아래 내용은 프로젝트가 실행되고 출력된 로그가 전송되어 나타나는 내용이다.
이번엔 우리가 지정한 index 양식을 사용해서 테스트해보자. postman 또는 talend를 사용해서 api 호출을 날려보자.
http://localhost:9200/application-logs-*/_search
다음과 같은 결과를 확인할 수 있다. 오늘 테스트한 결과밖에 없지만 와일드카드*을 사용해서 모든 로그 결과를 출력해주는 질의를 요청으로 보내고 받아온 결과 값이다.
{
"took": 4,
"timed_out": false,
"_shards":{
"total": 1,
"successful": 1,
"skipped": 0,
"failed": 0
},
"hits":{
"total":{
"value": 10000,
"relation": "gte"
},
"max_score": 1.0,
"hits":[
{"_index": "application-logs-2025.02.08", "_id": "T4VV5ZQBF9ACK-pR_Rx-", "_score": 1.0, "_source":{"@version": "1",…},
{"_index": "application-logs-2025.02.08", "_id": "S4VV5ZQBF9ACK-pR_Rxq", "_score": 1.0, "_source":{"@version": "1",…},
{"_index": "application-logs-2025.02.08", "_id": "SYVV5ZQBF9ACK-pR_Rxp", "_score": 1.0, "_source":{"@version": "1",…},
{"_index": "application-logs-2025.02.08", "_id": "UYVV5ZQBF9ACK-pR_RyB", "_score": 1.0, "_source":{"@version": "1",…},
{"_index": "application-logs-2025.02.08", "_id": "RYVV5ZQBF9ACK-pR_Rxh", "_score": 1.0, "_source":{"@version": "1",…},
{"_index": "application-logs-2025.02.08", "_id": "TIVV5ZQBF9ACK-pR_Rxq", "_score": 1.0, "_source":{"@version": "1",…},
{"_index": "application-logs-2025.02.08", "_id": "RIVV5ZQBF9ACK-pR_RxY", "_score": 1.0, "_source":{"@version": "1",…},
{"_index": "application-logs-2025.02.08", "_id": "RoVV5ZQBF9ACK-pR_Rxi", "_score": 1.0, "_source":{"@version": "1",…},
{"_index": "application-logs-2025.02.08", "_id": "SIVV5ZQBF9ACK-pR_Rxi", "_score": 1.0, "_source":{"@version": "1",…},
{"_index": "application-logs-2025.02.08", "_id": "SoVV5ZQBF9ACK-pR_Rxq", "_score": 1.0, "_source":{"@version": "1",…}
]
}
}위 결과에 대한 해석을 아래에 정리해두었다.
1. 검색 정보
• took: 4: 검색 수행 시간이 4ms.
• timed_out: false: 타임아웃 없이 정상적으로 검색 완료.
• _shards: 검색을 수행한 샤드 정보 (1개의 샤드에서 검색, 실패 없음).
• hits.total.value: 10000, relation: "gte": 검색 결과가 10,000건 이상(gte = greater than or equal) 존재.
2. 로그 내용
• 검색된 로그는 HTTP 요청 관련 헤더 정보가 포함되어 있음.
• "tags": ["_jsonparsefailure"]가 있는 것으로 보아 JSON 파싱 실패가 발생한 로그들이 저장된 것
• 주요 헤더 값:
• "Upgrade-Insecure-Requests: 1": 보안되지 않은 HTTP 요청을 HTTPS로 업그레이드할 것을 요청.
• "Cookie": JWT 인증 토큰과 JSESSIONID 포함 (보안상 노출 주의).
• "User-Agent": Chrome 133.0.0.0을 사용한 macOS 기반 브라우저 요청.
• "Accept-Language": 한국어(ko-KR), 영어(en-US) 등의 언어 설정 포함.
• "Connection: keep-alive": 지속적인 연결 유지 요청.
• "Host: localhost:5044": 로컬 서버(포트 5044)에서 발생한 요청.
이렇게 가져오기만 하면 사용할 이유가 없지만 다양한 옵션을 requestBody로 보내서 옵션에 맞는 데이터를 뽑아올 수 있다.
요청 url은 동일하나 POST방식으로 request body에 이러한 json데이터를 추가해서 보내보자.
아래 쿼리는 aggregation 이라는 기능으로 집합으로 어떠한 정확한 키워드를 갖고 있는 것들을 가져오는 것이다. keyword가 붙어있는 필드는 정확한 문자열, 그 외의 것들은 문자를 포함하는 것들을 가져온다. 우리가 가져올 것은 log의 level에 따른 값이다.
{
"aggs": {
"log_level_aggreagations": {
"terms": {
"field": "level.keyword"
}
}
}
}
이러한 결과의 값으로 이전에 받아왔던 값 이외에 추가적으로 각 level별의 발생수를 확인할 수 있다.
{
"took": 33,
"timed_out": false,
"_shards": {
"total": 1,
"successful": 1,
"skipped": 0,
"failed": 0
},
"hits": {
"total": {
"value": 10000,
"relation": "gte"
},
"max_score": 1.0,
"hits": [
{
"_index": "application-logs-2025.02.08",
"_id": "T4VV5ZQBF9ACK-pR_Rx-",
"_score": 1.0,
"_source": {
"@version": "1",
"tags": [
"_jsonparsefailure"
],
"message": "Upgrade-Insecure-Requests: 1\r",
"@timestamp": "2025-02-08T11:33:25.347575583Z"
}
},
{
"_index": "application-logs-2025.02.08",
"_id": "S4VV5ZQBF9ACK-pR_Rxq",
"_score": 1.0,
"_source": {
"@version": "1",
"tags": [
"_jsonparsefailure"
],
"message": "Cookie: Authorization=Bearer%20eyJhbGciOiJIUzI1NiJ9.eyJzdWIiOiJ1c2VyIiwiYXV0aCI6IlVTRVIiLCJleHAiOjE3Mzg3NDQxMzAsImlhdCI6MTczODc0MDUzMH0.kNQQrURVHWBqXPhSIKcXSAlOvBLKsGTaa5uHNAbrQV4; JSESSIONID=109F8419A5EB813F0EC7F813C0F7B099\r",
"@timestamp": "2025-02-08T11:33:25.349952541Z"
}
},
{
"_index": "application-logs-2025.02.08",
"_id": "SYVV5ZQBF9ACK-pR_Rxp",
"_score": 1.0,
"_source": {
"@version": "1",
"tags": [
"_jsonparsefailure"
],
"message": "User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/133.0.0.0 Safari/537.36\r",
"@timestamp": "2025-02-08T11:33:25.347862625Z"
}
},
{
"_index": "application-logs-2025.02.08",
"_id": "UYVV5ZQBF9ACK-pR_RyB",
"_score": 1.0,
"_source": {
"@version": "1",
"tags": [
"_jsonparsefailure"
],
"message": "Accept-Language: ko-KR,ko;q=0.9,en-US;q=0.8,en;q=0.7\r",
"@timestamp": "2025-02-08T11:33:25.349697250Z"
}
},
{
"_index": "application-logs-2025.02.08",
"_id": "RYVV5ZQBF9ACK-pR_Rxh",
"_score": 1.0,
"_source": {
"@version": "1",
"tags": [
"_jsonparsefailure"
],
"message": "sec-ch-ua-mobile: ?0\r",
"@timestamp": "2025-02-08T11:33:25.347067416Z"
}
},
{
"_index": "application-logs-2025.02.08",
"_id": "TIVV5ZQBF9ACK-pR_Rxq",
"_score": 1.0,
"_source": {
"@version": "1",
"tags": [
"_jsonparsefailure"
],
"message": "Sec-Fetch-Site: none\r",
"@timestamp": "2025-02-08T11:33:25.348413833Z"
}
},
{
"_index": "application-logs-2025.02.08",
"_id": "RIVV5ZQBF9ACK-pR_RxY",
"_score": 1.0,
"_source": {
"@version": "1",
"tags": [
"_jsonparsefailure"
],
"message": "Accept-Encoding: gzip, deflate, br, zstd\r",
"@timestamp": "2025-02-08T11:33:25.349458625Z"
}
},
{
"_index": "application-logs-2025.02.08",
"_id": "RoVV5ZQBF9ACK-pR_Rxi",
"_score": 1.0,
"_source": {
"@version": "1",
"tags": [
"_jsonparsefailure"
],
"message": "Connection: keep-alive\r",
"@timestamp": "2025-02-08T11:33:25.346440125Z"
}
},
{
"_index": "application-logs-2025.02.08",
"_id": "SIVV5ZQBF9ACK-pR_Rxi",
"_score": 1.0,
"_source": {
"@version": "1",
"tags": [
"_jsonparsefailure"
],
"message": "Sec-Fetch-Mode: navigate\r",
"@timestamp": "2025-02-08T11:33:25.348639333Z"
}
},
{
"_index": "application-logs-2025.02.08",
"_id": "SoVV5ZQBF9ACK-pR_Rxq",
"_score": 1.0,
"_source": {
"@version": "1",
"tags": [
"_jsonparsefailure"
],
"message": "Host: localhost:5044\r",
"@timestamp": "2025-02-08T11:33:25.346087625Z"
}
}
]
},
"aggregations": {
"log_level_aggreagations": {
"doc_count_error_upper_bound": 0,
"sum_other_doc_count": 0,
"buckets": [
{
"key": "DEBUG",
"doc_count": 14980
},
{
"key": "TRACE",
"doc_count": 3813
},
{
"key": "INFO",
"doc_count": 55
},
{
"key": "WARN",
"doc_count": 2
}
]
}
}
}만약 hits된 값이 너무 방대하여 일정 기간만 알아보고 싶다면 다음과 같은 옵션을 추가해서 요청을 보낸다.
- gte :greater than or equal 로 현재 시각에서 1분전까지의 데이터를 수집하는 것이다.
- lt : lessthan 으로 현재 시각보다 이전의 데이터만 반환받도록 설정하는 것이다.
{
"query" :{
"range" :{
"@timestamp" :{
"gte" : "now-1m",
"lt" : "now"
}
}
},
"aggs": {
"log_level_aggreagations": {
"terms": {
"field": "level.keyword"
}
}
}
}
또한 hits된 값들을 보지않고 개수만 보고싶다면 아래 옵션을 추가해준다.
{
"size" : 0,
"query" :{
"range" :{
"@timestamp" :{
"gte" : "now-1m",
"lt" : "now"
}
}
},
"aggs": {
"log_level_aggreagations": {
"terms": {
"field": "level.keyword"
}
}
}
}결과값으로 다음과 같이 key값별 카운트수만 획득할 수 있다.
{
"took": 26,
"timed_out": false,
"_shards": {
"total": 1,
"successful": 1,
"skipped": 0,
"failed": 0
},
"hits": {
"total": {
"value": 256,
"relation": "eq"
},
"max_score": null,
"hits": [
]
},
"aggregations": {
"log_level_aggreagations": {
"doc_count_error_upper_bound": 0,
"sum_other_doc_count": 0,
"buckets": [
{
"key": "DEBUG",
"doc_count": 235
},
{
"key": "TRACE",
"doc_count": 21
}
]
}
}
}Kibana를 활용하여 분석 및 시각화하기
1. Kibana 실행하기
- 실행할 때 키바나도 맥북 애플 실리콘 (M1, M2 등) 실행시 --platform linux/amd64 파라미터를 추가해줘야 한다.
docker run -d --name kibana --network elastic-network -p 5601:5601 -e "ELASTICSEARCH_HOSTS=http://elasticsearch:9200" kibana:8.10.1- 추가한 뒤에는 docker ps로 상태를 확인해준다.
2. Kibana 보드에 접속
http://localhost:5601/app/home 으로 접근하면 키바나 메인 페이지에 접근가능하다.
다음과 같은 창이 뜨면 잘 성공한 것이다.
3. Dashboard 접속
좌측 햄버거를 눌러 메뉴를 열고 Discover 탭을 클릭해주면 다음과 같은 창이 뜬다.
키워드 별로 분석한 차트 및 그래프 제공
Log Info 중에 원하는 키워드만 모아보기
검색어를 통해 원하는 키워드를 검색 가능하다 Error들만 모아서 어떤 에러가 발생했는지 어떤 에러가 얼마나 발생했는지 빈도 측정도 가능하다!
이 뿐만 아니라 원하는 값들을 가져와 다양한 그림으로도 생성이 가능하다.
좌측 메뉴에서 Dashboard 를 클릭하고 create a dashboard - create visualization을 눌러준다.
좌측 탭에서 원하는 필드를 드래그해서 가져오면 자동으로 생성해주거나 우측 탭에서 직접 가로와 세로축을 설정해서 원하는 필드들을 가져와 시각화할 수 있다.
logger_name.keyword를 가져왔더니 이렇게 그래프를 생성해줬다. 아래 suggestions를 통해 다른 추천 그래프로도 바꿔서 볼 수 있다.
시각화한 데이터는 우측 상단의 Save를 통해 저장할 수 있다.
여러개의 시각화 데이터를 모아서 볼 수 있는 대시보드가 생성된다.
이외에도 공부하면 할 수록 많은 기능들이 있기에 공식문서와 참고자료를 통해 에러를 수집하거나, 인기 검색어, 방문 통계등을 테스트해보려고 한다. 앞으로 더 도움이 될 만한 기능이 있다면 포스팅해보겠다!