logger command doesn't calculate facility and severity level correctly

## ESXi 7.0

 

ESXi Host에 내장된 도구인 logger 명령어를 이용하여, Syslog 메시지를 생성할 때 Syslog RFC에 기술되어 있는 Facility와 Severity Level이 잘못 표현되는 문제가 있어 이에 대해 설명합니다.

 

[구성 환경]

ESXi Host ## ESXi Host에는 아래 Remote Syslog Server로 Log를 전송하는 설정이 구성되어 있음

CentOS Syslog Server

 

[문제 증상]

ESXi Host에서 logger 명령어를 이용하여, 테스트로 Syslog 메시지 생성 시 Remote에 있는 Syslog Server에 올바른 Facility와 Severity Level로 기록되어 있지 않음

예를 들어, logger 명령어로는 다음과 같이 Facility는 Daemon으로 Severity Level은 Debug로 설정했으나 Syslog 서버에서는 Facility는 User로 Severity Level은 Crit으로 기록이 되는 현상입니다.

 

[분석 내용]

## Syslog는 결국 Syslog RFC에 맞게 동작하는지를 확인해야 하는데, ESXi Host가 원격지에 있는 Syslog Server로 네트워크를 통해 메시지를 전달하므로 Syslog Server 쪽에서 Packet 수집이 필요합니다.

1. ESXi Host에서 다음과 같은 logger 명령어를 실행합니다.

[root@mgmtesxi01:~] logger -t hwalangx -p daemon.debug "test debug"

 

2. 해당 명령어 실행 시에 ESXi Host에서는 어떻게 로그가 기록되는지 확인합니다. 

아래 로그를 보시면 아시겠지만, Facility와 Severity Level 관련된 내용을 확인할 수가 없습니다. 이는 logger 명령어에서 Facility와 Severity Level을 전달했더라도 syslog 서비스에서 어떻게 기록하느냐에 따라 달라질 수 있습니다.

 

## /var/run/log/syslog.log

2022-11-21T17:11:01.698Z hwalangx[837796]: test debug

 

3. 그렇다면, Remote Syslog Server에는 어떻게 기록되는지 확인해보겠습니다. 테스트 환경에서는 ESXi Host와 마찬가지로 Facility와 Severity Level을 표현해주지 못하고 있습니다.

## /var/log/messages

Nov 21 17:11:01 mgmtesxi01 hwalangx[837796]: test debug

 

실 고객사 환경의 Syslog Server에서는 level이 crit 라는 태그가 추가되어 있습니다. 즉, logger 명령어에서는 damon.debug 라는 옵션을 이용하여 Facility와 Severity Level을 명시했으나 실제 Syslog Server에 기록되는 로그에서는 다른 값으로 표현되고 있습니다.

2022-11-28T08:16:45+00:00 xxx xxx [level=crit] hwalangx[6659166]: test debug

 

4.  실제로 ESXi Host에서 Remote Syslog Server로 전달될 때 어떻게 Facility와 Severy Level 값이 기재되어 있는지를 파악하기 위해 Packet을 확인합니다.

테스트 환경에서는 ESXi Host에서 logger 명령어를 이용하여 Syslog 로그를 생성하면, CentOS로 보내도록 되어 있습니다.

아래, Packet에서 중요하게 봐야 하는 부분은 Syslog RFC format 중 PRI 부분입니다. 

참고로 RFC 문서(https://www.ietf.org/rfc/rfc3164.txt)에서 PRI 부분을 확인해보면 다음과 같이 기술되어 있습니다. "The Facilities and Severities of the messages are numerically coded with decimal values."

즉, PRI는 Facility와 Severity 값이 합쳐져서 10진수로 Syslog Header에 표현된다는 것입니다.

 

 

본 예제의 경우에는 PRI 부분이 <10> 으로 표현되어 있습니다.  10은 십진수이기 때문에 이를 이진수로 표현하면, 1010 이 됩니다. 

18        2022-11-21 22:11:02.347646        192.168.1.11        192.168.1.210        RSH        135        Client -> Server data Frame 18: 135 bytes on wire (1080 bits), 135 bytes captured (1080 bits)Ethernet II, Src: VMware_b6:07:48 (00:50:56:b6:07:48), Dst: VMware_84:7c:5b (00:50:56:84:7c:5b)Internet Protocol Version 4, Src: 192.168.1.11, Dst: 192.168.1.210Transmission Control Protocol, Src Port: 12671, Dst Port: 514, Seq: 112, Ack: 1, Len: 69Remote Shell    Client -> Server Data: 3c31303e323032322d31312d32315431373a31313a30312e3639385a206d676d74657378… 0000   00 50 56 84 7c 5b 00 50 56 b6 07 48 08 00 45 02   .PV.|[.PV..H..E.0010   00 79 9b ed 40 00 40 06 1a 62 c0 a8 01 0b c0 a8   .y..@.@..b......0020   01 d2 31 7f 02 02 68 6e 74 0f f0 a1 d7 87 80 18   ..1...hnt.......0030   00 82 07 0a 00 00 01 01 08 0a 38 01 0a d7 ff ff   ..........8.....0040   17 c4 3c 31 30 3e 32 30 32 32 2d 31 31 2d 32 31   ..<10>2022-11-210050   54 31 37 3a 31 31 3a 30 31 2e 36 39 38 5a 20 6d   T17:11:01.698Z m0060   67 6d 74 65 73 78 69 30 31 20 68 77 61 6c 61 6e   gmtesxi01 hwalan0070   67 78 5b 38 33 37 37 39 36 5d 3a 20 74 65 73 74   gx[837796]: test0080   20 64 65 62 75 67 0a                               debug.

 

PRI는 총 8bit로 구성되어 있으며, 앞 5bit는 Facility를 위해서, 마지막 3bit는 Severity를 표현하기 위해 사용됩니다.

즉 십진수로 10인 경우 이진수로 1010이며, 1은 Facility, 010은 Severity를 나타냅니다.

이 값을 가지고 RFC에 정의되어 있는 Facility와 Severity Level 값을 비교해보면 Facility는 "user-level messages"를 가리키고, Severity Level은 "Critical: critical conditions"를 나타내는 것을 알 수 있습니다.

 

5. 그렇다면, 아래와 같은 logger 명령어는 원래 PRI 값이 어떻게 표현되어야 했을까요?

[root@mgmtesxi01:~] logger -t hwalangx -p daemon.debug "test debug"

 

사용자는 Facility를 daemon, Severity Level을 debug로 명시하였고, RFC에서 정의한 값을 보면 daemon은 3이고, Severity Level은 7이어야 합니다.

즉, daemon.debug 값은 이진수로 00011111 로 표현할 수 있으며 십진수로는 31이 됩니다. 정상적인 상황이었다면 <PRI> 값이 <31>로 Packet에서 확인할 수 있었어야 합니다.

 

6. 원래 31로 표현되어야 하는데, Packet에서 보면 10으로 표현된 증상은 어디서 유발되었을까요?

RFC를 보면, 다음과 같이 Facility와 Severity 값을 가지고 어떻게 PRI를 계산하는지가 나와 있습니다. 간단히 설명드리면 Facility 값에는 8을 곱하고, 그 값에 Severity 값을 더하면 PRI 값을 표현할 수 있습니다.

The Priority value is calculated by first multiplying the Facility number by 8 and then adding the numerical value of the Severity.

For example, a kernel message (Facility=0) with a Severity of Emergency (Severity=0) would have a Priority value of 0.

Also, a "local use 4" message (Facility=20) with a Severity of Notice (Severity=5) would have a Priority value of 165.

In the PRI part of a syslog message, these values would be placed between the angle brackets as <0> and <165> respectively.

The only time a value of "0" will follow the "<" is for the Priority value of "0".

Otherwise, leading "0"s MUST NOT be used.

 

문제는, logger 명령어를 통해 syslog 서비스에 메시지를 전달할 때 이를 Parsing 해주는 모듈이 신규로 추가되었는데요.

해당 모듈에서 Input을 받을 때, 이미 8을 곱한 값으로 가정하고 Severity 값만 더하는 코드 상 문제가 있었습니다.

이 문제 때문에 원래 3 * 8 + 7 = 31로 표현되야 하는 PRI 값이, 3 + 7 = 10으로 표현되어 Facility는 User로 Severitys는 Crit로 해석되게 됩니다.

 

해당 문제는 내부적으로 Fix가 되었으나, 아직 Patch로 Release가 되지 않아 내년 정도 되어서야 Fix가 포함된 Patch가 나올 것으로 예상됩니다.

 

[참고 자료]

https://www.ietf.org/rfc/rfc3164.txt