apisix icon indicating copy to clipboard operation
apisix copied to clipboard

bug: After the forward-auth verification is passed, the upstream cannot obtain the request body (payload) with 504 Timeout

Open OnGoingLzy opened this issue 10 months ago • 5 comments

Current Behavior

After the forward-auth verification is passed, the upstream cannot obtain the request body (payload) image getData2 can be called normally, but getData() doesn't, and after many tests I think there are no parameters in the payload

image

This screenshot shows the error on the C# backend image

(GetData call failure occurs only when forward-auth is used, and can be called normally if it is not used)

Here's my Foward-auth configuration: "forward-auth": { "_meta": { "disable": false }, "client_headers": [ "apk", "timestamp", "nonce", "sign", "Content-Length", "Expect", "Transfer-Encoding", "Content-Encoding" ], "request_headers": [ "apk", "timestamp", "nonce", "sign", "Content-Length", "Expect", "Transfer-Encoding", "Content-Encoding" ], "request_method": "POST", "status_on_error": 500, "upstream_headers": [ "apk", "timestamp", "nonce", "sign", "Content-Length", "Expect", "Transfer-Encoding", "Content-Encoding" ], "uri": "http://localhost:9080/authApi/api/authorization/authorization1" },

other QS:forward-auth's configuration request_method:"GET" will result in an error: “time out”. Like mentioned in #11021,How can I avoid these issues in apisix-docker?

Expected Behavior

I hope that when using the forward-auth plugin, my request will be successfully requested to my upstream

Error Logs

apisix log :<2024-04-25 13:19:46 127.0.0.1 - - [25/Apr/2024:05:19:43 +0000] localhost:9080 "POST /authApi/api/authorization/authorization1 HTTP/1.1" 200 56 0.022 "-" "lua-resty-http/0.16.1 (Lua) ngx_lua/10026" 172.30.14.255:15976 200 0.021 "http://localhost:9080/api/authorization/authorization1" 2024-04-25 13:19:49 2024/04/25 05:19:49 [error] 57#57: *129256 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 172.17.0.1, server: _, request: "POST /userCenterApi/api/GetToken/GetData HTTP/1.1", upstream: "http://172.30.14.255:64335/api/GetToken/GetData", host: "localhost:9080" 2024-04-25 13:19:52 172.17.0.1 - - [25/Apr/2024:05:19:49 +0000] localhost:9080 "POST /userCenterApi/api/GetToken/GetData HTTP/1.1" 504 239 6.026 "-" "Apifox/1.0.0 (https://apifox.com)" 172.30.14.255:64335 504 6.001 "http://localhost:9080/api/GetToken/GetData"> backend log:<Microsoft.AspNetCore.Hosting.Diagnostics: Information: Request starting HTTP/1.1 POST http://localhost:9080/api/GetToken/GetData application/json 271 Microsoft.AspNetCore.Routing.EndpointMiddleware: Information: Executing endpoint 'fpxxpdfsb.Controllers.GetTokenController.GetData (ynsyyusercenterapi)' Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker: Information: Route matched with {action = "GetData", controller = "GetToken"}. Executing controller action with signature System.Threading.Tasks.Task GetData(ynsyyusercenterapi.Models.UserCenterInfo) on controller fpxxpdfsb.Controllers.GetTokenController (ynsyyusercenterapi). Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker: Information: Executed action fpxxpdfsb.Controllers.GetTokenController.GetData (ynsyyusercenterapi) in 6000.7691ms Microsoft.AspNetCore.Routing.EndpointMiddleware: Information: Executed endpoint 'fpxxpdfsb.Controllers.GetTokenController.GetData (ynsyyusercenterapi)' Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddleware: Error: An unhandled exception has occurred while executing the request.

Microsoft.AspNetCore.Connections.ConnectionResetException: The client has disconnected ---> System.Runtime.InteropServices.COMException (0x800704CD): 企图在不存在的网络连接上进行操作。 (0x800704CD) --- End of inner exception stack trace --- at Microsoft.AspNetCore.Server.IIS.Core.IO.AsyncIOOperation.GetResult(Int16 token) at Microsoft.AspNetCore.Server.IIS.Core.IISHttpContext.ReadBody() at System.IO.Pipelines.Pipe.GetReadResult(ReadResult& result) at System.IO.Pipelines.Pipe.GetReadAsyncResult() at System.IO.Pipelines.Pipe.DefaultPipeReader.GetResult(Int16 token) at Microsoft.AspNetCore.Server.IIS.Core.IISHttpContext.ReadAsync(Memory1 memory, CancellationToken cancellationToken) at Microsoft.AspNetCore.Server.IIS.Core.HttpRequestStream.ReadAsyncInternal(Memory1 buffer, CancellationToken cancellationToken) at System.Text.Json.JsonSerializer.ReadFromStreamAsync(Stream utf8Json, ReadBufferState bufferState, CancellationToken cancellationToken) at System.Text.Json.JsonSerializer.ReadAllAsync[TValue](Stream utf8Json, JsonTypeInfo jsonTypeInfo, CancellationToken cancellationToken) at Microsoft.AspNetCore.Mvc.Formatters.SystemTextJsonInputFormatter.ReadRequestBodyAsync(InputFormatterContext context, Encoding encoding) at Microsoft.AspNetCore.Mvc.Formatters.SystemTextJsonInputFormatter.ReadRequestBodyAsync(InputFormatterContext context, Encoding encoding) at Microsoft.AspNetCore.Mvc.ModelBinding.Binders.BodyModelBinder.BindModelAsync(ModelBindingContext bindingContext) at Microsoft.AspNetCore.Mvc.ModelBinding.ParameterBinder.BindModelAsync(ActionContext actionContext, IModelBinder modelBinder, IValueProvider valueProvider, ParameterDescriptor parameter, ModelMetadata metadata, Object value, Object container) at Microsoft.AspNetCore.Mvc.Controllers.ControllerBinderDelegateProvider.<>c__DisplayClass0_0.<<CreateBinderDelegate>g__Bind|0>d.MoveNext() --- End of stack trace from previous location --- at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeInnerFilterAsync>g__Awaited|13_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted) at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeFilterPipelineAsync>g__Awaited|20_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted) at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Logged|17_1(ResourceInvoker invoker) at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Logged|17_1(ResourceInvoker invoker) at Microsoft.AspNetCore.Routing.EndpointMiddleware.<Invoke>g__AwaitRequestTask|6_0(Endpoint endpoint, Task requestTask, ILogger logger) at Microsoft.AspNetCore.Authorization.AuthorizationMiddleware.Invoke(HttpContext context) at Microsoft.AspNetCore.Session.SessionMiddleware.Invoke(HttpContext context) at Microsoft.AspNetCore.Session.SessionMiddleware.Invoke(HttpContext context) at Swashbuckle.AspNetCore.SwaggerUI.SwaggerUIMiddleware.Invoke(HttpContext httpContext) at Swashbuckle.AspNetCore.Swagger.SwaggerMiddleware.Invoke(HttpContext httpContext, ISwaggerProvider swaggerProvider) at Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddleware.Invoke(HttpContext context) Microsoft.AspNetCore.Hosting.Diagnostics: Information: Request finished HTTP/1.1 POST http://localhost:9080/api/GetToken/GetData application/json 271 - 500 - text/plain;+charset=utf-8 6017.4294ms

Steps to Reproduce

  1. Run APACHE/APISIX the Docker image.
  2. Create a Route with the API.
  3. Configure the forward-auth for the route
  4. Test external certification
  5. Test the access route and observe whether the request enters the upstream backend
  6. The test found that the request successfully passed the external authentication and was forwarded to the upstream, but an error occurred

Environment

  • APISIX version (run apisix version):latest
  • Operating system (run uname -a):win10
  • OpenResty / Nginx version (run openresty -V or nginx -V):
  • etcd version, if relevant (run curl http://127.0.0.1:9090/v1/server_info):3.5(latest)
  • APISIX Dashboard version, if relevant:latest
  • Plugin runner version, for issues related to plugin runners:
  • LuaRocks version, for installation issues (run luarocks --version):

OnGoingLzy avatar Apr 25 '24 05:04 OnGoingLzy

Hi, Can you please provide the reproducing steps?

nitishfy avatar Apr 25 '24 16:04 nitishfy

Hi, Can you please provide the reproducing steps?

ok Step 1: Set up two routes and two upstreams in the dashboard. Associate route A with upstream A, and route B with upstream B. Route B is used for forwarding requests to an external authentication service (i.e., upstream B).

Step 2: Enable the forward-auth plugin for route A and set the URI to http://localhost:9080/authApi/api/authorization/authorization1 (Note: authApi is the path of route B, which means that when calling the external authentication, it should go through route B).

Step 3: Once the routes and upstreams are set up, test a POST request to the interface corresponding to upstream A through route A at http://localhost:9080/userCenterApi/api/GetToken/GetData (Note: userCenterApi is the path of route A, which means that accessing this path will make apisix forward the request).

Outcome: The external authentication service successfully validates, and during debugging, it was noticed that the request body content can be read normally. I use the following code to read the request body:

using (StreamReader reader = new StreamReader(Request.Body, Encoding.UTF8)) { body = await reader.ReadToEndAsync(); // Do something with the body... } After successful external validation, when the request is forwarded by route A to upstream A, upstream A is unable to read the request body. I use the following code to read the request body:

using (StreamReader reader = new StreamReader(Request.Body, Encoding.UTF8)) { body = await reader.ReadToEndAsync(); // Do something with the body... } The reason for not being able to read is due to the occurrence of an exception, Microsoft.AspNetCore.Connections.ConnectionResetException, with the message: "The client has disconnected." Subsequently, the apisix log shows: "upstream timed out (110: Connection timed out) while reading response header from upstream." Once I commented out the code for reading the request body, the exception did not occur, and there was no 504 timeout.

image

As a beginner, I am unable to identify the root cause of this error. Your assistance in resolving this issue would be greatly appreciated. Thank you!

OnGoingLzy avatar Apr 26 '24 08:04 OnGoingLzy

I am also running into the 504 timeout error with the following log:

*3516 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 172.21.0.1, server: _, request: "POST /anything HTTP/1.1", upstream: "http://174.129.50.9:80/anything", host: "127.0.0.1:9080"

It is unclear how to correctly use the "request_method": "POST" option without invoking this error. I am changing very minimal config from the doc example and will be easier to reproduce.

Details:

image

image

image

Things run well without "request_method": "POST" in the plugin config.

kayx23 avatar Apr 29 '24 03:04 kayx23

Related: https://github.com/apache/apisix/issues/11050, from the convo it looks like 3.6.0 does not have this issue. To be tested.

kayx23 avatar Apr 29 '24 04:04 kayx23

Related: #11050, from the convo it looks like 3.6.0 does not have this issue. To be tested.相关: #11050 ,从 convo 来看,3.6.0 没有这个问题。待测试。

Thanks for the reply, I'll try it in version 3.6.0

OnGoingLzy avatar May 06 '24 03:05 OnGoingLzy