도대체 왜요 왜요 왜?
저번에 자동 배포 프로세스를 수정, 배포 후 애플리케이션 실행까지 잘 되는것을 확인했습니다. 하지만 갑자기 배포 후 애플리케이션 구동이 안되었고 해당 원인을 찾는 과정과 해결 내용을 담아보았습니다. 
깃허브 액션 워크 플로우는 잘 동작 하였나?
•
yml 파일이 제대로 되지 않았는데도 이 단계에서 패스가 되는 경우가 있습니다.
•
때문에 여기서는 동작이 잘 되었나 만 확인합니다.
코드 디플로이는 EC2 에 제대로 배포를 했는가?
•
이 또한 애플리케이션의 실행 성공을 보장하지는 못합니다.
•
일단 EC2 에 배포는 성공 하였음을 알 수 있습니다.
여기까지 잘 작동이 되었는데, iterm 의 먹통?
코드 디플로이의 배포 성공까지 확인했는데 스웨거의 응답요청이 너무 오래 걸리거나 iterm 이 먹통이 되어버린다면 애플리케이션 실행과정에서 문제가 생겼음을 의심할 수 있습니다. 먹통이 되어버린 관계로 저는 EC2 를 재부팅 한 뒤에 다시 접속하여 로그를 살펴보았습니다.
EC2 인스턴스의 시작 프로세스와 관련이 있을까?
cloud-init.log 와 cloud-init-output.log 는 EC2 인스턴스가 시작될 때 수행되는 초기화 작업과 관련된 로그를 포함하고 있습니다. 문제가 EC2 인스턴스의 시작 프로세스와 관련되어 있는지 찾아보았습니다.
cloud-init.log
2023-10-11 16:42:17,370 - helpers.py[DEBUG]: config-power-state-change already ran (freq=once-per-instance)
2023-10-11 16:42:17,370 - handlers.py[DEBUG]: finish: modules-final/config-power-state-change: SUCCESS: config-power-state-change previously ran
2023-10-11 16:42:17,370 - main.py[DEBUG]: Ran 20 modules with 0 failures
2023-10-11 16:42:17,371 - atomic_helper.py[DEBUG]: Atomically writing to file /var/lib/cloud/data/status.json (via temporary file /var/lib/cloud/data/tmpxj14w30l) - w: [644] 542 bytes/chars
2023-10-11 16:42:17,371 - atomic_helper.py[DEBUG]: Atomically writing to file /var/lib/cloud/data/result.json (via temporary file /var/lib/cloud/data/tmp9x53pok8) - w: [644] 64 bytes/chars
2023-10-11 16:42:17,371 - util.py[DEBUG]: Creating symbolic link from '/run/cloud-init/result.json' => '../../var/lib/cloud/data/result.json'
2023-10-11 16:42:17,371 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False)
2023-10-11 16:42:17,371 - util.py[DEBUG]: Read 11 bytes from /proc/uptime
2023-10-11 16:42:17,372 - util.py[DEBUG]: cloud-init mode 'modules' took 0.287 seconds (0.28)
2023-10-11 16:42:17,372 - handlers.py[DEBUG]: finish: modules-final: SUCCESS: running modules for final
Plain Text
복사
cloud-init-output.log
[ec2-user@ip-172-31-10-248 log]$ sudo tail -f cloud-init-output.log
ci-info: +-------+-------------+---------+-----------+-------+
ci-info: | Route | Destination | Gateway | Interface | Flags |
ci-info: +-------+-------------+---------+-----------+-------+
ci-info: | 1 | fe80::/64 | :: | enX0 | U |
ci-info: | 3 | local | :: | enX0 | U |
ci-info: | 4 | multicast | :: | enX0 | U |
ci-info: +-------+-------------+---------+-----------+-------+
Cloud-init v. 22.2.2 running 'modules:config' at Wed, 11 Oct 2023 16:42:15 +0000. Up 12.95 seconds.
Cloud-init v. 22.2.2 running 'modules:final' at Wed, 11 Oct 2023 16:42:17 +0000. Up 14.06 seconds.
Cloud-init v. 22.2.2 finished at Wed, 11 Oct 2023 16:42:17 +0000. Datasource DataSourceEc2. Up 14.29 seconds
Plain Text
복사
두 로그에서 문제를 발견할 수 없었습니다. 일단 초기화와 시작면에서 문제가 없기에, 코드 디플로이가 정말 제 역할을 다 했는지 디플로이 로그를 확인했습니다.
deploy.log
Wed Oct 11 16:07:03 2023 > 현재 실행중인 애플리케이션이 없습니다
Wed Oct 11 16:07:04 2023 > /home/ec2-user/app/deploy/build/libs/demo-SPRINT2.jar 파일 복사
Wed Oct 11 16:07:04 2023 > /home/ec2-user/app/deploy/build/libs/demo-SPRINT2.jar 파일 실행
Wed Oct 11 16:07:04 2023 > 실행된 프로세스 아이디 입니다.
Plain Text
복사
•
애플리케이션을 구동 했지만 프로세스 아이디를 잡지 못하는 것에서 문제점을 발견했습니다.
•
이 경우 애플리케이션 로그를 확인해야 합니다.
application.log
2023-10-11T16:07:15.358Z INFO 14094 --- [ main] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Starting...
2023-10-11T16:07:16.392Z INFO 14094 --- [ main] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection com.mysql.cj.jdbc.ConnectionImpl@3effd4f3
2023-10-11T16:07:16.398Z INFO 14094 --- [ main] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Start completed.
2023-10-11T16:07:16.533Z INFO 14094 --- [ main] SQL dialect : HHH000400: Using dialect: org.hibernate.dialect.MySQLDialect
2023-10-11T16:07:20.909Z INFO 14094 --- [ main] o.h.e.t.j.p.i.JtaPlatformInitiator : HHH000490: Using JtaPlatform implementation: [org.hibernate.engine.transaction.jta.platform.internal.NoJtaPlatform]
2023-10-11T16:07:20.939Z INFO 14094 --- [ main] j.LocalContainerEntityManagerFactoryBean : Initialized JPA EntityManagerFactory for persistence unit 'default'
2023-10-11T16:27:49.474Z WARN 14094 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=4m15s14ms898µs324ns).
2023-10-11T16:28:30.854Z WARN 14094 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=55s682ms132µs760ns).
2023-10-11T16:37:46.044Z WARN 14094 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=1m20s144ms850µs639ns).
2023-10-11T16:38:29.474Z WARN 14094 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=49s224ms740µs603ns).
Plain Text
복사
로그를 보면 프로그램이 실행되다 만것을 확인할 수 있습니다.
CPU 사용률 확인
갑자기 치솟는 사용률도 모니터링에서 확인할 수 있었습니다.
무엇이 원인 이었나요?
저의 경우 실행에서 문제 였기 때문에 nginx 와 redis 를 다시 제대로 켠 뒤, 이를 확인하고 다시 이전에 실행한 워크 플로우를 다시 실행해보았습니다. 그 결과 제대로 실행이 되는 것을 확인했습니다.
냅다 자동배포를 하는 것의 위험성
자동배포를 하기 전에 서버의 상태를 한번 점검해야 합니다.
현재 EC2 가 상태 점검에 들어갔는가? 현재 CPU 와 리소스 상태는 어떠한가? 특정 프로그램이 많은 리소스를 잡아먹고 있지 않은가? 웹서버와 다른 서버들의 구동 상태는 어떠한가?이 외에 점검해야할 요소들을 꼼꼼히 점검한 후에 배포를 수행해야 합니다. 만약 저처럼 특정 브랜치의 이벤트를 기준으로 잡아 워크 플로우를 실행 할 경우 push 를 하기 전에 확인해봐야 합니다.