squid, использование опции debug_options или диагностика компонентов squid

Июнь 3rd, 2013 Рубрики: Linux, SQUID, Настройка сервера Linux

Категорически Всеdebug_optionsх приветствую у себя в блоге ) Во время базовой настройки squid, а так же аутентификации squid в AD довелось довольно часто и много траблшутить squid. В связи с этим, накопился некоторый объем сопутствующей и , возможно, полезной информации о диагностике squid, которой с Вами я спешу поделиться. Стоит отметить, что данная информация актуальна для squid версии 3.1. Возможно, для более старших версий что-то изменится... Как ни странно, в интернете я не смог найти более-менее наглядного материала по данному вопросу. Ни на английском, ни на русском. Страница документации squid debug_options так же не очень  многословна, wiki - аналогично.

Диагностика squid

Начать я хочу не с секции debug_options, а с общих рекомендаций:

  1. Не забывайте о наличии общих команд Linux, позволяющих диагностировать работу сервиса (например netstat и ps)
  2. У squid3 имеется несколько ключей запуска, которые позволяют осуществить некоторый объем диагностики. Среди данных ключей под нашу задачу можно выделить:
    1. -k команда - послать команду работающему серверу, при этом команда - есть:
      • reconfigure - посылка сигнала HUP - перечитать и использовать файл конфигурации (стоит использовать после parse). Стоит отметить, что при обработке команд reconfigure/rotate, Squid закрывает все соединения и открывает их заново, поэтому при большом количестве клиентов лучше этого не делать — создадите кому-то небольшой дискомфорт.
      • check - проверить корректность работы squid (без сообщений - работает корректно); сигнал ZERO (полезно в процессе работы)
      • parse - проверить синтаксис squid.conf
    2. -d - запуск squid3 для вывода отладочной информации на stderr
    3. -l facility - указать источник для записей в syslog 
    4. -X - включить 9 уровень журналирования при разборе конфига (для использования с -k parse)
  3. ну и не забывайте о наличии раздела настройки squid, в котором можно почерпнуть достаточно информации для исходной правильной конфигурации.

Опция debug_options в squid.conf

Если вышеприведенных инструментов будет недостаточно, можно заставить squid быть более разговорчивым с помощью опции debug_options в squid.conf. Давайте разберем синтаксис опции:

debug_options rotate=N section,verbosity [section,verbosity]...

Здесь, параметр rotate=N задает количество хранимых файлов cache.log при ротации. По-умолчанию, данное значение равно единице. Параметр section задает секцию (компонент squid), которая будет отправлять сообщения журналирования. На данном месте возможно использовать значение ALL (как говорит документация magic word "ALL"), которое обозначает все секции компоненты. Параметр verbosity указывает уровень критичности сообщений, записываемых в лог. Данный параметр может принимать следующие значения (некоторые не знал, как перевести):

Уровень Verbosity
Описание
0 Только сообщения критичного/смертельного (critical or fatal) уровня.
1 Уровни Warnings и important.
2 На данном уровне будут логироваться сообщения the minor problems, recovery, and regular high-level actions.
3-5 Сообщения, уровня пользовательской детализации.
6-9 Уровень выше 5го очень "многословен" ) Выводятся в лог отдельные события, сигналы, обращения к памяти/файлам.

Могу сказать, что в реальной жизни редко приходится использовать уровень выше 5го.

Параметр section в debug_options

Давайте приступим к самому интересному. Ниже я приведу список значений поля section для опции debug_options, описание каждого значения и пример лога, который формируется при использовании секции.

section -- и 00

-- CGI Cache Manager
-- External DISKD process implementation.
-- Refcount allocator
-- Unlink Daemon
-- WWW Client
00 Announcement Server
00 Client Database
00 DNS Resolver Daemon
00 Debug Routines
00 Hash Tables
00 UFS Store Dump Tool
-- и 00 - ХЗ, активности не замечено

section 01

01 Main Loop
01 Startup and Main Loop
01 - хорошо просматриваются стартовый парсинг системных конфигов, таких как /etc/hosts, resolv.conf и др.

section 02 и 03

02 Unlink Daemon
03 Configuration File Parsing
03 Configuration Settings
03 - ХЗ, активности не замечено

section 04 Error Generation

04 - дебаг формирования страниц ошибок squid  (хорошо видна подмена переменных, используемых в HTML коде в страниц ошибок)

section 05

05 Comm
05 Socket Functions
05 - Довольно не наглядный лог, не о чем не сказало. Куча инфы о сокетах в виде:

The AsyncCall comm_close_complete constructed, this=0x95b6b78 [call3644] или commSetSelect(FD 12,type=1,handler=0,client_data=0,timeout=0)

section 06 Disk I/O Routines

06 - статистика обращений к файлам на диске, в виде

2012/03/23 22:52:23.483| file_open: FD 7
2012/03/23 22:52:23.483| file_close: FD 7 really closing

или

2012/03/23 22:53:59.443| file_open: FD 66
2012/03/23 22:53:59.443| diskHandleWrite: FD 66
2012/03/23 22:53:59.443| diskHandleWrite: FD 66
2012/03/23 22:53:59.443| diskHandleWrite: FD 66 writing 111 bytes
2012/03/23 22:53:59.444| diskHandleWrite: FD 66 len = 111
2012/03/23 22:53:59.444| diskHandleWrite: FD 66
2012/03/23 22:53:59.444| diskHandleWrite: FD 66 writing 4096 bytes
2012/03/23 22:53:59.444| diskHandleWrite: FD 66 len = 4096
2012/03/23 22:53:59.447| diskHandleWrite: FD 66
2012/03/23 22:53:59.447| diskHandleWrite: FD 66 writing 1054 bytes
2012/03/23 22:53:59.447| diskHandleWrite: FD 66 writing 1054 bytes
2012/03/23 22:53:59.447| diskHandleWrite: FD 66 len = 1054
2012/03/23 22:53:59.447| diskHandleWrite: FD 66 len = 1054
2012/03/23 22:53:59.448| file_close: FD 66 really closing

section 07 Multicast

07 - по логике - должен писать что-то о мультикасте, но нет возможности протестировать

section 08 Swap File Bitmap

08 - хз

section 09 File Transfer Protocol (FTP)

09 - хорошо диагностирует FTP (если он у Вас разрешен к проксированию), достаточно уровня журнала 2-3. Все наглядно и понятно.

section 10 Gopher

гофером не пользуюсь, а вы? )

section 10 Hypertext Transfer Protocol (HTTP)

11 - записывает процесс обмена клиентом с удаленным сервером через сквид, при этом, при 9 уровне пишет все, вплоть до развернутых HTTP-ответов. Пример запроса http://www.k-max.name/favicon.ico на 3 уровне лога:

2012/03/23 23:13:05.761| httpStart: "GET http://www.k-max.name/favicon.ico"
2012/03/23 23:13:05.804| ctx: enter level 0: 'http://www.k-max.name/favicon.ico'
2012/03/23 23:13:05.804| processReplyHeader: key '71A136F1A710CA94CD009859AD58D03D'
2012/03/23 23:13:05.804| ctx: exit level 0
2012/03/23 23:13:05.804| ctx: enter level 0: 'http://www.k-max.name/favicon.ico'
2012/03/23 23:13:05.804| haveParsedReplyHeaders: HTTP CODE: 304
2012/03/23 23:13:05.804| haveParsedReplyHeaders: HTTP CODE: 304
2012/03/23 23:13:05.804| ctx: exit level 0
2012/03/23 23:13:05.804| persistentConnStatus: FD 11 eof=0
2012/03/23 23:13:05.804| Server.cc(225) quitIfAllDone: transaction done

Запрос того же http://www.k-max.name/favicon.ico на 9 уровне:

Показать debug лог »

2012/03/23 23:14:04.861| httpStart: "GET http://www.k-max.name/favicon.ico"
2012/03/23 23:14:04.861| http.cc(83) HttpStateData: HttpStateData 0xa5b8a78 created
2012/03/23 23:14:04.861| httpSendRequest: FD 11, request 0xa4e1a88, this 0xa5b8a78.
2012/03/23 23:14:04.861| The AsyncCall HttpStateData::httpTimeout constructed, this=0xa783830 [call16817]
2012/03/23 23:14:04.861| http.cc(1392) maybeReadVirginBody: may read up to 2047 bytes from FD 11
2012/03/23 23:14:04.861| The AsyncCall HttpStateData::readReply constructed, this=0x94b0fb0 [call16818]
2012/03/23 23:14:04.861| The AsyncCall HttpStateData::SendComplete constructed, this=0xa524a20 [call16819]
2012/03/23 23:14:04.861| The AsyncCall HttpStateData::readReply constructed, this=0x94b0fb0 [call16818]
2012/03/23 23:14:04.861| The AsyncCall HttpStateData::SendComplete constructed, this=0xa524a20 [call16819]
2012/03/23 23:14:04.861| decideIfWeDoRanges: range specs: 0, cachable: 1; we_do_ranges: 0
2012/03/23 23:14:04.861| httpBuildRequestHeader: Host: www.k-max.name
2012/03/23 23:14:04.861| httpBuildRequestHeader: Host: www.k-max.name
2012/03/23 23:14:04.862| httpBuildRequestHeader: User-Agent: Mozilla/5.0 (Windows NT 5.1; rv:10.0.2) Gecko/20120302 Firefox/10.0.2
2012/03/23 23:14:04.862| httpBuildRequestHeader: User-Agent: Mozilla/5.0 (Windows NT 5.1; rv:10.0.2) Gecko/20120302 Firefox/10.0.2
2012/03/23 23:14:04.862| httpBuildRequestHeader: Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
2012/03/23 23:14:04.862| httpBuildRequestHeader: Accept-Language: ru-ru,ru;q=0.8,en-us;q=0.5,en;q=0.3
2012/03/23 23:14:04.862| httpBuildRequestHeader: Accept-Encoding: gzip, deflate
2012/03/23 23:14:04.862| httpBuildRequestHeader: Proxy-Connection: keep-alive
2012/03/23 23:14:04.862| httpBuildRequestHeader: If-Modified-Since: Fri, 31 Dec 2010 16:47:34 GMT
2012/03/23 23:14:04.862| httpBuildRequestHeader: If-None-Match: "a319b-7a2-8f181580"
2012/03/23 23:14:04.862| httpBuildRequestHeader: If-None-Match: "a319b-7a2-8f181580"
2012/03/23 23:14:04.862| httpBuildRequestHeader: Cache-Control: max-age=0
2012/03/23 23:14:04.862| httpBuildRequestHeader: Cache-Control: max-age=0
2012/03/23 23:14:04.862| httpSendRequest: FD 11:
GET /favicon.ico HTTP/1.1
Host: www.k-max.name
User-Agent: Mozilla/5.0 (Windows NT 5.1; rv:10.0.2) Gecko/20120302 Firefox/10.0.2
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
Accept-Language: ru-ru,ru;q=0.8,en-us;q=0.5,en;q=0.3
Accept-Encoding: gzip, deflate
If-Modified-Since: Fri, 31 Dec 2010 16:47:34 GMT
If-None-Match: "a319b-7a2-8f181580"
Via: 1.1 gw (squid/3.1.6)
X-Forwarded-For: unknown
Cache-Control: max-age=0
Connection: keep-alive

2012/03/23 23:14:04.862| comm.cc(165) will call HttpStateData::SendComplete(FD 11, data=0xa5b8a78) [call16819]
2012/03/23 23:14:04.862| comm.cc(165) will call HttpStateData::SendComplete(FD 11, data=0xa5b8a78) [call16819]
2012/03/23 23:14:04.862| entering HttpStateData::SendComplete(FD 11, data=0xa5b8a78)
2012/03/23 23:14:04.862| AsyncCall.cc(32) make: make call HttpStateData::SendComplete [call16819]
2012/03/23 23:14:04.862| HttpStateData status in: [ job773]
2012/03/23 23:14:04.862| HttpStateData status in: [ job773]
2012/03/23 23:14:04.862| httpSendComplete: FD 11: size 483: errflag 0.
2012/03/23 23:14:04.862| httpSendComplete: FD 11: size 483: errflag 0.
2012/03/23 23:14:04.862| The AsyncCall HttpStateData::httpTimeout constructed, this=0x94fd3e0 [call16820]
2012/03/23 23:14:04.862| HttpStateData status out: [ job773]
2012/03/23 23:14:04.863| leaving HttpStateData::SendComplete(FD 11, data=0xa5b8a78)
2012/03/23 23:14:04.903| comm.cc(165) will call HttpStateData::readReply(FD 11, data=0xa5b8a78, size=318, buf=0xa47b688) [call16818]
2012/03/23 23:14:04.903| entering HttpStateData::readReply(FD 11, data=0xa5b8a78, size=318, buf=0xa47b688)
2012/03/23 23:14:04.903| AsyncCall.cc(32) make: make call HttpStateData::readReply [call16818]
2012/03/23 23:14:04.903| AsyncCall.cc(32) make: make call HttpStateData::readReply [call16818]
2012/03/23 23:14:04.903| HttpStateData status in: [ job773]
2012/03/23 23:14:04.903| HttpStateData status in: [ job773]
2012/03/23 23:14:04.903| httpReadReply: FD 11: len 318.
2012/03/23 23:14:04.904| ctx: enter level 0: 'http://www.k-max.name/favicon.ico'
2012/03/23 23:14:04.904| processReplyHeader: key '2EFDBB686248DB35939D740C70B8AD65'
2012/03/23 23:14:04.904| GOT HTTP REPLY HDR:
---------
HTTP/1.1 304 Not Modified
Date: Fri, 23 Mar 2012 19:14:04 GMT
Server: Apache/2.0.63-lk.d (Unix) mod_ssl/2.0.63-lk.d OpenSSL/0.9.8o mod_dp20/0.99.2 mod_python/3.3.1 Python/2.6.5 mod_ruby/1.2.6 Ruby/1.8.7(2010-08-16) mod_wsgi/3.3
Connection: Keep-Alive
Keep-Alive: timeout=30, max=128
ETag: "a319b-7a2-8f181580"

----------
2012/03/23 23:14:04.904| Server.cc(136) setVirginReply: 0xa5b8a78 setting virgin reply to 0xa694218
2012/03/23 23:14:04.904| Server.cc(136) setVirginReply: 0xa5b8a78 setting virgin reply to 0xa694218
2012/03/23 23:14:04.904| ctx: exit level 0
2012/03/23 23:14:04.904| Server.cc(819) adaptOrFinalizeReply: adaptationAccessCheckPending=0
2012/03/23 23:14:04.904| Serv delay_pools 1 per.cc(819) adaptOrFinalizeReply: adaptationAccessCheckPending=0
2012/03/23 23:14:04.904| Server.cc(153) setFinalReply: 0xa5b8a78 setting final reply to 0xa694218
2012/03/23 23:14:04.904| ctx: enter level 0: 'http://www.k-max.name/favicon.ico'
2012/03/23 23:14:04.904| haveParsedReplyHeaders: HTTP CODE: 304
2012/03/23 23:14:04.904| ctx: exit level 0
2012/03/23 23:14:04.904| http.cc(1299) processReplyBody: adaptationAccessCheckPending=0
2012/03/23 23:14:04.904| persistentConnStatus: FD 11 eof=0
2012/03/23 23:14:04.904| persistentConnStatus: content_length=-1
2012/03/23 23:14:04.904| persistentConnStatus: content_length=-1
2012/03/23 23:14:04.904| persistentConnStatus: flags.headers_parsed=1
2012/03/23 23:14:04.904| persistentConnStatus: clen=0
2012/03/23 23:14:04.904| processReplyBody: COMPLETE_PERSISTENT_MSG
2012/03/23 23:14:04.904| processReplyBody: COMPLETE_PERSISTENT_MSG
2012/03/23 23:14:04.904| Server.cc(169) serverComplete: serverComplete 0xa5b8a78
2012/03/23 23:14:04.904| Server.cc(194) serverComplete2: serverComplete2 0xa5b8a78
2012/03/23 23:14:04.905| Server.cc(234) completeForwarding: completing forwarding for 0xa5bd180*2
2012/03/23 23:14:04.905| Server.cc(225) quitIfAllDone: transaction done
2012/03/23 23:14:04.905| Server.cc(556) cleanAdaptation: cleaning ICAP; ACL: 0
2012/03/23 23:14:04.905| http.cc(163) ~HttpStateData: HttpStateData 0xa5b8a78 destroyed; FD -1
2012/03/23 23:14:04.905| leaving HttpStateData::readReply(FD 11, data=0xa5b8a78, size=318, buf=0xa47b688)
2012/03/23 23:14:04.905| leaving HttpStateData::readReply(FD 11, data=0xa5b8a78, size=318, buf=0xa47b688)

section 12 Internet Cache Protocol (ICP)

не использую ICP протестить не могу :(

section 12 High Level Memory Pool Management

13 - по всей видимости какая-то информация о памяти, но активности не выявлено

section 12

14 IP Cache
14 IP Storage and Handling
14 - пишется процесс получения/кэширования/очистки кэша IP в виде

2012/03/23 23:19:38.926| ipcache_nbgethostbyname: Name 'mc.yandex.ru'.
2012/03/23 23:19:38.926| ipcache_nbgethostbyname: HIT for 'mc.yandex.ru'
2012/03/23 23:19:38.926| ipcache_nbgethostbyname: HIT for 'mc.yandex.ru'
2012/03/23 23:19:38.926| connecting to: 87.250.250.119:80
2012/03/23 23:19:38.926| connecting to: 87.250.250.119:80
2012/03/23 23:19:43.810| ipcache_purgelru: removed 0 entries

section 15 Neighbor Routines

15 - видимо какая-то информация о соседских кэшах, нет возможности протетсить :(

section 16 Cache Manager Objects

16 - какая-то неразборчивая инфа о диагностике кэш-менеджера

section 17 Request Forwarding

17 - должно отображать какие-то перенаправления, но я не понял, какие (возможно, если используется несколько интерфейсов, или каскадирование кэшей). Зато хорошо видно, какие страницы запрашиваются и видно исходящий адрес/интерфейс для каждой запрашиваемой страницы

section 18 Cache Manager Statistics

18 - тоже что-то связанное с кэш менеджером - актвиности не видно

section 19 Store Memory Primitives

19 - пишет непонятную инфу о использовании памяти в виде

2012/03/23 23:33:23.513| mem_hdr::write: [335,337) object end 335
2012/03/23 23:33:23.513| mem_hdr::write: [335,337) object end 335
2012/03/23 23:33:23.513| memWrite: offset -4 len 2
2012/03/23 23:33:23.513| memWrite: offset -4 len 2

так же, на 4 уровне выводит сообщения

2012/03/23 23:34:35.814| MemObject::isContiguous: Returning true

на сколько понял, если объект отдается из кэша

section 20

20 Storage Manager
20 Storage Manager Heap-based replacement
20 Storage Manager Logging Functions
20 Storage Manager MD5 Cache Keys
20 Storage Manager Swapfile Metadata
20 Storage Manager Swapfile Unpacker
20 Storage Manager Swapin Functions
20 Storage Manager Swapout Functions
20 Store Rebuild Routines
20 Swap Dir base object

20 - пишет какую-то кашу о работе с запрошенными из браузера объектами и взаимодействие этих объектов с памятью/кэшем на диске

section 21

21 Integer functions
21 Misc Functions
21 Time Functions

21 - непонятная инфа. Есть кое-что о присваиваемых PID для squid в виде:

2012/03/23 23:43:10.268| enter_suid: PID 14367 taking root priveleges
2012/03/23 23:43:10.268| leave_suid: PID 14367 called
2012/03/23 23:43:10.268| leave_suid: PID 14367 giving up root, becoming 'proxy'
2012/03/23 23:43:10.268| leave_suid: PID 14367 giving up root, becoming 'proxy'
2012/03/23 23:43:10.268| Accepting HTTP connections at 127.0.0.1:3129, FD 46.

section 22 Refresh Calculation

22 - пишет информацию о обновлении объектов в кэше в виде:

2012/03/23 23:49:12.655| ctx: enter level 0: 'http://www.mmnt.ru/get?st=123&in=f'
2012/03/23 23:49:12.700| refreshCheck: 'http://www.mmnt.ru/get?st=123&in=f'
2012/03/23 23:49:12.700| STALE: age 60 > max 0
2012/03/23 23:49:12.700| Staleness = 60
2012/03/23 23:49:12.700| refreshCheck: Matched '(/cgi-bin/|\?) 0 0%% 0'
2012/03/23 23:49:12.700| Staleness = 60
2012/03/23 23:49:12.700| refreshCheck: Matched '(/cgi-bin/|\?) 0 0%% 0'
2012/03/23 23:49:12.700| refreshCheck: age = 60
2012/03/23 23:49:12.700| check_time: Fri, 23 Mar 2012 19:50:12 GMT
2012/03/23 23:49:12.700| entry->timestamp: Fri, 23 Mar 2012 19:49:12 GMT
2012/03/23 23:49:12.700| refreshIsCachable() returned non-cacheable..

удобно для отработки директив refresh_pattern. Довольно наглядно уже на 4 уровне лога

section 23

23 URL Parsing
23 URL Scheme parsing

23 - хорошо отображает как сквид "разбирает" ссылки по компонентам, на примере

2012/03/23 23:52:22.857| urlParse: Split URL 'http://www.k-max.name/favicon.ico' into proto='http', host='www.k-max.name', port='80', path='/favicon.ico'

section 25

25 MIME Parsing and Internal Icons
25 MiME Header Parsing

25 - отображает MIME типы проходящего через сквид контента (могу предположить, что берет из /etc/mime.types). При рестарте куча строк вида:

....
 2012/03/23 23:56:33.769| mimeInit: added '\.gif$ image/gif anthony-image.gif - image +download'
 2012/03/23 23:56:33.769| mimeInit: added '\.mime$ www/mime anthony-text.gif - ascii +download'
 ....

Думаю, что можно использовать для диагностики ACL req_mime_type или rep_mime_type для блокировки скачивания файлов по типу MIME.

section 26 Secure Sockets Layer Proxy

26 - пишет в лог какое-то месиво при использовании https (3 уровень от 9 не сильно отличается)

section 27 Cache Announcer

27 - ХЗ. Не обнаружено активности даже на 9 уровне

section 28 Access Control

28 - вот эта секция - основа для дебага acl и http_access. На 3 уровне лога уже вполне достаточная активность!

section 29

29 Authenticator
29 NTLM Authenticator
29 Negotiate Authenticator
29 - дебаг аутентификационной информации (малоиннформативный :( )

section 30 и 31

30 Ident (RFC 931)
31 Hypertext Caching Protocol

31 - ХЗ, активности не замечено :(

section 32 Asynchronous Disk I/O

32 - что то связано с IO, но малоинформативно

section 33 Client-side Routines

33 - отображает работу клиентского браузера (из всей каши, имхо интересны только содержимое HTTP-запросов, которое видно уже на 3 уровне дебага)

2012/03/24 00:48:34.431| parseHttpRequest: req_hdr = {Host: www.k-max.name
User-Agent: Mozilla/5.0 (Windows NT 5.1; rv:10.0.2) Gecko/20120302 Firefox/10.0.2
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
Accept-Language: ru-ru,ru;q=0.8,en-us;q=0.5,en;q=0.3
Accept-Encoding: gzip, deflate
Proxy-Connection: keep-alive
Cookie: __utma=238845466.1148771502.1332530869.1332530869.1332535340.2; __utmc=238845466; __utmz=238845466.1332530869.1.1.utmcsr=(direct)|utmccn=(direct)|utmcmd=(none); _ym_visorc=w; __utmb=238845466.2.10.1332535340
If-Modified-Since: Fri, 31 Dec 2010 16:47:34 GMT
If-None-Match: "a319b-7a2-8f181580"
Cache-Control: max-age=0

}
2012/03/24 00:48:34.431| parseHttpRequest: end = {
}
2012/03/24 00:48:34.431| parseHttpRequest: prefix_sz = 674, req_line_sz = 48
2012/03/24 00:48:34.432| clientSetKeepaliveFlag: http_ver = 1.1
2012/03/24 00:48:34.432| clientSetKeepaliveFlag: method = GET
2012/03/24 00:48:34.507| ClientSocketContext::keepaliveNextRequest: FD 106
2012/03/24 00:48:34.507| httpRequestFree: http://www.k-max.name/favicon.ico

section 34 Dnsserver interface

34 - ХЗ....

section 35 FQDN Cache

35 - отображает неинтересную статистику кэша fqdn DNS имен

section 37 ICMP Routines

37 - ХЗ. ICMP не смог помониторить - тишина. Может используется при каскадировании кэшей...

section 38 Network Measurement Database

38 - ХЗ. никакой активности...

section 39

39 Cache Array Routing Protocol
39 Peer source hash based selection
39 Peer user hash based selection

39 - ХЗ. Видимо для работы с соседними кэшами, может быть )

section 40

40 Referer Logging
40 User-Agent Logging

40 - ХЗ. По идее- должен быть лог реферреров и юзер-агентов браузера :( тишина

section 41 Event Processing

41 - пишется какая-то каша событий

section 42 и 43

42 ICMP Pinger program
43 AIOPS
43 Windows AIOPS

42,43 - ХЗ. Какой-то пингер и AIOPS

section 44 Peer Selection Algorithm

44 - используется при применении каскадирования кэшей, протестировать не удалось (

section 45 Callback Data Registry

45 - ХЗ... несусветная каша )

section 46 Access Log

46 - ХЗ. тишина

section 47

47 Store COSS Directory Routines
47 Store Directory Routines

47 - статистика работы с кэшем, для чего может быть использована- не знаю (

section 48 Persistent Connections

48 - какая-то статистика соединений в виде:

2012/03/24 01:10:52.974| PconnPool::push: pushed FD 28 for mc.yandex.ru:80
2012/03/24 01:10:52.981| PconnPool::key(kiks.yandex.ru,80,(no domain),[::]is {kiks.yandex.ru:80}
2012/03/24 01:10:52.981| PconnPool::push: new IdleConnList for {kiks.yandex.ru:80}
2012/03/24 01:10:52.981| PconnPool::push: pushed FD 30 for kiks.yandex.ru:80

section 49

49 SNMP Interface
49 SNMP support

49 - статистика протокола SNMP, к сожалению, не использую. Думаю, что будет актуально для диагностики директив snmp_access, snmp_incoming_address, snmp_outgoing_address, snmp_port

section 50 Log file handling

50 - статистика вида:

2012/03/24 01:13:21.746| comm_openex: Attempt open socket for: 0.0.0.0
2012/03/24 01:13:21.746| comm_openex: Opened socket FD 10 : family=2, type=1, protocol=6
2012/03/24 01:13:21.747| commBind: bind socket FD 10 to 0.0.0.0
2012/03/24 01:13:24.690| comm_old_accept: FD 67: (11) Resource temporarily unavailable
2012/03/24 01:13:24.750| comm_old_accept: FD 67: (11) Resource temporarily unavailable
2012/03/24 01:13:24.760| comm_openex: Attempt open socket for: 0.0.0.0
2012/03/24 01:13:24.761| comm_openex: Opened socket FD 21 : family=2, type=1, protocol=6
2012/03/24 01:13:24.761| commBind: bind socket FD 21 to 0.0.0.0
2012/03/24 01:13:24.761| comm_udp_sendto: Attempt to send UDP packet to 127.0.0.1:53 using FD 8 using Port 54923

section 51 Filedescriptor Functions

51 - отображает какую-то статистику по сокетам при запуске демона:

2012/03/24 01:16:02.704| helperOpenServers: Starting 15/15 'squid_kerb_auth' processes
2012/03/24 01:16:02.705| fd_open() FD 9 IPC UNIX STREAM Parent
2012/03/24 01:16:02.705| fd_open() FD 10 IPC UNIX STREAM Parent
2012/03/24 01:16:02.711| fd_open() FD 11 IPC UNIX STREAM Parent
2012/03/24 01:16:02.711| fd_open() FD 12 IPC UNIX STREAM Parent
....

и по соединениям:

2012/03/24 01:38:28.337| fd_open() FD 61 mailstatic.yandex.net:443
2012/03/24 01:38:28.340| fd_open() FD 62 mailstatic.yandex.net:443
2012/03/24 01:38:28.602| fd_open() FD 63 HTTP Request
2012/03/24 01:38:28.616| fd_open() FD 64 mc.yandex.ru:443
2012/03/24 01:38:33.023| fd_close FD 28 yandex.st:443
2012/03/24 01:38:33.023| fd_close FD 22 Reading next request

section 52 URN Parsing

52 - дебаггинг URN (не использую - не могу проверить)

section 53

53 AS Number handling
53 Radix Tree data structure implementation

53 - ХЗ... Тишина

section 54

54 Interprocess Communication
54 Windows Interprocess Communication

54 - статистика работы с сокетами IPC при запуске...

section 55 HTTP Header

55 - разбор сквидом http запроса от браузера и http ответа от сервера (человекопонятно становиться на 7 уровне, очень подробно - на 9) - ДИАГНОСТИКА запросов/ответов

section 56 HTTP Message Body

56 - тишина :(

section 57 HTTP Status-line

57 - статистика http статусов

section 58 HTTP Reply (Response)

58 - статистика http ответов с развернутым содержимым

section 59 и 60

59 auto-growing Memory Buffer with printf
60 Packer: A uniform interface to store-like modules

ХЗ, тишина

section 61 Redirector

61 - наверно, статистика редиректора (не использую...)

section 62-73

62 Generic Histogram
63 Low Level Memory Pool Management
64 HTTP Range Header
65 HTTP Cache Control Header
66 HTTP Header Tools
67 String
68 HTTP Content-Range Header
69 HTTP Header: Extension Field
70 Cache Digest
71 Store Digest Manager
72 Peer Digest Routines
73 HTTP Request

Заставить работать данные секции мне не удалось.

section 74 HTTP Message

74 - вывод http сообщений с содержимым (важная инфа для дебага), вид при запросе http://www.k-max.name/favicon.ico:

2012/03/24 02:08:21.099| httpParserParseReqLine: parsing GET http://www.k-max.name/favicon.ico HTTP/1.1
Accept: */*
Accept-Language: ru
User-Agent: Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 5.1; Trident/4.0; .NET CLR 1.1.4322; .NET CLR 2.0.50727; .NET CLR 3.0.4506.2152; .NET CLR 3.5.30729)
Accept-Encoding: gzip, deflate
Proxy-Connection: Keep-Alive
Host: www.k-max.name
Pragma: no-cache

2012/03/24 02:08:21.099| Parser: retval 1: from 0->47: method 0->2; url 4->36; version 38->46 (1/1)
2012/03/24 02:08:21.116| httpParseInit: Request buffer is GET http://www.k-max.name/favicon.ico HTTP/1.1
Accept: */*
Accept-Language: ru
User-Agent: Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 5.1; Trident/4.0; .NET CLR 1.1.4322; .NET CLR 2.0.50727; .NET CLR 3.0.4506.2152; .NET CLR 3.5.30729)
Accept-Encoding: gzip, deflate
Proxy-Connection: Keep-Alive
Proxy-Authorization: Negotiate TlRMTVNTUAABAAAAB4IIogAAAAAAAAAAAAAAAAAAAAAFASgKAAAADw==
Pragma: no-cache
Host: www.k-max.name

section 75 WHOIS protocol

75 - видимо должны быть логи при проксировании whois протокола

section 76 Internal Squid Object handling

76 - ХЗ, тишина

section 77 Delay Pools

77 - К сожалению, проводил данные тесты до написания статьи Delay Pools, поэтому лога пока нет

section 78

78 DNS lookups
78 DNS lookups; interacts with lib/rfc1035.c

78 - статистика работы DNS в виде:

2012/03/24 02:13:32.225| idnsALookup: buf is 24 bytes for who.is, id = 0x6d86
2012/03/24 02:13:32.230| idnsRead: starting with FD 8
2012/03/24 02:13:32.230| idnsRead: FD 8: received 117 bytes from 127.0.0.1:53
2012/03/24 02:13:32.230| idnsGrokReply: ID 0x6d86, 1 answers
2012/03/24 02:13:32.230| dns_internal.cc(1115) idnsGrokReply: Sending 1 DNS results to caller.
2012/03/24 02:13:32.643| idnsRead: starting with FD 8
2012/03/24 02:13:32.643| idnsRead: FD 8: received 506 bytes from 127.0.0.1:53

section 79

79 Disk IO Routines
79 Squid-side DISKD I/O functions.
79 Squid-side Disk I/O functions.
79 Storage Manager COSS Interface
79 Storage Manager UFS Interface

79 - статистика работы с кэшем

section 80 WCCP Support

80 - видимо статистика WCPP (не использую WCPP, пока... )) )

section 81

81 CPU Profiling Routines
81 Store HEAP Removal Policies
81 aio_xxx() POSIX emulation on Windows

81 - Думаю, что используется для вендового squid

section 82 External ACL

82 - статистика внешних ACL

section 83 SSL accelerator support

83 - ХЗ, непонятные строки вида:

2012/03/24 02:20:21.422| AccessCheck.cc(30) Start: adaptation off, skipping
2012/03/24 02:20:21.422| client_side_request.cc(1306) doCallouts: Doing calloutContext->clientAccessCheck2()
2012/03/24 02:20:21.422| client_side_request.cc(1313) doCallouts: Doing clientInterpretRequestHeaders()
2012/03/24 02:20:21.422| client_side_request.cc(1348) doCallouts: calling processRequest()

section 84 Helper process maintenance

84 - включение дебага хелперов аутентификации

section 85 Client-side Request Routines

85 - отличный дебаг http_access и acl - кратко и понятно

section 86

86 ESI Expressions
86 ESI processing

86 - ESI не использую, лог получить возможности нет

section 87 Client-side Stream routines.

87 - непонятная каша виде:

2012/03/24 02:26:44.506| clientStreamInsertHead: Inserted node 0xa8d2a78 with data 0xa8d17cc after head
2012/03/24 02:26:44.507| clientStreamRead: Calling 1 with cbdata 0xa8d2928 from node 0xa8d2a78
2012/03/24 02:26:44.581| clientStreamCallback: Calling 1 with cbdata 0xa8d17cc from node 0xa8d2a28
2012/03/24 02:26:44.581| clientStreamDetach: Detaching node 0xa8d2a78
2012/03/24 02:26:44.581| Freeing clientStreamNode 0xa8d2a78
2012/03/24 02:26:44.581| clientStreamAbort: Aborting stream with tail 0xa8d2a28
2012/03/24 02:26:44.581| clientStreamDetach: Detaching node 0xa8d2a28
2012/03/24 02:26:44.581| clientStreamDetach: Calling 1 with cbdata 0xa8d2928
2012/03/24 02:26:44.581| Freeing clientStreamNode 0xa8d2a28
2012/03/24 02:26:44.581| Freeing clientStreamNode 0xa8d2a28

section 88 Client-side Reply Routines

88 - отличный дебаг http_access и acl - кратко и понятно

section 89 NAT / IP Interception

89 - очень полезная секция при дебаге прозрачного прокси.

section 90

90 HTTP Cache Control Header
90 Storage Manager Client-Side Interface

90 - ХЗ. статистика работы с кэшем, вида:

2012/03/24 02:30:14.776| store_client::copy: 04AFD5B6421D00FDA0A0720BDD377B00, from 0, for length 4096, cb 1, cbdata 0xa975af0
2012/03/24 02:30:14.776| storeClientCopy2: 04AFD5B6421D00FDA0A0720BDD377B00
2012/03/24 02:30:14.776| store_client::doCopy: Waiting for more
2012/03/24 02:30:14.857| InvokeHandlers: 04AFD5B6421D00FDA0A0720BDD377B00
2012/03/24 02:30:14.857| StoreEntry::InvokeHandlers: checking client #0
2012/03/24 02:30:14.857| storeClientCopy2: returning because ENTRY_FWD_HDR_WAIT set
2012/03/24 02:30:14.857| storeClientCopy2: returning because ENTRY_FWD_HDR_WAIT set
2012/03/24 02:30:14.857| InvokeHandlers: 04AFD5B6421D00FDA0A0720BDD377B00
2012/03/24 02:30:14.857| InvokeHandlers: 04AFD5B6421D00FDA0A0720BDD377B00
2012/03/24 02:30:14.857| StoreEntry::InvokeHandlers: checking client #0
2012/03/24 02:30:14.857| storeClientCopy2: 04AFD5B6421D00FDA0A0720BDD377B00
2012/03/24 02:30:14.857| store_client::doCopy: Copying normal from memory

section 92-93

section 92 Storage File System
section 93 Adaptation
section 93 ICAP (RFC 3507) Client
section 93 eCAP Interface

Протестировать данные фичи нет возможности (

Итоги (советы) для debug_options

Вот, собственно, это все возможные секции debug_options на данный момент для squid версии 3.1. Из всего приведенного выше, определенно могу сказать, что многие секции дублируют друг-друга, некоторые трудно диагностируемы, т.к. не использую данные технологии. Да и логи по каждой секции предоставить довольно проблематично по причине большего объема и ненаглядности... В связи с этим, я был бы очень благодарен читателям за предоставление образцов логов по секциям, по которым не удалось получить какую-либо информацию, либо за какие-то дополнения о применении не протестированных/не полноценно протестированных секций.

Для управления логированием и уменьшения уровня неактуальных сообщений в логах при масштабном внедрении squid можно использовать следующие директивы:

acl no_log src 192.168.2.0/26
log_access allow no_log 
log_access deny all

Думаю, что тут все довольно наглядно.... Мы хотим продиагностировать клиентов из подсети 192.168.2.0/26, при этом, нам не хотелось бы забивать лог информацией от других IP адресов. Мы задаем указанные правила и в лог попадают только указанные хосты. ИМХО, очень удобно.

Хочу так же привести наглядный пример использования debug_options из SQUID FAQ:

Я установил собственные контроли доступа, но они не работают! Почему?

Если ACL-лы - причина ваших проблем и вы не знаете почему они не работают, вы можете воспользоваться этой инструкцией, чтобы отладить их. В squid.conf включите отладку для секции 33 на уровне 2 (либо больше, если 2 уровня будет не достаточно). К примеру:

debug_options ALL,1 33,2

Потом перезапустите Squid. Теперь, ваш cache.log (и/или access.log ???) должен содержать строку для каждого запроса, которая поясняет запрещен или резрешен запрос и с каким ACL он совпал. Если это не дало вам достаточно информации, чтобы избавиться от проблемы, вы можете также включить детальную отладку процесса обработки ACL

debug_options ALL,1 33,2 28,9

Перезапустите Squid.

Теперь ваш cache.log (и/или access.log ???) должен содержать детальную трассировку всего процесса контроля доступа. Будьте внимательны, на каждый запрос будет по несколько несколько строк.

Ссылки

http://www.squid-cache.org/Doc/config/debug_options/
http://wiki.squid-cache.org/KnowledgeBase/DebugSections
http://www.squid-cache.org/Doc/config/

С Уважением, Mc.Sim!




Теги: , ,

3 комментария к “squid, использование опции debug_options или диагностика компонентов squid”

  1. Firebolt
    Январь 26th, 2015 at 14:05
    1

    Согласно этому вот это нам не поможет:
    Для управления логированием и уменьшения уровня неактуальных сообщений в логах при масштабном внедрении squid можно использовать следующие директивы:

    Ты это точно применял? Я попробовал, а в cache.log все равно всё валится. Я не понял и почитал.

    • Апрель 9th, 2015 at 17:18
      2

      Нет, я это не применял.
      Эта директива управляет логированием только той информацией, которая попадает в access.log (не cache.log).

  2. Georgii
    Август 2nd, 2016 at 00:21
    3

    Спасибо! Очень помогло

Написать комментарий