Problems with vSphere Upgrade from v5.5 to 6.0

[NelsonCandela]

Dear all,

I am currently trying to upgrade a 5.5 VCSA environment with embedded PSC from 5.5 to 6.0 latest.

A few pieces of information first:

• Source and target host is the same as currently only one host is available
• A Helper-VM exists (Windows 2012 R2 VM) from which I start the Upgrade/migration process
• ESXi SSH is up and running on both ESXi server and old VCSA
• SSH login on both systems works fine
• SSL certificates of the VCSA are default, self-signed ones

Since DNS is not working (DNS servers are not resolvable) I have added the required IP addresses / host entries in both the Windows Helper VM as well as in the old VCSA (/etc/hosts). This makes the machines react to PING and I have added all aliases to the hosts files to be able to resolve FQDNs. Problem bypassed I hope, currently there is no other option I'm afraid. Also I have turned off the Firewall in the Windows Helper VM.

There are several log files written which do not tell me much about the factual problem. Even if the status windows remains the same for hours saying that the new VCSA is being started (see attached file/screenshot) it actually is started already but it seems no data is being transferred. Also the old VM is not being shut down, everyhing just kind of hangs with no progress shown.

Below I have put some information from the log files, maybe this makes things clearer (the last app. 20 lines of each file).

csd.log:

[...]

[2017-07-31 14:28:16] [INFO] Process [N3tY-hs8P-ZpjG-ywCE]: Waiting for process to exit...

[2017-07-31 14:28:16] [INFO] Process [N3tY-hs8P-ZpjG-ywCE]: Thread has been terminated.

[2017-07-31 14:28:16] [INFO] Process [N3tY-hs8P-ZpjG-ywCE]: Process has exited.

[2017-07-31 14:28:16] [INFO] Process [MjZz-n9t4-nZbI-QIrn]: Waiting for process to exit...

[2017-07-31 14:28:16] [INFO] Process [MjZz-n9t4-nZbI-QIrn]: Thread has been terminated.

[2017-07-31 14:28:16] [INFO] Process [MjZz-n9t4-nZbI-QIrn]: Process has exited.

[2017-07-31 14:28:16] [INFO] Process [ELko-Ap2c-O08w-yUzm]: Waiting for process to exit...

[2017-07-31 14:28:17] [INFO] Process [ELko-Ap2c-O08w-yUzm]: Thread has been terminated.

[2017-07-31 14:28:17] [INFO] Process [ELko-Ap2c-O08w-yUzm]: Process has exited.

[2017-07-31 14:28:17] [INFO] Process [8Xx2-Ekqo-JoGr-9aOS]: Waiting for process to exit...

[2017-07-31 14:28:17] [INFO] Process [8Xx2-Ekqo-JoGr-9aOS]: Thread has been terminated.

[2017-07-31 14:28:17] [INFO] Process [8Xx2-Ekqo-JoGr-9aOS]: Process has exited.

[2017-07-31 14:28:17] [INFO] Process [1ofB-AZcT-LwTU-Qqdk]: Waiting for process to exit...

[2017-07-31 14:28:18] [INFO] Process [1ofB-AZcT-LwTU-Qqdk]: Thread has been terminated.

[2017-07-31 14:28:18] [INFO] Process [1ofB-AZcT-LwTU-Qqdk]: Process has exited.

[2017-07-31 14:28:18] [INFO] Process [0ekx-Rskr-eHNK-IJVj]: Waiting for process to exit...

[2017-07-31 14:28:18] [INFO] Process [0ekx-Rskr-eHNK-IJVj]: Thread has been terminated.

[2017-07-31 14:28:18] [INFO] Process [0ekx-Rskr-eHNK-IJVj]: Process has exited.

filetransfer-2108.log

[...]

Initiating file transfer from guest ...

...done. Getting VM moRef...

...done.

Initiating file transfer from guest ...

...done. Getting VM moRef...

...done.

Initiating file transfer from guest ...

...done. Getting VM moRef...

...done.

Initiating file transfer from guest ...

...done. Getting VM moRef...

...done.

Initiating file transfer from guest ...

...done. Getting VM moRef...

...done.

Initiating file transfer from guest ...

...done. Getting VM moRef...

...done.

Initiating file transfer from guest ...

plugin-ovftool-2108.log:

[...]

2017-07-31T12:04:57.246+02:00 verbose -[02388] [Originator@6876 sub=Default] Parsing URL https://192.168.216.79/ha-nfc/524d7052-cfe1-713f-be97-cdbd1ea2a143/disk-1.vmdk...

2017-07-31T12:04:57.246+02:00 verbose -[02388] [Originator@6876 sub=Default] Constructing URL...

2017-07-31T12:04:57.246+02:00 verbose -[02388] [Originator@6876 sub=Default] https://192.168.216.79:443/ha-nfc/524d7052-cfe1-713f-be97-cdbd1ea2a143/disk-1.vmdk is redirected to https://192.168.216.79/ha-nfc/524d7052-cfe1-713f-be97-cdbd1ea2a143/disk-1.vmdk

2017-07-31T12:04:57.246+02:00 verbose -[02388] [Originator@6876 sub=Default] Changing HttpWriterFactory path to https://192.168.216.79/ha-nfc/524d7052-cfe1-713f-be97-cdbd1ea2a143

2017-07-31T12:05:14.449+02:00 verbose -[04088] [Originator@6876 sub=HttpConnectionPool-000001] [RemoveConnection] Connection removed; cnx: <SSL(<io_obj p:0x02f64c58, h:-1, <TCP '0.0.0.0:0'>, <TCP '192.168.216.79:443'>>)>; pooled: 0

2017-07-31T12:05:21.074+02:00 verbose -[02388] [Originator@6876 sub=Default] Closing writer. Locator: https://192.168.216.79:443/ha-nfc/524d7052-cfe1-713f-be97-cdbd1ea2a143/disk-1.vmdk (Written bytes: 1631066624)

2017-07-31T12:05:21.074+02:00 verbose -[02388] [Originator@6876 sub=Default] Curl session torn down

2017-07-31T12:05:21.074+02:00 verbose -[00836] [Originator@6876 sub=Default] Ovf convertion finished

2017-07-31T12:05:21.074+02:00 verbose -[00836] [Originator@6876 sub=Default] Vi4Target::Complete: Unexpected number of tasks running on target: 0

2017-07-31T12:05:21.308+02:00 verbose -[01736] [Originator@6876 sub=Default] Caught exception while sending lease progress: vmodl.fault.SystemError

2017-07-31T12:07:02.511+02:00 verbose -[00836] [Originator@6876 sub=Default] OutputFilePath :

2017-07-31T12:07:02.590+02:00 verbose -[00836] [Originator@6876 sub=Default] Url did not respond, so we got exception!

2017-07-31T12:07:02.605+02:00 verbose -[00836] [Originator@6876 sub=Default] Url did not respond, so we got exception!

2017-07-31T12:07:02.621+02:00 verbose -[00836] [Originator@6876 sub=Default] Url did not respond, so we got exception!

2017-07-31T12:07:02.636+02:00 verbose -[00836] [Originator@6876 sub=Default] Url did not respond, so we got exception!

2017-07-31T12:07:02.668+02:00 verbose -[00836] [Originator@6876 sub=Default] Url did not respond, so we got exception!

2017-07-31T12:07:02.668+02:00 verbose -[00836] [Originator@6876 sub=Default] Too many exceptions, stop monitoring this VM!

2017-07-31T12:07:02.668+02:00 verbose -[00836] [Originator@6876 sub=Default] Destruction of ViTarget

*The mentioned IP address (192.168.216.79) belongs to the ESXi host the old VCSA is running on

wss_8093.log:

[2017-07-31 09:47:14] [connect] WebSocket Connection 127.0.0.1:49235 v13 "Mozilla/5.0 (Windows NT 6.3; WOW64; Trident/7.0; rv:11.0) like Gecko" / 101

[2017-07-31 09:47:15] [control] Control frame received with opcode 8

[2017-07-31 09:47:15] [error] handle_read_frame error: asio.ssl:335544539 (short read)

[2017-07-31 09:47:15] [info] asio async_shutdown error: system:10053 (An established connection was aborted by the software in your host machine)

[2017-07-31 09:47:15] [disconnect] Disconnect close local:[1006,short read] remote:[1005]

wss_50100.log:

[...]

[2017-07-31 11:54:45] [control] Control frame received with opcode 10

[2017-07-31 11:55:15] [control] Control frame received with opcode 10

[2017-07-31 11:55:45] [control] Control frame received with opcode 10

[2017-07-31 11:56:15] [control] Control frame received with opcode 10

[2017-07-31 11:56:45] [control] Control frame received with opcode 10

[2017-07-31 11:57:45] [control] Control frame received with opcode 10

[2017-07-31 11:58:15] [control] Control frame received with opcode 10

[2017-07-31 11:58:45] [control] Control frame received with opcode 10

[2017-07-31 11:59:15] [control] Control frame received with opcode 10

[2017-07-31 11:59:45] [control] Control frame received with opcode 10

[2017-07-31 12:00:45] [control] Control frame received with opcode 10

[2017-07-31 12:01:15] [control] Control frame received with opcode 10

[2017-07-31 12:01:45] [control] Control frame received with opcode 10

[2017-07-31 12:02:15] [control] Control frame received with opcode 10

[2017-07-31 12:02:45] [control] Control frame received with opcode 10

[2017-07-31 12:03:15] [control] Control frame received with opcode 10

[2017-07-31 12:03:45] [control] Control frame received with opcode 10

[2017-07-31 12:06:15] [control] Control frame received with opcode 10

[2017-07-31 12:06:45] [control] Control frame received with opcode 10

vcsa_0000.log:

[...]

2017-07-31 14:21:29.339308 CIP Service [VCSA INFO] nfc.vmGetFile: {"type":"result","statusCode":"PROCESS_STATUS","sessionId":"MaKj-iWqJ-ETkG-R1iV","requestId":"6960","requestComponentId":"fileTransfer","requestObjectId":"pdIx-ghDj-k1uR-gnAG","result":"","isFinal":"true"}

2017-07-31 14:21:33.438158 CIP Service [VCSA INFO] nfc.vmGetFile: {"type":"result","statusCode":"PROCESS_STATUS","sessionId":"MaKj-iWqJ-ETkG-R1iV","requestId":"6964","requestComponentId":"fileTransfer","requestObjectId":"SnVo-6tUS-uw3U-GOqW","result":"","isFinal":"false","item":["{\"error\":\"vim.fault.FileNotFound\"}"]}

2017-07-31 14:21:34.251814 CIP Service [VCSA INFO] nfc.vmGetFile: {"type":"result","statusCode":"PROCESS_STATUS","sessionId":"MaKj-iWqJ-ETkG-R1iV","requestId":"6964","requestComponentId":"fileTransfer","requestObjectId":"SnVo-6tUS-uw3U-GOqW","result":"","isFinal":"true"}

2017-07-31 14:21:37.928790 CIP Service [VCSA INFO] nfc.vmGetFile: {"type":"result","statusCode":"PROCESS_STATUS","sessionId":"MaKj-iWqJ-ETkG-R1iV","requestId":"6970","requestComponentId":"fileTransfer","requestObjectId":"kAcn-kS6E-gaZE-jf2U","result":"","isFinal":"false","item":["{\"error\":\"vim.fault.FileNotFound\"}"]}

2017-07-31 14:21:39.367390 CIP Service [VCSA INFO] nfc.vmGetFile: {"type":"result","statusCode":"PROCESS_STATUS","sessionId":"MaKj-iWqJ-ETkG-R1iV","requestId":"6970","requestComponentId":"fileTransfer","requestObjectId":"kAcn-kS6E-gaZE-jf2U","result":"","isFinal":"true"}

2017-07-31 14:21:43.497472 CIP Service [VCSA INFO] nfc.vmGetFile: {"type":"result","statusCode":"PROCESS_STATUS","sessionId":"MaKj-iWqJ-ETkG-R1iV","requestId":"6974","requestComponentId":"fileTransfer","requestObjectId":"LMmF-XxWn-fRkW-LeuU","result":"","isFinal":"false","item":["{\"error\":\"vim.fault.FileNotFound\"}"]}

2017-07-31 14:21:44.311001 CIP Service [VCSA INFO] nfc.vmGetFile: {"type":"result","statusCode":"PROCESS_STATUS","sessionId":"MaKj-iWqJ-ETkG-R1iV","requestId":"6974","requestComponentId":"fileTransfer","requestObjectId":"LMmF-XxWn-fRkW-LeuU","result":"","isFinal":"true"}

2017-07-31 14:21:48.472313 CIP Service [VCSA INFO] nfc.vmGetFile: {"type":"result","statusCode":"PROCESS_STATUS","sessionId":"MaKj-iWqJ-ETkG-R1iV","requestId":"6978","requestComponentId":"fileTransfer","requestObjectId":"qqWx-MvQ8-Rf6K-hbLe","result":"","isFinal":"false","item":["{\"error\":\"vim.fault.FileNotFound\"}"]}

2017-07-31 14:21:49.285861 CIP Service [VCSA INFO] nfc.vmGetFile: {"type":"result","statusCode":"PROCESS_STATUS","sessionId":"MaKj-iWqJ-ETkG-R1iV","requestId":"6978","requestComponentId":"fileTransfer","requestObjectId":"qqWx-MvQ8-Rf6K-hbLe","result":"","isFinal":"true"}

2017-07-31 14:21:53.384690 CIP Service [VCSA INFO] nfc.vmGetFile: {"type":"result","statusCode":"PROCESS_STATUS","sessionId":"MaKj-iWqJ-ETkG-R1iV","requestId":"6982","requestComponentId":"fileTransfer","requestObjectId":"E9GZ-nSUA-qxmJ-30bp","result":"","isFinal":"false","item":["{\"error\":\"vim.fault.FileNotFound\"}"]}

2017-07-31 14:21:54.213901 CIP Service [VCSA INFO] nfc.vmGetFile: {"type":"result","statusCode":"PROCESS_STATUS","sessionId":"MaKj-iWqJ-ETkG-R1iV","requestId":"6982","requestComponentId":"fileTransfer","requestObjectId":"E9GZ-nSUA-qxmJ-30bp","result":"","isFinal":"true"}

2017-07-31 14:21:57.922111 CIP Service [VCSA INFO] nfc.vmGetFile: {"type":"result","statusCode":"PROCESS_STATUS","sessionId":"MaKj-iWqJ-ETkG-R1iV","requestId":"6985","requestComponentId":"fileTransfer","requestObjectId":"c4B2-em9Q-MSOj-urDs","result":"","isFinal":"false","item":["{\"error\":\"vim.fault.FileNotFound\"}"]}

2017-07-31 14:21:59.360655 CIP Service [VCSA INFO] nfc.vmGetFile: {"type":"result","statusCode":"PROCESS_STATUS","sessionId":"MaKj-iWqJ-ETkG-R1iV","requestId":"6985","requestComponentId":"fileTransfer","requestObjectId":"c4B2-em9Q-MSOj-urDs","result":"","isFinal":"true"}

2017-07-31 14:22:02.928418 CIP Service [VCSA INFO] nfc.vmGetFile: {"type":"result","statusCode":"PROCESS_STATUS","sessionId":"MaKj-iWqJ-ETkG-R1iV","requestId":"6989","requestComponentId":"fileTransfer","requestObjectId":"bQmp-2Eez-tVZg-LA5k","result":"","isFinal":"false","item":["{\"error\":\"vim.fault.FileNotFound\"}"]}

2017-07-31 14:22:04.366949 CIP Service [VCSA INFO] nfc.vmGetFile: {"type":"result","statusCode":"PROCESS_STATUS","sessionId":"MaKj-iWqJ-ETkG-R1iV","requestId":"6989","requestComponentId":"fileTransfer","requestObjectId":"bQmp-2Eez-tVZg-LA5k","result":"","isFinal":"true"}

2017-07-31 14:22:08.450151 CIP Service [VCSA INFO] nfc.vmGetFile: {"type":"result","statusCode":"PROCESS_STATUS","sessionId":"MaKj-iWqJ-ETkG-R1iV","requestId":"6995","requestComponentId":"fileTransfer","requestObjectId":"3tpd-85CB-4qCR-KEaD","result":"","isFinal":"false","item":["{\"error\":\"vim.fault.FileNotFound\"}"]}

2017-07-31 14:22:09.279263 CIP Service [VCSA INFO] nfc.vmGetFile: {"type":"result","statusCode":"PROCESS_STATUS","sessionId":"MaKj-iWqJ-ETkG-R1iV","requestId":"6995","requestComponentId":"fileTransfer","requestObjectId":"3tpd-85CB-4qCR-KEaD","result":"","isFinal":"true"}

2017-07-31 14:22:13.487460 CIP Service [VCSA INFO] nfc.vmGetFile: {"type":"result","statusCode":"PROCESS_STATUS","sessionId":"MaKj-iWqJ-ETkG-R1iV","requestId":"6999","requestComponentId":"fileTransfer","requestObjectId":"ThzM-hRKB-a27b-Q6qy","result":"","isFinal":"false","item":["{\"error\":\"vim.fault.FileNotFound\"}"]}

2017-07-31 14:22:14.301124 CIP Service [VCSA INFO] nfc.vmGetFile: {"type":"result","statusCode":"PROCESS_STATUS","sessionId":"MaKj-iWqJ-ETkG-R1iV","requestId":"6999","requestComponentId":"fileTransfer","requestObjectId":"ThzM-hRKB-a27b-Q6qy","result":"","isFinal":"true"}

This is really annoying as this was my second attempt to run this upgrade and it still is unsuccessful.

I have restarted everything, made sure all IP and FQDN information are okay (even if this is not a clean solution, it is a solution!), I can see that the migration wizards powers on the new VCSA (called VCSA6) but doesn't transfer data or shuts down the old VCSA.

Is there anyone who also had this problem before? Or even if someone who got pass this without problems who can tell me what he did different?

Thanks a lot in advance and best regards

NC

[NelsonCandela · Accepted solution]

I noticed during my fourth try that during the startup of the VCSA6 appliance an odd line was shown.

It said:

2017-08-01T12:49:23.901Z ERROR root Could not create command factory.

2017-08-01T12:49:23.902Z ERROR __main__ ERROR: Fatal error during upgrade REQUIREMENTS. For more details take a look at: /var/log/vmware/upgrade/requirements-upgrade-runner.log

I then took a look and now I know: DNS factually was the problem!

It's all good if you use the FQDN replacement within the hosts file locally, but during the process of going through the wizard all the information given are being passed on to the NEW appliance - but host file entries aren't. So when the new appliance is being deployed it is not able to resolve hostnames and thus will fail to proceed.

Long story short:

Old appliance knew what the server alias was.

New appliance didn't know what the server alias was.

Eventually I changed the FQDN in the wizard to IP addresses instead and all went well after all.

F***.