Yii2 basic: Логи. Как их делать и почему они нужны?

· Yii2 basic · 11 мин чтения

В этой записи пойдет речь о логах в Yii2 basic, а точнее о том, как из записывать, почему они вам пригодятся и как их читать.

Эта запись относится к курсу Yii2 basic.

Для чего они нужны

  • безопасность — если ваш сайт взломают или начнут происходить странные действия, которые вы не ожидали, то логи помогут восстановить хронологию событий чтобы разобраться из-за чего все началось и как это исправить
  • неисправности — если у вас что-то перестало работать, то это должно быть записано в логи, чтобы это можно было исправить

Какие бывают логи

В Yii2 можно записывать логи четырьмя основными способами:

  • В базу, используя — yii\log\DbTarget
  • Отправка по email, который заранее прописывается в конфиг, используя — yii\log\EmailTarget
  • В файл, используя класс — yii\log\FileTarget (самый распространенный вариант)
  • Сохранять логи в syslog, вызывая функцию syslog(), используя — yii\log\SyslogTarget

Чаще всего, я сохраняю логи в файл используя FileTarget и в этом посте, я буду описывать как им пользоваться.

Настройка логов

Чтобы начать пользоваться логами, в config/web.php, внутри components нужно указать следующее:

...
'log' => [
    'traceLevel' => YII_DEBUG ? 3 : 0,
    'targets' => [
        [
            'class' => 'yii\log\FileTarget',
            'levels' => ['error', 'warning'],
        ],
    ],
],
...

После levels добавьте следующую строку:

'logVars' => ['_GET', '_POST'],

Чтобы убрать лишнюю ненужную информацию из логов по типу $_SERVER, $_COOKIE и др.

В Yii2 basic, логгирование уже добавлено, поэтому никаких изменения делать не нужно. В случае, если будут какие-то не совпадения с тем, что я буду описывать ниже, то проверьте наличие компонента, как описано выше.

Уровни логов

Есть несколько уровней логов (levels из кода выше):

  • error — обычная ошибка, записывается с Yii::error()
  • warning — лог, уровня внимания, записывается с Yii::warning()
  • info — обычный лог, информативного уровня, записывается с Yii::info()
  • trace — лог, который может принимать в себя массивы, объекты и другие структуры, вызывается с Yii:trace(). В логе, они будут выведены в читабельном формате, используя статический метод export() из  yii\helpers\VarDumper.
  • profile — используется для расчета работы определенного участка кода. Вызывается с Yii::beginProfile('название_профиля') и Yii::endProfile('название_профиля'). То есть, когда код дойдет до Yii::beginProfile(), в лог запишется, что профиль запущен, когда скрипт дойдет до endProfile(), в лог, также запишется о его завершении. В итоге, можно будет посмотреть сколько было потрачено времени между запуском профиля и его окончанием. название_профиля — это ID профиля, который должен быть уникальным.

Запись логов

Зайдите в controllers/CarController.php, найдите actionIndex() и замените его на это:

public function actionIndex()
{
    $searchModel = new CarSearch();
    $dataProvider = $searchModel->search(Yii::$app->request->queryParams);

    Yii::info("Отображаем весь список машин.");

    return $this->render('index', [
        'searchModel' => $searchModel,
        'dataProvider' => $dataProvider,
    ]);
}

Выделенная строка сверху — это место, где будет записывать сообщение «Отображаем весь список машин.» в лог на уровне info (информативное сообщение).

Не забудьте в самом конце этой записи удалить Yii::info() из actionIndex().

Все логи, по умолчанию записываются в runtime/logs/, внутри файла app.log. Когда он становится слишком большой, у него появляются версии — app.log.1, app.log.2 и т.д. до пяти вариаций по умолчанию (вы можете сделать больше, если вам требуется).

Чтение логов

План действий (пока ничего не делайте, после этих двух этапов будет описано подробнее как и что нужно делать):

  1. Откроем app.log и посмотрим на него (используя команду tail с флагом -f) в консоли
  2. Зайдем на http://yii.loc/car и в app.log должны появиться новые изменения, включая сообщение «Отображаем весь список машин.»

Первое:

$ cd /var/www/yii-dev/runtime/logs/
$ tail -f app.log

У вас должна показаться маленькая часть лога, но это так и должно быть.

Второе:

Теперь зайдите на страницу http://yii.loc/car и следите за консолью, у вас должны начать появляться новые строчки. Должно быть похожее на следующее:

    kcu.constraint_schema = rc.constraint_schema AND
    kcu.constraint_name = rc.constraint_name
WHERE rc.constraint_schema = database() AND kcu.table_schema = database()
AND rc.table_name = 'cars' AND kcu.table_name = 'cars'
    in /var/www/yii-dev/models/search/CarSearch.php:44
    in /var/www/yii-dev/controllers/CarController.php:33
2017-09-02 22:11:09 [127.0.0.1][-][-][info][application] Отображаем весь список машин.
    in /var/www/yii-dev/controllers/CarController.php:35
2017-09-02 22:11:09 [127.0.0.1][-][-][info][yii\db\Command::query] SELECT COUNT(*) FROM `cars`
    in /var/www/yii-dev/views/car/index.php:40
    in /var/www/yii-dev/controllers/CarController.php:40
2017-09-02 22:11:09 [127.0.0.1][-][-][info][yii\db\Command::query] SELECT * FROM `cars` LIMIT 20
    in /var/www/yii-dev/views/car/index.php:40
    in /var/www/yii-dev/controllers/CarController.php:40
2017-09-02 22:11:09 [127.0.0.1][-][-][info][yii\web\Session::open] Session started
    in /var/www/yii-dev/views/layouts/main.php:43
    in /var/www/yii-dev/controllers/CarController.php:40

Выделенная строка — это и есть то, что мы указали используя Yii::info(). Как видите, у сообщения следующий формат:

2017-09-02 22:11:09 [127.0.0.1][-][-][info][application]

Где вначале — это дата и время, потом IP — сейчас это localhost, два пустых значения, которые не указаны, и что уровень — это «info». В самом конце выводится текст лога.

Фильтр логов

Теперь представьте, что у вас большое приложение и куча логов. У вас наверняка нет возможности читать все что там написано и нужно отфильтровать только самое нужно.

Например, давайте покажем только сообщения с уровнем «[info]». Мы так же будет использовать tail, но с использованием grep:

$ tail -f app.log | grep "\[info\]"

«[» и «]» нужно экранизировать, используя «\», так как иначе выведутся все логи, в которых есть буквы «i», «n», «f» и «o» — что нам НЕ нужно.

Теперь зайдите на /car и следите за консолью. У вас должно отображаться что-то похожее на это:

Yii2 basic tail -f | grep логирование

Если вы не видите изменений в логах при tail -f

Вероятнее всего, у вас НЕ стоят права на доступ к файлу у Apache — это решается просто:

$ sudo cd /var/www/yii/dev/
$ sudo chown -R www-data:www-data runtime/*

Теперь снова попробуйте описываемые инструкции выше, по поводу tail и в этот раз должно получиться.

Если логи до сих пор не записываются, тогда напишите комментарий ниже к этой записи, я постараюсь вам помочь.

Сделаем настоящие логи

Нам нужно подправить , actionUpdate() и actionDelete() в controllers/CarController.php, потому что в них происходят самые важные изменения данных в базе и если они будут происходить третьими лицами — это будет плохо, поэтому нужно всё логировать.

Вы можете добавить логи для actionCreate(), но это уже на ваше личное усмотрение.

Откройте CarController и замените behaviors() на следующее:

public function behaviors()
{
    return [
        'access' => [
            'class' => AccessControl::className(),
            'only' => ['index', 'view', 'create', 'delete'],
            'rules' => [
                [
                    'actions' => ['index', 'view', 'create', 'delete'],
                    'allow' => true,
                    'roles' => ['@'],
                ],
            ],
        ],
        'verbs' => [
            'class' => VerbFilter::className(),
            'actions' => [
                'delete' => ['POST'],
            ],
        ],
    ];
}

Выделенные строки выше — это те, которые были добавлены. Мы добавили новое значение 'access', которое определяет доступ к action’ам. Мы указываем, что хотим использовать класс AccessControll, говорим, что хотим фильтровать только (only): index, view, create и delete методы. Разрешаем доступ (allow), только для авторизованных пользователей ('roles' => '@'). «@» означает, что доступ будет только у авторизованных пользователей. Альтернатива для гостей будет — «?».

Так же нам нужно создать приватный атрибут $_user перед behavious(), который будет держать текущую информацию о пользователе. Выглядит это следующим образом:

class CarController extends Controller
{
    /**
     * @var null|User
     */
    private $_user = null;

    public function behaviors()
    {
    ...

Нам так же нужно заполнить $_user информацией о текущем пользователе. В Yii2, для получения данных о текущем пользователе используется команда Yii::$app->user. У нее есть множества вариантов использования, например узнать пользователь авторизован или нет (Yii::$app->user->isGuest) или же получить данные о пользователе (Yii::$app->user->identity). Нас интересует Yii::$app->user->identity.

После behaviours() добавьте новый метод beforeAction():

/**
 * @inheritdoc
 */
public function beforeAction($action)
{
    if ($this->_user === null)
        $this->_user = Yii::$app->user->identity;

    return parent::beforeAction($action);
}

Метод beforeAction() запускается до того как идет использование action’ов контроллера. Тем самым, каждый раз когда вы будите заходит на car/index и др, перед этим в $_user будут записаны данные от текущего, авторизованного пользователя. Это нам поможет понят кто именно изменяет или удаляет машину.

Теперь мы можем записывать логи.

actionUpdate()

public function actionUpdate($id)
{
    $model = $this->findModel($id);

    if ($model->load(Yii::$app->request->post())) {

        if ($model->save()) {
            Yii::info("Машина ID: {$model->id} была изменена {$this->_user->username}");
        } else {
            Yii::error("Машина ID: {$model->id} НЕ была изменена {$this->_user->username}. Возможные ошибки модели: " . json_encode($model->errors));
        }

        return $this->redirect(['view', 'id' => $model->id]);
    } else {
        return $this->render('update', [
            'model' => $model,
        ]);
    }
}

Из actionUpdate(), я вытащил метод save() из первоначального if и вставил внутри него, чтобы записывать нужные мне логи при save(), так как он возвращает булевое значение. Если машина, сохранена, тогда я записываю в логи, что все окей, используя статический метод Yii::info(), в случае, если не удалось сохранить, то в действие идет Yii::error(), который запишет ошибку.

actionDelete()

public function actionDelete($id)
{
    $model = $this->findModel($id);

    $modelId = $model->id;

    if ($model->delete()) {
        Yii::info("Машина ID: {$modelId} была удалена {$this->_user->username}");
    } else {
        Yii::error("Машина ID: {$modelId} НЕ была удалена {$this->_user->username}. Возможные ошибки модели: " . json_encode($model->errors));
    }

    return $this->redirect(['index']);
}

Логика этого action’а почти схожа с actionUpdate(), только в этом используется метод помощник — delete(), который удаляет запись из таблицы. Это достаточно серьезный action и мы должны понимать кто и что удалил, потому что если будет несколько пользователей и каждый «втихоря» будет удалять автомобили и вам нужно будет потом разобраться кто и что удалил, то логи вам в этом помогут.

Тестируем собственные логи

Вернемся немного назад и вспомним про tail -f и grep, которые мы использовали для чтения логов. Сейчас они там тоже пригодятся.

Чтобы понимать, что все работает как нужно:

  • зайдите на страницу изменения любого автомобиля (если у вас нет, то добавьте один).
  • откройте консоль, зайдите в директорию с логами: /var/www/yii-dev/runtime/logs/ и начните следить за данными фильтруя их:
$ tail -f app.log | grep "\[info\]"

Теперь введите другое название автомобиля и нажмите сохранить. В консоли, вы должны увидеть следующее:

2017-09-09 11:41:51 [127.0.0.1][1][-][info][yii\db\Connection::open] Opening DB connection: mysql:host=localhost;dbname=yii_loc
2017-09-09 11:41:51 [127.0.0.1][1][-][info][yii\db\Command::query] SHOW FULL COLUMNS FROM `user`
2017-09-09 11:41:51 [127.0.0.1][1][-][info][yii\db\Command::query] SELECT
2017-09-09 11:41:51 [127.0.0.1][1][-][info][yii\db\Command::query] SHOW FULL COLUMNS FROM `cars`
2017-09-09 11:41:51 [127.0.0.1][1][-][info][yii\db\Command::query] SELECT
2017-09-09 11:41:51 [127.0.0.1][1][-][info][yii\db\Command::query] SELECT * FROM `cars` WHERE `id`='7'
2017-09-09 11:41:51 [127.0.0.1][1][-][info][application] Машина ID: 7 была изменена admin
2017-09-09 11:41:51 [127.0.0.1][1][-][info][application] $_GET = [
2017-09-09 11:41:51 [127.0.0.1][1][-][info][yii\web\Session::open] Session started

Выделенная строка — это то, что вам интересует. Тоже самое должно произойти, когда вы попытаетесь удалить автомобиль. Но это уже проверите сами ;)

Yii2 debug модуль

Yii2 выпустил свой дебаг модуль (yii\gii\Module), который очень удобный в использовании и 100% вам пригодится во время разработки для сравнивания скорости загрузки, SQL запросов и другим показателям.

Визуально этот модуль должен находится в правом нижнем углу:

Yii2 debug модуль

Если нажать на стрелочку, то он откроется и выглядит это следующим образом:

Yii2 debug модуль в открытом формате

Но это не все, вы можете открыть еще больше. Давайте возьмем скрин выше и попробуем его разобрать:

  • нажав на вкладку «Log 10», где 10 — это кол-во логов записанное при открытии текущей страницы
  • так же, тут показывается сколько времени ушло на открытие страницы (36 миллисекунд), и что для этого понадобилось всего 3.5 мб памяти
  • сделано 6 SQL запросов и на это ушло всего 4 миллисекунды
  • Так же, показывается информацию о текущем пользователе, если вы нажмете на «User 1»
  • вы можете посмотреть все js/css и др. assets который были подгружены нажав на «Asset Bundles», всего 6

 

Читать далее — Yii2 basic: Запускаем проект, выходим в production

Об авторе

Full-stack разработчик. Люблю кодить, кофе и свой блог.