Pode
Pode copied to clipboard
Badgerati
How do I troubleshoot routes?
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
[Verbose]: [ContextId: 6333d327-1874-1d7f-2e4a-df70f7698335] Received request
[Verbose]: [ContextId: 6333d327-1874-1d7f-2e4a-df70f7698335] Sending response
[Verbose]: [ContextId: 6333d327-1874-1d7f-2e4a-df70f7698335] Response sent
[Verbose]: [ContextId: 6333d327-1874-1d7f-2e4a-df70f7698335] Request disposed
[Verbose]: [ContextId: 6333d327-1874-1d7f-2e4a-df70f7698335] Response disposed
[Verbose]: [ContextId: 7d73d055-4d3d-6013-e368-ae9f8b4f6e80] Received request
[Verbose]: [ContextId: 7d73d055-4d3d-6013-e368-ae9f8b4f6e80] Sending response
[Verbose]: [ContextId: 7d73d055-4d3d-6013-e368-ae9f8b4f6e80] Response sent
[Verbose]: [ContextId: 7d73d055-4d3d-6013-e368-ae9f8b4f6e80] Response disposed
[Verbose]: [ContextId: 7d73d055-4d3d-6013-e368-ae9f8b4f6e80] Socket listening
[Verbose]: [ContextId: 7d73d055-4d3d-6013-e368-ae9f8b4f6e80] Sending response
[Verbose]: [ContextId: 7d73d055-4d3d-6013-e368-ae9f8b4f6e80] Response sent
[Verbose]: [ContextId: 7d73d055-4d3d-6013-e368-ae9f8b4f6e80] Request disposed
[Verbose]: [ContextId: 7d73d055-4d3d-6013-e368-ae9f8b4f6e80] Response disposed
How would I continue troubleshooting? Why would two different calls to the same route log so differently?
/Peter
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 invoke-restmethod to call the URL. If the error occurs, then invoke-restmethod hangs forever.
Nothing gets logged and the routes scriptblock is not called.
If I press CTRL-C and break invoke-restmethod, then the scriptblock is called and the call is logged to the access_log.
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 Pode 2.9.0 Windows server 2019 pwsh 7.3.9
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:
4578 finished ContextID: 33a866ae-e8f2-8738-df87-b56e00cb5aee
Calling 4579
Received call 4579
4579 finished ContextID: bec4df88-8490-9da8-0f7b-e2b76536e542
Calling 4580
That means that irm had not finished.
in the apiserver window the following was showing:
[Verbose]: [ContextId: 33a866ae-e8f2-8738-df87-b56e00cb5aee] Received request
14:46:14.277 received 4578(PID=14640;TID=47)
[Verbose]: [ContextId: 33a866ae-e8f2-8738-df87-b56e00cb5aee] Sending response
[Verbose]: [ContextId: 33a866ae-e8f2-8738-df87-b56e00cb5aee] Response sent
[Verbose]: [ContextId: 33a866ae-e8f2-8738-df87-b56e00cb5aee] Request disposed
[Verbose]: [ContextId: 33a866ae-e8f2-8738-df87-b56e00cb5aee] Response disposed
[Verbose]: [ContextId: b17212e9-1c1c-cfaf-825a-d28f7046494b] Received request
[Verbose]: [ContextId: b17212e9-1c1c-cfaf-825a-d28f7046494b] Sending response
[Verbose]: [ContextId: b17212e9-1c1c-cfaf-825a-d28f7046494b] Response sent
[Verbose]: [ContextId: b17212e9-1c1c-cfaf-825a-d28f7046494b] Request disposed
[Verbose]: [ContextId: b17212e9-1c1c-cfaf-825a-d28f7046494b] Response disposed
[Verbose]: [ContextId: bec4df88-8490-9da8-0f7b-e2b76536e542] Received request
14:46:14.323 received 4579(PID=14640;TID=48)
[Verbose]: [ContextId: bec4df88-8490-9da8-0f7b-e2b76536e542] Sending response
[Verbose]: [ContextId: bec4df88-8490-9da8-0f7b-e2b76536e542] Response sent
[Verbose]: [ContextId: bec4df88-8490-9da8-0f7b-e2b76536e542] Request disposed
[Verbose]: [ContextId: bec4df88-8490-9da8-0f7b-e2b76536e542] Response disposed
[Verbose]: [ContextId: 77e5e9f8-7256-0b39-07ef-d4805ee345cd] Received request
[Verbose]: [ContextId: 77e5e9f8-7256-0b39-07ef-d4805ee345cd] Sending response
[Verbose]: [ContextId: 77e5e9f8-7256-0b39-07ef-d4805ee345cd] Response sent
[Verbose]: [ContextId: 77e5e9f8-7256-0b39-07ef-d4805ee345cd] Request disposed
[Verbose]: [ContextId: 77e5e9f8-7256-0b39-07ef-d4805ee345cd] Response disposed
--- CTRL-C ---
[Verbose]: [ContextId: ad1db8ba-e909-457d-6401-0f8208ec4c6a] Received request
14:59:32.706 received 4580(PID=14640;TID=47)
[Verbose]: [ContextId: ad1db8ba-e909-457d-6401-0f8208ec4c6a] Sending response
[Verbose]: [ContextId: ad1db8ba-e909-457d-6401-0f8208ec4c6a] Request disposed
[Verbose]: [ContextId: ad1db8ba-e909-457d-6401-0f8208ec4c6a] Response disposed
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 Http
When 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: IRM 1 call out of 10000 Application 4 calls out of 10