search

Azure / api-management-self-hosted-gateway

Home of Azure API Management's Self-Hosted Gateway
https://docs.microsoft.com/en-gb/azure/api-management/self-hosted-gateway-overview
Other
68 stars 29 forks source link

Unreported max timeout of 230 seconds #230

Open Andrei-Predoiu opened 1 year ago

Andrei-Predoiu commented 1 year ago

Report

On version 2.0.4 the Self hosted GW there was an internal max timeout of 240 seconds. Newer versions have an internal timeout of 230.

This is not documented and even seems to contradict existing documentation relating to the <forward-request timeout="..."/> policy.

Expected Behavior

The GW timeout respects the timeout set in the <forward-request timeout="..."/> policy

Actual Behavior

The GW times out after 230 seconds

Steps to Reproduce the Problem

  1. Create an api towards http://httpstat.us/
  2. Set a timeout of 200 for the backend forward-request 
    <backend>
    <forward-request timeout="200" />
</backend>
  3. Make a call that forwards to http://httpstat.us/200?sleep=500000
  4. notice it times out in 200 seconds
  5. Set the timeout to something higher, fx 600 
    <backend>
    <forward-request timeout="600" />
</backend>
  6. Make another call to the endpoint in step 3
  7. Notice it times out in 230 seconds

Logs from self-hosted gateway

V2.0.4

{"isRequestSuccess":false,"totalTime":240199,"category":"GatewayLogs","callerIpAddress":"172.28.133.3","timeGenerated":"2023-07-04T12:28:00.9939659Z","region":"westeurope","correlationId":"5120deac-673b-4540-a7ef-1ab95fa81e6a","method":"GET","url":"https://gwurl.net/internal/echo/200?sleep=500000","responseCode":500,"responseSize":191,"cache":"none","backendTime":240174,"apiId":"echoapi-file","operationId":"Retrieve-resource-cached","productId":"digital-showroom","apimSubscriptionId":"master","clientProtocol":"HTTP/1.1","cacheTime":8,"apiRevision":"1","clientTlsVersion":"1.2","backendMethod":"GET","backendUrl":"http://httpstat.us/200?sleep=500000","lastError":{"elapsed":240196,"source":"request-forwarder","path":"forward-request\\forward-request","reason":"BackendConnectionFailure","message":"Underlying transport connection was unexpectedly closed.","section":"backend"},"errors":[{"elapsed":240195,"source":"request-forwarder","path":"forward-request\\forward-request","reason":"BackendConnectionFailure","message":"Underlying transport connection was unexpectedly closed.","section":"backend"}]}

V2.3.1

{"isRequestSuccess":false,"totalTime":230225,"category":"GatewayLogs","callerIpAddress":"172.28.129.3","timeGenerated":"2023-07-04T12:34:54.9493679Z","region":"westeurope","correlationId":"e1ef9e91-1781-40da-a9ca-87c1581efa33","method":"GET","url":"https:/gwurl.net/internal/echo/200?sleep=500000","responseCode":500,"responseSize":191,"cache":"none","backendTime":230182,"apiId":"echoapi-file","operationId":"Retrieve-resource-cached","productId":"digital-showroom","apimSubscriptionId":"master","clientProtocol":"HTTP/1.1","cacheTime":8,"apiRevision":"1","clientTlsVersion":"1.2","backendMethod":"GET","backendUrl":"http://httpstat.us/200?sleep=500000","lastError":{"elapsed":230221,"source":"request-forwarder","path":"forward-request\\forward-request","reason":"BackendConnectionFailure","message":"Underlying transport connection was unexpectedly closed.","section":"backend"},"errors":[{"elapsed":230209,"source":"request-forwarder","path":"forward-request\\forward-request","reason":"BackendConnectionFailure","message":"Underlying transport connection was unexpectedly closed.","section":"backend"}]}
{"level":"Warning","timestamp":"2023-07-04T12:38:45.1748642Z","apiId":"echoapi-file","operationId":"Retrieve-resource-cached","subscriptionId":"master","tags":20,"httpMethod":"GET","source":"request-forwarder","exception":"Gateway.Http.Client.DotNetty.UnexpectedDisconnectException: Underlying transport connection was unexpectedly closed.\n   at Gateway.Http.Client.DotNetty.DotNettyHttpBackend.SendRequestAsync(IChannel channel, IHttpRequest request, Boolean expect100Continue, IPipelineContext context, CancellationToken cancellation) in D:\\a\\1\\s\\Proxy\\Gateway.Http.Client.DotNetty\\DotNettyHttpBackend.cs:line 411\n   at Gateway.Http.Client.DotNetty.DotNettyHttpBackend.SendRequestAsync(IChannel channel, IPipelineContext context, CancellationToken cancellation) in D:\\a\\1\\s\\Proxy\\Gateway.Http.Client.DotNetty\\DotNettyHttpBackend.cs:line 253\n   at Gateway.Http.Client.DotNetty.DotNettyHttpBackend.ProcessAsync(IPipelineContext context, CancellationToken cancellation) in D:\\a\\1\\s\\Proxy\\Gateway.Http.Client.DotNetty\\DotNettyHttpBackend.cs:line 128\n   at Microsoft.WindowsAzure.ApiManagement.Proxy.Gateway.Policies.PipelineWalker.ExecuteAsync(IPipelineContext context, IEnumerable`1 steps, CancellationToken cancellation) in D:\\a\\1\\s\\Proxy\\Gateway.Pipeline\\PipelineWalker.cs:line 67\n   at Microsoft.WindowsAzure.ApiManagement.Proxy.Gateway.ChildPipeline.ExecuteAsync(IPipelineContext context, CancellationToken cancellationToken) in D:\\a\\1\\s\\Proxy\\Gateway.Pipeline\\ChildPipeline.cs:line 38\n   at Gateway.Pipeline.Extensions.ValueTaskExtensions.Await[T](ValueTask`1 input) in D:\\a\\1\\s\\Proxy\\Gateway.Pipeline\\Extensions\\ValueTaskExtensions.cs:line 29\n   at Microsoft.WindowsAzure.ApiManagement.Proxy.Gateway.Policies.IO.CallServiceHandler.ProcessAsync(IPipelineContext context, CancellationToken cancellation) in D:\\a\\1\\s\\Proxy\\Gateway.Policies.General\\IO\\CallServiceHandler.cs:line 103\n   at Microsoft.WindowsAzure.ApiManagement.Proxy.Gateway.Policies.PipelineWalker.ExecuteAsync(IPipelineContext context, IEnumerable`1 steps, CancellationToken cancellation) in D:\\a\\1\\s\\Proxy\\Gateway.Pipeline\\PipelineWalker.cs:line 67\n   at Microsoft.WindowsAzure.ApiManagement.Proxy.Gateway.ChildPipeline.ExecuteAsync(IPipelineContext context, CancellationToken cancellationToken) in D:\\a\\1\\s\\Proxy\\Gateway.Pipeline\\ChildPipeline.cs:line 38\n   at Gateway.Pipeline.Extensions.ValueTaskExtensions.Await[T](ValueTask`1 input) in D:\\a\\1\\s\\Proxy\\Gateway.Pipeline\\Extensions\\ValueTaskExtensions.cs:line 29\n   at Microsoft.WindowsAzure.ApiManagement.Proxy.Gateway.Policies.PipelineWalker.ExecuteAsync(IPipelineContext context, IEnumerable`1 steps, CancellationToken cancellation) in D:\\a\\1\\s\\Proxy\\Gateway.Pipeline\\PipelineWalker.cs:line 67\n   at Microsoft.WindowsAzure.ApiManagement.Proxy.Gateway.PipelineExecutor.ExecuteAsync(IPipelineContext context, CancellationToken cancellationToken) in D:\\a\\1\\s\\Proxy\\Gateway.Pipeline\\PipelineExecutor.cs:line 204","transportError":0,"httpError":0}
{"level":"Warning","timestamp":"2023-07-04T13:05:08.6211305Z","apiId":"collection","operationId":"default","subscriptionId":"62679b3919e77bcdde9c0030","tags":20,"httpMethod":"POST","source":"request-forwarder"{"isRequestSuccess":false,"totalTime":16,"category":"GatewayLogs,"exception":","callerIpAddress":"172.28.134.2","timeGenerated":"2023-07-04T13:05:08.6051225Z""System.Net.Sockets.SocketException (104): Connection reset by peer\n   at DotNetty.Transport.ThrowHelper.ThrowSocketException(SocketError err)\n   at DotNetty.Transport.Channels.Sockets.TcpSocketChannel`1.DoReadBytes(IByteBuffer byteBuf)\n   at DotNetty.Transport.Channels.Sockets.AbstractSocketByteChannel`2.SocketByteChannelUnsafe.FinishRead(SocketChannelAsyncOperation`2 operation)\n--- End of stack trace from previous location ---\n   at Gateway.Http.Client.DotNetty.DotNettyHttpBackend.SendRequestAsync(IChannel channel, IHttpRequest request, Boolean expect100Continue, IPipelineContext context, CancellationToken cancellation) in D:\\a\\1\\s\\Proxy\\Gateway.Http.Client.DotNetty\\DotNettyHttpBackend.cs:line 411\n   at Gateway.Http.Client.DotNetty.DotNettyHttpBackend.SendRequestAsync(IChannel channel, IPipelineContext context, CancellationToken cancellation) in D:\\a\\1\\s\\Proxy\\Gateway.Http.Client.DotNetty\\DotNettyHttpBackend.cs:line 253\n   at Gateway.Http.Client.DotNetty.DotNettyHttpBackend.ProcessAsync(IPipelineContext context, CancellationToken cancellation) in D:\\a\\1\\s\\Proxy\\Gateway.Http.Client.DotNetty\\DotNettyHttpBackend.cs:line 128\n   at Microsoft.WindowsAzure.ApiManagement.Proxy.Gateway.Policies.PipelineWalker.ExecuteAsync(IPipelineContext context, IEnumerable`1 steps, CancellationToken cancellation) in D:\\a\\1\\s\\Proxy\\Gateway.Pipeline\\PipelineWalker.cs:line 67\n   at Microsoft.WindowsAzure.ApiManagement.Proxy.Gateway.ChildPipeline.ExecuteAsync(IPipelineContext context, CancellationToken cancellationToken) in D:\\a\\1\\s\\Proxy\\Gateway.Pipeline\\ChildPipeline.cs:line 38\n   at Gateway.Pipeline.Extensions.ValueTaskExtensions.Await[T](ValueTask`1 input) in D:\\a\\1\\s\\Proxy\\Gateway.Pipeline\\Extensions\\ValueTaskExtensions.cs:line 29\n   at Microsoft.WindowsAzure.ApiManagement.Proxy.Gateway.Policies.IO.CallServiceHandler.ProcessAsync(IPipelineContext context, CancellationToken cancellation) in D:\\a\\1\\s\\Proxy\\Gateway.Policies.General\\IO\\CallServiceHandler.cs:line 103\n   at Microsoft.WindowsAzure.ApiManagement.Proxy.Gateway.Policies.PipelineWalker.ExecuteAsync(IPipelineContext context, IEnumerable`1 steps, CancellationToken cancellation) in D:\\a\\1\\s\\Proxy\\Gateway.Pipeline\\PipelineWalker.cs:line 67\n   at Microsoft.WindowsAzure.ApiManagement.Proxy.Gateway.ChildPipeline.ExecuteAsync(IPipelineContext context, CancellationToken cancellationToken) in D:\\a\\1\\s\\Proxy\\Gateway.Pipeline\\ChildPipeline.cs:line 38\n   at Gateway.Pipeline.Extensions.ValueTaskExtensions.Await[T](ValueTask`1 input) in D:\\a\\1\\s\\Proxy\\Gateway.Pipeline\\Extensions\\ValueTaskExtensions.cs:line 29\n   at Microsoft.WindowsAzure.ApiManagement.Proxy.Gateway.Policies.PipelineWalker.ExecuteAsync(IPipelineContext context, IEnumerable`1 steps, CancellationToken cancellation) in D:\\a\\1\\s\\Proxy\\Gateway.Pipeline\\PipelineWalker.cs:line 67\n   at Microsoft.WindowsAzure.ApiManagement.Proxy.Gateway.PipelineExecutor.ExecuteAsync(IPipelineContext context, CancellationToken cancellationToken) in D:\\a\\1\\s\\Proxy\\Gateway.Pipeline\\PipelineExecutor.cs:line 204","transportError":104,"region":,"httpError":"0westeurope"},"correlationId":

Self-hosted Gateway Version

2.3.1

Deployment

Self-Managed (YAML/Helm)

Platform

Google Cloud

Kubernetes Version

1.25

Anything else?

No response

tomkerkhove commented 1 year ago

Thanks for reporting, would you mind also opening a support ticket to track this please?

Andrei-Predoiu commented 1 year ago

Thanks, i opened a case

Andrei-Predoiu commented 1 year ago

Hi Tom, microsoft informed me that they raised the case as a bug.

Andrei-Predoiu commented 1 year ago

@tomkerkhove any updates or eta?

tomkerkhove commented 1 year ago

No, sorry.

tomkerkhove commented 4 months ago

What kind of load balancer is fronting this self-hostd gateway? I see it runs on Google so I am not sure, but on Azure the maximum timeout is 240 seconds and we're usually seeing the request to end after 230s because of this

Andrei-Predoiu commented 4 months ago

That's a great question, we have nginx with 900 seconds timeout but there are several network components after nginx, until the traffic reaches the "internet". I'll look into it.

tomkerkhove commented 1 month ago

Can you please try applying the following settings and see if it resolved it?