VMware

ESXi regularly logs last boot timestamp as event time

/scratch/log/vpxa.log contains strange timestamps:

….
2019-09-09T16:04:06.101Z verbose vpxa[7121B70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-7857c633] Starting next WaitForUpdates() call to hostd
2019-09-09T16:04:06.101Z verbose vpxa[7121B70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-7857c633] Completed WaitForUpdatesDone callback
*** 2019-07-10T16:41:56.537Z Section for VMware ESX, pid=68093, version=6.5.0, build=10719125, option=Release
2019-09-09T16:04:06.683Z verbose vpxa[7774B70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-4a957bfe] Received WaitForUpdatesDone callback
2019-09-09T16:04:06.683Z verbose vpxa[7774B70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-4a957bfe] Applying updates from 6597522 to 6597523 (at 6597522)
….

NTP is of course configured correctly. (All the other timestamps are ok)

Our logging infra does not like these events.

It seems to show the time the host was last restarted (uptime 61 days) and not the time of the event in question.

Can you please try for me on your ESXi hosts that were last restarted more than two weeks ago:

for i in /scratch/log/vpxa.*.gz; do
gunzip -c $i | grep build= | grep -v 2019-09-
done

(I’d like to know if or when this was fixed.) Example output:

2019-07-10T16:41:56.537Z Section for VMware ESX, pid=68093, version=6.5.0, build=10719125, option=Release
2019-07-10T16:41:56.537Z Section for VMware ESX, pid=68093, version=6.5.0, build=10719125, option=Release
2019-07-10T16:41:56.537Z Section for VMware ESX, pid=68093, version=6.5.0, build=10719125, option=Release
2019-07-10T16:41:56.537Z Section for VMware ESX, pid=68093, version=6.5.0, build=10719125, option=Release
2019-07-10T16:41:56.537Z Section for VMware ESX, pid=68093, version=6.5.0, build=10719125, option=Release
2019-07-10T16:41:56.537Z Section for VMware ESX, pid=68093, version=6.5.0, build=10719125, option=Release
2019-07-10T16:41:56.537Z Section for VMware ESX, pid=68093, version=6.5.0, build=10719125, option=Release

Please post your output. (If you feel comfortable sharing your build number.)


View Reddit by mro21View Source

Related Articles

One Comment

  1. It’s a bit dumb, but expected. On every rotate of the vpxa logs, a command is run to produce that `Section for…` header row.

    cat /etc/vmsyslog.conf.d/vpxa.conf
    [vmsyslog-logger]
    id = vpxa
    descr = Vpxa logs
    idents = Vpxa
    file = vpxa
    fclass = FileLoggerMessageOnly
    nclass = NetworkFilterVmacoreLogLine
    onrotate = logger -t Vpxa < /var/run/vmware/vpxaLogHeader.txt
    rotate = 20
    size = 5120

    That `Section for…` header row is a string literal from this file.

    cat /var/run/vmware/vpxaLogHeader.txt
    2019-07-20T21:57:42.445Z Section for VMware ESX, pid=67462, version=6.5.0, build=8294253, option=Release

    The vmsyslogd process doesn’t add (or manipulate) timestamps in vpxa logs – they’re already present in the text stream vpxa sends. When sending logs to remote syslog servers, the ESXi host hostname is inserted at character 25 _without parsing_, because performance. So not having a timestamp at all is worse. There wasn’t a really simple way to add a correct timestamp for this one event, so this hack job exists. Arguably the `logger` command should do so, but that’s unmodified from Busybox.

    You could totally replace the on-rotate command, though.

    python -c “from datetime import datetime; s=datetime.utcnow().isoformat(); h=open(‘/var/run/vmware/vpxaLogHeader.txt’).read().strip(); print(‘%sZ %s’ % (s[0:23], h[25:]))” | logger -t Vpxa

    tail -n 1 /var/log/vpxa.log
    2019-09-10T02:38:14.009Z Section for VMware ESX, pid=67462, version=6.5.0, build=8294253, option=Release

Leave a Reply

Your email address will not be published. Required fields are marked *

Close