Contributor
Contributor

unmap timeout?

Hi All,

I've been trying to script an unmap of our datastores using powercli.

This lead me to this fantastic post and script/s,

ESXcli 5.5 UNMAP and PowerCLI script?

Like others in this discussion I continue to have a problem with the unmap command timing out on the powercli window. It just hangs and seems to be waiting for a response from the esxcli unmap command, however from the ESXi host I can tell that the command has completed.

I added the following command to the script without any changes.

Set-PowerCLIConfiguration -Scope Session -WebOperationTimeoutSeconds -1

The previous workaround which seems to have worked was to change the unit count (number of blocks per call of unmap) to a much higher number. In the script it is 0.5% of the free space. This results in a much quicker execution and is below the timeout, so everything works.

However ESXi has changed the way it allows unmaps with high unit counts, so that its no longer possible to change the unit count if the datastore free space is less than 25%. It reverts to the default of 200 and results in a timeout in powercli.

https://drewtonnesen.wordpress.com/2015/07/26/unmap-in-esxi-5-5-p3/

I've tried to log an SR (15832009712) but GSS doesn't support PowerCLI. I was referred to VMware SDK and API Support | United States however we don't have API/SDK support (just the normal production GSS support).

My Current Situation

- PowerCLI waits definitely for a response from the unmap command if the default unit size is used on a large datastore.

- If <75% and unit size changed, it works.

- If datastore is quite small with 200 unit size ~1TB, it works.

I don't know if this is PowerCLI timeout, vCenter or even ESXi. All i know at present is that the powercli window says its executing the script and seems like its waiting for a response from the unmap command.

A previous post when using a different script (had same issue but the issue wasn't understood at the time) resulted in only 1 reply saying they had the same issue.

unmap - only unmaps first datastore

I've looked into running the command async and then a sleep, as a job, but I don't know powershell enough to pull off an advanced topic such as that.

If anyone has a working version of an unmap script, I would appreciate to understand how you got around this issue.

0 Kudos
7 Replies

Hi ChrisNewell‌,

I can reproduce that isse with very large Datastores.

It looks like a vCenter related Timeout:

2016-02-0114:45:25.945

2016-02-01T13:45:25.933Z XXXXXXXXXXXXXXXXXX Vpxa: [2BB03B70 error 'vpxavpxaVmomi' opID=68b5f1b8-3f] [VpxaClientAdapter::InvokeCommon] Got exception while invoking executeSoap on vmodl.reflect.ManagedMethodExecuter:ha-managed-method-executer: 'Operation timed out', backtrace:

2016-02-0114:45:25.945

--> backtrace[00] rip 1d XXXXXXXXXXXXXXXXXX Vpxa: c01b3 Vmacore::System::Stacktrace::CaptureWork(unsigned int)

2016-02-0114:45:25.945

--> backtrace[01] rip 1d XXXXXXXXXXXXXXXXXX Vpxa: 18abb Vmacore::System::SystemFactoryImpl::CreateQuickBacktrace(Vmacore::Ref<Vmacore::System::Backtrace>&)

2016-02-0114:45:25.945

--> backtrace[02] rip 1d XXXXXXXXXXXXXXXXXX Vpxa: b9eb5 Vmacore::Throwable::Throwable(std::string const&)

2016-02-0114:45:25.945

--> backtrace[03] rip 1d XXXXXXXXXXXXXXXXXX Vpxa: 610f5 Vmacore::Http::UserAgentImpl::AsyncSendRequestHelper::WaitForResponse(long long, Vmacore::Ref<Vmacore::Http::ClientResponse>&)

2016-02-0114:45:25.946

--> backtrace[04] rip 1d XXXXXXXXXXXXXXXXXX Vpxa: 61636 Vmacore::Http::UserAgentImpl::TimedWaitSendRequest(Vmacore::Http::PendingRequestItem*, long long, Vmacore::Ref<Vmacore::Http::ClientResponse>&)

2016-02-0114:45:25.946

--> backtrace[05] rip 1d XXXXXXXXXXXXXXXXXX Vpxa: ec76c Vmomi::SoapStubAdapterImpl::InvokeCommon(Vmomi::MoRef*, Vmomi::ManagedMethod*, Vmacore::RefVector<Vmomi::Any> const&, Vmomi::RequestContext*, bool, Vmacore::Ref<Vmomi::Any>&)

2016-02-0114:45:25.946

--> backtrace[06] rip 1d XXXXXXXXXXXXXXXXXX Vpxa: ecd78 Vmomi::SoapStubAdapterImpl::Invoke_Task(Vmomi::MoRef*, Vmomi::ManagedMethod*, Vmacore::RefVector<Vmomi::Any>&, Vmomi::RequestContext*, Vmacore::Ref<Vmomi::Any>&)

2016-02-0114:45:25.946

--> backtrace[07] rip 1c XXXXXXXXXXXXXXXXXX Vpxa: d3234 /usr/lib/vmware/vpxa/bin/vpxa(+0x245234) [0x1ccd3234]

2016-02-0114:45:25.946

--> backtrace[08] rip 1c XXXXXXXXXXXXXXXXXX Vpxa: d35a8 /usr/lib/vmware/vpxa/bin/vpxa(+0x2455a8) [0x1ccd35a8]

2016-02-0114:45:25.946

--> backtrace[09] rip 1d XXXXXXXXXXXXXXXXXX Vpxa: 19764 Vmomi::StubImpl::_Invoke_Task(Vmomi::ManagedMethod*, Vmacore::RefVector<Vmomi::Any>&, Vmacore::Ref<Vmomi::Any>&)

2016-02-0114:45:25.947

--> backtrace[10] rip 1d XXXXXXXXXXXXXXXXXX Vpxa: 0e4e2 Vmomi::Reflect::ManagedMethodExecuterStub::ExecuteSoap(std::string const&, std::string const&, std::string const&, Vmomi::DataArray<Vmomi::Reflect::ManagedMethodExecuter::SoapArgument>*, Vmacore::Ref<Vmomi::Reflect::ManagedMethodExecuter::SoapResult>&)

2016-02-0114:45:25.947

--> backtrace[11] rip 1d XXXXXXXXXXXXXXXXXX Vpxa: 10a54 /lib/libvmomi.so(+0x2c2a54) [0x1df10a54]

2016-02-0114:45:25.947

--> backtrace[12] rip 1d XXXXXXXXXXXXXXXXXX Vpxa: c72c7 Vmomi::ManagedMethodImpl::Dispatch(Vmomi::ManagedObject*, Vmacore::RefVector<Vmomi::Any>&, Vmacore::Ref<Vmomi::Any>&)

2016-02-0114:45:25.947

--> backtrace[13] rip 1d XXXXXXXXXXXXXXXXXX Vpxa: c8312 Vmomi::ManagedMethodImpl::Invoke(Vmomi::ManagedObject*, Vmacore::RefVector<Vmomi::Any>&, Vmacore::Ref<Vmomi::Any>&)

2016-02-0114:45:25.948

--> backtrace[14] rip 1c XXXXXXXXXXXXXXXXXX Vpxa: 6961a /usr/lib/vmware/vpxa/bin/vpxa(+0x3db61a) [0x1ce6961a]

2016-02-0114:45:25.948

--> backtrace[15] rip 1c XXXXXXXXXXXXXXXXXX Vpxa: 0eabb /usr/lib/vmware/vpxa/bin/vpxa(+0x480abb) [0x1cf0eabb]

2016-02-0114:45:25.948

--> backtrace[16] rip 1c XXXXXXXXXXXXXXXXXX Vpxa: d2052 /usr/lib/vmware/vpxa/bin/vpxa(+0x244052) [0x1ccd2052]

2016-02-0114:45:25.948

--> backtrace[17] rip 1c XXXXXXXXXXXXXXXXXX Vpxa: ed49d VpxLRO::PreAndBodyStartWork(VpxLRO*)

2016-02-0114:45:25.948

--> backtrace[18] rip 1c XXXXXXXXXXXXXXXXXX Vpxa: e0d51 /usr/lib/vmware/vpxa/bin/vpxa(+0x452d51) [0x1cee0d51]

2016-02-0114:45:25.948

--> backtrace[19] rip 1c XXXXXXXXXXXXXXXXXX Vpxa: ea4d5 /usr/lib/vmware/vpxa/bin/vpxa(+0x45c4d5) [0x1ceea4d5]

2016-02-0114:45:25.948

--> backtrace[20] rip 1c XXXXXXXXXXXXXXXXXX Vpxa: ef732 VpxLRO::LroMainEntry(VpxLRO*)

2016-02-0114:45:25.948

--> backtrace[21] rip 1c XXXXXXXXXXXXXXXXXX Vpxa: e0fb1 /usr/lib/vmware/vpxa/bin/vpxa(+0x452fb1) [0x1cee0fb1]

2016-02-0114:45:25.948

--> backtrace[22] rip 1c XXXXXXXXXXXXXXXXXX Vpxa: ea3d8 /usr/lib/vmware/vpxa/bin/vpxa(+0x45c3d8) [0x1ceea3d8]

2016-02-0114:45:25.949

--> backtrace[23] rip 1c XXXXXXXXXXXXXXXXXX Vpxa: 00d02 VpxLroList::ThreadMainEntry()

2016-02-0114:45:25.949

--> backtrace[24] rip 1c XXXXXXXXXXXXXXXXXX Vpxa: 9fa4b boost::detail::function::void_function_invoker0<void (*)(), void>::invoke(boost::detail::function::function_buffer&)

2016-02-0114:45:25.949

--> backtrace[25] rip 1d XXXXXXXXXXXXXXXXXX Vpxa: 2176a Vmacore::System::ThreadPoolAsio::DoWork(Vmacore::Functor<void, Vmacore::Nil, Vmacore::Nil, Vmacore::Nil, Vmacore::Nil, Vmacore::Nil, Vmacore::Nil, Vmacore::Nil> const&, bool)

2016-02-0114:45:25.949

--> backtrace[26] rip 1d XXXXXXXXXXXXXXXXXX Vpxa: 21fa8 Vmacore::System::ThreadPoolAsio::DoOrEnqueueWork(Vmacore::System::ThreadPoolAsio::WorkTypeInfo&, Vmacore::Functor<void, Vmacore::Nil, Vmacore::Nil, Vmacore::Nil, Vmacore::Nil, Vmacore::Nil, Vmacore::Nil, Vmacore::Nil> const&, int)

2016-02-0114:45:25.949

--> backtrace[27] rip 1d XXXXXXXXXXXXXXXXXX Vpxa: 22210 Vmacore::System::ThreadPoolAsio::HandleWork(Vmacore::System::ThreadPoolAsio::WorkType, Vmacore::Functor<void, Vmacore::Nil, Vmacore::Nil, Vmacore::Nil, Vmacore::Nil, Vmacore::Nil, Vmacore::Nil, Vmacore::Nil> const&)

2016-02-0114:45:25.949

--> backtrace[28] rip 1d XXXXXXXXXXXXXXXXXX Vpxa: 2a4c1 Vmacore::System::ThreadPoolAsioWorkBinder::InvokeWork_0(Vmacore::System::ThreadPoolAsio::WorkType, boost::function<void ()> const&)

2016-02-0114:45:25.949

--> backtrace[29] rip 1d XXXXXXXXXXXXXXXXXX Vpxa: 25f1a boost::detail::function::void_function_obj_invoker0<boost::_bi::bind_t<void, void (*)(Vmacore::System::ThreadPoolAsio::WorkType, boost::function<void ()> const&), boost::_bi::list2<boost::_bi::value<Vmacore::System::ThreadPoolAsio::WorkType>, boost::_bi::value<boost::function<void ()> > > >, void>::invoke(boost::detail::function::function_buffer&)

2016-02-0114:45:25.949

--> backtrace[30] rip 1d XXXXXXXXXXXXXXXXXX Vpxa: 2bf9c boost::asio::detail::completion_handler<boost::function<void ()> >::do_complete(boost::asio::detail::task_io_service*, boost::asio::detail::task_io_service_operation*, boost::system::error_code, unsigned int)

2016-02-0114:45:25.950

--> backtrace[31] rip 1d XXXXXXXXXXXXXXXXXX Vpxa: 292ae boost::asio::detail::task_io_service::do_one(boost::asio::detail::scoped_lock<boost::asio::detail::posix_mutex>&, boost::asio::detail::task_io_service::idle_thread_info*)

2016-02-0114:45:25.950

--> backtrace[32] rip 1d XXXXXXXXXXXXXXXXXX Vpxa: 20eac Vmacore::System::ThreadPoolAsio::RunWorkerThread()

2016-02-0114:45:25.950

--> backtrace[33] rip 1d XXXXXXXXXXXXXXXXXX Vpxa: 25f73 boost::detail::function::void_function_obj_invoker0<boost::_bi::bind_t<void, boost::_mfi::mf0<void, Vmacore::System::ThreadPoolAsio>, boost::_bi::list1<boost::_bi::value<Vmacore::Ref<Vmacore::System::ThreadPoolAsio> > > >, void>::invoke(boost::detail::function::function_buffer&)

2016-02-0114:45:25.950

--> backtrace[34] rip 1d XXXXXXXXXXXXXXXXXX Vpxa: c9d34 Vmacore::System::ThreadPosixPrivate::ThreadBegin(void*)

2016-02-0114:45:25.950

--> backtrace[35] rip 1d XXXXXXXXXXXXXXXXXX Vpxa: 4ed6a /lib/libpthread.so.0(+0x6d6a) [0x1d44ed6a]

2016-02-0114:45:25.950

--> backtrace[36] rip 1e XXXXXXXXXXXXXXXXXX Vpxa: 1de4e /lib/libc.so.6(clone+0x5e) [0x1ed1de4e]

Can you also see these logs on the ESXi Host?

Kind Regards,

Markus

https://mycloudrevolution.com | https://twitter.com/vMarkus_K | https://github.com/vMarkusK
0 Kudos
Contributor
Contributor

Hi vMarkusK,

Thanks for your investigation. Seems like you are onto something.

Another user supplied a similar log result as yours for the same issue.

http://serverfault.com/questions/608494/esxcli-command-timeout-at-30-minutes

I won't be able to test this again until tonight. But I'll update this discussion once I have the results.

0 Kudos
Contributor
Contributor

Hi vMarkusK,

I've completed the unmap twice and went through the vpxa (and hostd) logs on the ESXi server. Sadly I can't find any backtrace for a timeout.

The time out which i'm getting seems to be shorter than most being reported. The script seems to hand if the unmap takes longer than 10minutues to complete.

Given that you have been able to reproduce the issue there is always the chance that i'm checking the wrong log files. I've included the hostd and vpxa files which shows when the unmap started and completed on that host.

The unmap started at 23:31 and finished at 23:43 (log time), 10:31 and 10:43 Local Time.

0 Kudos

Hi,

I will check yout logs later.

I reproduced it again with Timer:

esxcli_Timout.png

Every time after 30m is connection lost...

I tried to open a VMware Case.

Kind Regards,

Markus

https://mycloudrevolution.com | https://twitter.com/vMarkus_K | https://github.com/vMarkusK
0 Kudos

Hi again,

I'm not sure that we have similar issues.

I can see in your LOG:


Unmap: Done : Total Unmapped blocks from volume 5518c96e-3606c86d-6dab-40f2e9c2ba18 : 1107762

2016-02-02T23:43:44.683Z [3FC40B70 info 'Solo.VmwareCLI' opID=hostd-d57c user=vpxuser] Dispatch unmap done

At time you said.

Can you post your PowerCLI Session output?


Kind Regards,

Markus

https://mycloudrevolution.com | https://twitter.com/vMarkus_K | https://github.com/vMarkusK
0 Kudos

After a long running support case VMware offered me that the maximum WebOperationTimeout of 30 minutes is hardcoded...

https://mycloudrevolution.com | https://twitter.com/vMarkus_K | https://github.com/vMarkusK
0 Kudos
Enthusiast
Enthusiast

Hi, 

I have managed to solve this timout for vsphere 6.0 using: 

Set-PowerCLIConfiguration -WebOperationTimeoutSeconds -1

In 5.5 env I am still getting timout: 

2020-11-26T16:13:17.451Z [74A80B70 verbose 'SoapAdapter'] Responded to service state request
2020-11-26T16:13:19.486Z [730CBB70 verbose 'SoapAdapter'] Responded to service state request
2020-11-26T16:13:24.017Z [72DC1B70 verbose 'SoapAdapter'] Unrecognized version URI "urn:vim25/s55741"; using default handler for "urn:vim25/5.5"
2020-11-26T16:13:36.002Z [FFA8DB70 info 'Solo.Vmomi' opID=hostd-c712 user=root] Activation [N5Vmomi10ActivationE:0x70f1e428] : Invoke done [waitForUpdatesEx] on [vmodl.query.PropertyCollector:ha-property-collector]
2020-11-26T16:13:36.002Z [FFA8DB70 verbose 'Solo.Vmomi' opID=hostd-c712 user=root] Arg version:
--> "98147"
2020-11-26T16:13:36.002Z [FFA8DB70 verbose 'Solo.Vmomi' opID=hostd-c712 user=root] Arg options:
--> (vmodl.query.PropertyCollector.WaitOptions) {
--> dynamicType = <unset>,
--> maxWaitSeconds = 600,
--> maxObjectUpdates = 100,
--> }
2020-11-26T16:13:36.002Z [FFA8DB70 info 'Solo.Vmomi' opID=hostd-c712 user=root] Throw vmodl.fault.RequestCanceled
2020-11-26T16:13:36.002Z [FFA8DB70 info 'Solo.Vmomi' opID=hostd-c712 user=root] Result:
--> (vmodl.fault.RequestCanceled) {
--> dynamicType = <unset>,
--> faultCause = (vmodl.MethodFault) null,
--> msg = "",
--> }

Is "WebOperationTimeout of 30" really hardcoded for Vsphere 5.5 ?

 

 

 

0 Kudos