Invoke-AzOperationalInsightsQuery: `-Wait` parameter is not respected when the supplied argument is larger than 100 #16553

dingliu · 2021-12-01T14:39:39Z

Description

-Wait can be used to specify an upper bound on the amount of time the server will spend processing the query, as number of seconds. The details are documented here and here.

However, when the supplied argument is larger than 100 and the query execution time is also longer than 100s, Invoke-AzOperationalInsightsQuery fails with error:

The request was canceled due to the configured HttpClient.Timeout of 100 seconds elapsing.

Issue script & Debug output

PS C:\> $kqlResult = Invoke-AzOperationalInsightsQuery -Workspace $omsWs -Query $kustoQueryString -Wait 180 -DefaultProfile $azCtx -Debug

DEBUG: 9:22:24 AM - InvokeOperationalInsightsQuery begin processing with ParameterSet 'ByWorkspaceObject'.
DEBUG: 9:22:24 AM - using account id '<USER_ACCOUNT_UPN>'...
DEBUG: [Common.Authentication]: Authenticating using Account: '<USER_ACCOUNT_UPN>', environment: 'AzureCloud', tenant: '<AAD_TENANT_ID>'
DEBUG: 9:22:24 AM - [SilentAuthenticator] Calling SharedTokenCacheCredential.GetTokenAsync - TenantId:'<AAD_TENANT_ID>', Scopes:'https://api.loganalytics.io/.default', AuthorityHost:'https://login.microsoftonline.com/', UserId:'<USER_ACCOUNT_UPN>' 
DEBUG: SharedTokenCacheCredential.GetToken invoked. Scopes: [ https://api.loganalytics.io/.default ] ParentRequestId: 
DEBUG: (False) MSAL 4.30.1.0 MSAL.NetCore Microsoft Windows 10.0.18363 [12/01/2021 14:22:24 - ] Azure region was not configured or could not be discovered. Not using a regional authority.
DEBUG: (False) MSAL 4.30.1.0 MSAL.NetCore Microsoft Windows 10.0.18363 [12/01/2021 14:22:24] Found 2 cache accounts and 0 broker accounts
DEBUG: (False) MSAL 4.30.1.0 MSAL.NetCore Microsoft Windows 10.0.18363 [12/01/2021 14:22:24] Returning 2 accounts
DEBUG: (False) MSAL 4.30.1.0 MSAL.NetCore Microsoft Windows 10.0.18363 [12/01/2021 14:22:24 - ] MSAL MSAL.NetCore with assembly version '4.30.1.0'. CorrelationId(<CORRELATION_ID>)
DEBUG: (False) MSAL 4.30.1.0 MSAL.NetCore Microsoft Windows 10.0.18363 [12/01/2021 14:22:24 - ] === AcquireTokenSilent Parameters ===
DEBUG: (False) MSAL 4.30.1.0 MSAL.NetCore Microsoft Windows 10.0.18363 [12/01/2021 14:22:24 - ] LoginHint provided: False
DEBUG: (False) MSAL 4.30.1.0 MSAL.NetCore Microsoft Windows 10.0.18363 [12/01/2021 14:22:24 - ] Account provided: True
DEBUG: (False) MSAL 4.30.1.0 MSAL.NetCore Microsoft Windows 10.0.18363 [12/01/2021 14:22:24 - ] ForceRefresh: False
DEBUG: (False) MSAL 4.30.1.0 MSAL.NetCore Microsoft Windows 10.0.18363 [12/01/2021 14:22:24 - ] 
=== Request Data ===
Authority Provided? - True
Scopes - https://api.loganalytics.io/.default
Extra Query Params Keys (space separated) - 
ApiId - AcquireTokenSilent
IsConfidentialClient - False
SendX5C - False
LoginHint ? False
IsBrokerConfigured - False
HomeAccountId - False
CorrelationId - <CORRELATION_ID>

DEBUG: (False) MSAL 4.30.1.0 MSAL.NetCore Microsoft Windows 10.0.18363 [12/01/2021 14:22:24 - ] === Token Acquisition (SilentRequest) started:

        Authority Host: login.microsoftonline.com
DEBUG: (False) MSAL 4.30.1.0 MSAL.NetCore Microsoft Windows 10.0.18363 [12/01/2021 14:22:24 - ] Azure region was not configured or could not be discovered. Not using a regional authority.
DEBUG: (False) MSAL 4.30.1.0 MSAL.NetCore Microsoft Windows 10.0.18363 [12/01/2021 14:22:24 - ] Access token has expired or about to expire. [Current time (12/01/2021 14:22:24) - Expiration Time (11/30/2021 22:21:08 +00:00) - Extended Expiration Time (11/30/2021 22:21:08 +00:00)]
DEBUG: (False) MSAL 4.30.1.0 MSAL.NetCore Microsoft Windows 10.0.18363 [12/01/2021 14:22:24 - ] Azure region was not configured or could not be discovered. Not using a regional authority.
DEBUG: (False) MSAL 4.30.1.0 MSAL.NetCore Microsoft Windows 10.0.18363 [12/01/2021 14:22:24 - ] Azure region was not configured or could not be discovered. Not using a regional authority.
DEBUG: (False) MSAL 4.30.1.0 MSAL.NetCore Microsoft Windows 10.0.18363 [12/01/2021 14:22:24 - ] Refresh token found in the cache? - True
DEBUG: (False) MSAL 4.30.1.0 MSAL.NetCore Microsoft Windows 10.0.18363 [12/01/2021 14:22:24 - ] Azure region was not configured or could not be discovered. Not using a regional authority.
DEBUG: (False) MSAL 4.30.1.0 MSAL.NetCore Microsoft Windows 10.0.18363 [12/01/2021 14:22:24 - ] Resolving authority endpoints... Already resolved? - TRUE
DEBUG: Request [<CLIENT_REQUEST_ID>] POST https://login.microsoftonline.com/<AAD_TENANT_ID>/oauth2/v2.0/token
x-client-SKU:REDACTED
x-client-Ver:REDACTED
x-client-CPU:REDACTED
x-client-OS:REDACTED
x-client-current-telemetry:REDACTED
x-client-last-telemetry:REDACTED
x-ms-lib-capability:REDACTED
client-request-id:REDACTED
return-client-request-id:REDACTED
x-app-name:REDACTED
x-app-ver:REDACTED
x-ms-client-request-id:<CLIENT_REQUEST_ID>
x-ms-return-client-request-id:true
User-Agent:azsdk-net-Identity/1.4.0,(.NET 6.0.0-rtm.21522.10; Microsoft Windows 10.0.18363)
Content-Type:application/x-www-form-urlencoded
client assembly: Azure.Identity
DEBUG: Response [<CLIENT_REQUEST_ID>] 200 OK (00.5s)
Cache-Control:no-store, no-cache
Pragma:no-cache
Strict-Transport-Security:REDACTED
X-Content-Type-Options:REDACTED
P3P:REDACTED
client-request-id:REDACTED
x-ms-request-id:<X_MS_REQUEST_ID>
x-ms-ests-server:REDACTED
x-ms-clitelem:REDACTED
Set-Cookie:REDACTED
Date:Wed, 01 Dec 2021 14:22:23 GMT
Content-Type:application/json; charset=utf-8
Expires:-1
Content-Length:5424

DEBUG: (False) MSAL 4.30.1.0 MSAL.NetCore Microsoft Windows 10.0.18363 [12/01/2021 14:22:24 - ] Checking client info returned from the server..
DEBUG: (False) MSAL 4.30.1.0 MSAL.NetCore Microsoft Windows 10.0.18363 [12/01/2021 14:22:24 - ] Saving Token Response to cache..
DEBUG: (False) MSAL 4.30.1.0 MSAL.NetCore Microsoft Windows 10.0.18363 [12/01/2021 14:22:24 - ] Subject not present in Id token
DEBUG: (False) MSAL 4.30.1.0 MSAL.NetCore Microsoft Windows 10.0.18363 [12/01/2021 14:22:24 - ] Azure region was not configured or could not be discovered. Not using a regional authority.
DEBUG: (False) MSAL 4.30.1.0 MSAL.NetCore Microsoft Windows 10.0.18363 [12/01/2021 14:22:24 - ] Saving AT in cache and removing overlapping ATs...
DEBUG: (False) MSAL 4.30.1.0 MSAL.NetCore Microsoft Windows 10.0.18363 [12/01/2021 14:22:24 - ] Looking for scopes for the authority in the cache which intersect with https://api.loganalytics.io/.default
DEBUG: (False) MSAL 4.30.1.0 MSAL.NetCore Microsoft Windows 10.0.18363 [12/01/2021 14:22:24 - ] Intersecting scope entries count - 1
DEBUG: (False) MSAL 4.30.1.0 MSAL.NetCore Microsoft Windows 10.0.18363 [12/01/2021 14:22:24 - ] Matching entries after filtering by user - 1
DEBUG: (False) MSAL 4.30.1.0 MSAL.NetCore Microsoft Windows 10.0.18363 [12/01/2021 14:22:24 - ] Saving Id Token and Account in cache ...
DEBUG: (False) MSAL 4.30.1.0 MSAL.NetCore Microsoft Windows 10.0.18363 [12/01/2021 14:22:24 - ] Saving RT in cache...
DEBUG: (False) MSAL 4.30.1.0 MSAL.NetCore Microsoft Windows 10.0.18363 [12/01/2021 14:22:24] Not writing FRT in ADAL legacy cache. 
DEBUG: (False) MSAL 4.30.1.0 MSAL.NetCore Microsoft Windows 10.0.18363 [12/01/2021 14:22:24 - ] Fetched access token from host login.microsoftonline.com.
DEBUG: (False) MSAL 4.30.1.0 MSAL.NetCore Microsoft Windows 10.0.18363 [12/01/2021 14:22:24 - ] === Token Acquisition finished successfully. An access token was returned with Expiration Time: 12/01/2021 15:25:13 +00:00 and Scopes https://api.loganalytics.io/user_impersonation https://api.loganalytics.io/.default
DEBUG: SharedTokenCacheCredential.GetToken succeeded. Scopes: [ https://api.loganalytics.io/.default ] ParentRequestId:  ExpiresOn: 2021-12-01T15:25:13.0000000+00:00
DEBUG: [Common.Authentication]: Received token with LoginType 'User', Tenant: '<AAD_TENANT_ID>', UserId: '<USER_ACCOUNT_UPN>'
DEBUG: ============================ HTTP REQUEST ============================

HTTP Method:
POST

Absolute Uri:
https://api.loganalytics.io/v1/workspaces/<WORKSPACE_ID>/query

Headers:
x-ms-client-request-id        : <X_MS_CLIENT_REQUEST_ID>

Body:
{
  "query": "<KUSTO_QUERY_AS_ESCAPED_STRING>"
}


Invoke-AzOperationalInsightsQuery: The request was canceled due to the configured HttpClient.Timeout of 100 seconds elapsing.

Environment data

Name                           Value
----                           -----
PSVersion                      7.2.0
PSEdition                      Core
GitCommitId                    7.2.0
OS                             Microsoft Windows 10.0.18363
Platform                       Win32NT
PSCompatibleVersions           {1.0, 2.0, 3.0, 4.0…}
PSRemotingProtocolVersion      2.3
SerializationVersion           1.1.0.1
WSManStackVersion              3.0

Module versions

ModuleType Version    PreRelease Name
---------- -------    ---------- ----
Script     2.6.1                 Az.Accounts
Script     2.3.1                 Az.OperationalInsights

Error output

PS C:\> Resolve-AzError

WARNING: Upcoming breaking changes in the cmdlet 'Resolve-AzError' :
The `Resolve-Error` alias will be removed in a future release.  Please change any scripts that use this alias to use `Resolve-AzError` instead.
Note : Go to https://aka.ms/azps-changewarnings for steps to suppress this breaking change warning, and other information on breaking changes in Azure PowerShell.

   HistoryId: 80

Message        : The request was canceled due to the configured HttpClient.Timeout of 100 seconds elapsing.
StackTrace     :    at System.Net.Http.HttpClient.HandleFailure(Exception e, Boolean telemetryStarted, HttpResponseMessage response, CancellationTokenSource cts, CancellationToken cancellationToken, CancellationTokenSource pendingRequestsCts)
                    at System.Net.Http.HttpClient.<SendAsync>g__Core|83_0(HttpRequestMessage request, HttpCompletionOption completionOption, CancellationTokenSource cts, Boolean disposeCts, CancellationTokenSource pendingRequestsCts, CancellationToken originalCancellationToken)
                    at Microsoft.Azure.OperationalInsights.OperationalInsightsDataClient.QueryWithHttpMessagesAsync(String query, Nullable`1 timespan, IList`1 workspaces, Dictionary`2 customHeaders, CancellationToken cancellationToken)
                    at Microsoft.Azure.OperationalInsights.OperationalInsightsDataClientExtensions.QueryAsync(IOperationalInsightsDataClient operations, String query, Nullable`1 timespan, IList`1 workspaces, CancellationToken cancellationToken)
                    at Microsoft.Azure.OperationalInsights.OperationalInsightsDataClientExtensions.Query(IOperationalInsightsDataClient operations, String query, Nullable`1 timespan, IList`1 workspaces)
                    at Microsoft.Azure.Commands.OperationalInsights.Query.InvokeOperationalInsightsQuery.ExecuteCmdlet()
                    at Microsoft.WindowsAzure.Commands.Utilities.Common.CmdletExtensions.<>c__3`1.<ExecuteSynchronouslyOrAsJob>b__3_0(T c)
                    at Microsoft.WindowsAzure.Commands.Utilities.Common.CmdletExtensions.ExecuteSynchronouslyOrAsJob[T](T cmdlet, Action`1 executor)
                    at Microsoft.WindowsAzure.Commands.Utilities.Common.CmdletExtensions.ExecuteSynchronouslyOrAsJob[T](T cmdlet)
                    at Microsoft.WindowsAzure.Commands.Utilities.Common.AzurePSCmdlet.ProcessRecord()
Exception      : System.Threading.Tasks.TaskCanceledException
InvocationInfo : {Invoke-AzOperationalInsightsQuery}
Line           : $kqlResult = Invoke-AzOperationalInsightsQuery -Workspace $omsWs -Query $kustoQueryString -Wait 180 -DefaultProfile $azCtx -Debug
Position       : At line:1 char:14
                 + … kqlResult = Invoke-AzOperationalInsightsQuery -Workspace $omsWs -Quer …
                 +               ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
HistoryId      : 80

Message        : A task was canceled.
StackTrace     : 
Exception      : System.TimeoutException
InvocationInfo : {Invoke-AzOperationalInsightsQuery}
Line           : $kqlResult = Invoke-AzOperationalInsightsQuery -Workspace $omsWs -Query $kustoQueryString -Wait 180 -DefaultProfile $azCtx -Debug
Position       : At line:1 char:14
                 + … kqlResult = Invoke-AzOperationalInsightsQuery -Workspace $omsWs -Quer …
                 +               ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
HistoryId      : 80

Message        : A task was canceled.
StackTrace     :    at System.Net.Http.HttpConnectionResponseContent.SerializeToStreamAsync(Stream stream, TransportContext context, CancellationToken cancellationToken)
                    at System.Net.Http.HttpContent.LoadIntoBufferAsyncCore(Task serializeToStreamTask, MemoryStream tempBuffer)
                    at System.Net.Http.HttpClient.<SendAsync>g__Core|83_0(HttpRequestMessage request, HttpCompletionOption completionOption, CancellationTokenSource cts, Boolean disposeCts, CancellationTokenSource pendingRequestsCts, CancellationToken originalCancellationToken)
Exception      : System.Threading.Tasks.TaskCanceledException
InvocationInfo : {Invoke-AzOperationalInsightsQuery}
Line           : $kqlResult = Invoke-AzOperationalInsightsQuery -Workspace $omsWs -Query $kustoQueryString -Wait 180 -DefaultProfile $azCtx -Debug
Position       : At line:1 char:14
                 + … kqlResult = Invoke-AzOperationalInsightsQuery -Workspace $omsWs -Quer …
                 +               ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
HistoryId      : 80

The text was updated successfully, but these errors were encountered:

dingliu · 2021-12-01T15:19:28Z

A possible interim workaround is:

$restMethod = 'Post'
$restContesntType = 'application/json'
$timeOutSec = 180
$uriTemplate = "https://api.loganalytics.io/v1/workspaces/{0}/query"

$azToken = (Get-AzAccessToken -ResourceTypeName OperationalInsights -DefaultProfile $azCtx).Token
$restUri = $uriTemplate -f $omsWs.CustomerId

[hashtable] $restHeaders = @{
    Authorization = "Bearer $azToken"
    Prefer        = "wait=$timeOutSec"
}
[string] $restBody = @{ query = $kustoQueryString } | ConvertTo-Json

Measure-Command {
    $kqlResult = Invoke-RestMethod -Method $restMethod -Uri $restUri -ContentType $restContesntType -Headers $restHeaders -Body $restBody
}

But the result returned from Invoke-RestMethod is a generic [PSObject] which needs extra steps to process.

dcaro · 2021-12-02T01:39:37Z

Thanks @dingliu for reporting this issue, we are investigating this issue.

LucasYao93 · 2021-12-08T03:18:03Z

Hi @dingliu
The command Invoke-AzOperationalInsightsQuery use .Net HttpClient send request. The value of wait not be assign to timeout of the HttpClient. The HttpClient timeout default value is 100s. So cause out 100s exception.

Why Invoke-RestMethod Workaround
The timeout of HttpClient value is set to Timeout.Infinite if not assign value.

@dingmeng-xue
I have a problem. Timeout.Infinite and default 100s which one be set to value the timeout when not pass the wait parameter in command?

dingmeng-xue · 2021-12-08T04:36:35Z

@LucasYao93 , 100s default value is used by all management plane cmdlets. I think we need to set wait on header if the user provides the value of wait. Could you try it? I worry the timeout used by management plane is different from API of operationalinsightsquery.

LucasYao93 · 2021-12-08T05:52:51Z

@LucasYao93 , 100s default value is used by all management plane cmdlets. I think we need to set wait on header if the user provides the value of wait. Could you try it? I worry the timeout used by management plane is different from API of operationalinsightsquery.

@dingmeng-xue

I have fetched request use fiddler. The wait has been included in header.

POST https://api.loganalytics.io/v1/workspaces/xxxxxx-xxxxxx-xxxxxxxxxx-xxxxx/query HTTP/1.1
Host: api.loganalytics.io
x-ms-client-request-id: xxxxxx-xxxxxx-xxxxxxxxxx-xxxxx
User-Agent: FxVersion/5.0.921.35908 OSName/Windows OSVersion/Microsoft.Windows.10.0.22000 Microsoft.Azure.OperationalInsights.OperationalInsightsDataClient/0.10.0.0 Az.OperationalInsights/2.3.1 PSVersion/v7.1.4 AzurePowershell/v6.4.0
prefer: response-v1=true,include-render=true,include-statistics=true,wait=180
x-ms-app: csharpsdk,LogAnalyticsPSClient
CommandName: Invoke-AzOperationalInsightsQuery
ParameterSetName: ByWorkspaceId
Content-Type: application/json; charset=utf-8
Content-Length: 27

{
  "query": "union * "
}

We can set a timeout for the command without affecting other parts

stack-mriso · 2022-10-07T14:13:21Z

Any update on this? I'm running into this issue still

dingliu added bug This issue requires a change to an existing behavior in the product in order to be resolved. needs-triage This is a new issue that needs to be triaged to the appropriate team. labels Dec 1, 2021

ghost added question The issue doesn't require a change to the product in order to be resolved. Most issues start as that customer-reported and removed needs-triage This is a new issue that needs to be triaged to the appropriate team. labels Dec 1, 2021

dcaro assigned LucasYao93 Dec 2, 2021

dcaro added the Monitor - Operational Insights label Dec 2, 2021

dingmeng-xue added the needs-team-attention This issue needs attention from Azure service team or SDK team label Dec 7, 2021

isra-fel mentioned this issue May 10, 2024

Fix timeout of Invoke-AzOperationalInsightsQuery #24882

Merged

6 tasks

YanaXu closed this as completed in #24882 May 11, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Invoke-AzOperationalInsightsQuery: `-Wait` parameter is not respected when the supplied argument is larger than 100 #16553

Invoke-AzOperationalInsightsQuery: `-Wait` parameter is not respected when the supplied argument is larger than 100 #16553

dingliu commented Dec 1, 2021

dingliu commented Dec 1, 2021

dcaro commented Dec 2, 2021

LucasYao93 commented Dec 8, 2021 •

edited

dingmeng-xue commented Dec 8, 2021

LucasYao93 commented Dec 8, 2021 •

edited

stack-mriso commented Oct 7, 2022

Invoke-AzOperationalInsightsQuery: -Wait parameter is not respected when the supplied argument is larger than 100 #16553

Invoke-AzOperationalInsightsQuery: -Wait parameter is not respected when the supplied argument is larger than 100 #16553

Comments

dingliu commented Dec 1, 2021

Description

Issue script & Debug output

Environment data

Module versions

Error output

dingliu commented Dec 1, 2021

dcaro commented Dec 2, 2021

LucasYao93 commented Dec 8, 2021 • edited

dingmeng-xue commented Dec 8, 2021

LucasYao93 commented Dec 8, 2021 • edited

stack-mriso commented Oct 7, 2022

Invoke-AzOperationalInsightsQuery: `-Wait` parameter is not respected when the supplied argument is larger than 100 #16553

Invoke-AzOperationalInsightsQuery: `-Wait` parameter is not respected when the supplied argument is larger than 100 #16553

LucasYao93 commented Dec 8, 2021 •

edited

LucasYao93 commented Dec 8, 2021 •

edited