[문제 증상]
전체 ESXi Host의 패치 작업 이 후 한 대의 ESXi Host가 vCenter에서 지속적으로 연결 끊기는 현상
[구성 환경]
ESXi Hostname : abc.contoso.com
ESXi IP Address : 192.168.244.46
vCenter Hostname : vcsa01.contoso.com
vCenter IP Address : 192.168.113.17
[조치 내역]
1. DNS 에서 동일한 ESXi Host에 대해 2개의 A/PTR Record가 있어, 불필요한 Record 제거 요
[분석 내용]
1. vCenter와 ESXi Host간 연결 끊김 현상이 있는 경우 우선 vCenter의 vpxd.log 에서 "NO_RESPONSE" keyword로 검색
| # grep -i "NO_RESPONSE" vpxd.log 2023-06-03T00:06:32.483Z warning vpxd[63037] [Originator@6876 sub=MoHost opID=HostSync-host-37931-7f75b4b7] host [vim.HostSystem:host-37931,abc.contoso.com] connection state changed to NO_RESPONSE <snip> 2023-06-05T00:05:00.503Z warning vpxd[64705] [Originator@6876 sub=MoHost opID=HostSync-host-37931-73b9cd07] host [vim.HostSystem:host-37931,abc.contoso.com] connection state changed to NO_RESPONSE |
2. vCenter의 vpxd.log 에서 "NO_RESPONSE"를 확인한 후 기본적으로 아래 Keyword를 이용하여 추가 확인
## 다른 메시지 없음
DNS 관련 이슈
# grep "Failed to resolve address" vpxd-xxx.log | wc -l
성능 관련 이슈
# grep "too long" vpxd-xxx.log
3. ESXi Host의 hostd.log에서 알려진 메시지들이 있는지 확인
## 알려진 메시지 없음
cat hostd.all | grep "Memory checker" | grep "exceeds"
cat hostd.all | grep "IpmiIfcSdrReadRecordId: retry expired"
cat hostd.all | grep "ISSL routines:ssl3_read_bytes:sslv3 alert certificate expired"
4. Packet 수집을 통해 실제로 vCenter와 ESXi Host 간 Heartbeat Packet을 주기적으로 주고 받는지 확인
아래 아키텍처를 기준으로 양 단에서 UDP 902 포트를 기준으로 Packet 확인
## Packet은 10초 마다 정상적으로 송수신 되는 상황
## 해당 Packet이 6번 연속으로 vCenter에서 수신되지 않으면 vCenter는 해당 Host를 Not responding 상태로 생
## 만약, ESXi Host에서는 보냈으나 vCenter에서는 못 받은 경우 네트워크 환경에 따라 중간 Firewall 확인 필요
## 만약, ESXi Host에서 보내고 있지 않은 경우 hostd와 vpxd 서비스 재시작 후 증상이 동일한지 테스트, 재시작 후에도 문제가 동일한 경우 hostd.log와 vpxa.log 상세 분석 필요
## 만약, 특정 시점에만 문제가 있다면 해당 시점에 수행 중인 작업 이력 확인(백업 등)
# tcpdump -i eth0 src <ESXi IP Address> and dst <vCenter IP Address> and dst port 902
| root@vcsa01 [ ~ ]# tcpdump -i eth0 src 192.168.244.46 and dst 192.168.113.17 and dst port 902 tcpdump: verbose output suppressed, use -v or -vv for full protocol decode listening on eth0, link-type EN10MB (Ethernet), capture size 262144 bytes 05:39:53.669178 IP 192.168.244.46.32102 > vcsa01.contoso.com.ideafarm-door: UDP, length 334 05:40:03.672781 IP 192.168.244.46.25361 > vcsa01.contoso.com.ideafarm-door: UDP, length 334 <snip> |
# pktcap-uw --vmk <vCenter와 통신 가능한 vmkernel internface 번호> --dstip <vCenter IP Address> --dstudpport 902 --dir 2 -o - | tcpdump-uw -enr -
| [root@esxi:~] pktcap-uw --vmk vmk1 --dstip 192.168.113.17 --dstudpport 902 --dir 2 -o - | tcpdump-uw -enr - The name of the vmk is vmk1. The session filter destination IP address is 192.168.1.3. The session filter destination UDP port is 902. pktcap: The output file is -. pktcap: No server port specifed, select 50244 as the port. pktcap: Local CID 2. pktcap: Listen on port 50244. pktcap: Main thread: 470135012160. pktcap: Dump Thread: 470135547648. reading from file -, link-type EN10MB (Ethernet) pktcap: Recv Thread: 470136076032. pktcap: Accept... pktcap: Vsock connection from port 1034 cid 2. 05:56:54.873065 00:50:56:6c:8a:c9 > 00:0c:29:4b:d7:9a, ethertype IPv4 (0x0800), length 376: 192.168.244.46.39043 > 192.168.113.17.902: UDP, length 334 05:57:04.874846 00:50:56:6c:8a:c9 > 00:0c:29:4b:d7:9a, ethertype IPv4 (0x0800), length 376: 192.168.244.46.59856 > 192.168.113.17.902: UDP, length 334 <snip> |
5. vCenter의 vpxd.log에서 "NO_RESPONSE" 메시지가 기록되는 시점에 ESXi Host의 vpxa.log에서 다음과 같은 메시지 확인
/var/run/log
| 2023-06-05T00:14:40.950Z warning vpxa[2131759] [Originator@6876 sub=vmomi.soapStub[2] opID=lhtyiabt-672343-auto-eesa-h5:70103063-1e-02-6e3e9fc5-DvsHandleHostReconnect-35242b9-44] SOAP request returned HTTP failure; <<io_obj p:0x00000002e9c3ae28, h:12, <TCP '127.0.0.1 : 50235'>, <TCP '127.0.0.1 : 8307'>>, /sdk>, method: applyDvsList; code: 500(Internal Server Error) 2023-06-05T00:14:40.953Z info vpxa[2131744] [Originator@6876 sub=vpxLro opID=lhtyiabt-672343-auto-eesa-h5:70103063-1e-02-6e3e9fc5-SWI-d9a8163-7a] [VpxLRO] -- BEGIN lro-47 -- vpxa -- vpxapi.VpxaService.ConfigureDatastoreIORMOnHost -- 520c9a33-688c-70ac-5296-ff9ce183b5c8 2023-06-05T00:14:40.950Z error vpxa[2131759] [Originator@6876 sub=vpxaVmomi opID=lhtyiabt-672343-auto-eesa-h5:70103063-1e-02-6e3e9fc5-DvsHandleHostReconnect-35242b9-44] Got exception when invoking VMOMI method; <<last binding: <<TCP '127.0.0.1 : 50566'>, <TCP '127.0.0.1 : 8307'>>>, /sdk>, vim.dvs.HostDistributedVirtualSwitchManager.applyDvsList, N3Vim5Fault22DvsApplyOperationFault9ExceptionE(Fault cause: vim.fault.DvsApplyOperationFault 2023-06-05T00:14:40.957Z info vpxa[2131744] [Originator@6876 sub=vpxLro opID=lhtyiabt-672343-auto-eesa-h5:70103063-1e-02-6e3e9fc5-SWI-d9a8163-7a] [VpxLRO] -- FINISH lro-47 2023-06-05T00:14:40.956Z warning vpxa[2131759] [Originator@6876 sub=Vmomi opID=lhtyiabt-672343-auto-eesa-h5:70103063-1e-02-6e3e9fc5-DvsHandleHostReconnect-35242b9-44] VMOMI activation LRO failed; <<520c9a33-688c-70ac-5296-ff9ce183b5c8, <TCP '127.0.0.1 : 8089'>, <TCP '127.0.0.1 : 42224'>>, hostDvsManager, vim.dvs.HostDistributedVirtualSwitchManager.applyDvsList>, N3Vim5Fault22DvsApplyOperationFault9ExceptionE(Fault cause: vim.fault.DvsApplyOperationFault 2023-06-05T00:14:40.960Z info vpxa[2131759] [Originator@6876 sub=Default opID=lhtyiabt-672343-auto-eesa-h5:70103063-1e-02-6e3e9fc5-DvsHandleHostReconnect-35242b9-44] [VpxLRO] -- ERROR lro-45 -- hostDvsManager -- vim.dvs.HostDistributedVirtualSwitchManager.applyDvsList: vim.fault.DvsApplyOperationFault: --> Result: --> (vim.fault.DvsApplyOperationFault) { --> faultCause = (vmodl.MethodFault) null, --> faultMessage = <unset>, --> objectFault = (vim.fault.DvsApplyOperationFault.FaultOnObject) [ --> (vim.fault.DvsApplyOperationFault.FaultOnObject) { --> objectId = "50 0e a7 35 d2 34 b2 ba-a1 78 06 8f bd 06 2f 31", --> type = "vim.DistributedVirtualSwitch", --> fault = (vim.fault.ResourceInUse) { --> faultCause = (vmodl.MethodFault) null, --> faultMessage = <unset>, --> type = "vim.DistributedVirtualSwitch", --> name = "50 0e a7 35 d2 34 b2 ba-a1 78 06 8f bd 06 2f 31" --> msg = "The resource '50 0e a7 35 d2 34 b2 ba-a1 78 06 8f bd 06 2f 31' is in use." --> } --> } --> ] --> msg = "Received SOAP response fault from [<<io_obj p:0x00000002e9c3ae28, h:12, <TCP '127.0.0.1 : 50235'>, <TCP '127.0.0.1 : 8307'>>, /sdk>]: applyDvsList --> fault.DvsApplyOperationFault.summary" --> } --> Args: --> --> Arg uuid: --> (string) [] |
6. vpxa.log에 기록된 목적지 port가 8307 이므로 해당 port로 제공하는 서비스 확인
## 8307 port를 통해 서비스를 제공하는 프로세스는 rhttpproxy
| # grep 8307 localcli_network_ip_connection_list.txt tcp 0 0 127.0.0.1:25596 127.0.0.1:8307 TIME_WAIT 0 tcp 0 0 127.0.0.1:61708 127.0.0.1:8307 TIME_WAIT 0 tcp 0 0 127.0.0.1:8307 127.0.0.1:60737 ESTABLISHED 2099758 newreno hostd-IO tcp 0 0 127.0.0.1:60737 127.0.0.1:8307 ESTABLISHED 2101368 newreno rhttpproxy-work tcp 0 0 127.0.0.1:8307 127.0.0.1:48880 ESTABLISHED 2099758 newreno hostd-IO tcp 0 0 127.0.0.1:48880 127.0.0.1:8307 ESTABLISHED 2130527 newreno rhttpproxy-work tcp 0 0 127.0.0.1:8307 127.0.0.1:17652 ESTABLISHED 2099758 newreno hostd-IO tcp 0 0 127.0.0.1:17652 127.0.0.1:8307 ESTABLISHED 2099261 newreno rhttpproxy-work tcp 0 0 127.0.0.1:8307 127.0.0.1:57784 ESTABLISHED 2099758 newreno hostd-IO tcp 0 0 127.0.0.1:57784 127.0.0.1:8307 ESTABLISHED 2100479 newreno rhttpproxy-work tcp 0 0 127.0.0.1:8307 127.0.0.1:50576 ESTABLISHED 2099758 newreno hostd-IO tcp 0 0 127.0.0.1:50576 127.0.0.1:8307 ESTABLISHED 2099138 newreno rhttpproxy-work tcp 0 0 127.0.0.1:8307 0.0.0.0:0 LISTEN 2099598 newreno hostd |
7. rhttpproxy 로그에서 vpxa.log에 기록된 client port가 50235를 확인했으나, 관련 로그 확인 불가
8. vCenter의 vpxd.log를 다시 살펴본 결과 다음과 같이 문제가 발생하는 ESXi Host의 동일한 ID 값으로 서로 다른 ESXi Host IP Address를 사용하여 접근 시도하는 것을 확인
## 마지막 라인을 보면, opID에 HB-host-37931 이 기록되어 있는데 이는 문제가 발생하는 ESXi Host의 구분값
## 동일한 ESXi Host 구분값인데 정상 IP인 192.168.244.46이 아닌, 192.168.243.46으로 접근 시도
/var/log/vmware/vpxd/vpxd.log
| 2023-06-04T22:40:15.613Z info vpxd[59895] [Originator@6876 sub=HostCnx opID=CheckforMissingHeartbeats-6038094c] [VpxdHostCnx] No heartbeats received from host; cnx: 52976f19-6237-3ea1-44b2-5ee314611253, h: host-37931, time since last heartbeat: 94216ms 2023-06-04T22:40:15.613Z info vpxd[59895] [Originator@6876 sub=HostCnx opID=CheckforMissingHeartbeats-6038094c] Marking the connection alive to false: 52976f19-6237-3ea1-44b2-5ee314611253 2023-06-04T22:40:15.613Z info vpxd[59895] [Originator@6876 sub=InvtHostCnx opID=CheckforMissingHeartbeats-6038094c] Got lost connection callback for host-37931 2023-06-04T22:40:15.613Z warning vpxd[64701] [Originator@6876 sub=InvtHostCnx opID=HostSync-host-37931-76da2bbc] Connection not alive due to missing heartbeats; [vim.HostSystem:host-37931,abc.contoso.com], cnx: 52976f19-6237-3ea1-44b2-5ee314611253 2023-06-04T22:40:15.613Z info vpxd[64701] [Originator@6876 sub=QuickStats opID=HostSync-host-37931-76da2bbc] Host [vim.HostSystem:host-37931,abc.contoso.com] should not be polled 2023-06-04T22:40:15.614Z warning vpxd[64701] [Originator@6876 sub=MoHost opID=HostSync-host-37931-76da2bbc] host [vim.HostSystem:host-37931,abc.contoso.com] connection state changed to NO_RESPONSE 2023-06-04T22:40:15.614Z info vpxd[64701] [Originator@6876 sub=QuickStats opID=HostSync-host-37931-76da2bbc] Host [vim.HostSystem:host-37931,abc.contoso.com] should not be polled 2023-06-04T22:40:15.615Z info vpxd[64701] [Originator@6876 sub=InvtHostCnx opID=HostSync-host-37931-76da2bbc] Skip restoring heartbeat: already got heartbeats; [vim.HostSystem:host-37931,abc.contoso.com], ct: 144 2023-06-04T22:40:15.616Z warning vpxd[64701] [Originator@6876 sub=InvtHostCnx opID=HostSync-host-37931-76da2bbc] Exception occurred during host sync; Host communication failed; [vim.HostSystem:host-37931,abc.contoso.com], e: N5Vmomi5Fault17HostCommunication9ExceptionE(Fault cause: vmodl.fault.HostCommunication --> ) --> [context]zKq7AVECAQAAABvdLAERdnB4ZAAAHug3bGlidm1hY29yZS5zbwAAAYksAIl7LQBX+DIBGbdvdnB4ZAABiDGNASxujYEBjGABgUKNYAGBcJxgAYHTyV8BgZ5zYAEAl1ojAD+wIwDcczcCh38AbGlicHRocmVhZC5zby4wAAPvNQ9saWJjLnNvLjYA[/context] 2023-06-04T22:40:15.620Z info vpxd[64701] [Originator@6876 sub=QuickStats opID=HostSync-host-37931-76da2bbc] Host [vim.HostSystem:host-37931,abc.contoso.com] should not be polled 2023-06-04T22:40:15.840Z info vpxd[65245] [Originator@6876 sub=vpxLro opID=sps-Main-464236-370-918415-84] [VpxLRO] -- BEGIN session[52511ff2-45da-bb83-cf91-3ca1f78c21ba]5272b1ba-8742-f975-72cb-c4a23294a489 -- CatalogSyncManager -- vim.vslm.vcenter.CatalogSyncManager.queryCatalogChange -- 52511ff2-45da-bb83-cf91-3ca1f78c21ba(5205bb2a-0c04-2d2a-9b56-3198c5a3429c) 2023-06-04T22:40:15.853Z info vpxd[65245] [Originator@6876 sub=vpxLro opID=sps-Main-464236-370-918415-84] [VpxLRO] -- FINISH session[52511ff2-45da-bb83-cf91-3ca1f78c21ba]5272b1ba-8742-f975-72cb-c4a23294a489 2023-06-04T22:40:15.899Z warning vpxd[64784] [Originator@6876 sub=IO.Connection opID=HB-host-37931@1686-52d66fc6-SWI-4b70ddca] Failed to connect; <io_obj p:0x00007f4dd49726c8, h:152, <TCP '192.168.113.17 : 44276'>, <TCP '192.168.243.46 : 443'>>, e: 110(Connection timed out), duration: 31436msec |
9. vCenter에서 netstat 결과 확인 시, 실제로 192.168.243.46으로 시도한 흔적을 확인
## 192.168.243.46으로는 통신이 안되기 때문에, SYN_SENT 상태만 존재
| # grep "192.168.243.46" * netstat_-anp.txt:tcp 0 1 192.168.113.17:58770 192.168.243.46:443 SYN_SENT 59625/vpxd netstat_-anp.txt:tcp 0 1 192.168.113.17:58800 192.168.243.46:443 SYN_SENT 59625/vpxd netstat_-anp.txt:tcp 0 1 192.168.113.17:58776 192.168.243.46:443 SYN_SENT 59625/vpxd netstat_-anp.txt:tcp 0 1 192.168.113.17:58662 192.168.243.46:443 SYN_SENT 59625/vpxd netstat_-anp.txt:tcp 0 1 192.168.113.17:58836 192.168.243.46:443 SYN_SENT 59625/vpxd netstat_-anp.txt:tcp 0 1 192.168.113.17:58766 192.168.243.46:443 SYN_SENT 59625/vpxd # grep "192.168.244.46" * netstat_-anp.txt:tcp 0 0 192.168.113.17:41322 192.168.244.46:443 ESTABLISHED 59625/vpxd netstat_-anp.txt:tcp 0 0 192.168.113.17:41670 192.168.244.46:443 TIME_WAIT - netstat_-anp.txt:tcp 0 0 192.168.113.17:38212 192.168.244.46:443 ESTABLISHED 59625/vpxd netstat_-anp.txt:tcp 0 0 192.168.113.17:38224 192.168.244.46:443 TIME_WAIT - netstat_-anp.txt:tcp 0 0 192.168.113.17:37368 192.168.244.46:443 ESTABLISHED 59625/vpxd netstat_-anp.txt:tcp 0 0 192.168.113.17:38880 192.168.244.46:443 ESTABLISHED 59625/vpxd |
10. 실제 고객사에 확인 시 vCenter에서 문제가 발생하는 ESXi Host 이름으로 DNS lookup 시, 두 개의 IP Address인 192.168.243.46과 192.168.244.46이 반환
## 이에 정상적인 192.168.244.46만 남기고 192.168.243.46에 해당하는 A/PTR Record 제거 요청
'Compute' 카테고리의 다른 글
| [Kubernetes] 0.사전 작업 (0) | 2023.07.03 |
|---|---|
| [NUMA] esxtop metrics (0) | 2023.06.14 |
| [NUMA] numactl and numastat (2) | 2023.06.11 |
| [NUMA] Scheduler (0) | 2023.06.11 |
| [NUMA] Constructs (0) | 2023.06.11 |
