Spurious "NSX Edge was booted" messages in Events

[minosi]

Hi,

asking more for experience if anyone saw this (or similar) behavior.

Over last few days we started getting bellow messageses in the NSX Manager Event log:

---cut---

<14>Jun 18 00:08:01 NSX-MANAGER 2017-06-18 00:08:01.630 UTC  INFO pool-21-thread-1 SystemEventDaoImpl:133 - [SystemEvent] Time:'Sun Jun 18 00:07:58.000 UTC 2017', Severity:'Informational', Event Source:'edge-5', Code:'30101', Event Message:'NSX Edge was booted', Module:'vShield Edge Appliance', Universal Object:'false'

---cut---

<14>Jun 19 00:08:03 NSX-MANAGER 2017-06-19 00:08:03.639 UTC  INFO pool-21-thread-1 SystemEventDaoImpl:133 - [SystemEvent] Time:'Mon Jun 19 00:07:57.000 UTC 2017', Severity:'Informational', Event Source:'edge-5', Code:'30101', Event Message:'NSX Edge was booted', Module:'vShield Edge Appliance', Universal Object:'false'

---cut---

What is strange here is that there is:

- it seems to log each 24 hours almost by the second, but not each day (so far it did on 16th, 18th and 19th)

- no corresponding event on the vCenter

- no config change happened (certainly not an ESG reboot/restart/config change)

- the rest of the infra is clean, and there was no physical disruption at the time

Digging further, here are the log events just before the Event log entry is logged:

---cut---

<14>Jun 19 00:07:10 NSX-MANAGER 2017-06-19 00:07:10.675 UTC  INFO edgeVseMonitoringThread EdgeVseHealthMonitoringThread:278 - Finished Health check for 4 edge vms in 4 millisec

<12>Jun 19 00:07:26 NSX-MANAGER 2017-06-19 00:07:26.097 UTC  WARN vixCommandExecutor-1 VixCommandExecutor:336 - Host update required for VMId vm-419, delaying command execution by 30 seconds

<12>Jun 19 00:07:26 NSX-MANAGER 2017-06-19 00:07:26.102 UTC  WARN vixCommandExecutor-1 VixCommandExecutor:336 - Host update required for VMId vm-421, delaying command execution by 30 seconds

<12>Jun 19 00:07:59 NSX-MANAGER 2017-06-19 00:07:59.536 UTC  WARN ViInventoryThread ViManagedVirtualMachineProps:317 - Skipping as NIC already exists with ID : vm-419:-1

<14>Jun 19 00:07:59 NSX-MANAGER 2017-06-19 00:07:59.536 UTC  INFO ViInventoryThread ViInventory:5031 - Virtual Center: Updating Inventory. new:0 modified:1 removed:0

<14>Jun 19 00:07:59 NSX-MANAGER 2017-06-19 00:07:59.544 UTC  INFO ViInventoryThread EndpointSVMUpdater:206 - Solution 6341068275337691137 is not registered

<14>Jun 19 00:07:59 NSX-MANAGER 2017-06-19 00:07:59.568 UTC  INFO ViInventoryThread ViInventory:1329 - 129/273 objects published.

<14>Jun 19 00:07:59 NSX-MANAGER 2017-06-19 00:07:59.569 UTC  INFO ViInventoryThread VimObjectBridge:954 - VimObjectBridge: Ending inventory update

<14>Jun 19 00:07:59 NSX-MANAGER 2017-06-19 00:07:59.569 UTC  INFO ViInventoryThread VimObjectBridge:222 - Processing 1 updates and 0 deletions for this transaction

<14>Jun 19 00:07:59 NSX-MANAGER 2017-06-19 00:07:59.570 UTC  INFO ViInventoryThread VimObjectBridge:227 - VimObjectBridge: Time taken to process transaction : 16

<14>Jun 19 00:07:59 NSX-MANAGER 2017-06-19 00:07:59.570 UTC  INFO ViInventoryThread ViInventory:1692 - cleared the deleted objects set

<14>Jun 19 00:07:59 NSX-MANAGER 2017-06-19 00:07:59.570 UTC  INFO ViInventoryThread ViInventory:1545 - Resolved, last version:82 num vc objs:157 num vimos:273

<12>Jun 19 00:07:59 NSX-MANAGER 2017-06-19 00:07:59.795 UTC  WARN ViInventoryThread ViManagedVirtualMachineProps:317 - Skipping as NIC already exists with ID : vm-421:-1

<14>Jun 19 00:07:59 NSX-MANAGER 2017-06-19 00:07:59.796 UTC  INFO ViInventoryThread ViInventory:5031 - Virtual Center: Updating Inventory. new:0 modified:1 removed:0

<14>Jun 19 00:07:59 NSX-MANAGER 2017-06-19 00:07:59.803 UTC  INFO ViInventoryThread EndpointSVMUpdater:206 - Solution 6341068275337691137 is not registered

<14>Jun 19 00:07:59 NSX-MANAGER 2017-06-19 00:07:59.826 UTC  INFO ViInventoryThread ViInventory:1329 - 129/273 objects published.

<14>Jun 19 00:07:59 NSX-MANAGER 2017-06-19 00:07:59.827 UTC  INFO ViInventoryThread VimObjectBridge:954 - VimObjectBridge: Ending inventory update

<14>Jun 19 00:07:59 NSX-MANAGER 2017-06-19 00:07:59.827 UTC  INFO ViInventoryThread VimObjectBridge:222 - Processing 1 updates and 0 deletions for this transaction

<14>Jun 19 00:07:59 NSX-MANAGER 2017-06-19 00:07:59.828 UTC  INFO ViInventoryThread VimObjectBridge:227 - VimObjectBridge: Time taken to process transaction : 16

<14>Jun 19 00:07:59 NSX-MANAGER 2017-06-19 00:07:59.828 UTC  INFO ViInventoryThread ViInventory:1692 - cleared the deleted objects set

<14>Jun 19 00:07:59 NSX-MANAGER 2017-06-19 00:07:59.828 UTC  INFO ViInventoryThread ViInventory:1545 - Resolved, last version:83 num vc objs:157 num vimos:273

<14>Jun 19 00:08:02 NSX-MANAGER 2017-06-19 00:08:02.603 UTC  INFO pool-21-thread-1 StatusAndStatsUtil:879 - Propogating vse event EDGE_VM_POWER_ON Module: vShield Edge Appliance Severity Informational

<14>Jun 19 00:08:02 NSX-MANAGER 2017-06-19 00:08:02.603 UTC  INFO pool-21-thread-1 EdgeUtils:315 - SysEvent-Detailed-Message :(Kept only in logs) :: vShield Edge was Booted.

<14>Jun 19 00:08:02 NSX-MANAGER 2017-06-19 00:08:02.604 UTC  INFO pool-21-thread-1 EdgeUtils:316 - populateSystemEvent parameters : sourceName edge-1, morefIdOfObjectOnVc vm-419, moduleName vShield Edge Appliance, eventCode EDGE_VM_POWER_ON, severity Informational, messageParams [] eventMetaData {edgeId=edge-1, edgeVmName=ESG01-1, edgeVmId=vm-419}

<14>Jun 19 00:08:02 NSX-MANAGER 2017-06-19 00:08:02.609 UTC  INFO pool-21-thread-1 SystemEventDaoImpl:133 - [SystemEvent] Time:'Mon Jun 19 00:07:58.000 UTC 2017', Severity:'Informational', Event Source:'edge-1', Code:'30101', Event Message:'NSX Edge was booted', Module:'vShield Edge Appliance', Universal Object:'false'

<14>Jun 19 00:08:02 NSX-MANAGER 2017-06-19 00:08:02.623 UTC  INFO pool-21-thread-1 AbstractEdgeApplianceManager:578 - Downloading file '/var/log/events/events.old' from VSE 'vm-419' to location '/tmp/events.edge-1' on VSM

<14>Jun 19 00:08:03 NSX-MANAGER 2017-06-19 00:08:03.635 UTC  INFO pool-21-thread-1 StatusAndStatsUtil:879 - Propogating vse event EDGE_VM_POWER_ON Module: vShield Edge Appliance Severity Informational

<14>Jun 19 00:08:03 NSX-MANAGER 2017-06-19 00:08:03.635 UTC  INFO pool-21-thread-1 EdgeUtils:315 - SysEvent-Detailed-Message :(Kept only in logs) :: vShield Edge was Booted.

<14>Jun 19 00:08:03 NSX-MANAGER 2017-06-19 00:08:03.636 UTC  INFO pool-21-thread-1 EdgeUtils:316 - populateSystemEvent parameters : sourceName edge-5, morefIdOfObjectOnVc vm-421, moduleName vShield Edge Appliance, eventCode EDGE_VM_POWER_ON, severity Informational, messageParams [] eventMetaData {edgeId=edge-5, edgeVmName=ESG02-1, edgeVmId=vm-421}

<14>Jun 19 00:08:03 NSX-MANAGER 2017-06-19 00:08:03.639 UTC  INFO pool-21-thread-1 SystemEventDaoImpl:133 - [SystemEvent] Time:'Mon Jun 19 00:07:57.000 UTC 2017', Severity:'Informational', Event Source:'edge-5', Code:'30101', Event Message:'NSX Edge was booted', Module:'vShield Edge Appliance', Universal Object:'false'

<14>Jun 19 00:08:03 NSX-MANAGER 2017-06-19 00:08:03.646 UTC  INFO pool-21-thread-1 AbstractEdgeApplianceManager:578 - Downloading file '/var/log/events/events.old' from VSE 'vm-421' to location '/tmp/events.edge-5' on VSM

---cut---

Context:

These ESGs are deployed on a non-NSX cluster and are thus using VIX for communication with NSX manager. The nodes are at 5.5u3 and not prepared for NSX (no VXLAN, no DLR, only ESG appliances hosting).

Thanks for any pointers.

[mhampto]

Hello,

Looked through some of our existing bugs the "Message:'NSX Edge was booted'" error is pretty generic and the other log entry does not narrow down the issue. With this appearing on hosts that are not part of NSX, these messages appear benign, though if you want to investigate them further and confirm, please open a Support Request.