The VPXD VmReconfiguredEvent messages are being forwarded as multiple independent syslog messages
search cancel

The VPXD VmReconfiguredEvent messages are being forwarded as multiple independent syslog messages

book

Article ID: 449467

calendar_today

Updated On:

Products

VMware vCenter Server

Issue/Introduction

  • The vCenter Server service (VPXD) VmReconfiguredEvent messages are being forwarded as multiple independent syslog messages, with a timestamp and hostname prepended to every line. Because of this, the remote syslog server indexes each line as a separate event and cannot reconstruct the original multiline event.

<TIMESTAMP> vcenter.example.com vpxd[7165] Event [5680655] [1-1] [<TIMESTAMP>] [vim.event.VmReconfiguredEvent] [info] [VSPHERE.LOCAL\Administrator
] [<DATACENTER] [5680652] [Reconfigured <VM_NAME> on <ESX_SERVER> in <DATACENTER>.
<TIMESTAMP> vcenter.example.com
<TIMESTAMP> vcenter.example.com Modified:
<TIMESTAMP> vcenter.example.com
<TIMESTAMP> vcenter.example.com config.hardware.numCPU: 1 -> 2;
<TIMESTAMP> vcenter.example.com config.cpuAllocation.shares.shares: 1000 -> 2000;
<TIMESTAMP> vcenter.example.com  Added:
<TIMESTAMP> vcenter.example.com
<TIMESTAMP> vcenter.example.com  Deleted:
<TIMESTAMP> vcenter.example.com
<TIMESTAMP> vcenter.example.com ]

  • This applies to any VPXD multi-line messages and not just VmReconfiguredEvent messages
  • The vCenter syslog config file /etc/vmware-syslog/syslog.conf is configured to use TCP or SSL as the transport protocol as denoted by the double @ symbols. UDP would be a single @ symbol:

*.* @@<REMOTE_SYSLOG_SERVER>:514;RSYSLOG_SyslogProtocol23Format
*.* @@<REMOTE_SYSLOG_SERVER>:51484;RSYSLOG_SyslogProtocol23Format

  • The default vCenter VPXD services syslog config file /etc/vmware-syslog/vmware-services-vpxd.conf has not been modified and is configured to group messages by timestamp:

#vpxd main log
input(type="imfile"
      File="/var/log/vmware/vpxd/vpxd.log"
      Tag="vpxd-main"
      Severity="info"
      startmsg.regex="^[[:digit:]]{4}-[[:digit:]]{1,2}-[[:digit:]]{1,2}T[[:digit:]]{1,2}:[[:digit:]]{1,2}:[[:digit:]]{1,2}"
      Facility="local0"
      deleteStateOnFileDelete="on"
      reopenOnTruncate="on")

  • When performing a VM reconfigure task and running the packet capture tcpdump -i any dst host <syslog_server> and tcp port 514 -As0
    on vCenter, you can see the VM reconfigure message being sent on a single packet and the new line characters (\n) in the message are visible:

    <TIMESTAMP> eth0  Out IP <VCENTER_SERVER>.33914 > <REMOTE_SYSLOG_SERVER>.syslog: SYSLOG local0.info, length: 810
    E..F..@.@..#...Q...=.z...2."<134>1 <TIMESTAMP> <VCENTER_SERVER> vpxd-main - - - <TIMESTAMP>info vpxd[08062] [Originator@6876 sub=VmProv opID=mrbhb6rg-273408-auto-5uyp-h5:70020561-e2-01] Applying ConfigSpec (vim.vm.ConfigSpec) {\n-->    changeVersion = "<TIMESTAMP>", \n-->    createDate = "<TIMESTAMP>", \n-->    flags = (vim.vm.FlagInfo) {\n-->       virtualMmuUsage = "automatic", \n-->       virtualExecUsage = "hvAuto", \n-->    }, \n-->    numCPUs = 1, \n-->    cpuAllocation = (vim.ResourceAllocationInfo) {\n-->       shares = (vim.SharesInfo) {\n-->          shares = 1000, \n-->          level = "normal"\n-->       }, \n-->    }, \n-->    virtualNuma = (vim.vm.VirtualNuma) {\n-->    }, \n--> } to VM ds:///vmfs/volumes/0c16f0d1-efa53cef/test/vm_name.vmx on host <ESX_HOST>

    NOTE: <134>1 in the packet capture above means that the syslog client is sending the message in the RFC 5424 format. 

Environment

vCenter Server 8 and 9

Cause

Since vCenter's syslog is configured to send messages grouped by timestamp and doesn't split the messages into multiple lines, something along the network path to the syslog server or the syslog server itself is splitting the messages into multiple lines. Often times vCenter will be configured to send its logs to a log forwarder that will relay the logs to the destination syslog server.

If either a log forwarder or syslog server is configured to use RFC 3164 or is using RFC 5424 with octet-counted framing disabled, you will see the original message sent by vCenter split into multiple lines on the syslog server.

By default, legacy TCP receivers using RFC 3164 look for a literal newline character (\n) to mark the end of a message. If vCenter sends a log containing internal \n characters (as shown in packet capture in the Issue/Description above) over a standard TCP stream, a legacy receiver will split the stream on the new \n characters resulting in the multi-line log messages.

Resolution

Configure either the log forwarder or syslog srever to use RFC 5424 or Octet-Counted Framing. Before sending the message, vCenter calculates the exact length of the multi-line block and prepends it to the stream (e.g., 452 <syslog message...>). A log forwarder or syslog server using Octet-Counted Framing will know to read exactly 452 characters, ignores the internal newlines, and keeps the log whole.

Additional Information

Powered by Wolken Software