1. 程式人生 > >偶現的MissingServletRequestParameterException,誰動了我的引數?

偶現的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的類圖結構。以及請求被處理的流程圖

Request類圖

Request處理流程圖

所以,最原始的資料被儲存在了org.apache.coyote.Request這個類中,深入這個類,我們就能夠更接近答案。於是直接到了Http11Processorservice方法中,看具體的處理過程。首先在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傳遞到任何非同步方法中!