"Cannot login user [email protected]: no permission" in ESXi host events when lockdown mode is enabled on ESXi

Products

• VMware vSphere ESXi

Issue/Introduction

To identify the custom script or third party software that are continuously trying to login using root credentials, causing these events to be generated.

Symptoms:
"Cannot login user [email protected]: no permission" on the ESXi host post enabling lockdown mode

 

Environment

VMware vSphere ESXi 7.0
VMware vSphere ESXi 8.0

Cause

These repeated logins attempts are either caused by a custom script or third party tool.

Resolution

To identify the source of the script which is trying to login as root user, perform the following steps.

• Check the opID for these operations in hostd.log by running the following command: 
  
  less /var/run/log/hostd.log | grep -i "no permission"

Sample Output:

yyyy-mm-ddThh:mm:ss.Z info hostd[1052116] [Originator@6876 sub=Vimsvc.ha-eventmgr opID=vim-cmd-22-46f6] Event 3806 : Cannot login user [email protected]: no permission
yyyy-mm-ddThh:mm:ss.Z info hostd[1051625] [Originator@6876 sub=Vimsvc.ha-eventmgr opID=vim-cmd-54-4700] Event 3807 : Cannot login user [email protected]: no permission
yyyy-mm-ddThh:mm:ss.Z info hostd[1052638] [Originator@6876 sub=Vimsvc.ha-eventmgr opID=vim-cmd-9b-52f3] Event 3815 : Cannot login user [email protected]: no permission
yyyy-mm-ddThh:mm:ss.Z info hostd[1051623] [Originator@6876 sub=Vimsvc.ha-eventmgr opID=vim-cmd-cd-52f9] Event 3816 : Cannot login user [email protected]: no permission

yyyy-mm-ddThh:mm:ss.Z In(166) Hostd[2098939]: [Originator@6876 sub=Vimsvc.ha-eventmgr opID=esxcli-80-ff97 sid=527e4b60] Event 47483 : Cannot login user [email protected]: no permission
yyyy-mm-ddThh:mm:ss.Z In(166) Hostd[2098951]: [Originator@6876 sub=Vimsvc.ha-eventmgr opID=esxcli-60-03ba sid=5270adc0] Event 47488 : Cannot login user [email protected]: no permission
yyyy-mm-ddThh:mm:ss.Z In(166) Hostd[2098940]: [Originator@6876 sub=Vimsvc.ha-eventmgr opID=esxcli-4f-07bb sid=527bd879] Event 47495 : Cannot login user [email protected]: no permission
yyyy-mm-ddThh:mm:ss.Z In(166) Hostd[2098932]: [Originator@6876 sub=Vimsvc.ha-eventmgr opID=esxcli-39-0b74 sid=52edbc2e] Event 47497 : Cannot login user [email protected]: no permission

Take a note of the opID from the above snippets. If the opID starts with "vim-cmd" or with "esxcli", then some script or service on the host is calling /bin/vim-cmd or /bin/esxcli periodically.

    A. For vim-cmd:

• We can replace the vim-cmd with a wrapper to find out the parent of invocation

Note: Run these commands directly on the ESXi shell once.

[root@ESXi:~] localcli system settings advanced set -o /VisorFS/VisorFSPristineTardisk -i 0
[root@ESXi:~] mkdir /bin/bin
[root@ESXi:~] mv /bin/vim-cmd /bin/bin/
[root@ESXi:~] echo '#!/bin/sh' > /bin/vim-cmd
[root@ESXi:~] echo 'logger ================= vim-cmd ==============' >> /bin/vim-cmd
[root@ESXi:~] echo 'ps -CcJ | grep -B 5 vim-cmd | logger' >> /bin/vim-cmd
[root@ESXi:~] echo /bin/bin/vim-cmd >> /bin/vim-cmd
[root@ESXi:~] chmod +x /bin/vim-cmd

Once you run the above commands, re-enable lockdown mode to reproduce the issue. Once the issue is reproduced, check /var/log/syslog.log:

Sample snippet: In this scenario, as highlighted below, these seem to be coming from a third party script in /opt/emc/rp/kdriver.

yyyy-mm-ddThh:mm:ss.Z root[1079055]: ================= vim-cmd ==============
yyyy-mm-ddThh:mm:ss.Z root[1079058]:   ^Nx^O ^Nm^O^Nq^O1079019  1079019  sleep                 sleep 60
yyyy-mm-ddThh:mm:ss.Z root[1079058]:   ^Nt^O^Nq^O1069210  1069210  sh                    /usr/bin/sh /opt/emc/rp/kdriver/bin/launch_kdriver_watchdog.sh
yyyy-mm-ddThh:mm:ss.Z root[1079058]:   ^Nx^O ^Nt^O^Nq^O1069256  1069256  sh                    /usr/bin/sh ./run_kdriver.sh
yyyy-mm-ddThh:mm:ss.Z root[1079058]:   ^Nx^O ^Nx^O ^Nm^O^Nq^O1069315  1069315  kdriver               /opt/emc/rp/kdriver/bin/kdriver
yyyy-mm-ddThh:mm:ss.Z root[1079058]:   ^Nx^O ^Nm^O^Nq^O1069233  1069233  sh                    /usr/bin/sh ./kdriver_heartbeats.sh
yyyy-mm-ddThh:mm:ss.Z root[1079058]:   ^Nx^O   ^Nm^O^Nq^O1079054  1079054  sh                    /bin/sh /bin/vim-cmd vmsvc/getallvms
yyyy-mm-ddThh:mm:ss.Z root[1079058]:   ^Nx^O     ^Nt^O^Nq^O1079058  1079058  logger                logger
yyyy-mm-ddThh:mm:ss.Z root[1079058]:   ^Nx^O     ^Nt^O^Nq^O1079057  1079057  grep                  grep -B 5 vim-cmd
yyyy-mm-ddThh:mm:ss.Z root[1079064]: ================= vim-cmd ==============
yyyy-mm-ddThh:mm:ss.Z root[1079067]:   ^Nx^O ^Nm^O^Nq^O1079019  1079019  sleep                 sleep 60
yyyy-mm-ddThh:mm:ss.Z root[1079067]:   ^Nt^O^Nq^O1069210  1069210  sh                    /usr/bin/sh /opt/emc/rp/kdriver/bin/launch_kdriver_watchdog.sh
yyyy-mm-ddThh:mm:ss.Z root[1079067]:   ^Nx^O ^Nt^O^Nq^O1069256  1069256  sh                    /usr/bin/sh ./run_kdriver.sh
yyyy-mm-ddThh:mm:ss.Z root[1079067]:   ^Nx^O ^Nx^O ^Nm^O^Nq^O1069315  1069315  kdriver               /opt/emc/rp/kdriver/bin/kdriver
yyyy-mm-ddThh:mm:ss.Z root[1079067]:   ^Nx^O ^Nm^O^Nq^O1069233  1069233  sh                    /usr/bin/sh ./kdriver_heartbeats.sh
yyyy-mm-ddThh:mm:ss.Z root[1079067]:   ^Nx^O   ^Nm^O^Nq^O1079063  1079063  sh                    /bin/sh /bin/vim-cmd vmsvc/getallvms
yyyy-mm-ddThh:mm:ss.Z root[1079067]:   ^Nx^O     ^Nt^O^Nq^O1079067  1079067  logger                logger
yyyy-mm-ddThh:mm:ss.Z root[1079067]:   ^Nx^O     ^Nt^O^Nq^O1079066  1079066  grep                  grep -B 5 vim-cmd

• They can restore the original file by copying it over to the wrapper to revert the changes made:
  
  [root@ESXi:~] mv /bin/bin/vim-cmd /bin/vim-cmd

    B. For esxcli:

• Create a new file called "/bin/esxcli.wrapper"

[root@ESXi:~] vi /bin/esxcli.wrapper

• Enter the following contents in the file:

#!/bin/sh
logger ================= esxcli ==============
ps -CcJ | grep -B 5 esxcli | logger
/bin/esxcli.py $@

• Then set wrapper as an executable.

[root@ESXi:~]chmod +x /bin/esxcli.wrapper

• The root account can no longer change permissions or executable files in ESXi 7.0.x and above. Therefore run the command below to make the required changes:
  
  [root@ESXi:~]vsish -e set /config/VisorFS/intOpts/VisorFSPristineTardisk 0

Reference: The root account can no longer change permissions or executable files in ESXi 7.0.x

• Then we need to point the soft link "/bin/esxcli" to the new wrapper script "/bin/esxcli.wrapper" instead of "/bin/esxcli".

[root@ESXi:~]rm -f /bin/esxcli
[root@ESXi:~]ln -s /bin/esxcli.wrapper /bin/esxcli

• Once you run the above commands, re-enable lockdown mode to reproduce the issue. Once the issue is reproduced, check /var/log/syslog.log:

Sample snippet: In this scenario, as highlighted below, these seem to be coming from HPE VIBs sut and ams.

yyyy-mm-ddThh:mm:ss.Z No(13) root[19970780]: ================= esxcli ==============
yyyy-mm-ddThh:mm:ss.Z No(13) root[19970783]:   ^Nx^O ^Nm^O^Nq^O2099769   2099769  smadvrev              /opt/amsdv/bin/smadvrev
yyyy-mm-ddThh:mm:ss.Z No(13) root[19970783]:   ^Nt^O^Nq^O2099681   2099681  sh                    /bin/sh /usr/lib/vmware/daemonMgmt/bin/watchdog.sh -t 100 -c -s amsdv-ahsdv /opt/amsdv/bin/ahsdv
yyyy-mm-ddThh:mm:ss.Z No(13) root[19970783]:   ^Nx^O ^Nm^O^Nq^O2099695   2099695  ahsdv                 /opt/amsdv/bin/ahsdv
yyyy-mm-ddThh:mm:ss.Z No(13) root[19970783]:   ^Nt^O^Nq^O2099502   2099502  sh                    /bin/sh /usr/lib/vmware/daemonMgmt/bin/watchdog.sh -t 100 -n -s sut-sut /opt/sut/bin/sut
yyyy-mm-ddThh:mm:ss.Z No(13) root[19970783]:   ^Nx^O ^Nm^O^Nq^O2099522   2099522  sut                   /opt/sut/bin/sut
yyyy-mm-ddThh:mm:ss.Z No(13) root[19970783]:   ^Nx^O   ^Nm^O^Nq^O19970778  19970778  sh                    sh -c esxcli system maintenanceMode get >& /tmp/stagingdirectory/sutmaintenancemode.log
yyyy-mm-ddThh:mm:ss.Z No(13) root[19970783]:   ^Nx^O     ^Nm^O^Nq^O19970779  19970779  sh                    /bin/sh /sbin/esxcli system maintenanceMode get
yyyy-mm-ddThh:mm:ss.Z No(13) root[19970783]:   ^Nx^O       ^Nt^O^Nq^O19970783  19970783  logger                logger
yyyy-mm-ddThh:mm:ss.Z No(13) root[19970783]:   ^Nx^O       ^Nt^O^Nq^O19970782  19970782  grep                  grep -B 5 esxcli

• After reproducing the issue and verifying the log file in "/var/log/syslog.log", restore the original state with these commands:

[root@ESXi:~]rm -f /bin/esxcli
[root@ESXi:~]ln -s /bin/esxcli.py /bin/esxcli
[root@ESXi:~]vsish -e set /config/VisorFS/intOpts/VisorFSPristineTardisk 1

 

Workaround:
The root user can be added as an exception user as per the article below:
Enabling Lockdown Mode on ESXi shows - Cannot login user [email protected]: no permission events

 

Additional Information

User [email protected] logged in as hbr-agent messages are filling up host event logs

There is a known issue when using NSX Version 4.1.2.1 and enabling ESXi Lockdown mode.  When NSX version 4.1.2.1 is being used with ESXi version 7.0 or 8.0 in Lockdown mode, the ESXi event log may see similar behavior with "Cannot login user [email protected]: no permission" logs repeating in the Monitor --> Event section of the vCenter UI for a host.  The above resolution may identify nsx-exporter and nsx-sfhc processes attempting login and failing.  This is a known issue and can be resolved by upgrading NSX Manager to version 4.1.2.3