sysmgr-2-cfgwrite_timeout_abort & vns_agent high CPU utilization issue

esoc.engineering · ‎01-25-2012

I've been troubleshooting in a lab environment restoring a 1000v that will not allow the running-config to be copied 100% to the startup-config. This was a HA cluster and I've since resolved that and have the 1000v running in standalone mode. I've left the SVS connection broken while I isolate the issue with being able to save the configuration. A "show processor cpu sort" reveals that the vns_agent is consistently running around 99%. VCenter confirms that the VM is consuming it's CPU resources that are allocated to it.

The VSM can communicate with the VEM modules in the hosts, and in the process of troubleshooting I've learned the ins and outs of the vemcmd and vemset commands on the ESXi hosts. Vem-health script indicates that VEM-VSM connectivity is fine except on one of the hosts which is a different issue at hand (has to do with the card configuration for the VEM for packet and control vlans).

Everything I've investigates so far indicates that it cannot complete a process with the internal file linux/FreeBSD file system of the VSM. I used the "show system internal dir <path>" command to browse the file system and poke around to find out more but I'm hunting in the dark at this point and coming up dry on documentation to research on the issue.

Any help or direction would be much appreciated. I've booted the VSM in the vsh in the past but didn't see any additional commands I could think to utilize for this specific issue. Trying to maintain the VDH ID and therefore the licenses if at all possible. Last resort is the blow it out and build from scratch and request new licenses for the generated VDH ID. I already know how to recover the vmware svs connection and VEM connectivity as long as the same vem feature level (version) is utilized.

Thanks in advance...

Results of a copy run start are as follows:

n1kv-vds# copy run start

[########################################] 98%2012 Jan 24 16:49:57 n1kv-vds %SYSMGR-3-CFGWRITE_SRVTIMEOUT: Service "vns_agent" failed to store its configuration in the timeout period

2012 Jan 24 16:49:57 n1kv-vds %SYSMGR-2-CFGWRITE_ABORTED: Configuration copy aborted.

Configuration update aborted: timed out

2012 Jan 24 16:49:59 n1kv-vds %SYSMGR-3-CFGWRITE_FAILED: Configuration copy failed (error-id 0x401E0045).

n1kv-vds(config)# show system error-id 0x401E0045

Error Facility: sysmgr
Error Description: timed out

"show system internal sysmgr state" indicates the following:

The master System Manager has PID 2013 and UUID 0x1.

Last time System Manager was gracefully shutdown.

The state is SRV_STATE_MASTER_ACTIVE_ALONE entered at time Fri Jan 20 16:00:49 2012.

HA info:

slotid = 1 supid = 0
cardstate = SYSMGR_CARDSTATE_ACTIVE .
cardstate = SYSMGR_CARDSTATE_ACTIVE (hot switchover is configured enabled).
Configured to use the real platform manager.
Configured to use the real redundancy driver.
Redundancy register: this_sup = RDN_ST_AC, other_sup = RDN_ST_NP.
EOBC device name: eth0.
Remote addresses: MTS - [not available] IP - [not available]
MSYNC not done.
Remote MSYNC not done.
Module online notification received.
Local super-state is: SYSMGR_SUPERSTATE_STABLE
Standby super-state is: SYSMGR_SUPERSTATE_STABLE
Swover Reason : SYSMGR_UNKNOWN_SWOVER
Total number of Switchovers: 0
Swover threshold settings: 20 switchovers within 1200 seconds
Switchovers within threshold interval: 0
Last switchover time: 0 seconds after system start time
Cumulative time between last 0 switchovers: 0
Start done received for 2 plugins, Total number of plugins = 2

"show system internal log sysmgr cfgctrl" reveals the following:

<Tue Jan 24 17:03:57 2012> write_config: entering write_config, is_global = 0, cfgctrl_vdc = 1

<Tue Jan 24 17:03:57 2012> write_config: normal 'copy r s' path

<Tue Jan 24 17:03:57 2012> prepare_writing_config: vdc = 1

slot: 1 is the current valid slot

<Tue Jan 24 17:03:57 2012> prepare_writing_config: slot: 0 is the least recently used /mnt/cfg/ slot

<Tue Jan 24 17:03:57 2012> prepare_writing_config: calling clear_cfg_ramfs() to clear startup-cfg from RAMfs

<Tue Jan 24 17:03:57 2012> clear_cfg_ramfs: calling to startcfg_clear_ramfs_cfg() to clear the startup-cfg directory in RAMfs

startcfg_clear_ramfs_cfg: Invoked for vdc 1

Executing "/bin/rm -rf /var/sysmgr/startup-cfg/log".

Executing "/bin/rm -rf /var/sysmgr/startup-cfg/bin".

Executing "/bin/rm -rf /var/sysmgr/startup-cfg/linux".

Executing "/bin/rm -rf /var/sysmgr/startup-cfg/boot".

Executing "/bin/rm -rf /var/sysmgr/startup-cfg/ascii".

Executing "/bin/rm -rf /var/sysmgr/startup-cfg/debug".

Executing "/bin/rm -rf /var/sysmgr/startup-cfg/licenses".

Executing "/bin/rm -rf /var/sysmgr/startup-cfg/no-erase".

get_ramfs_cfg_label_path: returning cfg label path: /var/sysmgr/startup-cfg/cfglabel.sysmgr

Executing "/bin/rm -f /var/sysmgr/startup-cfg/cfglabel.sysmgr".

init_ramfs_startup_cfg: Invoked for vdc 1

Executing "mkdir -p -m 777 /var/sysmgr/startup-cfg/log".

Executing "mkdir -p -m 777 /var/sysmgr/startup-cfg/bin".

Executing "mkdir -p -m 777 /var/sysmgr/startup-cfg/linux".

Executing "mkdir -p -m 777 /var/sysmgr/startup-cfg/boot".

Executing "mkdir -p -m 777 /var/sysmgr/startup-cfg/ascii".

Executing "mkdir -p -m 777 /var/sysmgr/startup-cfg/debug".

Executing "mkdir -p -m 777 /var/sysmgr/startup-cfg/licenses".

Executing "mkdir -p -m 777 /var/sysmgr/startup-cfg/no-erase".

<Tue Jan 24 17:03:57 2012> cfgwrite_log_open: inside cfgwrite_log_open()

<Tue Jan 24 17:03:57 2012> cfgwrite_log_open: calling freopen() for stderr with filename /var/sysmgr/startup-cfg/log/cfgwrite_log.sysm

gr

<Tue Jan 24 17:03:57 2012> cfgwrite_log_open: calling freopen() for stdout with filename /var/sysmgr/startup-cfg/log/cfgwrite_log.sysm

gr

<Tue Jan 24 17:03:57 2012> cfgwrite_log_open: log file /var/sysmgr/startup-cfg/log/cfgwrite_log.sysmgr opened succesfully

<Tue Jan 24 17:03:57 2012> write_config: calling cfg_action_req_send()

<Tue Jan 24 17:03:57 2012> cfg_action_req_send: for VDC 1

<Tue Jan 24 17:03:57 2012> cfg_action_req_send: service "urib" doesn't have configuration to store.

<Tue Jan 24 17:03:57 2012> cfg_action_req_send: service "u6rib" doesn't have configuration to store.

<Tue Jan 24 17:03:57 2012> cfg_action_req_send: service "tcpudp" doesn't have configuration to store.

<Tue Jan 24 17:03:57 2012> cfg_action_req_send: service "sysinfo" doesn't have configuration to store.

<Tue Jan 24 17:03:57 2012> cfg_action_req_send: service "smm" doesn't have configuration to store.

<Tue Jan 24 17:03:57 2012> cfg_action_req_send: service "psshelper" doesn't have configuration to store.

<Tue Jan 24 17:03:57 2012> cfg_action_req_send: service "pktmgr" doesn't have configuration to store.

<Tue Jan 24 17:03:57 2012> cfg_action_req_send: service "pfm_dummy" doesn't have configuration to store.

<Tue Jan 24 17:03:57 2012> cfg_action_req_send: service "npacl" doesn't have configuration to store.

<Tue Jan 24 17:03:58 2012> cfg_action_req_send: service "l3vm" doesn't have configuration to store.

<Tue Jan 24 17:03:58 2012> cfg_action_req_send: service "ipv6" doesn't have configuration to store.

<Tue Jan 24 17:03:58 2012> cfg_action_req_send: service "ip" doesn't have configuration to store.

<Tue Jan 24 17:03:58 2012> cfg_action_req_send: service "igmp" doesn't have configuration to store.

<Tue Jan 24 17:03:58 2012> cfg_action_req_send: service "icmpv6" doesn't have configuration to store.

<Tue Jan 24 17:03:58 2012> cfg_action_req_send: service "fs-daemon" doesn't have configuration to store.

<Tue Jan 24 17:03:58 2012> cfg_action_req_send: service "feature-mgr" doesn't have configuration to store.

<Tue Jan 24 17:03:58 2012> cfg_action_req_send: service "confcheck" doesn't have configuration to store.

<Tue Jan 24 17:03:58 2012> cfg_action_req_send: service "arp" doesn't have configuration to store.

<Tue Jan 24 17:03:58 2012> cfg_action_req_send: service "adjmgr" doesn't have configuration to store.

<Tue Jan 24 17:03:58 2012> cfg_action_req_send: service "PSSHelper Global Service" doesn't have configuration to store.

<Tue Jan 24 17:03:58 2012> cfg_action_req_send: exiting, cumulative num_expected_responses = 59 including vdc 1

<Tue Jan 24 17:03:58 2012> cfg_action_req_send: exiting, num_expected_responses = 59

<Tue Jan 24 17:03:58 2012> write_config: calling cfg_action_rsp_wait()

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x16a

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x2cc

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x25

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x2fa

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x1bd

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x188

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0xa7

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x193

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x2e8

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x165

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x59

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x64

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x20

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x95

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0xab

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x1c

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0xb

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x1cb

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x192

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x2a

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x194

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x15c

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x183

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0xb4

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x1e9

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0xbb

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x1a8

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x48

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0xf6

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x1a6

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x1bc

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0xae

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x10

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x15b

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x179

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0xb3

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x25a

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x155

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x156

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0xaf

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x17a

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0xbf

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x56

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x128

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x3b2

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x3b5

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x15f

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x199

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x37

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x71

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x27

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x50

<Tue Jan 24 17:03:58 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x5c

<Tue Jan 24 17:03:59 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x6f

<Tue Jan 24 17:03:59 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x3

<Tue Jan 24 17:03:59 2012> cfg_action_rsp_process: Rcvd response from vdc 1 SYSMGR sap

<Tue Jan 24 17:03:59 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0xa9

<Tue Jan 24 17:03:59 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x6a

<Tue Jan 24 17:04:59 2012> cfg_action_rsp_process: Rcvd response from vdc 1 from sap 0x4c

<Tue Jan 24 17:08:19 2012> restore_ramfs_cfg: calling startcfg_mount_flash_startup_cfg_partitions() to mount /mnt/cfg/0 and /mnt/cfg/1

startcfg_restore_cfg_to_ramfs: Invoked for vdc 1

calling startcfg_clear_ramfs_cfg() to clear ramfs

startcfg_clear_ramfs_cfg: Invoked for vdc 1

Executing "/bin/rm -rf /var/sysmgr/startup-cfg/log".

Executing "/bin/rm -rf /var/sysmgr/startup-cfg/bin".

Executing "/bin/rm -rf /var/sysmgr/startup-cfg/linux".

Executing "/bin/rm -rf /var/sysmgr/startup-cfg/boot".

Executing "/bin/rm -rf /var/sysmgr/startup-cfg/ascii".

Executing "/bin/rm -rf /var/sysmgr/startup-cfg/debug".

Executing "/bin/rm -rf /var/sysmgr/startup-cfg/licenses".

Executing "/bin/rm -rf /var/sysmgr/startup-cfg/no-erase".

get_ramfs_cfg_label_path: returning cfg label path: /var/sysmgr/startup-cfg/cfglabel.sysmgr

Executing "/bin/rm -f /var/sysmgr/startup-cfg/cfglabel.sysmgr".

init_ramfs_startup_cfg: Invoked for vdc 1

Executing "mkdir -p -m 777 /var/sysmgr/startup-cfg/log".

Executing "mkdir -p -m 777 /var/sysmgr/startup-cfg/bin".

Executing "mkdir -p -m 777 /var/sysmgr/startup-cfg/linux".

Executing "mkdir -p -m 777 /var/sysmgr/startup-cfg/boot".

Executing "mkdir -p -m 777 /var/sysmgr/startup-cfg/ascii".

Executing "mkdir -p -m 777 /var/sysmgr/startup-cfg/debug".

Executing "mkdir -p -m 777 /var/sysmgr/startup-cfg/licenses".

Executing "mkdir -p -m 777 /var/sysmgr/startup-cfg/no-erase".

checking to see if file: /mnt/cfg/0/log/log_cfg.tar.gz exists

file /mnt/cfg/0/log/log_cfg.tar.gz does not exist- copy contents of this directory back to ramfs

executing command: cd /var/sysmgr/startup-cfg/log; cp -af /mnt/cfg/0/log/* /var/sysmgr/startup-cfg/log

Executing "cd /var/sysmgr/startup-cfg/log; cp -af /mnt/cfg/0/log/* /var/sysmgr/startup-cfg/log".

cp: cannot stat `/mnt/cfg/0/log/*': No such file or directory

command:cd /var/sysmgr/startup-cfg/log; cp -af /mnt/cfg/0/log/* /var/sysmgr/startup-cfg/log failed with return code:1

checking to see if file: /mnt/cfg/0/bin/bin_cfg.tar.gz exists

file /mnt/cfg/0/bin/bin_cfg.tar.gz does not exist- copy contents of this directory back to ramfs

executing command: cd /var/sysmgr/startup-cfg/bin; cp -af /mnt/cfg/0/bin/* /var/sysmgr/startup-cfg/bin

Executing "cd /var/sysmgr/startup-cfg/bin; cp -af /mnt/cfg/0/bin/* /var/sysmgr/startup-cfg/bin".

cp: cannot stat `/mnt/cfg/0/bin/*': No such file or directory

command:cd /var/sysmgr/startup-cfg/bin; cp -af /mnt/cfg/0/bin/* /var/sysmgr/startup-cfg/bin failed with return code:1

checking to see if file: /mnt/cfg/0/linux/linux_cfg.tar.gz exists

file /mnt/cfg/0/linux/linux_cfg.tar.gz does not exist- copy contents of this directory back to ramfs

executing command: cd /var/sysmgr/startup-cfg/linux; cp -af /mnt/cfg/0/linux/* /var/sysmgr/startup-cfg/linux

Executing "cd /var/sysmgr/startup-cfg/linux; cp -af /mnt/cfg/0/linux/* /var/sysmgr/startup-cfg/linux".

cp: cannot stat `/mnt/cfg/0/linux/*': No such file or directory

command:cd /var/sysmgr/startup-cfg/linux; cp -af /mnt/cfg/0/linux/* /var/sysmgr/startup-cfg/linux failed with return code:1

checking to see if file: /mnt/cfg/0/boot/boot_cfg.tar.gz exists

file /mnt/cfg/0/boot/boot_cfg.tar.gz does not exist- copy contents of this directory back to ramfs

executing command: cd /var/sysmgr/startup-cfg/boot; cp -af /mnt/cfg/0/boot/* /var/sysmgr/startup-cfg/boot

Executing "cd /var/sysmgr/startup-cfg/boot; cp -af /mnt/cfg/0/boot/* /var/sysmgr/startup-cfg/boot".

checking to see if file: /mnt/cfg/0/ascii/ascii_cfg.tar.gz exists

file /mnt/cfg/0/ascii/ascii_cfg.tar.gz does not exist- copy contents of this directory back to ramfs

executing command: cd /var/sysmgr/startup-cfg/ascii; cp -af /mnt/cfg/0/ascii/* /var/sysmgr/startup-cfg/ascii

Executing "cd /var/sysmgr/startup-cfg/ascii; cp -af /mnt/cfg/0/ascii/* /var/sysmgr/startup-cfg/ascii".

cp: cannot stat `/mnt/cfg/0/ascii/*': No such file or directory

command:cd /var/sysmgr/startup-cfg/ascii; cp -af /mnt/cfg/0/ascii/* /var/sysmgr/startup-cfg/ascii failed with return code:1

checking to see if file: /mnt/cfg/0/debug/debug_cfg.tar.gz exists

file /mnt/cfg/0/debug/debug_cfg.tar.gz does not exist- copy contents of this directory back to ramfs

executing command: cd /var/sysmgr/startup-cfg/debug; cp -af /mnt/cfg/0/debug/* /var/sysmgr/startup-cfg/debug

Executing "cd /var/sysmgr/startup-cfg/debug; cp -af /mnt/cfg/0/debug/* /var/sysmgr/startup-cfg/debug".

cp: cannot stat `/mnt/cfg/0/debug/*': No such file or directory

command:cd /var/sysmgr/startup-cfg/debug; cp -af /mnt/cfg/0/debug/* /var/sysmgr/startup-cfg/debug failed with return code:1

checking to see if file: /mnt/cfg/0/licenses/licenses_cfg.tar.gz exists

file: /mnt/cfg/0/licenses/licenses_cfg.tar.gz exists- untar into ramfs

Executing "(cd /var/sysmgr/startup-cfg/licenses; tar zxvf /mnt/cfg/0/licenses/licenses_cfg.tar.gz)".

checking to see if file: /mnt/cfg/0/no-erase/no-erase_cfg.tar.gz exists

file: /mnt/cfg/0/no-erase/no-erase_cfg.tar.gz exists- untar into ramfs

Executing "(cd /var/sysmgr/startup-cfg/no-erase; tar zxvf /mnt/cfg/0/no-erase/no-erase_cfg.tar.gz)".

./

before exiting- lets add the label to the RAMFS partition

startcfg_ramfs_label_add: Invoked for vdc 1

get_ramfs_cfg_label_path: returning cfg label path: /var/sysmgr/startup-cfg/cfglabel.sysmgr

path of label file: /var/sysmgr/startup-cfg/cfglabel.sysmgr

resetting timestamp in RAMFS partition for vdc 1

utime returned value: 0

finished adding label to RAMFS partition

<Tue Jan 24 17:08:21 2012> restore_ramfs_cfg: calling startcfg_umount_flash_startup_cfg_partitions() to unmount both flash partitions

Log closed on Tue Jan 24 17:08:21 2012