Hi Team, I am facing a very strange issue in my project. It is related to rest API call using spring reactive webclient bulider. It is working fine on local and prod as well but abnormally giving below error after 3 or 4 request to same endpoint. "org.springframework.web.server.MethodNotAllowedException: 405 METHOD_NOT_ALLOWED "Request method 'T' not supported" This is valid exception as method going to "T" for Get method and "ST" for Post method .I am not able to understand why two starting charcter truncating from method name
Please help me resolve this error.
Comment From: sbrannen
Can you please provide a minimal sample application that reproduces the issue (preferably a project that we can check out from a Git repository or a complete zip file).
Thanks
Comment From: manuj20
It is not reproducible on Local .We are getting this abnormal behaviour on production sometime not everytime .For 1 request out of 5 for same during load testing. We try to reproduce it on local.But We can't.
Comment From: bclozel
From your description, it’s not clear if the issue comes from the client or the server. Spring is not involved directly in writing or reading the HTTP protocol, so this might be a problem with the server/client library, or more likely a concurrency issue with your own code.
I’m closing this issue for now as there is no way to make progress with so little information. Feel free to reopen this issue when you’ll manage to reproduce the problem in a minimal (this is important) application. To reproduce this locally, maybe you could try and simulate concurrency with multiple concurrent requests to your service (try the « ab » tool for example).
Thanks!
Comment From: rohan-new
@manuj20 Were you able to resolve the issue ? As I am facing the same issue of getting 405 method not allowed on subsequent api calls using webclient.
Comment From: manuj20
@rohan-new We are not able to resolve this issue as per my knowledge...as it was happening with probability 1 out 20...so reproduce it difficult we carry forward this error by customised webclient connection pool configuration...We did just this but that doesn't seems to me solution . . So you can carry forward with this thread by reopening it
Comment From: mdzhigarov
We have stumbled upon the same exact issue. No workarounds so far, currently trying to enable netty trace logging to gather more information
Comment From: rohan-new
@mdzhigarov I was able to solve the issue by doing the following, u could do the same. `
HttpClient httpClient = HttpClient.create()
.option(ChannelOption.CONNECT_TIMEOUT_MILLIS, 2000)
.responseTimeout(Duration.ofMillis(5000))
.wiretap("reactor.netty.http.client.HttpClient",
LogLevel.DEBUG, AdvancedByteBufFormat.TEXTUAL)
.doOnConnected(conn ->
conn.addHandlerLast(new ReadTimeoutHandler(5000, TimeUnit.MILLISECONDS))
.addHandlerLast(new WriteTimeoutHandler(5000, TimeUnit.MILLISECONDS)));
WebClient.Builder webClientBuilder = WebClient.builder()
.clientConnector(new ReactorClientHttpConnector(httpClient));
testWebClient = webClientBuilder
.baseUrl(baseUrl)
.build();
public Mono<CustomerDetails> getCustomerDetails(String customerId) {
return testWebClient.get()
.uri(uriBuilder ->
uriBuilder.path("/customer/id/{customerId}")
.build(customerId))
.header("customerId", customerId)
.retrieve()
.bodyToMono(new ParameterizedTypeReference<RestResponse<CustomerDetails>>() {
})
.log("getCustomerDetails")
.map(RestResponse::getData);
}
`
Comment From: mdzhigarov
Same issue here. Happens on customer's production environment intermittently every once in a while. We enabled the TRACE logging on Netty level and the logs clearly show that the message is being dropped on Server Side:
2022-06-30T18:49:22.777Z DEBUG project-service [host='project-service-app-679cf4b45d-9vmnt' thread='reactor-http-epoll-5' user='svc-tfe-p-vra2' org='797ddc2a-b8af-4c12-b23a-593e6300ca86' trace='ce5e92fa-1d0c-46e2-92c5-78249a33ec48' parent='bbaa7c50-777f-44e7-8c1b-dcd2f14455e2' span='0f8b7d5e-537e-49f1-a158-e9597eef72d7'] r.n.channel.ChannelOperationsHandler.debug:250 - [8deeb8b4, L:/10.244.0.106:8080 - R:/10.244.0.107:55756] No ChannelOperation attached. Dropping:
+-------------------------------------------------+
| 0 1 2 3 4 5 6 7 8 9 a b c d e f |
+--------+-------------------------------------------------+----------------+
|00000000| 47 45 |GE |
+--------+-------------------------------------------------+----------------+
2022-06-30T18:49:22.777Z DEBUG project-service [host='project-service-app-679cf4b45d-9vmnt' thread='reactor-http-epoll-5' user='svc-tfe-p-vra2' org='797ddc2a-b8af-4c12-b23a-593e6300ca86' trace='ce5e92fa-1d0c-46e2-92c5-78249a33ec48' parent='bbaa7c50-777f-44e7-8c1b-dcd2f14455e2' span='0f8b7d5e-537e-49f1-a158-e9597eef72d7'] r.n.http.server.HttpServerOperations.debug:250 - [8deeb8b4, L:/10.244.0.106:8080 - R:/10.244.0.107:55756] Increasing pending responses, now 1
2022-06-30T18:49:22.778Z DEBUG project-service [host='project-service-app-679cf4b45d-9vmnt' thread='reactor-http-epoll-5' user='svc-tfe-p-vra2' org='797ddc2a-b8af-4c12-b23a-593e6300ca86' trace='ce5e92fa-1d0c-46e2-92c5-78249a33ec48' parent='bbaa7c50-777f-44e7-8c1b-dcd2f14455e2' span='0f8b7d5e-537e-49f1-a158-e9597eef72d7'] reactor.netty.http.server.HttpServer.debug:250 - [8deeb8b4-20, L:/10.244.0.106:8080 - R:/10.244.0.107:55756] Handler is being applied: org.springframework.http.server.reactive.ReactorHttpHandlerAdapter@72c237cc
2022-06-30T18:49:22.780Z DEBUG project-service [host='project-service-app-679cf4b45d-9vmnt' thread='reactor-http-epoll-5' user='provisioning-1etgGQszMTg23xq2(ADM-LAMORI)' org='797ddc2a-b8af-4c12-b23a-593e6300ca86' trace='fa24c1dd-c9c1-42d0-b7fe-55fa71776924' parent='5ba7c4f0-d3ab-4058-80fc-533b2d6523b3' span='9b055f77-8de5-4164-8331-785e41ff5008'] r.n.http.server.HttpServerOperations.debug:250 - [8deeb8b4-20, L:/10.244.0.106:8080 - R:/10.244.0.107:55756] Decreasing pending responses, now 0
2022-06-30T18:49:22.781Z INFO project-service [host='project-service-app-679cf4b45d-9vmnt' thread='reactor-http-epoll-5' user='provisioning-1etgGQszMTg23xq2(ADM-LAMORI)' org='797ddc2a-b8af-4c12-b23a-593e6300ca86' trace='fa24c1dd-c9c1-42d0-b7fe-55fa71776924' parent='5ba7c4f0-d3ab-4058-80fc-533b2d6523b3' span='9b055f77-8de5-4164-8331-785e41ff5008'] reactor.netty.http.server.AccessLog.info:270 - 10.244.0.107 - - [30/Jun/2022:18:49:22 +0000] "T /project-service/api/projects/21dfa050-7e19-4112-acbf-db32f6c34b63 HTTP/1.1" 405 327 8080 4 ms
2022-06-30T18:49:22.782Z DEBUG project-service [host='project-service-app-679cf4b45d-9vmnt' thread='reactor-http-epoll-5' user='provisioning-1etgGQszMTg23xq2(ADM-LAMORI)' org='797ddc2a-b8af-4c12-b23a-593e6300ca86' trace='fa24c1dd-c9c1-42d0-b7fe-55fa71776924' parent='5ba7c4f0-d3ab-4058-80fc-533b2d6523b3' span='9b055f77-8de5-4164-8331-785e41ff5008'] r.n.http.server.HttpServerOperations.debug:245 - [8deeb8b4-20, L:/10.244.0.106:8080 - R:/10.244.0.107:55756] Last HTTP packet was sent, terminating the channel
2022-06-30T18:49:22.782Z DEBUG project-service [host='project-service-app-679cf4b45d-9vmnt' thread='reactor-http-epoll-5' user='provisioning-1etgGQszMTg23xq2(ADM-LAMORI)' org='797ddc2a-b8af-4c12-b23a-593e6300ca86' trace='fa24c1dd-c9c1-42d0-b7fe-55fa71776924' parent='5ba7c4f0-d3ab-4058-80fc-533b2d6523b3' span='9b055f77-8de5-4164-8331-785e41ff5008'] r.n.http.server.HttpServerOperations.debug:245 - [8deeb8b4-20, L:/10.244.0.106:8080 - R:/10.244.0.107:55756] Last HTTP response frame
2022-06-30T18:49:22.783Z TRACE project-service [host='project-service-app-679cf4b45d-9vmnt' thread='reactor-http-epoll-5' user='provisioning-1etgGQszMTg23xq2(ADM-LAMORI)' org='797ddc2a-b8af-4c12-b23a-593e6300ca86' trace='fa24c1dd-c9c1-42d0-b7fe-55fa71776924' parent='5ba7c4f0-d3ab-4058-80fc-533b2d6523b3' span='9b055f77-8de5-4164-8331-785e41ff5008'] reactor.netty.channel.ChannelOperations.trace:235 - [8deeb8b4, L:/10.244.0.106:8080 - R:/10.244.0.107:55756] Disposing ChannelOperation from a channel
The same channel 8deeb8b4 was used 12 seconds earlier for another GET request which completed successfully:
2022-06-30T18:49:10.911Z DEBUG project-service [host='project-service-app-679cf4b45d-9vmnt' thread='reactor-http-epoll-5' user='svc-tfe-p-vra2' org='797ddc2a-b8af-4c12-b23a-593e6300ca86' trace='ce5e92fa-1d0c-46e2-92c5-78249a33ec48' parent='52edb9f6-da0f-49b6-a134-b06e10f385c3' span='a4ae8a6e-87d9-440a-a55b-a735fb9aec60'] r.n.http.server.HttpServerOperations.debug:250 - [8deeb8b4, L:/10.244.0.106:8080 - R:/10.244.0.107:55756] Increasing pending responses, now 1
2022-06-30T18:49:10.911Z DEBUG project-service [host='project-service-app-679cf4b45d-9vmnt' thread='reactor-http-epoll-5' user='svc-tfe-p-vra2' org='797ddc2a-b8af-4c12-b23a-593e6300ca86' trace='ce5e92fa-1d0c-46e2-92c5-78249a33ec48' parent='52edb9f6-da0f-49b6-a134-b06e10f385c3' span='a4ae8a6e-87d9-440a-a55b-a735fb9aec60'] reactor.netty.http.server.HttpServer.debug:250 - [8deeb8b4-19, L:/10.244.0.106:8080 - R:/10.244.0.107:55756] Handler is being applied: org.springframework.http.server.reactive.ReactorHttpHandlerAdapter@72c237cc
2022-06-30T18:49:10.912Z INFO project-service [host='project-service-app-679cf4b45d-9vmnt' thread='reactor-http-epoll-5' user='svc-tfe-p-vra2' org='797ddc2a-b8af-4c12-b23a-593e6300ca86' trace='ce5e92fa-1d0c-46e2-92c5-78249a33ec48' parent='bbaa7c50-777f-44e7-8c1b-dcd2f14455e2' span='0f8b7d5e-537e-49f1-a158-e9597eef72d7'] c.v.a.c.LocalUserPermissionsRetriever.retrieveUserPermissions:33 - retrieving user permissions
2022-06-30T18:49:10.913Z INFO project-service [host='project-service-app-679cf4b45d-9vmnt' thread='reactor-http-epoll-5' user='svc-tfe-p-vra2' org='797ddc2a-b8af-4c12-b23a-593e6300ca86' trace='ce5e92fa-1d0c-46e2-92c5-78249a33ec48' parent='bbaa7c50-777f-44e7-8c1b-dcd2f14455e2' span='0f8b7d5e-537e-49f1-a158-e9597eef72d7'] c.v.a.r.service.AuthContextServiceImpl.lambda$getAuthContext$7:71 - Looking up groups for user svc-tfe-p-vra2
2022-06-30T18:49:10.913Z INFO project-service [host='project-service-app-679cf4b45d-9vmnt' thread='reactor-http-epoll-5' user='svc-tfe-p-vra2' org='797ddc2a-b8af-4c12-b23a-593e6300ca86' trace='ce5e92fa-1d0c-46e2-92c5-78249a33ec48' parent='bbaa7c50-777f-44e7-8c1b-dcd2f14455e2' span='0f8b7d5e-537e-49f1-a158-e9597eef72d7'] c.v.a.r.service.AuthContextServiceImpl.lambda$getAuthContext$4:74 - Looking up groups for user svc-tfe-p-vra2 took for svc-tfe-p-vra2 took 0 ms
2022-06-30T18:49:10.913Z INFO project-service [host='project-service-app-679cf4b45d-9vmnt' thread='reactor-http-epoll-5' user='svc-tfe-p-vra2' org='797ddc2a-b8af-4c12-b23a-593e6300ca86' trace='ce5e92fa-1d0c-46e2-92c5-78249a33ec48' parent='bbaa7c50-777f-44e7-8c1b-dcd2f14455e2' span='0f8b7d5e-537e-49f1-a158-e9597eef72d7'] c.v.a.p.s.ProjectPrincipalServiceImpl.findAllByPrincipalAndGroupIdsDetailed:84 - Looking up projects detailed for user svc-tfe-p-vra2
2022-06-30T18:49:10.913Z INFO project-service [host='project-service-app-679cf4b45d-9vmnt' thread='reactor-http-epoll-5' user='svc-tfe-p-vra2' org='797ddc2a-b8af-4c12-b23a-593e6300ca86' trace='ce5e92fa-1d0c-46e2-92c5-78249a33ec48' parent='bbaa7c50-777f-44e7-8c1b-dcd2f14455e2' span='0f8b7d5e-537e-49f1-a158-e9597eef72d7'] c.v.a.r.s.RoleAssignmentServiceImpl.findAllAssignmentsByPrincipalAndGroupIds:153 - Looking up role assignments for user svc-tfe-p-vra2
2022-06-30T18:49:10.920Z INFO project-service [host='project-service-app-679cf4b45d-9vmnt' thread='parallel-2' user='svc-tfe-p-vra2' org='797ddc2a-b8af-4c12-b23a-593e6300ca86' trace='ce5e92fa-1d0c-46e2-92c5-78249a33ec48' parent='bbaa7c50-777f-44e7-8c1b-dcd2f14455e2' span='0f8b7d5e-537e-49f1-a158-e9597eef72d7'] c.v.a.r.service.AuthContextServiceImpl.lambda$getAuthContext$6:107 - Getting auth context took for svc-tfe-p-vra2 took 7 ms
2022-06-30T18:49:10.920Z INFO project-service [host='project-service-app-679cf4b45d-9vmnt' thread='parallel-2' user='svc-tfe-p-vra2' org='797ddc2a-b8af-4c12-b23a-593e6300ca86' trace='ce5e92fa-1d0c-46e2-92c5-78249a33ec48' parent='bbaa7c50-777f-44e7-8c1b-dcd2f14455e2' span='0f8b7d5e-537e-49f1-a158-e9597eef72d7'] c.v.a.p.controller.ProjectController.getAllProjects:168 - Received projects get all request
2022-06-30T18:49:10.921Z INFO project-service [host='project-service-app-679cf4b45d-9vmnt' thread='parallel-2' user='svc-tfe-p-vra2' org='797ddc2a-b8af-4c12-b23a-593e6300ca86' trace='ce5e92fa-1d0c-46e2-92c5-78249a33ec48' parent='bbaa7c50-777f-44e7-8c1b-dcd2f14455e2' span='0f8b7d5e-537e-49f1-a158-e9597eef72d7'] c.v.a.p.service.ProjectServiceImpl.lambda$findAll$54:607 - findAll projects with Admin token orgId 797ddc2a-b8af-4c12-b23a-593e6300ca86
2022-06-30T18:49:10.935Z DEBUG project-service [host='project-service-app-679cf4b45d-9vmnt' thread='reactor-http-epoll-5' user='svc-tfe-p-vra2' org='797ddc2a-b8af-4c12-b23a-593e6300ca86' trace='ce5e92fa-1d0c-46e2-92c5-78249a33ec48' parent='bbaa7c50-777f-44e7-8c1b-dcd2f14455e2' span='0f8b7d5e-537e-49f1-a158-e9597eef72d7'] r.n.http.server.HttpServerOperations.debug:250 - [8deeb8b4-19, L:/10.244.0.106:8080 - R:/10.244.0.107:55756] Decreasing pending responses, now 0
2022-06-30T18:49:10.935Z DEBUG project-service [host='project-service-app-679cf4b45d-9vmnt' thread='reactor-http-epoll-5' user='svc-tfe-p-vra2' org='797ddc2a-b8af-4c12-b23a-593e6300ca86' trace='ce5e92fa-1d0c-46e2-92c5-78249a33ec48' parent='bbaa7c50-777f-44e7-8c1b-dcd2f14455e2' span='0f8b7d5e-537e-49f1-a158-e9597eef72d7'] r.n.http.server.HttpServerOperations.debug:245 - [8deeb8b4-19, L:/10.244.0.106:8080 - R:/10.244.0.107:55756] Last HTTP response frame
2022-06-30T18:49:10.935Z INFO project-service [host='project-service-app-679cf4b45d-9vmnt' thread='reactor-http-epoll-5' user='svc-tfe-p-vra2' org='797ddc2a-b8af-4c12-b23a-593e6300ca86' trace='ce5e92fa-1d0c-46e2-92c5-78249a33ec48' parent='bbaa7c50-777f-44e7-8c1b-dcd2f14455e2' span='0f8b7d5e-537e-49f1-a158-e9597eef72d7'] reactor.netty.http.server.AccessLog.info:270 - 10.244.0.107 - - [30/Jun/2022:18:49:10 +0000] "GET /project-service/api/projects?apiVersion=2019-01-15&apiVersion=2019-01-15&$expand HTTP/1.1" 200 18328 8080 24 ms
2022-06-30T18:49:10.935Z DEBUG project-service [host='project-service-app-679cf4b45d-9vmnt' thread='reactor-http-epoll-5' user='svc-tfe-p-vra2' org='797ddc2a-b8af-4c12-b23a-593e6300ca86' trace='ce5e92fa-1d0c-46e2-92c5-78249a33ec48' parent='bbaa7c50-777f-44e7-8c1b-dcd2f14455e2' span='0f8b7d5e-537e-49f1-a158-e9597eef72d7'] r.n.http.server.HttpServerOperations.debug:245 - [8deeb8b4-19, L:/10.244.0.106:8080 - R:/10.244.0.107:55756] Last HTTP packet was sent, terminating the channel
2022-06-30T18:49:10.935Z TRACE project-service [host='project-service-app-679cf4b45d-9vmnt' thread='reactor-http-epoll-5' user='svc-tfe-p-vra2' org='797ddc2a-b8af-4c12-b23a-593e6300ca86' trace='ce5e92fa-1d0c-46e2-92c5-78249a33ec48' parent='bbaa7c50-777f-44e7-8c1b-dcd2f14455e2' span='0f8b7d5e-537e-49f1-a158-e9597eef72d7'] reactor.netty.channel.ChannelOperations.trace:235 - [8deeb8b4, L:/10.244.0.106:8080 - R:/10.244.0.107:55756] Disposing ChannelOperation from a channel
Comment From: mdzhigarov
Reproduced the issue by creating a web client that sends GET request with content-length: 2 header and no body. The first GET request is successful - it returns a valid result. The second GET request fails with "message": "405 METHOD_NOT_ALLOWED \"Request method 'T' not supported\""
It seems that Netty is doing the right thing - dropping the first 2 bytes of the second request - 'GE' because the channel expects 2 bytes from the first request.
Should we fix the Spring WebClient to drop such invalid requests - having content-length with no actual body? I can easily workaround this but I feel that Spring should guard me if I try to create such malicious request
Comment From: leahlin01
got same issue here but with POST methods
container_ip：10.10.33.205
container_name： ish-intelligence-store-platform-admin-web
image_name：tastien-registry-vpc.cn-shanghai.cr.aliyuncs.com/tst-uat/ish-intelligence-store-platform-admin-web:5322
pod_name：ish-intelligence-store-platform-admin-web-6d8d47d954-h8g76
pod_uid：4a8cb38e-fe5c-4e10-b139-e4bf9c140f42
source：stdout
time：2024-09-24T01:16:53.710284065Z
app_id：intelligence-store-platform-admin-web
content：2024-09-24 09:16:53.709 ERROR [intelligence-store-platform-admin-web] [http-nio-8080-exec-187] [07452746a8fbdc11402d448032ddef1f] [||] c.s.i.a.a.WebExceptionHandler - 系统异常 原因：null uri:/intelligence/member/login,堆栈：Request method 'O' not supported
org.springframework.web.HttpRequestMethodNotSupportedException: Request method 'O' not supported
at org.springframework.web.servlet.mvc.method.RequestMappingInfoHandlerMapping.handleNoMatch(RequestMappingInfoHandlerMapping.java:197)
at org.springframework.web.servlet.handler.AbstractHandlerMethodMapping.lookupHandlerMethod(AbstractHandlerMethodMapping.java:379)
at org.springframework.web.servlet.handler.AbstractHandlerMethodMapping.getHandlerInternal(AbstractHandlerMethodMapping.java:318)
at org.springframework.web.servlet.handler.AbstractHandlerMethodMapping.getHandlerInternal(AbstractHandlerMethodMapping.java:62)
at org.springframework.web.servlet.handler.AbstractHandlerMapping.getHandler(AbstractHandlerMapping.java:350)
at org.springfram
log_level：ERROR
logger_class：c.s.i.a.a.WebExceptionHandler
message：null
thread：http-nio-8080-exec-187
time：2024-09-24 09:16:53.709
trace_id：07452746a8fbdc11402d448032ddef1f