【Spring】java 单体式应用微服务拆分过程 bug 修复：4xx 系列

须遥
155 阅读28分钟

💡简介

  • 将单体式 Spring 应用拆分为微服务式应用过程中，遇到了一系列有关 Spring 框架的问题，将修复过程及相关问题信息分析过程记录下来，便于以后解决同类问题，也顺便提高自己对 Spring 框架的理解。

  • 前期还遇到Serialize 类序列化失败等问题，暂未记录下来，未来有机会再回顾并补充相关记录。

  • 陆续修了几个 bug，最终都落到了 4xx 问题上。该类问题较难处理，主要是由于问题信息不够细致，很有可能报错内容与真实问题存在偏差。

🔨辅助工具1️⃣——接口测试脚本（自制Postman平替）

  • 为了精准定位问题，希望找到一个工具进行各个中间接口的测试，然而 postman 要下载（未来也许会去下）并且听说长得也不太好看，尝试了下 Edge 自带的网络控制台也不太好用（主要是数据格式不确定该如何设计），因此还是决定自己写一个小脚本。（如果你有什么推荐也欢迎在评论区告诉我）
  • 仅需要基础功能：
    1. 指定接口（目标 URL）
    2. 指定请求类型（POST、GET 等）
    3. 指定类型参数（RequestParam、body 等）
  • 脚本如下：
#!/usr/bin/python3
# -*- encoding: utf-8 -*-
'''
@File    :   apiTest.py
@Time    :   2023/08/26
@Author  :   Yuehao.Xu
'''

import requests
import json

# 一个请求函数，能够设定目标接口、请求类型、参数、请求头等，并返回请求结果
def request(url, method, datas=None, params=None, headers=None):
    return requests.request(method=method, url=url, data=datas, params=params, headers=headers)

def testURL():
    url = ""
    method = "POST"
    datas = {
        "username": "admin"
    }
    params = {
        "k": "v"
    }
    headers = {'content-type': 'application/json'}
    res = request(url, method, datas=json.dumps(datas), params=params, headers=headers)
    print(res.text)

def main():
    testURL()

if __name__ == '__main__':
    main()

🧠问题1️⃣——404

✏️问题描述

  • 前期修复 Jackson 相关问题费尽心力，当 jackson 不再报错后，开始出现两类 404 问题。
    • 第一类主要信息为Content type 'application/json;charset=UTF-8' not supported。
    • 第二类信息很少feign.FeignException: status 404 reading xx#xx(xx); content: {"timestamp":xx,"status":404,"error":"Not Found","message":"Not Found","path":"xx"}

ℹ️报错信息1️⃣

feign.FeignException: status 404 reading PostRepositoryRealClient#findAllByPostTypeAndPostStatusAndDeleted(PostParams); 
content: {
    status: 404,
    error: Not Found,
    exception: org.springframework.web.HttpMediaTypeNotSupportedException,
    message:org.springframework.web.HttpMediaTypeNotSupportedException: Content type 'application/json;charset=UTF-8' not supported
}

ℹ️报错信息2️⃣

feign.FeignException: status 404 reading xx#xx(xx); 
content:
{
	"status":404,
	"error":"Not Found",
	"message":"Not Found"
}

🛠️相关尝试及解决方案

📚问题分析

  • 第一类问题：可能导致的原因很多，本次是由于 json 反序列化失败导致的，具体排查方法可见下文。
  • 第二类问题：
    • 经过断点排查，发现原因如下：
      • Spring MVC前置处理器 org.springframework.web.servlet.DispatcherServlet在 handle 处理完成后，会获得一个ModelAndView类对象mv，交由 processDispatchResult 方法进行响应处理。
      • 此时若被调用函数未加@ResponseBody，则mv不为null，则会调用render(mv, request, response);进行处理，其中会将ModelAndView转为View类型的对象view。
      • 而当返回值不代表页面（不存在于 View 列表中）时，该转换过程则会报错，并返回404。

🔨解决方案

  • 第二类问题：

    • 基于以上分析，在所有函数前标记注解@ResponseBody即可。（哪怕返回值类型是void。怎么觉得不太自然？）

  • ⚠️注：

    • 目前的解决方法还未触及根本，如 ModelAndView是什么？实际工程中如何区分需要View和不需要View的请求？

🧠问题2️⃣——415

✏️问题描述

  • 随着不断断点排查，缩小范围，排查后发现以下函数接收不到请求：
    @RequestMapping(value = "/findAllByPostTypeAndPostStatusAndDeleted", method = RequestMethod.POST)
    @ResponseBody
    Page<Post> findAllByPostTypeAndPostStatusAndDeleted(@RequestBody PostParams postPrams) {
        ...
    }
  • 调整日志等级为 DEBUG，尽可能查看更多信息。（DEBUG 等级下比较烦的是信息太多了，难以检索关键信息，只能耐着性子仔细看看）
  • 看到以下几条报错信息，简单检索之后开始分析：

ℹ️报错信息1️⃣

org.springframework.web.util.NestedServletException: Request processing failed; 
    nested exception is feign.FeignException: status 415 reading PostRepositoryRealClient#findAllByPostTypeAndPostStatusAndDeleted(PostParams); 
content: {
    "status":415,
    "error":"Unsupported Media Type",
    "exception":"org.springframework.web.HttpMediaTypeNotSupportedException",
    "message":"Unsupported Media Type"
}

ℹ️报错信息2️⃣

  • （额外发现一条 WARNING）
WARN  o.s.h.c.j.MappingJackson2HttpMessageConverter - Failed to evaluate Jackson deserialization for type [[simple type, class com.raysmond.blog.common.models.PostParams]]: java.lang.NullPointerException

ℹ️报错信息3️⃣——DEBUG 日志

  • （DEBUG日志很多，在这里也稍微记录一下分析过程，方便下次分析）
  • （很长，暂且记录下来）（不知道有没有可以自行选择是否展示代码的功能，比如不想展示的时候点一下按钮就缩起来）
    • 更新：原来这叫代码折叠[2]，已进行更新，点击下面文字展开代码
  1. 首先接收到请求，输出信息
``` ... 2023-08-xx xx:xx:xx.xxx [qtp237594516-48] DEBUG o.e.jetty.server.HttpChannel - REQUEST for //localhost:8051/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted on HttpChannelOverHttp@487628e{r=1,c=false,a=IDLE,uri=//localhost:8051/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted} POST //localhost:8051/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted HTTP/1.1 Host: localhost:8051 User-Agent: python-requests/2.25.1 Accept-Encoding: gzip, deflate Accept: */* Connection: keep-alive Content-Type: application/json Content-Length: 192 ... ```
  1. 其次进行一系列匹配，确认是否是相关资源的访问或用户登录登出的请求（下面举一个例子）
``` ... 2023-08-xx xx:xx:xx.xxx [qtp237594516-48] DEBUG o.s.s.w.u.m.OrRequestMatcher - Trying to match using Ant [pattern='/css/**'] 2023-08-xx xx:xx:xx.xxx [qtp237594516-48] DEBUG o.s.s.w.u.m.AntPathRequestMatcher - Checking match of request : '/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted'; against '/css/**' ... 2023-08-xx xx:xx:xx.xxx [qtp237594516-48] DEBUG o.s.s.w.a.i.FilterSecurityInterceptor - Authorization successful 2023-08-xx xx:xx:xx.xxx [qtp237594516-48] DEBUG o.s.s.w.a.i.FilterSecurityInterceptor - RunAsManager did not change Authentication object 2023-08-xx xx:xx:xx.xxx [qtp237594516-48] DEBUG o.s.s.web.FilterChainProxy - /PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted reached end of additional filter chain; proceeding with original chain ... ```
  1. 找到对应函数，并解析参数（ 此处有一个小疑问：JPA EntityManager、jetty 分别是干什么的？ ）
``` 2023-08-28 23:36:15.512 [qtp237594516-48] DEBUG o.s.b.f.s.DefaultListableBeanFactory - Returning cached instance of singleton bean 'postRepositoryController' 2023-08-28 23:36:15.514 [qtp237594516-48] DEBUG o.s.o.j.s.OpenEntityManagerInViewInterceptor - Opening JPA EntityManager in OpenEntityManagerInViewInterceptor 2023-08-28 23:36:15.536 [qtp237594516-48] DEBUG o.e.jetty.server.HttpConnection - HttpConnection@2d95e62f[p=HttpParser{s=CONTENT,0 of 192},g=HttpGenerator@d670640{s=START}]=>HttpChannelOverHttp@487628e{r=1,c=false,a=DISPATCHED,uri=//localhost:8051/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted}<-SocketChannelEndPoint@719a7db0{/0:0:0:0:0:0:0:1:62012<->/0:0:0:0:0:0:0:1:8051,OPEN,fill=-,flush=-,to=78/30000}{io=0/0,kio=0,kro=1}->HttpConnection@2d95e62f[p=HttpParser{s=CONTENT,0 of 192},g=HttpGenerator@d670640{s=START}]=>HttpChannelOverHttp@487628e{r=1,c=false,a=DISPATCHED,uri=//localhost:8051/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted} parse HeapByteBuffer@45ff047e[p=264,l=456,c=8192,r=192]={POST /PostReposit...Length: 192\r\n\r\n<<<{"tag": "null", "...eted": "false"}>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00} {} 2023-08-28 23:36:15.536 [qtp237594516-48] DEBUG o.eclipse.jetty.http.HttpParser - parseNext s=CONTENT HeapByteBuffer@45ff047e[p=264,l=456,c=8192,r=192]={POST /PostReposit...Length: 192\r\n\r\n<<<{"tag": "null", "...eted": "false"}>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00} 2023-08-28 23:36:15.537 [qtp237594516-48] DEBUG o.e.jetty.server.HttpChannel - HttpChannelOverHttp@487628e{r=1,c=false,a=DISPATCHED,uri=//localhost:8051/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted} onContent Content@2f24f2eb{HeapByteBufferR@203ca537[p=264,l=456,c=8192,r=192]={POST /PostReposit...Length: 192\r\n\r\n<<<{"tag": "null", "...eted": "false"}>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}} 2023-08-28 23:36:15.537 [qtp237594516-48] DEBUG o.eclipse.jetty.server.HttpInput - HttpInputOverHTTP@4925bcd[c=0,q=0,[0]=null,s=STREAM] addContent Content@2f24f2eb{HeapByteBufferR@203ca537[p=264,l=456,c=8192,r=192]={POST /PostReposit...Length: 192\r\n\r\n<<<{"tag": "null", "...eted": "false"}>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}} 2023-08-28 23:36:15.537 [qtp237594516-48] DEBUG o.eclipse.jetty.http.HttpParser - CONTENT --> END 2023-08-28 23:36:15.537 [qtp237594516-48] DEBUG o.e.jetty.server.HttpChannel - HttpChannelOverHttp@487628e{r=1,c=false,a=DISPATCHED,uri=//localhost:8051/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted} onContentComplete 2023-08-28 23:36:15.537 [qtp237594516-48] DEBUG o.e.jetty.server.HttpChannel - HttpChannelOverHttp@487628e{r=1,c=false,a=DISPATCHED,uri=//localhost:8051/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted} onRequestComplete 2023-08-28 23:36:15.537 [qtp237594516-48] DEBUG o.eclipse.jetty.server.HttpInput - HttpInputOverHTTP@4925bcd[c=0,q=1,[0]=EOF,s=STREAM] addContent EOF ```
  1. 开始处理相关信息，并出现上述 报错信息2️⃣，
``` 2023-08-28 23:36:15.537 [qtp237594516-48] DEBUG o.e.jetty.server.HttpConnection - HttpConnection@2d95e62f[p=HttpParser{s=END,192 of 192},g=HttpGenerator@d670640{s=START}]=>HttpChannelOverHttp@487628e{r=1,c=false,a=DISPATCHED,uri=//localhost:8051/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted}<-SocketChannelEndPoint@719a7db0{/0:0:0:0:0:0:0:1:62012<->/0:0:0:0:0:0:0:1:8051,OPEN,fill=-,flush=-,to=79/30000}{io=0/0,kio=0,kro=1}->HttpConnection@2d95e62f[p=HttpParser{s=END,192 of 192},g=HttpGenerator@d670640{s=START}]=>HttpChannelOverHttp@487628e{r=1,c=false,a=DISPATCHED,uri=//localhost:8051/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted} parsed false HttpParser{s=END,192 of 192} 2023-08-28 23:36:15.537 [qtp237594516-48] DEBUG o.eclipse.jetty.server.HttpInput - HttpInputOverHTTP@4925bcd[c=1,q=1,[0]=EOF,s=STREAM] read 1 from Content@2f24f2eb{HeapByteBufferR@203ca537[p=265,l=456,c=8192,r=191]={POST /PostReposit...ength: 192\r\n\r\n{<<<"tag": "null", "p...eted": "false"}>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}} 2023-08-28 23:36:15.548 [qtp237594516-48] WARN o.s.h.c.j.MappingJackson2HttpMessageConverter - Failed to evaluate Jackson deserialization for type [[simple type, class com.raysmond.blog.common.models.PostParams]] ```
5. 下面是更细致的报错信息
``` java.lang.NullPointerException: null at com.fasterxml.jackson.databind.jsontype.impl.SubTypeValidator.validateSubType(SubTypeValidator.java:84) at com.fasterxml.jackson.databind.deser.BeanDeserializerFactory._validateSubType(BeanDeserializerFactory.java:867) at com.fasterxml.jackson.databind.deser.BeanDeserializerFactory.createBeanDeserializer(BeanDeserializerFactory.java:143) at com.fasterxml.jackson.databind.deser.DeserializerCache._createDeserializer2(DeserializerCache.java:403) at com.fasterxml.jackson.databind.deser.DeserializerCache._createDeserializer(DeserializerCache.java:349) at com.fasterxml.jackson.databind.deser.DeserializerCache._createAndCache2(DeserializerCache.java:264) at com.fasterxml.jackson.databind.deser.DeserializerCache._createAndCacheValueDeserializer(DeserializerCache.java:244) at com.fasterxml.jackson.databind.deser.DeserializerCache.findValueDeserializer(DeserializerCache.java:142) at com.fasterxml.jackson.databind.DeserializationContext.findNonContextualValueDeserializer(DeserializationContext.java:466) at com.fasterxml.jackson.databind.deser.BeanDeserializerBase.resolve(BeanDeserializerBase.java:479) at com.fasterxml.jackson.databind.deser.DeserializerCache._createAndCache2(DeserializerCache.java:293) at com.fasterxml.jackson.databind.deser.DeserializerCache._createAndCacheValueDeserializer(DeserializerCache.java:244) at com.fasterxml.jackson.databind.deser.DeserializerCache.hasValueDeserializerFor(DeserializerCache.java:191) at com.fasterxml.jackson.databind.DeserializationContext.hasValueDeserializerFor(DeserializationContext.java:421) at com.fasterxml.jackson.databind.ObjectMapper.canDeserialize(ObjectMapper.java:2729) at org.springframework.http.converter.json.AbstractJackson2HttpMessageConverter.canRead(AbstractJackson2HttpMessageConverter.java:159) at org.springframework.web.servlet.mvc.method.annotation.AbstractMessageConverterMethodArgumentResolver.readWithMessageConverters(AbstractMessageConverterMethodArgumentResolver.java:195) at org.springframework.web.servlet.mvc.method.annotation.RequestResponseBodyMethodProcessor.readWithMessageConverters(RequestResponseBodyMethodProcessor.java:150) at org.springframework.web.servlet.mvc.method.annotation.RequestResponseBodyMethodProcessor.resolveArgument(RequestResponseBodyMethodProcessor.java:128) at org.springframework.web.method.support.HandlerMethodArgumentResolverComposite.resolveArgument(HandlerMethodArgumentResolverComposite.java:121) at org.springframework.web.method.support.InvocableHandlerMethod.getMethodArgumentValues(InvocableHandlerMethod.java:158) at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:128) at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:97) at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:827) at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:738) at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85) at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:967) at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:901) at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970) at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:872) at javax.servlet.http.HttpServlet.service(HttpServlet.java:707) at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846) at javax.servlet.http.HttpServlet.service(HttpServlet.java:790) at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:841) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1650) at org.eclipse.jetty.websocket.server.WebSocketUpgradeFilter.doFilter(WebSocketUpgradeFilter.java:206) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1637) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:317) at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:127) at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:91) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331) at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:114) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331) at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:137) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331) at org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:111) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331) at org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:170) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331) at org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:63) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331) at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:116) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331) at org.springframework.security.web.header.HeaderWriterFilter.doFilterInternal(HeaderWriterFilter.java:64) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331) at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:105) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331) at org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter.doFilterInternal(WebAsyncManagerIntegrationFilter.java:56) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331) at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:214) at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:177) at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:347) at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:263) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1637) at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1637) at org.springframework.web.filter.HttpPutFormContentFilter.doFilterInternal(HttpPutFormContentFilter.java:108) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1637) at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:81) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1637) at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:197) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1637) at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:533) at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548) at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:190) at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1595) at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:188) at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1253) at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:168) at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:473) at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1564) at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:166) at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1155) at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) at org.eclipse.jetty.server.Server.handle(Server.java:561) at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:334) at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:251) at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:279) at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:104) at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:124) at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:679) at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:597) at java.lang.Thread.run(Thread.java:748) ```
  1. 再往后就出现了报错信息，之后就是我们在前端所看到的报错信息
``` 2023-08-28 23:36:15.551 [qtp237594516-48] DEBUG o.s.b.f.s.DefaultListableBeanFactory - Returning cached instance of singleton bean 'exceptionHandlerController' 2023-08-28 23:36:15.554 [qtp237594516-48] DEBUG o.s.s.w.c.HttpSessionSecurityContextRepository - SecurityContext is empty or contents are anonymous - context will not be stored in HttpSession. 2023-08-28 23:36:15.554 [qtp237594516-48] DEBUG o.e.j.s.ErrorPageErrorHandler - getErrorPage(POST /PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted) => error_page=/error (from global default) 2023-08-28 23:36:15.555 [qtp237594516-48] DEBUG o.e.j.s.handler.ErrorHandler - error page dispatch /error->Dispatcher@0x6c792fdb{null,/error} 2023-08-28 23:36:15.556 [qtp237594516-48] DEBUG o.e.j.s.handler.ContextHandler - scope /||/error @ o.s.b.c.e.j.JettyEmbeddedWebAppContext@79c2bc34{/,[file:///private/var/folders/sg/fcqtq3fx50b9tfz0jmw8jh3m0000gq/T/jetty-docbase.8645957883152335123.8051/, jar:file:/Users/freshwind/.gradle/caches/modules-2/files-2.1/org.webjars/jquery/2.1.1/dd89e356066869550b5509c4370f995ad6698d9a/jquery-2.1.1.jar!/META-INF/resources, jar:file:/Users/freshwind/.gradle/caches/modules-2/files-2.1/org.webjars/bootstrap/3.2.0/aadbf822539bc170014701382cff887094c4c3df/bootstrap-3.2.0.jar!/META-INF/resources, jar:file:/Users/freshwind/.gradle/caches/modules-2/files-2.1/org.webjars/font-awesome/4.7.0/ae86dfacae19ede1910de53f38a573215256646b/font-awesome-4.7.0.jar!/META-INF/resources, jar:file:/Users/freshwind/.gradle/caches/modules-2/files-2.1/org.webjars/ace/1.2.8/dea95ef85f17e404c3930ce0618585d64ac93568/ace-1.2.8.jar!/META-INF/resources],AVAILABLE} 2023-08-28 23:36:15.556 [qtp237594516-48] DEBUG o.e.j.s.handler.ContextHandler - context=||/error @ o.s.b.c.e.j.JettyEmbeddedWebAppContext@79c2bc34{/,[file:///private/var/folders/sg/fcqtq3fx50b9tfz0jmw8jh3m0000gq/T/jetty-docbase.8645957883152335123.8051/, jar:file:/Users/freshwind/.gradle/caches/modules-2/files-2.1/org.webjars/jquery/2.1.1/dd89e356066869550b5509c4370f995ad6698d9a/jquery-2.1.1.jar!/META-INF/resources, jar:file:/Users/freshwind/.gradle/caches/modules-2/files-2.1/org.webjars/bootstrap/3.2.0/aadbf822539bc170014701382cff887094c4c3df/bootstrap-3.2.0.jar!/META-INF/resources, jar:file:/Users/freshwind/.gradle/caches/modules-2/files-2.1/org.webjars/font-awesome/4.7.0/ae86dfacae19ede1910de53f38a573215256646b/font-awesome-4.7.0.jar!/META-INF/resources, jar:file:/Users/freshwind/.gradle/caches/modules-2/files-2.1/org.webjars/ace/1.2.8/dea95ef85f17e404c3930ce0618585d64ac93568/ace-1.2.8.jar!/META-INF/resources],AVAILABLE} 2023-08-28 23:36:15.556 [qtp237594516-48] DEBUG org.eclipse.jetty.server.session - sessionHandler=org.eclipse.jetty.server.session.SessionHandler2006081398==dftMaxIdleSec=1800 2023-08-28 23:36:15.556 [qtp237594516-48] DEBUG org.eclipse.jetty.server.session - session=null 2023-08-28 23:36:15.556 [qtp237594516-48] DEBUG o.e.jetty.servlet.ServletHandler - servlet |/error|null -> dispatcherServlet@7ef5559e==org.springframework.web.servlet.DispatcherServlet,jsp=null,order=-1,inst=true 2023-08-28 23:36:15.556 [qtp237594516-48] DEBUG o.e.jetty.servlet.ServletHandler - chain=null 2023-08-28 23:36:15.558 [qtp237594516-48] DEBUG o.s.b.f.s.DefaultListableBeanFactory - Returning cached instance of singleton bean 'basicErrorController' 2023-08-28 23:36:15.574 [qtp237594516-48] DEBUG o.e.jetty.server.HttpChannel - sendResponse info=null content=DirectByteBuffer@3d1f33c7[p=0,l=257,c=32768,r=257]={<<<{"timestamp":1693...tusAndDeleted"}>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00} complete=false committing=true callback=Blocker@244f040d{null} 2023-08-28 23:36:15.574 [qtp237594516-48] DEBUG o.e.jetty.server.HttpChannel - COMMIT for /error on HttpChannelOverHttp@487628e{r=1,c=true,a=DISPATCHED,uri=//localhost:8051/error} 415 null HTTP/1.1 Date: Mon, 28 Aug 2023 15:36:15 GMT X-Content-Type-Options: nosniff X-XSS-Protection: 1; mode=block Pragma: no-cache X-Frame-Options: DENY Content-Type: application/json;charset=utf-8 ```

🛠️相关尝试及解决方案

🔍简单检索信息

  • HTTP请求415错误 – 不支持的媒体类型(Unsupported media type)[1]
  • 通常可以检查以下情况：
    1. 检查你的 http 请求头信息，比如 因为 User-Agent 被服务器设置拒绝请求了；
    • 比如你写的的爬虫，就很有可能因为没有伪装成浏览器，被拒绝请求
    1. 检查你的 http 请求方法，以及服务器端的设置
    • 比如：有一个强制用 post 请求的接口，你是否使用了非 post 请求
    1. post 请求参数设置，必须为 json 格式

📚问题分析

  • 根据相关信息，推测大概率是所传输数据无法解析问题。根据相关信息，优先检查如何解决报错信息2️⃣。

    • 经过简单检索，发现似乎没有相关信息，因此决定基于报错信息查看源码，理解报错原因。

  • 首先从报错信息at com.fasterxml.jackson.databind.ObjectMapper.canDeserialize(ObjectMapper.java:2729)定位到 ObjectMapper，查看相关逻辑。

    • 根据报错信息一步步找到com/fasterxml/jackson/databind/jsontype/impl/SubTypeValidator.java:84，相关函数代码如下：
    public void validateSubType(DeserializationContext ctxt, JavaType type) throws JsonMappingException
    {
        // There are certain nasty classes that could cause problems, mostly
        // via default typing -- catch them here.
        final Class<?> raw = type.getRawClass();
        String full = raw.getName();

        main_check:
        do {
            if (_cfgIllegalClassNames.contains(full)) {
                break;
            }

            // 18-Dec-2017, tatu: As per [databind#1855], need bit more sophisticated handling
            //    for some Spring framework types
            if (full.startsWith(PREFIX_STRING)) {
                for (Class<?> cls = raw; cls != Object.class; cls = cls.getSuperclass()) {
                    String name = cls.getSimpleName();
                    // looking for "AbstractBeanFactoryPointcutAdvisor" but no point to allow any is there?
                    if ("AbstractPointcutAdvisor".equals(name)
                            // ditto  for "FileSystemXmlApplicationContext": block all ApplicationContexts
                            || "AbstractApplicationContext".equals(name)) {
                        break main_check;
                    }
                }
            }
            return;
        } while (false);

        throw JsonMappingException.from(ctxt,
                String.format("Illegal type (%s) to deserialize: prevented for security reasons", full));
    }
  • 在其中的for (Class<?> cls = raw; cls != Object.class; cls = cls.getSuperclass()) 循环中，如果当前cls为interface接口类（在本次测试中cls为org.springframework.data.domain.Pageable接口），则经过cls = cls.getSuperclass()语句后会使得cls==null。
  • 检索该语句，发现 GitHub 上有人提过该 bug[3]。（此时在心里猜测可能是版本问题，因为前文中查看ObjectMapper.java文件并增加断点后发现同时存在 2.8.11 和 2.9.2 两个版本的同名文件）
  • 根据 Github 讨论结果：Fix included in 2.8.11.1 / 2.9.4，尝试清除所有现有包并更新到最新版本。

🔨尝试方案1️⃣——清除所有包并更新到最新版本

  • 检查 build.gradle 发现使用的版本为 2.8.11，看来确实是版本问题。修改为以下内容：（Maven 采用相应的修改方式，只需确保版本更新即可）
dependencies {
	...
	compile group: 'com.fasterxml.jackson.core', name: 'jackson-databind', version: '+'
	...
}
  • 保险起见，可以彻底清理 gradle 缓存（后续发现这里清理不彻底可能导致存在问题）（以下为 mac 版本）[5]：
./gradlew --stop
rm -rf ~/.gradle/caches/
  • 重新加载包（例如在 idea 下点击 reload 按钮）
  • 静静等待...（吐槽一下，gradle 每次加载太久了）
  • 发现自己的 build.gradle 文件格式乱得一塌糊涂，另立一个 flag⛳️，有空补一篇 gradle 的基础知识
  • 结果：功夫不负有心人，变成 400 Bad Requests 了。

🧠问题3️⃣——400

✏️问题描述

  • 前期修复后，开始出现 400 问题，主要信息为Bad Request（相当于啥也没有）。

ℹ️报错信息1️⃣

content: {
	"status":400,
	"error":"Bad Request",
	"exception": "org.springframework.http.converter.HttpMessageNotReadableException",
	"message":"Bad Request"
}

ℹ️报错信息2️⃣——DEBUG 日志

  • 同样，仔细检查日志，以下隐去一些重复的不重要部分
  1. 首先接收到请求，输出信息
``` POST //localhost:8051/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted HTTP/1.1 Host: localhost:8051 User-Agent: python-requests/2.31.0 Accept-Encoding: gzip, deflate, br Accept: */* Connection: keep-alive Content-Type: application/json Content-Length: 191 ```
  1. 其次进行一系列匹配，确认是否是相关资源的访问或用户登录登出的请求
  • 其中有一部分之前没注意到的，是进行身份认证 
2023-08-30 18:13:24.851 [qtp1307131613-30] DEBUG o.s.s.w.a.i.FilterSecurityInterceptor - Secure object: FilterInvocation: URL: /PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted; Attributes: [permitAll]
2023-08-30 18:13:24.851 [qtp1307131613-30] DEBUG o.s.s.w.a.i.FilterSecurityInterceptor - Previously Authenticated: org.springframework.security.authentication.AnonymousAuthenticationToken@9055c2bc: Principal: anonymousUser; Credentials: [PROTECTED]; Authenticated: true; Details: org.springframework.security.web.authentication.WebAuthenticationDetails@b364: RemoteIpAddress: 0:0:0:0:0:0:0:1; SessionId: null; Granted Authorities: ROLE_ANONYMOUS
2023-08-30 18:13:24.856 [qtp1307131613-30] DEBUG o.s.s.a.vote.AffirmativeBased - Voter: org.springframework.security.web.access.expression.WebExpressionVoter@4251b99a, returned: 1
2023-08-30 18:13:24.856 [qtp1307131613-30] DEBUG o.s.s.w.a.i.FilterSecurityInterceptor - Authorization successful
2023-08-30 18:13:24.856 [qtp1307131613-30] DEBUG o.s.s.w.a.i.FilterSecurityInterceptor - RunAsManager did not change Authentication object
2023-08-30 18:13:24.856 [qtp1307131613-30] DEBUG o.s.s.web.FilterChainProxy - /PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted reached end of additional filter chain; proceeding with original chain
  1. 找到对应函数，并解析参数 
2023-08-30 18:13:24.856 [qtp1307131613-30] DEBUG o.e.jetty.servlet.ServletHandler - call filter Jetty_WebSocketUpgradeFilter
2023-08-30 18:13:24.859 [qtp1307131613-30] DEBUG o.e.jetty.servlet.ServletHandler - call servlet dispatcherServlet@7ef5559e==org.springframework.web.servlet.DispatcherServlet,jsp=null,order=-1,inst=true
2023-08-30 18:13:24.869 [qtp1307131613-30] DEBUG o.s.b.f.s.DefaultListableBeanFactory - Returning cached instance of singleton bean 'postRepositoryController'
2023-08-30 18:13:24.869 [qtp1307131613-30] DEBUG o.s.o.j.s.OpenEntityManagerInViewInterceptor - Opening JPA EntityManager in OpenEntityManagerInViewInterceptor
2023-08-30 18:13:24.879 [qtp1307131613-30] DEBUG o.e.jetty.server.HttpConnection - HttpConnection@5a00b8c9[p=HttpParser{s=CONTENT,0 of 191},g=HttpGenerator@648f8367{s=START}]=>HttpChannelOverHttp@4c618052{r=1,c=false,a=DISPATCHED,uri=//localhost:8051/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted}<-SocketChannelEndPoint@6e51a4e4{/0:0:0:0:0:0:0:1:55642<->/0:0:0:0:0:0:0:1:8051,OPEN,fill=-,flush=-,to=40/30000}{io=0/0,kio=0,kro=1}->HttpConnection@5a00b8c9[p=HttpParser{s=CONTENT,0 of 191},g=HttpGenerator@648f8367{s=START}]=>HttpChannelOverHttp@4c618052{r=1,c=false,a=DISPATCHED,uri=//localhost:8051/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted} parse HeapByteBuffer@60d27582[p=268,l=459,c=8192,r=191]={POST /PostReposit...Length: 191\r\n\r\n<<<{"tag": "tag", "p...eted": "false"}>>>gnoreCase":false,...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00} {}
2023-08-30 18:13:24.879 [qtp1307131613-30] DEBUG o.eclipse.jetty.http.HttpParser - parseNext s=CONTENT HeapByteBuffer@60d27582[p=268,l=459,c=8192,r=191]={POST /PostReposit...Length: 191\r\n\r\n<<<{"tag": "tag", "p...eted": "false"}>>>gnoreCase":false,...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
2023-08-30 18:13:24.879 [qtp1307131613-30] DEBUG o.e.jetty.server.HttpChannel - HttpChannelOverHttp@4c618052{r=1,c=false,a=DISPATCHED,uri=//localhost:8051/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted} onContent Content@68dfa4ee{HeapByteBufferR@70d39629[p=268,l=459,c=8192,r=191]={POST /PostReposit...Length: 191\r\n\r\n<<<{"tag": "tag", "p...eted": "false"}>>>gnoreCase":false,...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}}
2023-08-30 18:13:24.879 [qtp1307131613-30] DEBUG o.eclipse.jetty.server.HttpInput - HttpInputOverHTTP@33d91dcb[c=0,q=0,[0]=null,s=STREAM] addContent Content@68dfa4ee{HeapByteBufferR@70d39629[p=268,l=459,c=8192,r=191]={POST /PostReposit...Length: 191\r\n\r\n<<<{"tag": "tag", "p...eted": "false"}>>>gnoreCase":false,...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}}
2023-08-30 18:13:24.879 [qtp1307131613-30] DEBUG o.eclipse.jetty.http.HttpParser - CONTENT --> END
2023-08-30 18:13:24.879 [qtp1307131613-30] DEBUG o.e.jetty.server.HttpChannel - HttpChannelOverHttp@4c618052{r=1,c=false,a=DISPATCHED,uri=//localhost:8051/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted} onContentComplete
2023-08-30 18:13:24.879 [qtp1307131613-30] DEBUG o.e.jetty.server.HttpChannel - HttpChannelOverHttp@4c618052{r=1,c=false,a=DISPATCHED,uri=//localhost:8051/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted} onRequestComplete
2023-08-30 18:13:24.879 [qtp1307131613-30] DEBUG o.eclipse.jetty.server.HttpInput - HttpInputOverHTTP@33d91dcb[c=0,q=1,[0]=EOF,s=STREAM] addContent EOF
2023-08-30 18:13:24.880 [qtp1307131613-30] DEBUG o.e.jetty.server.HttpConnection - HttpConnection@5a00b8c9[p=HttpParser{s=END,191 of 191},g=HttpGenerator@648f8367{s=START}]=>HttpChannelOverHttp@4c618052{r=1,c=false,a=DISPATCHED,uri=//localhost:8051/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted}<-SocketChannelEndPoint@6e51a4e4{/0:0:0:0:0:0:0:1:55642<->/0:0:0:0:0:0:0:1:8051,OPEN,fill=-,flush=-,to=41/30000}{io=0/0,kio=0,kro=1}->HttpConnection@5a00b8c9[p=HttpParser{s=END,191 of 191},g=HttpGenerator@648f8367{s=START}]=>HttpChannelOverHttp@4c618052{r=1,c=false,a=DISPATCHED,uri=//localhost:8051/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted} parsed false HttpParser{s=END,191 of 191}
2023-08-30 18:13:24.880 [qtp1307131613-30] DEBUG o.eclipse.jetty.server.HttpInput - HttpInputOverHTTP@33d91dcb[c=1,q=1,[0]=EOF,s=STREAM] read 1 from Content@68dfa4ee{HeapByteBufferR@70d39629[p=269,l=459,c=8192,r=190]={POST /PostReposit...ength: 191\r\n\r\n{<<<"tag": "tag", "po...eted": "false"}>>>gnoreCase":false,...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}}
2023-08-30 18:13:24.880 [qtp1307131613-30] DEBUG o.eclipse.jetty.server.HttpInput - HttpInputOverHTTP@33d91dcb[c=191,q=1,[0]=EOF,s=STREAM] read 190 from Content@68dfa4ee{HeapByteBufferR@70d39629[p=459,l=459,c=8192,r=0]={POST /PostReposit...eted": "false"}<<<>>>gnoreCase":false,...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}}
2023-08-30 18:13:24.881 [qtp1307131613-30] DEBUG o.e.jetty.server.HttpConnection - releaseRequestBuffer HttpConnection@5a00b8c9[p=HttpParser{s=END,191 of 191},g=HttpGenerator@648f8367{s=START}]=>HttpChannelOverHttp@4c618052{r=1,c=false,a=DISPATCHED,uri=//localhost:8051/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted}<-SocketChannelEndPoint@6e51a4e4{/0:0:0:0:0:0:0:1:55642<->/0:0:0:0:0:0:0:1:8051,OPEN,fill=-,flush=-,to=41/30000}{io=0/0,kio=0,kro=1}->HttpConnection@5a00b8c9[p=HttpParser{s=END,191 of 191},g=HttpGenerator@648f8367{s=START}]=>HttpChannelOverHttp@4c618052{r=1,c=false,a=DISPATCHED,uri=//localhost:8051/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted}
2023-08-30 18:13:24.884 [qtp1307131613-30] DEBUG o.s.b.f.s.DefaultListableBeanFactory - Returning cached instance of singleton bean 'exceptionHandlerController'
2023-08-30 18:13:24.886 [qtp1307131613-30] DEBUG o.s.s.w.c.HttpSessionSecurityContextRepository - SecurityContext is empty or contents are anonymous - context will not be stored in HttpSession.
  1. 这里比较棘手，突然就开始错误处理，并未说明是什么原因 
2023-08-30 18:13:24.886 [qtp1307131613-30] DEBUG o.e.j.s.ErrorPageErrorHandler - getErrorPage(POST /PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted) => error_page=/error (from global default)
2023-08-30 18:13:24.887 [qtp1307131613-30] DEBUG o.e.j.s.handler.ErrorHandler - error page dispatch /error->Dispatcher@0x30bd8073{null,/error}
2023-08-30 18:13:24.887 [qtp1307131613-30] DEBUG o.e.j.s.handler.ContextHandler - scope /||/error @ o.s.b.c.e.j.JettyEmbeddedWebAppContext@15c1b543{/,[file:///private/var/folders/sg/fcqtq3fx50b9tfz0jmw8jh3m0000gq/T/jetty-docbase.986210962886620735.8051/],AVAILABLE}
2023-08-30 18:13:24.887 [qtp1307131613-30] DEBUG o.e.j.s.handler.ContextHandler - context=||/error @ o.s.b.c.e.j.JettyEmbeddedWebAppContext@15c1b543{/,[file:///private/var/folders/sg/fcqtq3fx50b9tfz0jmw8jh3m0000gq/T/jetty-docbase.986210962886620735.8051/],AVAILABLE}
2023-08-30 18:13:24.887 [qtp1307131613-30] DEBUG org.eclipse.jetty.server.session - sessionHandler=org.eclipse.jetty.server.session.SessionHandler596984576==dftMaxIdleSec=1800
2023-08-30 18:13:24.887 [qtp1307131613-30] DEBUG org.eclipse.jetty.server.session - session=null
2023-08-30 18:13:24.887 [qtp1307131613-30] DEBUG o.e.jetty.servlet.ServletHandler - servlet |/error|null -> dispatcherServlet@7ef5559e==org.springframework.web.servlet.DispatcherServlet,jsp=null,order=-1,inst=true
2023-08-30 18:13:24.887 [qtp1307131613-30] DEBUG o.e.jetty.servlet.ServletHandler - chain=null
2023-08-30 18:13:24.888 [qtp1307131613-30] DEBUG o.s.b.f.s.DefaultListableBeanFactory - Returning cached instance of singleton bean 'basicErrorController'
2023-08-30 18:13:24.900 [qtp1307131613-30] DEBUG o.e.jetty.server.HttpChannel - sendResponse info=null content=DirectByteBuffer@4a6a174d[p=0,l=243,c=32768,r=243]={<<<{"timestamp":1693...tusAndDeleted"}>>>tus 500 reading P...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00} complete=false committing=true callback=Blocker@49de1203{null}
2023-08-30 18:13:24.901 [qtp1307131613-30] DEBUG o.e.jetty.server.HttpChannel - COMMIT for /error on HttpChannelOverHttp@4c618052{r=1,c=true,a=DISPATCHED,uri=//localhost:8051/error}
400 null HTTP/1.1
Date: Wed, 30 Aug 2023 10:13:24 GMT
X-Content-Type-Options: nosniff
X-XSS-Protection: 1; mode=block
Pragma: no-cache
X-Frame-Options: DENY
Content-Type: application/json;charset=utf-8
\
2023-08-30 18:13:24.901 [qtp1307131613-30] DEBUG o.e.jetty.server.HttpConnection - org.eclipse.jetty.server.HttpConnection$SendCallback@329269b6[PROCESSING][i=HTTP/1.1{s=400,h=6,cl=-1},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@6e70c98f] generate: NEED_HEADER (null,[p=0,l=243,c=32768,r=243],false)@START
2023-08-30 18:13:24.901 [qtp1307131613-30] DEBUG o.e.jetty.http.HttpGenerator - generateHeaders HTTP/1.1{s=400,h=6,cl=-1} last=false content=DirectByteBuffer@4a6a174d[p=0,l=243,c=32768,r=243]={<<<{"timestamp":1693...tusAndDeleted"}>>>tus 500 reading P...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
2023-08-30 18:13:24.901 [qtp1307131613-30] DEBUG o.e.jetty.http.HttpGenerator - Date: Wed, 30 Aug 2023 10:13:24 GMT
X-Content-Type-Options: nosniff
X-XSS-Protection: 1; mode=block
Pragma: no-cache
X-Frame-Options: DENY
Content-Type: application/json;charset=utf-8

🛠️相关尝试及解决方案

🔍简单检索信息

  • Spring MVC : 400 错误是怎么发生的 ?[4]

  • Spring MVC前置处理器 org.springframework.web.servlet.DispatcherServlet 处理一个请求时，会在doDispatch方法中尝试捕获 handler 匹配过程， handler adapter 匹配过程和 handler 执行过程中的异常，该异常记做 dispatchException。

  • 具体来说，对请求处理的主体流程可以简单地理解为两个步骤：

    1. 寻找 handler 并执行以处理请求（request）。细分为以下几个方面：
      • 目标 handler 匹配过程，
      • 目标 handler adapter 匹配过程，
      • 目标 handler 执行过程，
      • 成功处理结果记录到 ModelAndView mv，
      • 异常捕获并记录到 Exception dispatchException
    2. 加工handler请求处理结果做出响应（response）

  • 其中步骤 2 由 processDispatchResult 方法完成。

  • 若捕获到异常，将调用 processHandlerException 来将异常转换成 ModelAndView。对于常见的 HTTP 状态码，可能对应多种异常。

    • 在本问题中所出现的400 Bad Request可能对应： Servlet 请求参数缺失、 Servlet 请求处理过程中的绑定异常 、类型不匹配、HTTP 消息不可读、Spring验证框架中的绑定异常等。

  • 补充：

    • 对于参数解析错误，一般都在org.springframework.web.method.support.InvocableHandlerMethod的getMethodArgumentValues方法下发生。

📚问题分析

  • 根据上述信息，找到DispatcherServlet类（位于org.springframework.web.servlet.DispatcherServlet）的processDispatchResult函数，通过断点截获来确定到底是哪种异常被转换成了400 Bad Request状态码。
  • 果不其然，截获后发现了更准确的问题报错：
JSON parse error: Cannot deserialize value of type `com.raysmond.blog.common.models.support.PostType` from String "Post": value not one of declared Enum instance names: [POST, PAGE]
JSON parse error: Cannot deserialize value of type `com.raysmond.blog.common.models.support.PostStatus` from String "Published": value not one of declared Enum instance names: [DRAFT, PUBLISHED]
  • 显然是 Enum 类型变量初始化问题，明确问题后就能直接解决了。
  • 直接调用该函数的 bug 成功解决，然而当通过另一个函数调用时又出现了错误，且所报错误如下（然而该问题所对应的代码已经被修改过了，因此猜测是文件缓存问题）：
JSON parse error: Cannot construct instance of `org.springframework.data.domain.Pageable` (no Creators, like default construct, exist): abstract types either need to be mapped to concrete types, have custom deserializer, or contain additional type information

  • 经过细细的断点调试，发现 ObjectMapper.java 又存在两个版本 2.9.2 和 2.15.2，为排除该干扰，彻底清理 gradle 缓存[5]。

  • 经过更细致地监控（全开 DEBUG 模式），获取以下复杂报错信息（但并没有获得什么更有价值的信息）：

  1. 和 Eureka 通信
2023-09-02 18:57:40.145 [Eureka-JerseyClient-Conn-Cleaner2] DEBUG c.n.d.s.MonitoredConnectionManager - Closing connections idle longer than 30000 SECONDS
2023-09-02 18:57:40.146 [Eureka-JerseyClient-Conn-Cleaner2] DEBUG c.n.d.shared.NamedConnectionPool - Closing connections idle longer than 30000 SECONDS
2023-09-02 18:57:40.153 [Eureka-JerseyClient-Conn-Cleaner2] DEBUG c.n.d.s.MonitoredConnectionManager - Closing connections idle longer than -1 SECONDS
2023-09-02 18:57:40.153 [Eureka-JerseyClient-Conn-Cleaner2] DEBUG c.n.d.shared.NamedConnectionPool - Closing connections idle longer than 0 SECONDS
  1. 获取请求
2023-09-02 18:57:40.168 [HikariPool-1 housekeeper] DEBUG c.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Pool stats (total=10, active=0, idle=10, waiting=0)
2023-09-02 18:57:46.446 [qtp1864548849-44-acceptor-0@750e313c-ServerConnector@7de2bdc7{HTTP/1.1,[http/1.1]}{0.0.0.0:8051}] DEBUG o.e.jetty.io.ManagedSelector - Queued change org.eclipse.jetty.io.ManagedSelector$Accept@ec53d19 on org.eclipse.jetty.io.ManagedSelector@79753f20 id=0 keys=1 selected=0
2023-09-02 18:57:46.447 [qtp1864548849-46] DEBUG o.e.jetty.io.ManagedSelector - Selector loop woken up from select, 0/1 selected
2023-09-02 18:57:46.447 [qtp1864548849-46] DEBUG o.e.jetty.io.ManagedSelector - Running action org.eclipse.jetty.io.ManagedSelector$Accept@ec53d19
2023-09-02 18:57:46.447 [qtp1864548849-46] DEBUG o.e.jetty.io.ManagedSelector - Queued change org.eclipse.jetty.io.ManagedSelector$CreateEndPoint@7184b93e on org.eclipse.jetty.io.ManagedSelector@79753f20 id=0 keys=2 selected=0
2023-09-02 18:57:46.447 [qtp1864548849-46] DEBUG o.e.jetty.io.ManagedSelector - Running action org.eclipse.jetty.io.ManagedSelector$CreateEndPoint@7184b93e
2023-09-02 18:57:46.447 [qtp1864548849-46] DEBUG org.eclipse.jetty.io.IdleTimeout - SocketChannelEndPoint@5315f828{/100.64.188.184:55553<->/100.64.188.184:8051,OPEN,fill=-,flush=-,to=0/30000}{io=0/0,kio=0,kro=0}-><null> idle timeout check, elapsed: 0 ms, remaining: 30000 ms
2023-09-02 18:57:46.448 [qtp1864548849-46] DEBUG o.e.jetty.io.AbstractEndPoint - onOpen SocketChannelEndPoint@5315f828{/100.64.188.184:55553<->/100.64.188.184:8051,OPEN,fill=-,flush=-,to=1/30000}{io=0/0,kio=0,kro=0}-><null>
2023-09-02 18:57:46.449 [qtp1864548849-46] DEBUG o.e.jetty.server.HttpChannel - new HttpChannelOverHttp@38fffb8{r=0,c=false,a=IDLE,uri=null} -> SocketChannelEndPoint@5315f828{/100.64.188.184:55553<->/100.64.188.184:8051,OPEN,fill=-,flush=-,to=2/30000}{io=0/0,kio=0,kro=0}-><null>,null,HttpChannelState@5716ebbe{s=IDLE a=NOT_ASYNC i=true r=IDLE w=false}
2023-09-02 18:57:46.449 [qtp1864548849-46] DEBUG o.e.jetty.server.HttpConnection - New HTTP Connection HttpConnection@2b3e8dcc[p=HttpParser{s=START,0 of 0},g=HttpGenerator@d6ee9c8{s=START}]=>HttpChannelOverHttp@38fffb8{r=0,c=false,a=IDLE,uri=null}<-SocketChannelEndPoint@5315f828{/100.64.188.184:55553<->/100.64.188.184:8051,OPEN,fill=-,flush=-,to=2/30000}{io=0/0,kio=0,kro=0}-><null>
2023-09-02 18:57:46.449 [qtp1864548849-46] DEBUG o.e.jetty.io.AbstractConnection - onOpen HttpConnection@2b3e8dcc[p=HttpParser{s=START,0 of 0},g=HttpGenerator@d6ee9c8{s=START}]=>HttpChannelOverHttp@38fffb8{r=0,c=false,a=IDLE,uri=null}<-SocketChannelEndPoint@5315f828{/100.64.188.184:55553<->/100.64.188.184:8051,OPEN,fill=-,flush=-,to=2/30000}{io=0/0,kio=0,kro=0}->HttpConnection@2b3e8dcc[p=HttpParser{s=START,0 of 0},g=HttpGenerator@d6ee9c8{s=START}]=>HttpChannelOverHttp@38fffb8{r=0,c=false,a=IDLE,uri=null}
2023-09-02 18:57:46.449 [qtp1864548849-46] DEBUG o.e.jetty.io.AbstractConnection - fillInterested HttpConnection@2b3e8dcc[p=HttpParser{s=START,0 of 0},g=HttpGenerator@d6ee9c8{s=START}]=>HttpChannelOverHttp@38fffb8{r=0,c=false,a=IDLE,uri=null}<-SocketChannelEndPoint@5315f828{/100.64.188.184:55553<->/100.64.188.184:8051,OPEN,fill=-,flush=-,to=2/30000}{io=0/0,kio=0,kro=0}->HttpConnection@2b3e8dcc[p=HttpParser{s=START,0 of 0},g=HttpGenerator@d6ee9c8{s=START}]=>HttpChannelOverHttp@38fffb8{r=0,c=false,a=IDLE,uri=null}
2023-09-02 18:57:46.450 [qtp1864548849-46] DEBUG o.eclipse.jetty.io.FillInterest - interested FillInterest@71e0a5e2{AC.ReadCB@2b3e8dcc{HttpConnection@2b3e8dcc[p=HttpParser{s=START,0 of 0},g=HttpGenerator@d6ee9c8{s=START}]=>HttpChannelOverHttp@38fffb8{r=0,c=false,a=IDLE,uri=null}<-SocketChannelEndPoint@5315f828{/100.64.188.184:55553<->/100.64.188.184:8051,OPEN,fill=FI,flush=-,to=1/30000}{io=0/0,kio=0,kro=0}->HttpConnection@2b3e8dcc[p=HttpParser{s=START,0 of 0},g=HttpGenerator@d6ee9c8{s=START}]=>HttpChannelOverHttp@38fffb8{r=0,c=false,a=IDLE,uri=null}}}
2023-09-02 18:57:46.450 [qtp1864548849-46] DEBUG o.e.jetty.io.ChannelEndPoint - changeInterests p=false 0->1 for SocketChannelEndPoint@5315f828{/100.64.188.184:55553<->/100.64.188.184:8051,OPEN,fill=FI,flush=-,to=1/30000}{io=0/1,kio=0,kro=0}->HttpConnection@2b3e8dcc[p=HttpParser{s=START,0 of 0},g=HttpGenerator@d6ee9c8{s=START}]=>HttpChannelOverHttp@38fffb8{r=0,c=false,a=IDLE,uri=null}
2023-09-02 18:57:46.450 [qtp1864548849-46] DEBUG o.e.jetty.io.ManagedSelector - Queued change CEP:SocketChannelEndPoint@5315f828{/100.64.188.184:55553<->/100.64.188.184:8051,OPEN,fill=FI,flush=-,to=1/30000}{io=0/1,kio=0,kro=0}->HttpConnection@2b3e8dcc[p=HttpParser{s=START,0 of 0},g=HttpGenerator@d6ee9c8{s=START}]=>HttpChannelOverHttp@38fffb8{r=0,c=false,a=IDLE,uri=null}:runUpdateKey:NON_BLOCKING on org.eclipse.jetty.io.ManagedSelector@79753f20 id=0 keys=2 selected=0
2023-09-02 18:57:46.450 [qtp1864548849-46] DEBUG o.e.jetty.io.ManagedSelector - Created SocketChannelEndPoint@5315f828{/100.64.188.184:55553<->/100.64.188.184:8051,OPEN,fill=FI,flush=-,to=1/30000}{io=0/1,kio=0,kro=0}->HttpConnection@2b3e8dcc[p=HttpParser{s=START,0 of 0},g=HttpGenerator@d6ee9c8{s=START}]=>HttpChannelOverHttp@38fffb8{r=0,c=false,a=IDLE,uri=null}
2023-09-02 18:57:46.451 [qtp1864548849-46] DEBUG o.e.jetty.io.ManagedSelector - Running action CEP:SocketChannelEndPoint@5315f828{/100.64.188.184:55553<->/100.64.188.184:8051,OPEN,fill=FI,flush=-,to=1/30000}{io=0/1,kio=0,kro=0}->HttpConnection@2b3e8dcc[p=HttpParser{s=START,0 of 0},g=HttpGenerator@d6ee9c8{s=START}]=>HttpChannelOverHttp@38fffb8{r=0,c=false,a=IDLE,uri=null}:runUpdateKey:NON_BLOCKING
2023-09-02 18:57:46.451 [qtp1864548849-46] DEBUG o.e.jetty.io.ChannelEndPoint - Key interests updated 0 -> 1 on SocketChannelEndPoint@5315f828{/100.64.188.184:55553<->/100.64.188.184:8051,OPEN,fill=FI,flush=-,to=2/30000}{io=1/1,kio=1,kro=0}->HttpConnection@2b3e8dcc[p=HttpParser{s=START,0 of 0},g=HttpGenerator@d6ee9c8{s=START}]=>HttpChannelOverHttp@38fffb8{r=0,c=false,a=IDLE,uri=null}
2023-09-02 18:57:46.451 [qtp1864548849-46] DEBUG o.e.jetty.io.ManagedSelector - Selector loop waiting on select
2023-09-02 18:57:46.451 [qtp1864548849-46] DEBUG o.e.jetty.io.ManagedSelector - Selector loop woken up from select, 1/2 selected
2023-09-02 18:57:46.451 [qtp1864548849-46] DEBUG o.e.jetty.io.ManagedSelector - selected sun.nio.ch.SelectionKeyImpl@48f41b4e SocketChannelEndPoint@5315f828{/100.64.188.184:55553<->/100.64.188.184:8051,OPEN,fill=FI,flush=-,to=2/30000}{io=1/1,kio=1,kro=1}->HttpConnection@2b3e8dcc[p=HttpParser{s=START,0 of 0},g=HttpGenerator@d6ee9c8{s=START}]=>HttpChannelOverHttp@38fffb8{r=0,c=false,a=IDLE,uri=null} 
2023-09-02 18:57:46.451 [qtp1864548849-46] DEBUG o.e.jetty.io.ChannelEndPoint - onSelected 1->0 r=true w=false for SocketChannelEndPoint@5315f828{/100.64.188.184:55553<->/100.64.188.184:8051,OPEN,fill=FI,flush=-,to=2/30000}{io=1/0,kio=1,kro=1}->HttpConnection@2b3e8dcc[p=HttpParser{s=START,0 of 0},g=HttpGenerator@d6ee9c8{s=START}]=>HttpChannelOverHttp@38fffb8{r=0,c=false,a=IDLE,uri=null}
2023-09-02 18:57:46.451 [qtp1864548849-46] DEBUG o.e.jetty.io.ChannelEndPoint - task CEP:SocketChannelEndPoint@5315f828{/100.64.188.184:55553<->/100.64.188.184:8051,OPEN,fill=FI,flush=-,to=2/30000}{io=1/0,kio=1,kro=1}->HttpConnection@2b3e8dcc[p=HttpParser{s=START,0 of 0},g=HttpGenerator@d6ee9c8{s=START}]=>HttpChannelOverHttp@38fffb8{r=0,c=false,a=IDLE,uri=null}:runFillable:BLOCKING
2023-09-02 18:57:46.452 [qtp1864548849-46] DEBUG o.e.j.u.t.s.EatWhatYouKill - EatWhatYouKill@7b3489b7/SelectorProducer@33317d26/PRODUCING/org.eclipse.jetty.util.thread.ReservedThreadExecutor@2e46ffd5{s=2,p=0} t=CEP:SocketChannelEndPoint@5315f828{/100.64.188.184:55553<->/100.64.188.184:8051,OPEN,fill=FI,flush=-,to=2/30000}{io=1/0,kio=1,kro=1}->HttpConnection@2b3e8dcc[p=HttpParser{s=START,0 of 0},g=HttpGenerator@d6ee9c8{s=START}]=>HttpChannelOverHttp@38fffb8{r=0,c=false,a=IDLE,uri=null}:runFillable:BLOCKING/BLOCKING
2023-09-02 18:57:46.452 [qtp1864548849-46] DEBUG o.e.j.u.t.s.EatWhatYouKill - EatWhatYouKill@7b3489b7/SelectorProducer@33317d26/IDLE/org.eclipse.jetty.util.thread.ReservedThreadExecutor@2e46ffd5{s=1,p=0} EPC t=CEP:SocketChannelEndPoint@5315f828{/100.64.188.184:55553<->/100.64.188.184:8051,OPEN,fill=FI,flush=-,to=3/30000}{io=1/0,kio=1,kro=1}->HttpConnection@2b3e8dcc[p=HttpParser{s=START,0 of 0},g=HttpGenerator@d6ee9c8{s=START}]=>HttpChannelOverHttp@38fffb8{r=0,c=false,a=IDLE,uri=null}:runFillable:BLOCKING
2023-09-02 18:57:46.452 [qtp1864548849-50] DEBUG o.e.j.u.t.ReservedThreadExecutor - org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread@22afa967 woken up
2023-09-02 18:57:46.452 [qtp1864548849-50] DEBUG o.e.j.u.t.s.EatWhatYouKill - EatWhatYouKill@7b3489b7/SelectorProducer@33317d26/IDLE/org.eclipse.jetty.util.thread.ReservedThreadExecutor@2e46ffd5{s=1,p=0} run
2023-09-02 18:57:46.452 [qtp1864548849-46] DEBUG o.eclipse.jetty.io.FillInterest - fillable FillInterest@71e0a5e2{AC.ReadCB@2b3e8dcc{HttpConnection@2b3e8dcc[p=HttpParser{s=START,0 of 0},g=HttpGenerator@d6ee9c8{s=START}]=>HttpChannelOverHttp@38fffb8{r=0,c=false,a=IDLE,uri=null}<-SocketChannelEndPoint@5315f828{/100.64.188.184:55553<->/100.64.188.184:8051,OPEN,fill=FI,flush=-,to=3/30000}{io=1/0,kio=1,kro=1}->HttpConnection@2b3e8dcc[p=HttpParser{s=START,0 of 0},g=HttpGenerator@d6ee9c8{s=START}]=>HttpChannelOverHttp@38fffb8{r=0,c=false,a=IDLE,uri=null}}}
2023-09-02 18:57:46.452 [qtp1864548849-50] DEBUG o.e.j.u.t.s.EatWhatYouKill - EatWhatYouKill@7b3489b7/SelectorProducer@33317d26/IDLE/org.eclipse.jetty.util.thread.ReservedThreadExecutor@2e46ffd5{s=1,p=0} produce
2023-09-02 18:57:46.458 [qtp1864548849-50] DEBUG o.e.jetty.io.ChannelEndPoint - Key interests updated 1 -> 0 on SocketChannelEndPoint@5315f828{/100.64.188.184:55553<->/100.64.188.184:8051,OPEN,fill=-,flush=-,to=3/30000}{io=0/0,kio=0,kro=1}->HttpConnection@2b3e8dcc[p=HttpParser{s=START,0 of 0},g=HttpGenerator@d6ee9c8{s=START}]=>HttpChannelOverHttp@38fffb8{r=0,c=false,a=IDLE,uri=null}
2023-09-02 18:57:46.458 [qtp1864548849-46] DEBUG o.e.jetty.server.HttpConnection - HttpConnection@2b3e8dcc[p=HttpParser{s=START,0 of 0},g=HttpGenerator@d6ee9c8{s=START}]=>HttpChannelOverHttp@38fffb8{r=0,c=false,a=IDLE,uri=null}<-SocketChannelEndPoint@5315f828{/100.64.188.184:55553<->/100.64.188.184:8051,OPEN,fill=-,flush=-,to=3/30000}{io=0/0,kio=0,kro=1}->HttpConnection@2b3e8dcc[p=HttpParser{s=START,0 of 0},g=HttpGenerator@d6ee9c8{s=START}]=>HttpChannelOverHttp@38fffb8{r=0,c=false,a=IDLE,uri=null} onFillable enter HttpChannelState@5716ebbe{s=IDLE a=NOT_ASYNC i=true r=IDLE w=false} null
2023-09-02 18:57:46.458 [qtp1864548849-50] DEBUG o.e.jetty.io.ManagedSelector - Selector loop waiting on select
  1. 初步处理请求信息
2023-09-02 18:57:46.464 [qtp1864548849-46] DEBUG o.e.jetty.io.ChannelEndPoint - filled 579 SocketChannelEndPoint@5315f828{/100.64.188.184:55553<->/100.64.188.184:8051,OPEN,fill=-,flush=-,to=12/30000}{io=0/0,kio=0,kro=1}->HttpConnection@2b3e8dcc[p=HttpParser{s=START,0 of 0},g=HttpGenerator@d6ee9c8{s=START}]=>HttpChannelOverHttp@38fffb8{r=0,c=false,a=IDLE,uri=null}
2023-09-02 18:57:46.466 [qtp1864548849-46] DEBUG o.e.jetty.server.HttpConnection - HttpConnection@2b3e8dcc[p=HttpParser{s=START,0 of 0},g=HttpGenerator@d6ee9c8{s=START}]=>HttpChannelOverHttp@38fffb8{r=0,c=false,a=IDLE,uri=null}<-SocketChannelEndPoint@5315f828{/100.64.188.184:55553<->/100.64.188.184:8051,OPEN,fill=-,flush=-,to=2/30000}{io=0/0,kio=0,kro=1}->HttpConnection@2b3e8dcc[p=HttpParser{s=START,0 of 0},g=HttpGenerator@d6ee9c8{s=START}]=>HttpChannelOverHttp@38fffb8{r=0,c=false,a=IDLE,uri=null} filled 579 HeapByteBuffer@77409e4b[p=0,l=579,c=8192,r=579]={<<<POST /PostReposit...:5,"offset":0}}>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
2023-09-02 18:57:46.467 [qtp1864548849-46] DEBUG o.e.jetty.server.HttpConnection - HttpConnection@2b3e8dcc[p=HttpParser{s=START,0 of 0},g=HttpGenerator@d6ee9c8{s=START}]=>HttpChannelOverHttp@38fffb8{r=0,c=false,a=IDLE,uri=null}<-SocketChannelEndPoint@5315f828{/100.64.188.184:55553<->/100.64.188.184:8051,OPEN,fill=-,flush=-,to=3/30000}{io=0/0,kio=0,kro=1}->HttpConnection@2b3e8dcc[p=HttpParser{s=START,0 of 0},g=HttpGenerator@d6ee9c8{s=START}]=>HttpChannelOverHttp@38fffb8{r=0,c=false,a=IDLE,uri=null} parse HeapByteBuffer@77409e4b[p=0,l=579,c=8192,r=579]={<<<POST /PostReposit...:5,"offset":0}}>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00} {}
2023-09-02 18:57:46.467 [qtp1864548849-46] DEBUG o.eclipse.jetty.http.HttpParser - parseNext s=START HeapByteBuffer@77409e4b[p=0,l=579,c=8192,r=579]={<<<POST /PostReposit...:5,"offset":0}}>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
2023-09-02 18:57:46.467 [qtp1864548849-46] DEBUG o.eclipse.jetty.http.HttpParser - START --> SPACE1
2023-09-02 18:57:46.467 [qtp1864548849-46] DEBUG o.eclipse.jetty.http.HttpParser - SPACE1 --> URI
2023-09-02 18:57:46.467 [qtp1864548849-46] DEBUG o.eclipse.jetty.http.HttpParser - URI --> SPACE2
2023-09-02 18:57:46.467 [qtp1864548849-46] DEBUG o.eclipse.jetty.http.HttpParser - SPACE2 --> REQUEST_VERSION
2023-09-02 18:57:46.467 [qtp1864548849-46] DEBUG o.eclipse.jetty.http.HttpParser - REQUEST_VERSION --> HEADER
2023-09-02 18:57:46.467 [qtp1864548849-46] DEBUG o.eclipse.jetty.http.HttpParser - HEADER:null --> VALUE
2023-09-02 18:57:46.467 [qtp1864548849-46] DEBUG o.eclipse.jetty.http.HttpParser - HEADER:null --> IN_VALUE
2023-09-02 18:57:46.468 [qtp1864548849-46] DEBUG o.eclipse.jetty.http.HttpParser - HEADER:null --> FIELD
2023-09-02 18:57:46.468 [qtp1864548849-46] DEBUG o.eclipse.jetty.http.HttpParser - HEADER:null --> VALUE
2023-09-02 18:57:46.468 [qtp1864548849-46] DEBUG o.eclipse.jetty.http.HttpParser - HEADER:null --> IN_VALUE
2023-09-02 18:57:46.468 [qtp1864548849-46] DEBUG o.eclipse.jetty.http.HttpParser - HEADER:null --> FIELD
2023-09-02 18:57:46.468 [qtp1864548849-46] DEBUG o.eclipse.jetty.http.HttpParser - HEADER:null --> VALUE
2023-09-02 18:57:46.468 [qtp1864548849-46] DEBUG o.eclipse.jetty.http.HttpParser - HEADER:null --> IN_VALUE
2023-09-02 18:57:46.468 [qtp1864548849-46] DEBUG o.eclipse.jetty.http.HttpParser - HEADER:null --> FIELD
2023-09-02 18:57:46.468 [qtp1864548849-46] DEBUG o.eclipse.jetty.http.HttpParser - HEADER:Accept: */* --> IN_VALUE
2023-09-02 18:57:46.468 [qtp1864548849-46] DEBUG o.eclipse.jetty.http.HttpParser - HEADER:Accept: */* --> FIELD
2023-09-02 18:57:46.468 [qtp1864548849-46] DEBUG o.eclipse.jetty.http.HttpParser - HEADER:Content-Type: application/json --> IN_VALUE
2023-09-02 18:57:46.468 [qtp1864548849-46] DEBUG o.eclipse.jetty.http.HttpParser - HEADER:Content-Type: application/json --> FIELD
2023-09-02 18:57:46.468 [qtp1864548849-46] DEBUG o.eclipse.jetty.http.HttpParser - HEADER:Accept-Encoding: gzip --> IN_VALUE
2023-09-02 18:57:46.468 [qtp1864548849-46] DEBUG o.eclipse.jetty.http.HttpParser - HEADER:Accept-Encoding: gzip --> FIELD
2023-09-02 18:57:46.468 [qtp1864548849-46] DEBUG o.eclipse.jetty.http.HttpParser - HEADER --> CONTENT
2023-09-02 18:57:46.469 [qtp1864548849-46] DEBUG o.e.jetty.server.HttpChannel - REQUEST for //100.64.188.184:8051/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted on HttpChannelOverHttp@38fffb8{r=1,c=false,a=IDLE,uri=//100.64.188.184:8051/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted}
POST //100.64.188.184:8051/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted HTTP/1.1
Host: 100.64.188.184:8051
User-Agent: Java/1.8.0_271
Content-Length: 351
Accept: */*
Content-Type: application/json
Accept-Encoding: gzip
2023-09-02 18:57:46.469 [qtp1864548849-46] DEBUG o.e.jetty.server.HttpConnection - HttpConnection@2b3e8dcc[p=HttpParser{s=CONTENT,0 of 351},g=HttpGenerator@d6ee9c8{s=START}]=>HttpChannelOverHttp@38fffb8{r=1,c=false,a=IDLE,uri=//100.64.188.184:8051/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted}<-SocketChannelEndPoint@5315f828{/100.64.188.184:55553<->/100.64.188.184:8051,OPEN,fill=-,flush=-,to=5/30000}{io=0/0,kio=0,kro=1}->HttpConnection@2b3e8dcc[p=HttpParser{s=CONTENT,0 of 351},g=HttpGenerator@d6ee9c8{s=START}]=>HttpChannelOverHttp@38fffb8{r=1,c=false,a=IDLE,uri=//100.64.188.184:8051/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted} parsed true HttpParser{s=CONTENT,0 of 351}
2023-09-02 18:57:46.469 [qtp1864548849-46] DEBUG o.e.jetty.server.HttpChannel - HttpChannelOverHttp@38fffb8{r=1,c=false,a=IDLE,uri=//100.64.188.184:8051/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted} handle //100.64.188.184:8051/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted 
2023-09-02 18:57:46.469 [qtp1864548849-46] DEBUG o.e.j.server.HttpChannelState - handling HttpChannelState@5716ebbe{s=IDLE a=NOT_ASYNC i=true r=IDLE w=false}
2023-09-02 18:57:46.469 [qtp1864548849-46] DEBUG o.e.jetty.server.HttpChannel - HttpChannelOverHttp@38fffb8{r=1,c=false,a=DISPATCHED,uri=//100.64.188.184:8051/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted} action DISPATCH
2023-09-02 18:57:46.469 [qtp1864548849-46] DEBUG org.eclipse.jetty.server.Server - REQUEST POST /PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted on HttpChannelOverHttp@38fffb8{r=1,c=false,a=DISPATCHED,uri=//100.64.188.184:8051/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted}
2023-09-02 18:57:46.470 [qtp1864548849-46] DEBUG o.e.j.s.handler.ContextHandler - scope null||/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted @ o.s.b.c.e.j.JettyEmbeddedWebAppContext@1d008e61{/,[file:///private/var/folders/sg/fcqtq3fx50b9tfz0jmw8jh3m0000gq/T/jetty-docbase.8868443885322920717.8051/],AVAILABLE}
2023-09-02 18:57:46.470 [qtp1864548849-46] DEBUG o.e.j.s.handler.ContextHandler - context=||/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted @ o.s.b.c.e.j.JettyEmbeddedWebAppContext@1d008e61{/,[file:///private/var/folders/sg/fcqtq3fx50b9tfz0jmw8jh3m0000gq/T/jetty-docbase.8868443885322920717.8051/],AVAILABLE}
2023-09-02 18:57:46.470 [qtp1864548849-46] DEBUG org.eclipse.jetty.server.session - sessionHandler=org.eclipse.jetty.server.session.SessionHandler421217482==dftMaxIdleSec=1800
2023-09-02 18:57:46.470 [qtp1864548849-46] DEBUG org.eclipse.jetty.server.session - session=null
  1. 匹配请求
2023-09-02 18:57:46.470 [qtp1864548849-46] DEBUG o.e.jetty.servlet.ServletHandler - servlet |/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted|null -> dispatcherServlet@7ef5559e==org.springframework.web.servlet.DispatcherServlet,jsp=null,order=-1,inst=true
2023-09-02 18:57:46.470 [qtp1864548849-46] DEBUG o.e.jetty.servlet.ServletHandler - chain=characterEncodingFilter->hiddenHttpMethodFilter->httpPutFormContentFilter->requestContextFilter->springSecurityFilterChain->Jetty_WebSocketUpgradeFilter->dispatcherServlet@7ef5559e==org.springframework.web.servlet.DispatcherServlet,jsp=null,order=-1,inst=true
2023-09-02 18:57:46.470 [qtp1864548849-46] DEBUG o.e.jetty.servlet.ServletHandler - call filter characterEncodingFilter
2023-09-02 18:57:46.470 [qtp1864548849-46] DEBUG o.e.jetty.servlet.ServletHandler - call filter hiddenHttpMethodFilter
2023-09-02 18:57:46.471 [qtp1864548849-46] DEBUG o.e.jetty.servlet.ServletHandler - call filter httpPutFormContentFilter
2023-09-02 18:57:46.471 [qtp1864548849-46] DEBUG o.e.jetty.servlet.ServletHandler - call filter requestContextFilter
2023-09-02 18:57:46.471 [qtp1864548849-46] DEBUG o.s.b.w.f.OrderedRequestContextFilter - Bound request context to thread: Request(POST //100.64.188.184:8051/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted)@114beb7b
2023-09-02 18:57:46.471 [qtp1864548849-46] DEBUG o.e.jetty.servlet.ServletHandler - call filter springSecurityFilterChain
2023-09-02 18:57:46.471 [qtp1864548849-46] DEBUG o.s.s.w.u.m.OrRequestMatcher - Trying to match using Ant [pattern='/css/**']
2023-09-02 18:57:46.471 [qtp1864548849-46] DEBUG o.s.s.w.u.m.AntPathRequestMatcher - Checking match of request : '/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted'; against '/css/**'
2023-09-02 18:57:46.471 [qtp1864548849-46] DEBUG o.s.s.w.u.m.OrRequestMatcher - Trying to match using Ant [pattern='/js/**']
2023-09-02 18:57:46.471 [qtp1864548849-46] DEBUG o.s.s.w.u.m.AntPathRequestMatcher - Checking match of request : '/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted'; against '/js/**'
2023-09-02 18:57:46.471 [qtp1864548849-46] DEBUG o.s.s.w.u.m.OrRequestMatcher - Trying to match using Ant [pattern='/images/**']
2023-09-02 18:57:46.471 [qtp1864548849-46] DEBUG o.s.s.w.u.m.AntPathRequestMatcher - Checking match of request : '/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted'; against '/images/**'
2023-09-02 18:57:46.471 [qtp1864548849-46] DEBUG o.s.s.w.u.m.OrRequestMatcher - Trying to match using Ant [pattern='/webjars/**']
2023-09-02 18:57:46.471 [qtp1864548849-46] DEBUG o.s.s.w.u.m.AntPathRequestMatcher - Checking match of request : '/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted'; against '/webjars/**'
2023-09-02 18:57:46.471 [qtp1864548849-46] DEBUG o.s.s.w.u.m.OrRequestMatcher - Trying to match using Ant [pattern='/**/favicon.ico']
2023-09-02 18:57:46.471 [qtp1864548849-46] DEBUG o.s.s.w.u.m.AntPathRequestMatcher - Checking match of request : '/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted'; against '/**/favicon.ico'
2023-09-02 18:57:46.471 [qtp1864548849-46] DEBUG o.s.s.w.u.m.OrRequestMatcher - Trying to match using Ant [pattern='/error']
2023-09-02 18:57:46.471 [qtp1864548849-46] DEBUG o.s.s.w.u.m.AntPathRequestMatcher - Checking match of request : '/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted'; against '/error'
2023-09-02 18:57:46.471 [qtp1864548849-46] DEBUG o.s.s.w.u.m.OrRequestMatcher - No matches found
2023-09-02 18:57:46.471 [qtp1864548849-46] DEBUG o.s.s.web.FilterChainProxy - /PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted at position 1 of 10 in additional filter chain; firing Filter: 'WebAsyncManagerIntegrationFilter'
2023-09-02 18:57:46.471 [qtp1864548849-46] DEBUG o.s.s.web.FilterChainProxy - /PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted at position 2 of 10 in additional filter chain; firing Filter: 'SecurityContextPersistenceFilter'
2023-09-02 18:57:46.471 [qtp1864548849-46] DEBUG o.s.s.w.c.HttpSessionSecurityContextRepository - No HttpSession currently exists
2023-09-02 18:57:46.471 [qtp1864548849-46] DEBUG o.s.s.w.c.HttpSessionSecurityContextRepository - No SecurityContext was available from the HttpSession: null. A new one will be created.
2023-09-02 18:57:46.471 [qtp1864548849-46] DEBUG o.s.s.web.FilterChainProxy - /PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted at position 3 of 10 in additional filter chain; firing Filter: 'HeaderWriterFilter'
2023-09-02 18:57:46.472 [qtp1864548849-46] DEBUG o.s.s.w.h.w.HstsHeaderWriter - Not injecting HSTS header since it did not match the requestMatcher org.springframework.security.web.header.writers.HstsHeaderWriter$SecureRequestMatcher@4325f834
2023-09-02 18:57:46.472 [qtp1864548849-46] DEBUG o.s.s.web.FilterChainProxy - /PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted at position 4 of 10 in additional filter chain; firing Filter: 'LogoutFilter'
2023-09-02 18:57:46.472 [qtp1864548849-46] DEBUG o.s.s.w.u.m.OrRequestMatcher - Trying to match using Ant [pattern='/logout', GET]
2023-09-02 18:57:46.472 [qtp1864548849-46] DEBUG o.s.s.w.u.m.AntPathRequestMatcher - Request 'POST /PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted' doesn't match 'GET /logout
2023-09-02 18:57:46.472 [qtp1864548849-46] DEBUG o.s.s.w.u.m.OrRequestMatcher - Trying to match using Ant [pattern='/logout', POST]
2023-09-02 18:57:46.472 [qtp1864548849-46] DEBUG o.s.s.w.u.m.AntPathRequestMatcher - Checking match of request : '/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted'; against '/logout'
2023-09-02 18:57:46.472 [qtp1864548849-46] DEBUG o.s.s.w.u.m.OrRequestMatcher - Trying to match using Ant [pattern='/logout', PUT]
2023-09-02 18:57:46.472 [qtp1864548849-46] DEBUG o.s.s.w.u.m.AntPathRequestMatcher - Request 'POST /PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted' doesn't match 'PUT /logout
2023-09-02 18:57:46.472 [qtp1864548849-46] DEBUG o.s.s.w.u.m.OrRequestMatcher - Trying to match using Ant [pattern='/logout', DELETE]
2023-09-02 18:57:46.472 [qtp1864548849-46] DEBUG o.s.s.w.u.m.AntPathRequestMatcher - Request 'POST /PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted' doesn't match 'DELETE /logout
2023-09-02 18:57:46.472 [qtp1864548849-46] DEBUG o.s.s.w.u.m.OrRequestMatcher - No matches found
2023-09-02 18:57:46.472 [qtp1864548849-46] DEBUG o.s.s.web.FilterChainProxy - /PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted at position 5 of 10 in additional filter chain; firing Filter: 'RequestCacheAwareFilter'
2023-09-02 18:57:46.472 [qtp1864548849-46] DEBUG o.s.s.web.FilterChainProxy - /PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted at position 6 of 10 in additional filter chain; firing Filter: 'SecurityContextHolderAwareRequestFilter'
2023-09-02 18:57:46.472 [qtp1864548849-46] DEBUG o.s.s.web.FilterChainProxy - /PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted at position 7 of 10 in additional filter chain; firing Filter: 'AnonymousAuthenticationFilter'
2023-09-02 18:57:46.472 [qtp1864548849-46] DEBUG o.s.s.w.a.AnonymousAuthenticationFilter - Populated SecurityContextHolder with anonymous token: 'org.springframework.security.authentication.AnonymousAuthenticationToken@6faab5ec: Principal: anonymousUser; Credentials: [PROTECTED]; Authenticated: true; Details: org.springframework.security.web.authentication.WebAuthenticationDetails@ffffc434: RemoteIpAddress: 100.64.188.184; SessionId: null; Granted Authorities: ROLE_ANONYMOUS'
2023-09-02 18:57:46.472 [qtp1864548849-46] DEBUG o.s.s.web.FilterChainProxy - /PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted at position 8 of 10 in additional filter chain; firing Filter: 'SessionManagementFilter'
2023-09-02 18:57:46.472 [qtp1864548849-46] DEBUG o.s.s.web.FilterChainProxy - /PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted at position 9 of 10 in additional filter chain; firing Filter: 'ExceptionTranslationFilter'
2023-09-02 18:57:46.472 [qtp1864548849-46] DEBUG o.s.s.web.FilterChainProxy - /PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted at position 10 of 10 in additional filter chain; firing Filter: 'FilterSecurityInterceptor'
2023-09-02 18:57:46.472 [qtp1864548849-46] DEBUG o.s.s.w.u.m.OrRequestMatcher - Trying to match using Ant [pattern='/logout', GET]
2023-09-02 18:57:46.472 [qtp1864548849-46] DEBUG o.s.s.w.u.m.AntPathRequestMatcher - Request 'POST /PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted' doesn't match 'GET /logout
2023-09-02 18:57:46.472 [qtp1864548849-46] DEBUG o.s.s.w.u.m.OrRequestMatcher - Trying to match using Ant [pattern='/logout', POST]
2023-09-02 18:57:46.472 [qtp1864548849-46] DEBUG o.s.s.w.u.m.AntPathRequestMatcher - Checking match of request : '/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted'; against '/logout'
2023-09-02 18:57:46.472 [qtp1864548849-46] DEBUG o.s.s.w.u.m.OrRequestMatcher - Trying to match using Ant [pattern='/logout', PUT]
2023-09-02 18:57:46.472 [qtp1864548849-46] DEBUG o.s.s.w.u.m.AntPathRequestMatcher - Request 'POST /PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted' doesn't match 'PUT /logout
2023-09-02 18:57:46.472 [qtp1864548849-46] DEBUG o.s.s.w.u.m.OrRequestMatcher - Trying to match using Ant [pattern='/logout', DELETE]
2023-09-02 18:57:46.472 [qtp1864548849-46] DEBUG o.s.s.w.u.m.AntPathRequestMatcher - Request 'POST /PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted' doesn't match 'DELETE /logout
2023-09-02 18:57:46.472 [qtp1864548849-46] DEBUG o.s.s.w.u.m.OrRequestMatcher - No matches found
2023-09-02 18:57:46.472 [qtp1864548849-46] DEBUG o.s.s.w.a.i.FilterSecurityInterceptor - Secure object: FilterInvocation: URL: /PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted; Attributes: [permitAll]
2023-09-02 18:57:46.473 [qtp1864548849-46] DEBUG o.s.s.w.a.i.FilterSecurityInterceptor - Previously Authenticated: org.springframework.security.authentication.AnonymousAuthenticationToken@6faab5ec: Principal: anonymousUser; Credentials: [PROTECTED]; Authenticated: true; Details: org.springframework.security.web.authentication.WebAuthenticationDetails@ffffc434: RemoteIpAddress: 100.64.188.184; SessionId: null; Granted Authorities: ROLE_ANONYMOUS
2023-09-02 18:57:46.473 [qtp1864548849-46] DEBUG o.s.s.a.vote.AffirmativeBased - Voter: org.springframework.security.web.access.expression.WebExpressionVoter@78ef6211, returned: 1
2023-09-02 18:57:46.473 [qtp1864548849-46] DEBUG o.s.s.w.a.i.FilterSecurityInterceptor - Authorization successful
2023-09-02 18:57:46.473 [qtp1864548849-46] DEBUG o.s.s.w.a.i.FilterSecurityInterceptor - RunAsManager did not change Authentication object
2023-09-02 18:57:46.474 [qtp1864548849-46] DEBUG o.s.s.web.FilterChainProxy - /PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted reached end of additional filter chain; proceeding with original chain
  1. 处理请求
2023-09-02 18:57:46.474 [qtp1864548849-46] DEBUG o.e.jetty.servlet.ServletHandler - call filter Jetty_WebSocketUpgradeFilter
2023-09-02 18:57:46.474 [qtp1864548849-46] DEBUG o.e.jetty.servlet.ServletHandler - call servlet dispatcherServlet@7ef5559e==org.springframework.web.servlet.DispatcherServlet,jsp=null,order=-1,inst=true
2023-09-02 18:57:46.474 [qtp1864548849-46] DEBUG o.s.w.servlet.DispatcherServlet - DispatcherServlet with name 'dispatcherServlet' processing POST request for [/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted]
2023-09-02 18:57:46.474 [qtp1864548849-46] DEBUG o.s.w.s.m.m.a.RequestMappingHandlerMapping - Looking up handler method for path /PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted
2023-09-02 18:57:46.475 [qtp1864548849-46] DEBUG o.s.w.s.m.m.a.RequestMappingHandlerMapping - Returning handler method [org.springframework.data.domain.Page<com.raysmond.blog.common.models.Post> com.raysmond.blog.microservice1.repositories.controllers.PostRepositoryController.findAllByPostTypeAndPostStatusAndDeleted(com.raysmond.blog.common.models.PostParams)]
2023-09-02 18:57:46.475 [qtp1864548849-46] DEBUG o.s.b.f.s.DefaultListableBeanFactory - Returning cached instance of singleton bean 'postRepositoryController'
2023-09-02 18:57:46.475 [qtp1864548849-46] DEBUG o.s.o.j.s.OpenEntityManagerInViewInterceptor - Opening JPA EntityManager in OpenEntityManagerInViewInterceptor
2023-09-02 18:57:46.479 [qtp1864548849-46] DEBUG o.e.jetty.server.HttpConnection - HttpConnection@2b3e8dcc[p=HttpParser{s=CONTENT,0 of 351},g=HttpGenerator@d6ee9c8{s=START}]=>HttpChannelOverHttp@38fffb8{r=1,c=false,a=DISPATCHED,uri=//100.64.188.184:8051/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted}<-SocketChannelEndPoint@5315f828{/100.64.188.184:55553<->/100.64.188.184:8051,OPEN,fill=-,flush=-,to=15/30000}{io=0/0,kio=0,kro=1}->HttpConnection@2b3e8dcc[p=HttpParser{s=CONTENT,0 of 351},g=HttpGenerator@d6ee9c8{s=START}]=>HttpChannelOverHttp@38fffb8{r=1,c=false,a=DISPATCHED,uri=//100.64.188.184:8051/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted} parse HeapByteBuffer@77409e4b[p=228,l=579,c=8192,r=351]={POST /PostReposit...oding: gzip\r\n\r\n<<<{"tag":"tag","pos...:5,"offset":0}}>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00} {}
2023-09-02 18:57:46.479 [qtp1864548849-46] DEBUG o.eclipse.jetty.http.HttpParser - parseNext s=CONTENT HeapByteBuffer@77409e4b[p=228,l=579,c=8192,r=351]={POST /PostReposit...oding: gzip\r\n\r\n<<<{"tag":"tag","pos...:5,"offset":0}}>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
2023-09-02 18:57:46.479 [qtp1864548849-46] DEBUG o.e.jetty.server.HttpChannel - HttpChannelOverHttp@38fffb8{r=1,c=false,a=DISPATCHED,uri=//100.64.188.184:8051/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted} onContent Content@4e445473{HeapByteBufferR@341ed4da[p=228,l=579,c=8192,r=351]={POST /PostReposit...oding: gzip\r\n\r\n<<<{"tag":"tag","pos...:5,"offset":0}}>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}}
2023-09-02 18:57:46.479 [qtp1864548849-46] DEBUG o.eclipse.jetty.server.HttpInput - HttpInputOverHTTP@4025a80e[c=0,q=0,[0]=null,s=STREAM] addContent Content@4e445473{HeapByteBufferR@341ed4da[p=228,l=579,c=8192,r=351]={POST /PostReposit...oding: gzip\r\n\r\n<<<{"tag":"tag","pos...:5,"offset":0}}>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}}
2023-09-02 18:57:46.480 [qtp1864548849-46] DEBUG o.eclipse.jetty.http.HttpParser - CONTENT --> END
2023-09-02 18:57:46.480 [qtp1864548849-46] DEBUG o.e.jetty.server.HttpChannel - HttpChannelOverHttp@38fffb8{r=1,c=false,a=DISPATCHED,uri=//100.64.188.184:8051/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted} onContentComplete
2023-09-02 18:57:46.480 [qtp1864548849-46] DEBUG o.e.jetty.server.HttpChannel - HttpChannelOverHttp@38fffb8{r=1,c=false,a=DISPATCHED,uri=//100.64.188.184:8051/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted} onRequestComplete
2023-09-02 18:57:46.480 [qtp1864548849-46] DEBUG o.eclipse.jetty.server.HttpInput - HttpInputOverHTTP@4025a80e[c=0,q=1,[0]=EOF,s=STREAM] addContent EOF
2023-09-02 18:57:46.480 [qtp1864548849-46] DEBUG o.e.jetty.server.HttpConnection - HttpConnection@2b3e8dcc[p=HttpParser{s=END,351 of 351},g=HttpGenerator@d6ee9c8{s=START}]=>HttpChannelOverHttp@38fffb8{r=1,c=false,a=DISPATCHED,uri=//100.64.188.184:8051/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted}<-SocketChannelEndPoint@5315f828{/100.64.188.184:55553<->/100.64.188.184:8051,OPEN,fill=-,flush=-,to=16/30000}{io=0/0,kio=0,kro=1}->HttpConnection@2b3e8dcc[p=HttpParser{s=END,351 of 351},g=HttpGenerator@d6ee9c8{s=START}]=>HttpChannelOverHttp@38fffb8{r=1,c=false,a=DISPATCHED,uri=//100.64.188.184:8051/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted} parsed false HttpParser{s=END,351 of 351}
2023-09-02 18:57:46.480 [qtp1864548849-46] DEBUG o.eclipse.jetty.server.HttpInput - HttpInputOverHTTP@4025a80e[c=1,q=1,[0]=EOF,s=STREAM] read 1 from Content@4e445473{HeapByteBufferR@341ed4da[p=229,l=579,c=8192,r=350]={POST /PostReposit...ding: gzip\r\n\r\n{<<<"tag":"tag","post...:5,"offset":0}}>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}}
2023-09-02 18:57:46.481 [qtp1864548849-46] DEBUG o.s.w.s.m.m.a.RequestResponseBodyMethodProcessor - Read [class com.raysmond.blog.common.models.PostParams] as "application/json;charset=UTF-8" with [org.springframework.http.converter.json.MappingJackson2HttpMessageConverter@f6e3b67]
2023-09-02 18:57:46.481 [qtp1864548849-46] DEBUG o.eclipse.jetty.server.HttpInput - HttpInputOverHTTP@4025a80e[c=351,q=1,[0]=EOF,s=STREAM] read 350 from Content@4e445473{HeapByteBufferR@341ed4da[p=579,l=579,c=8192,r=0]={POST /PostReposit...:5,"offset":0}}<<<>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}}
2023-09-02 18:57:46.481 [qtp1864548849-46] DEBUG o.e.jetty.server.HttpConnection - releaseRequestBuffer HttpConnection@2b3e8dcc[p=HttpParser{s=END,351 of 351},g=HttpGenerator@d6ee9c8{s=START}]=>HttpChannelOverHttp@38fffb8{r=1,c=false,a=DISPATCHED,uri=//100.64.188.184:8051/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted}<-SocketChannelEndPoint@5315f828{/100.64.188.184:55553<->/100.64.188.184:8051,OPEN,fill=-,flush=-,to=17/30000}{io=0/0,kio=0,kro=1}->HttpConnection@2b3e8dcc[p=HttpParser{s=END,351 of 351},g=HttpGenerator@d6ee9c8{s=START}]=>HttpChannelOverHttp@38fffb8{r=1,c=false,a=DISPATCHED,uri=//100.64.188.184:8051/PostRepositoryController/findAllByPostTypeAndPostStatusAndDeleted}
  1. 报错
2023-09-02 18:57:46.483 [qtp1864548849-46] DEBUG o.s.w.s.m.m.a.ServletInvocableHandlerMethod - Failed to resolve argument 0 of type 'com.raysmond.blog.common.models.PostParams'
org.springframework.http.converter.HttpMessageNotReadableException: JSON parse error: Cannot construct instance of `org.springframework.data.domain.Pageable` (no Creators, like default construct, exist): abstract types either need to be mapped to concrete types, have custom deserializer, or contain additional type information; nested exception is com.fasterxml.jackson.databind.exc.InvalidDefinitionException: Cannot construct instance of `org.springframework.data.domain.Pageable` (no Creators, like default construct, exist): abstract types either need to be mapped to concrete types, have custom deserializer, or contain additional type information
 at [Source: java.io.PushbackInputStream@e7b9342; line: 1, column: 179] (through reference chain: com.raysmond.blog.common.models.PostParams["pageRequest"])
	at org.springframework.http.converter.json.AbstractJackson2HttpMessageConverter.readJavaType(AbstractJackson2HttpMessageConverter.java:238)
	at org.springframework.http.converter.json.AbstractJackson2HttpMessageConverter.read(AbstractJackson2HttpMessageConverter.java:223)
	at org.springframework.web.servlet.mvc.method.annotation.AbstractMessageConverterMethodArgumentResolver.readWithMessageConverters(AbstractMessageConverterMethodArgumentResolver.java:201)
	at org.springframework.web.servlet.mvc.method.annotation.RequestResponseBodyMethodProcessor.readWithMessageConverters(RequestResponseBodyMethodProcessor.java:150)
	at org.springframework.web.servlet.mvc.method.annotation.RequestResponseBodyMethodProcessor.resolveArgument(RequestResponseBodyMethodProcessor.java:128)
	at org.springframework.web.method.support.HandlerMethodArgumentResolverComposite.resolveArgument(HandlerMethodArgumentResolverComposite.java:121)
	at org.springframework.web.method.support.InvocableHandlerMethod.getMethodArgumentValues(InvocableHandlerMethod.java:158)
	at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:128)
	at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:97)
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:827)
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:738)
	at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85)
	at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:967)
	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:901)
	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970)
	at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:872)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
	at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:841)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1650)
	at org.eclipse.jetty.websocket.server.WebSocketUpgradeFilter.doFilter(WebSocketUpgradeFilter.java:206)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1637)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:317)
	at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:127)
	at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:91)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
	at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:114)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
	at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:137)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
	at org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:111)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
	at org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:170)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
	at org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:63)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
	at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:116)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
	at org.springframework.security.web.header.HeaderWriterFilter.doFilterInternal(HeaderWriterFilter.java:64)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
	at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:105)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
	at org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter.doFilterInternal(WebAsyncManagerIntegrationFilter.java:56)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
	at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:214)
	at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:177)
	at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:347)
	at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:263)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1637)
	at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1637)
	at org.springframework.web.filter.HttpPutFormContentFilter.doFilterInternal(HttpPutFormContentFilter.java:108)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1637)
	at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:81)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1637)
	at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:197)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1637)
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:533)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:190)
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1595)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:188)
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1253)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:168)
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:473)
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1564)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:166)
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1155)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
	at org.eclipse.jetty.server.Server.handle(Server.java:561)
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:334)
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:251)
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:279)
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:104)
	at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:124)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:247)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:140)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131)
	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:243)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:679)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:597)
	at java.lang.Thread.run(Thread.java:748)
Caused by: com.fasterxml.jackson.databind.exc.InvalidDefinitionException: Cannot construct instance of `org.springframework.data.domain.Pageable` (no Creators, like default construct, exist): abstract types either need to be mapped to concrete types, have custom deserializer, or contain additional type information
 at [Source: java.io.PushbackInputStream@e7b9342; line: 1, column: 179] (through reference chain: com.raysmond.blog.common.models.PostParams["pageRequest"])
	at com.fasterxml.jackson.databind.exc.InvalidDefinitionException.from(InvalidDefinitionException.java:67)
	at com.fasterxml.jackson.databind.DeserializationContext.reportBadDefinition(DeserializationContext.java:1451)
	at com.fasterxml.jackson.databind.DeserializationContext.handleMissingInstantiator(DeserializationContext.java:1027)
	at com.fasterxml.jackson.databind.deser.AbstractDeserializer.deserialize(AbstractDeserializer.java:265)
	at com.fasterxml.jackson.databind.deser.SettableBeanProperty.deserialize(SettableBeanProperty.java:519)
	at com.fasterxml.jackson.databind.deser.BeanDeserializer._deserializeWithErrorWrapping(BeanDeserializer.java:527)
	at com.fasterxml.jackson.databind.deser.BeanDeserializer._deserializeUsingPropertyBased(BeanDeserializer.java:448)
	at com.fasterxml.jackson.databind.deser.BeanDeserializerBase.deserializeFromObjectUsingNonDefault(BeanDeserializerBase.java:1265)
	at com.fasterxml.jackson.databind.deser.BeanDeserializer.deserializeFromObject(BeanDeserializer.java:325)
	at com.fasterxml.jackson.databind.deser.BeanDeserializer.deserialize(BeanDeserializer.java:159)
	at com.fasterxml.jackson.databind.ObjectMapper._readMapAndClose(ObjectMapper.java:4001)
	at com.fasterxml.jackson.databind.ObjectMapper.readValue(ObjectMapper.java:3072)
	at org.springframework.http.converter.json.AbstractJackson2HttpMessageConverter.readJavaType(AbstractJackson2HttpMessageConverter.java:235)
	... 91 common frames omitted
  • 通过断点监控，发现com.fasterxml.jackson.databind.deser.BeanDeserializer中函数deserializeFromObject解析输入参数时存在pageRequest参数（很奇怪），进而导致了以上报错，实际上不应该传递该参数。
  • 根据前期排查，直接向 microservice1 发送 POST 请求时可以正常，而通过 microservice2 发送 POST 请求时会出现该问题，因此暂时判断问题出在 microservice2，对 microservice2 通过 feignclient 发送请求的过程进行断点排查+详细日志输出。
  • 检索信息，查看 feignclient 端所传递信息情况，发现com.fasterxml.jackson.databind.ObjectWriter的writeValue函数导致转为 json 后的数据出现pageRequest参数。
    • 更具体地说，是在使用com.fasterxml.jackson.databind.ser.DefaultSerializerProvider的serializeValue函数中所获取的JsonSerializer<Object>类对象的属性存在pageRequest参数。
      • 至此，怀疑是因为在 PageParam 类中写了getPageRequest和setPageReuqest两个函数，进一步被@Data之类的注解自动识别为属性。
    • 首先进一步断点排查，查看com.fasterxml.jackson.databind.ser.DefaultSerializerProvider类的findTypedValueSerializer函数如何构建出错的JsonSerializer<Object>类对象。
      • 发现相关JsonSerializer<Object>类对象已经提前设定好，基本排除 JsonSerialize 问题。
    • 进一步检索 @Data 注解原理，发现似乎并无关联。
    • 进一步检索 Jackson 对于 getter 函数的处理，发现果然存在问题，Jackson 会自动将存在 getter 函数的属性解析[6]。（你害我害得好苦啊）（太自动化了竟然也不是好事）

🔨解决方案

  • 定位到问题后，解决就变得非常简单了。
  • 在 getter、setter 函数上增加 @JsonIgnore 注解即可。
  • 后续：问题转变为反序列化org.springframework.data.domain.Page失败，相关解决方案已补充至{% post_link program_language/java-spring-bug-json-parse-error 【Spring】java 单体式应用微服务拆分过程 bug 修复：Json Parse Error %}。

📖知识补充——@JsonIgnore 注解

Marker annotation that indicates that the annotated method or field is to be ignored by introspection-based serialization and deserialization functionality. That is, it should not be consider a "getter", "setter" or "creator". 标记注释，表示注释的方法或字段将被基于自检的序列化和反序列化功能忽略。也就是说，它不应被视为 "getter"、"setter "或 "creator"。

  • 本次发现的隐含小坑：
    • 此处暗示，getter、setter函数会影响 Json 序列化及反序列化结果。
    • 当使用不想被序列化/反序列化的getter、setter函数时应当标注该注解。

🧠问题4️⃣——400：Already had POJO for id

✏️问题描述

  • 对于存在循环引用的对象，传参后出现Already had POJO for id报错。

ℹ️报错信息1️⃣

Failed to read HTTP message: org.springframework.http.converter.HttpMessageNotReadableException: JSON parse error: Already had POJO for id (java.lang.Long) [[ObjectId: key=1, type=com.fasterxml.jackson.databind.deser.impl.PropertyBasedObjectIdGenerator, scope=com.raysmond.blog.common.models.User]]

📚问题分析

  • 根据前期相应方法，逐步断点，最后定位到报错源：
  1. com.fasterxml.jackson.databind.deser.impl.ObjectIdValueProperty的deserializeSetAndReturn方法希望将ReadableObjectId类型的变量roid与Object类型的变量instance进行绑定。
ReadableObjectId roid = ctxt.findObjectId(id, _objectIdReader.generator, _objectIdReader.resolver);
roid.bindItem(instance);
  1. com.fasterxml.jackson.databind.deser.impl.ReadableObjectId的bindItem方法调用_resolver变量进行绑定。
  2. com.fasterxml.jackson.annotation.SimpleObjectIdResolver的SimpleObjectIdResolver方法进行最终绑定，代码如下：
    public void bindItem(IdKey id, Object ob)
    {
        if (_items == null) {
            _items = new HashMap<ObjectIdGenerator.IdKey,Object>();
        } else if (_items.containsKey(id)) {
            throw new IllegalStateException("Already had POJO for id (" + id.key.getClass().getName() + ") [" + id
                    + "]");
        }
        _items.put(id, ob);
    }
  • 思考逻辑，希望的逻辑是：先检索是否已经存在该 id 为 key 的对象，如果已存在则不再重新插入。
    • 基于该逻辑向前梳理，找“当 id 已存在时 spring 是如何处理的”。
    • 逐步断点理解流程后突然意识到（受到[8]修改 generator 参数的启发），所谓“解决循环引用”的过程，很可能是从标记了@JsonIdentityInfo注解的类开始，对其下每个被标记了该注解的属性对象用 id 代替。而我们的项目中定义了这样一个 DTO 类：
public class PostUserParams {
    private Post post;
    private User user;
    public PostUserParams(Post post, User user) {
        this.post = post;
        this.user = user;
    }
}
  • 其中的 post 和 user 对象分别在两个@JsonIdentityInfo序列化过程中，而当post的子对象post_user与user相同时则会出现冲突（在两个序列化过程中出现相同，而非同一个序列化过程中出现相同）。
  • 因此问题应当出在序列化过程而非反序列化过程。

🔨解决方案

  • 一种思路是在序列化user的过程中识别该对象是否已被序列化过。
  • 另一种思路是把user当做没出现过的对象，序列化成其他值。
  • 前者还没想到怎么使用，后者尝试将@JsonIdentityInfo的generator参数改为ObjectIdGenerators.IntSequenceGenerator.class并删去property属性[8][9]。

📚相关知识补充

  • 根据相关资料[8][9]及com.fasterxml.jackson.annotation.ObjectIdGenerators源码，generator 参数有以下几个选项：
    1. ObjectIdGenerators.IntSequenceGenerator：
      • Simple sequence-number based generator, which uses basic Java ints (starting with value 1) as Object Identifiers.
      • 基于序列号的简单生成器，使用基本的 Java ints（从值 1 开始）作为对象标识符。
    2. ObjectIdGenerators.PropertyGenerator：
      • Abstract place-holder class which is used to denote case where Object Identifier to use comes from a POJO property (getter method or field). If so, value is written directly during serialization, and used as-is during deserialization. Actual implementation class is part of databind package.
      • 抽象占位类，用于表示要使用的对象标识符来自 POJO 属性（获取方法或字段）的情况。如果是这样，值将在序列化过程中直接写入，并在反序列化过程中按原样使用。实际实现类是 databind 包的一部分。
    3. ObjectIdGenerators.StringIdGenerator (since 2.7)：
      • Implementation that will accept arbitrary (but unique) String Ids on deserialization, and (by default) use random UUID generation similar to ObjectIdGenerators.UUIDGenerator for generation ids.
      • This generator is most useful for cases where another system creates String Ids (of arbitrary structure, if any), and Jackson only needs to keep track of id-to-Object mapping. Generation also works, although if UUIDs are always used, ObjectIdGenerators.UUIDGenerator is a better match as it will also validate ids being used.
      • 该实现将在反序列化时接受任意（但唯一）的字符串 Ids，并且（默认情况下）使用类似于 ObjectIdGenerators.UUIDGenerator 的随机 UUID 生成器生成 ID。
      • 这种生成器最适用于其他系统创建字符串 Ids（任意结构，如果有的话），而 Jackson 只需要跟踪 id 到对象的映射的情况。尽管如果总是使用 UUID，ObjectIdGenerators.UUIDGenerator 也能发挥作用，但它也会验证正在使用的 id。
    4. ObjectIdGenerators.UUIDGenerator：
      • Implementation that just uses UUIDs as reliably unique identifiers: downside is that resulting String is 36 characters long.
      • One difference to other generators is that scope is always set as Object.class (regardless of arguments): this because UUIDs are globally unique, and scope has no meaning.
      • 该实现只使用 UUID 作为可靠的唯一标识符：缺点是生成的字符串长达 36 个字符。
      • 与其他生成器的一个不同之处是，scope 总是设置为 Object.class（与参数无关）：这是因为 UUID 是全局唯一的，而 scope 没有任何意义。

🤔思考

  • 排查 bug 的思路？
    • 根据前期 bug 排查，已经确定 microservice1 在接收到正常数据时能够正常运行，但后期排查时又不小心忽略了该结论，导致浪费大量时间排查 microservice1。
    • 应该始终提醒自己从宏观层面回顾，之前获得了什么结论，现在需要证明/排除的是什么问题。

🚧ToDoList（也许会补上）

  1. Spring 框架基础原理
  2. Jackson 组件原理及相关注解作用
  3. {% post_link program_language/java-spring-bug-4xx 到底为啥报4xx相关错误 %}
  4. {% post_link program_language/java-spring-bug-json-infinite-recursion json循环引用报错 %}
  5. Serialize Json 报错

:world_map:参考文献

[1] HTTP请求415错误 – 不支持的媒体类型(Unsupported media type)

[2] Markdown中折叠代码的方法

[3] NullPointerException in SubTypeValidator.validateSubType when validating Spring interface

[4] Spring MVC : 400 错误是怎么发生的 ?

[5] 清除gradle缓存

[6] Jackson deserialization behaviour for a getter without property

[7] Annotation Type JsonIgnore

[8] 公用技术——数据格式——JSON——Jackson类库——复杂对象

[9] Class ObjectIdGenerator

avatar
文章
阅读
粉丝