记一次 Laravel MethodNotAllowedHttpException 问题排查

问题描述

线上一个 laravel 4.2 的项目有 Exception 产生,通过查看 log 发现每天会有 2 条左右出现,量也不大,通过日志能看出是 MethodNotAllowedHttpException 异常,下面记录一下解决过程。

[2019-05-17 06:04:38] Oregon.ERROR: Symfony\Component\HttpKernel\Exception\MethodNotAllowedHttpException in /******/endpoint/bootstrap/compiled.php:5753
Stack trace:
#0 /******/endpoint/bootstrap/compiled.php(5749): Illuminate\Routing\RouteCollection->methodNotAllowed(Array)
#1 /******/endpoint/bootstrap/compiled.php(5727): Illuminate\Routing\RouteCollection->getOtherMethodsRoute(Object(Illuminate\Http\Request), Array)
#2 /******/endpoint/bootstrap/compiled.php(5051): Illuminate\Routing\RouteCollection->match(Object(Illuminate\Http\Request))
#3 /******/endpoint/bootstrap/compiled.php(5039): Illuminate\Routing\Router->findRoute(Object(Illuminate\Http\Request))
#4 /******/endpoint/bootstrap/compiled.php(5031): Illuminate\Routing\Router->dispatchToRoute(Object(Illuminate\Http\Request))
#5 /******/endpoint/bootstrap/compiled.php(720): Illuminate\Routing\Router->dispatch(Object(Illuminate\Http\Request))
#6 /******/endpoint/bootstrap/compiled.php(696): Illuminate\Foundation\Application->dispatch(Object(Illuminate\Http\Request))
#7 /******/endpoint/bootstrap/compiled.php(7803): Illuminate\Foundation\Application->handle(Object(Illuminate\Http\Request), 1, true)
#8 /******/endpoint/bootstrap/compiled.php(8410): Illuminate\Session\Middleware->handle(Object(Illuminate\Http\Request), 1, true)
#9 /******/endpoint/bootstrap/compiled.php(8357): Illuminate\Cookie\Queue->handle(Object(Illuminate\Http\Request), 1, true)
#10 /******/endpoint/bootstrap/compiled.php(11154): Illuminate\Cookie\Guard->handle(Object(Illuminate\Http\Request), 1, true)
#11 /******/endpoint/bootstrap/compiled.php(657): Stack\StackedHttpKernel->handle(Object(Illuminate\Http\Request))
#12 /******/endpoint/public/index.php(48): Illuminate\Foundation\Application->run()
#13 {main} [] []

排查过程

  通过查找 nginx access log 找到对应的信息,是 post 请求 index.php,我用 postMan 来进行模拟并没有复现这个 exception,我拿到的只是一个 200 的 Response,并不是 500,这应该是扫描器批量扫描的,或者是 spider 爬的,并没有走域名,而是从 ip 直接访问。

**.93.2.** **.71.95.** 182.61.178.228 - "17/May/2019:06:04:39 +0800" "POST /index.php HTTP/1.1" 453 4534 0.680 500 unix:/tmp/php-cgi-72.sock - 0.004 "Mozilla/5.0 (Windows NT 6.1; Win64; x64; rv:28.0) Gecko/20100101 Firefox/28.0" 

查找 nginx error log 没有对应的 log,问题到这里就僵住了,返回去看 exception log 找到抛出异常之前最后一个执行的方法

Illuminate\Routing\RouteCollection->getOtherMethodsRoute

/* 代码路径 */
/vendor/laravel/framework/src/Illuminate/Routing/RouteCollection.php  :186
    /**
     * Get a route (if necessary) that responds when other available methods are present.
     *
     * @param  \Illuminate\Http\Request  $request
     * @param  array  $others
     * @return \Illuminate\Routing\Route
     *
     * @throws \Symfony\Component\Routing\Exception\MethodNotAllowedHttpException
     */
    protected function getOtherMethodsRoute($request, array $others)
    {
        if ($request->method() == 'OPTIONS')
        {
            return (new Route('OPTIONS', $request->path(), function() use ($others)
            {
                return new Response('', 200, array('Allow' => implode(',', $others)));

            }))->bind($request);
        }

        $this->methodNotAllowed($others);
    }

  看到这就大体明白了,如果 method 是 OPTIONS 会有 200 的正常 Response,否则就抛出错误,猜测 Http method 肯定是一个比较冷门的,导致框架报错,从 postMan 找一个比较冷门的 method UNLOCK 试了一下,果然状态 500,成功复现。

  这里有一段小插曲:为什么状态是 500 呢,应该是 405 才对,查看代码发现处理 error 的逻辑里面调用了一个已经优化掉的日志类,去掉那一行调用,一切正常。

正常的 405 报错:

解决方案

/app/start/global.php 增加异常处理代码

App::error( function( Symfony\Component\HttpKernel\Exception\MethodNotAllowedHttpException $exception, $code)
{
    Log::debug( 'MethodNotAllowedHttpException: ' . Request::method() );
    return ['code' => $code, 'message' => 'MethodNotAllowedHttpException'];
});

加上这段代码之后就会捕获这个异常,直接 return 即可,这样就不会有 exception 产生了。到这里框架层面的问题已经解决了,但是 Nginx 为什么是 POST 请求,到底是个什么请求导致了报错,这个有必要去研究一下,于是在 Closure 里面加一行 Log 代码记录一下 method 到底是什么东西。

提交代码,上线观察,未完待续……
2019年5月17日17:36:20

Update 2019年5月18日13:45:24
日志已经搜集到,method 为 CONSTRUCT,确实比较冷门,也有可能是特意伪造的。

[2019-05-18 04:28:05] Oregon.DEBUG: MethodNotAllowedHttpException: __CONSTRUCT [] []
[2019-05-18 11:16:39] Oregon.DEBUG: MethodNotAllowedHttpException: __CONSTRUCT [] []

对应的 nginx log 状态也已经是 200 了,exception 没有再出现过。

10.93.2.** **.26.44.** 10.93.1.81 129.204.51.63 "18/May/2019:04:28:05 +0800" "POST /index.php HTTP/1.1" 554 626 0.003 200 unix:/tmp/php-cgi-72.sock - 0.004 "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 5.1; Trident/4.0)" 

评论