Getting Errors like ‘Quota Update Failed’ and ‘Out of Sync’ while trying to perform all the Operations for Plans on Azure Site using SCVMM
Symptoms
This is one of the other very Interesting VMM cases I worked on recently . The issue was that we were not able to perform any operations from the Azure Admin Portal including deleting users, deleting subscription for a user and we were getting Errors like 'Plan Out Of sync' and ‘Quota update failed ‘. And infact when we tried to delete one of the subscriptions, it said the “There is no Subscription associated with the Tenant’'
Troubleshooting
As there are multiple components involved in the case of Private Clouds like Azure Pack, SPF (Service Provider Foundation) and VMM, the first thing we needed to make sure is that we have latest versions of all these three components installed. Azure Pack should have UR 5 installed, VMM should also have UR 5 installed for VMM Console and Server, and SPF should have UR 4 installed (these versions are as per the current availability, it will keep changing in the future as and when new versions are released for these components).
SO, we confirmed that all the three components were on the latest versions.
Then we decided to collect Logs while trying to reproduce the issue. And the logs which we required were as follows:
1) VMM Tracing
2) SPF Tracing
3) IIS logs from SPF machine
4) FREP logs from SPF machine
We used the following Batch Files to collect these logs rather than using the usual method of manually collecting the Traces as per the Articles below:
Debug Tracing for SPF:
https://support.microsoft.com/kb/2850280
Debug Tracing for VMM(Virtual Machine Manager):
https://support.microsoft.com/en-us/kb/2913445
Edit batch files to fit you storage locations:
SPF Tracing:
@Echo OFF
@Echo ***** Delete and old SFP trace settings*****
logman delete spfdebugtrace
@Echo ***** Create SPF trace *****
logman create trace spfdebugtrace -o %SYSTEMDRIVE%SPFlogsSFPLog_%COMPUTERNAME%.ETL -p Microsoft-ServiceProviderFoundation 0xc000000000000000 0x5
@Echo ***** Update SPF trace with PowerShell *****
logman update spfdebugtrace -p Microsoft-Windows-PowerShell 0xf0010000000003ff 0x5
@Echo ***** Update SPF trace with ActivityEventSource *****
logman update spfdebugtrace -p ActivityEventSource 0x0 0xff
@Echo ***** Start SPFtrace *****
logman start spfdebugtrace
@Echo ***** --- Repro issue --- *****
@Echo ***** --- Press a key to stop --- *****
pause
@Echo ***** Stopping SPFtrace *****
logman stop spfdebugtrace
@Echo ***** Delete SFP trace settings**********
logman delete spfdebugtrace
VMM tracing:
@Echo OFF
@Echo ***** Delete and old VMM trace files *****
logman delete VMM
@Echo ***** Create VMM trace *****
logman create trace VMM -v mmddhhmm -o %SYSTEMDRIVE%VMMlogsVMMLog_%COMPUTERNAME%.ETL -cnf 01:00:00 -p Microsoft-VirtualMachineManager-Debug -nb 10 250 -bs 16 -max 512
@Echo ***** Start VMM trace *****
logman start vmm
@Echo ***** --- Repro issue --- *****
@Echo ***** --- Press a key to stop --- *****
pause
@Echo ***** Stopping VMM trace *****
logman stop vmm
We converted the SPF & VMM traces using NETSH on the machines. E.g.
netsh trace convert SFPLog_ SPF01_000001.etl
Then I looked at the SPF Tracing logs and see the Errors below:
1 [0]0D2C.0754::2015-03-27 15:09:21.026 []***
2 [0]0D2C.0754::2015-03-27 15:09:21.042 [ActivityEventSource]Started activity [HttpRequestActivity, id {8ab952bd-c43f-4ded-b173-50d4055f9341}] parent activity [WebAuthentication Call, id {4659b10b-cf3a-4bcc-9769-f6e1b8663fe5}] Elapsed: 0ms Context: {c477a2fb-8864-4d89-96c7-24bdccee5b94} Properties: RequestUrl=[https://wapserver.contoso.local:8090/provider/subscriptions] & x-ms-client-request-id=[e8dbc04c-5381-40ba-8909-69b83a4f3f13] & x-ms-client-session-id=[99459df3-bb71-4f30-9315-1b0c6c916a58]
3 [0]0D2C.0754::2015-03-27 15:09:21.058 [ActivityEventSource]Successfully completed activity [HttpRequestActivity, id {8ab952bd-c43f-4ded-b173-50d4055f9341}] parent activity [WebAuthentication Call, id {4659b10b-cf3a-4bcc-9769-f6e1b8663fe5}] Elapsed: 0ms Context: {c477a2fb-8864-4d89-96c7-24bdccee5b94} Duration: 124ms Properties: OriginalPath=[/provider/subscriptions] & RequestUrl=[https://wapserver.contoso.local:8090/provider/subscriptions] & SubscriptionId=[] & x-ms-client-request-id=[e8dbc04c-5381-40ba-8909-69b83a4f3f13] & x-ms-client-session-id=[99459df3-bb71-4f30-9315-1b0c6c916a58]
4 [1]0D2C.0754::2015-03-27 15:09:24.406 [Microsoft-ServiceProviderFoundation]Component: Provider Activity [WebAuthentication Call, id {4659b10b-cf3a-4bcc-9769-f6e1b8663fe5}] Parent activity [none, id {00000000-0000-0000-0000-000000000000}] Elapsed: 0ms Context: {c477a2fb-8864-4d89-96c7-24bdccee5b94} Creating Tenant and linking to stamp TenantName: user.name@contoso.com_a7c63b17-c0fb-48bf-bdc4-5f7db1c2610b
5 [0]0D2C.0754::2015-03-27 15:09:24.484 [Microsoft-ServiceProviderFoundation]Component: Provider Activity [WebAuthentication Call, id {4659b10b-cf3a-4bcc-9769-f6e1b8663fe5}] Parent activity [none, id {00000000-0000-0000-0000-000000000000}] Elapsed: 0ms Context: {c477a2fb-8864-4d89-96c7-24bdccee5b94 } Failed to delete subscription. Reason: Message : The underlying connection was closed: An unexpected error occurred on a send., InnerMessage: Unable to read data from the transport connection: An existing connection was forcibly closed by the remote host.
6 [0]0D2C.0754::2015-03-27 15:09:24.489 [Microsoft-ServiceProviderFoundation]Component: Provider Activity [WebAuthentication Call, id {4659b10b-cf3a-4bcc-9769-f6e1b8663fe5}] Parent activity [none, id {00000000-0000-0000-0000-000000000000}] Elapsed: 0ms Context: {c477a2fb-8864-4d89-96c7-24bdccee5b94} at System.Net.HttpWebRequest.GetResponse() at System.Data.Services.Client.WebUtil.GetResponseHelper(ODataRequestMessageWrapper request, DataServiceContext context, IAsyncResult asyncResult, Boolean handleWebException) at System.Data.Services.Client.QueryResult.ExecuteQuery(DataServiceContext context) at System.Data.Services.Client.DataServiceRequest.Execute[TElement](DataServiceContext context, QueryComponents queryComponents) at System.Data.Services.Client.DataServiceQuery`1.Execute() at System.Data.Services.Client.DataServiceQuery`1.GetEnumerator() at System.Linq.Enumerable.FirstOrDefault[TSource](IEnumerable`1 source) at System.Data.Services.Client.DataServiceQueryProvider.ReturnSingleton[TElement](Expression expression) at System.Linq.Queryable.FirstOrDefault[TSource](IQueryable`1 source) at Microsoft.SystemCenter.Foundation.Provider.SubscriptionResourceProvider.DeleteSubscription(String id)
7 [0]0D2C.0754::2015-03-27 15:09:24.490 [Microsoft-ServiceProviderFoundation]Component: Provider Activity [WebAuthentication Call, id {4659b10b-cf3a-4bcc-9769-f6e1b8663fe5}] Parent activity [none, id {00000000-0000-0000-0000-000000000000}] Elapsed: 0ms Context: {c477a2fb-8864-4d89-96c7-24bdccee5b94} The underlying connection was closed: An unexpected error occurred on a send.
8 [0]0D2C.0754::2015-03-27 15:09:24.491 [Microsoft-ServiceProviderFoundation]Component: Provider Activity [WebAuthentication Call, id {4659b10b-cf3a-4bcc-9769-f6e1b8663fe5}] Parent activity [none, id {00000000-0000-0000-0000-000000000000}] Elapsed: 0ms Context: {c477a2fb-8864-4d89-96c7-24bdccee5b94 } Message : The underlying connection was closed: An unexpected error occurred on a send., InnerMessage: Unable to read data from the transport connection: An existing connection was forcibly closed by the remote host.
The main error is below:
Failed to delete subscription. Reason: Message : The underlying connection was closed: An unexpected error occurred on a send., InnerMessage: Unable to read data from the transport connection: An existing connection was forcibly closed by the remote host.
I Researched more on the above Error and came to know that it could occur if the SubscriptionID=[] which means if it is Blank then we can hit an issue.
So now we had to check the Bindings of IIS on SPF and make sure there are no Duplicate Bindings for the same Port and if they are there then we will have to delete the Binding for a specific IP and leave the one with All IPs with the Self Signed Certificate.
We Checked the IIS Bindings on the SPF machine and found out that there were Two Bindings there for HTTPS Port 8090 and the second Binding did not have any IP address bound to it as shown below:
So we removed that Binding from there and after that we were able to perform all the Operations fine from the Azure site.
Author:
Nitin Singh
Support Escalation Engineer
Microsoft Security and Manageability Division