记一次 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)" 

本作品采用《CC 协议》，转载必须注明作者和本文链接