Главная / Форумы / SAMS / Squid Account Management System (SAMS)

Постоянно умирает Samsdaemon!

bordac, 19.01.2010 — 20:18

Здравствуйте коллеги!
У нас через Sams2 проходит на данный момент 860 пользователей. Время от времени (закономерность не выявлена) логи squida перестают обрабатываться - причина - неживой samsdaemon,
команда /etc/init.d/sams2 status выводит следующее:

"samsdaemon неживой, но pid-файл существует"

Логи сквида периодически (каждые сутки) проходят ротацию. Текущий размер последнего лога: 177550189 байт.
С чем это связано? Где копать?

Sams 2.0.0-alpha2
Squid 3.1
Mysql 5.0.77

‹ SAMS перестал показывать пользователей Написал статейку про рихтовку SAMS ›
bordac, 09.02.2010 — 11:10

Хм, никогда этим не пользовался, можно попробовать! Спасибо!

mclight77, 09.02.2010 — 00:00

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

bordac, 08.02.2010 — 12:43

Спасибо!
А если настроить в кроне запуск samsdaemon каждые 5 минут. Если он уже запущен, запуск новой копии не произойдёт, если он упал, запустится снова. Вроде бы тоже не плохое решение?

mclight77, 04.02.2010 — 20:35

Почему UPnP не могут идти по 80 порту? Не вижу в этом криминала.

sams 2.х не ломается на длинных строках, а вот с такой дурацкой строкой на текущий момент можно побороться примерно так:
1) отключить обработку лог файлов в веб интерфейсе sams
2) в logrotate настроить ротацию логов squid каждые N минут.
3) в logrotate, секции postrotate, вызывать скрипт, который из последнего архива access.log вырезает дурацкие строки и запускает samsparser на уже корректный файл.

может, и не самое изящное решение, но должно работать.

bordac, 04.02.2010 — 14:26

И как с этим бороться?? UPnP запросы идут по 80 порту??

Lark аватар
Lark, 02.02.2010 — 17:31

при работе торрент клиента появляются эти записи в логе. а связана эта фигня имхо с UPnP запросами торрент клиента

2010/02/02 13:40:44| parseHttpRequest: Unsupported method '��^N��T�^A��^V�^^���bm�k9�a����^Eg^B/t~9�'
2010/02/02 13:40:44| clientTryParseRequest: FD 17 (192.168.0.7:2802) Invalid Request
2010/02/02 14:00:11| parseHttpRequest: Unsupported method 'ޝ�K2��l^]n'
2010/02/02 14:00:11| clientTryParseRequest: FD 21 (192.168.0.7:3757) Invalid Request
2010/02/02 14:04:37| parseHttpRequest: Unsupported method '��^Q^E��M�^R^BҨ0.^U�DѨv�بCs^\a�H���B��'
2010/02/02 14:04:37| clientTryParseRequest: FD 19 (192.168.0.7:4069) Invalid Request
2010/02/02 14:10:41| parseHttpRequest: Unsupported method 'T_^_%����,�t��L^Zlm뙙�Ǚ'
2010/02/02 14:10:41| clientTryParseRequest: FD 19 (192.168.0.7:4425) Invalid Request

bordac, 02.02.2010 — 13:09

День добрый!
Да, эти строки я и раньше замечал, только не нашел им объяснение.
В логах squid (cache.log) редко встречаются вот такие записи:

2010/01/27 02:19:43| clientParseRequestMethod: Unsupported method in request '%▒▒s▒$I▒▒7▒o▒#▒cK▒▒▒.▒I▒70]▒i^L▒[v▒*▒b▒Sd\▒鹐.m8▒▒▒▒▒2!▒Uwi▒K▒▒]▒s▒ꂁ▒,b▒
▒N ?▒▒ !^뇯t▒AZ1O*΁+V▒▒▒]▒+^L▒▒▒▒52ܼ▒Q▒"▒▒qՋ▒▒▒▒t▒▒▒[▒ʍ�n▒▒▒▒Y▒:▒,=
▒▒▒▒f▒▒▒▒▒▒▒▒̈́'x▒auɎ▒▒▒▒▒▒▒▒+O ▒▒▒#▒▒V^▒&▒▒?/▒▒▒{▒▒▒▒С▒㪂x▒▒#}Ay▒R▒▒▒L▒▒{^▒\ٌ▒qR▒6▒▒=^+▒▒▒▒▒<]▒▒v▒%▒낭w_▒
2▒▒︤,▒▒s{▒▒ك▒▒▒͐*{▒▒Е▒▒1▒▒▒瞤▒SH▒▒!|r▒vMC▒w▒▒X~▒
}▒2▒▒▒c▒'Y▒▒ ▒=▒▒▒▒▒▒Pf▒▒g
2010/01/27 02:19:43| clientProcessRequest: Invalid Request

не знаю, имеет ли это общее с абракадабрами в access.log

Откуда берутся эти строки - загадка. Мы перенаправляем на Squid только 80 порт (с помощью протокола WCCP). Торренты используют 80 порт?

Ещё иногда попадаются очень длинные, но при этом рабочие ссылки, на них уже ругается сам Squid. Может и samsdaemon на них тоже вспотыкается...

Большое спасибо за помощь и уделённое время! Будем искать причины непонятных запросов.

mclight77, 02.02.2010 — 02:32

ты можешь объяснить наличие вот таких строк в лог файле?

1264048690.648 0 10.32.1.146 NONE/400 3847 "R8СK_ЫfUO_Эйз.ZГ_oр*T_&ъ= %84%E4%%B9%AE%C3%D3%B7%CE%5DB?%14%A4%D8%D1%B5c%95%9Ejw5d%19%EC0%%E8p%80%C0%FDX%B4%10%98%93c%13%C7%3E%AC%FDW%03%90%F7%F5%A1%DC%8C%EB8Y%B6%B2 - NONE/- text/html

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

вот еще, вдогонку :)
1264050654.358 0 10.55.9.30 NONE/400 3338  p - NONE/- text/html

полагаю, это эхо использования пиринговой сети?

пока советую найти способ избавится от этих строк, а я попробую повысить отказоустойчивость программы, только не могу сказать что это произойдет быстро :(

bordac, 29.01.2010 — 14:53

Выложил логи на narod.ru ссылку кинул на почту.

mclight77, 27.01.2010 — 23:05

логи показали что по каким-то неведомым причинам неправильно идентифицируется метод из строки логов. Тот, который GET, CONNECT и т.д. попробую немного пошаманить, но скорей всего это будет похоже не пляски с бубном. Есть возможность выслать пример лог файла, на котором демон или парсер падает?

PS сорри за задержку, все время не получалось найти чтоб покопаться.

bordac, 26.01.2010 — 17:17

Samsdaemon продолжает переодически падать... Логи ничего не показали?

bordac, 22.01.2010 — 18:55

Ура! Наконец-то samsdaemon соизволил снова упасть! =))
Что-то я не соображу как приаттачить сюда файл, поэтому высылаю на почту...

mclight77, 22.01.2010 — 02:08

Парсер запоминает смещение в файле, и если при следующей обработке размер файла меньше запомненного смещения, то обработка начинается с начала файла. Если samsparser запускать без ключа -f, то он использует тот-же файл, что и samsdaemon, и использует запомненное смещение. По идее, перед ротацией логов нужно запускать samsparser. Для этого в logrotate для squid нужно добавить
prerotate
/путь/до/samsparser
endscript
Но это еще не проанализировано должным образом, потому не гарантирую отсутствие каких либо коллизий.

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

В показанном логе ничего криминального не увидел. Было бы очень неплохо таки добиться падения до вечера пятницы, чтобы в выходные мог внимательней поизучать, а то ночами сидеть уже сил нехватает...

bordac, 21.01.2010 — 18:04

А вот и samsparser выдал следующее:

samsparser -f /usr/local/squid/var/logs/access.log.1
Ошибка сегментирования

помню что там на букву "с" что-то было =)

bordac, 21.01.2010 — 17:59

Парсер вручную запускал, когда samsdaemon падал, а ночью происходила ротация логов, когда на следующий день перезапускал samsdaemon, вчерашние логи оказывались частично не обработанными..
Кстати, у меня возник вопрос:
Как я понял, samsdaemon после обработки лога запоминает смещение в файле а затем, при следующем периодическом запуске он начинает обработку с запомненного смещения. Тогда:
допустим samsdaemon обрабатывал логи и текущее смещение составило 1234, и тут произошла ротация логов, access.log очистился, в лог занеслось 32 строчки. С какого смещения начнётся обработка при следующей обработке логов?

Я запускал samsparser на уже обработанных логах, но ни дублирование записей, ни увеличение скачанного трафика не заметил...

bordac, 21.01.2010 — 17:31

Вот содержимое лога:

==715== Memcheck, a memory error detector.
==715== Copyright (C) 2002-2006, and GNU GPL'd, by Julian Seward et al.
==715== Using LibVEX rev 1658, a library for dynamic binary translation.
==715== Copyright (C) 2004-2006, and GNU GPL'd, by OpenWorks LLP.
==715== Using valgrind-3.2.1, a dynamic binary instrumentation framework.
==715== Copyright (C) 2000-2006, and GNU GPL'd, by Julian Seward et al.
==715== For more details, rerun with: -v
==715==
==715== My PID = 715, parent PID = 613. Prog and args are:
==715== /usr/local/bin/samsdaemon
==715==
==715==
==715== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 40 from 1)
==715== malloc/free: in use at exit: 61,472 bytes in 20 blocks.
==715== malloc/free: 901 allocs, 881 frees, 314,465 bytes allocated.
==715== For counts of detected errors, rerun with: -v
==715== searching for pointers to 20 not-freed blocks.
==715== checked 854,848 bytes.
==715==
==715== 16 bytes in 1 blocks are still reachable in loss record 1 of 3
==715== at 0x40053C0: malloc (vg_replace_malloc.c:149)
==715== by 0x3C8B0C: my_malloc (in /usr/lib/mysql/libmysqlclient.so.15.0.0)
==715== by 0x3C980D: my_error_register (in /usr/lib/mysql/libmysqlclient.so.15.0.0)
==715== by 0x3C879F: init_client_errs (in /usr/lib/mysql/libmysqlclient.so.15.0.0)
==715== by 0x3C4BD8: mysql_server_init (in /usr/lib/mysql/libmysqlclient.so.15.0.0)
==715== by 0x3EEFA1: mysql_init (in /usr/lib/mysql/libmysqlclient.so.15.0.0)
==715== by 0x80923DC: MYSQLConn::connect() (mysqlconn.cpp:48)
==715== by 0x8068581: SamsConfig::readDB() (samsconfig.cpp:202)
==715== by 0x8067305: SamsConfig::reload() (samsconfig.cpp:70)
==715== by 0x8083DAE: main (samsdaemon.cpp:276)
==715==
==715==
==715== 136 bytes in 4 blocks are possibly lost in loss record 2 of 3
==715== at 0x4005B65: operator new(unsigned) (vg_replace_malloc.c:163)
==715== by 0x48910FA: std::string::_Rep::_S_create(unsigned, unsigned, std::allocator const&) (in /usr/lib/libstdc++.so.6.0.8)
==715== by 0x4891C97: std::string::_Rep::_M_clone(std::allocator const&, unsigned) (in /usr/lib/libstdc++.so.6.0.8)
==715== by 0x4892847: std::string::reserve(unsigned) (in /usr/lib/libstdc++.so.6.0.8)
==715== by 0x4892A68: std::string::append(char const*, unsigned) (in /usr/lib/libstdc++.so.6.0.8)
==715== by 0x8083BA3: main (basic_string.h:822)
==715==
==715==
==715== 61,320 bytes in 15 blocks are still reachable in loss record 3 of 3
==715== at 0x40053C0: malloc (vg_replace_malloc.c:149)
==715== by 0x3CFE85: my_once_alloc (in /usr/lib/mysql/libmysqlclient.so.15.0.0)
==715== by 0x3D068A: (within /usr/lib/mysql/libmysqlclient.so.15.0.0)
==715== by 0x3D10A6: (within /usr/lib/mysql/libmysqlclient.so.15.0.0)
==715== by 0x3D1221: get_charset_by_csname (in /usr/lib/mysql/libmysqlclient.so.15.0.0)
==715== by 0x3EE4E2: mysql_init_character_set (in /usr/lib/mysql/libmysqlclient.so.15.0.0)
==715== by 0x3EFBCB: mysql_real_connect (in /usr/lib/mysql/libmysqlclient.so.15.0.0)
==715== by 0x809243C: MYSQLConn::connect() (mysqlconn.cpp:55)
==715== by 0x8068581: SamsConfig::readDB() (samsconfig.cpp:202)
==715== by 0x8067305: SamsConfig::reload() (samsconfig.cpp:70)
==715== by 0x8083DAE: main (samsdaemon.cpp:276)
==715==
==715== LEAK SUMMARY:
==715== definitely lost: 0 bytes in 0 blocks.
==715== possibly lost: 136 bytes in 4 blocks.
==715== still reachable: 61,336 bytes in 16 blocks.
==715== suppressed: 0 bytes in 0 blocks.

Запустил valgrind с samsdaemon снова, пока не падает...

mclight77, 21.01.2010 — 01:06

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

mclight77, 21.01.2010 — 00:57

кинуть можно аттачем сюда, так быстрее будет. Или на mclight77@permlug.org, но когда я туда доберусь - сказать сложно. Логи valgrind должны были измениться, там в конце должен быть backtrace с того места, откуда упало, и статистика использования памяти.

bordac, 20.01.2010 — 17:58

samsdaemon снова умер, но логи valgrind не изменились, так и должно быть?? В логах есть только записи которые появились при старте valgrind...

bordac, 20.01.2010 — 12:04

Моя ОС: CentOS 5.4 ядро 2.6.30.10
Редиректор не используется.

Запустил valgrind, лог пишется, будем ждать когда умрёт samsdaemon.

Есть ещё одна проблема, но не такая важная: когда запускаю вручную:
samsparser -f /usr/local/squid/var/logs/access.log
иногда обработка проходит удачно, а иногда выдаёт что-то типа: "ошибка синхронизации" (точно не помню) сегодня утром парсер отработал нормально. Будет ошибка, скажу точно что он говорит.

Куда потом логи кинуть? Скажи ICQ, или вот моя: 586506978.

wildsisop, 20.01.2010 — 01:10

у меня такое происходит, если MySQL вдруг оказывается недоступен. тогда samsdaemon тупо падает, и всё.

mclight77, 19.01.2010 — 23:09

Копать нужно в отладке. Идеальным вариантом в этом случае были бы логи от valgrind. Есть ли такая возможность?
запускается это так:
valgrind --show-reachable=yes --log-file=/tmp/samsdaemon.valgrind --leak-check=full /путь/к/samsdaemon

это значительно замедлит работу, но лучше потерпеть и выяснить причину. Кстати, используется ли редиректор и какая ОС?

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

Выберите нужный метод показа комментариев и нажмите "Сохранить установки".