Discourse의 일시적인 '다운' 발생 - 로그에서 더 많은 정보를 얻는 방법

안녕하세요,

오늘 아침에 몇몇 사용자가 우리의 Discourse 인스턴스가 다운되어 있는 것 같다고 알려주었습니다. 하지만 제가 확인했을 때는 이미 다시 올라와 있었습니다. 모니터링 스택에서 여러 번 ‘오프라인’ 상태인 것처럼 보이는 현상을 확인할 수 있었지만, launcher logs app을 통해 로그를 확인해 보니, 로그가 날짜와 시간 없이 출력되고 있는 것 같습니다 (:confused:) 그리고 아마도 가장 최근 것만 표시되는 것으로 보이는데, Discourse 인스턴스를 구성하는 여러 컴포넌트(nginx, redis, psql 등)가 있기 때문에 로그의 출처를 구분하기가 정말 어렵습니다.

더 정확한 로그를 얻을 수 있는 방법이 있거나, 더 좋다면 loki / promtail로 수집할 수 있도록 로그를 외부로 노출할 수 있는 방법이 있을까요?

모든 차트는 제가 이 모니터링을 추가한 시점부터 ‘최근 5일’ 데이터를 보여주고 있습니다. 모니터링에서 확인할 수 있는 내용은 다음과 같습니다:

컨테이너 가동 시간:

discourse-prometheus 플러그인에서, Discourse가 응답하지 않는 시간에 해당하는 것으로 추정되는 많은 '공백’이 있습니다. 이는 오늘 아침에 사용자들로부터 알림을 받은 시점과 일치합니다:

이것이 ‘작은’ 시간 창이 아니며, 사용자에게는 분명히 허용할 수 없는 수준임을 명확히 하기 위해 최근 6시간을 확대했습니다:

./launcher logs app으로 추출한 로그

root@vmi1229594:/var/discourse# ./launcher logs app
x86_64 arch detected.
run-parts: executing /etc/runit/1.d/00-ensure-links
run-parts: executing /etc/runit/1.d/00-fix-var-logs
run-parts: executing /etc/runit/1.d/01-cleanup-web-pids
run-parts: executing /etc/runit/1.d/anacron
run-parts: executing /etc/runit/1.d/cleanup-pids
Cleaning stale PID files
run-parts: executing /etc/runit/1.d/copy-env
Started runsvdir, PID is 41
ok: run: redis: (pid 53) 0s
ok: run: postgres: (pid 55) 0s
supervisor pid: 51 unicorn pid: 87
Shutting Down
run-parts: executing /etc/runit/3.d/01-nginx
ok: down: nginx: 0s, normally up
run-parts: executing /etc/runit/3.d/02-unicorn
(51) exiting
ok: down: unicorn: 1s, normally up
run-parts: executing /etc/runit/3.d/10-redis
ok: down: redis: 0s, normally up
run-parts: executing /etc/runit/3.d/99-postgres
ok: down: postgres: 0s, normally up
ok: down: nginx: 5s, normally up
ok: down: postgres: 0s, normally up
ok: down: redis: 3s, normally up
ok: down: unicorn: 5s, normally up
ok: down: cron: 1s, normally up
ok: down: rsyslog: 1s, normally up
run-parts: executing /etc/runit/1.d/00-ensure-links
run-parts: executing /etc/runit/1.d/00-fix-var-logs
run-parts: executing /etc/runit/1.d/01-cleanup-web-pids
run-parts: executing /etc/runit/1.d/anacron
run-parts: executing /etc/runit/1.d/cleanup-pids
Cleaning stale PID files
run-parts: executing /etc/runit/1.d/copy-env
Started runsvdir, PID is 35
ok: run: redis: (pid 49) 0s
ok: run: postgres: (pid 48) 0s
supervisor pid: 43 unicorn pid: 81
(43) Reopening logs
(43) Reopening logs
Shutting Down
run-parts: executing /etc/runit/3.d/01-nginx
ok: down: nginx: 0s, normally up
run-parts: executing /etc/runit/3.d/02-unicorn
(43) exiting
ok: down: unicorn: 0s, normally up
run-parts: executing /etc/runit/3.d/10-redis
ok: down: redis: 0s, normally up
run-parts: executing /etc/runit/3.d/99-postgres
timeout: run: postgres: (pid 48) 34983s, want down, got TERM
run-parts: /etc/runit/3.d/99-postgres exited with return code 1
ok: down: nginx: 10s, normally up
ok: down: redis: 8s, normally up
ok: down: unicorn: 10s, normally up
ok: down: cron: 0s, normally up
ok: down: rsyslog: 0s, normally up
kill: run: postgres: (pid 48) 34991s, want down, got TERM
run-parts: executing /etc/runit/1.d/00-ensure-links
run-parts: executing /etc/runit/1.d/00-fix-var-logs
run-parts: executing /etc/runit/1.d/01-cleanup-web-pids
run-parts: executing /etc/runit/1.d/anacron
run-parts: executing /etc/runit/1.d/cleanup-pids
Cleaning stale PID files
run-parts: executing /etc/runit/1.d/copy-env
Started runsvdir, PID is 35
fail: redis: runsv not running
ok: run: redis: (pid 53) 1s
ok: run: postgres: (pid 48) 1s
supervisor pid: 79 unicorn pid: 83
(79) Reopening logs
Shutting Down
run-parts: executing /etc/runit/3.d/01-nginx
ok: down: nginx: 0s, normally up
run-parts: executing /etc/runit/3.d/02-unicorn
(79) exiting
ok: down: unicorn: 0s, normally up
run-parts: executing /etc/runit/3.d/10-redis
ok: down: redis: 0s, normally up
run-parts: executing /etc/runit/3.d/99-postgres
ok: down: postgres: 0s, normally up
ok: down: nginx: 5s, normally up
ok: down: postgres: 0s, normally up
ok: down: redis: 3s, normally up
ok: down: unicorn: 5s, normally up
ok: down: cron: 1s, normally up
ok: down: rsyslog: 1s, normally up
run-parts: executing /etc/runit/1.d/00-ensure-links
run-parts: executing /etc/runit/1.d/00-fix-var-logs
run-parts: executing /etc/runit/1.d/01-cleanup-web-pids
run-parts: executing /etc/runit/1.d/anacron
run-parts: executing /etc/runit/1.d/cleanup-pids
Cleaning stale PID files
run-parts: executing /etc/runit/1.d/copy-env
Started runsvdir, PID is 34
ok: run: redis: (pid 49) 0s
ok: run: postgres: (pid 44) 0s
supervisor pid: 41 unicorn pid: 80
(41) Reopening logs
(41) Reopening logs
(41) Reopening logs
(41) Reopening logs
(41) Reopening logs

명확성을 위해, 로그가 컨테이너의 /var/logs에 있을 수 있다는 점은 알고 있습니다. 하지만 제 경험상 nginx, postgres, redis에서는 이상한 현상이 전혀 나타나지 않습니다.

nginx에는 토픽에서 온 사용자 배지 JSON에 대한 요청 범람(그리고 이에 따른 제한)에 대한 로그가 많이 있습니다.
postgresql은 단순히 실행된 쿼리를 반환합니다(아마도? 매우 긴 쿼리들이죠).
redis는 정상적으로 데이터를 정기적으로 저장하는 것만 표시합니다.

messages 파일에서는 다음과 같이 그렇게 안심되지 않는 메시지를 볼 수 있습니다:

[....]
May  1 07:46:50 vmi1229594-app logrotate: ALERT exited abnormally with [1]
May  2 07:56:45 vmi1229594-app logrotate: ALERT exited abnormally with [1]
May  2 23:20:57 vmi1229594-app rsyslogd: [origin software="rsyslogd" swVersion="8.2102.0" x-pid="49" x-info="https://www.rsyslog.com"] start
May  3 07:35:27 vmi1229594-app logrotate: ALERT exited abnormally with [1]
May  4 07:38:08 vmi1229594-app logrotate: ALERT exited abnormally with [1]
May  5 07:40:32 vmi1229594-app logrotate: ALERT exited abnormally with [1]
May  6 08:01:40 vmi1229594-app logrotate: ALERT exited abnormally with [1]
May  7 07:38:45 vmi1229594-app logrotate: ALERT exited abnormally with [1]
May  8 07:37:31 vmi1229594-app logrotate: ALERT exited abnormally with [1]
May  9 07:35:21 vmi1229594-app logrotate: ALERT exited abnormally with [1]
May 10 07:53:08 vmi1229594-app logrotate: ALERT exited abnormally with [1]
May 11 07:43:09 vmi1229594-app logrotate: ALERT exited abnormally with [1]
May 12 07:56:06 vmi1229594-app logrotate: ALERT exited abnormally with [1]
May 12 15:15:30 vmi1229594-app rsyslogd: [origin software="rsyslogd" swVersion="8.2102.0" x-pid="48" x-info="https://www.rsyslog.com"] start
May 12 15:59:28 vmi1229594-app rsyslogd: [origin software="rsyslogd" swVersion="8.2102.0" x-pid="41" x-info="https://www.rsyslog.com"] start
May 12 17:20:56 vmi1229594-app rsyslogd: [origin software="rsyslogd" swVersion="8.2102.0" x-pid="43" x-info="https://www.rsyslog.com"] start
May 12 18:55:45 vmi1229594-app rsyslogd: [origin software="rsyslogd" swVersion="8.2102.0" x-pid="44" x-info="https://www.rsyslog.com"] start
May 12 19:13:36 vmi1229594-app rsyslogd: [origin software="rsyslogd" swVersion="8.2102.0" x-pid="42" x-info="https://www.rsyslog.com"] start
May 12 21:04:24 vmi1229594-app rsyslogd: [origin software="rsyslogd" swVersion="8.2102.0" x-pid="44" x-info="https://www.rsyslog.com"] start
May 12 22:15:46 vmi1229594-app rsyslogd: [origin software="rsyslogd" swVersion="8.2102.0" x-pid="47" x-info="https://www.rsyslog.com"] start
May 13 07:43:36 vmi1229594-app logrotate: ALERT exited abnormally with [1]
May 13 20:07:44 vmi1229594-app rsyslogd: [origin software="rsyslogd" swVersion="8.2102.0" x-pid="49" x-info="https://www.rsyslog.com"] start
May 14 07:46:22 vmi1229594-app logrotate: ALERT exited abnormally with [1]
May 14 22:05:18 vmi1229594-app rsyslogd: [origin software="rsyslogd" swVersion="8.2102.0" x-pid="42" x-info="https://www.rsyslog.com"] start
May 14 22:16:04 vmi1229594-app rsyslogd: [origin software="rsyslogd" swVersion="8.2102.0" x-pid="44" x-info="https://www.rsyslog.com"] start
May 14 22:43:03 vmi1229594-app rsyslogd: [origin software="rsyslogd" swVersion="8.2102.0" x-pid="49" x-info="https://www.rsyslog.com"] start
May 14 23:00:09 discourse_app rsyslogd: [origin software="rsyslogd" swVersion="8.2102.0" x-pid="49" x-info="https://www.rsyslog.com"] start
May 15 00:22:59 discourse_app rsyslogd: [origin software="rsyslogd" swVersion="8.2102.0" x-pid="45" x-info="https://www.rsyslog.com"] start
May 15 00:56:17 discourse_app logrotate: ALERT exited abnormally with [1]
May 15 10:06:13 discourse_app rsyslogd: [origin software="rsyslogd" swVersion="8.2102.0" x-pid="43" x-info="https://www.rsyslog.com"] start
May 16 07:55:46 discourse_app logrotate: ALERT exited abnormally with [1]
May 16 08:40:17 discourse_app rsyslogd: [origin software="rsyslogd" swVersion="8.2102.0" x-pid="45" x-info="https://www.rsyslog.com"] start
May 17 07:58:24 discourse_app logrotate: ALERT exited abnormally with [1]
May 18 07:55:33 discourse_app logrotate: ALERT exited abnormally with [1]
May 19 07:48:14 discourse_app logrotate: ALERT exited abnormally with [1]
May 20 08:03:44 discourse_app logrotate: ALERT exited abnormally with [1]
May 21 07:40:15 discourse_app logrotate: ALERT exited abnormally with [1]
May 22 07:44:59 discourse_app logrotate: ALERT exited abnormally with [1]

그리고 syslog에는 이와 같은 내용이 아주 많이 있습니다:

[....]
May 20 05:17:01 discourse_app CRON[1001623]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
May 20 05:25:01 discourse_app CRON[1002727]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
May 20 05:35:01 discourse_app CRON[1004446]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
May 20 05:45:01 discourse_app CRON[1006215]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
May 20 05:55:01 discourse_app CRON[1007612]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
May 20 06:05:01 discourse_app CRON[1009398]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
May 20 06:15:01 discourse_app CRON[1011120]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
May 20 06:17:01 discourse_app CRON[1011400]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
May 20 06:25:01 discourse_app CRON[1012535]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
May 20 06:25:01 discourse_app CRON[1012537]: (root) CMD (test -x /usr/sbin/anacron || ( cd / && run-parts --report /etc/cron.daily ))
May 20 06:35:01 discourse_app CRON[1014375]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
May 20 06:45:01 discourse_app CRON[1016178]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
May 20 06:55:01 discourse_app CRON[1017757]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
May 20 07:05:02 discourse_app CRON[1019550]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
May 20 07:15:01 discourse_app CRON[1021373]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
May 20 07:17:01 discourse_app CRON[1021667]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
May 20 07:25:01 discourse_app CRON[1022811]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
May 20 07:30:01 discourse_app CRON[1023931]: (root) CMD (/usr/sbin/anacron -s >/dev/null)
May 20 07:30:01 discourse_app anacron[1023933]: Anacron 2.3 started on 2023-05-20
May 20 07:30:01 discourse_app anacron[1023933]: Will run job `cron.daily' in 5 min.
May 20 07:30:01 discourse_app anacron[1023933]: Jobs will be executed sequentially
May 20 07:35:01 discourse_app anacron[1023933]: Job `cron.daily' started
May 20 07:35:01 discourse_app anacron[1024646]: Updated timestamp for job `cron.daily' to 2023-05-20
May 20 07:35:01 discourse_app CRON[1024649]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
May 20 07:45:01 discourse_app CRON[1026439]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
May 20 07:55:01 discourse_app CRON[1027921]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
May 20 08:03:44 discourse_app logrotate: ALERT exited abnormally with [1]
May 20 08:03:44 discourse_app anacron[1023933]: Job `cron.daily' terminated (exit status: 1) (mailing output)
May 20 08:03:44 discourse_app anacron[1023933]: Can't find sendmail at /usr/sbin/sendmail, not mailing output
May 20 08:03:44 discourse_app anacron[1023933]: Normal exit (1 job run)
May 20 08:05:01 discourse_app CRON[1029819]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
May 20 08:15:01 discourse_app CRON[1031611]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
May 20 08:17:01 discourse_app CRON[1031886]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
[....]

주된 질문: Discourse 컨텍스트에서 이 메시지들은 무엇을 의미하며, 더 많은 정보를 얻는 방법은 무엇인가요?
부연 설명: 이러한 로그를 외부로 가져와 중앙 집중식으로 관리할 수 있는 방법이 있나요?

launcher logs는 단순히 docker logs의 래퍼이며, -t 옵션을 사용하여 타임스탬프를 표시할 수 있습니다. 아래 명령어를 사용하면 타임스탬프가 포함된 로그를 확인할 수 있습니다:

sudo docker logs -t --tail 1000 app

두 파일에서 인용한 줄들은 Discourse와 관련이 없습니다. 해당 줄 중 일부에 discourse_app가 포함되어 있다고 해서 Discourse Docker 설정과 관련이 있다고 생각하셨다면, 이는 호스트명(hostname)일 뿐 Discourse Docker 설정과 관련이 있음을 나타내는 라벨이 아님을 유념하시기 바랍니다.

해당 로그를 보면 logrotate가 실패하고 있는 것으로 보이지만, 로컬 메일 설정을 설치하지 않는 한 상세한 오류를 확인할 수 없습니다. Debian 계열 운영체제를 가정할 때 apt install default-mta를 실행한 후, 다음 오류가 발생할 때까지 기다렸다가 mail 명령어로 로컬 메일을 확인해 보세요.

또한 디스크 사용 가능 공간, 메모리 부하 등 서버 상태를 점검해 보시는 것도 좋습니다. 극심한 메모리 부하(예: 페이지ング)가 반복적인 응답 불가 현상의 원인으로 추정됩니다.

개인적으로 dmesg 출력의 관련 부분을 살펴볼 것입니다. 하나의 가능성은 방화벽(UFW) 이벤트가 트래픽을 차단하고 있다는 것입니다.

사실, 연결 상태에 대한 일부 로깅이 유용할 수 있습니다. 이는 머신 자체가 도달할 수 없는 경우와 discourse가 응답하지 않는 경우를 구별하는 데 도움이 됩니다.

CDN 구성을 사용하고 있다면 그것도 확인해 보세요.

Leonardo님, 감사합니다. postfix(ubuntu 기본값)를 추가했습니다. 어떤 결과가 나올지 지켜보겠습니다.

다른 모니터링 도구를 사용하고 있지만, 솔직히 메모리나 디스크 공간에 문제가 보이지 않습니다.

Swap은 사용 가능한 8GB 중 2GB 정도를 유지하고 있습니다. VM에는 30GB의 RAM이 사용 가능합니다. 저에게 정말 이상한 점은 discourse가 메모리를 얼마나 많이 사용하는지입니다 → Discourse Docker HW reserved/used (CPU, RAM, Disk) and how to manage it

저는 dmesg에 익숙하지 않지만, 볼 수 있는 것은 여러 다른 IP 주소에서 온 수많은 [UFW BLOCK] 메시지입니다. 하지만 너무 많아 패턴이 있는지 파악하기 어렵습니다.

예를 들어:

[Tue May 23 09:32:21 2023] [UFW BLOCK] IN=eth0 OUT= MAC=MAC_ADDRESS_A SRC=IP_ADDRESS_A DST=SERVER_IP LEN=40 TOS=0x00 PREC=0x00 TTL=248 ID=54321 PROTO=TCP SPT=34909 DPT=40930 WINDOW=65535 RES=0x00 SYN URGP=0
[Tue May 23 09:32:22 2023] [UFW BLOCK] IN=eth0 OUT= MAC=MAC_ADDRESS_A SRC=IP_ADDRESS_A DST=SERVER_IP LEN=40 TOS=0x00 PREC=0x00 TTL=248 ID=54321 PROTO=TCP SPT=43093 DPT=40942 WINDOW=65535 RES=0x00 SYN URGP=0
[Tue May 23 09:32:29 2023] [UFW BLOCK] IN=eth0 OUT= MAC=MAC_ADDRESS_A SRC=IP_ADDRESS_B DST=SERVER_IP LEN=40 TOS=0x00 PREC=0x00 TTL=249 ID=57687 PROTO=TCP SPT=42801 DPT=3350 WINDOW=1024 RES=0x00 SYN URGP=0
[Tue May 23 09:32:35 2023] [UFW BLOCK] IN=eth0 OUT= MAC=MAC_ADDRESS_A SRC=IP_ADDRESS_C DST=SERVER_IP LEN=40 TOS=0x00 PREC=0x00 TTL=54 ID=61548 PROTO=TCP SPT=21721 DPT=23 WINDOW=43065 RES=0x00 SYN URGP=0
[Tue May 23 09:32:59 2023] [UFW BLOCK] IN=eth0 OUT= MAC=MAC_ADDRESS_A SRC=IP_ADDRESS_D DST=SERVER_IP LEN=44 TOS=0x00 PREC=0x00 TTL=114 ID=0 PROTO=TCP SPT=50293 DPT=1023 WINDOW=29200 RES=0x00 SYN URGP=0

식별자는 익명화되었지만, 동일하다면 동일한 참조를 사용합니다.

Cloudflare을 사용하지만 SSL/도메인 제공자 및 캐시 용도로만 사용합니다. 불행히도 그 부분은 제가 담당하지 않으므로, 그 방향으로 더 깊이 파기 전에 다른 가능성을 먼저 다뤄보고 싶습니다.

도메인을 가리키는 blackbox exporter를 통한 업타임 체크를 추가하여 다운타임이 감지되는지 확인했습니다.

저도 비슷한 상황입니다. 우리가 신경 써야 할 것은 포트 80과 443에 대한 것뿐인 것 같습니다. 다음을 시도해 보세요:
dmesg | egrep "DPT=80 |DPT=443 " | egrep PROTO=TCP
아마도 아무것도 표시되지 않을 가능성이 높습니다. 하지만 표시된다면, 이는 방화벽이 discourse로의 접근을 차단하고 있다는 것을 의미할 수 있습니다.

네, 제 경우에도 아무것도 없습니다.

어쨌든 모니터링을 보면 컨테이너는 항상 실행 중이고 홈페이지도 정상적인 것처럼 보이지만, 실제로는 앱이 요청에 응답하지 않는 상태입니다. 차트에 noData 구간이 있는 것이 이를 뒷받침한다고 솔직히 말씀드릴 수 있습니다. 이는 홈페이지(우리의 경우 카테고리 페이지)는 Cloudflare에 캐시되어 있어 로드될 수 있지만, 이후 탐색은 단순히 타임아웃 요청으로 이어진다는 것을 의미합니다.

최근 24시간

/latest 페이지는 내용이 거의 끊임없이 변하기 때문에 캐시되지 않을 가능성이 높으므로, 해당 페이지에 새로운 업타임 체크를 추가해 보겠습니다.

CloudFlare는 페이지를 캐시해서는 안 됩니다. Discourse는 웹사이트가 아니라 애플리케이션입니다.

이러한 장애는 약 1시간 이상 지속되며 자정 전후에 집중되는 경향이 있습니다. 이는 여러분이 관찰한 내용과 일치합니까?