Reverse lookup for SMTP service

vCenter에서 발생한 Alarm이 SMTP 서버로 전달되지 않는 현상에 대해서 다뤄봅니다.
## vCenter 7.0

vCenter를 Upgrade 한 이후에 기존에 Alarm을 수신하던 SMTP 서버에 메시지가 전달되지 않는 이슈가 있었습니다.
vpxd.log를 확인해보니 다음과 같이 반복적으로 SMTP 서버를 설정할 때 실패하는 것을 확인할 수 있습니다.
## /var/log/vmware/vpxd/vpxd.log

2022-08-12T00:56:14.344Z info vpxd[57307] [Originator@6876 sub=MoOptionMgr opID=l5j8vjet-81817-auto-1r4w-h5:70018000-2] Setting SMTP relay server to [x.y.z.w]:25 2022-08-12T00:56:34.368Z error vpxd[57307] [Originator@6876 sub=MoOptionMgr opID=l5j8vjet-81817-auto-1r4w-h5:70018000-2] Cannot set SMTP relay server:Timeout configuring sendmail 2022-08-19T01:12:24.327Z info vpxd[27713] [Originator@6876 sub=MoOptionMgr opID=l5j8vjet-99135-auto-24ht-h5:70021702-e7] Setting SMTP relay server to [x.y.z.w]:587 2022-08-19T01:12:44.342Z error vpxd[27713] [Originator@6876 sub=MoOptionMgr opID=l5j8vjet-99135-auto-24ht-h5:70021702-e7] Cannot set SMTP relay server:Timeout configuring sendmail 2022-08-19T02:10:37.946Z info vpxd[45213] [Originator@6876 sub=MoOptionMgr opID=l5j8vjet-99793-auto-2503-h5:70022029-92] Setting SMTP relay server to [x.y.z.w]:25 2022-08-19T02:10:57.971Z error vpxd[45213] [Originator@6876 sub=MoOptionMgr opID=l5j8vjet-99793-auto-2503-h5:70022029-92] Cannot set SMTP relay server:Timeout configuring sendmail

vpxd.log를 보면, 더욱 명시적으로 Alarm이 발생할 때 SMTP 서버로 메일 발송이 실패한 것을 알 수 있었습니다.

Aug 12 01:16:00 localhost vpxd[27669]: Event [46316] [1-1] [2022-08-12T01:16:00.597329Z] [vim.event.AlarmEmailFailedEvent] [error] [] [xxx_Datacenter] [46316] [Alarm 'test' on xxx cannot send email to xxx@xxx.com]

 

또한, messages 로그를 봤을 때도 messages 로그에 대한 경험이 없던터라 특별한 메시지를 인지할 수 없었습니다.
## /var/log/vmware/messages

2022-08-19T02:10:38.034129+00:00 localhost systemd[1]: Stopping Sendmail Mail Transport Agent... 2022-08-19T02:10:38.044836+00:00 localhost systemd[1]: Stopped Sendmail Mail Transport Agent. 2022-08-19T02:10:38.047282+00:00 localhost systemd[1]: Starting Sendmail Mail Transport Agent... 2022-08-19T02:10:38.073381+00:00 localhost sendmail[35326]: My unqualified host name (localhost) unknown; sleeping for retry 2022-08-19T02:11:38.073919+00:00 localhost sendmail[35326]: unable to qualify my own domain name (localhost) -- using short name 2022-08-19T02:11:38.092853+00:00 localhost systemd[1]: Started Sendmail Mail Transport Agent.

우선, 분석을 시작하기 전에 vCenter에서 SMTP 서버로 알람을 보낼 때 어떠한 식으로 로그가 기록되는지를 파악하기 위해 다음 그림과 같이 환경 구성을 하고 테스트를 진행하였습니다.

고객 환경은 SMTP 서버를 Windows Server의 IIS에 구축했기 때문에 동일하게 Windows Server를 이용하였습니다.

다음과 같이 SMTP 서버 설정이 완료되고 나면, 테스트를 위해 SMTP 서버에서 모든 로그가 기록되도록 설정합니다.

SMTP 서버가 정상적으로 메시지를 수신하는지를 확인하기 위해 Client에서 Telnet을 이용하여 SMTP 서버에 접근한 후 몇 가지 메시지를 전송하여, SMTP 서버의 로그를 검증합니다.
아래에서 SMTP 서버 측 로그를 확인해보면, Client에서 테스트 한 값들이 기록된 것을 알 수 있습니다.
## Client 수행 명령

telnet set LocalECHO open 192.168.1.91 25 220 SMTP Microsoft ESMTP MAIL Service, Version: 8.5.9600.16384 ready at Fri, 2 Sep 2022 20:29:05 -0700 helo me 250 SMTP Hello [192.168.1.2] mail from:administrator@vsphere.local 250 2.1.0 administrator@vsphere.local....Sender OK Subject:This is a test 500 5.3.3 Unrecognized command Testing 500 5.3.3 Unrecognized command . 500 5.3.3 Unrecognized command

## SMTP 서버 로그

#Software: Microsoft Internet Information Services 8.5 #Version: 1.0 #Date: 2022-09-03 03:30:00 #Fields: date time c-ip cs-username s-sitename s-computername s-ip s-port cs-method cs-uri-stem cs-uri-query sc-status sc-win32-status sc-bytes cs-bytes time-taken cs-version cs-host cs(User-Agent) cs(Cookie) cs(Referer) 2022-09-03 03:30:11 192.168.1.2 me SMTPSVC1 SMTP 192.168.1.91 0 HELO - +me 250 0 30 7 0 SMTP - - - - 2022-09-03 03:31:52 192.168.1.2 me SMTPSVC1 SMTP 192.168.1.91 0 MAIL - +from:administrator@vsphere.local 250 0 52 37 0 SMTP - - - - 2022-09-03 03:32:24 192.168.1.2 me SMTPSVC1 SMTP 192.168.1.91 0 subject:this - +is+a+test 500 0 32 22 0 SMTP - - - - 2022-09-03 03:32:36 192.168.1.2 me SMTPSVC1 SMTP 192.168.1.91 0 testing - - 500 0 32 7 0 SMTP - - - - 2022-09-03 03:32:40 192.168.1.2 me SMTPSVC1 SMTP 192.168.1.91 0 . - - 500 0 32 1 0 SMTP - - - -

위와 같이 정상적으로 SMTP 서버가 동작하도록 환경을 구성한 후에 vCenter에 SMTP 서버를 다음과 같이 등록합니다.

이 후, vCenter에 테스트 용도의 Alarm을 등록하고 테스트 목적으로 Alarm을 발생시켜 어떤 로그가 기록되는지 살펴봅니다.

정상적인 경우, vCenter에 SMTP 서버를 등록할 때 오류 없이 "Setting SMTP relay server" 메시지로 완료가 됩니다.
## /var/log/vmware/vpxd/vpxd.log

2022-09-02T22:31:16.071Z info vpxd[63355] [Originator@6876 sub=MoOptionMgr opID=l7hnm84k-33045-auto-pi4-h5:70014737-a9] Invoking callbacks for key mail.smtp.server, pre commit 2022-09-02T22:31:16.074Z info vpxd[63355] [Originator@6876 sub=MoOptionMgr opID=l7hnm84k-33045-auto-pi4-h5:70014737-a9] Invoking callbacks for key mail.smtp.server, post commit 2022-09-02T22:31:16.074Z info vpxd[63355] [Originator@6876 sub=MoOptionMgr opID=l7hnm84k-33045-auto-pi4-h5:70014737-a9] Setting SMTP relay server to [ad01.contoso.com]:25

정상적인 경우 vCenter에서 Alarm이 발생하면 sendmail 서비스를 통해 SMTP 서버로 전송되는 것을 확인할 수 있습니다.
## /var/log/vmware/messages

2022-09-02T22:34:43.432291+00:00 vc01 sendmail[57205]: 282MXsvN057205: from=<administrator@vsphere.local>, size=1250, class=0, nrcpts=1, msgid=<202209022233.282MXsie057200@vc01.contoso.com>, proto=ESMTPS, daemon=MTA, relay=vc01.contoso.com [127.0.0.1] 2022-09-02T22:34:43.432983+00:00 vc01 sendmail[57210]: 282MXs8b057210: from=<administrator@vsphere.local>, size=1104, class=0, nrcpts=1, msgid=<202209022233.282MXsGg057209@vc01.contoso.com>, proto=ESMTPS, daemon=MTA, relay=vc01.contoso.com [127.0.0.1] 2022-09-02T22:34:43.433199+00:00 vc01 sendmail[57210]: 282MXs8b057210: to=<administrator@vsphere.local>, delay=00:00:00, mailer=relay, pri=31104, dsn=4.4.3, stat=queued 2022-09-02T22:34:43.440573+00:00 vc01 sendmail[57209]: 282MXsGg057209: to=administrator@vsphere.local, ctladdr=administrator@vsphere.local (0/0), delay=00:00:49, xdelay=00:00:49, mailer=relay, pri=30885, relay=[127.0.0.1] [127.0.0.1], dsn=2.0.0, stat=Sent (282MXs8b057210 Message accepted for delivery) 2022-09-02T22:34:43.443086+00:00 vc01 sendmail[57200]: 282MXsie057200: to=administrator@contoso.com, ctladdr=administrator@vsphere.local (0/0), delay=00:00:49, xdelay=00:00:49, mailer=relay, pri=31031, relay=[127.0.0.1] [127.0.0.1], dsn=2.0.0, stat=Sent (282MXsvN057205 Message accepted for delivery) 2022-09-02T22:35:04.691298+00:00 vc01 sendmail[57847]: 282MXsvN057205: to=<administrator@contoso.com>, delay=00:00:21, xdelay=00:00:21, mailer=relay, pri=121250, relay=ad01.contoso.com. [192.168.1.2], dsn=5.7.1, stat=User unknown 2022-09-02T22:35:04.733554+00:00 vc01 sendmail[57847]: 282MXsvN057205: 282MZ4vM057847: DSN: User unknown 2022-09-02T22:35:04.736079+00:00 vc01 sendmail[57847]: 282MZ4vM057847: to=<administrator@vsphere.local>, delay=00:00:00, mailer=relay, pri=32538, dsn=4.4.3, stat=queued

해당 시점에 SMTP 서버 로그를 확인해봐도 정상적으로 메시지가 수신되었음을 알 수 있습니다.
## SMTP 서버 로그

#Software: Microsoft Internet Information Services 8.5 #Version: 1.0 #Date: 2022-09-02 22:05:23 #Fields: date time c-ip cs-username s-sitename s-computername s-ip s-port cs-method cs-uri-stem cs-uri-query sc-status sc-win32-status sc-bytes cs-bytes time-taken cs-version cs-host cs(User-Agent) cs(Cookie) cs(Referer) 2022-09-02 22:35:04 192.168.1.3 vc01.contoso.com SMTPSVC1 AD01 192.168.1.2 0 EHLO - +vc01.contoso.com 250 0 192 21 0 SMTP - - - - 2022-09-02 22:35:04 192.168.1.3 vc01.contoso.com SMTPSVC1 AD01 192.168.1.2 0 MAIL - +From:<administrator@vsphere.local> 250 0 52 49 0 SMTP - - - - 2022-09-02 22:35:04 192.168.1.3 vc01.contoso.com SMTPSVC1 AD01 192.168.1.2 0 RCPT - +To:<administrator@contoso.com> 550 0 57 35 0 SMTP - - - - 2022-09-02 22:35:04 192.168.1.3 vc01.contoso.com SMTPSVC1 AD01 192.168.1.2 0 DATA - - 554 0 0 4 0 SMTP - - - - 2022-09-02 22:35:04 192.168.1.3 vc01.contoso.com SMTPSVC1 AD01 192.168.1.2 0 QUIT - vc01.contoso.com 240 21297 65 4 0 SMTP - - - -

이제 정상적인 상황에서 동작할 때 어떻게 로그가 기록되는지를 확인했기 때문에, 왜 정상적이지 않은 상황에서 SMTP 서버 등록 시도 시 "Cannot set SMTP relay server:Timeout configuring sendmail" 메시지가 기록되는지를 확인해야 합니다.

Research 결과, 해당 메시지는 vCenter에 등록한 SMTP 서버에 대해 Reserve Lookup이 시간 내에 마무리되지 않는 경우 발생할 수 있는 것으로 파악되었습니다.

그렇다면, 실제로 vCenter에 SMTP 서버를 등록할 때 Reverse Lookup을 하는 것이 맞는지 확인이 필요합니다.
테스트를 위해 vCenter에서 SMTP 서버로 ad01.contoso.com을 등록할 때 vCenter 로그와 Network Packet을 통해 확인해보겠습니다.

vpxd 로그에서는 ad01.contoso.com으로 SMTP 서버가 정상적으로 등록되는 것을 확인할 수 있습니다.
## /var/log/vmware/vpxd/vpxd.log

root@vcsa01 [ /var/log/vmware/vpxd ]# tail -f vpxd.log | grep -i "SMTP" 2022-09-22T17:33:02.286Z info vpxd[34834] [Originator@6876 sub=MoOptionMgr opID=l846fgba-43030-auto-x7h-h5:70018609-1c] Invoking callbacks for key mail.smtp.server, pre commit 2022-09-22T17:33:02.287Z info vpxd[34834] [Originator@6876 sub=MoOptionMgr opID=l846fgba-43030-auto-x7h-h5:70018609-1c] Invoking callbacks for key mail.smtp.server, post commit 2022-09-22T17:33:02.287Z info vpxd[34834] [Originator@6876 sub=MoOptionMgr opID=l846fgba-43030-auto-x7h-h5:70018609-1c] Setting SMTP relay server to [ad01.contoso.com]:25

정상적인 경우, vCenter에서 ad01.contoso.com의 주소인 192.168.1.3에 대해 Reserve Lookup을 수행하는 것을 확인할 수 있고, 이에 대한 PTR Record를 DNS 서버가 정상적으로 반환해주는 것 또한 볼 수 있습니다.
## Network Packets

2022-09-22 17:33:02.338698 192.168.1.3 192.168.1.2 DNS 84 Standard query 0x7a06 PTR 3.1.168.192.in-addr.arpa 2022-09-22 17:33:02.339164 192.168.1.2 192.168.1.3 DNS 116 Standard query response 0x7a06 PTR 3.1.168.192.in-addr.arpa PTR vcsa01.contoso.com

이제, 실제로 vCenter에서 Reverse Lookup이 잘 되는지를 vCenter에서 확인하는 방법을 살펴보겠습니다.
이전에는 nslookup 도구만을 알고 있었는데 dig라는 도구가 있어 이를 통해 Forward Lookup 및 Reverse Lookup을 테스트 해볼 수 있습니다.

정상적으로 값이 Return 되는 경우 ANSWER SECTION 밑에 올바른 A 또는 PTR Record가 확인되어야 하며, 주석처리가 되어 있지 않아야 합니다.(;; 문자가 없어야 합니다.)
dig 옵션에서 +noedns의 경우는 DNS 서버가 Windows Server에 설치되어 있는 경우 필요할 수 있습니다.
## Forward Lookup

root@vcsa01 [ ~ ]# dig +noedns ad01.contoso.com ; <<>> DiG 9.16.27 <<>> +noedns ad01.contoso.com ;; global options: +cmd ;; Got answer: ;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 41846 ;; flags: qr aa rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 0 ;; QUESTION SECTION: ;ad01.contoso.com. IN A ;; ANSWER SECTION: ad01.contoso.com. 3600 IN A 192.168.1.2 ;; Query time: 4 msec ;; SERVER: 127.0.0.1#53(127.0.0.1) ;; WHEN: Tue Oct 25 22:07:13 UTC 2022 ;; MSG SIZE rcvd: 50

## Reverse Lookup

root@vcsa01 [ ~ ]# dig +noedns -x 192.168.1.2 ; <<>> DiG 9.16.27 <<>> +noedns -x 192.168.1.2 ;; global options: +cmd ;; Got answer: ;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 5574 ;; flags: qr aa rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 0 ;; QUESTION SECTION: ;2.1.168.192.in-addr.arpa. IN PTR ;; ANSWER SECTION: 2.1.168.192.in-addr.arpa. 1200 IN PTR ad01.contoso.com. ;; Query time: 0 msec ;; SERVER: 127.0.0.1#53(127.0.0.1) ;; WHEN: Tue Oct 25 22:07:40 UTC 2022 ;; MSG SIZE rcvd: 72

위 내용을 토대로 문제가 있는 vCenter를 확인해 본 결과, vCenter가 바라보고 있던 DNS 서버의 주소가 실제 DNS 서버 주소가 아닌 Default Gateway 주소였고 이로 인하여 해당 주소로 Reverse Lookup을 시도할 때 Timeout 시간 내에 완료되지 못했던 것입니다.

문제 해결을 위해서 Default Gateway 주소 대신 실제 DNS 서버 구축 후 vCenter에서 바라보는 DNS 서버 주소를 실제 DNS 서버로 변경한 후 테스트를 하여, 정상적으로 SMTP 서버가 등록되는 것을 확인할 수 있었습니다.

결국, vCenter 구축 시 가장 중요한 요소 중 하나인 Forward/Reverse Lookup을 위한 DNS 서버의 부재로 인해서 SMTP 서버 등록이 실패하였고, 이로 인하여 Alert 발생 시 sendmail 서비스를 통한 메시지 발송이 실패한 것입니다.