[DNS] BIND가 받은 쿼리 정보를 원격 서버의 rsyslogd로 전송하기

요약
- 배경
  - 온프레미스 인프라
  - Rocky Linux 9, BIND 9.16.23, rsyslogd 8.2102.0-113.el9_2
  - 로그를 보내는 도착지 주소는 LB
- 절차
  - 원격 서버
    - rsyslog에서 로그를 수신할 포트 열어 주기
  - Cache DNS 서버
    - rsyslog에서 로깅 설정 추가
    - named 로그 세팅
    - 필요에 따라, rsyslog가 보낼 수 있는 쿼리의 제한 수량을 조정
배경
- 타 부서의 요청으로, 내가 관리하는 캐시 DNS 서버에서 BIND 로그를 로그스태시 서버로 쏘게 할 일이 생겼다. 받은 정보는 로그스태시 서버 앞 단에 있는 LB의 IP 주소와 사용 포트(UDP 5063)이다.
- 내가 시스템 관리자이므로 모든 서버에 대한 접속은 자유롭게 가능함.

절차

원격 서버 - logstash-01/02

루트 권한으로 /etc/rsyslog.conf를 열고, 아래 주석을 확인한다.

...

# Provides UDP syslog reception
# for parameters see http://www.rsyslog.com/doc/imudp.html
#module(load="imudp") # needs to be done just once
#input(type="imudp" port="514")

# Provides TCP syslog reception
# for parameters see http://www.rsyslog.com/doc/imtcp.html
#module(load="imtcp") # needs to be done just once
#input(type="imtcp" port="514")

...

원하는 프로토콜과 포트에 맞추어, 두 코드 블럭 중 한 곳의 주석을 풀어고 포트를 지정한다.

...

# Provides UDP syslog reception
# for parameters see http://www.rsyslog.com/doc/imudp.html
module(load="imudp") # needs to be done just once
input(type="imudp" port="5063")

...

`systemctl restart rsyslogd`로 재기동 후, 아래와 같이 포트 개방 여부를 확인한다.
```
$ netstat -unlp | grep 5063
udp        0      0 0.0.0.0:5063   0.0.0.0:*   1777459/java
udp6       0      0 :::5063        :::*        1792701/rsyslogd
```
자바도 열린 걸 볼 수 있는데, 저게 로그스태시더라. /usr/share/logstash/jdk/bin/java가 도는 것이다.

캐시 DNS 서버 - cdns-01/02

named 설정을 고치기 전에, 여기서도 rsyslog 설정을 손대야 한다. 이 서버는 /etc/rsyslog.conf에 손을 대는 대신 /etc/rsyslog.d/bind-log.conf를 생성해 두고 아래 구문을 추가했다.
```
local0.*        @192.168.0.5:5063
```
- local0: 여분의 로그 메시지를 위해 남은 local0~7 중 하나. 기존에 local0을 써 두었다면 다른 거 쓰면 될 거 같다. 사실 여기까지만 이해했고, 정확히 이 부분에 어느 녀석들이 들어가는지는 좀더 봐야 한다..
- 192.168.0.5: 로그스태시 LB의 IP

마찬가지로 루트 권한으로 /etc/named.conf를 열고, 로깅 세팅을 아래와 같이 해 준다. named.d 디렉토리 안에 별도의 .conf 파일 하나 만들고 해 줘도 좋다. queries_rsyslog 채널의 syslog 항목에 위에서 입력한 local0가 들어가는 것을 확인하라.

// syslog 쿼리 로그 보내는 세팅만 하고 싶을 때
logging {
        channel queries_rsyslog {
                syslog local0;
                print-time yes;
                print-category yes;
                print-severity yes;
                severity info;
        };

        category queries { queries_rsyslog; };
};

// 그 외에 로컬에 쌓는 로그도 같이 추가하고 싶을 때
logging {
        channel default_log {
                file "/var/named/log/default.log" versions 50 size 20m;
                print-time yes;
                print-severity yes;
                print-category yes;
                severity info;
        };

        channel queries_log {
                file "/var/named/log/queries.log" versions 50 size 20m;
                print-time yes;
                print-category yes;
                print-severity yes;
                severity info;
        };

        channel query_errors_log {
                file "/var/named/log/query_errors.log" versions 50 size 20m;
                print-time yes;
                print-category yes;
                print-severity yes;
                severity info;
        };

        channel queries_rsyslog {
                syslog local0;
                print-time yes;
                print-category yes;
                print-severity yes;
                severity info;
        };

        category default { default_log; };
        category queries { queries_log; queries_rsyslog; };
        category query-errors { query_errors_log; };
        category lame-servers { null; };
};

마지막으로, 캐시 DNS 측의 rsyslog가 보낼 수 있는 메시지의 최대 수를 조절한다. 사례는 아래에 적는다.

...

#### MODULES ####

...

module(load="imjournal" 
       RateLimit.Interval="30"      # 30초 안에 보낼 수 있는 메시지 수를
       RateLimit.Burst="20000"      # 2만 개로 지정한다.
       StateFile="imjournal.state")
       
...

마쳤으면 rsyslogd와 named를 차례로 재기동해 주자. 그 다음, 모니터링 도구를 사용해서 확인하면 된다.
주의: named는 `named-checkconf` 명령으로 우선 오류 없는지 확인해 주자. 그리고 로그 남기는 건 reload만 해서는 시작되지 않더라. 그래서 이중화 된 다른 한 서버가 정상적으로 도는 거 확인한 상태에서 restart를 해 주어야 한다.

이슈 사례 - 시간 당 송신 가능한 메시지 최대 수 초과로 인한 송신 실패

캐시 DNS 서버에서 tcpdump를 사용하여 로그스태시로 가는 udp 5063 통신 패킷을 확인하던 도중 발견했다. 이 캐시 DNS 서버들은 분당 수천 개의 DNS 쿼리를 받아들이기 때문에 실시간으로 rsyslog가 쏘는 메시지 양도 그만큼 되어야 하는데, 10분 간격으로 메시지 쏘기를 멈추더니 5~10분 간 아무런 패킷이 잡히질 않았다.

...
Dec 28 16:47:18 cdns-01 rsyslogd[1020665]: imjournal: 16464 messages lost due to rate-limiting (20000 allowed within 600 seconds)
Dec 28 16:57:19 cdns-01 rsyslogd[1020665]: imjournal: 14487 messages lost due to rate-limiting (20000 allowed within 600 seconds)
Dec 28 17:07:20 cdns-01 rsyslogd[1020665]: imjournal: 24646 messages lost due to rate-limiting (20000 allowed within 600 seconds)
Dec 28 17:17:21 cdns-01 rsyslogd[1020665]: imjournal: 18538 messages lost due to rate-limiting (20000 allowed within 600 seconds)
Dec 28 17:27:22 cdns-01 rsyslogd[1020665]: imjournal: 15630 messages lost due to rate-limiting (20000 allowed within 600 seconds)
Dec 28 17:37:23 cdns-01 rsyslogd[1020665]: imjournal: 18411 messages lost due to rate-limiting (20000 allowed within 600 seconds)
Dec 28 17:47:24 cdns-01 rsyslogd[1020665]: imjournal: 17545 messages lost due to rate-limiting (20000 allowed within 600 seconds)
Dec 28 17:57:25 cdns-01 rsyslogd[1020665]: imjournal: 15574 messages lost due to rate-limiting (20000 allowed within 600 seconds)
Dec 28 18:07:26 cdns-01 rsyslogd[1020665]: imjournal: 25922 messages lost due to rate-limiting (20000 allowed within 600 seconds)
Dec 28 18:17:27 cdns-01 rsyslogd[1020665]: imjournal: 19361 messages lost due to rate-limiting (20000 allowed within 600 seconds)
Dec 28 18:27:28 cdns-01 rsyslogd[1020665]: imjournal: 18518 messages lost due to rate-limiting (20000 allowed within 600 seconds)
...

공식 문서를 확인해 보니, 600초(10분) 당 2만 개의 메시지를 보낼 수 있도록 하는 게 기본 설정이다.(아래 관련 웹사이트 참조) 이 부분을 위에서 /etc/rsyslog.conf를 수정하여 바꾸어준 것이고.

한 가지 더 공유할 것은, Interval을 600초 그대로 두고 Burst만 100만 이렇게 올리면 적용이 제대로 안 된다는 것이다. 실제로 각각 600, 1000000으로 설정한 결과 아래와 같이 로그가 남았다.
2024.01.02 추가: RateLimit.Burst의 최대 값은 65535이다. 나랑 비슷한 문제를 겪은 사람이 레드햇 포탈에 보여서 링크 올린다. https://access.redhat.com/solutions/5185431

...
Dec 29 00:08:43 cdns-01 rsyslogd[1105947]: imjournal: 38299 messages lost due to rate-limiting (50000 allowed within 600 seconds)
Dec 29 00:18:44 cdns-01 rsyslogd[1105947]: imjournal: 34645 messages lost due to rate-limiting (50000 allowed within 600 seconds)
Dec 29 00:28:45 cdns-01 rsyslogd[1105947]: imjournal: 33048 messages lost due to rate-limiting (50000 allowed within 600 seconds)
Dec 29 00:38:46 cdns-01 rsyslogd[1105947]: imjournal: 33978 messages lost due to rate-limiting (50000 allowed within 600 seconds)
Dec 29 00:48:47 cdns-01 rsyslogd[1105947]: imjournal: 32122 messages lost due to rate-limiting (50000 allowed within 600 seconds)
Dec 29 00:58:48 cdns-01 rsyslogd[1105947]: imjournal: 31290 messages lost due to rate-limiting (50000 allowed within 600 seconds)
Dec 29 01:08:49 cdns-01 rsyslogd[1105947]: imjournal: 39145 messages lost due to rate-limiting (50000 allowed within 600 seconds)
Dec 29 01:18:50 cdns-01 rsyslogd[1105947]: imjournal: 31488 messages lost due to rate-limiting (50000 allowed within 600 seconds)
...

그래서 위에서 설정한 것처럼, 30초 당 2만 개로 한 것이다. 실제로 각 캐시 DNS 서버가 보통 30초 당 받는 쿼리의 양이 5천 개가 좀 안 되는 수준이었고, 서버 하나가 죽는 것 및 쿼리 폭증을 감안해서 30초 당 2만으로 잡았다. 아래에 실제로 캐시 DNS 서버의 모니터링 결과를 공유한다.
캐시 DNS가 받는 A 쿼리
동 시간대에 캐시 DNS가 네트워크 인터페이스를 타고 밖으로 보낸 비트 수.
초록색 - 600초 당 2만 개 메시지 송신 제한이 있음을 모른 채 송신을 시작한 시점.
빨강 - 600초 당 100만 개로 설정한 시점. 일단 크게 잡았고 00시~02시의 쿼리 유입도 처리할 수 있을 줄 알았지만, 상술한 대로 5만 개가 한계였다.
파랑 - 최종 값인 30초 당 2만 개로 수정한 시점
위 스크린샷에서 28일 오후 ~ 29일 새벽까지를 확대한 것. 저 뚝뚝 떨어지는 순간들이 설정 미스로 인해 메시지가 안 갔던 기간들이다.

관련 웹사이트
- bind 로깅 관련 - https://kb.isc.org/docs/aa-01526
- rsyslog imjournal 설정 관련 - https://www.rsyslog.com/doc/v8-stable/configuration/modules/imjournal.html

code and chord

[DNS] BIND가 받은 쿼리 정보를 원격 서버의 rsyslogd로 전송하기

티스토리툴바