Attachment 1692598 Details for Bug 1837840 – esx5.5-vddk6.7.3-hang.log

esx5.5-vddk6.7.3-hang.log

esx5.5-vddk6.7.3-hang.log (text/plain), 66.32 KB, created by mxie@redhat.com on 2020-05-27 08:13:27 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: mxie@redhat.com

Created: 2020-05-27 08:13:27 UTC

Size: 66.32 KB

patch

obsolete

>#  virt-v2v -ic vpx://root@10.73.73.148/data/10.73.3.19/?no_verify=1 -it vddk -io vddk-libdir=/root/vmware-vix-disklib-distrib -io vddk-thumbprint=AA:F5:4C:48:C9:BF:75:1A:94:41:61:4C:D5:EC:DF:46:48:B5:9B:4D esx5.5-rhel6.10-x86_64 -on esx5.5-vddk6.7 -ip /home/passwd -v -x |& ts
>May 27 14:15:58 virt-v2v: virt-v2v 1.42.0rhel=8,release=3.module+el8.3.0+6497+b190d2a5 (x86_64)
>May 27 14:15:58 libvirt version: 6.3.0
>May 27 14:15:58 [   0.2] Opening the source -i libvirt -ic vpx://root@10.73.73.148:443/data/10.73.3.19/?no_verify=1 esx5.5-rhel6.10-x86_64 -it vddk  -io vddk-libdir=/root/vmware-vix-disklib-distrib -io vddk-thumbprint=AA:F5:4C:48:C9:BF:75:1A:94:41:61:4C:D5:EC:DF:46:48:B5:9B:4D
>May 27 14:15:58 libvirt xml is:
>May 27 14:15:58 <domain type='vmware' xmlns:vmware='http://libvirt.org/schemas/domain/vmware/1.0'>
>May 27 14:15:58   <name>esx5.5-rhel6.10-x86_64</name>
>May 27 14:15:58   <uuid>42379ca1-f0d2-b2af-1bb1-0980f0dcc053</uuid>
>May 27 14:15:58   <memory unit='KiB'>2097152</memory>
>May 27 14:15:58   <currentMemory unit='KiB'>2097152</currentMemory>
>May 27 14:15:58   <vcpu placement='static'>1</vcpu>
>May 27 14:15:58   <os>
>May 27 14:15:58     <type arch='x86_64'>hvm</type>
>May 27 14:15:58   </os>
>May 27 14:15:58   <clock offset='utc'/>
>May 27 14:15:58   <on_poweroff>destroy</on_poweroff>
>May 27 14:15:58   <on_reboot>restart</on_reboot>
>May 27 14:15:58   <on_crash>destroy</on_crash>
>May 27 14:15:58   <devices>
>May 27 14:15:58     <disk type='file' device='disk'>
>May 27 14:15:58       <source file='[ESX5.5-matrix] esx5.5-rhel6.10-x86_64/esx5.5-rhel6.10-x86_64.vmdk'/>
>May 27 14:15:58       <target dev='sda' bus='scsi'/>
>May 27 14:15:58       <address type='drive' controller='0' bus='0' target='0' unit='0'/>
>May 27 14:15:58     </disk>
>May 27 14:15:58     <controller type='scsi' index='0' model='vmpvscsi'/>
>May 27 14:15:58     <interface type='bridge'>
>May 27 14:15:58       <mac address='00:50:56:b7:dc:41'/>
>May 27 14:15:58       <source bridge='VM Network'/>
>May 27 14:15:58       <model type='vmxnet3'/>
>May 27 14:15:58     </interface>
>May 27 14:15:58     <video>
>May 27 14:15:58       <model type='vmvga' vram='8192' primary='yes'/>
>May 27 14:15:58     </video>
>May 27 14:15:58   </devices>
>May 27 14:15:58   <vmware:datacenterpath>data</vmware:datacenterpath>
>May 27 14:15:58   <vmware:moref>vm-52</vmware:moref>
>May 27 14:15:58 </domain>
>May 27 14:15:58 
>May 27 14:15:58 nbdkit --dump-config
>May 27 14:15:58 nbdkit version: 1.20.2
>May 27 14:15:58 nbdkit --dump-config
>May 27 14:15:58 nbdkit version: 1.20.2
>May 27 14:15:58 libguestfs: trace: set_verbose true
>May 27 14:15:58 libguestfs: trace: set_verbose = 0
>May 27 14:15:58 libguestfs: trace: get_sockdir
>May 27 14:15:58 libguestfs: trace: get_sockdir = "/tmp"
>May 27 14:15:58 nbdkit --dump-config
>May 27 14:15:58 nbdkit version: 1.20.2
>May 27 14:15:58 running nbdkit:
>May 27 14:15:58  LANG=C 'nbdkit' '--exit-with-parent' '--foreground' '--newstyle' '--pidfile' '/tmp/v2vnbdkit.2QJC70/nbdkit1.pid' '--unix' '/tmp/v2vnbdkit.2QJC70/nbdkit1.sock' '-D' 'nbdkit.backend.datapath=0' '-D' 'vddk.datapath=0' '--exportname' '/' '--readonly' '--selinux-label' 'system_u:object_r:svirt_socket_t:s0' '--verbose' '--filter' 'cacheextents' '--filter' 'readahead' '--filter' 'retry' 'vddk' 'server=10.73.73.148' 'user=root' 'password=+/home/passwd' 'vm=moref=vm-52' 'file=[ESX5.5-matrix] esx5.5-rhel6.10-x86_64/esx5.5-rhel6.10-x86_64.vmdk' 'libdir=/root/vmware-vix-disklib-distrib' 'thumbprint=AA:F5:4C:48:C9:BF:75:1A:94:41:61:4C:D5:EC:DF:46:48:B5:9B:4D'
>May 27 14:15:58 nbdkit: debug: TLS disabled: could not load TLS certificates
>May 27 14:15:58 nbdkit: debug: registering plugin /usr/lib64/nbdkit/plugins/nbdkit-vddk-plugin.so
>May 27 14:15:58 nbdkit: debug: registered plugin /usr/lib64/nbdkit/plugins/nbdkit-vddk-plugin.so (name vddk)
>May 27 14:15:58 nbdkit: debug: vddk: load
>May 27 14:15:58 nbdkit: debug: registering filter /usr/lib64/nbdkit/filters/nbdkit-retry-filter.so
>May 27 14:15:58 nbdkit: debug: registered filter /usr/lib64/nbdkit/filters/nbdkit-retry-filter.so (name retry)
>May 27 14:15:58 nbdkit: debug: retry: load
>May 27 14:15:58 nbdkit: debug: registering filter /usr/lib64/nbdkit/filters/nbdkit-readahead-filter.so
>May 27 14:15:58 nbdkit: debug: registered filter /usr/lib64/nbdkit/filters/nbdkit-readahead-filter.so (name readahead)
>May 27 14:15:58 nbdkit: debug: readahead: load
>May 27 14:15:58 nbdkit: debug: registering filter /usr/lib64/nbdkit/filters/nbdkit-cacheextents-filter.so
>May 27 14:15:58 nbdkit: debug: registered filter /usr/lib64/nbdkit/filters/nbdkit-cacheextents-filter.so (name cacheextents)
>May 27 14:15:58 nbdkit: debug: cacheextents: load
>May 27 14:15:58 nbdkit: debug: cacheextents: config key=server, value=10.73.73.148
>May 27 14:15:58 nbdkit: debug: readahead: config key=server, value=10.73.73.148
>May 27 14:15:58 nbdkit: debug: retry: config key=server, value=10.73.73.148
>May 27 14:15:58 nbdkit: debug: vddk: config key=server, value=10.73.73.148
>May 27 14:15:58 nbdkit: debug: cacheextents: config key=user, value=root
>May 27 14:15:58 nbdkit: debug: readahead: config key=user, value=root
>May 27 14:15:58 nbdkit: debug: retry: config key=user, value=root
>May 27 14:15:58 nbdkit: debug: vddk: config key=user, value=root
>May 27 14:15:58 nbdkit: debug: cacheextents: config key=password, value=+/home/passwd
>May 27 14:15:58 nbdkit: debug: readahead: config key=password, value=+/home/passwd
>May 27 14:15:58 nbdkit: debug: retry: config key=password, value=+/home/passwd
>May 27 14:15:58 nbdkit: debug: vddk: config key=password, value=+/home/passwd
>May 27 14:15:58 nbdkit: debug: cacheextents: config key=vm, value=moref=vm-52
>May 27 14:15:58 nbdkit: debug: readahead: config key=vm, value=moref=vm-52
>May 27 14:15:58 nbdkit: debug: retry: config key=vm, value=moref=vm-52
>May 27 14:15:58 nbdkit: debug: vddk: config key=vm, value=moref=vm-52
>May 27 14:15:58 nbdkit: debug: cacheextents: config key=file, value=[ESX5.5-matrix] esx5.5-rhel6.10-x86_64/esx5.5-rhel6.10-x86_64.vmdk
>May 27 14:15:58 nbdkit: debug: readahead: config key=file, value=[ESX5.5-matrix] esx5.5-rhel6.10-x86_64/esx5.5-rhel6.10-x86_64.vmdk
>May 27 14:15:58 nbdkit: debug: retry: config key=file, value=[ESX5.5-matrix] esx5.5-rhel6.10-x86_64/esx5.5-rhel6.10-x86_64.vmdk
>May 27 14:15:58 nbdkit: debug: vddk: config key=file, value=[ESX5.5-matrix] esx5.5-rhel6.10-x86_64/esx5.5-rhel6.10-x86_64.vmdk
>May 27 14:15:58 nbdkit: debug: cacheextents: config key=libdir, value=/root/vmware-vix-disklib-distrib
>May 27 14:15:58 nbdkit: debug: readahead: config key=libdir, value=/root/vmware-vix-disklib-distrib
>May 27 14:15:58 nbdkit: debug: retry: config key=libdir, value=/root/vmware-vix-disklib-distrib
>May 27 14:15:58 nbdkit: debug: vddk: config key=libdir, value=/root/vmware-vix-disklib-distrib
>May 27 14:15:58 nbdkit: debug: cacheextents: config key=thumbprint, value=AA:F5:4C:48:C9:BF:75:1A:94:41:61:4C:D5:EC:DF:46:48:B5:9B:4D
>May 27 14:15:58 nbdkit: debug: readahead: config key=thumbprint, value=AA:F5:4C:48:C9:BF:75:1A:94:41:61:4C:D5:EC:DF:46:48:B5:9B:4D
>May 27 14:15:58 nbdkit: debug: retry: config key=thumbprint, value=AA:F5:4C:48:C9:BF:75:1A:94:41:61:4C:D5:EC:DF:46:48:B5:9B:4D
>May 27 14:15:58 nbdkit: debug: vddk: config key=thumbprint, value=AA:F5:4C:48:C9:BF:75:1A:94:41:61:4C:D5:EC:DF:46:48:B5:9B:4D
>May 27 14:15:58 nbdkit: debug: cacheextents: config_complete
>May 27 14:15:58 nbdkit: debug: readahead: config_complete
>May 27 14:15:58 nbdkit: debug: retry: config_complete
>May 27 14:15:58 nbdkit: debug: vddk: config_complete
>May 27 14:15:58 nbdkit: debug: using thread model: serialize_all_requests
>May 27 14:15:58 nbdkit: debug: cacheextents: get_ready
>May 27 14:15:58 nbdkit: debug: readahead: get_ready
>May 27 14:15:58 nbdkit: debug: retry: get_ready
>May 27 14:15:58 nbdkit: debug: vddk: get_ready
>May 27 14:15:58 nbdkit: debug: original command line occupies 584 bytes
>May 27 14:15:58 nbdkit: debug: adding reexeced_=
>May 27 14:15:58 nbdkit: debug: re-executing with updated LD_LIBRARY_PATH=/root/vmware-vix-disklib-distrib/lib64
>May 27 14:15:58 nbdkit: debug: TLS disabled: could not load TLS certificates
>May 27 14:15:58 nbdkit: debug: registering plugin /usr/lib64/nbdkit/plugins/nbdkit-vddk-plugin.so
>May 27 14:15:58 nbdkit: debug: registered plugin /usr/lib64/nbdkit/plugins/nbdkit-vddk-plugin.so (name vddk)
>May 27 14:15:58 nbdkit: debug: vddk: load
>May 27 14:15:58 nbdkit: debug: registering filter /usr/lib64/nbdkit/filters/nbdkit-retry-filter.so
>May 27 14:15:58 nbdkit: debug: registered filter /usr/lib64/nbdkit/filters/nbdkit-retry-filter.so (name retry)
>May 27 14:15:58 nbdkit: debug: retry: load
>May 27 14:15:58 nbdkit: debug: registering filter /usr/lib64/nbdkit/filters/nbdkit-readahead-filter.so
>May 27 14:15:58 nbdkit: debug: registered filter /usr/lib64/nbdkit/filters/nbdkit-readahead-filter.so (name readahead)
>May 27 14:15:58 nbdkit: debug: readahead: load
>May 27 14:15:58 nbdkit: debug: registering filter /usr/lib64/nbdkit/filters/nbdkit-cacheextents-filter.so
>May 27 14:15:58 nbdkit: debug: registered filter /usr/lib64/nbdkit/filters/nbdkit-cacheextents-filter.so (name cacheextents)
>May 27 14:15:58 nbdkit: debug: cacheextents: load
>May 27 14:15:58 nbdkit: debug: cacheextents: config key=server, value=10.73.73.148
>May 27 14:15:58 nbdkit: debug: readahead: config key=server, value=10.73.73.148
>May 27 14:15:58 nbdkit: debug: retry: config key=server, value=10.73.73.148
>May 27 14:15:58 nbdkit: debug: vddk: config key=server, value=10.73.73.148
>May 27 14:15:58 nbdkit: debug: cacheextents: config key=user, value=root
>May 27 14:15:58 nbdkit: debug: readahead: config key=user, value=root
>May 27 14:15:58 nbdkit: debug: retry: config key=user, value=root
>May 27 14:15:58 nbdkit: debug: vddk: config key=user, value=root
>May 27 14:15:58 nbdkit: debug: cacheextents: config key=password, value=+/home/passwd
>May 27 14:15:58 nbdkit: debug: readahead: config key=password, value=+/home/passwd
>May 27 14:15:58 nbdkit: debug: retry: config key=password, value=+/home/passwd
>May 27 14:15:58 nbdkit: debug: vddk: config key=password, value=+/home/passwd
>May 27 14:15:58 nbdkit: debug: cacheextents: config key=vm, value=moref=vm-52
>May 27 14:15:58 nbdkit: debug: readahead: config key=vm, value=moref=vm-52
>May 27 14:15:58 nbdkit: debug: retry: config key=vm, value=moref=vm-52
>May 27 14:15:58 nbdkit: debug: vddk: config key=vm, value=moref=vm-52
>May 27 14:15:58 nbdkit: debug: cacheextents: config key=file, value=[ESX5.5-matrix] esx5.5-rhel6.10-x86_64/esx5.5-rhel6.10-x86_64.vmdk
>May 27 14:15:58 nbdkit: debug: readahead: config key=file, value=[ESX5.5-matrix] esx5.5-rhel6.10-x86_64/esx5.5-rhel6.10-x86_64.vmdk
>May 27 14:15:58 nbdkit: debug: retry: config key=file, value=[ESX5.5-matrix] esx5.5-rhel6.10-x86_64/esx5.5-rhel6.10-x86_64.vmdk
>May 27 14:15:58 nbdkit: debug: vddk: config key=file, value=[ESX5.5-matrix] esx5.5-rhel6.10-x86_64/esx5.5-rhel6.10-x86_64.vmdk
>May 27 14:15:58 nbdkit: debug: cacheextents: config key=libdir, value=/root/vmware-vix-disklib-distrib
>May 27 14:15:58 nbdkit: debug: readahead: config key=libdir, value=/root/vmware-vix-disklib-distrib
>May 27 14:15:58 nbdkit: debug: retry: config key=libdir, value=/root/vmware-vix-disklib-distrib
>May 27 14:15:58 nbdkit: debug: vddk: config key=libdir, value=/root/vmware-vix-disklib-distrib
>May 27 14:15:58 nbdkit: debug: cacheextents: config key=thumbprint, value=AA:F5:4C:48:C9:BF:75:1A:94:41:61:4C:D5:EC:DF:46:48:B5:9B:4D
>May 27 14:15:58 nbdkit: debug: readahead: config key=thumbprint, value=AA:F5:4C:48:C9:BF:75:1A:94:41:61:4C:D5:EC:DF:46:48:B5:9B:4D
>May 27 14:15:58 nbdkit: debug: retry: config key=thumbprint, value=AA:F5:4C:48:C9:BF:75:1A:94:41:61:4C:D5:EC:DF:46:48:B5:9B:4D
>May 27 14:15:58 nbdkit: debug: vddk: config key=thumbprint, value=AA:F5:4C:48:C9:BF:75:1A:94:41:61:4C:D5:EC:DF:46:48:B5:9B:4D
>May 27 14:15:58 nbdkit: debug: cacheextents: config key=reexeced_, value=
>May 27 14:15:58 nbdkit: debug: readahead: config key=reexeced_, value=
>May 27 14:15:58 nbdkit: debug: retry: config key=reexeced_, value=
>May 27 14:15:58 nbdkit: debug: vddk: config key=reexeced_, value=
>May 27 14:15:58 nbdkit: debug: cacheextents: config_complete
>May 27 14:15:58 nbdkit: debug: readahead: config_complete
>May 27 14:15:58 nbdkit: debug: retry: config_complete
>May 27 14:15:58 nbdkit: debug: vddk: config_complete
>May 27 14:15:58 nbdkit: debug: cleaning up after re-exec
>May 27 14:15:58 nbdkit: debug: using thread model: serialize_all_requests
>May 27 14:15:58 nbdkit: debug: cacheextents: get_ready
>May 27 14:15:58 nbdkit: debug: readahead: get_ready
>May 27 14:15:58 nbdkit: debug: retry: get_ready
>May 27 14:15:58 nbdkit: debug: vddk: get_ready
>May 27 14:15:58 nbdkit: debug: VDDK call: VixDiskLib_InitEx (5, 5, &debug_fn, &error_fn, &error_fn, /root/vmware-vix-disklib-distrib, NULL)
>May 27 14:15:58 nbdkit: debug: DictionaryLoad: Cannot open file "/etc/vmware/vsphereFeatures/vsphereFeatures.cfg": No such file or directory.
>May 27 14:15:58 nbdkit: debug: [msg.dictionary.load.openFailed] Cannot open file "/etc/vmware/vsphereFeatures/vsphereFeatures.cfg": No such file or directory.
>May 27 14:15:58 nbdkit: debug: FeatureStateLib: Error while loading feature config file: /etc/vmware/vsphereFeatures/vsphereFeatures.cfg, using default feature state values.
>May 27 14:15:58 nbdkit: debug: OBJLIB-LIB: Objlib initialized.
>May 27 14:15:58 nbdkit: debug: VixDiskLib: Attempting to locate advanced transport module in "/root/vmware-vix-disklib-distrib".
>May 27 14:15:59 nbdkit: debug: VixDiskLib: Advanced transport plugin /root/vmware-vix-disklib-distrib/lib64/libdiskLibPlugin.so was successfully loaded into vixDiskLib.
>May 27 14:15:59 nbdkit: debug: VixDiskLib: Enabling advanced transport modes.
>May 27 14:15:59 nbdkit: debug: VixDiskLib: Initialize transport modes.
>May 27 14:15:59 nbdkit: debug: 2020-05-27T14:15:59.102+08:00 info -[20374] [Originator@6876 sub=ThreadPool] Thread enlisted
>May 27 14:15:59 nbdkit: debug: 2020-05-27T14:15:59.102+08:00 info -[20374] [Originator@6876 sub=ThreadPool] Entering worker thread loop
>May 27 14:15:59 nbdkit: debug: 2020-05-27T14:15:59.102+08:00 info -[20376] [Originator@6876 sub=ThreadPool] Thread enlisted
>May 27 14:15:59 nbdkit: debug: 2020-05-27T14:15:59.102+08:00 info -[20376] [Originator@6876 sub=ThreadPool] Entering IO thread loop
>May 27 14:15:59 nbdkit: debug: 2020-05-27T14:15:59.102+08:00 info -[20377] [Originator@6876 sub=ThreadPool] Thread enlisted
>May 27 14:15:59 nbdkit: debug: 2020-05-27T14:15:59.102+08:00 info -[20377] [Originator@6876 sub=ThreadPool] Entering fair thread loop
>May 27 14:15:59 nbdkit: debug: 2020-05-27T14:15:59.102+08:00 info -[20369] [Originator@6876 sub=vm] DictionaryLoad: Cannot open file "/etc/vmware/vsphereFeatures/vsphereFeatures.cfg": No such file or directory.
>May 27 14:15:59 nbdkit: debug: 2020-05-27T14:15:59.102+08:00 info -[20369] [Originator@6876 sub=vm] [msg.dictionary.load.openFailed] Cannot open file "/etc/vmware/vsphereFeatures/vsphereFeatures.cfg": No such file or directory.
>May 27 14:15:59 nbdkit: debug: 2020-05-27T14:15:59.103+08:00 info -[20369] [Originator@6876 sub=vm] FeatureStateLib: Error while loading feature config file: /etc/vmware/vsphereFeatures/vsphereFeatures.cfg, using default feature state values.
>May 27 14:15:59 nbdkit: debug: 2020-05-27T14:15:59.103+08:00 info -[20369] [Originator@6876 sub=Libs] [NFC DEBUG] NFC connection accept timeout: 180000 milliseconds
>May 27 14:15:59 nbdkit: debug: 2020-05-27T14:15:59.103+08:00 info -[20369] [Originator@6876 sub=Libs] [NFC DEBUG] NFC request timeout: 180000 milliseconds
>May 27 14:15:59 nbdkit: debug: 2020-05-27T14:15:59.103+08:00 info -[20369] [Originator@6876 sub=Libs] [NFC DEBUG] NFC read timeout: 60000 milliseconds
>May 27 14:15:59 nbdkit: debug: 2020-05-27T14:15:59.103+08:00 info -[20369] [Originator@6876 sub=Libs] [NFC DEBUG] NFC write timeout: 600000 milliseconds
>May 27 14:15:59 nbdkit: debug: 2020-05-27T14:15:59.103+08:00 info -[20369] [Originator@6876 sub=Libs] [NFC DEBUG] NFC fssrvr request timeout: 0 milliseconds
>May 27 14:15:59 nbdkit: debug: 2020-05-27T14:15:59.103+08:00 info -[20369] [Originator@6876 sub=Libs] [NFC DEBUG] NFC fssrvr write timeout: 0 milliseconds
>May 27 14:15:59 nbdkit: debug: 2020-05-27T14:15:59.103+08:00 info -[20369] [Originator@6876 sub=Libs] [NFC DEBUG] NFC max recv retries: 1
>May 27 14:15:59 nbdkit: debug: 2020-05-27T14:15:59.103+08:00 info -[20369] [Originator@6876 sub=Libs] DictionaryLoad: Cannot open file "/etc/vmware/config": No such file or directory.
>May 27 14:15:59 nbdkit: debug: 2020-05-27T14:15:59.103+08:00 info -[20369] [Originator@6876 sub=Libs] [msg.dictionary.load.openFailed] Cannot open file "/etc/vmware/config": No such file or directory.
>May 27 14:15:59 nbdkit: debug: 2020-05-27T14:15:59.103+08:00 info -[20369] [Originator@6876 sub=Libs] PREF Optional preferences file not found at /etc/vmware/config. Using default values.
>May 27 14:15:59 nbdkit: debug: 2020-05-27T14:15:59.103+08:00 info -[20369] [Originator@6876 sub=Libs] DictionaryLoad: Cannot open file "/usr/lib/vmware/settings": No such file or directory.
>May 27 14:15:59 nbdkit: debug: 2020-05-27T14:15:59.103+08:00 info -[20369] [Originator@6876 sub=Libs] [msg.dictionary.load.openFailed] Cannot open file "/usr/lib/vmware/settings": No such file or directory.
>May 27 14:15:59 nbdkit: debug: 2020-05-27T14:15:59.103+08:00 info -[20369] [Originator@6876 sub=Libs] PREF Optional preferences file not found at /usr/lib/vmware/settings. Using default values.
>May 27 14:15:59 nbdkit: debug: 2020-05-27T14:15:59.103+08:00 info -[20369] [Originator@6876 sub=Libs] DictionaryLoad: Cannot open file "/usr/lib/vmware/config": No such file or directory.
>May 27 14:15:59 nbdkit: debug: 2020-05-27T14:15:59.103+08:00 info -[20369] [Originator@6876 sub=Libs] [msg.dictionary.load.openFailed] Cannot open file "/usr/lib/vmware/config": No such file or directory.
>May 27 14:15:59 nbdkit: debug: 2020-05-27T14:15:59.103+08:00 info -[20369] [Originator@6876 sub=Libs] PREF Optional preferences file not found at /usr/lib/vmware/config. Using default values.
>May 27 14:15:59 nbdkit: debug: 2020-05-27T14:15:59.103+08:00 info -[20369] [Originator@6876 sub=Libs] DictionaryLoad: Cannot open file "/root/.vmware/config": No such file or directory.
>May 27 14:15:59 nbdkit: debug: 2020-05-27T14:15:59.103+08:00 info -[20369] [Originator@6876 sub=Libs] [msg.dictionary.load.openFailed] Cannot open file "/root/.vmware/config": No such file or directory.
>May 27 14:15:59 nbdkit: debug: 2020-05-27T14:15:59.103+08:00 info -[20369] [Originator@6876 sub=Libs] PREF Optional preferences file not found at /root/.vmware/config. Using default values.
>May 27 14:15:59 nbdkit: debug: 2020-05-27T14:15:59.103+08:00 info -[20369] [Originator@6876 sub=Libs] DictionaryLoad: Cannot open file "/root/.vmware/preferences": No such file or directory.
>May 27 14:15:59 nbdkit: debug: 2020-05-27T14:15:59.103+08:00 info -[20369] [Originator@6876 sub=Libs] [msg.dictionary.load.openFailed] Cannot open file "/root/.vmware/preferences": No such file or directory.
>May 27 14:15:59 nbdkit: debug: 2020-05-27T14:15:59.103+08:00 info -[20369] [Originator@6876 sub=Libs] PREF Optional preferences file not found at /root/.vmware/preferences. Using default values.
>May 27 14:15:59 nbdkit: debug: 2020-05-27T14:15:59.106+08:00 info -[20369] [Originator@6876 sub=Libs] lib/ssl: OpenSSL using FIPS_drbg for RAND
>May 27 14:15:59 nbdkit: debug: 2020-05-27T14:15:59.106+08:00 info -[20369] [Originator@6876 sub=Libs] lib/ssl: protocol list tls1.2
>May 27 14:15:59 nbdkit: debug: 2020-05-27T14:15:59.106+08:00 info -[20369] [Originator@6876 sub=Libs] lib/ssl: protocol list tls1.2 (openssl flags 0x17000000)
>May 27 14:15:59 nbdkit: debug: 2020-05-27T14:15:59.106+08:00 info -[20369] [Originator@6876 sub=Libs] lib/ssl: cipher list ECDHE+AESGCM:RSA+AESGCM:ECDHE+AES:RSA+AES
>May 27 14:15:59 nbdkit: debug: 2020-05-27T14:15:59.106+08:00 info -[20369] [Originator@6876 sub=Libs] lib/ssl: curves list prime256v1:secp384r1:secp521r1
>May 27 14:15:59 nbdkit: debug: 2020-05-27T14:15:59.146+08:00 info -[20369] [Originator@6876 sub=vm] DictionaryLoad: Cannot open file "/etc/vmware/vsphereFeatures/vsphereFeatures.cfg": No such file or directory.
>May 27 14:15:59 nbdkit: debug: 2020-05-27T14:15:59.146+08:00 info -[20369] [Originator@6876 sub=vm] [msg.dictionary.load.openFailed] Cannot open file "/etc/vmware/vsphereFeatures/vsphereFeatures.cfg": No such file or directory.
>May 27 14:15:59 nbdkit: debug: 2020-05-27T14:15:59.146+08:00 info -[20369] [Originator@6876 sub=vm] FeatureStateLib: Error while loading feature config file: /etc/vmware/vsphereFeatures/vsphereFeatures.cfg, using default feature state values.
>May 27 14:15:59 nbdkit: debug: VixDiskLib: Available transport modes: file:san:hotadd:nbdssl:nbd.
>May 27 14:15:59 nbdkit: debug: VMware VixDiskLib (6.7) Release build-14389676
>May 27 14:15:59 nbdkit: debug: DictionaryLoad: Cannot open file "/etc/vmware/config": No such file or directory.
>May 27 14:15:59 nbdkit: debug: [msg.dictionary.load.openFailed] Cannot open file "/etc/vmware/config": No such file or directory.
>May 27 14:15:59 nbdkit: debug: PREF Optional preferences file not found at /etc/vmware/config. Using default values.
>May 27 14:15:59 nbdkit: debug: DictionaryLoad: Cannot open file "/usr/lib/vmware/settings": No such file or directory.
>May 27 14:15:59 nbdkit: debug: [msg.dictionary.load.openFailed] Cannot open file "/usr/lib/vmware/settings": No such file or directory.
>May 27 14:15:59 nbdkit: debug: PREF Optional preferences file not found at /usr/lib/vmware/settings. Using default values.
>May 27 14:15:59 nbdkit: debug: DictionaryLoad: Cannot open file "/usr/lib/vmware/config": No such file or directory.
>May 27 14:15:59 nbdkit: debug: [msg.dictionary.load.openFailed] Cannot open file "/usr/lib/vmware/config": No such file or directory.
>May 27 14:15:59 nbdkit: debug: PREF Optional preferences file not found at /usr/lib/vmware/config. Using default values.
>May 27 14:15:59 nbdkit: debug: DictionaryLoad: Cannot open file "/root/.vmware/config": No such file or directory.
>May 27 14:15:59 nbdkit: debug: [msg.dictionary.load.openFailed] Cannot open file "/root/.vmware/config": No such file or directory.
>May 27 14:15:59 nbdkit: debug: PREF Optional preferences file not found at /root/.vmware/config. Using default values.
>May 27 14:15:59 nbdkit: debug: DictionaryLoad: Cannot open file "/root/.vmware/preferences": No such file or directory.
>May 27 14:15:59 nbdkit: debug: [msg.dictionary.load.openFailed] Cannot open file "/root/.vmware/preferences": No such file or directory.
>May 27 14:15:59 nbdkit: debug: PREF Optional preferences file not found at /root/.vmware/preferences. Using default values.
>May 27 14:15:59 nbdkit: debug: lib/ssl: OpenSSL using FIPS_drbg for RAND
>May 27 14:15:59 nbdkit: debug: lib/ssl: protocol list tls1.2
>May 27 14:15:59 nbdkit: debug: lib/ssl: protocol list tls1.2 (openssl flags 0x17000000)
>May 27 14:15:59 nbdkit: debug: lib/ssl: cipher list ECDHE+AESGCM:RSA+AESGCM:ECDHE+AES:RSA+AES
>May 27 14:15:59 nbdkit: debug: lib/ssl: curves list prime256v1:secp384r1:secp521r1
>May 27 14:15:59 nbdkit: debug: DictionaryLoad: Cannot open file "/etc/vmware/vsphereFeatures/vsphereFeatures.cfg": No such file or directory.
>May 27 14:15:59 nbdkit: debug: [msg.dictionary.load.openFailed] Cannot open file "/etc/vmware/vsphereFeatures/vsphereFeatures.cfg": No such file or directory.
>May 27 14:15:59 nbdkit: debug: FeatureStateLib: Error while loading feature config file: /etc/vmware/vsphereFeatures/vsphereFeatures.cfg, using default feature state values.
>May 27 14:15:59 nbdkit: debug: VixDiskLibVim: VixDiskLibVim_Init: Initialization is completed.
>May 27 14:15:59 nbdkit: debug: bound to unix socket /tmp/v2vnbdkit.2QJC70/nbdkit1.sock
>May 27 14:15:59 nbdkit: debug: written pidfile /tmp/v2vnbdkit.2QJC70/nbdkit1.pid
>May 27 14:15:59 chcon 'system_u:object_r:svirt_image_t:s0' '/tmp/v2vnbdkit.2QJC70/nbdkit1.sock'
>May 27 14:15:59     source name: esx5.5-rhel6.10-x86_64
>May 27 14:15:59 hypervisor type: vmware
>May 27 14:15:59        VM genid: 
>May 27 14:15:59          memory: 2147483648 (bytes)
>May 27 14:15:59        nr vCPUs: 1
>May 27 14:15:59      CPU vendor: 
>May 27 14:15:59       CPU model: 
>May 27 14:15:59    CPU topology: 
>May 27 14:15:59    CPU features: 
>May 27 14:15:59        firmware: unknown
>May 27 14:15:59         display: 
>May 27 14:15:59           video: vmvga
>May 27 14:15:59           sound: 
>May 27 14:15:59 disks:
>May 27 14:15:59 	nbd:unix:/tmp/v2vnbdkit.2QJC70/nbdkit1.sock:exportname=/ (raw) [scsi]
>May 27 14:15:59 removable media:
>May 27 14:15:59 
>May 27 14:15:59 NICs:
>May 27 14:15:59 	Bridge "VM Network" mac: 00:50:56:b7:dc:41 [vmxnet3]
>May 27 14:15:59 
>May 27 14:15:59 check_host_free_space: overlay_dir=/var/tmp free_space=725103955968
>May 27 14:15:59 [   1.7] Creating an overlay to protect the source from being modified
>May 27 14:15:59 qemu-img 'create' '-q' '-f' 'qcow2' '-b' 'nbd:unix:/tmp/v2vnbdkit.2QJC70/nbdkit1.sock:exportname=/' '-o' 'compat=1.1,backing_fmt=raw' '/var/tmp/v2vovl264a6c.qcow2'
>May 27 14:15:59 nbdkit: debug: accepted connection
>May 27 14:15:59 nbdkit: vddk[1]: debug: cacheextents: preconnect
>May 27 14:15:59 nbdkit: vddk[1]: debug: readahead: preconnect
>May 27 14:15:59 nbdkit: vddk[1]: debug: retry: preconnect
>May 27 14:15:59 nbdkit: vddk[1]: debug: vddk: preconnect
>May 27 14:15:59 nbdkit: vddk[1]: debug: newstyle negotiation: flags: global 0x3
>May 27 14:15:59 nbdkit: vddk[1]: debug: newstyle negotiation: client flags: 0x3
>May 27 14:15:59 nbdkit: vddk[1]: debug: newstyle negotiation: NBD_OPT_STRUCTURED_REPLY: client requested structured replies
>May 27 14:15:59 nbdkit: vddk[1]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: client requested export '/'
>May 27 14:15:59 nbdkit: vddk[1]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: set count: 1
>May 27 14:15:59 nbdkit: vddk[1]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: set base:allocation
>May 27 14:15:59 nbdkit: vddk[1]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: replying with base:allocation id 1
>May 27 14:15:59 nbdkit: vddk[1]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: reply complete
>May 27 14:15:59 nbdkit: vddk[1]: debug: newstyle negotiation: NBD_OPT_GO: client requested export '/'
>May 27 14:15:59 nbdkit: vddk[1]: debug: cacheextents: open readonly=1
>May 27 14:15:59 nbdkit: vddk[1]: debug: readahead: open readonly=1
>May 27 14:15:59 nbdkit: vddk[1]: debug: retry: open readonly=1
>May 27 14:15:59 nbdkit: vddk[1]: debug: vddk: open readonly=1
>May 27 14:15:59 nbdkit: vddk[1]: debug: VDDK call: VixDiskLib_AllocateConnectParams ()
>May 27 14:15:59 nbdkit: vddk[1]: debug: VDDK call: VixDiskLib_ConnectEx (h->params, 1, NULL, NULL, &connection)
>May 27 14:15:59 nbdkit: vddk[1]: debug: VixDiskLib: VixDiskLib_ConnectEx: Establish connection using (null).
>May 27 14:15:59 nbdkit: vddk[1]: debug: VixDiskLib: VixDiskLib_Connect: Establish connection.
>May 27 14:15:59 nbdkit: vddk[1]: debug: VixDiskLib: Resolve host.
>May 27 14:16:00 nbdkit: vddk[1]: debug: 2020-05-27T14:16:00.098+08:00 error -[20381] [Originator@6876 sub=Default] Cannot use advanced transport modes for 10.73.73.148/moref=vm-52/: Cannot create directory /tmp/vmware-root/42379ca1-f0d2-b2af-1bb1-0980f0dcc053-vm-52.
>May 27 14:16:00 nbdkit: vddk[1]: debug: VixDiskLib: VixDiskLib_ConnectEx: Advanced transport modes not available for opening moref=vm-52. (Cannot use advanced transport modes for 10.73.73.148/moref=vm-52/: Cannot create directory /tmp/vmware-root/42379ca1-f0d2-b2af-1bb1-0980f0dcc053-vm-52.)
>May 27 14:16:00 nbdkit: vddk[1]: debug: VDDK call: VixDiskLib_Open (connection, [ESX5.5-matrix] esx5.5-rhel6.10-x86_64/esx5.5-rhel6.10-x86_64.vmdk, 4, &handle)
>May 27 14:16:00 nbdkit: vddk[1]: debug: VixDiskLib: VixDiskLib_OpenEx: Open a disk.
>May 27 14:16:00 nbdkit: vddk[1]: debug: VixDiskLibVim: VixDiskLibVim_GetFileName: Get file name for [ESX5.5-matrix] esx5.5-rhel6.10-x86_64/esx5.5-rhel6.10-x86_64.vmdk.
>May 27 14:16:00 nbdkit: vddk[1]: debug: VixDiskLibVim: VixDiskLibVim_GetNfcTicket: Get NFC ticket for [ESX5.5-matrix] esx5.5-rhel6.10-x86_64/esx5.5-rhel6.10-x86_64.vmdk.
>May 27 14:16:00 nbdkit: vddk[1]: debug: DictionaryLoad: Cannot open file "/etc/vmware/config": No such file or directory.
>May 27 14:16:00 nbdkit: vddk[1]: debug: [msg.dictionary.load.openFailed] Cannot open file "/etc/vmware/config": No such file or directory.
>May 27 14:16:00 nbdkit: vddk[1]: debug: PREF Optional preferences file not found at /etc/vmware/config. Using default values.
>May 27 14:16:00 nbdkit: vddk[1]: debug: DictionaryLoad: Cannot open file "/usr/lib/vmware/settings": No such file or directory.
>May 27 14:16:00 nbdkit: vddk[1]: debug: [msg.dictionary.load.openFailed] Cannot open file "/usr/lib/vmware/settings": No such file or directory.
>May 27 14:16:00 nbdkit: vddk[1]: debug: PREF Optional preferences file not found at /usr/lib/vmware/settings. Using default values.
>May 27 14:16:00 nbdkit: vddk[1]: debug: DictionaryLoad: Cannot open file "/usr/lib/vmware/config": No such file or directory.
>May 27 14:16:00 nbdkit: vddk[1]: debug: [msg.dictionary.load.openFailed] Cannot open file "/usr/lib/vmware/config": No such file or directory.
>May 27 14:16:00 nbdkit: vddk[1]: debug: PREF Optional preferences file not found at /usr/lib/vmware/config. Using default values.
>May 27 14:16:00 nbdkit: vddk[1]: debug: DictionaryLoad: Cannot open file "/root/.vmware/config": No such file or directory.
>May 27 14:16:00 nbdkit: vddk[1]: debug: [msg.dictionary.load.openFailed] Cannot open file "/root/.vmware/config": No such file or directory.
>May 27 14:16:00 nbdkit: vddk[1]: debug: PREF Optional preferences file not found at /root/.vmware/config. Using default values.
>May 27 14:16:00 nbdkit: vddk[1]: debug: DictionaryLoad: Cannot open file "/root/.vmware/preferences": No such file or directory.
>May 27 14:16:00 nbdkit: vddk[1]: debug: [msg.dictionary.load.openFailed] Cannot open file "/root/.vmware/preferences": No such file or directory.
>May 27 14:16:00 nbdkit: vddk[1]: debug: PREF Optional preferences file not found at /root/.vmware/preferences. Using default values.
>May 27 14:16:00 nbdkit: vddk[1]: debug: lib/ssl: OpenSSL using FIPS_drbg for RAND
>May 27 14:16:00 nbdkit: vddk[1]: debug: lib/ssl: protocol list tls1.2
>May 27 14:16:00 nbdkit: vddk[1]: debug: lib/ssl: protocol list tls1.2 (openssl flags 0x17000000)
>May 27 14:16:00 nbdkit: vddk[1]: debug: lib/ssl: cipher list ECDHE+AESGCM:RSA+AESGCM:ECDHE+AES:RSA+AES
>May 27 14:16:00 nbdkit: vddk[1]: debug: lib/ssl: curves list prime256v1:secp384r1:secp521r1
>May 27 14:16:00 nbdkit: vddk[1]: debug: VixDiskLibVim: Request RandomAccessRO diskKey = 2000, readOnly = 1, openSnapshot = 0.
>May 27 14:16:00 nbdkit: vddk[1]: debug: VixDiskLibVim: VixDiskLibVimFreeInternalVCAboutInfo: Free Internal VC AboutInfo.
>May 27 14:16:00 nbdkit: vddk[1]: debug: VixDiskLibVim: VixDiskLibVim_HandleDiskCryptoKey: handle the key of disk [ESX5.5-matrix] esx5.5-rhel6.10-x86_64/esx5.5-rhel6.10-x86_64.vmdk.
>May 27 14:16:00 nbdkit: vddk[1]: debug: VixDiskLibVim: VixDiskLibVim_FreeNfcTicket: Free NFC ticket.
>May 27 14:16:00 nbdkit: vddk[1]: debug: VixDiskLibVim: VixDiskLibVim_FreeFileName: Free file name.
>May 27 14:16:00 nbdkit: vddk[1]: debug: NBD_ClientOpen: attempting to create connection to vpxa-nfc://[ESX5.5-matrix] esx5.5-rhel6.10-x86_64/esx5.5-rhel6.10-x86_64.vmdk@10.73.3.19:902
>May 27 14:16:00 nbdkit: vddk[1]: debug: CnxAuthdProtoSecureConnect: Target authd does not support BANNER (530).
>May 27 14:16:00 nbdkit: vddk[1]: debug: DictionaryLoad: Cannot open file "/etc/vmware/vsphereFeatures/vsphereFeatures.cfg": No such file or directory.
>May 27 14:16:00 nbdkit: vddk[1]: debug: [msg.dictionary.load.openFailed] Cannot open file "/etc/vmware/vsphereFeatures/vsphereFeatures.cfg": No such file or directory.
>May 27 14:16:00 nbdkit: vddk[1]: debug: FeatureStateLib: Error while loading feature config file: /etc/vmware/vsphereFeatures/vsphereFeatures.cfg, using default feature state values.
>May 27 14:16:00 nbdkit: vddk[1]: debug: NFC Sync IO session is established.
>May 27 14:16:00 nbdkit: vddk[1]: debug: Opening file [ESX5.5-matrix] esx5.5-rhel6.10-x86_64/esx5.5-rhel6.10-x86_64.vmdk (vpxa-nfc://[ESX5.5-matrix] esx5.5-rhel6.10-x86_64/esx5.5-rhel6.10-x86_64.vmdk@10.73.3.19:902)
>May 27 14:16:00 nbdkit: vddk[1]: debug: DISKLIB-LINK  : Opened 'vpxa-nfc://[ESX5.5-matrix] esx5.5-rhel6.10-x86_64/esx5.5-rhel6.10-x86_64.vmdk@10.73.3.19:902' (0xe): custom, 33554432 sectors / 16 GB.
>May 27 14:16:01 nbdkit: vddk[1]: debug: DISKLIB-LIB   : Opened "vpxa-nfc://[ESX5.5-matrix] esx5.5-rhel6.10-x86_64/esx5.5-rhel6.10-x86_64.vmdk@10.73.3.19:902" (flags 0xe, type custom).
>May 27 14:16:01 nbdkit: vddk[1]: debug: VixDiskLib: VixDiskLib_GetTransportMode: Retrieve transport mode.
>May 27 14:16:01 nbdkit: vddk[1]: debug: transport mode: nbd
>May 27 14:16:01 nbdkit: vddk[1]: debug: vddk: open returned handle 0x7f9cf4001e30
>May 27 14:16:01 nbdkit: vddk[1]: debug: retry: open returned handle 0x7f9cf4583470
>May 27 14:16:01 nbdkit: vddk[1]: debug: readahead: open returned handle 0x7f9cfbfff580
>May 27 14:16:01 nbdkit: vddk[1]: debug: cacheextents: open returned handle 0x7f9cfbfff580
>May 27 14:16:01 nbdkit: vddk[1]: debug: vddk: prepare readonly=1
>May 27 14:16:01 nbdkit: vddk[1]: debug: retry: prepare readonly=1
>May 27 14:16:01 nbdkit: vddk[1]: debug: readahead: prepare readonly=1
>May 27 14:16:01 nbdkit: vddk[1]: debug: retry: get_size
>May 27 14:16:01 nbdkit: vddk[1]: debug: vddk: get_size
>May 27 14:16:01 nbdkit: vddk[1]: debug: VDDK call: VixDiskLib_GetInfo (handle, &info)
>May 27 14:16:01 nbdkit: vddk[1]: debug: VixDiskLib: VixDiskLib_GetInfo: Retrieve disk info.
>May 27 14:16:02 nbdkit: vddk[1]: debug: VDDK call: VixDiskLib_FreeInfo (info)
>May 27 14:16:02 nbdkit: vddk[1]: debug: VixDiskLib: VixDiskLib_FreeInfo: Clean up VixDiskLib.
>May 27 14:16:02 nbdkit: vddk[1]: debug: cacheextents: prepare readonly=1
>May 27 14:16:02 nbdkit: vddk[1]: debug: cacheextents: get_size
>May 27 14:16:02 nbdkit: vddk[1]: debug: readahead: get_size
>May 27 14:16:02 nbdkit: vddk[1]: debug: cacheextents: can_zero
>May 27 14:16:02 nbdkit: vddk[1]: debug: cacheextents: can_fast_zero
>May 27 14:16:02 nbdkit: vddk[1]: debug: cacheextents: can_trim
>May 27 14:16:02 nbdkit: vddk[1]: debug: cacheextents: can_fua
>May 27 14:16:02 nbdkit: vddk[1]: debug: cacheextents: can_flush
>May 27 14:16:02 nbdkit: vddk[1]: debug: readahead: can_flush
>May 27 14:16:02 nbdkit: vddk[1]: debug: retry: can_flush
>May 27 14:16:02 nbdkit: vddk[1]: debug: vddk: can_flush
>May 27 14:16:02 nbdkit: vddk[1]: debug: cacheextents: is_rotational
>May 27 14:16:02 nbdkit: vddk[1]: debug: readahead: is_rotational
>May 27 14:16:02 nbdkit: vddk[1]: debug: retry: is_rotational
>May 27 14:16:02 nbdkit: vddk[1]: debug: vddk: is_rotational
>May 27 14:16:02 nbdkit: vddk[1]: debug: cacheextents: can_multi_conn
>May 27 14:16:02 nbdkit: vddk[1]: debug: readahead: can_multi_conn
>May 27 14:16:02 nbdkit: vddk[1]: debug: retry: can_multi_conn
>May 27 14:16:02 nbdkit: vddk[1]: debug: vddk: can_multi_conn
>May 27 14:16:02 nbdkit: vddk[1]: debug: cacheextents: can_cache
>May 27 14:16:02 nbdkit: vddk[1]: debug: readahead: can_cache
>May 27 14:16:02 nbdkit: vddk[1]: debug: cacheextents: can_extents
>May 27 14:16:02 nbdkit: vddk[1]: debug: readahead: can_extents
>May 27 14:16:02 nbdkit: vddk[1]: debug: retry: can_extents
>May 27 14:16:02 nbdkit: vddk[1]: debug: vddk: can_extents
>May 27 14:16:02 nbdkit: vddk[1]: debug: VDDK call: VixDiskLib_QueryAllocatedBlocks (handle, 0, 128 sectors, 128 sectors)
>May 27 14:16:02 nbdkit: vddk[1]: debug: VixDiskLib: VixDiskLib_QueryAllocatedBlocks: Query allocated blocks.
>May 27 14:16:03 nbdkit: vddk[1]: error: [NFC ERROR] NfcFssrvrProcessErrorMsg: received NFC error 2 from server: Illegal message during fssrvr session, id = 49
>May 27 14:16:03 nbdkit: vddk[1]: debug: DISKLIB-LIB_MISC   : DiskLibGetAllocatedSectorChunksInRangeInt: failed to get allocated sector bitmap with 'NBD_ERR_GENERIC' (290).
>May 27 14:16:03 nbdkit: vddk[1]: debug: VixDiskLib: Detected DiskLib error 290 (NBD_ERR_GENERIC).
>May 27 14:16:03 nbdkit: vddk[1]: debug: VixDiskLib: VixDiskLibQueryBlockList: Fail to query blocks (offset 0, chunkSize 128, chunkNumber 1). Error 1 (Unknown error) (DiskLib error 290: NBD_ERR_GENERIC) at 563.
>May 27 14:16:03 nbdkit: vddk[1]: debug: can_extents: VixDiskLib_QueryAllocatedBlocks test failed, extents support will be disabled: original error: Unknown error
>May 27 14:16:03 nbdkit: vddk[1]: debug: newstyle negotiation: flags: export 0x487
>May 27 14:16:03 nbdkit: vddk[1]: debug: newstyle negotiation: NBD_OPT_GO: ignoring NBD_INFO_* request 3 (NBD_INFO_BLOCK_SIZE)
>May 27 14:16:03 nbdkit: vddk[1]: debug: handshake complete, processing requests serially
>May 27 14:16:03 nbdkit: vddk[1]: debug: client sent NBD_CMD_DISC, closing connection
>May 27 14:16:03 nbdkit: vddk[1]: debug: cacheextents: finalize
>May 27 14:16:03 nbdkit: vddk[1]: debug: readahead: finalize
>May 27 14:16:03 nbdkit: vddk[1]: debug: retry: finalize
>May 27 14:16:03 nbdkit: vddk[1]: debug: vddk: finalize
>May 27 14:16:03 nbdkit: vddk[1]: debug: cacheextents: close
>May 27 14:16:03 nbdkit: vddk[1]: debug: readahead: close
>May 27 14:16:03 nbdkit: vddk[1]: debug: retry: close
>May 27 14:16:03 nbdkit: vddk[1]: debug: reopens needed: 0
>May 27 14:16:03 nbdkit: vddk[1]: debug: vddk: close
>May 27 14:16:03 nbdkit: vddk[1]: debug: VDDK call: VixDiskLib_Close (handle)
>May 27 14:16:03 nbdkit: vddk[1]: debug: VixDiskLib: VixDiskLib_Close: Close disk.
>May 27 14:16:03 nbdkit: vddk[1]: error: [NFC ERROR] NfcFssrvr_Close: Received unexpected message: NFC_SESSION_COMPLETE from server. Expected message: NFC_FSSRVR_CLOSE
>May 27 14:16:03 nbdkit: vddk[1]: debug: VixDiskLibVim: VixDiskLibVim_HandleDiskCryptoKey: handle the key of disk [ESX5.5-matrix] esx5.5-rhel6.10-x86_64/esx5.5-rhel6.10-x86_64.vmdk.
>May 27 14:16:03 nbdkit: vddk[1]: debug: VDDK call: VixDiskLib_Disconnect (connection)
>May 27 14:16:03 nbdkit: vddk[1]: debug: VixDiskLib: VixDiskLib_Disconnect: Disconnect.
>May 27 14:16:03 nbdkit: vddk[1]: debug: VixDiskLib: VixDiskLib_FreeConnectParams: Free connection parameters.
>May 27 14:16:03 nbdkit: vddk[1]: debug: VDDK call: VixDiskLib_FreeConnectParams (params)
>May 27 14:16:03 nbdkit: vddk[1]: debug: VixDiskLib: VixDiskLib_FreeConnectParams: Free connection parameters.
>May 27 14:16:03 libguestfs: trace: set_verbose true
>May 27 14:16:03 libguestfs: trace: set_verbose = 0
>May 27 14:16:03 libguestfs: trace: disk_has_backing_file "/var/tmp/v2vovl264a6c.qcow2"
>May 27 14:16:03 libguestfs: command: run: qemu-img --help | grep -sqE -- '\binfo\b.*-U\b'
>May 27 14:16:03 libguestfs: command: run: qemu-img
>May 27 14:16:03 libguestfs: command: run: \ info
>May 27 14:16:03 libguestfs: command: run: \ -U
>May 27 14:16:03 libguestfs: command: run: \ --output json
>May 27 14:16:03 libguestfs: command: run: \ /var/tmp/v2vovl264a6c.qcow2
>May 27 14:16:03 libguestfs: parse_json: qemu-img info JSON output:\n{\n    "backing-filename-format": "raw",\n    "virtual-size": 17179869184,\n    "filename": "/var/tmp/v2vovl264a6c.qcow2",\n    "cluster-size": 65536,\n    "format": "qcow2",\n    "actual-size": 200704,\n    "format-specific": {\n        "type": "qcow2",\n        "data": {\n            "compat": "1.1",\n            "lazy-refcounts": false,\n            "refcount-bits": 16,\n            "corrupt": false\n        }\n    },\n    "full-backing-filename": "nbd:unix:/tmp/v2vnbdkit.2QJC70/nbdkit1.sock:exportname=/",\n    "backing-filename": "nbd:unix:/tmp/v2vnbdkit.2QJC70/nbdkit1.sock:exportname=/",\n    "dirty-flag": false\n}\n\n
>May 27 14:16:03 libguestfs: trace: disk_has_backing_file = 1
>May 27 14:16:03 libguestfs: trace: set_verbose true
>May 27 14:16:03 libguestfs: trace: set_verbose = 0
>May 27 14:16:03 libguestfs: trace: disk_virtual_size "/var/tmp/v2vovl264a6c.qcow2"
>May 27 14:16:03 libguestfs: command: run: qemu-img --help | grep -sqE -- '\binfo\b.*-U\b'
>May 27 14:16:03 libguestfs: command: run: qemu-img
>May 27 14:16:03 libguestfs: command: run: \ info
>May 27 14:16:03 libguestfs: command: run: \ -U
>May 27 14:16:03 libguestfs: command: run: \ --output json
>May 27 14:16:03 libguestfs: command: run: \ /var/tmp/v2vovl264a6c.qcow2
>May 27 14:16:03 libguestfs: parse_json: qemu-img info JSON output:\n{\n    "backing-filename-format": "raw",\n    "virtual-size": 17179869184,\n    "filename": "/var/tmp/v2vovl264a6c.qcow2",\n    "cluster-size": 65536,\n    "format": "qcow2",\n    "actual-size": 200704,\n    "format-specific": {\n        "type": "qcow2",\n        "data": {\n            "compat": "1.1",\n            "lazy-refcounts": false,\n            "refcount-bits": 16,\n            "corrupt": false\n        }\n    },\n    "full-backing-filename": "nbd:unix:/tmp/v2vnbdkit.2QJC70/nbdkit1.sock:exportname=/",\n    "backing-filename": "nbd:unix:/tmp/v2vnbdkit.2QJC70/nbdkit1.sock:exportname=/",\n    "dirty-flag": false\n}\n\n
>May 27 14:16:03 libguestfs: trace: disk_virtual_size = 17179869184
>May 27 14:16:03 [   5.4] Opening the overlay
>May 27 14:16:03 libguestfs: trace: set_verbose true
>May 27 14:16:03 libguestfs: trace: set_verbose = 0
>May 27 14:16:03 libguestfs: trace: set_identifier "v2v"
>May 27 14:16:03 libguestfs: trace: v2v: set_identifier = 0
>May 27 14:16:03 libguestfs: trace: v2v: get_memsize
>May 27 14:16:03 libguestfs: trace: v2v: get_memsize = 768
>May 27 14:16:03 libguestfs: trace: v2v: set_memsize 2150
>May 27 14:16:03 libguestfs: trace: v2v: set_memsize = 0
>May 27 14:16:03 libguestfs: trace: v2v: set_network true
>May 27 14:16:03 libguestfs: trace: v2v: set_network = 0
>May 27 14:16:03 libguestfs: trace: v2v: add_drive "/var/tmp/v2vovl264a6c.qcow2" "format:qcow2" "cachemode:unsafe" "discard:besteffort" "copyonread:true"
>May 27 14:16:03 libguestfs: trace: v2v: add_drive = 0
>May 27 14:16:03 libguestfs: trace: v2v: launch
>May 27 14:16:03 libguestfs: trace: v2v: max_disks
>May 27 14:16:03 libguestfs: trace: v2v: max_disks = 255
>May 27 14:16:03 libguestfs: trace: v2v: get_tmpdir
>May 27 14:16:03 libguestfs: trace: v2v: get_tmpdir = "/tmp"
>May 27 14:16:03 libguestfs: trace: v2v: version
>May 27 14:16:03 libguestfs: trace: v2v: version = <struct guestfs_version = major: 1, minor: 42, release: 0, extra: rhel=8,release=1.module+el8.3.0+6496+d39ac712,libvirt, >
>May 27 14:16:03 libguestfs: trace: v2v: get_backend
>May 27 14:16:03 libguestfs: trace: v2v: get_backend = "libvirt"
>May 27 14:16:03 libguestfs: launch: program=virt-v2v
>May 27 14:16:03 libguestfs: launch: identifier=v2v
>May 27 14:16:03 libguestfs: launch: version=1.42.0rhel=8,release=1.module+el8.3.0+6496+d39ac712,libvirt
>May 27 14:16:03 libguestfs: launch: backend registered: unix
>May 27 14:16:03 libguestfs: launch: backend registered: uml
>May 27 14:16:03 libguestfs: launch: backend registered: libvirt
>May 27 14:16:03 libguestfs: launch: backend registered: direct
>May 27 14:16:03 libguestfs: launch: backend=libvirt
>May 27 14:16:03 libguestfs: launch: tmpdir=/tmp/libguestfsYGx07x
>May 27 14:16:03 libguestfs: launch: umask=0022
>May 27 14:16:03 libguestfs: launch: euid=0
>May 27 14:16:03 libguestfs: libvirt version = 6003000 (6.3.0)
>May 27 14:16:03 libguestfs: guest random name = guestfs-0d5k4b8x8q9o0ugv
>May 27 14:16:03 libguestfs: connect to libvirt
>May 27 14:16:03 libguestfs: opening libvirt handle: URI = qemu:///system, auth = default+wrapper, flags = 0
>May 27 14:16:03 libguestfs: successfully opened libvirt handle: conn = 0x5565d96bb5a0
>May 27 14:16:03 libguestfs: qemu version (reported by libvirt) = 5000000 (5.0.0)
>May 27 14:16:03 libguestfs: get libvirt capabilities
>May 27 14:16:03 libguestfs: parsing capabilities XML
>May 27 14:16:03 libguestfs: trace: v2v: get_backend_setting "force_tcg"
>May 27 14:16:03 libguestfs: trace: v2v: get_backend_setting = NULL (error)
>May 27 14:16:03 libguestfs: parsing domcapabilities XML
>May 27 14:16:03 libguestfs: trace: v2v: get_backend_setting "internal_libvirt_label"
>May 27 14:16:03 libguestfs: trace: v2v: get_backend_setting = NULL (error)
>May 27 14:16:03 libguestfs: trace: v2v: get_backend_setting "internal_libvirt_imagelabel"
>May 27 14:16:03 libguestfs: trace: v2v: get_backend_setting = NULL (error)
>May 27 14:16:03 libguestfs: trace: v2v: get_backend_setting "internal_libvirt_norelabel_disks"
>May 27 14:16:03 libguestfs: trace: v2v: get_backend_setting = NULL (error)
>May 27 14:16:03 libguestfs: build appliance
>May 27 14:16:03 libguestfs: trace: v2v: get_cachedir
>May 27 14:16:03 libguestfs: trace: v2v: get_cachedir = "/var/tmp"
>May 27 14:16:03 libguestfs: begin building supermin appliance
>May 27 14:16:03 libguestfs: run supermin
>May 27 14:16:03 libguestfs: command: run: /usr/bin/supermin
>May 27 14:16:03 libguestfs: command: run: \ --build
>May 27 14:16:03 libguestfs: command: run: \ --verbose
>May 27 14:16:03 libguestfs: command: run: \ --if-newer
>May 27 14:16:03 libguestfs: command: run: \ --lock /var/tmp/.guestfs-0/lock
>May 27 14:16:03 libguestfs: command: run: \ --copy-kernel
>May 27 14:16:03 libguestfs: command: run: \ -f ext2
>May 27 14:16:03 libguestfs: command: run: \ --host-cpu x86_64
>May 27 14:16:03 libguestfs: command: run: \ /usr/lib64/guestfs/supermin.d
>May 27 14:16:03 libguestfs: command: run: \ -o /var/tmp/.guestfs-0/appliance.d
>May 27 14:16:03 supermin: version: 5.1.19
>May 27 14:16:03 supermin: rpm: detected RPM version 4.14
>May 27 14:16:03 supermin: package handler: fedora/rpm
>May 27 14:16:03 supermin: acquiring lock on /var/tmp/.guestfs-0/lock
>May 27 14:16:03 supermin: if-newer: output does not need rebuilding
>May 27 14:16:03 libguestfs: finished building supermin appliance
>May 27 14:16:03 libguestfs: trace: v2v: disk_create "/tmp/libguestfsYGx07x/overlay1.qcow2" "qcow2" -1 "backingfile:/var/tmp/.guestfs-0/appliance.d/root" "backingformat:raw"
>May 27 14:16:03 libguestfs: command: run: qemu-img
>May 27 14:16:03 libguestfs: command: run: \ create
>May 27 14:16:03 libguestfs: command: run: \ -f qcow2
>May 27 14:16:03 libguestfs: command: run: \ -o backing_file=/var/tmp/.guestfs-0/appliance.d/root,backing_fmt=raw
>May 27 14:16:03 libguestfs: command: run: \ /tmp/libguestfsYGx07x/overlay1.qcow2
>May 27 14:16:03 Formatting '/tmp/libguestfsYGx07x/overlay1.qcow2', fmt=qcow2 size=4294967296 backing_file=/var/tmp/.guestfs-0/appliance.d/root backing_fmt=raw cluster_size=65536 lazy_refcounts=off refcount_bits=16
>May 27 14:16:03 libguestfs: trace: v2v: disk_create = 0
>May 27 14:16:03 libguestfs: trace: v2v: get_sockdir
>May 27 14:16:03 libguestfs: trace: v2v: get_sockdir = "/tmp"
>May 27 14:16:03 libguestfs: create libvirt XML
>May 27 14:16:03 libguestfs: command: run: file
>May 27 14:16:03 libguestfs: command: run: \ -- /var/tmp/.guestfs-0/appliance.d/root
>May 27 14:16:03 libguestfs: trace: v2v: get_cachedir
>May 27 14:16:03 libguestfs: trace: v2v: get_cachedir = "/var/tmp"
>May 27 14:16:03 libguestfs: libvirt XML:\n<?xml version="1.0"?>\n<domain type="kvm" xmlns:qemu="http://libvirt.org/schemas/domain/qemu/1.0">\n  <name>guestfs-0d5k4b8x8q9o0ugv</name>\n  <memory unit="MiB">2150</memory>\n  <currentMemory unit="MiB">2150</currentMemory>\n  <cpu mode="host-passthrough">\n    <model fallback="allow"/>\n  </cpu>\n  <vcpu>1</vcpu>\n  <clock offset="utc">\n    <timer name="rtc" tickpolicy="catchup"/>\n    <timer name="pit" tickpolicy="delay"/>\n    <timer name="hpet" present="no"/>\n  </clock>\n  <os>\n    <type>hvm</type>\n    <kernel>/var/tmp/.guestfs-0/appliance.d/kernel</kernel>\n    <initrd>/var/tmp/.guestfs-0/appliance.d/initrd</initrd>\n    <cmdline>panic=1 console=ttyS0 edd=off udevtimeout=6000 udev.event-timeout=6000 no_timer_check printk.time=1 cgroup_disable=memory usbcore.nousb cryptomgr.notests tsc=reliable 8250.nr_uarts=1 root=UUID=81b85e4f-3ff3-4510-b643-fa7ae5823200 selinux=0 guestfs_verbose=1 guestfs_network=1 TERM=xterm-256color guestfs_identifier=v2v</cmdline>\n    <bios useserial="yes"/>\n  </os>\n  <on_reboot>destroy</on_reboot>\n  <devices>\n    <rng model="virtio">\n      <backend model="random">/dev/urandom</backend>\n    </rng>\n    <controller type="scsi" index="0" model="virtio-scsi"/>\n    <disk device="disk" type="file">\n      <source file="/var/tmp/v2vovl264a6c.qcow2"/>\n      <target dev="sda" bus="scsi"/>\n      <driver name="qemu" type="qcow2" cache="unsafe" discard="unmap" copy_on_read="on"/>\n      <address type="drive" controller="0" bus="0" target="0" unit="0"/>\n    </disk>\n    <disk type="file" device="disk">\n      <source file="/tmp/libguestfsYGx07x/overlay1.qcow2"/>\n      <target dev="sdb" bus="scsi"/>\n      <driver name="qemu" type="qcow2" cache="unsafe"/>\n      <address type="drive" controller="0" bus="0" target="1" unit="0"/>\n    </disk>\n    <serial type="unix">\n      <source mode="connect" path="/tmp/libguestfs8848u5/console.sock"/>\n      <target port="0"/>\n    </serial>\n    <channel type="unix">\n      <source mode="connect" path="/tmp/libguestfs8848u5/guestfsd.sock"/>\n      <target type="virtio" name="org.libguestfs.channel.0"/>\n    </channel>\n    <controller type="usb" model="none"/>\n    <memballoon model="none"/>\n  </devices>\n  <qemu:commandline>\n    <qemu:env name="TMPDIR" value="/var/tmp"/>\n    <qemu:arg value="-netdev"/>\n    <qemu:arg value="user,id=usernet,net=169.254.0.0/16"/>\n    <qemu:arg value="-device"/>\n    <qemu:arg value="virtio-net-pci,netdev=usernet"/>\n  </qemu:commandline>\n</domain>\n
>May 27 14:16:03 libguestfs: trace: v2v: get_cachedir
>May 27 14:16:03 libguestfs: trace: v2v: get_cachedir = "/var/tmp"
>May 27 14:16:03 libguestfs: command: run: ls
>May 27 14:16:03 libguestfs: command: run: \ -a
>May 27 14:16:03 libguestfs: command: run: \ -l
>May 27 14:16:03 libguestfs: command: run: \ -R
>May 27 14:16:03 libguestfs: command: run: \ -Z /var/tmp/.guestfs-0
>May 27 14:16:03 libguestfs: /var/tmp/.guestfs-0:
>May 27 14:16:03 libguestfs: total 4
>May 27 14:16:03 libguestfs: drwxr-xr-x.  3 root root unconfined_u:object_r:user_tmp_t:s0   37 May 27 14:16 .
>May 27 14:16:03 libguestfs: drwxrwxrwt. 19 root root system_u:object_r:tmp_t:s0          4096 May 27 14:16 ..
>May 27 14:16:03 libguestfs: drwxr-xr-x.  2 root root unconfined_u:object_r:user_tmp_t:s0   46 May 27 12:47 appliance.d
>May 27 14:16:03 libguestfs: -rw-r--r--.  1 root root unconfined_u:object_r:user_tmp_t:s0    0 May 26 21:21 lock
>May 27 14:16:03 libguestfs: 
>May 27 14:16:03 libguestfs: /var/tmp/.guestfs-0/appliance.d:
>May 27 14:16:03 libguestfs: total 331380
>May 27 14:16:03 libguestfs: drwxr-xr-x. 2 root root unconfined_u:object_r:user_tmp_t:s0         46 May 27 12:47 .
>May 27 14:16:03 libguestfs: drwxr-xr-x. 3 root root unconfined_u:object_r:user_tmp_t:s0         37 May 27 14:16 ..
>May 27 14:16:03 libguestfs: -rw-r--r--. 1 qemu qemu system_u:object_r:virt_content_t:s0    4525056 May 27 14:16 initrd
>May 27 14:16:03 libguestfs: -rwxr-xr-x. 1 qemu qemu system_u:object_r:virt_content_t:s0    9048720 May 27 14:16 kernel
>May 27 14:16:03 libguestfs: -rw-r--r--. 1 qemu qemu system_u:object_r:virt_content_t:s0 4294967296 May 27 14:16 root
>May 27 14:16:03 libguestfs: command: run: ls
>May 27 14:16:03 libguestfs: command: run: \ -a
>May 27 14:16:03 libguestfs: command: run: \ -l
>May 27 14:16:03 libguestfs: command: run: \ -Z /tmp/libguestfs8848u5
>May 27 14:16:03 libguestfs: total 4
>May 27 14:16:03 libguestfs: drwxr-xr-x.  2 root root unconfined_u:object_r:user_tmp_t:s0   47 May 27 14:16 .
>May 27 14:16:03 libguestfs: drwxrwxrwt. 40 root root system_u:object_r:tmp_t:s0          4096 May 27 14:16 ..
>May 27 14:16:03 libguestfs: srw-rw----.  1 root qemu unconfined_u:object_r:user_tmp_t:s0    0 May 27 14:16 console.sock
>May 27 14:16:03 libguestfs: srw-rw----.  1 root qemu unconfined_u:object_r:user_tmp_t:s0    0 May 27 14:16 guestfsd.sock
>May 27 14:16:03 libguestfs: launch libvirt guest
>May 27 14:16:03 nbdkit: debug: accepted connection
>May 27 14:16:03 nbdkit: vddk[2]: debug: cacheextents: preconnect
>May 27 14:16:03 nbdkit: vddk[2]: debug: readahead: preconnect
>May 27 14:16:03 nbdkit: vddk[2]: debug: retry: preconnect
>May 27 14:16:03 nbdkit: vddk[2]: debug: vddk: preconnect
>May 27 14:16:03 nbdkit: vddk[2]: debug: newstyle negotiation: flags: global 0x3
>May 27 14:16:03 nbdkit: vddk[2]: debug: newstyle negotiation: client flags: 0x3
>May 27 14:16:03 nbdkit: vddk[2]: debug: newstyle negotiation: NBD_OPT_STRUCTURED_REPLY: client requested structured replies
>May 27 14:16:03 nbdkit: vddk[2]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: client requested export '/'
>May 27 14:16:03 nbdkit: vddk[2]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: set count: 1
>May 27 14:16:03 nbdkit: vddk[2]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: set base:allocation
>May 27 14:16:03 nbdkit: vddk[2]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: replying with base:allocation id 1
>May 27 14:16:03 nbdkit: vddk[2]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: reply complete
>May 27 14:16:03 nbdkit: vddk[2]: debug: newstyle negotiation: NBD_OPT_GO: client requested export '/'
>May 27 14:16:03 nbdkit: vddk[2]: debug: cacheextents: open readonly=1
>May 27 14:16:03 nbdkit: vddk[2]: debug: readahead: open readonly=1
>May 27 14:16:03 nbdkit: vddk[2]: debug: retry: open readonly=1
>May 27 14:16:03 nbdkit: vddk[2]: debug: vddk: open readonly=1
>May 27 14:16:03 nbdkit: vddk[2]: debug: VDDK call: VixDiskLib_AllocateConnectParams ()
>May 27 14:16:03 nbdkit: vddk[2]: debug: VDDK call: VixDiskLib_ConnectEx (h->params, 1, NULL, NULL, &connection)
>May 27 14:16:03 nbdkit: vddk[2]: debug: VixDiskLib: VixDiskLib_ConnectEx: Establish connection using (null).
>May 27 14:16:03 nbdkit: vddk[2]: debug: VixDiskLib: VixDiskLib_Connect: Establish connection.
>May 27 14:16:03 nbdkit: vddk[2]: debug: VixDiskLib: Resolve host.
>May 27 14:16:04 nbdkit: vddk[2]: debug: 2020-05-27T14:16:04.195+08:00 error -[20442] [Originator@6876 sub=Default] Cannot use advanced transport modes for 10.73.73.148/moref=vm-52/: Cannot create directory /tmp/vmware-root/42379ca1-f0d2-b2af-1bb1-0980f0dcc053-vm-52.
>May 27 14:16:04 nbdkit: vddk[2]: debug: VixDiskLib: VixDiskLib_ConnectEx: Advanced transport modes not available for opening moref=vm-52. (Cannot use advanced transport modes for 10.73.73.148/moref=vm-52/: Cannot create directory /tmp/vmware-root/42379ca1-f0d2-b2af-1bb1-0980f0dcc053-vm-52.)
>May 27 14:16:04 nbdkit: vddk[2]: debug: VDDK call: VixDiskLib_Open (connection, [ESX5.5-matrix] esx5.5-rhel6.10-x86_64/esx5.5-rhel6.10-x86_64.vmdk, 4, &handle)
>May 27 14:16:04 nbdkit: vddk[2]: debug: VixDiskLib: VixDiskLib_OpenEx: Open a disk.
>May 27 14:16:04 nbdkit: vddk[2]: debug: VixDiskLibVim: VixDiskLibVim_GetFileName: Get file name for [ESX5.5-matrix] esx5.5-rhel6.10-x86_64/esx5.5-rhel6.10-x86_64.vmdk.
>May 27 14:16:04 nbdkit: vddk[2]: debug: VixDiskLibVim: VixDiskLibVim_GetNfcTicket: Get NFC ticket for [ESX5.5-matrix] esx5.5-rhel6.10-x86_64/esx5.5-rhel6.10-x86_64.vmdk.
>May 27 14:16:04 nbdkit: vddk[2]: debug: VixDiskLibVim: Request RandomAccessRO diskKey = 2000, readOnly = 1, openSnapshot = 0.
>May 27 14:16:04 nbdkit: vddk[2]: debug: VixDiskLibVim: VixDiskLibVimFreeInternalVCAboutInfo: Free Internal VC AboutInfo.
>May 27 14:16:04 nbdkit: vddk[2]: debug: VixDiskLibVim: VixDiskLibVim_HandleDiskCryptoKey: handle the key of disk [ESX5.5-matrix] esx5.5-rhel6.10-x86_64/esx5.5-rhel6.10-x86_64.vmdk.
>May 27 14:16:04 nbdkit: vddk[2]: debug: VixDiskLibVim: VixDiskLibVim_FreeNfcTicket: Free NFC ticket.
>May 27 14:16:04 nbdkit: vddk[2]: debug: VixDiskLibVim: VixDiskLibVim_FreeFileName: Free file name.
>May 27 14:16:04 nbdkit: vddk[2]: debug: NBD_ClientOpen: attempting to create connection to vpxa-nfc://[ESX5.5-matrix] esx5.5-rhel6.10-x86_64/esx5.5-rhel6.10-x86_64.vmdk@10.73.3.19:902
>May 27 14:16:04 nbdkit: vddk[2]: debug: CnxAuthdProtoSecureConnect: Target authd does not support BANNER (530).
>May 27 14:16:04 nbdkit: vddk[2]: debug: DictionaryLoad: Cannot open file "/etc/vmware/vsphereFeatures/vsphereFeatures.cfg": No such file or directory.
>May 27 14:16:04 nbdkit: vddk[2]: debug: [msg.dictionary.load.openFailed] Cannot open file "/etc/vmware/vsphereFeatures/vsphereFeatures.cfg": No such file or directory.
>May 27 14:16:04 nbdkit: vddk[2]: debug: FeatureStateLib: Error while loading feature config file: /etc/vmware/vsphereFeatures/vsphereFeatures.cfg, using default feature state values.
>May 27 14:16:04 nbdkit: vddk[2]: debug: NFC Sync IO session is established.
>May 27 14:16:04 nbdkit: vddk[2]: debug: Opening file [ESX5.5-matrix] esx5.5-rhel6.10-x86_64/esx5.5-rhel6.10-x86_64.vmdk (vpxa-nfc://[ESX5.5-matrix] esx5.5-rhel6.10-x86_64/esx5.5-rhel6.10-x86_64.vmdk@10.73.3.19:902)
>May 27 14:16:04 nbdkit: vddk[2]: debug: DISKLIB-LINK  : Opened 'vpxa-nfc://[ESX5.5-matrix] esx5.5-rhel6.10-x86_64/esx5.5-rhel6.10-x86_64.vmdk@10.73.3.19:902' (0xe): custom, 33554432 sectors / 16 GB.
>May 27 14:16:05 nbdkit: vddk[2]: debug: DISKLIB-LIB   : Opened "vpxa-nfc://[ESX5.5-matrix] esx5.5-rhel6.10-x86_64/esx5.5-rhel6.10-x86_64.vmdk@10.73.3.19:902" (flags 0xe, type custom).
>May 27 14:16:05 nbdkit: vddk[2]: debug: VixDiskLib: VixDiskLib_GetTransportMode: Retrieve transport mode.
>May 27 14:16:05 nbdkit: vddk[2]: debug: transport mode: nbd
>May 27 14:16:05 nbdkit: vddk[2]: debug: vddk: open returned handle 0x7f9cf42fd130
>May 27 14:16:05 nbdkit: vddk[2]: debug: retry: open returned handle 0x7f9cf4001ee0
>May 27 14:16:05 nbdkit: vddk[2]: debug: readahead: open returned handle 0x7f9cfbfff580
>May 27 14:16:05 nbdkit: vddk[2]: debug: cacheextents: open returned handle 0x7f9cfbfff580
>May 27 14:16:05 nbdkit: vddk[2]: debug: vddk: prepare readonly=1
>May 27 14:16:05 nbdkit: vddk[2]: debug: retry: prepare readonly=1
>May 27 14:16:05 nbdkit: vddk[2]: debug: readahead: prepare readonly=1
>May 27 14:16:05 nbdkit: vddk[2]: debug: retry: get_size
>May 27 14:16:05 nbdkit: vddk[2]: debug: vddk: get_size
>May 27 14:16:05 nbdkit: vddk[2]: debug: VDDK call: VixDiskLib_GetInfo (handle, &info)
>May 27 14:16:05 nbdkit: vddk[2]: debug: VixDiskLib: VixDiskLib_GetInfo: Retrieve disk info.
>May 27 14:16:06 nbdkit: vddk[2]: debug: VDDK call: VixDiskLib_FreeInfo (info)
>May 27 14:16:06 nbdkit: vddk[2]: debug: VixDiskLib: VixDiskLib_FreeInfo: Clean up VixDiskLib.
>May 27 14:16:06 nbdkit: vddk[2]: debug: cacheextents: prepare readonly=1
>May 27 14:16:06 nbdkit: vddk[2]: debug: cacheextents: get_size
>May 27 14:16:06 nbdkit: vddk[2]: debug: readahead: get_size
>May 27 14:16:06 nbdkit: vddk[2]: debug: cacheextents: can_zero
>May 27 14:16:06 nbdkit: vddk[2]: debug: cacheextents: can_fast_zero
>May 27 14:16:06 nbdkit: vddk[2]: debug: cacheextents: can_trim
>May 27 14:16:06 nbdkit: vddk[2]: debug: cacheextents: can_fua
>May 27 14:16:06 nbdkit: vddk[2]: debug: cacheextents: can_flush
>May 27 14:16:06 nbdkit: vddk[2]: debug: readahead: can_flush
>May 27 14:16:06 nbdkit: vddk[2]: debug: retry: can_flush
>May 27 14:16:06 nbdkit: vddk[2]: debug: vddk: can_flush
>May 27 14:16:06 nbdkit: vddk[2]: debug: cacheextents: is_rotational
>May 27 14:16:06 nbdkit: vddk[2]: debug: readahead: is_rotational
>May 27 14:16:06 nbdkit: vddk[2]: debug: retry: is_rotational
>May 27 14:16:06 nbdkit: vddk[2]: debug: vddk: is_rotational
>May 27 14:16:06 nbdkit: vddk[2]: debug: cacheextents: can_multi_conn
>May 27 14:16:06 nbdkit: vddk[2]: debug: readahead: can_multi_conn
>May 27 14:16:06 nbdkit: vddk[2]: debug: retry: can_multi_conn
>May 27 14:16:06 nbdkit: vddk[2]: debug: vddk: can_multi_conn
>May 27 14:16:06 nbdkit: vddk[2]: debug: cacheextents: can_cache
>May 27 14:16:06 nbdkit: vddk[2]: debug: readahead: can_cache
>May 27 14:16:06 nbdkit: vddk[2]: debug: cacheextents: can_extents
>May 27 14:16:06 nbdkit: vddk[2]: debug: readahead: can_extents
>May 27 14:16:06 nbdkit: vddk[2]: debug: retry: can_extents
>May 27 14:16:06 nbdkit: vddk[2]: debug: vddk: can_extents
>May 27 14:16:06 nbdkit: vddk[2]: debug: VDDK call: VixDiskLib_QueryAllocatedBlocks (handle, 0, 128 sectors, 128 sectors)
>May 27 14:16:06 nbdkit: vddk[2]: debug: VixDiskLib: VixDiskLib_QueryAllocatedBlocks: Query allocated blocks.
>May 27 14:16:07 nbdkit: vddk[2]: error: [NFC ERROR] NfcFssrvrProcessErrorMsg: received NFC error 2 from server: Illegal message during fssrvr session, id = 49
>May 27 14:16:07 nbdkit: vddk[2]: debug: DISKLIB-LIB_MISC   : DiskLibGetAllocatedSectorChunksInRangeInt: failed to get allocated sector bitmap with 'NBD_ERR_GENERIC' (290).
>May 27 14:16:07 nbdkit: vddk[2]: debug: VixDiskLib: Detected DiskLib error 290 (NBD_ERR_GENERIC).
>May 27 14:16:07 nbdkit: vddk[2]: debug: VixDiskLib: VixDiskLibQueryBlockList: Fail to query blocks (offset 0, chunkSize 128, chunkNumber 1). Error 1 (Unknown error) (DiskLib error 290: NBD_ERR_GENERIC) at 563.
>May 27 14:16:07 nbdkit: vddk[2]: debug: can_extents: VixDiskLib_QueryAllocatedBlocks test failed, extents support will be disabled: original error: Unknown error
>May 27 14:16:07 nbdkit: vddk[2]: debug: newstyle negotiation: flags: export 0x487
>May 27 14:16:07 nbdkit: vddk[2]: debug: newstyle negotiation: NBD_OPT_GO: ignoring NBD_INFO_* request 3 (NBD_INFO_BLOCK_SIZE)
>May 27 14:16:07 nbdkit: vddk[2]: debug: handshake complete, processing requests serially
>May 27 14:16:07 nbdkit: vddk[2]: error: [NFC ERROR] NfcFssrvr_IOEx: Received unexpected message: NFC_SESSION_COMPLETE from server. Expected message: NFC_FSSRVR_MULTIIO_EX
>May 27 14:16:07 nbdkit: vddk[2]: debug: DISKLIB-LIB   : RWv failed ioId: #1 (290) (34) .
>May 27 14:16:07 nbdkit: vddk[2]: debug: VixDiskLib: Detected DiskLib error 290 (NBD_ERR_GENERIC).
>May 27 14:16:07 nbdkit: vddk[2]: debug: VixDiskLib: VixDiskLib_Read: Read 128 sectors at 0 failed. Error 1 (Unknown error) (DiskLib error 290: NBD_ERR_GENERIC) at 5814.
>May 27 14:16:07 nbdkit: vddk[2]: error: VixDiskLib_Read: Unknown error
>May 27 14:16:07 nbdkit: vddk[2]: debug: pread failed: original errno = 5
>May 27 14:16:07 nbdkit: vddk[2]: debug: retry 1: waiting 2 seconds before retrying
>May 27 14:16:09 nbdkit: vddk[2]: debug: vddk: reopen readonly=1
>May 27 14:16:09 nbdkit: vddk[2]: debug: vddk: finalize
>May 27 14:16:09 nbdkit: vddk[2]: debug: vddk: close
>May 27 14:16:09 nbdkit: vddk[2]: debug: VDDK call: VixDiskLib_Close (handle)
>May 27 14:16:09 nbdkit: vddk[2]: debug: VixDiskLib: VixDiskLib_Close: Close disk.
>May 27 14:16:09 nbdkit: vddk[2]: error: [NFC ERROR] NfcNetTcpSetError: Broken pipe
>May 27 14:16:09 nbdkit: vddk[2]: error: [NFC ERROR] NfcNetTcpWrite: bWritten: -1. Errno: 32.
>May 27 14:16:09 nbdkit: vddk[2]: error: [NFC ERROR] NfcSendMessage: NfcNet_Send failed: NFC_NETWORK_ERROR
>May 27 14:16:09 nbdkit: vddk[2]: error: [NFC ERROR] NfcFssrvr_Close: Failed to send close message: The operation experienced a network error (NFC_NETWORK_ERROR)
>May 27 14:16:09 nbdkit: vddk[2]: error: [NFC ERROR] NfcNetTcpSetError: Broken pipe
>May 27 14:16:09 nbdkit: vddk[2]: error: [NFC ERROR] NfcNetTcpWrite: bWritten: -1. Errno: 32.
>May 27 14:16:09 nbdkit: vddk[2]: error: [NFC ERROR] NfcSendMessage: NfcNet_Send failed: NFC_NETWORK_ERROR
>May 27 14:16:09 nbdkit: vddk[2]: debug: VixDiskLibVim: VixDiskLibVim_HandleDiskCryptoKey: handle the key of disk [ESX5.5-matrix] esx5.5-rhel6.10-x86_64/esx5.5-rhel6.10-x86_64.vmdk.
>May 27 14:16:09 nbdkit: vddk[2]: debug: VDDK call: VixDiskLib_Disconnect (connection)
>May 27 14:16:09 nbdkit: vddk[2]: debug: VixDiskLib: VixDiskLib_Disconnect: Disconnect.
>May 27 14:16:09 nbdkit: vddk[2]: debug: VixDiskLib: VixDiskLib_FreeConnectParams: Free connection parameters.
>May 27 14:16:09 nbdkit: vddk[2]: debug: VDDK call: VixDiskLib_FreeConnectParams (params)
>May 27 14:16:09 nbdkit: vddk[2]: debug: VixDiskLib: VixDiskLib_FreeConnectParams: Free connection parameters.
>May 27 14:16:09 nbdkit: vddk[2]: debug: vddk: open readonly=1
>May 27 14:16:09 nbdkit: vddk[2]: debug: VDDK call: VixDiskLib_AllocateConnectParams ()
>May 27 14:16:09 nbdkit: vddk[2]: debug: VDDK call: VixDiskLib_ConnectEx (h->params, 1, NULL, NULL, &connection)
>May 27 14:16:09 nbdkit: vddk[2]: debug: VixDiskLib: VixDiskLib_ConnectEx: Establish connection using (null).
>May 27 14:16:09 nbdkit: vddk[2]: debug: VixDiskLib: VixDiskLib_Connect: Establish connection.
>May 27 14:16:09 nbdkit: vddk[2]: debug: VixDiskLib: Resolve host.
>May 27 14:16:09 nbdkit: vddk[2]: debug: 2020-05-27T14:16:09.645+08:00 error -[20442] [Originator@6876 sub=Default] Cannot use advanced transport modes for 10.73.73.148/moref=vm-52/: Cannot create directory /tmp/vmware-root/42379ca1-f0d2-b2af-1bb1-0980f0dcc053-vm-52.
>May 27 14:16:09 nbdkit: vddk[2]: debug: VixDiskLib: VixDiskLib_ConnectEx: Advanced transport modes not available for opening moref=vm-52. (Cannot use advanced transport modes for 10.73.73.148/moref=vm-52/: Cannot create directory /tmp/vmware-root/42379ca1-f0d2-b2af-1bb1-0980f0dcc053-vm-52.)
>May 27 14:16:09 nbdkit: vddk[2]: debug: VDDK call: VixDiskLib_Open (connection, [ESX5.5-matrix] esx5.5-rhel6.10-x86_64/esx5.5-rhel6.10-x86_64.vmdk, 4, &handle)
>May 27 14:16:09 nbdkit: vddk[2]: debug: VixDiskLib: VixDiskLib_OpenEx: Open a disk.
>May 27 14:16:09 nbdkit: vddk[2]: debug: VixDiskLibVim: VixDiskLibVim_GetFileName: Get file name for [ESX5.5-matrix] esx5.5-rhel6.10-x86_64/esx5.5-rhel6.10-x86_64.vmdk.
>May 27 14:16:09 nbdkit: vddk[2]: debug: VixDiskLibVim: VixDiskLibVim_GetNfcTicket: Get NFC ticket for [ESX5.5-matrix] esx5.5-rhel6.10-x86_64/esx5.5-rhel6.10-x86_64.vmdk.
>May 27 14:16:09 nbdkit: vddk[2]: debug: VixDiskLibVim: Request RandomAccessRO diskKey = 2000, readOnly = 1, openSnapshot = 0.
>May 27 14:16:09 nbdkit: vddk[2]: debug: VixDiskLibVim: VixDiskLibVimFreeInternalVCAboutInfo: Free Internal VC AboutInfo.
>May 27 14:16:09 nbdkit: vddk[2]: debug: VixDiskLibVim: VixDiskLibVim_HandleDiskCryptoKey: handle the key of disk [ESX5.5-matrix] esx5.5-rhel6.10-x86_64/esx5.5-rhel6.10-x86_64.vmdk.
>May 27 14:16:09 nbdkit: vddk[2]: debug: VixDiskLibVim: VixDiskLibVim_FreeNfcTicket: Free NFC ticket.
>May 27 14:16:09 nbdkit: vddk[2]: debug: VixDiskLibVim: VixDiskLibVim_FreeFileName: Free file name.
>May 27 14:16:09 nbdkit: vddk[2]: debug: NBD_ClientOpen: attempting to create connection to vpxa-nfc://[ESX5.5-matrix] esx5.5-rhel6.10-x86_64/esx5.5-rhel6.10-x86_64.vmdk@10.73.3.19:902
>May 27 14:16:10 nbdkit: vddk[2]: debug: CnxAuthdProtoSecureConnect: Target authd does not support BANNER (530).
>May 27 14:16:10 nbdkit: vddk[2]: debug: DictionaryLoad: Cannot open file "/etc/vmware/vsphereFeatures/vsphereFeatures.cfg": No such file or directory.
>May 27 14:16:10 nbdkit: vddk[2]: debug: [msg.dictionary.load.openFailed] Cannot open file "/etc/vmware/vsphereFeatures/vsphereFeatures.cfg": No such file or directory.
>May 27 14:16:10 nbdkit: vddk[2]: debug: FeatureStateLib: Error while loading feature config file: /etc/vmware/vsphereFeatures/vsphereFeatures.cfg, using default feature state values.
>May 27 14:16:10 nbdkit: vddk[2]: debug: NFC Sync IO session is established.
>May 27 14:16:10 nbdkit: vddk[2]: debug: Opening file [ESX5.5-matrix] esx5.5-rhel6.10-x86_64/esx5.5-rhel6.10-x86_64.vmdk (vpxa-nfc://[ESX5.5-matrix] esx5.5-rhel6.10-x86_64/esx5.5-rhel6.10-x86_64.vmdk@10.73.3.19:902)
>May 27 14:16:10 nbdkit: vddk[2]: debug: DISKLIB-LINK  : Opened 'vpxa-nfc://[ESX5.5-matrix] esx5.5-rhel6.10-x86_64/esx5.5-rhel6.10-x86_64.vmdk@10.73.3.19:902' (0xe): custom, 33554432 sectors / 16 GB.
>May 27 14:16:11 nbdkit: vddk[2]: debug: DISKLIB-LIB   : Opened "vpxa-nfc://[ESX5.5-matrix] esx5.5-rhel6.10-x86_64/esx5.5-rhel6.10-x86_64.vmdk@10.73.3.19:902" (flags 0xe, type custom).
>May 27 14:16:11 nbdkit: vddk[2]: debug: VixDiskLib: VixDiskLib_GetTransportMode: Retrieve transport mode.
>May 27 14:16:11 nbdkit: vddk[2]: debug: transport mode: nbd
>May 27 14:16:11 nbdkit: vddk[2]: debug: vddk: open returned handle 0x7f9cf45ae630
>May 27 14:16:11 nbdkit: vddk[2]: debug: vddk: prepare readonly=1
>May 27 14:16:11 nbdkit: vddk[2]: debug: vddk: get_size
>May 27 14:16:11 nbdkit: vddk[2]: debug: VDDK call: VixDiskLib_GetInfo (handle, &info)
>May 27 14:16:11 nbdkit: vddk[2]: debug: VixDiskLib: VixDiskLib_GetInfo: Retrieve disk info.
>May 27 14:16:12 nbdkit: vddk[2]: debug: VDDK call: VixDiskLib_FreeInfo (info)
>May 27 14:16:12 nbdkit: vddk[2]: debug: VixDiskLib: VixDiskLib_FreeInfo: Clean up VixDiskLib.
>
>
>
>
>
>
>
>
>
>
>

Actions: View

Attachments on bug 1837840: 1692569 | 1692572 | 1692596 | 1692597 | 1692598 | 1692600