Львы в пустыне и интроспекция

в 12:03, , рубрики: laravel, php, отладка

Наверное, практически все обитатели Хабра знают что такое дихотомия и как с ее помощью поймать льва в пустыне. Ошибки в программах тоже можно ловить дихотомией, особенно, при отсутствии вменяемой диагностической информации.

image

Однажды отлаживая свой проект на PHP/Laravel, я увидел в браузере вот такую ошибку:

image

Это было, как минимум, странно, потому, что, судя по описанию в 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();

Теперь сбойная страница выглядела так:

image

Поставив написанную выше команду сначала в начало, а затем в конец пути обработки 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.

Багрепорт — отправлен.

Какие выводы можно сделать из всего этого?

  1. Отладка дихотомией, хотя и является допотопным способом отладки, но иногда может быть необходима, особенно, в условиях недостатка диагностической информации
  2. На мой взгляд, у 502-ошибки, невразумительны, как сообщение о ней (“Bad gateway”), так и его расшифровка в RFC про “неверный ответ от восходящего сервера”. Хотя, если считать подключаемые к Web-сервера модули программами-серверами то смысл расшифровки ошибки в RFC понять можно. Однако, скажем, тот же PHP-FPM в документации называется модулем а не сервером.
  3. Статический анализатор — рулит, он бы сразу сообщил об ошибке в описании константы. Но тогда баг не был бы пойман.

На сем позвольте закончить, всем спасибо за внимание!

Автор: sunman

Источник


* - обязательные к заполнению поля


https://ajax.googleapis.com/ajax/libs/jquery/3.4.1/jquery.min.js