Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

HttpMessageNotReadableException occurs when handling a request. #577

Closed
leekib opened this issue May 31, 2023 · 9 comments · Fixed by #588
Closed

HttpMessageNotReadableException occurs when handling a request. #577

leekib opened this issue May 31, 2023 · 9 comments · Fixed by #588
Assignees
Milestone

Comments

@leekib
Copy link
Contributor

leekib commented May 31, 2023

Serverless Java Container version: 2.0.0-M1

Implementations: Spring Boot 3

Framework version: SpringBoot 3.1.0

Frontend service: HTTP API

Deployment method: Console

Scenario

I've tried to deploy a simple GraphQL API using spring-boot-starter-graphql and aws-serverless-java-conainer-springboot3.
When I run it on a local environment using Tomcat, the request is processed normally. However, when I deploy it on AWS Lambda, I get an org.springframework.http.converter.HttpMessageNotReadableException: JSON parse error: No content to map due to end-of-input error.

It seems error occurs while handling request.

I've been trying to solve it for three-full-days, but it hasn't been resolved. Any help would be appreciated.

Expected behavior

200 response should come when a request is sent to http api gateway url using curl.

curl 'https://[APIGATEWAY_URL]/graphql' -H 'Accept-Encoding: gzip, deflate, br' -H 'Content-Type: application/json' -H 'Accept: application/json' -H 'Connection: keep-alive' -H 'Origin: altair://-' --data-binary '{"query":"query example{\n  exampleQuery(input: { id: 1 }) {\n    ok\n  }\n}\n","variables":{}}' --compressed

Actual behavior

An error occurs as shown in the log below.

Steps to reproduce

This is the smallest project repository that can reproduce the error.
https://github.com/2012160085/photomanagement

Full log output

START RequestId: 5beefda9-8340-4539-a1b1-c1e154571024 Version: $LATEST
--
2023-05-31T07:18:56.999Z TRACE 8 --- [           main] o.s.b.w.s.f.OrderedRequestContextFilter  : Bound request context to thread: com.amazonaws.serverless.proxy.internal.servlet.AwsProxyHttpServletRequest@450794b4
2023-05-31T07:18:57.000Z TRACE 8 --- [           main] o.s.web.servlet.DispatcherServlet        : POST "/graphql", parameters={}, headers={masked} in DispatcherServlet 'dispatcherServlet'
2023-05-31T07:18:57.000Z TRACE 8 --- [           main] o.s.w.s.function.RequestPredicates       : Method "[GET]" does not match against value "POST"
2023-05-31T07:18:57.000Z TRACE 8 --- [           main] o.s.w.s.function.RequestPredicates       : Method "[POST]" matches against value "POST"
2023-05-31T07:18:57.000Z TRACE 8 --- [           main] o.s.w.s.function.RequestPredicates       : Pattern "/graphql" matches against value "/graphql"
2023-05-31T07:18:57.000Z TRACE 8 --- [           main] o.s.w.s.function.RequestPredicates       : Content-Type "[application/json]" matches against value "application/json;charset=UTF-8"
2023-05-31T07:18:57.000Z TRACE 8 --- [           main] o.s.w.s.function.RequestPredicates       : Accept "[application/graphql-response+json, application/json, application/graphql+json]" matches against value "[application/json]"
2023-05-31T07:18:57.000Z TRACE 8 --- [           main] o.s.w.servlet.function.RouterFunctions   : Predicate "((POST && /graphql) && (Content-Type: application/json && Accept: [application/graphql-response+json, application/json, application/graphql+json]))" matches against "HTTP POST /graphql"
2023-05-31T07:18:57.000Z TRACE 8 --- [           main] o.s.w.s.f.support.RouterFunctionMapping  : Mapped to org.springframework.boot.autoconfigure.graphql.servlet.GraphQlWebMvcAutoConfiguration$Lambda$909/0x0000000801c42aa0@332a7fce
2023-05-31T07:18:57.001Z DEBUG 8 --- [           main] o.s.g.server.webmvc.GraphQlHttpHandler   : Executing: document='query example{
exampleQuery(input: { id: 1 }) {
ok
}
}
', operationName='example', id=a1e5941b-7608-2e7e-389f-de1c93d105df, Locale=ko
2023-05-31T07:18:57.003Z TRACE 8 --- [           main] o.s.b.f.s.DefaultListableBeanFactory     : Returning cached instance of singleton bean 'exampleController'
2023-05-31T07:18:57.003Z TRACE 8 --- [           main] o.s.graphql.data.method.HandlerMethod    : Arguments: [TestInput(id=1)]
2023-05-31T07:18:57.003Z DEBUG 8 --- [           main] o.s.g.server.webmvc.GraphQlHttpHandler   : Execution complete
2023-05-31T07:18:57.004Z DEBUG 8 --- [           main] o.s.w.c.request.async.WebAsyncManager    : Started async request
2023-05-31T07:18:57.004Z DEBUG 8 --- [           main] o.s.w.c.request.async.WebAsyncManager    : Async result set, dispatch to /graphql
2023-05-31T07:18:57.004Z TRACE 8 --- [           main] o.s.web.servlet.DispatcherServlet        : "ASYNC" dispatch for POST "/graphql", parameters={}, headers={masked} in DispatcherServlet 'dispatcherServlet'
2023-05-31T07:18:57.004Z TRACE 8 --- [           main] o.s.w.s.function.RequestPredicates       : Method "[GET]" does not match against value "POST"
2023-05-31T07:18:57.004Z TRACE 8 --- [           main] o.s.w.s.function.RequestPredicates       : Method "[POST]" matches against value "POST"
2023-05-31T07:18:57.004Z TRACE 8 --- [           main] o.s.w.s.function.RequestPredicates       : Pattern "/graphql" matches against value "/graphql"
2023-05-31T07:18:57.004Z TRACE 8 --- [           main] o.s.w.s.function.RequestPredicates       : Content-Type "[application/json]" matches against value "application/json;charset=UTF-8"
2023-05-31T07:18:57.004Z TRACE 8 --- [           main] o.s.w.s.function.RequestPredicates       : Accept "[application/graphql-response+json, application/json, application/graphql+json]" matches against value "[application/json]"
2023-05-31T07:18:57.004Z TRACE 8 --- [           main] o.s.w.servlet.function.RouterFunctions   : Predicate "((POST && /graphql) && (Content-Type: application/json && Accept: [application/graphql-response+json, application/json, application/graphql+json]))" matches against "HTTP POST /graphql"
2023-05-31T07:18:57.004Z TRACE 8 --- [           main] o.s.w.s.f.support.RouterFunctionMapping  : Mapped to org.springframework.boot.autoconfigure.graphql.servlet.GraphQlWebMvcAutoConfiguration$Lambda$909/0x0000000801c42aa0@332a7fce
2023-05-31T07:18:57.005Z  WARN 8 --- [           main] .w.s.m.s.DefaultHandlerExceptionResolver : Resolved [org.springframework.http.converter.HttpMessageNotReadableException: JSON parse error: No content to map due to end-of-input]
2023-05-31T07:18:57.005Z TRACE 8 --- [           main] o.s.web.servlet.DispatcherServlet        : No view rendering, null ModelAndView returned.
2023-05-31T07:18:57.005Z DEBUG 8 --- [           main] o.s.web.servlet.DispatcherServlet        : Exiting from "ERROR" dispatch, status 400, headers={}
2023-05-31T07:18:57.005Z TRACE 8 --- [           main] o.s.web.servlet.DispatcherServlet        : No view rendering, null ModelAndView returned.
2023-05-31T07:18:57.005Z DEBUG 8 --- [           main] o.s.web.servlet.DispatcherServlet        : Exiting from "ERROR" dispatch, status 400, headers={}
2023-05-31T07:18:57.005Z TRACE 8 --- [           main] o.s.b.w.s.f.OrderedRequestContextFilter  : Cleared thread-bound request context: com.amazonaws.serverless.proxy.internal.servlet.AwsProxyHttpServletRequest@450794b4
2023-05-31T07:18:57.005Z  INFO 8 --- [           main] c.a.s.p.internal.LambdaContainerHandler  : 222.237.84.246 null- null [31/05/2023:07:18:56Z] "POST /graphql HTTP/1.1" 400 - "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) AltairGraphQLClient/5.0.20 Chrome/102.0.5005.167 Electron/19.0.10 Safari/537.36" combined
END RequestId: 5beefda9-8340-4539-a1b1-c1e154571024
REPORT RequestId: 5beefda9-8340-4539-a1b1-c1e154571024	Duration: 9.80 ms	Billed Duration: 10 ms	Memory Size: 1024 MB	Max Memory Used: 192 MB

For comparision, local log with Tomcat.

2023-05-31T16:37:45.233+09:00 TRACE 47111 --- [nio-8080-exec-8] o.s.b.w.s.f.OrderedRequestContextFilter  : Bound request context to thread: org.apache.catalina.connector.RequestFacade@4890085a
2023-05-31T16:37:45.234+09:00 TRACE 47111 --- [nio-8080-exec-8] o.s.web.servlet.DispatcherServlet        : POST "/graphql", parameters={}, headers={masked} in DispatcherServlet 'dispatcherServlet'
2023-05-31T16:37:45.235+09:00 TRACE 47111 --- [nio-8080-exec-8] o.s.w.s.function.RequestPredicates       : Method "[GET]" does not match against value "POST"
2023-05-31T16:37:45.235+09:00 TRACE 47111 --- [nio-8080-exec-8] o.s.w.s.function.RequestPredicates       : Method "[POST]" matches against value "POST"
2023-05-31T16:37:45.235+09:00 TRACE 47111 --- [nio-8080-exec-8] o.s.w.s.function.RequestPredicates       : Pattern "/graphql" matches against value "/graphql"
2023-05-31T16:37:45.235+09:00 TRACE 47111 --- [nio-8080-exec-8] o.s.w.s.function.RequestPredicates       : Content-Type "[application/json]" matches against value "application/json;charset=UTF-8"
2023-05-31T16:37:45.235+09:00 TRACE 47111 --- [nio-8080-exec-8] o.s.w.s.function.RequestPredicates       : Accept "[application/graphql-response+json, application/graphql+json, application/json]" matches against value "[application/json]"
2023-05-31T16:37:45.235+09:00 TRACE 47111 --- [nio-8080-exec-8] o.s.w.servlet.function.RouterFunctions   : Predicate "((POST && /graphql) && (Content-Type: application/json && Accept: [application/graphql-response+json, application/graphql+json, application/json]))" matches against "HTTP POST /graphql"
2023-05-31T16:37:45.235+09:00 TRACE 47111 --- [nio-8080-exec-8] o.s.w.s.f.support.RouterFunctionMapping  : Mapped to org.springframework.boot.autoconfigure.graphql.servlet.GraphQlWebMvcAutoConfiguration$$Lambda$1053/0x000000080145ab38@7c1a8f0f
2023-05-31T16:37:45.236+09:00 DEBUG 47111 --- [nio-8080-exec-8] o.s.g.server.webmvc.GraphQlHttpHandler   : Executing: document='query example{
  exampleQuery(input: { id: 1 }) {
    ok
  }
}
', operationName='example', id=9681b2c4-bd16-f0fb-6997-6098e9a2736f, Locale=ko
2023-05-31T16:37:45.239+09:00 TRACE 47111 --- [nio-8080-exec-8] o.s.b.f.s.DefaultListableBeanFactory     : Returning cached instance of singleton bean 'exampleController'
2023-05-31T16:37:45.240+09:00 TRACE 47111 --- [nio-8080-exec-8] o.s.graphql.data.method.HandlerMethod    : Arguments: [TestInput(id=1)]
2023-05-31T16:37:45.240+09:00 DEBUG 47111 --- [nio-8080-exec-8] o.s.g.server.webmvc.GraphQlHttpHandler   : Execution complete
2023-05-31T16:37:45.241+09:00 DEBUG 47111 --- [nio-8080-exec-8] o.s.w.c.request.async.WebAsyncManager    : Started async request
2023-05-31T16:37:45.241+09:00 DEBUG 47111 --- [nio-8080-exec-8] o.s.w.c.request.async.WebAsyncManager    : Async result set, dispatch to /graphql
2023-05-31T16:37:45.241+09:00 DEBUG 47111 --- [nio-8080-exec-8] o.s.web.servlet.DispatcherServlet        : Exiting but response remains open for further handling
2023-05-31T16:37:45.241+09:00 TRACE 47111 --- [nio-8080-exec-8] o.s.b.w.s.f.OrderedRequestContextFilter  : Cleared thread-bound request context: org.apache.catalina.connector.RequestFacade@4890085a
2023-05-31T16:37:45.241+09:00 TRACE 47111 --- [nio-8080-exec-8] o.s.b.w.s.f.OrderedRequestContextFilter  : Bound request context to thread: org.apache.catalina.core.ApplicationHttpRequest@4f70ef6c
2023-05-31T16:37:45.242+09:00 TRACE 47111 --- [nio-8080-exec-8] o.s.web.servlet.DispatcherServlet        : "ASYNC" dispatch for POST "/graphql", parameters={}, headers={masked} in DispatcherServlet 'dispatcherServlet'
2023-05-31T16:37:45.242+09:00 TRACE 47111 --- [nio-8080-exec-8] o.s.w.s.function.RequestPredicates       : Method "[GET]" does not match against value "POST"
2023-05-31T16:37:45.242+09:00 TRACE 47111 --- [nio-8080-exec-8] o.s.w.s.function.RequestPredicates       : Method "[POST]" matches against value "POST"
2023-05-31T16:37:45.242+09:00 TRACE 47111 --- [nio-8080-exec-8] o.s.w.s.function.RequestPredicates       : Pattern "/graphql" matches against value "/graphql"
2023-05-31T16:37:45.243+09:00 TRACE 47111 --- [nio-8080-exec-8] o.s.w.s.function.RequestPredicates       : Content-Type "[application/json]" matches against value "application/json;charset=UTF-8"
2023-05-31T16:37:45.243+09:00 TRACE 47111 --- [nio-8080-exec-8] o.s.w.s.function.RequestPredicates       : Accept "[application/graphql-response+json, application/graphql+json, application/json]" matches against value "[application/json]"
2023-05-31T16:37:45.243+09:00 TRACE 47111 --- [nio-8080-exec-8] o.s.w.servlet.function.RouterFunctions   : Predicate "((POST && /graphql) && (Content-Type: application/json && Accept: [application/graphql-response+json, application/graphql+json, application/json]))" matches against "HTTP POST /graphql"
2023-05-31T16:37:45.243+09:00 TRACE 47111 --- [nio-8080-exec-8] o.s.w.s.f.support.RouterFunctionMapping  : Mapped to org.springframework.boot.autoconfigure.graphql.servlet.GraphQlWebMvcAutoConfiguration$$Lambda$1053/0x000000080145ab38@7c1a8f0f
2023-05-31T16:37:45.243+09:00 TRACE 47111 --- [nio-8080-exec-8] o.s.w.s.f.s.HandlerFunctionAdapter       : Resume with async result [org.springframework.web.servlet.function.DefaultEntityResponseBuilder$DefaultEntityResponse@67450a4c]
2023-05-31T16:37:45.244+09:00 TRACE 47111 --- [nio-8080-exec-8] o.s.web.servlet.DispatcherServlet        : No view rendering, null ModelAndView returned.
2023-05-31T16:37:45.244+09:00 DEBUG 47111 --- [nio-8080-exec-8] o.s.web.servlet.DispatcherServlet        : Exiting from "ASYNC" dispatch, status 200, headers={masked}
2023-05-31T16:37:45.244+09:00 TRACE 47111 --- [nio-8080-exec-8] o.s.b.w.s.f.OrderedRequestContextFilter  : Cleared thread-bound request context: org.apache.catalina.core.ApplicationHttpRequest@4f70ef6c
@olegz
Copy link
Collaborator

olegz commented Jun 8, 2023

I am looking at it [Spring Team]

@deki
Copy link
Collaborator

deki commented Jun 8, 2023

Thanks @olegz

@olegz
Copy link
Collaborator

olegz commented Jun 9, 2023

Quick update; Based on my current observation it appears that the GraphQl configurations are not picked up. Trying to determine why . .

@olegz
Copy link
Collaborator

olegz commented Jun 12, 2023

@2012160085 for my curiosity do you see the following message in the AWS logs

Resolved location pattern [classpath:graphql/**/*.graphqls] to resources [file [/Users. . . .

OR
do you see it like this

Resolved location pattern [classpath:graphql/**/*.graphqls] to resources []

@leekib
Copy link
Contributor Author

leekib commented Jun 12, 2023

@2012160085 for my curiosity do you see the following message in the AWS logs

Resolved location pattern [classpath:graphql/**/*.graphqls] to resources [file [/Users. . . .

OR do you see it like this

Resolved location pattern [classpath:graphql/**/*.graphqls] to resources []

I see the following log from AWS Lambda.

Resolved location pattern [classpath:graphql/**/*.graphqls] to resources [file [/var/task/graphql/schema.graphqls]]

@leekib leekib closed this as completed Jun 12, 2023
@leekib
Copy link
Contributor Author

leekib commented Jun 12, 2023

closed by mistake. sorry..

@leekib leekib reopened this Jun 12, 2023
olegz added a commit to olegz/aws-serverless-java-container that referenced this issue Jun 14, 2023
@olegz olegz mentioned this issue Jun 14, 2023
olegz added a commit to olegz/aws-serverless-java-container that referenced this issue Jun 14, 2023
@olegz olegz mentioned this issue Jun 14, 2023
2 tasks
olegz added a commit to olegz/aws-serverless-java-container that referenced this issue Jun 14, 2023
@olegz
Copy link
Collaborator

olegz commented Jun 14, 2023

PR is issued. It was actually the bug in AwsAsyncContext (see commit message). It is also easily reproducible locally again's the code provided by the issue reporter

public static void main(String[] args) throws Exception {
    	StreamLambdaHandler handler = new StreamLambdaHandler();
    	InputStream targetStream = new ByteArrayInputStream(API_GATEWAY_EVENT.getBytes());
    	ByteArrayOutputStream output = new ByteArrayOutputStream();
    	handler.handleRequest(targetStream, output, null);
    	System.out.println("RESULT: " + output.toString(StandardCharsets.UTF_8));
    }

    static String API_GATEWAY_EVENT = "{\n"
			+ "    \"version\": \"1.0\",\n"
			+ "    \"resource\": \"$default\",\n"
			+ "    \"path\": \"/graphql\",\n"
			+ "    \"httpMethod\": \"POST\",\n"
			+ "    \"headers\": {\n"
			+ "        \"Content-Length\": \"45\",\n"
			+ "        \"Content-Type\": \"application/json\",\n"
			+ "        \"Host\": \"i76bfh111.execute-api.eu-west-3.amazonaws.com\",\n"
			+ "        \"User-Agent\": \"curl/7.79.1\",\n"
			+ "        \"X-Amzn-Trace-Id\": \"Root=1-64087690-2151375b219d3ba3389ea84e\",\n"
			+ "        \"X-Forwarded-For\": \"109.210.252.44\",\n"
			+ "        \"X-Forwarded-Port\": \"443\",\n"
			+ "        \"X-Forwarded-Proto\": \"https\",\n"
			+ "        \"accept\": \"*/*\"\n"
			+ "    },\n"
			+ "    \"multiValueHeaders\": {\n"
			+ "        \"Content-Length\": [\n"
			+ "            \"45\"\n"
			+ "        ],\n"
			+ "        \"Content-Type\": [\n"
			+ "            \"application/json\"\n"
			+ "        ],\n"
			+ "        \"Host\": [\n"
			+ "            \"i76bfhczs0.execute-api.eu-west-3.amazonaws.com\"\n"
			+ "        ],\n"
			+ "        \"User-Agent\": [\n"
			+ "            \"curl/7.79.1\"\n"
			+ "        ],\n"
			+ "        \"X-Amzn-Trace-Id\": [\n"
			+ "            \"Root=1-64087690-2151375b219d3ba3389ea84e\"\n"
			+ "        ],\n"
			+ "        \"X-Forwarded-For\": [\n"
			+ "            \"109.210.252.44\"\n"
			+ "        ],\n"
			+ "        \"X-Forwarded-Port\": [\n"
			+ "            \"443\"\n"
			+ "        ],\n"
			+ "        \"X-Forwarded-Proto\": [\n"
			+ "            \"https\"\n"
			+ "        ],\n"
			+ "        \"accept\": [\n"
			+ "            \"*/*\"\n"
			+ "        ]\n"
			+ "    },\n"
			+ "    \"queryStringParameters\": {\n"
			+ "        \"abc\": \"xyz\",\n"
			+ "        \"foo\": \"baz\"\n"
			+ "    },\n"
			+ "    \"multiValueQueryStringParameters\": {\n"
			+ "        \"abc\": [\n"
			+ "            \"xyz\"\n"
			+ "        ],\n"
			+ "        \"foo\": [\n"
			+ "            \"bar\",\n"
			+ "            \"baz\"\n"
			+ "        ]\n"
			+ "    },\n"
			+ "    \"requestContext\": {\n"
			+ "        \"accountId\": \"123456789098\",\n"
			+ "        \"apiId\": \"i76bfhczs0\",\n"
			+ "        \"domainName\": \"i76bfhc111.execute-api.eu-west-3.amazonaws.com\",\n"
			+ "        \"domainPrefix\": \"i76bfhczs0\",\n"
			+ "        \"extendedRequestId\": \"Bdd2ngt5iGYEMIg=\",\n"
			+ "        \"httpMethod\": \"POST\",\n"
			+ "        \"identity\": {\n"
			+ "            \"accessKey\": null,\n"
			+ "            \"accountId\": null,\n"
			+ "            \"caller\": null,\n"
			+ "            \"cognitoAmr\": null,\n"
			+ "            \"cognitoAuthenticationProvider\": null,\n"
			+ "            \"cognitoAuthenticationType\": null,\n"
			+ "            \"cognitoIdentityId\": null,\n"
			+ "            \"cognitoIdentityPoolId\": null,\n"
			+ "            \"principalOrgId\": null,\n"
			+ "            \"sourceIp\": \"109.210.252.44\",\n"
			+ "            \"user\": null,\n"
			+ "            \"userAgent\": \"curl/7.79.1\",\n"
			+ "            \"userArn\": null\n"
			+ "        },\n"
			+ "        \"path\": \"/pets\",\n"
			+ "        \"protocol\": \"HTTP/1.1\",\n"
			+ "        \"requestId\": \"Bdd2ngt5iGYEMIg=\",\n"
			+ "        \"requestTime\": \"08/Mar/2023:11:50:40 +0000\",\n"
			+ "        \"requestTimeEpoch\": 1678276240455,\n"
			+ "        \"resourceId\": \"$default\",\n"
			+ "        \"resourcePath\": \"$default\",\n"
			+ "        \"stage\": \"$default\"\n"
			+ "    },\n"
			+ "    \"pathParameters\": null,\n"
			+ "    \"stageVariables\": null,\n"
			+ "    \"body\": \"{\\\"query\\\":\\\"query example{exampleQuery(input: { id: 1 }) {ok}}\\\",\\\"variables\\\":{}}\",\n"
			+ "    \"isBase64Encoded\": false\n"
			+ "}";

olegz added a commit to olegz/aws-serverless-java-container that referenced this issue Jun 22, 2023
@deki deki closed this as completed in #588 Jun 22, 2023
deki added a commit that referenced this issue Jun 22, 2023
GH-577 Ensure listeners are notified after dispatch
@deki deki added this to the Release 2.0 milestone Jun 22, 2023
@deki
Copy link
Collaborator

deki commented Jun 22, 2023

This will be part of 2.0.0-M2 release. Thanks to @olegz for analyzing and fixing the issue.

@olegz
Copy link
Collaborator

olegz commented Jun 23, 2023

I just realised, you can remove the

@RequestMapping(path="/hi", method=RequestMethod.GET, produces = {"text/plain"})
    public Mono<String> hi() {
        return Mono.just(HELLO_MESSAGE);
    }

accidental leftover

deki added a commit that referenced this issue Jul 11, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants