Наверное, практически все обитатели Хабра знают что такое дихотомия и как с ее помощью поймать льва в пустыне. Ошибки в программах тоже можно ловить дихотомией, особенно, при отсутствии вменяемой диагностической информации.
Однажды отлаживая свой проект на PHP/Laravel, я увидел в браузере вот такую ошибку:
Это было, как минимум, странно, потому, что, судя по описанию в RFC 2616, 502 ошибка означает, что “Сервер, действуя как шлюз или прокси, получил неверный ответ от восходящего сервера”. В моем случае никаких шлюзов, прокси между Web-сервером и браузером не было, Web-сервер представлял собой nginx, работающий под virtualbox, и выдающий Web-контент напрямую, без каких-либо посредников. В логах nginx было вот это:
2018/06/20 13:42:41 [error] 2791#2791: *2206 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 192.168.10.1, server: colg.test, request: "GET / HTTP/1.1", upstream: "fastcgi://unix:/var/run/php/php7.1-fpm.sock:", host: "colg.test"
Cлова “восходящий сервер” в описании 502 ошибки (“upstream server” в англоязычном оригинале RFC) наводили на мысль о каких-то дополнительных сетевых серверах на пути запроса от браузера к nginx, но, судя по всему, в данном случае, упоминаемый в сообщении модуль PHP-FPM, являясь программой-сервером, выступает в роли этого самого восходящего сервера. В логах PHP было вот что:
[20-Jun-2018 13:42:41] WARNING: [pool www] child 26098 exited on signal 11 (SIGSEGV - core dumped) after 102247.908379 seconds from start
Теперь было понятно где проблема возникает, но ее причина была неясна. PHP просто выпадал в core dump, не выводя никакой информации о том, в какой момент интерпретации PHP-программы происходит ошибка. Так что пришло время ловить льва в пустыне — применить мой любимый в подобных случаях метод отладки дихотомией. Предвидя возражения в комментах, замечу, что здесь можно было бы использовать отладчик, например, тот же XDebug, но дихотомией было интереснее. Кроме того, дальше дойдет очередь и до XDebug.
Итак, на пути обработки Web-запроса я поставил простейший диагностический вывод, с дальнейшим завершением программы, чтобы убедиться в том, что до места его установки ошибки не возникает:
echo “I am here”; die();Теперь сбойная страница выглядела так:
Поставив написанную выше команду сначала в начало, а затем в конец пути обработки Web-запроса, я выяснил, что ошибка (кто бы сомневался!) возникает где-то между этими двумя точками. Установив диагностику примерно посредине пути Web-запроса, я узнал, что ошибка проявляется где-то ближе к концу. Еще через пару таких итераций, я понял, что ошибка возникает не в самом контроллере Laravel’овской MVC-архитектуры, а уже на выходе из него, при рендеринге view, который здесь простейший, в таком духе:
@extends('layouts.app')
@section('content')
<div>
<div class="panel-heading">Myservice</div>
<div class="panel-body"></div>
</div>
@endsectionКак видно, PHP-кода шаблон view не содержит (шаблонизатор Laravel позволяет использовать PHP-код во view), и проблемы уж точно не здесь. Но выше мы видим, что этот view наследует шаблон layouts.app, так что смотрим туда. Там уже посложнее: есть элементы навигации, формы логина, и прочие общие для всех страниц сервиса вещи. Опуская все, что там есть, приведу лишь строчку, из-за которой и возникал сбой, она была найдена все той же дихотомией. Вот эта строчка:
<script>
window.bkConst = {!! (new AppSrcHelpersUtilsHelper())->loadBackendConstantsAsJSData() !!};
</script>Тут как раз в коде шаблона view использовался PHP. Это была моя «прелесть» — вывод констант backend, в виде JS-кода, для использования их же на frontend, во имя принципа DRY. В методе loadBackendConstantsAsJSData было перечислено несколько классов с необходимыми на frontend константами. Ошибка же возникала в используемом им методе addClassConstants, где для получения списка констант класса применялась интроспекция PHP:
/**
* add all class constants to resulted JSON
* @param string $classFullName
*/
private function addClassConstants(string $classFullName, array &$constantsArray)
{
$r = new ReflectionClass($classFullName);
$result = [];
$className = $r->getShortName();
$classConstants = $r->getConstants();
foreach($classConstants as $name => $value) {
if (is_array($value) || is_object($value)) {
continue;
}
$result["$className::$name"] = $value;
}
$constantsArray = array_merge($constantsArray, $result);
}
После поиска среди передаваемых в этот метод классов с константами, выяснилось, что причина всему — вот этот класс с константами — путями к методам REST API.
class APIPath
{
const API_BASE_PATH = '/api/v1';
const DATA_API = self::API_BASE_PATH . "/data";
...
const DATA_ADDITIONAL_API = DATA_API . "/additional";
}
Строчек в нем довольно много, и, чтобы найти нужную, снова пригодилась дихотомия. Теперь, надеюсь все заметили, что в определении константы пропущен self:: перед именем константы DATA_API. После его добавления на свое законное место все заработало.
Решив, что проблема — в механизме интроспекции, я стал писать минимальный пример для воспроизводства бага:
class SomeConstants
{
const SOME_CONSTANT = SOME_NONSENSE;
}
$r = new ReflectionClass(SomeConstants::class);
$r->getConstants();
Однако, при запуске этого скрипта PHP падать не собирался, а выдавал вполне вменяемое предупреждение.
PHP Warning: Use of undefined constant SOME_NONSENSE - assumed 'SOME_NONSENSE' (this will throw an Error in a future version of PHP) in /home/vagrant/code/colg/_tmp/1.php on line 17
К этому моменту я уже убедился, что проблема проявляется не только при загрузке сайта, но и при выполнении написанного выше кода через командную строку. Единственным отличием среды выполнения от минимального скрипта было наличие контекста Laravel: проблемный код запускался через ее утилиту artisan. Значит, под Laravel было какое-то отличие. Чтобы понять в чем оно заключается, пришло время воспользоваться отладчиком. Запустив код под xdebug, я увидел, что сбой происходит уже после вызова метода ReflectionClass::getConstants, в методе IlluminateFoundationBootstrapHandleExceptions::handleError, который выглядит очень просто:
public function handleError($level, $message, $file = '', $line = 0, $context = [])
{
if (error_reporting() & $level) {
throw new ErrorException($message, 0, $level, $file, $line);
}
}
Поток выполнения попадал туда после выброса исключения из-за той самой ошибки описания константы, с которого все началось, а PHP падал при попытке выбросить исключение ErrorException. Исключение в обработчике исключения… Сразу вспомнился знаменитый Double fault. Итак, для вызова сбоя нужно установить обработчики исключений аналогично Laravel'овским. Чуть выше по коду как раз был метод bootstrap, который этим занимался:
Теперь доработанный минимальный пример выглядел так:
<?php
class SomeConstants
{
const SOME_CONSTANT = SOME_NONSENSE;
}
function handleError()
{
throw new ErrorException();
}
set_error_handler('handleError');
set_exception_handler('handleError');
$r = new ReflectionClass(SomeConstants::class);
$r->getConstants();
и его запуск стабильно укладывал интерпретатор PHP версии 7.2.4 в core dump.
Похоже, что здесь имеет место быть бесконечная рекурсия — при обработке исключения от первоначальной ошибки в handleException выбрасывается следующее исключение, обрабатываемое снова в handleException, и так до бесконечности. Причем, для воспроизводства сбоя нужно установить и error_handler, и exception_handler, если установлено только что-то одно из них, то проблема не проявляется. Не вышло также просто выбрасывать исключение, вместо генерации ошибки, похоже, тут не совсем обычная рекурсия, а что-то вроде циркулярной зависимости.
После этого я проверил наличие проблемы под разными версиям PHP (спасибо, Docker!). Оказалось, что сбой проявляется лишь, начиная с версии PHP 7.1, более ранние версии PHP работают корректно — ругаются на неперехваченное исключение ErrorException.
Багрепорт — отправлен.
Какие выводы можно сделать из всего этого?
- Отладка дихотомией, хотя и является допотопным способом отладки, но иногда может быть необходима, особенно, в условиях недостатка диагностической информации
- На мой взгляд, у 502-ошибки, невразумительны, как сообщение о ней (“Bad gateway”), так и его расшифровка в RFC про “неверный ответ от восходящего сервера”. Хотя, если считать подключаемые к Web-сервера модули программами-серверами то смысл расшифровки ошибки в RFC понять можно. Однако, скажем, тот же PHP-FPM в документации называется модулем а не сервером.
- Статический анализатор — рулит, он бы сразу сообщил об ошибке в описании константы. Но тогда баг не был бы пойман.
На сем позвольте закончить, всем спасибо за внимание!
Автор: sunman
