問題描述
線上一個 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