How do I troubleshoot routes? #1181
Comments
|
Hi @grtswt, how many threads are you running? Might be that your existing threads are busy while the new call comes in. |
|
I'm using four threads. And I think in this case that only one was busy at this time. Lets say that I use If I press CTRL-C and break It is as if Pode is still waiting for the request to finish sending. |
|
That would explain why it goes back into "socket listening", it's still waiting for IRM to send all the data - or it thinks there's still more data. What version of Pode, Powershell, and OS are you on? Are you using HTTP or HTTPS? Would you be able to give an example of the script that triggers this behaviour, plus the IRM call? I have seen this before, and it was on Mac and HTTPS calls when the SSL Protocol was wrong. |
|
I'm using APIServer import-module Pode
#Import-Module -Name Pode.Kestrel
Import-Module -Name PSHTML
#Import-Module ActiveDirectory
$sysRoot = (get-item $PSScriptRoot).FullName
write-host "Starting"
#Start-PodeServer -ListenerType Kestrel -Threads 2 -Verbose -RootPath "..\SystemConfig" {
Start-PodeServer -Threads 4 -RootPath $sysRoot {
Add-PodeEndpoint -Address localhost -Port 8080 -Protocol Https -SelfSigned
New-PodeLoggingMethod -File -Name 'access_log' -Path $sysroot |Enable-PodeRequestLogging
New-PodeLoggingMethod -Terminal | Enable-PodeErrorLogging -Levels '*'
New-PodeAuthScheme -Basic | Add-PodeAuthUserFile -Name 'Login' -Sessionless
$CurrentThreads = [System.Collections.Concurrent.ConcurrentDictionary[int32,string]]::new()
Add-PodeRoute -Method get -Path "/threads" -ContentType "text/html" -ArgumentList @($CurrentThreads) -ScriptBlock {
param (
[System.Collections.Concurrent.ConcurrentDictionary[int32,string]]
$CurrentThreads
)
$str = "[{0}] Thread {1} This thread" -f [datetime]::now.tostring("yyyy-MM-dd HH:mm:ss.fff"),[System.Threading.Thread]::CurrentThread.ManagedThreadId,$webevent.path
$adder = $updater = { return Write-Output $str -NoEnumerate }
$CurrentThreads.AddOrUpdate([System.Threading.Thread]::CurrentThread.ManagedThreadId, $adder, $updater)
$html = html {
head {
Title "Current threads"
style "table, th, td {border: 1px solid black; border-collapse: collapse;}"
}
body {
H1 "Current threads and their action"
table {
Thead { tr {th "TID";th "Action"} }
Tbody {
foreach ($t in $CurrentThreads.GetEnumerator()) {
tr {td $t.key;td $t.Value}
}
}
}
}
}
$str = "[{0}] Thread {1} sleeping" -f [datetime]::now.tostring("yyyy-MM-dd HH:mm:ss.fff"),[System.Threading.Thread]::CurrentThread.ManagedThreadId
$adder = $updater = { return Write-Output $str -NoEnumerate }
$CurrentThreads.AddOrUpdate([System.Threading.Thread]::CurrentThread.ManagedThreadId, $adder, $updater)
Write-PodeHtmlResponse -Value $html -StatusCode 200
}
add-poderoute -Path "/test" -Method Get -Authentication 'Login' -argumentlist @($CurrentThreads) -ScriptBlock {
param([System.Collections.Concurrent.ConcurrentDictionary[int32,string]]$CurrentThreads)
$str = "[{0}] Thread {1} executing {2}" -f [datetime]::now.tostring("yyyy-MM-dd HH:mm:ss.fff"),[System.Threading.Thread]::CurrentThread.ManagedThreadId,$webevent.path
$adder = $updater = { return Write-Output $str -NoEnumerate }
$CurrentThreads.AddOrUpdate([System.Threading.Thread]::CurrentThread.ManagedThreadId, $adder, $updater)
#Just log the request
write-podehost ("{0} received {1}(PID={2};TID={3})" -f [datetime]::now.ToString("HH:mm:ss.fff"),$webevent.query["call"],$PID,[System.Threading.Thread]::CurrentThread.ManagedThreadId)
Write-PodeTextResponse -Value ("Received call {0}" -f $webevent.query["call"]) -ContentType "text/plain" -StatusCode 200
# Do nothing else
$str = "[{0}] Thread {1} sleeping" -f [datetime]::now.tostring("yyyy-MM-dd HH:mm:ss.fff"),[System.Threading.Thread]::CurrentThread.ManagedThreadId
$adder = $updater = { return Write-Output $str -NoEnumerate }
$CurrentThreads.AddOrUpdate([System.Threading.Thread]::CurrentThread.ManagedThreadId, $adder, $updater)
} |out-null
}Query loop: [string]$userName = 'test'
[string]$userPassword = 'test'
# Convert to SecureString
[securestring]$secStringPassword = ConvertTo-SecureString $userPassword -AsPlainText -Force
[pscredential]$cred = New-Object System.Management.Automation.PSCredential ($userName, $secStringPassword)
$url = "https://127.0.0.1:8080/test?call={0}"
ForEach($i in 1..10000) {
"Calling $i"
Invoke-RestMethod -Uri ($url -f $i) -Method get -Credential $cred -ResponseHeadersVariable rh -SkipCertificateCheck
"Call {0} finished, ContextID: {1}" -f $i, ($rh.'X-Pode-ContextId' -join " ")
} I tested the above in two different windows and the query loop hung on: That means that irm had not finished. in the apiserver window the following was showing: It had stopped on the CTRL-C. When I pressed CTRL-C in the query loop window, the rows below CTRL-C appeared in the server window. I don't know why my original server (in the first log) does a restart of the same ContextID. And the sample code instead has another hidden call (with a different ContextID). For example b17212e9-1c1c-cfaf-825a-d28f7046494b in the second logfile is a call wasn't explicitly executed. Maybe it is hidden inside IRM. |
|
Thanks! I am able to reproduce the hanging with the above. Just to make sure, what happens if you drop HTTPS? Ie: Add-PodeEndpoint -Address localhost -Port 8080 -Protocol HttpWhen I do this, I can't get it to hang any more. Is this the same for you as well? If so, I'll have to do some debugging around where the request stream is being read in 🤔 |
|
I can confirm that it works if I turn off encryption. While using encryption, I noticed that cURL gave fewer errors. But I only tried that with 20000 repetitions. Might be some random thing. The Application that calls the API-server is written i Java and I can't control how it makes the calls. If I compare the fault frequency between IRM and the Application: |
I have a problem where calls to an URL sometimes hang. Nothing gets logged in the access log and the scriptblock in the route never gets executed. I Post this as a Question since I don't know if it is my fault or not.
In the log below, ContextID 6333d327-1874-1d7f-2e4a-df70f7698335 is a successful call and ContextID 7d73d055-4d3d-6013-e368-ae9f8b4f6e80 is where it failed
How would I continue troubleshooting? Why would two different calls to the same route log so differently?
/Peter
The text was updated successfully, but these errors were encountered: