[recovery mode] Просмотр запросов к веб серверу apache в реальном времени08.09.2016 10:48

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

"[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

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

NorthDakota

7 сентября 2016 в 19:33

0

↑

↓

tail -f access.log не?
- Shtucer
  
  7 сентября 2016 в 20:55
  
  0
  
  ↑
  
  ↓
  скорее
```
grc | tail -f access.log
```
  смысл в подсветке, как я понимаю, но с самописными костылями.
  - mpakep
    
    7 сентября 2016 в 22:00
    
    0
    
    ↑
    
    ↓
    
    Не только. Первоначальная мысль была в подсчете количества запросов в секунду и времени обработки каждого запроса. Потом были добавлены процент загрузки и подсвечены боты. Также удобно наблюдать за определенными адресами. По определенному шаблону наблюдаю за обращениями к новым запросам и статусами ответов, перенаправлений, стутусом удаления страницы и других ошибок.
  - Merkat0r
    
    7 сентября 2016 в 22:01
    
    0
    
    ↑
    
    ↓
    
    дожили…
    - chemistmail
      
      7 сентября 2016 в 22:11 (комментарий был изменён)
      
      0
      
      ↑
      
      ↓
      
      И не говори…
      стутус был последним перышком, сломавшим спину верблюда.
    - Shtucer
      
      7 сентября 2016 в 22:12
      
      0
      
      ↑
      
      ↓
      
      А что не так? Чересчур по-хипстерски? Можно рассмотреть вариант на awk.
      - chemistmail
        
        7 сентября 2016 в 22:21
        
        0
        
        ↑
        
        ↓
        
        cat log | grep 'что надо' > предмет_для_изучения
        sort, uniq, sed, awk для большей детализации.
        Это не по хипстерски, это детский сад.
        Не публикуй такое.
        
        Shtucer
        
        7 сентября 2016 в 22:29
        
        0
        
        ↑
        
        ↓
        
        Не совпадает с условиями задачи же. А задача у человека была «смотреть матрицу». Ну и cat log это то ещё средство… особенно в случае с неротируемым логом эдак за недельку (видал и поболее, всякое бывает). А кому-то без ELK жизнь не мила. На всякий шуруп свой молоток на пхп напишем. :)
        
        mpakep
        
        7 сентября 2016 в 22:34
        
        0
        
        ↑
        
        ↓
        
        На втором мониторе у меня сейчас постоянно такая лента идет. Специально искать по логам «не зная что» ни времени нет ни желания. А когда что то постоянно течет глаз зам выхватывает из потока нестандартные запросы и адреса. На мой взгляд скорость реакции на многие вещи возросла многократно. Недавно к примеру заметил активность. То ли парсер, то ли новая поисковая система, делала десятки запрово в секунду чем сильно напрягала сервер. Проблема быстро была устранена.
        
        Shtucer
        
        7 сентября 2016 в 22:38
        
        0
        
        ↑
        
        ↓
        
        И да, почему cat log | grep 'что надо' вместо grep 'что надо' log и почему такое можно публиковать?
chemistmail

7 сентября 2016 в 21:58

0

↑

↓

Что за детский сад?
Учится конечно нужно, и важно, но голову включать тоже стоит. Не стоит писать такие вещи.
> 100 запросов в секунду тоже глазами смотреть?
, а > 1000?
a > 10000?
- mpakep
  
  7 сентября 2016 в 22:04
  
  0
  
  ↑
  
  ↓
  
  Обычно задача стоит выдернуть из потока запросов требующих внимание. У меня такие попадались в форме нестандартных статусов или некорректных адресов. На вывод можно применить фильтра | grep 404 и более внимательно изучить.
  - chemistmail
    
    7 сентября 2016 в 22:14
    
    0
    
    ↑
    
    ↓
    
    Боюсь спросить про нестандартные статусы? RFC изменили, а я не в курсе?
    - mpakep
      
      7 сентября 2016 в 22:28
      
      0
      
      ↑
      
      ↓
      
      Нестандартные это я не правильно выразился. Скорее неожиданные. Те, которые не ожидал увидеть. А с подсветкой они становятся куда заметрее. Было бы сложнее увидеть такой в логе.
- chemistmail
  
  7 сентября 2016 в 22:08 (комментарий был изменён)
  
  0
  
  ↑
  
  ↓
  
  Боги… За что…
mpakep

7 сентября 2016 в 22:05

0

↑

↓

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

7 сентября 2016 в 22:13

0

↑

↓

Я бы предложил обратить внимание на goaccess. Вот там удобно в реальном времени смотреть кто портит жизнь вашему веб серверу.
- mpakep
  
  7 сентября 2016 в 22:16
  
  0
  
  ↑
  
  ↓
  
  Спасибо. Буду изучать.
- mpakep
  
  7 сентября 2016 в 22:46
  
  0
  
  ↑
  
  ↓
  
  Как в goaccess с русскими адресами? Знаю не много по сейчас корректно с punycode умеет работать.