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

Запускается вывод с использованием консоли линукс пробросом по ssh вывода из логов. Плюсом стала минимальная нагрузка при этом на сервер, так как все вычисления происходят на локальной странице. Помогает в подсчетах небольшой php скрипт на вход которого поступает вывод данных из /var/log/apache2/access.log который в свое время подсвечивает важные части лога яркой подсветкой.

К сожалению стандартных уровней логирования подходящих под мои условия я не нашел, В моем случае важным параметром было имя хоста куда приходит запрос, но параметр %V который отвечает за вывод полного имени хоста в стандартных настройках отсутствовал. Пришлось дописать нужные параметры к common

LogFormat "%h %V %l %u %t \"%r\" %>s %O %D" common

Важно видеть в подобной ленте ботов, эту задачу помогла решить установка вывода в лог ДНС имени клиента. Эта настройка также выключена по умолчанию в конфигурационном файле.

HostnameLookups On

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



Ну и сам скрипт который отображает данный вывод.

/usr/local/bin/log.php

<?php

$colors = array(
	"200"=>"[0;32m", "404"=>"[1;31m", "410"=>"[0;31m", "403"=>"[0;91m", "301"=>"[1;33m", "302"=>"[1;36m", "304"=>"[1;36m",
); # Цвета статусов
$bots = array("localhost", "googlebot", "yandex", "spider", "ahrefs", "mail.ru", "bot"); # Шаблон имен ботов, отображается более темным

$url = ["login", "admin"]; # Интересующие адреса будут подсвечиваться в ленте

require "/home/mpak2/www/idna_convert.class.inc";
$idna = new idna_convert();
$in = fopen('php://stdin', 'r');
$tm = []; $t = microtime(true); $nn = 0; $microtime = microtime(true);
while($str = fgets($in)){
	if(!$ar = explode(" ", $str)){ print_r("Ошибка формирования массива элементов");
	}elseif(!$n = number_format($nt = (100*(count($tm)-1)+($nn%100))/(microtime(true)-$t), 2)){ print_r("Ошибка форматирования времени генерации ресурса");
	}elseif(!($percent = number_format((array_sum(array_column($tm, 'msec'))/1e6)/(microtime(true)-$t)*100, 2)) & false){ print_r("Ошибка вычисления процента загрузки");
	}elseif(!$mtime = $ar[11]/1e6){ print_r("Ошибка вычисления время обработки ресурса");
	}elseif(!$mtm = (($_tm = number_format($mtime, 3)) > 1 ? "\e[1;31m{$_tm}\e[0m" : $_tm)){ print_r("Ошибка форматирования микровремени");
	}elseif(!$uri = urldecode($ar[7])){ mpre("Ошибка адрес не определен");
	}elseif(!$uri = (array_filter(array_map(function($u) use($uri){ return strpos($uri, $u); }, $url)) ? "\e[1;37m". urldecode($ar[7]). "\e[0m" : urldecode($ar[7]))){ print_r("Локальный адрес не установлен");
#	}elseif(!$uri = "/какой-то/адрес"){ mpre("Замена адреса");
	}elseif(!$status = (array_key_exists($ar[9], $colors) ? "\e{$colors[$ar[9]]}{$ar[9]}\e[0m" : $ar[9])){ print_r("Ошибка раскрашивания статуса");
	}elseif(!$host = "\e[1;34m". $idna->decode($ar[1]). "\e[0m"){ print_r("Ошибка определения хоста запроса");
#	}elseif(!$host = "хабра-хабр.рф"){ print_r("Замена имени хоста на звездочки");
	}elseif(!$bot = ((array_filter(array_map(function($b) use($ar){ return (strpos($ar[0], $b) !== false ? $b : false); }, $bots))) ? "\e[1;35m{$ar[0]}\e[0m" : "\e[1;32m{$ar[0]}\e[0m")){ print_r("Ошибка определения бота");
	}elseif(!$size = number_format($ar[10]/1024, 2). "КБ"){ print_r("Ошибка определения размера запроса");
	}else{// print_r($ar);
		if(($nn++ % 100) == 0){
			array_unshift($tm, ['msec'=>0, 'microtime'=>microtime(true)]);
			if(count($tm) > 10){
				$t = array_pop($tm)['microtime'];
			}
		} if(!($nn % 1000) && ($cmd = "echo '". strtr($n, ['.'=>' ']). "' | festival --tts --language russian &")){
			passthru($cmd);
		} $tm[0]['msec'] += $ar[10];

		passthru("echo '{$nn} {$n} {$percent}% {$mtm}c {$status} http://{$host}{$uri} ({$bot}) {$size}'");
	}
};

Запускается командой: ssh root@хабра-хабр.рф 'tail -f /var/log/apache2/access.log' | php -f /usr/local/bin/log.php
Поделиться с друзьями
-->

Комментарии (27)


  1. NorthDakota
    07.09.2016 19:33

    tail -f access.log не?


    1. Shtucer
      07.09.2016 20:55

      скорее

      grc | tail -f access.log

      смысл в подсветке, как я понимаю, но с самописными костылями.


      1. mpakep
        07.09.2016 22:00

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


      1. Merkat0r
        07.09.2016 22:01

        дожили…


        1. chemistmail
          07.09.2016 22:11

          И не говори…
          стутус был последним перышком, сломавшим спину верблюда.


        1. Shtucer
          07.09.2016 22:12

          А что не так? Чересчур по-хипстерски? Можно рассмотреть вариант на awk.


          1. chemistmail
            07.09.2016 22:21

            cat log | grep 'что надо' > предмет_для_изучения

            sort, uniq, sed, awk для большей детализации.

            Это не по хипстерски, это детский сад.

            Не публикуй такое.


            1. Shtucer
              07.09.2016 22:29

              Не совпадает с условиями задачи же. А задача у человека была «смотреть матрицу». Ну и cat log это то ещё средство… особенно в случае с неротируемым логом эдак за недельку (видал и поболее, всякое бывает). А кому-то без ELK жизнь не мила. На всякий шуруп свой молоток на пхп напишем. :)


              1. mpakep
                07.09.2016 22:34
                +1

                На втором мониторе у меня сейчас постоянно такая лента идет. Специально искать по логам «не зная что» ни времени нет ни желания. А когда что то постоянно течет глаз зам выхватывает из потока нестандартные запросы и адреса. На мой взгляд скорость реакции на многие вещи возросла многократно. Недавно к примеру заметил активность. То ли парсер, то ли новая поисковая система, делала десятки запрово в секунду чем сильно напрягала сервер. Проблема быстро была устранена.


            1. Shtucer
              07.09.2016 22:38
              +2

              И да, почему cat log | grep 'что надо' вместо grep 'что надо' log и почему такое можно публиковать?


  1. chemistmail
    07.09.2016 21:58
    +1

    Что за детский сад?
    Учится конечно нужно, и важно, но голову включать тоже стоит. Не стоит писать такие вещи.

    > 100 запросов в секунду тоже глазами смотреть?
    а > 1000?
    a > 10000?


    1. mpakep
      07.09.2016 22:04

      Обычно задача стоит выдернуть из потока запросов требующих внимание. У меня такие попадались в форме нестандартных статусов или некорректных адресов. На вывод можно применить фильтра | grep 404 и более внимательно изучить.


      1. chemistmail
        07.09.2016 22:14

        Боюсь спросить про нестандартные статусы? RFC изменили а я не в курсе?


        1. mpakep
          07.09.2016 22:28

          Нестандартные это я не правильно выразился. Скорее неожиданные. Те, которые не ожидал увидеть. А с подсветкой они становятся куда заметрее. Было бы сложнее увидеть такой в логе.


    1. chemistmail
      07.09.2016 22:08

      Боги… За что…


    1. ValdikSS
      08.09.2016 14:37
      +1

      > 100 запросов в секунду тоже глазами смотреть?
      а > 1000?
      a > 10000?
      Да, а в чем проблема? Постойте-ка, неужели ни автор, ни люди в комментариях не знают про специализированные утилиты для работы с журналом, вроде lnav, и goaccess, или об утилитах, предназначенных для удобной работы с текстовыми файлами, которые и разукрасят их, и отфильтруют в реальном времени, вроде multitail, или хотя бы об утилитах, предназначенных для фильтрования вывода в реальном времени, вроде peco/percol/fzf?


  1. mpakep
    07.09.2016 22:05

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


  1. ALexhha
    07.09.2016 22:13
    +1

    Я бы предложил обратить внимание на goaccess. Вот там удобно в реальном времени смотреть кто портит жизнь вашему веб серверу.


    1. mpakep
      07.09.2016 22:16

      Спасибо. Буду изучать.


    1. mpakep
      07.09.2016 22:46

      Как в goaccess с русскими адресами? Знаю не много по сейчас корректно с punycode умеет работать.


  1. demimurych
    08.09.2016 11:47

    А не было желания задуматься — почему HostnameLookups по умолчанию выключен?


    1. mpakep
      08.09.2016 14:55
      -1

      Предполагаю это увеличивает ресурсы нужные для работы. Если они незначительные можно ими пренебречь. Количество поймынных с помощью этой функции багов с лихвой компенсирует ресурсы затраченные на запрос к ДНС серверу. К тому же в любой момент можно вернуться к исходным настройкам когда станет понятно что исправлять нам нечего.


  1. megazloj
    08.09.2016 14:15

    А еще есть apachetop


    1. mpakep
      08.09.2016 14:57

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


      1. megazloj
        08.09.2016 14:58

        С кириллическими доменами не сталкивался в логах, поэтому не могу ответить на вопрос


  1. artzub
    08.09.2016 14:56

    Если просто нагрузку смотреть то я предпочитаю logstalgia
    можно по ssh tail -f сделать и завернуть выдачу в logstalgia и смотреть на своей машине.


  1. shep
    08.09.2016 20:42

    Может еще более хипстерский, но и более красивый вариант: ставите piwik, настраиваете отправку логов в него и имеете очень удобный настраиваемый дэшборд реального времени + возможность аналитики.