Time of Issue: 7th Nov in between 12 pm to 5 pm SGT

Time in GMT:  7th Nov in between 4:00 AM to 9:00 AM GMT

Hostname: vxyzcldesx0106a.vpc.ind.abc.com

ESXi Version: VMware ESXi 6.7.0 build-16075168

Hostd Logs:

• Tracking the vMotion Operation of VM: abcgtappdb1a from 11.119.202.46  to ESXi Host with IP : 11.119.202.45.

2020-11-07T06:48:45.116Z info hostd[2101310] [Originator@6876 sub=Vcsvc.VMotion opID=kcafy66f-1865100-auto-13z4e-h5:70262681-d6-01-5d-be53 user=vpxuser:VPC.IND.ABC.COM\abcdefghij] PrepareSourceEx [4875840848257183182], VM = ’96’
2020-11-07T06:48:45.117Z info hostd[2101310] [Originator@6876 sub=Vcsvc.VMotionSrc.4875840848257183182 opID=kcafy66f-1865100-auto-13z4e-h5:70262681-d6-01-5d-be53 user=vpxuser:VPC.IND.ABC.COM\abcdefghij] VMotionEntry: migrateType = 1
2020-11-07T06:48:45.117Z info hostd[2101310] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e8f8-51d02cd6-259a-b496915f4dfc/abcgtappdb1a/abcgtappdb1a.vmx opID=kcafy66f-1865100-auto-13z4e-h5:70262681-d6-01-5d-be53 user=vpxuser:VPC.IND.ABC.COM\abcdefghij] State Transition (VM_STATE_ON -> VM_STATE_EMIGRATING)

2020-11-07T06:48:45.117Z error hostd[2103226] [Originator@6876 sub=Snmpsvc] VmConfigListener: unknown msg PN7Vmacore6ObjectE, ignored.
2020-11-07T06:48:45.120Z info hostd[2101310] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e8f8-51d02cd6-259a-b496915f4dfc/abcgtappdb1a/abcgtappdb1a.vmx opID=kcafy66f-1865100-auto-13z4e-h5:70262681-d6-01-5d-be53 user=vpxuser:VPC.IND.ABC.COM\abcdefghij] VMotionPrepare: srcLoggingIp=
2020-11-07T06:48:45.120Z info hostd[2101310] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e8f8-51d02cd6-259a-b496915f4dfc/abcgtappdb1a/abcgtappdb1a.vmx opID=kcafy66f-1865100-auto-13z4e-h5:70262681-d6-01-5d-be53 user=vpxuser:VPC.IND.ABC.COM\abcdefghij] VMotionPrepare: dstLoggingIp=
2020-11-07T06:48:45.120Z info hostd[2101310] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e8f8-51d02cd6-259a-b496915f4dfc/abcgtappdb1a/abcgtappdb1a.vmx opID=kcafy66f-1865100-auto-13z4e-h5:70262681-d6-01-5d-be53 user=vpxuser:VPC.IND.ABC.COM\abcdefghij] VMotionPrepare 4875840848257183182: ftPrimaryIp=
2020-11-07T06:48:45.120Z info hostd[2101310] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e8f8-51d02cd6-259a-b496915f4dfc/abcgtappdb1a/abcgtappdb1a.vmx opID=kcafy66f-1865100-auto-13z4e-h5:70262681-d6-01-5d-be53 user=vpxuser:VPC.IND.ABC.COM\abcdefghij] VMotionPrepare 4875840848257183182: ftSecondaryIp=
2020-11-07T06:48:45.120Z info hostd[2101310] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e8f8-51d02cd6-259a-b496915f4dfc/abcgtappdb1a/abcgtappdb1a.vmx opID=kcafy66f-1865100-auto-13z4e-h5:70262681-d6-01-5d-be53 user=vpxuser:VPC.IND.ABC.COM\abcdefghij] VMotionPrepare: srcMgmtIp=11.119.201.46
2020-11-07T06:48:45.120Z info hostd[2101310] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e8f8-51d02cd6-259a-b496915f4dfc/abcgtappdb1a/abcgtappdb1a.vmx opID=kcafy66f-1865100-auto-13z4e-h5:70262681-d6-01-5d-be53 user=vpxuser:VPC.IND.ABC.COM\abcdefghij] VMotionPrepare: dstMgmtIp=11.119.201.45
2020-11-07T06:48:45.120Z info hostd[2101310] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e8f8-51d02cd6-259a-b496915f4dfc/abcgtappdb1a/abcgtappdb1a.vmx opID=kcafy66f-1865100-auto-13z4e-h5:70262681-d6-01-5d-be53 user=vpxuser:VPC.IND.ABC.COM\abcdefghij] VMotionPrepare: dstVmDirPath=/vmfs/volumes/5dc0e8f8-51d02cd6-259a-b496915f4dfc/abcgtappdb1a/
2020-11-07T06:48:45.120Z info hostd[2101310] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e8f8-51d02cd6-259a-b496915f4dfc/abcgtappdb1a/abcgtappdb1a.vmx opID=kcafy66f-1865100-auto-13z4e-h5:70262681-d6-01-5d-be53 user=vpxuser:VPC.IND.ABC.COM\abcdefghij] VMotionPrepare: dstVmFileName=abcgtappdb1a.vmx
2020-11-07T06:48:45.120Z info hostd[2101310] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e8f8-51d02cd6-259a-b496915f4dfc/abcgtappdb1a/abcgtappdb1a.vmx opID=kcafy66f-1865100-auto-13z4e-h5:70262681-d6-01-5d-be53 user=vpxuser:VPC.IND.ABC.COM\abcdefghij] Handling 0 deviceChanges
2020-11-07T06:48:45.120Z info hostd[2101310] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e8f8-51d02cd6-259a-b496915f4dfc/abcgtappdb1a/abcgtappdb1a.vmx opID=kcafy66f-1865100-auto-13z4e-h5:70262681-d6-01-5d-be53 user=vpxuser:VPC.IND.ABC.COM\abcdefghij] VMotionPrepare (4875840848257183182): Sending ‘to’ srcIp=11.119.202.46 dstIp=11.119.202.45, type=1, encrypted=, remoteThumbprint=A3:88:A5:85:6E:0B:58:6D:9D:3C:F2:2C:A8:39:13:28:6E:39:E5:B1
2020-11-07T06:48:45.122Z info hostd[2101310] [Originator@6876 sub=Libs opID=kcafy66f-1865100-auto-13z4e-h5:70262681-d6-01-5d-be53 user=vpxuser:VPC.IND.ABC.COM\abcdefghij] SIOC: SIOC is notified not to start injector
2020-11-07T06:48:45.122Z info hostd[2101310] [Originator@6876 sub=Vcsvc.VMotion opID=kcafy66f-1865100-auto-13z4e-h5:70262681-d6-01-5d-be53 user=vpxuser:VPC.IND.ABC.COM\abcdefghij] Completed scheduling PrepareSourceEx [4875840848257183182]
2020-11-07T06:48:45.141Z info hostd[2101312] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e8f8-51d02cd6-259a-b496915f4dfc/abcgtappdb1a/abcgtappdb1a.vmx] VigorMigrateNotifyCb:: hostlog state changed from none to emigrating
2020-11-07T06:48:45.160Z info hostd[2101312] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e8f8-51d02cd6-259a-b496915f4dfc/abcgtappdb1a/abcgtappdb1a.vmx] VMotionStatusCb [4875840848257183182] : Prepare task completed successfully
2020-11-07T06:48:45.488Z info hostd[2102014] [Originator@6876 sub=Vcsvc.VMotion opID=kcafy66f-1865100-auto-13z4e-h5:70262681-d6-01-5d-be5c user=vpxuser:VPC.IND.ABC.COM\abcdefghij] InitiateSource [4875840848257183182], WID = 3554220
2020-11-07T06:48:45.489Z info hostd[2102014] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e8f8-51d02cd6-259a-b496915f4dfc/abcgtappdb1a/abcgtappdb1a.vmx opID=kcafy66f-1865100-auto-13z4e-h5:70262681-d6-01-5d-be5c user=vpxuser:VPC.IND.ABC.COM\abcdefghij] GetWid: got 3142607
2020-11-07T06:48:45.491Z info hostd[2102014] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e8f8-51d02cd6-259a-b496915f4dfc/abcgtappdb1a/abcgtappdb1a.vmx opID=kcafy66f-1865100-auto-13z4e-h5:70262681-d6-01-5d-be5c user=vpxuser:VPC.IND.ABC.COM\abcdefghij] VMotionInitiateSrc (4875840848257183182): wid=3554220

2020-11-07T06:50:49.848Z info hostd[2103121] [Originator@6876 sub=Vcsvc.VMotionSrc.4875840848257183182] ResolveCb: VMX reports needsUnregister = true for migrateType MIGRATE_TYPE_VMOTION
2020-11-07T06:50:49.848Z info hostd[2103121] [Originator@6876 sub=Vcsvc.VMotionSrc.4875840848257183182] ResolveCb: Succeeded
2020-11-07T06:50:49.854Z info hostd[2103121] [Originator@6876 sub=Vcsvc.VMotionSrc.4875840848257183182] CompleteOp: Vmotion task succeeded with result: (vim.host.VMotionManager.SrcVMotionResult) {
–>    vmDowntime = 30055016,
–>    vmPrecopyStunTime = 950067,
–>    vmPrecopyBandwidth = 185874910
2020-11-07T06:50:50.212Z info hostd[2314670] [Originator@6876 sub=Vcsvc.VMotion opID=kcafy66f-1865100-auto-13z4e-h5:70262681-d6-01-3c-c1b0 user=vpxuser:VPC.IND.ABC.COM\abcdefghij] CompleteSource [4875840848257183182]

VMKernel Logs:

• From the Source Vmkernel Logs we can see the Operation for Pre-Copy is going on. However cannot continue to Investigate this as there are no logs available for Dst IP: 11.119.202.45

2020-11-07T06:48:45.495Z cpu79:3142606)Migrate: vm 3142607: 3885: Setting VMOTION info: Source ts = 4875840848257183182, src ip = <11.119.202.46> dest ip = <11.119.202.45> Dest wid = 3554220 using SHARED swap, encrypted
2020-11-07T06:48:45.497Z cpu64:3555377)MigrateNet: 1751: 4875840848257183182 S: Successfully bound connection to vmknic vmk1 – ‘11.119.202.46′
2020-11-07T06:48:45.499Z cpu71:3555377)MigrateNet: 1751: 4875840848257183182 S: Successfully bound connection to vmknic vmk1 – ‘11.119.202.46′
2020-11-07T06:48:45.500Z cpu71:3555377)VMotionUtil: 5199: 4875840848257183182 S: Stream connection 1 added.
2020-11-07T06:50:16.543Z cpu0:3142607)VMotion: 5367: 4875840848257183182 S: Another pre-copy iteration needed with 206830 pages left to send (prev2 4194304, prev 4194304, pages dirtied by pass through device 0, network bandwidth ~177.478 MB/s, 7312% t2d)

2020-11-07T06:50:19.177Z cpu7:3142607)VMotion: 5277: 4875840848257183182 S: Stopping pre-copy: only 18543 pages left to send, which can be sent within the switchover time goal of 0.500 seconds (network bandwidth ~185.557 MB/s, 1106% t2d)
2020-11-07T06:50:49.683Z cpu110:3555377)VMotionSend: 5095: 4875840848257183182 S: Sent all modified pages to destination (network bandwidth ~195.415 MB/s)

===================================================================================================================

• Checking another Occurrence:

Hostd Logs:

• Started to Track another vMotion event from Source IP: 11.119.201.46 and dst IP: 11.119.201.45. However skipping it because we don’t have the logs for ESXI Host vxyzcldesx0105a

2020-11-07T06:47:45.366Z info hostd[2101523] [Originator@6876 sub=Vcsvc.VMotion opID=kcafy66f-1865088-auto-13z43-h5:70262677-a8-01-76-bc2b user=vpxuser:VPC.IND.ABC.COM\abcdefghij] PrepareSourceEx [4875840848257105227], VM = ‘106’
2020-11-07T06:47:45.366Z info hostd[2101523] [Originator@6876 sub=Vcsvc.VMotionSrc.4875840848257105227 opID=kcafy66f-1865088-auto-13z43-h5:70262677-a8-01-76-bc2b user=vpxuser:VPC.IND.ABC.COM\abcdefghij] VMotionEntry: migrateType = 1
2020-11-07T06:47:45.366Z info hostd[2101523] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e90f-efe1c56e-70e7-b496915f4dfc/ABCGICTSAPP2A/ABCGICTSAPP2A.vmx opID=kcafy66f-1865088-auto-13z43-h5:70262677-a8-01-76-bc2b user=vpxuser:VPC.IND.ABC.COM\abcdefghij] State Transition (VM_STATE_ON -> VM_STATE_EMIGRATING)
2020-11-07T06:47:45.369Z info hostd[2101523] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e90f-efe1c56e-70e7-b496915f4dfc/ABCGICTSAPP2A/ABCGICTSAPP2A.vmx opID=kcafy66f-1865088-auto-13z43-h5:70262677-a8-01-76-bc2b user=vpxuser:VPC.IND.ABC.COM\abcdefghij] VMotionPrepare: srcLoggingIp=
2020-11-07T06:47:45.369Z info hostd[2101523] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e90f-efe1c56e-70e7-b496915f4dfc/ABCGICTSAPP2A/ABCGICTSAPP2A.vmx opID=kcafy66f-1865088-auto-13z43-h5:70262677-a8-01-76-bc2b user=vpxuser:VPC.IND.ABC.COM\abcdefghij] VMotionPrepare: dstLoggingIp=
2020-11-07T06:47:45.369Z info hostd[2101523] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e90f-efe1c56e-70e7-b496915f4dfc/ABCGICTSAPP2A/ABCGICTSAPP2A.vmx opID=kcafy66f-1865088-auto-13z43-h5:70262677-a8-01-76-bc2b user=vpxuser:VPC.IND.ABC.COM\abcdefghij] VMotionPrepare 4875840848257105227: ftPrimaryIp=
2020-11-07T06:47:45.369Z info hostd[2101523] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e90f-efe1c56e-70e7-b496915f4dfc/ABCGICTSAPP2A/ABCGICTSAPP2A.vmx opID=kcafy66f-1865088-auto-13z43-h5:70262677-a8-01-76-bc2b user=vpxuser:VPC.IND.ABC.COM\abcdefghij] VMotionPrepare 4875840848257105227: ftSecondaryIp=
2020-11-07T06:47:45.369Z info hostd[2101523] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e90f-efe1c56e-70e7-b496915f4dfc/ABCGICTSAPP2A/ABCGICTSAPP2A.vmx opID=kcafy66f-1865088-auto-13z43-h5:70262677-a8-01-76-bc2b user=vpxuser:VPC.IND.ABC.COM\abcdefghij] VMotionPrepare: srcMgmtIp=11.119.201.46
2020-11-07T06:47:45.369Z info hostd[2101523] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e90f-efe1c56e-70e7-b496915f4dfc/ABCGICTSAPP2A/ABCGICTSAPP2A.vmx opID=kcafy66f-1865088-auto-13z43-h5:70262677-a8-01-76-bc2b user=vpxuser:VPC.IND.ABC.COM\abcdefghij] VMotionPrepare: dstMgmtIp=11.119.201.45
2020-11-07T06:47:45.369Z info hostd[2101523] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e90f-efe1c56e-70e7-b496915f4dfc/ABCGICTSAPP2A/ABCGICTSAPP2A.vmx opID=kcafy66f-1865088-auto-13z43-h5:70262677-a8-01-76-bc2b user=vpxuser:VPC.IND.ABC.COM\abcdefghij] VMotionPrepare: dstVmDirPath=/vmfs/volumes/5dc0e90f-efe1c56e-70e7-b496915f4dfc/ABCGICTSAPP2A/
2020-11-07T06:47:45.369Z info hostd[2101523] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e90f-efe1c56e-70e7-b496915f4dfc/ABCGICTSAPP2A/ABCGICTSAPP2A.vmx opID=kcafy66f-1865088-auto-13z43-h5:70262677-a8-01-76-bc2b user=vpxuser:VPC.IND.ABC.COM\abcdefghij] VMotionPrepare: dstVmFileName=ABCGICTSAPP2A.vmx
2020-11-07T06:47:45.369Z info hostd[2101523] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e90f-efe1c56e-70e7-b496915f4dfc/ABCGICTSAPP2A/ABCGICTSAPP2A.vmx opID=kcafy66f-1865088-auto-13z43-h5:70262677-a8-01-76-bc2b user=vpxuser:VPC.IND.ABC.COM\abcdefghij] Handling 0 deviceChanges
2020-11-07T06:47:45.369Z info hostd[2101523] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e90f-efe1c56e-70e7-b496915f4dfc/ABCGICTSAPP2A/ABCGICTSAPP2A.vmx opID=kcafy66f-1865088-auto-13z43-h5:70262677-a8-01-76-bc2b user=vpxuser:VPC.IND.ABC.COM\abcdefghij] VMotionPrepare (4875840848257105227): Sending ‘to’ srcIp=11.119.202.46 dstIp=11.119.202.45, type=1, encrypted=, remoteThumbprint=A3:88:A5:85:6E:0B:58:6D:9D:3C:F2:2C:A8:39:13:28:6E:39:E5:B1
2020-11-07T06:47:45.371Z info hostd[2101523] [Originator@6876 sub=Libs opID=kcafy66f-1865088-auto-13z43-h5:70262677-a8-01-76-bc2b user=vpxuser:VPC.IND.ABC.COM\abcdefghij] SIOC: SIOC is notified not to start injector
2020-11-07T06:47:45.371Z info hostd[2101523] [Originator@6876 sub=Vcsvc.VMotion opID=kcafy66f-1865088-auto-13z43-h5:70262677-a8-01-76-bc2b user=vpxuser:VPC.IND.ABC.COM\abcdefghij] Completed scheduling PrepareSourceEx [4875840848257105227]
2020-11-07T06:47:45.400Z info hostd[2102188] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e90f-efe1c56e-70e7-b496915f4dfc/ABCGICTSAPP2A/ABCGICTSAPP2A.vmx] VMotionStatusCb [4875840848257105227] : Prepare task completed successfully
2020-11-07T06:47:45.828Z info hostd[2102133] [Originator@6876 sub=Vcsvc.VMotion opID=kcafy66f-1865088-auto-13z43-h5:70262677-a8-01-c9-bc4c user=vpxuser:VPC.IND.ABC.COM\abcdefghij] InitiateSource [4875840848257105227], WID = 3554125
2020-11-07T06:47:45.832Z info hostd[2102133] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e90f-efe1c56e-70e7-b496915f4dfc/ABCGICTSAPP2A/ABCGICTSAPP2A.vmx opID=kcafy66f-1865088-auto-13z43-h5:70262677-a8-01-c9-bc4c user=vpxuser:VPC.IND.ABC.COM\abcdefghij] VMotionInitiateSrc (4875840848257105227): wid=3554125
2020-11-07T06:49:36.234Z info hostd[2102187] [Originator@6876 sub=Vcsvc.VMotionSrc.4875840848257105227] ResolveCb: VMX reports needsUnregister = true for migrateType MIGRATE_TYPE_VMOTION
2020-11-07T06:49:36.234Z info hostd[2102187] [Originator@6876 sub=Vcsvc.VMotionSrc.4875840848257105227] ResolveCb: Succeeded
2020-11-07T06:49:36.241Z info hostd[2102187] [Originator@6876 sub=Vcsvc.VMotionSrc.4875840848257105227] CompleteOp: Vmotion task succeeded with result: (vim.host.VMotionManager.SrcVMotionResult) {
–>    vmDowntime = 30155081,
2020-11-07T06:49:36.510Z info hostd[2102137] [Originator@6876 sub=Vcsvc.VMotion opID=kcafy66f-1865088-auto-13z43-h5:70262677-a8-01-9b-bfec user=vpxuser:VPC.IND.ABC.COM\abcdefghij] CompleteSource [4875840848257105227]

===================================================================================================================

• Checking another Occurrence:

• Here we can see that VM: ABCGICTSAPP4A Migrated from Source IP: 11.119.201.42 and 11.119.201.41 and the VmDowntime Value is: 30058581 i.e. 30 Seconds.

VM Name: ABCGICTSAPP4A

Source Logging:

• From the Vmware Logs we can see that the Migration Event started from: 8:17.26 GMT – 8:19.01 GMT i.e. 2 Minutes.

2020-11-07T08:17:26.134Z| vmx| I125: Received migrate ‘to’ request for mid id 4875840853626506769, src ip <11.119.202.42>, dst ip <11.119.202.41>(invalidate source config).
2020-11-07T08:17:26.135Z| vmx| I125: MigrateSetInfo: state=1 srcIp=<11.119.202.42> dstIp=<11.119.202.41> mid=4875840853626506769 uuid=4c4c4544-0059-5a10-804b-b5c04f525a32 priority=high
2020-11-07T08:17:26.135Z| vmx| I125: MigrateSetState: Transitioning from state 0 to 1.
2020-11-07T08:17:26.141Z| vmx| I125: MigrateReadHostLog: Hostlog’s migID 4875834475184592293 doesn’t match active migID 4875840853626506769.  Resetting hostlog state.
2020-11-07T08:17:26.141Z| vmx| I125: MigrateReadHostLog: Hostlog_Dump: Hostlog ABCGICTSAPP4A-0d61fc26.hlog
2020-11-07T08:17:26.141Z| vmx| I125:    UUID: [placeholder uuid]
2020-11-07T08:17:26.141Z| vmx| I125:    MigID: 0
2020-11-07T08:17:26.141Z| vmx| I125:    HLState: none
2020-11-07T08:17:26.141Z| vmx| I125:    ToFrom: to
2020-11-07T08:17:26.141Z| vmx| I125:    MigType: invalid
2020-11-07T08:17:26.141Z| vmx| I125:    OpType: vmotion
2020-11-07T08:17:26.141Z| vmx| I125:    WorldID: 0
2020-11-07T08:17:26.158Z| vmx| A100: ConfigDB: Setting config.readOnly = “TRUE”
2020-11-07T08:17:26.159Z| vmx| I125: VigorTransport_ServerSendResponse opID=kcafy66f-1994887-auto-16r9m-h5:70265139-a4-01-ea-1221 seq=2347330: Completed Migrate request.
2020-11-07T08:17:26.543Z| vmx| I125: VigorTransportProcessClientPayload: opID=kcafy66f-1994887-auto-16r9m-h5:70265139-a4-01-e5-1246 seq=2347339: Receiving Migrate.MigrateSource request.
2020-11-07T08:17:26.543Z| vmx| I125: Received migrate ‘start’ request for mig id 4875840853626506769, dest world id 4102756.
2020-11-07T08:17:26.543Z| vmx| I125: MigrateSetState: Transitioning from state 1 to 2.

2020-11-07T08:17:26.555Z| worker-3143031| I125: vxtap(sr_quiesce_svd:555) INFO svd_ndx 0: called
2020-11-07T08:17:26.555Z| worker-3143031| I125: vxtap(sr_quiesce_svd:569) INFO svd_ndx 0: incrementing skip shmem = 1 task 2057446C30
2020-11-07T08:17:26.555Z| worker-3143031| I125: vxtap(sr_quiesce_svd:582) INFO svd_ndx 0: SVD quiesce initiated. pending IOs = 0, pending tasks = 1
2020-11-07T08:17:26.555Z| worker-3143031| I125: vxtap(sr_quiesce_svd:593) INFO svd_ndx 0: setting up timer to execute quiesce_svd tasks
2020-11-07T08:17:26.555Z| worker-3143031| I125: vxtap(sr_quiesce_svd:608) INFO svd_ndx 0: successfully setup timer to execute quiesce_svd tasks
2020-11-07T08:17:26.555Z| worker-3143031| I125: vxtap(sr_quiesce_svd:617) INFO svd_ndx 0: returning
2020-11-07T08:17:26.555Z| worker-3143031| I125: vxtap(sr_vm_migration:4891) INFO Timer to report migration progress started
2020-11-07T08:17:26.555Z| filtPoll| I125: vxtap(sr_execute_svd_quiesce_tasks:379) INFO svd_ndx 0: called
2020-11-07T08:17:26.555Z| filtPoll| I125: vxtap(sr_execute_svd_quiesce_tasks:390) INFO svd_ndx 0: taskq_cnt = 1, p_entry 2057446C48, executing 0, is_last_task_full_sync 0
2020-11-07T08:17:26.555Z| filtPoll| I125: vxtap(sr_li_change_state:1747) INFO svd_ndx 0: Request to change LI state from LI_STATE_ACTIVE, pause PAUSE_NONE, sync 0 to LI_STATE_PAUSED, pause PAUSE_EVENT, sync 0, reason 0
2020-11-07T08:17:26.555Z| filtPoll| I125: vxtap(sr_abort_sync_and_clean:1995) INFO svd_ndx 0: No sync in progress
2020-11-07T08:17:26.555Z| filtPoll| I125: vxtap(sr_abort_sync_and_clean:2004) INFO svd_ndx 0: No drl clear in progress
2020-11-07T08:17:26.555Z| filtPoll| I125: vxtap(sr_abort_sync_and_clean:2097) INFO svd_ndx 0: Aborting of sync and DRL clear is complete
2020-11-07T08:17:26.555Z| filtPoll| I125: vxtap(sr_li_trans_from_active:1668) INFO svd_ndx 0: PAUSE_EVENT: disconnecting from daemon
2020-11-07T08:17:26.555Z| filtPoll| I125: vxtap(sr_disconnect_daemon:3991) INFO svd_ndx 0: disconnecting from daemon
2020-11-07T08:17:26.555Z| filtPoll| I125: vxtap(sr_disconnect_daemon:4019) INFO svd_ndx 0: daemon poll remove
2020-11-07T08:17:26.555Z| filtPoll| I125: vxtap(sr_li_change_state:1772) INFO svd_ndx 0: New LI state LI_STATE_PAUSED, pause PAUSE_EVENT, sync 0 res 0
2020-11-07T08:17:26.555Z| filtPoll| I125: vxtap(sr_execute_svd_quiesce_tasks:422) INFO svd_ndx 0: decrementing skip shmem = 0, task 2057446C30
2020-11-07T08:17:26.556Z| filtPoll| I125: vxtap(sr_execute_svd_quiesce_tasks:440) INFO svd_ndx 0: returning
2020-11-07T08:17:26.556Z| filtPoll| I125: vxtap(sr_svd_quiesce_timer:508) INFO svd_ndx 0: Execution of quiesce callback tasks completed
2020-11-07T08:17:26.556Z| filtPoll| I125: vxtap(sr_unquiesce_svd:629) INFO SVD unquiesce start
2020-11-07T08:17:26.556Z| filtPoll| I125: vxtap(sr_unquiesce_svd:640) INFO SVD unquiesce end. pending IOs = 0
2020-11-07T08:17:31.557Z| filtPoll| I125: vxtap(sr_event_progress_timer_cb:4375) INFO handle 200BFB7580: event progress timer done.
2020-11-07T08:17:31.557Z| worker-3143031| I125: vxtap(sr_quiesce_svd:582) INFO svd_ndx 1: SVD quiesce initiated. pending IOs = 0, pending tasks = 1
2020-11-07T08:17:31.557Z| worker-3143031| I125: vxtap(sr_quiesce_svd:593) INFO svd_ndx 1: setting up timer to execute quiesce_svd tasks
2020-11-07T08:17:31.557Z| worker-3143031| I125: vxtap(sr_quiesce_svd:608) INFO svd_ndx 1: successfully setup timer to execute quiesce_svd tasks
2020-11-07T08:17:31.557Z| filtPoll| I125: vxtap(sr_execute_svd_quiesce_tasks:390) INFO svd_ndx 1: taskq_cnt = 1, p_entry 2057E1CB38, executing 0, is_last_task_full_sync 0
2020-11-07T08:17:31.557Z| worker-3143031| I125: vxtap(sr_vm_migration:4891) INFO Timer to report migration progress started
2020-11-07T08:17:31.557Z| filtPoll| I125: vxtap(sr_li_change_state:1747) INFO svd_ndx 1: Request to change LI state from LI_STATE_ACTIVE, pause PAUSE_NONE, sync 0 to LI_STATE_PAUSED, pause PAUSE_EVENT, sync 0, reason 0
2020-11-07T08:17:31.557Z| filtPoll| I125: vxtap(sr_abort_sync_and_clean:1995) INFO svd_ndx 1: No sync in progress
2020-11-07T08:17:31.557Z| filtPoll| I125: vxtap(sr_abort_sync_and_clean:2004) INFO svd_ndx 1: No drl clear in progress
2020-11-07T08:17:31.557Z| filtPoll| I125: vxtap(sr_li_change_state:1772) INFO svd_ndx 1: New LI state LI_STATE_PAUSED, pause PAUSE_EVENT, sync 0 res 0
2020-11-07T08:17:36.559Z| filtPoll| I125: vxtap(sr_event_progress_timer_cb:4380) INFO handle 200BFB72E0: completed IO percentage = 100
2020-11-07T08:17:36.560Z| worker-3143031| I125: vxtap(sr_quiesce_svd:608) INFO svd_ndx 2: successfully setup timer to execute quiesce_svd tasks
2020-11-07T08:17:36.560Z| worker-3143031| I125: vxtap(sr_quiesce_svd:617) INFO svd_ndx 2: returning
2020-11-07T08:17:36.560Z| worker-3143031| I125: vxtap(sr_vm_migration:4891) INFO Timer to report migration progress started
2020-11-07T08:17:36.560Z| filtPoll| I125: vxtap(sr_li_change_state:1747) INFO svd_ndx 2: Request to change LI state from LI_STATE_ACTIVE, pause PAUSE_NONE, sync 0 to LI_STATE_PAUSED, pause PAUSE_EVENT, sync 0, reason 0
2020-11-07T08:17:41.562Z| worker-3143031| I125: vxtap(sr_vm_migration:4808) INFO Event ==> Inside xMigration, phase = PREPARE
2020-11-07T08:17:41.562Z| worker-3143031| I125: vxtap(sr_quiesce_svd:555) INFO svd_ndx 3: called
2020-11-07T08:17:41.562Z| filtPoll| I125: vxtap(sr_li_change_state:1747) INFO svd_ndx 3: Request to change LI state from LI_STATE_ACTIVE, pause PAUSE_NONE, sync 0 to LI_STATE_PAUSED, pause PAUSE_EVENT, sync 0, reason 0

2020-11-07T08:17:56.820Z| vmx| I125: Sidecar_SetOpenFlags: Failed to set open flags for sidecar ‘vtstap_5’, Operation not supported.
2020-11-07T08:17:56.820Z| vmx| I125: DISKLIB-LIB_SIDECAR : DiskLib_SidecarSetOpenFlags: Failed to set open flags for sidecar ‘vtstap_5’, Operation not supported.
2020-11-07T08:17:56.820Z| vmx| I125: DISKLIB-LIB_MISC   : DiskLib_SetOpenFlags: Failed to set open flags for sidecars: The virtual disk requires a feature not supported by this program (57)
2020-11-07T08:17:56.820Z| vmx| I125: Sidecar_SetOpenFlags: Failed to set open flags for sidecar ‘vtstap_5’, Operation not supported.
2020-11-07T08:17:56.820Z| vmx| I125: DISKLIB-LIB_SIDECAR : DiskLib_SidecarSetOpenFlags: Failed to set open flags for sidecar ‘vtstap_5’, Operation not supported.
2020-11-07T08:17:56.820Z| vmx| I125: DISKLIB-LIB_MISC   : DiskLib_SetOpenFlags: Failed to set open flags for sidecars: The virtual disk requires a feature not supported by this program (57)
2020-11-07T08:17:56.820Z| vmx| I125: Sidecar_SetOpenFlags: Failed to set open flags for sidecar ‘vtstap_5’, Operation not supported.
2020-11-07T08:17:56.820Z| vmx| I125: DISKLIB-LIB_SIDECAR : DiskLib_SidecarSetOpenFlags: Failed to set open flags for sidecar ‘vtstap_5’, Operation not supported.

2020-11-07T08:17:56.820Z| vmx| I125: MigratePrepareEventLog: Prepare multiwriter disk handoff complete.
2020-11-07T08:17:56.827Z| vmx| I125: MigratePrepareEventLog: Prepare destination complete.
2020-11-07T08:17:56.827Z| vmx| I125: MigratePrepareEventLog: Prepare vPMem Regions complete.
2020-11-07T08:17:56.827Z| vmx| I125: MigratePrepareEventLog: Prepare event complete.
2020-11-07T08:17:56.827Z| vmx| I125: MigrateSetState: Transitioning from state 2 to 3.
2020-11-07T08:18:31.353Z| vcpu-0| I125: MigrateSetState: Transitioning from state 3 to 4.

• This is the Time when the Suspend Operation has started and is Taking 30 Seconds.

2020-11-07T08:18:31.353Z| vcpu-0| I125: Migrate: Preparing to suspend.
2020-11-07T08:18:31.353Z| vcpu-0| I125: Migrate: VM starting stun, waiting 100 seconds for go/no-go message.

2020-11-07T08:18:31.358Z| Upcall-a36c207b| I125: vxtap(sr_disk_stun:2779) INFO handle 200BFB6F80: inside disk_stun, flags=0, progressFunc=0
2020-11-07T08:18:31.358Z| Upcall-a36c207b| I125: vxtap(sr_disk_stun:2793) INFO handle 200BFB6F80, svd_ndx 5: entry stun level = 0
2020-11-07T08:18:31.359Z| Upcall-a36c207b| I125: vxtap(sr_disk_stun:2804) INFO handle 200BFB6F80: disk_stun returning
2020-11-07T08:18:31.359Z| Upcall-a36c207b| I125: vxtap(sr_disk_stun:2779) INFO handle 200BFB7910: inside disk_stun, flags=0, progressFunc=0
2020-11-07T08:18:31.359Z| Upcall-a36c207b| I125: vxtap(sr_disk_stun:2793) INFO handle 200BFB7910, svd_ndx 4: entry stun level = 0
2020-11-07T08:18:31.359Z| Upcall-a36c207b| I125: vxtap(sr_disk_stun:2804) INFO handle 200BFB7910: disk_stun returning
2020-11-07T08:18:31.360Z| Upcall-a36c207b| I125: vxtap(sr_disk_stun:2779) INFO handle 200BFB7D50: inside disk_stun, flags=0, progressFunc=0
2020-11-07T08:18:31.360Z| Upcall-a36c207b| I125: vxtap(sr_disk_stun:2793) INFO handle 200BFB7D50, svd_ndx 3: entry stun level = 0
2020-11-07T08:18:31.360Z| Upcall-a36c207b| I125: vxtap(sr_disk_stun:2804) INFO handle 200BFB7D50: disk_stun returning
2020-11-07T08:18:31.360Z| Upcall-a36c207b| I125: vxtap(sr_disk_stun:2779) INFO handle 200BFB7430: inside disk_stun, flags=0, progressFunc=0
2020-11-07T08:18:31.360Z| Upcall-a36c207b| I125: vxtap(sr_disk_stun:2793) INFO handle 200BFB7430, svd_ndx 2: entry stun level = 0
2020-11-07T08:18:31.360Z| Upcall-a36c207b| I125: vxtap(sr_disk_stun:2804) INFO handle 200BFB7430: disk_stun returning
2020-11-07T08:18:31.360Z| Upcall-a36c207b| I125: vxtap(sr_disk_stun:2779) INFO handle 200BFB72E0: inside disk_stun, flags=0, progressFunc=0
2020-11-07T08:18:31.360Z| Upcall-a36c207b| I125: vxtap(sr_disk_stun:2793) INFO handle 200BFB72E0, svd_ndx 1: entry stun level = 0
2020-11-07T08:18:31.360Z| Upcall-a36c207b| I125: vxtap(sr_disk_stun:2804) INFO handle 200BFB72E0: disk_stun returning
2020-11-07T08:18:31.361Z| Upcall-a36c207b| I125: vxtap(sr_disk_stun:2779) INFO handle 200BFB7580: inside disk_stun, flags=0, progressFunc=0
2020-11-07T08:18:31.361Z| Upcall-a36c207b| I125: vxtap(sr_disk_stun:2793) INFO handle 200BFB7580, svd_ndx 0: entry stun level = 0
2020-11-07T08:18:31.361Z| Upcall-a36c207b| I125: vxtap(sr_disk_stun:2804) INFO handle 200BFB7580: disk_stun returning

2020-11-07T08:19:01.410Z| vcpu-0| I125: Migrate_Open: Migrating to <11.119.202.41> with migration id 4875840853626506769
2020-11-07T08:19:01.410Z| vcpu-0| I125: Progress -1% (msg.checkpoint.saveStatus)
2020-11-07T08:19:01.410Z| vcpu-0| I125: Checkpointed in VMware ESX, 6.7.0, build-16075168, Linux Host
2020-11-07T08:19:01.419Z| vcpu-0| I125: Progress 101% (none)
2020-11-07T08:19:01.419Z| vcpu-0| I125: Migrate: VM successfully stunned.

2020-11-07T08:19:01.419Z| vcpu-0| I125: MigrateSetState: Transitioning from state 4 to 5.
2020-11-07T08:19:01.419Z| vcpu-0| I125: Closing all the disks of the VM.
2020-11-07T08:19:01.592Z| vmx| I125: MigrateSetState: Transitioning from state 5 to 6.
2020-11-07T08:19:01.592Z| vmx| I125: Migrate: Powering off
2020-11-07T08:19:01.592Z| vmx| I125: Stopping VCPU threads…

2020-11-07T08:19:01.605Z| vmx| I125: MigrateSetState: Transitioning from state 6 to 0.
2020-11-07T08:19:01.605Z| vmx| I125: SVMotion_PowerOff: Not running Storage vMotion. Nothing to do
2020-11-07T08:19:01.734Z| vmx| W115: VMX has left the building: 0.

Destination Logging:

2020-11-07T08:17:26.388Z| vmx| I125: Hostname=vxyzcldesx0101a.vpc.ind.abc.com
2020-11-07T08:17:26.459Z| vmx| I125: Received migrate ‘from’ request for mid id 4875840853626506769, src ip <11.119.202.42>.
2020-11-07T08:17:26.459Z| vmx| I125: MigrateSetInfo: state=8 srcIp=<11.119.202.42> dstIp=<11.119.202.41> mid=4875840853626506769 uuid=4c4c4544-0059-5a10-8048-b5c04f525a32 priority=high
2020-11-07T08:17:26.459Z| vmx| I125: MigrateSetState: Transitioning from state 0 to 8.
2020-11-07T08:17:26.474Z| vmx| W115: PowerOn
2020-11-07T08:17:26.520Z| vmx| I125: MigrateSetState: Transitioning from state 8 to 9.

2020-11-07T08:17:26.520Z| vmx| I125: Vigor_ClientRequestCb: failed to do op=3 on unregistered device ‘Tools’ (cmd=queryFields)
2020-11-07T08:17:26.520Z| vmx| I125: Vigor_ClientRequestCb: failed to do op=3 on unregistered device ‘GuestInfo’ (cmd=queryFields)
2020-11-07T08:17:26.520Z| vmx| I125: Vigor_ClientRequestCb: failed to do op=3 on unregistered device ‘GuestPeriodic’ (cmd=queryFields)
2020-11-07T08:17:26.521Z| vmx| I125: Vigor_ClientRequestCb: failed to do op=3 on unregistered device ‘GuestAppMonitor’ (cmd=queryFields)
2020-11-07T08:17:56.821Z| vmx| I125: MigrateSetState: Transitioning from state 9 to 10.
2020-11-07T08:18:07.541Z| vmx| I125: Vigor_ClientRequestCb: failed to do op=3 on unregistered device ‘Tools’ (cmd=queryFields)
2020-11-07T08:18:07.541Z| vmx| I125: Vigor_ClientRequestCb: failed to do op=3 on unregistered device ‘GuestInfo’ (cmd=queryFields)
2020-11-07T08:18:07.541Z| vmx| I125: Vigor_ClientRequestCb: failed to do op=3 on unregistered device ‘GuestPeriodic’ (cmd=queryFields)
2020-11-07T08:18:07.541Z| vmx| I125: Vigor_ClientRequestCb: failed to do op=3 on unregistered device ‘GuestAppMonitor’ (cmd=queryFields)
2020-11-07T08:19:01.439Z| vmx| I125: MigrateSetState: Transitioning from state 10 to 11.
2020-11-07T08:19:01.525Z| vmx| I125: Progress -1% (msg.checkpoint.restoreStatus)
2020-11-07T08:19:01.540Z| vmx| I125: Progress 0% (none)
2020-11-07T08:19:01.540Z| vmx| I125: Progress 101% (none)
2020-11-07T08:19:01.588Z| vmx| I125: MigrateSetState: Transitioning from state 11 to 12.
2020-11-07T08:19:01.706Z| vcpu-0| I125: MigrateSetState: Transitioning from state 12 to 0.

Source ESXI Host: vxyzcldesx0102a

Hostd Logs:

• Looking at the logs we can see that the vMotion task got initiated at 8:17 and completed at 8:19 which is 2 Minutes.

2020-11-07T08:17:26.129Z info hostd[2102134] [Originator@6876 sub=Vcsvc.VMotion opID=kcafy66f-1994887-auto-16r9m-h5:70265139-a4-01-ea-1221 user=vpxuser:VPC.IND.ABC.COM\abcdefghij] PrepareSourceEx [4875840853626506769], VM = ’89’
2020-11-07T08:17:26.130Z info hostd[2102134] [Originator@6876 sub=Vcsvc.VMotionSrc.4875840853626506769 opID=kcafy66f-1994887-auto-16r9m-h5:70265139-a4-01-ea-1221 user=vpxuser:VPC.IND.ABC.COM\abcdefghij] VMotionEntry: migrateType = 1
2020-11-07T08:17:26.130Z info hostd[2102134] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e92f-565389fc-76da-b496915f4dfc/ABCGICTSAPP4A/ABCGICTSAPP4A.vmx opID=kcafy66f-1994887-auto-16r9m-h5:70265139-a4-01-ea-1221 user=vpxuser:VPC.IND.ABC.COM\abcdefghij] State Transition (VM_STATE_ON -> VM_STATE_EMIGRATING)
2020-11-07T08:17:26.132Z info hostd[2102134] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e92f-565389fc-76da-b496915f4dfc/ABCGICTSAPP4A/ABCGICTSAPP4A.vmx opID=kcafy66f-1994887-auto-16r9m-h5:70265139-a4-01-ea-1221 user=vpxuser:VPC.IND.ABC.COM\abcdefghij] VMotionPrepare: srcLoggingIp=
2020-11-07T08:17:26.132Z info hostd[2102134] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e92f-565389fc-76da-b496915f4dfc/ABCGICTSAPP4A/ABCGICTSAPP4A.vmx opID=kcafy66f-1994887-auto-16r9m-h5:70265139-a4-01-ea-1221 user=vpxuser:VPC.IND.ABC.COM\abcdefghij] VMotionPrepare: dstLoggingIp=
2020-11-07T08:17:26.132Z info hostd[2102134] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e92f-565389fc-76da-b496915f4dfc/ABCGICTSAPP4A/ABCGICTSAPP4A.vmx opID=kcafy66f-1994887-auto-16r9m-h5:70265139-a4-01-ea-1221 user=vpxuser:VPC.IND.ABC.COM\abcdefghij] VMotionPrepare 4875840853626506769: ftPrimaryIp=
2020-11-07T08:17:26.132Z info hostd[2102134] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e92f-565389fc-76da-b496915f4dfc/ABCGICTSAPP4A/ABCGICTSAPP4A.vmx opID=kcafy66f-1994887-auto-16r9m-h5:70265139-a4-01-ea-1221 user=vpxuser:VPC.IND.ABC.COM\abcdefghij] VMotionPrepare 4875840853626506769: ftSecondaryIp=
2020-11-07T08:17:26.132Z info hostd[2102134] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e92f-565389fc-76da-b496915f4dfc/ABCGICTSAPP4A/ABCGICTSAPP4A.vmx opID=kcafy66f-1994887-auto-16r9m-h5:70265139-a4-01-ea-1221 user=vpxuser:VPC.IND.ABC.COM\abcdefghij] VMotionPrepare: srcMgmtIp=11.119.201.42
2020-11-07T08:17:26.132Z info hostd[2102134] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e92f-565389fc-76da-b496915f4dfc/ABCGICTSAPP4A/ABCGICTSAPP4A.vmx opID=kcafy66f-1994887-auto-16r9m-h5:70265139-a4-01-ea-1221 user=vpxuser:VPC.IND.ABC.COM\abcdefghij] VMotionPrepare: dstMgmtIp=11.119.201.41
2020-11-07T08:17:26.132Z info hostd[2102134] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e92f-565389fc-76da-b496915f4dfc/ABCGICTSAPP4A/ABCGICTSAPP4A.vmx opID=kcafy66f-1994887-auto-16r9m-h5:70265139-a4-01-ea-1221 user=vpxuser:VPC.IND.ABC.COM\abcdefghij] VMotionPrepare: dstVmDirPath=/vmfs/volumes/5dc0e92f-565389fc-76da-b496915f4dfc/ABCGICTSAPP4A/
2020-11-07T08:17:26.132Z info hostd[2102134] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e92f-565389fc-76da-b496915f4dfc/ABCGICTSAPP4A/ABCGICTSAPP4A.vmx opID=kcafy66f-1994887-auto-16r9m-h5:70265139-a4-01-ea-1221 user=vpxuser:VPC.IND.ABC.COM\abcdefghij] VMotionPrepare: dstVmFileName=ABCGICTSAPP4A.vmx
2020-11-07T08:17:26.132Z info hostd[2102134] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e92f-565389fc-76da-b496915f4dfc/ABCGICTSAPP4A/ABCGICTSAPP4A.vmx opID=kcafy66f-1994887-auto-16r9m-h5:70265139-a4-01-ea-1221 user=vpxuser:VPC.IND.ABC.COM\abcdefghij] Handling 0 deviceChanges
2020-11-07T08:17:26.132Z info hostd[2102134] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e92f-565389fc-76da-b496915f4dfc/ABCGICTSAPP4A/ABCGICTSAPP4A.vmx opID=kcafy66f-1994887-auto-16r9m-h5:70265139-a4-01-ea-1221 user=vpxuser:VPC.IND.ABC.COM\abcdefghij] VMotionPrepare (4875840853626506769): Sending ‘to’ srcIp=11.119.202.42 dstIp=11.119.202.41, type=1, encrypted=, remoteThumbprint=87:8B:F0:BA:6A:87:62:88:A9:37:01:4B:B8:D9:84:E5:BE:A1:E5:EB
2020-11-07T08:17:26.133Z info hostd[2102134] [Originator@6876 sub=Libs opID=kcafy66f-1994887-auto-16r9m-h5:70265139-a4-01-ea-1221 user=vpxuser:VPC.IND.ABC.COM\abcdefghij] SIOC: SIOC is notified not to start injector
2020-11-07T08:17:26.134Z info hostd[2102134] [Originator@6876 sub=Vcsvc.VMotion opID=kcafy66f-1994887-auto-16r9m-h5:70265139-a4-01-ea-1221 user=vpxuser:VPC.IND.ABC.COM\abcdefghij] Completed scheduling PrepareSourceEx [4875840853626506769]
2020-11-07T08:17:26.162Z info hostd[2101306] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e92f-565389fc-76da-b496915f4dfc/ABCGICTSAPP4A/ABCGICTSAPP4A.vmx] VMotionStatusCb [4875840853626506769] : Prepare task completed successfully
2020-11-07T08:17:26.539Z info hostd[2103252] [Originator@6876 sub=Vcsvc.VMotion opID=kcafy66f-1994887-auto-16r9m-h5:70265139-a4-01-e5-1246 user=vpxuser:VPC.IND.ABC.COM\abcdefghij] InitiateSource [4875840853626506769], WID = 4102756
2020-11-07T08:17:26.541Z info hostd[2103252] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e92f-565389fc-76da-b496915f4dfc/ABCGICTSAPP4A/ABCGICTSAPP4A.vmx opID=kcafy66f-1994887-auto-16r9m-h5:70265139-a4-01-e5-1246 user=vpxuser:VPC.IND.ABC.COM\abcdefghij] VMotionInitiateSrc (4875840853626506769): wid=4102756
2020-11-07T08:19:01.761Z info hostd[2310793] [Originator@6876 sub=Vcsvc.VMotionSrc.4875840853626506769] ResolveCb: VMX reports needsUnregister = true for migrateType MIGRATE_TYPE_VMOTION
2020-11-07T08:19:01.761Z info hostd[2310793] [Originator@6876 sub=Vcsvc.VMotionSrc.4875840853626506769] ResolveCb: Succeeded
2020-11-07T08:19:01.777Z info hostd[2310793] [Originator@6876 sub=Vcsvc.VMotionSrc.4875840853626506769] CompleteOp: Vmotion task succeeded with result: (vim.host.VMotionManager.SrcVMotionResult) {
–>    vmDowntime = 30058581,
–>    vmPrecopyStunTime = 2124130,
–>    vmPrecopyBandwidth = 217446027
–> }
2020-11-07T08:19:02.089Z info hostd[2103252] [Originator@6876 sub=Vcsvc.VMotion opID=kcafy66f-1994887-auto-16r9m-h5:70265139-a4-01-15-150f user=vpxuser:VPC.IND.ABC.COM\abcdefghij] CompleteSource [4875840853626506769]

VMKernel Logs:

• From the Vmkernel logs we can see that the migration operation sent through in One Go without waiting for the Paging operation to Complete.

2020-11-07T08:17:26.546Z cpu5:3143013)Migrate: vm 3143014: 3885: Setting VMOTION info: Source ts = 4875840853626506769, src ip = <11.119.202.42> dest ip = <11.119.202.41> Dest wid = 4102756 using SHARED swap, encrypted
2020-11-07T08:17:26.548Z cpu5:3143013)Hbr: 3561: Migration start received (worldID=3143014) (migrateType=1) (event=0) (isSource=1) (sharedConfig=1)
2020-11-07T08:17:26.549Z cpu108:3549528)MigrateNet: 1751: 4875840853626506769 S: Successfully bound connection to vmknic vmk1 – ‘11.119.202.42′
2020-11-07T08:17:26.550Z cpu117:2100698)MigrateNet: vm 2100698: 3263: Accepted connection from <11.119.202.41>
2020-11-07T08:17:26.550Z cpu108:3549528)MigrateNet: 1751: 4875840853626506769 S: Successfully bound connection to vmknic vmk1 – ‘11.119.202.42′
2020-11-07T08:17:26.551Z cpu108:3549528)VMotionUtil: 5199: 4875840853626506769 S: Stream connection 1 added.
2020-11-07T08:18:29.817Z cpu77:3143014)VMotion: 5367: 4875840853626506769 S: Another pre-copy iteration needed with 163367 pages left to send (prev2 8388608, prev 8388608, pages dirtied by pass through device 0, network bandwidth ~166.318 MB/s, 28336% t$
2020-11-07T08:18:31.313Z cpu74:3143014)VMotion: 5277: 4875840853626506769 S: Stopping pre-copy: only 9086 pages left to send, which can be sent within the switchover time goal of 0.500 seconds (network bandwidth ~258.381 MB/s, 1825% t2d)
2020-11-07T08:19:01.578Z cpu95:3549528)VMotionSend: 5095: 4875840853626506769 S: Sent all modified pages to destination (network bandwidth ~259.180 MB/s)

Destination ESXI Host: vxyzcldesx0101a

Hostd Logs:

• Investigating the Hostd Logs for the destination ESXi Host and we can see below:

2020-11-07T08:17:26.217Z info hostd[2101306] [Originator@6876 sub=Vcsvc.VMotion opID=kcafy66f-1994887-auto-16r9m-h5:70265139-a4-01-78-b90e user=vpxuser:VPC.IND.ABC.COM\abcdefghij] PrepareDestinationEx [4875840853626506769]
2020-11-07T08:17:26.217Z info hostd[2101306] [Originator@6876 sub=Vcsvc.VMotionDst.4875840853626506769 opID=kcafy66f-1994887-auto-16r9m-h5:70265139-a4-01-78-b90e user=vpxuser:VPC.IND.ABC.COM\abcdefghij] VMotionEntry: migrateType = 1
2020-11-07T08:17:26.218Z info hostd[2101306] [Originator@6876 sub=Vcsvc.VMotion opID=kcafy66f-1994887-auto-16r9m-h5:70265139-a4-01-78-b90e user=vpxuser:VPC.IND.ABC.COM\abcdefghij] Completed PrepareDestinationEx [4875840853626506769]
2020-11-07T08:17:26.256Z info hostd[2267555] [Originator@6876 sub=Vcsvc.VMotion opID=kcafy66f-1994887-auto-16r9m-h5:70265139-a4-01-21-b922 user=vpxuser:VPC.IND.ABC.COM\abcdefghij] InitiateDestination [4875840853626506769], VM = ‘/vmfs/volumes/5dc0e92f-565389fc-76da-b496915f4dfc/ABCGICTSAPP4A/ABCGICTSAPP4A.vmx’
2020-11-07T08:17:26.330Z info hostd[2267555] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e92f-565389fc-76da-b496915f4dfc/ABCGICTSAPP4A/ABCGICTSAPP4A.vmx opID=kcafy66f-1994887-auto-16r9m-h5:70265139-a4-01-21-b922 user=vpxuser:VPC.IND.ABC.COM\abcdefghij] VMotionPrepare 4875840853626506769: ftPrimaryIp=
2020-11-07T08:17:26.330Z info hostd[2267555] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e92f-565389fc-76da-b496915f4dfc/ABCGICTSAPP4A/ABCGICTSAPP4A.vmx opID=kcafy66f-1994887-auto-16r9m-h5:70265139-a4-01-21-b922 user=vpxuser:VPC.IND.ABC.COM\abcdefghij] VMotionPrepare 4875840853626506769: ftSecondaryIp=
2020-11-07T08:17:26.330Z info hostd[2267555] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5dc0e92f-565389fc-76da-b496915f4dfc/ABCGICTSAPP4A/ABCGICTSAPP4A.vmx opID=kcafy66f-1994887-auto-16r9m-h5:70265139-a4-01-21-b922 user=vpxuser:VPC.IND.ABC.COM\abcdefghij] VMotionPrepare (4875840853626506769): Sending ‘from’ srcIp=11.119.202.42 dstIp=11.119.202.41, type=1, encrypted=, remoteThumbprint=DB:9B:79:70:70:78:5D:8F:69:96:64:0B:4D:11:A9:C8:FC:5A:FA:D1
2020-11-07T08:17:26.348Z info hostd[2267555] [Originator@6876 sub=Vcsvc.VMotionDst.4875840853626506769 opID=kcafy66f-1994887-auto-16r9m-h5:70265139-a4-01-21-b922 user=vpxuser:VPC.IND.ABC.COM\abcdefghij] Initiate: Waiting for WID
2020-11-07T08:17:26.525Z info hostd[2267555] [Originator@6876 sub=Vcsvc.VMotionDst.4875840853626506769 opID=kcafy66f-1994887-auto-16r9m-h5:70265139-a4-01-21-b922 user=vpxuser:VPC.IND.ABC.COM\abcdefghij] Initiate: Got WID 4102756
2020-11-07T08:19:01.708Z info hostd[2267639] [Originator@6876 sub=Vcsvc.VMotionDst.4875840853626506769] ResolveCb: VMX reports needsUnregister = false for migrateType MIGRATE_TYPE_VMOTION
2020-11-07T08:19:01.709Z info hostd[2267639] [Originator@6876 sub=Vcsvc.VMotionDst.4875840853626506769] ResolveCb: Succeeded

• At the Destination end we can see the exact value of the vmDowntime which is 0.17 Seconds.

2020-11-07T08:19:01.999Z info hostd[2267639] [Originator@6876 sub=Vcsvc.VMotionDst.4875840853626506769] CompleteOp: Vmotion task succeeded with result: (vim.host.VMotionManager.VMotionResult) {
–>    dstVmId = <unset>,
–>    vmDowntime = 176570,
–>    vmStunTime = 0,
–>    vmPagesSrcTime = 0,
–>    vmNumRemotePageFaults = 0

2020-11-07T08:19:02.120Z info hostd[2102014] [Originator@6876 sub=Vcsvc.VMotion opID=kcafy66f-1994887-auto-16r9m-h5:70265139-a4-01-b7-bcaa user=vpxuser:VPC.IND.ABC.COM\abcdefghij] CompleteDestination [4875840853626506769]

VMKernel Logs:

• From the Destination VMKernel Logs as well we are not able to see any issues:

2020-11-07T08:17:26.516Z cpu68:4102711)Migrate: vm 4102756: 3885: Setting VMOTION info: Dest ts = 4875840853626506769, src ip = <11.119.202.42> dest ip = <11.119.202.41> Dest wid = 0 using SHARED swap, encrypted
2020-11-07T08:17:26.520Z cpu68:4102711)Hbr: 3561: Migration start received (worldID=4102756) (migrateType=1) (event=0) (isSource=0) (sharedConfig=1)
2020-11-07T08:17:26.550Z cpu26:2100698)MigrateNet: vm 2100698: 3263: Accepted connection from <11.119.202.42>
2020-11-07T08:17:26.550Z cpu26:2100698)MigrateNet: vm 2100698: 3351: dataSocket 0x43126bd44e30 receive buffer size is 563272
2020-11-07T08:17:26.550Z cpu26:2100698)Migrate: 358: Remote machine is ESX 6.5 or newer.
2020-11-07T08:17:26.550Z cpu49:4102772)MigrateNet: 1751: 4875840853626506769 D: Successfully bound connection to vmknic vmk1 – ‘11.119.202.41′
2020-11-07T08:17:26.552Z cpu26:2100698)MigrateNet: vm 2100698: 3263: Accepted connection from <11.119.202.42>
2020-11-07T08:17:26.552Z cpu26:2100698)MigrateNet: vm 2100698: 3351: dataSocket 0x43126bb0bfe0 receive buffer size is 563272
2020-11-07T08:17:26.552Z cpu26:2100698)Migrate: 358: Remote machine is ESX 6.5 or newer.
2020-11-07T08:17:26.552Z cpu26:2100698)VMotionUtil: 5199: 4875840853626506769 D: Stream connection 1 added.

2020-11-07T08:18:01.873Z cpu127:4102710)VMotionRecv: 761: 4875840853626413833 D: Estimated network bandwidth 181.163 MB/s during pre-copy

2020-11-07T08:18:31.353Z cpu1:4102773)VMotionRecv: 761: 4875840853626506769 D: Estimated network bandwidth 170.381 MB/s during pre-copy
2020-11-07T08:19:01.561Z cpu17:4102756)VMotion: 6573: 4875840853626506769 D: Waiting to receive all changed pages before resuming…
2020-11-07T08:19:01.579Z cpu3:4102773)VMotionRecv: 2961: 4875840853626506769 D: DONE paging in
2020-11-07T08:19:01.579Z cpu3:4102773)VMotionRecv: 2969: 4875840853626506769 D: Estimated network bandwidth 258.277 MB/s during page-in
2020-11-07T08:19:01.579Z cpu17:4102756)VMotion: 6633: 4875840853626506769 D: Received all changed pages.
2020-11-07T08:19:01.588Z cpu17:4102756)VMotion: 6412: 4875840853626506769 D: Resume handshake successful

2020-11-07T08:19:01.718Z cpu29:4102845)Swap: vm 4102756: 5104: Finish swapping in migration swap file. (faulted 0 pages). Success.

===================================================================================================================

• Checking another Occurrence:

• Here we can see that VM: X06GFINNAPP1A vMotion from 22.225.71.84  to 22.225.71.104.

• Seems like the destination logs are not present. Skipping the review.

Conclusion:

• While looking into the logs we can see that the VM Operation was stunned for 30 Seconds. While looking deeper into the Information and events during that time we can see below:

Suspend Operation Started:

2020-11-07T08:18:31.353Z| vcpu-0| I125: Migrate: Preparing to suspend.

• Closing of SCSI Disk 0:5 Started and took almost 5 Seconds, While waiting for the VXTAP to Complete its tasks:

2020-11-07T08:18:31.362Z| vcpu-0| I125: Closing disk ‘scsi0:5’
2020-11-07T08:18:31.362Z| vcpu-0| I125: vxtap(sr_disk_close:4300) INFO handle 200BFB7580: inside disk_close
2020-11-07T08:18:31.362Z| vcpu-0| I125: vxtap(sr_li_close:4109) INFO handle=200BFB7580 svd_ndx 0: stunLevel=1
2020-11-07T08:18:31.362Z| vcpu-0| I125: vxtap(sr_li_close:4167) INFO svd_ndx 0: cleanup done
2020-11-07T08:18:31.362Z| vcpu-0| I125: vxtap(sr_li_close:4173) INFO have config sidecar hdl
2020-11-07T08:18:31.363Z| vcpu-0| I125: vxtap(sr_li_close:4199) INFO Closed sidecar#0
2020-11-07T08:18:31.363Z| vcpu-0| I125: vxtap(sr_li_close:4199) INFO Closed sidecar#1
2020-11-07T08:18:31.364Z| vcpu-0| I125: vxtap(sr_li_close:4199) INFO Closed sidecar#2
2020-11-07T08:18:31.364Z| vcpu-0| I125: vxtap(sr_li_close:4199) INFO Closed sidecar#3
2020-11-07T08:18:31.365Z| vcpu-0| I125: vxtap(sr_li_close:4199) INFO Closed sidecar#4
2020-11-07T08:18:31.365Z| vcpu-0| I125: vxtap(sr_li_close:4205) INFO svd_ndx 0: sidecars closed
2020-11-07T08:18:31.365Z| vcpu-0| I125: vxtap(sr_li_close:4259) INFO svd_ndx 0: LI close done
2020-11-07T08:18:36.366Z| vcpu-0| I125: vxtap(sr_li_close:4291) INFO handle 200BFB7580: returning SUCCESS
2020-11-07T08:18:36.366Z| vcpu-0| I125: vxtap(sr_disk_close:4304) INFO handle 200BFB7580: disk_close returning, res 0
2020-11-07T08:18:36.369Z| vcpu-0| I125: DISKLIB-VMFS  : “/vmfs/volumes/5dc0e903-1754fd22-a28a-b496915f4dfc/x06gcldvrpgw28/x06gcldvrpgw28_41-flat.vmdk” : closed.

• Closing of Disk 0:4 was started and again took 5 Seconds.

2020-11-07T08:18:36.369Z| vcpu-0| I125: Closing disk ‘scsi0:4’
2020-11-07T08:18:36.369Z| vcpu-0| I125: vxtap(sr_disk_close:4300) INFO handle 200BFB72E0: inside disk_close
2020-11-07T08:18:36.369Z| vcpu-0| I125: vxtap(sr_li_close:4109) INFO handle=200BFB72E0 svd_ndx 1: stunLevel=1
2020-11-07T08:18:36.369Z| vcpu-0| I125: vxtap(sr_li_close:4167) INFO svd_ndx 1: cleanup done
2020-11-07T08:18:36.369Z| vcpu-0| I125: vxtap(sr_li_close:4173) INFO have config sidecar hdl
2020-11-07T08:18:36.369Z| vcpu-0| I125: vxtap(sr_li_close:4199) INFO Closed sidecar#0
2020-11-07T08:18:36.370Z| vcpu-0| I125: vxtap(sr_li_close:4199) INFO Closed sidecar#1
2020-11-07T08:18:36.370Z| vcpu-0| I125: vxtap(sr_li_close:4199) INFO Closed sidecar#2
2020-11-07T08:18:36.371Z| vcpu-0| I125: vxtap(sr_li_close:4199) INFO Closed sidecar#3
2020-11-07T08:18:36.372Z| vcpu-0| I125: vxtap(sr_li_close:4199) INFO Closed sidecar#4
2020-11-07T08:18:36.372Z| vcpu-0| I125: vxtap(sr_li_close:4205) INFO svd_ndx 1: sidecars closed
2020-11-07T08:18:36.372Z| vcpu-0| I125: vxtap(sr_li_close:4259) INFO svd_ndx 1: LI close done
2020-11-07T08:18:41.373Z| vcpu-0| I125: vxtap(sr_li_close:4291) INFO handle 200BFB72E0: returning SUCCESS
2020-11-07T08:18:41.373Z| vcpu-0| I125: vxtap(sr_disk_close:4304) INFO handle 200BFB72E0: disk_close returning, res 0
2020-11-07T08:18:41.375Z| vcpu-0| I125: DISKLIB-VMFS  : “/vmfs/volumes/5dc0e903-1754fd22-a28a-b496915f4dfc/x06gcldvrpgw28/x06gcldvrpgw28_60-flat.vmdk” : closed.

2020-11-07T08:18:41.375Z| vcpu-0| I125: Closing disk ‘scsi0:3’
2020-11-07T08:18:41.376Z| vcpu-0| I125: vxtap(sr_disk_close:4300) INFO handle 200BFB7430: inside disk_close
2020-11-07T08:18:41.376Z| vcpu-0| I125: vxtap(sr_li_close:4109) INFO handle=200BFB7430 svd_ndx 2: stunLevel=1
2020-11-07T08:18:41.376Z| vcpu-0| I125: vxtap(sr_li_close:4167) INFO svd_ndx 2: cleanup done
2020-11-07T08:18:41.376Z| vcpu-0| I125: vxtap(sr_li_close:4173) INFO have config sidecar hdl
2020-11-07T08:18:41.376Z| vcpu-0| I125: vxtap(sr_li_close:4199) INFO Closed sidecar#0
2020-11-07T08:18:41.377Z| vcpu-0| I125: vxtap(sr_li_close:4199) INFO Closed sidecar#1
2020-11-07T08:18:41.377Z| vcpu-0| I125: vxtap(sr_li_close:4199) INFO Closed sidecar#2
2020-11-07T08:18:41.378Z| vcpu-0| I125: vxtap(sr_li_close:4199) INFO Closed sidecar#3
2020-11-07T08:18:41.378Z| vcpu-0| I125: vxtap(sr_li_close:4199) INFO Closed sidecar#4
2020-11-07T08:18:41.378Z| vcpu-0| I125: vxtap(sr_li_close:4205) INFO svd_ndx 2: sidecars closed
2020-11-07T08:18:41.379Z| vcpu-0| I125: vxtap(sr_li_close:4259) INFO svd_ndx 2: LI close done
2020-11-07T08:18:46.379Z| vcpu-0| I125: vxtap(sr_li_close:4291) INFO handle 200BFB7430: returning SUCCESS
2020-11-07T08:18:46.379Z| vcpu-0| I125: vxtap(sr_disk_close:4304) INFO handle 200BFB7430: disk_close returning, res 0
2020-11-07T08:18:46.382Z| vcpu-0| I125: DISKLIB-VMFS  : “/vmfs/volumes/5dc0e903-1754fd22-a28a-b496915f4dfc/x06gcldvrpgw28/x06gcldvrpgw28_29-flat.vmdk” : closed.

2020-11-07T08:18:46.382Z| vcpu-0| I125: Closing disk ‘scsi0:2’
2020-11-07T08:18:46.382Z| vcpu-0| I125: vxtap(sr_disk_close:4300) INFO handle 200BFB7D50: inside disk_close
2020-11-07T08:18:46.382Z| vcpu-0| I125: vxtap(sr_li_close:4109) INFO handle=200BFB7D50 svd_ndx 3: stunLevel=1
2020-11-07T08:18:46.382Z| vcpu-0| I125: vxtap(sr_li_close:4167) INFO svd_ndx 3: cleanup done
2020-11-07T08:18:46.382Z| vcpu-0| I125: vxtap(sr_li_close:4173) INFO have config sidecar hdl
2020-11-07T08:18:46.384Z| vcpu-0| I125: vxtap(sr_li_close:4199) INFO Closed sidecar#0
2020-11-07T08:18:46.384Z| vcpu-0| I125: vxtap(sr_li_close:4199) INFO Closed sidecar#1
2020-11-07T08:18:46.385Z| vcpu-0| I125: vxtap(sr_li_close:4199) INFO Closed sidecar#2
2020-11-07T08:18:46.386Z| vcpu-0| I125: vxtap(sr_li_close:4199) INFO Closed sidecar#3
2020-11-07T08:18:46.387Z| vcpu-0| I125: vxtap(sr_li_close:4199) INFO Closed sidecar#4
2020-11-07T08:18:46.387Z| vcpu-0| I125: vxtap(sr_li_close:4205) INFO svd_ndx 3: sidecars closed
2020-11-07T08:18:46.388Z| vcpu-0| I125: vxtap(sr_li_close:4259) INFO svd_ndx 3: LI close done
2020-11-07T08:18:51.390Z| vcpu-0| I125: vxtap(sr_li_close:4291) INFO handle 200BFB7D50: returning SUCCESS
2020-11-07T08:18:51.390Z| vcpu-0| I125: vxtap(sr_disk_close:4304) INFO handle 200BFB7D50: disk_close returning, res 0
2020-11-07T08:18:51.392Z| vcpu-0| I125: DISKLIB-VMFS  : “/vmfs/volumes/5dc0e903-1754fd22-a28a-b496915f4dfc/x06gcldvrpgw28/x06gcldvrpgw28_11-flat.vmdk” : closed.

2020-11-07T08:18:51.392Z| vcpu-0| I125: Closing disk ‘scsi0:1’
2020-11-07T08:18:51.392Z| vcpu-0| I125: vxtap(sr_disk_close:4300) INFO handle 200BFB7910: inside disk_close
2020-11-07T08:18:51.392Z| vcpu-0| I125: vxtap(sr_li_close:4109) INFO handle=200BFB7910 svd_ndx 4: stunLevel=1
2020-11-07T08:18:51.393Z| vcpu-0| I125: vxtap(sr_li_close:4167) INFO svd_ndx 4: cleanup done
2020-11-07T08:18:51.393Z| vcpu-0| I125: vxtap(sr_li_close:4173) INFO have config sidecar hdl
2020-11-07T08:18:51.393Z| vcpu-0| I125: vxtap(sr_li_close:4199) INFO Closed sidecar#0
2020-11-07T08:18:51.394Z| vcpu-0| I125: vxtap(sr_li_close:4199) INFO Closed sidecar#1
2020-11-07T08:18:51.394Z| vcpu-0| I125: vxtap(sr_li_close:4199) INFO Closed sidecar#2
2020-11-07T08:18:51.395Z| vcpu-0| I125: vxtap(sr_li_close:4199) INFO Closed sidecar#3
2020-11-07T08:18:51.395Z| vcpu-0| I125: vxtap(sr_li_close:4199) INFO Closed sidecar#4
2020-11-07T08:18:51.395Z| vcpu-0| I125: vxtap(sr_li_close:4205) INFO svd_ndx 4: sidecars closed
2020-11-07T08:18:51.396Z| vcpu-0| I125: vxtap(sr_li_close:4259) INFO svd_ndx 4: LI close done
2020-11-07T08:18:56.396Z| vcpu-0| I125: vxtap(sr_li_close:4291) INFO handle 200BFB7910: returning SUCCESS
2020-11-07T08:18:56.396Z| vcpu-0| I125: vxtap(sr_disk_close:4304) INFO handle 200BFB7910: disk_close returning, res 0
2020-11-07T08:18:56.399Z| vcpu-0| I125: DISKLIB-VMFS  : “/vmfs/volumes/5dc0e903-1754fd22-a28a-b496915f4dfc/x06gcldvrpgw28/x06gcldvrpgw28_34-flat.vmdk” : closed.

2020-11-07T08:18:56.399Z| vcpu-0| I125: Closing disk ‘scsi0:0’
2020-11-07T08:18:56.399Z| vcpu-0| I125: vxtap(sr_disk_close:4300) INFO handle 200BFB6F80: inside disk_close
2020-11-07T08:18:56.399Z| vcpu-0| I125: vxtap(sr_li_close:4109) INFO handle=200BFB6F80 svd_ndx 5: stunLevel=1
2020-11-07T08:18:56.399Z| vcpu-0| I125: vxtap(sr_li_close:4167) INFO svd_ndx 5: cleanup done
2020-11-07T08:18:56.399Z| vcpu-0| I125: vxtap(sr_li_close:4173) INFO have config sidecar hdl
2020-11-07T08:18:56.399Z| vcpu-0| I125: vxtap(sr_li_close:4199) INFO Closed sidecar#0
2020-11-07T08:18:56.400Z| vcpu-0| I125: vxtap(sr_li_close:4199) INFO Closed sidecar#1
2020-11-07T08:18:56.401Z| vcpu-0| I125: vxtap(sr_li_close:4199) INFO Closed sidecar#2
2020-11-07T08:18:56.402Z| vcpu-0| I125: vxtap(sr_li_close:4199) INFO Closed sidecar#3
2020-11-07T08:18:56.402Z| vcpu-0| I125: vxtap(sr_li_close:4199) INFO Closed sidecar#4
2020-11-07T08:18:56.402Z| vcpu-0| I125: vxtap(sr_li_close:4205) INFO svd_ndx 5: sidecars closed
2020-11-07T08:18:56.403Z| vcpu-0| I125: vxtap(sr_li_close:4259) INFO svd_ndx 5: LI close done
2020-11-07T08:19:01.404Z| vcpu-0| I125: vxtap(sr_li_close:4285) INFO handle 200BFB6F80: removing log reload timer
2020-11-07T08:19:01.404Z| vcpu-0| I125: vxtap(sr_li_close:4291) INFO handle 200BFB6F80: returning SUCCESS
2020-11-07T08:19:01.404Z| vcpu-0| I125: vxtap(sr_disk_close:4304) INFO handle 200BFB6F80: disk_close returning, res 0

• Look at this the issue seems to be happening because we are waiting for VXTAP to Complete its process while closing the Disk During the Suspend Operation.

Action Plan:

• Based on the logs we can see the issue seems to be with the VXTAP Driver from Veritas. In order to Confirm, please take a VM out of the Veritas Driver and then try to reproduce the issue.

• In the Meantime you can also check with the VXTAP Team to check if there is any known issue or its something which they have seen before.