偶現的MissingServletRequestParameterException,誰動了我的引數?
概述
最近遇到一個偶現的問題,在向服務端請求的時候,偶爾會出現異常,在請求中的query String 傳遞了引數,卻出現了異常MissingServletRequestParameterException
如下所示:
018-02-05 11:29:34.910 ERROR 41469 --- [a626f375-7f79-4fd2-88be-1db10a3811cb-] [nio-8080-exec-7] c.s.s.f.ValidationGlobalExceptionHandler : org.springframework.web.bind.MissingServletRequestParameterException: Required long parameter 'xxx' is not present
at org.springframework.web.method.annotation.RequestParamMethodArgumentResolver.handleMissingValue(RequestParamMethodArgumentResolver.java:198)
at org.springframework.web.method.annotation.AbstractNamedValueMethodArgumentResolver.resolveArgument(AbstractNamedValueMethodArgumentResolver.java:109 )
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:963)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:897)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970)
at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:861)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:635)
at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:742)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
在請求中顯然是帶了這個引數的,開始時還以為自己眼花,於是又試了一下,結果介面返回又正常了。
但是,既然錯誤日誌出現了,就不能輕易地放過,尤其是這種偶現的錯誤,充滿著風險,極有可能在某個關鍵時刻爆發。因此決定抽出時間排查這個問題。接下來,就是整個排查過程。
排查過程
具體的請求如下所示:
curl -X GET --header "Accept: */*" "http://localhost:8080/xxx/api/v3/xxx/getXX?param=123456"
其中param在Controller的方法中被宣告為required=true
,也就是必傳引數,而在前後端互動裡,這個引數也是一定會傳的。
既然這是一個偶現的問題,就不可能通過手動一次次地呼叫請求進行問題的重現。在這裡我採用了Jmeter作為請求觸發器,進行30次一批的重複請求,結果在跑第一次的時候,就出現了一次請求異常。
反覆跑了兩三次之後,都出現了同樣的結果,既然問題已經確認,並且能夠穩定重現,接下來就是如何找到問題的根源並解決這個問題了。
因為有具體的異常類,所以我的第一想法就是在這個異常類的建構函式中加斷點,看看為什麼會丟擲這個異常。通過呼叫棧,在RequestParamMethodArgumentResolver(AbstractNamedValueMethodArgumentResolver)
中發現如下程式碼片段
Object arg = resolveName(resolvedName.toString(), nestedParameter, webRequest); //在RequestParamMethodArgumentResolver中,直接通過呼叫request.getParameterValues(name)來獲取普通請求的引數
if (arg == null) {
if (namedValueInfo.defaultValue != null) {
arg = resolveStringValue(namedValueInfo.defaultValue);
}
else if (namedValueInfo.required && !nestedParameter.isOptional()) {
handleMissingValue(namedValueInfo.name, nestedParameter, webRequest); //如果沒有獲取到且沒有預設值,就會在這裡丟擲異常。
}
arg = handleNullValue(namedValueInfo.name, arg, nestedParameter.getNestedParameterType());
}
else if ("".equals(arg) && namedValueInfo.defaultValue != null) {
arg = resolveStringValue(namedValueInfo.defaultValue);
}
看到這裡的時候心裡不禁疑惑,難道真的沒傳引數?或者是引數在傳遞的過程丟了?或者…被框架吃了?!
但疑惑不是我想要的,答案才是我想要的。既然request.getParameterValues
裡面沒有得到想要的值,那就應該去找正常請求時,這個值是如何被設定的。
首先想到的是檢視Request
的類圖結構。以及請求被處理的流程圖
所以,最原始的資料被儲存在了org.apache.coyote.Request
這個類中,深入這個類,我們就能夠更接近答案。於是直接到了Http11Processor
的service
方法中,看具體的處理過程。首先在799行加斷點,看看是處理結果是什麼,由於問題是處在parameter上,直接檢視此時request中parameters的各種值。
正常請求:
異常請求:
對比兩者不難發現,異常請求中的queryMB與正常請求中的是一樣的,也就是說我們請求中帶的引數被傳遞到了伺服器。但異常請求didQueryParameters
被置成了true,而從程式碼中可以知道,這個程式碼實際上是用於判斷query string是否已經被解析過了,並且,在請求處理結束的時候,會呼叫parameter的recycle方法
public void recycle() {
parameterCount = 0;
paramHashValues.clear(); //清空了解析後的parameter map
didQueryParameters=false; //是否被解析過,置成false
encoding=null;
decodedQuery.recycle();
parseFailedReason = null;
}
由於Tomcat中,Request以及Response物件都是會被迴圈使用的,因此這個時候也是整個Request被重置的時候。
所以根本原因是,在Parameter被重置了之後,didQueryParameters
又被置成了true,導致新的請求引數沒有被正確解析,就報錯了(此時的parameterMap已經被重置,為空)。而didQueryParameters
只有在一種情況下才會被置為true,也就是handleQueryParameters
方法被呼叫時。而handleQueryParameters
會在多個場景中被呼叫,其中一個就是getParameterValues
,獲取請求引數的值。
到這裡,就可以推斷,應用中可能存在程式碼,在請求結束之後,仍然通過Request物件獲取其中的引數值。
全域性搜尋引用了HttpServletRequest
的地方。最終發現埋點類中有如下程式碼
@Async
public void buryPoint(long userId, HttpServletRequest request.....) {
if (request != null) {
xxx = request.getParameter("xxx");
}
由於這段邏輯是非同步執行的,因此完全有可能在請求結束之後,仍然呼叫request.getParameter
方法,導致下一次的請求引數不被解析。將此段程式碼註釋掉,重新使用Jmeter進行請求,錯誤不再出現。
結論
不要將HttpServletRequest傳遞到任何非同步方法中!