Як я патчив Zabbix

Днями, у мене нарешті дійшли руки до оновлення Zabbix.

З моменту прочитання статті Вийшов Zabbix 2.2 у відповідному блозі, я не міг дочекатися, коли ж в Gentoo размаскируют версію 2.2. Практично не було такого нововведення в цій версії, яке б мені не було цікаво і корисно в «побуті». Це і моніторинг VMware, і прискорення системи, та покращення в LLDP, коротше практично кожен пункт.

Йшли місяці, а версії 2.2 не було навіть у замаскованих.

Іноді я відкладаю рух в сторону і займаюся чим-небудь «паралельним» щодо термінових і важливих завдань і робіт. В цей раз я згадав про бажання оновити Zabbix до версії 2.2.

Перевірив маскованих*, ну нарешті, є 2.2.5

Ну все, переходимо, пройшов вже рік з моменту випуску, версія stable'е не буває, так що що б не сталося, вирішимо.

Размаскировываем, збираємо скрізь де треба (основне це звісно сервер проксі), перезапускаємо. Переустанавливаем web інтерфейс іііі…
І нічого, йде оновлення БД.
Штука це не швидка, база у мене не маленька, а потім процес взагалі завис.

Ну думаю, почалося, як кажуть, не встигли почати, а вже все погано.

В логах mysql було Error number 28 means 'No space left on device', місця скрізь було більш ніж достатньо. Як говориться «при наявності гугла, я богоподобен» ©, не відразу, але вдалося знайти/здогадатися що цей device це ibdata1 і ibdata2, розмір яких регулюється параметром innodb_data_file_path. Після того як я поміняв max з 256M на 512М оновлення бази завершилося успішно і сервер стартонув.

На проксі теж були проблеми, і теж через бази даних. Просто sqlite не оновлюється, тому зупиняємо проксі, видаляємо стару базу і запускаємо проксі. Як йдеться уважніше читайте Upgrade notes

Звичайно за час оновлення накопичилося багато прострочених даних, тому перевіряємо то що можемо перевірити, що в інтерфейсі все показується, і чекаємо, поки все устаканиться і актуалізується.

Через пару годин, дивимося графік:

image

День починав ставати млосним.

У нас чергу. Звідки?.. Основні прострочені дані з одного з проксі. А що за дані. А дані отримані за SNMPv3.

Відмінно. Були і раніше у мене до цього функціоналу питання, але все руки не доходили, та була надія що оновлення ці питання вирішить. А тут система стає практично не працездатна. У свій час, читаючи про те, як люди з допомогою одного сервера або проксі моніторять сотні мережних девайсів я не міг зрозуміти в чому ж справа? У мене кілька десятків пристроїв, і все працює на межі. Вже і БД оптимізована донезмоги, і сервер покладено на швидкий датастор, і пам'яті йому дано чимало.

Відкочуватися назад не хотілося, тому було вирішено у що б то не стало спробувати розібратися з проблемою.

Я вибрав один з проксі, за яким найбільше SNMP пристроїв, і почав розбиратися.

Ось що у нас в логах на проксі**:
4447:20141218:124053.605 SNMP agent item "ifAdminStatus.["10130"]" on host "co-xx02" failed: first network error, wait for 15 seconds
4468:20141218:124108.270 resuming SNMP agent checks on host "co-xx02": connection restored

І так безладно по всьому SNMP хостів, з різними итемами.

Мережевих проблем у мене точно немає, але для вірності я звичайно ж по швидкому перевірив зв'язність, швидкість і логи комутаторів. Перевіряємо сам SNMP з допомогою snmpwalk причому смикаємо взагалі все дерево. Ніяких проблем.
Гуглим. У кого-то забиті поллеры, у кого-то некоректні таймаут, якийсь баг пов'язаний з цим виправлено у версії 2.2.3. У кого-то хитра проблема з мережею і втрачається UDP. Але це не наш випадок.
Що тоді?..

Цікавий факт, якщо перезавантажити проксі
/etc/init.d/zabbix-proxy restart

То видно як починає скорочуватися чергу, але потім бах, знову щось трапляється і вона вмить виростає***.

image

Що ж відбувається?..
Включаємо розширене логування на zabbix-proxy
DebugLevel=4
Перезапускаємо zabbix-proxy і чекаємо появи помилок

Тепер замість Network Error бачимо більш повну інформацію

Виглядає це приблизно так
5414:20141218:125955.481 zbx_snmp_get_values() snmp_synch_response() status:1 errstat:-1 mapping_num:94
5414:20141218:125955.481 End of zbx_snmp_get_values():NETWORK_ERROR
5414:20141218:125955.481 End of zbx_snmp_process_standard():NETWORK_ERROR
5414:20141218:125955.481 In zbx_snmp_close_session()
5414:20141218:125955.481 End of zbx_snmp_close_session()
5414:20141218:125955.481 getting SNMP values failed: Cannot connect to "192.168.x.x:161": Too long.
5414:20141218:125955.481 End of get_values_snmp()
5414:20141218:125955.481 In deactivate_host() hostid:10207 itemid:43739 type:6
5414:20141218:125955.481 query [txnlev:1] [begin;]
5414:20141218:125955.481 query [txnlev:1] [update hosts set snmp_errors_from=1418896795,snmp_disable_until=1418896810,snmp_error='Cannot connect to "192.168.x.x:161": Too long.' where hostid=10207]
5414:20141218:125955.481 query [txnlev:1] [commit;]
5414:20141218:125955.481 SNMP agent item "ifOperStatus.["10143"]" on host "co-xx04" failed: first network error, wait for 15 seconds
5414:20141218:125955.481 deactivate_host() errors_from:1418896795 available:1
5414:20141218:125955.482 End of deactivate_host()


Статус 1, статус помилки -1, число елементів 94
Тут же висновок що це NETWORK_ERROR
І трохи нижче розшифровка Too long вимкнення хоста. Зрозуміло що якщо хост деактивовано, дані з нього отримати не можна, дані ставляться в чергу, от і пояснення черги.

Відразу ж зацікавив параметр errstat

Робимо cat /var/log/zabbix/zabbix_proxy.log | grep errstat
5412:20141218:130351.410 zbx_snmp_get_values() snmp_synch_response() status:0 errstat:0 mapping_num:11
5433:20141218:130351.470 zbx_snmp_get_values() snmp_synch_response() status:1 errstat:-1 mapping_num:94
5430:20141218:130351.476 zbx_snmp_get_values() snmp_synch_response() status:1 errstat:-1 mapping_num:94
5417:20141218:130353.442 zbx_snmp_get_values() snmp_synch_response() status:0 errstat:0 mapping_num:5
5420:20141218:130353.534 zbx_snmp_get_values() snmp_synch_response() status:1 errstat:-1 mapping_num:94


Ага, копаємо глибшеТут повинна бути картинка We need to go deeper, але не буде. Мені здається вона всіх дістала.


Робимо cat /var/log/zabbix/zabbxi_proxy.log | grep errstat:-1
5416:20141218:130353.540 zbx_snmp_get_values() snmp_synch_response() status:1 errstat:-1 mapping_num:94
5412:20141218:130355.571 zbx_snmp_get_values() snmp_synch_response() status:1 errstat:-1 mapping_num:94
5417:20141218:130355.591 zbx_snmp_get_values() snmp_synch_response() status:1 errstat:-1 mapping_num:94
...
5420:20141218:130453.187 zbx_snmp_get_values() snmp_synch_response() status:1 errstat:-1 mapping_num:94
5412:20141218:130455.206 zbx_snmp_get_values() snmp_synch_response() status:1 errstat:-1 mapping_num:94
5413:20141218:130455.207 zbx_snmp_get_values() snmp_synch_response() status:1 errstat:-1 mapping_num:94


Настав час відключити моніторинг всіх пристроїв через проксі крім одного, тому що інакше в балці занадто складно розбиратися. Все одно система в такому вигляді як зараз для моніторингу не придатна.
Відключаємо, робимо
cat /var/log/zabbix/zabbxi_proxy.log | grep mapping_num
і перезагрузим проксі
Ніяких помилок перший час, так і mapping_num потихеньку зростає від 1 все більше і більше (вирізані окремі рядки щоб показати принцип)

Можна вічно дивитися за тим, як зростає mapping_num
7876:20141218:131251.660 zbx_snmp_get_values() snmp_synch_response() status:0 errstat:0 mapping_num:4
7872:20141218:131251.681 zbx_snmp_get_values() snmp_synch_response() status:0 errstat:0 mapping_num:6
7872:20141218:131251.919 zbx_snmp_get_values() snmp_synch_response() status:0 errstat:0 mapping_num:8
7876:20141218:131251.919 zbx_snmp_get_values() snmp_synch_response() status:0 errstat:0 mapping_num:9
7868:20141218:131351.965 zbx_snmp_get_values() snmp_synch_response() status:0 errstat:0 mapping_num:13
10502:20141218:135237.884 zbx_snmp_get_values() snmp_synch_response() status:0 errstat:0 mapping_num:31
10507:20141218:135238.244 zbx_snmp_get_values() snmp_synch_response() status:0 errstat:0 mapping_num:62
12429:20141218:141637.942 zbx_snmp_get_values() snmp_synch_response() status:0 errstat:0 mapping_num:31
12429:20141218:141637.966 zbx_snmp_get_values() snmp_synch_response() status:0 errstat:0 mapping_num:31
12433:20141218:141651.142 zbx_snmp_get_values() snmp_synch_response() status:1 errstat:-1 mapping_num:94



А потім оппа 94, і -1 і too long. Тобто відразу після запуску проксі тестує пристрої, посилає їм SNMP запити, збільшуючи кількість итемов в одному запиті. Черга починає швидко скорочуватися. Потім він (себто проксі) доходить до чарівного числа 94, відбувається збій і пристрої починають відключатися заббиксом на 15 секунд, що в свою чергу починає різко збільшувати чергу.

Як бачимо, тут вже зовсім не Network error, тут вже Too long.

Гаразд пробуємо щось знайти по zabbix snmp too long, нічого.

Знову таймаут, перевантаження поллера… В одному цікавому пості була інформація, що така помилка виникала коли був невірно сформований OID для итема, так що я двічі перевірив всі свої OID'и в тому числі через snmpget

Тобто в підсумку гугл мені допомогти не зміг.

Будемо розбиратися самі, це корисно.
Отже, що у нас є?
Як тільки число итемов стає 94 (тобто досить великим) щось відбувається і система збивається.

Тут знову картинка, якої не буде ;)

Пора лізти в код. В gentoo нічого качати не треба, вже все є, так що я просто розпакував все в робочу директорію.

Знайдемо спочатку де виводиться помилка. Шукаємо по errstat
На здивування всього два таких місця у файлі з промовистою назвою checks_snmp.c

ось ці два місця:
з рядка 745
/* communicate with agent */
status = snmp_synch_response(ss, pdu, &response);

zabbix_log(LOG_LEVEL_DEBUG, "%s() snmp_synch_response() status:%d errstat:%ld max_vars:%d",
__function_name, status, NULL == response ? (long)-1 : response->errstat, max_vars);

і з рядка 938
status = snmp_synch_response(ss, pdu, &response);

zabbix_log(LOG_LEVEL_DEBUG, "%s() snmp_synch_response() status:%d errstat:%ld mapping_num:%d",
__function_name, status, NULL == response ? (long)-1 : response->errstat, mapping_num);


Поки нас цікавить другий шматок (виходячи з того, що mapping_num є тільки в ньому)

Навіть не програміст бачить, що у нас response NULL, а чому?..

Згадаймо, що при errstat:-1, який тепер зрозуміло звідки береться, у нас status:1. Тобто функція snmp_synch_response повертає 1, а що це значить?..
А це означає STAT_ERROR (1) (а ще вона вміє STAT_TIMEOUT (2) і STAT_SUCCESS (0))

Як йдеться незрозуміло, але здорово…
Зайдемо з іншого боку, десь тут же в цьому файлі має бути повернення NETWORK_ERROR спробуємо розібратися, де і чому.

Перше ж входження у функції zbx_get_snmp_response_error (що як би натякає)

Подивитися код zbx_get_snmp_response_error
static int zbx_get_snmp_response_error(const struct snmp_session *ss, const DC_INTERFACE *interface, int status,
const struct snmp_pdu *response, char *error, int max_error_len)
{
int ret;

if (STAT_SUCCESS == status)
{
zbx_snprintf(error, max_error_len, "SNMP error: %s", snmp_errstring(response->errstat));
ret = NOTSUPPORTED;
}
else if (STAT_ERROR == status)
{
zbx_snprintf(error, max_error_len, "Cannot connect to \"%s:%hu\": %s.",
interface->addr, interface->port, snmp_api_errstring(ss->s_snmp_errno));

switch (ss->s_snmp_errno)
{
case SNMPERR_UNKNOWN_USER_NAME:
case SNMPERR_UNSUPPORTED_SEC_LEVEL:
case SNMPERR_AUTHENTICATION_FAILURE:
ret = NOTSUPPORTED;
break;
default:
ret = NETWORK_ERROR;
}
}
else if (STAT_TIMEOUT == status)
{
zbx_snprintf(error, max_error_len, "Timeout while connecting to \"%s:%hu\".",
interface->addr, interface->port);
ret = NETWORK_ERROR;
}
else
{
zbx_snprintf(error, max_error_len, "SNMP error: [%d]", status);
ret = NOTSUPPORTED;
}

return ret;
}



Ага. Тобто ми зі своїм STAT_ERROR входимо в switch де не потрапляємо під жодне з наведених умов, і таким чином отримуємо NETWORK_ERROR по дефолту.
Ми вже зрозуміли що цей дефолт дезорієнтує нас, потрібно з'ясувати що ж це за помилка насправді. Код помилки зберігається в ss->s_snmp_errno, додамо висновок змінної в лог.

Програміст з мене так собі, так що швиденько з допомогою лома і чиєїсь матері © сляпал сподобався, ось такий:
diff-urN zabbix-2.2.5/src/zabbix_server/poller/checks_snmp.c zabbix-2.2.5.new/src/zabbix_server/poller/checks_snmp.c
--- zabbix-2.2.5/src/zabbix_server/poller/checks_snmp.c 2014-07-17 17:49:45.000000000 +0400
+++ zabbix-2.2.5.new/src/zabbix_server/poller/checks_snmp.c 2014-10-10 16:38:31.000000000 +0400
@@ -938,7 +938,7 @@
status = snmp_synch_response(ss, pdu, &response);

zabbix_log(LOG_LEVEL_DEBUG, "%s() snmp_synch_response() status:%d errstat:%ld mapping_num:%d",
- __function_name, status, NULL == response ? (long)-1 : response->errstat, mapping_num);
+ __function_name, status, NULL == response ? (STAT_ERROR == status ? (long) ss->s_snmp_errno : (long)-1) : response->errstat, mapping_num);

if (STAT_SUCCESS == status && SNMP_ERR_NOERROR == response->errstat)
{


Якщо статус STAT_ERROR виводити ss->s_snmp_errno

Закинув ісходник заббикса в локальний репозиторій, швидко підправив ебилд і вперед.
Компилим, перезапускаємо, чекаємо.

І ось вона наша реальна помилка.
11211:20141218:155253.362 zbx_snmp_get_values() snmp_synch_response() status:0 errstat:0 mapping_num:18
11210:20141218:155253.393 zbx_snmp_get_values() snmp_synch_response() status:1 errstat:-5 mapping_num:94


Помилка -5
Дивимося Net-SNMP snmp_api.h
#define SNMPERR_TOO_LONG (-5)


Щось схоже було видно в логах, але по словосполученню Too Long ми знайти нічого не змогли, подивимося що ж це за помилка і коли виникає.
у snmp_api.c можна це побачити
ще трохи коду
/*
* Make sure we don't send something that is bigger than the msgMaxSize
* specified in the received PDU.
*/

if (pdu->version == SNMP_VERSION_3 && session->sndMsgMaxSize != 0 && length > session->sndMsgMaxSize) {
DEBUGMSGTL(("sess_async_send",
"length of packet (%lu) exceeds session maximum (%lu)\n",
(unsigned long)length, (unsigned long)session->sndMsgMaxSize));
session->s_snmp_errno = SNMPERR_TOO_LONG;
SNMP_FREE(pktbuf);
return 0;
}

/*
* Check that the транспортний протокол is capable of sending a packet as
* large as length.
*/

if (transport->msgMaxSize != 0 && length > transport->msgMaxSize) {
DEBUGMSGTL(("sess_async_send",
"length of packet (%lu) exceeds transport maximum (%lu)\n",
(unsigned long)length, (unsigned long)transport->msgMaxSize));
session->s_snmp_errno = SNMPERR_TOO_LONG;
SNMP_FREE(pktbuf);
return 0;
}


Є всього два варіанти:
1. Довжина даних які ми хочемо послати більше ніж параметр msgMaxSize визначений в отриманому PDU
2. Нижележащий транспорт не здатний послати пакет такої довжини

Виникає питання як же пофіксити цю помилку. З вищесказаного випливає, що потрібно шукати отримуємо ми msgMaxSize, чи правильно ми це обробляємо і т. д. і т. п. Але я исходники zabbix бачу в перший раз, а C у другій (ну ладно в третій).
Коротше не викликає ентузіазму… Так і поламати напевно що-небудь можна буде.

Ліричний відступ:
Треба сказати, що під час розглядів з цією проблемою, я в тому числі наткнувся на інформацію про масовій обробці SNMP. Тобто zabbix одним запитом може запросити безліч SNMP елементів даних.

Подробиці SNMP bulk processing

Суть в тому, що zabbix вміє запитувати до 128 значень одним запитом, але не всі пристрої здатні обробити ці 128 значень за один раз. І в zabbiх використовується стратегія пошуку максимального значення для кожного конкретного пристрою. Ми до речі бачили це в логах. Поступове підвищення mapping_num. Як тільки zabbix отримує помилку від пристрою SNMPERR_TOO_BIG він за певним алгоритмом шукає максимальне значення повертає результати без помилок.

До чого це я.
Механізм обробки помилки переповнення (назвемо його так) в заббиксе є, треба його лише розширити на ще один випадок.
Сам алгоритм розписаний під висновком нашої помилки.

Знову цей код
else if (1 < mapping_num &&
((STAT_SUCCESS == status && SNMP_ERR_TOOBIG == response->errstat) || STAT_TIMEOUT == status))
{
/* Since we are trying to obtain multiple values from the SNMP agent, the response that it has to */
/* generate might be too big. It seems to be required by the SNMP standard that in such cases the */
/* error status should be set to "tooBig(1)". However, some devices simply do not respond to such */
/* queries and we get a timeout. Крім того, some devices exhibit both behaviors - they either send */
/* "tooBig(1)" or do not respond at all. So what we do is halve the number of variables to query - */
/* it should work in the vast majority of cases, because, since we are now querying "num" values, */
/* we know that querying "num/2" values succeeded previously. The case where it can still fail due */
/* to process maximum response size is if we are now querying values that are unusually large. So */
/* if querying with half the number of the last values does not work either, we resort to querying */
/* values one by one, and the next time configuration cache gives us items to query, it will give */
/* us less. */

if (*min_fail > mapping_num)
*min_fail = mapping_num;

if (0 == level)
{
/* halve the number of items */

int base;

ret = zbx_snmp_get_values(ss, items, oids, results, errcodes, query_and_ignore_type, num / 2,
level + 1, error, max_error_len, max_succeed, min_fail);

if (SUCCEED != ret)
goto exit;

base = num / 2;

ret = zbx_snmp_get_values(ss, items + base, oids + base, results + base, errcodes + base,
NULL == query_and_ignore_type ? NULL : query_and_ignore_type + base, num - base,
level + 1, error, max_error_len, max_succeed, min_fail);
}
else if (1 == level)
{
/* resort to querying items one by one */

for (i = 0; i < num; i++)
{
if (SUCCEED != errcodes[i])
continue;

ret = zbx_snmp_get_values(ss, items + i, oids + i, results + i, errcodes + i,
NULL == query_and_ignore_type ? NULL : query_and_ignore_type + i, 1,
level + 1, error, max_error_len, max_succeed, min_fail);

if (SUCCEED != ret)
goto exit;
}
}
}


Тобто все просто, нам треба додати своє умова, не порушивши роботу наявних. Для цього у нас є всі дані:
  • status повинен бути STAT_ERROR
  • ss->s_snmp_errno повинен бути SNMPERR_TOO_LONG
Враховуємо ще що у нас два таких місця (як і два виведення в лог-файл) і результуючий патч буде таким:

Нарешті
diff-urN zabbix-2.2.5/src/zabbix_server/poller/checks_snmp.c zabbix-2.2.5.new/src/zabbix_server/poller/checks_snmp.c
--- zabbix-2.2.5/src/zabbix_server/poller/checks_snmp.c 2014-07-17 17:49:45.000000000 +0400
+++ zabbix-2.2.5.new/src/zabbix_server/poller/checks_snmp.c 2014-10-10 16:38:31.000000000 +0400
@@ -746,10 +746,10 @@
status = snmp_synch_response(ss, pdu, &response);

zabbix_log(LOG_LEVEL_DEBUG, "%s() snmp_synch_response() status:%d errstat:%ld max_vars:%d",
- __function_name, status, NULL == response ? (long)-1 : response->errstat, max_vars);
+ __function_name, status, NULL == response ? (STAT_ERROR == status ? (long)ss->s_snmp_errno : (long)-1) : response->errstat, max_vars);

if (1 < max_vars &&
- ((STAT_SUCCESS == status && SNMP_ERR_TOOBIG == response->errstat) || STAT_TIMEOUT == status))
+ ((STAT_SUCCESS == status && SNMP_ERR_TOOBIG == response->errstat) || STAT_TIMEOUT == status || (STAT_ERROR == status && SNMPERR_TOO_LONG == ss->s_snmp_errno)))
{
/* The logic of iteratively reducing request size here is the same as in function */
/* zbx_snmp_get_values(). Please refer to the description there for explanation. */
@@ -938,7 +938,7 @@
status = snmp_synch_response(ss, pdu, &response);

zabbix_log(LOG_LEVEL_DEBUG, "%s() snmp_synch_response() status:%d errstat:%ld mapping_num:%d",
- __function_name, status, NULL == response ? (long)-1 : response->errstat, mapping_num);
+ __function_name, status, NULL == response ? (STAT_ERROR == status ? (long) ss->s_snmp_errno : (long)-1) : response->errstat, mapping_num);

if (STAT_SUCCESS == status && SNMP_ERR_NOERROR == response->errstat)
{
@@ -1001,7 +1001,7 @@
}
}
else if (1 < mapping_num &&
- ((STAT_SUCCESS == status && SNMP_ERR_TOOBIG == response->errstat) || STAT_TIMEOUT == status))
+ ((STAT_SUCCESS == status && SNMP_ERR_TOOBIG == response->errstat) || STAT_TIMEOUT == status || (STAT_ERROR == status && SNMPERR_TOO_LONG == ss->s_snmp_errno)))
{
/* Since we are trying to obtain multiple values from the SNMP agent, the response that it has to */
/* generate might be too big. It seems to be required by the SNMP standard that in such cases the */


Компілюємо, перезапускаємо…

І ось результат:

image

Помилка Network Error пропала з логів.
Ура!..

Післямова

Звичайно, у дійсності, пошук помилки і рішення зайняв більше часу. Довелося більше колупати исходники і zabbix і net-snmp, щоб в результаті зупинитися на двох місцях в коді.
Але відчуття перемоги над «неживою матерією» безцінне.

* бажання накотило 7 жовтня, а тоді 2.2.5 ще була замаскована. За випадковим збігом її размаскировали 10 жовтня;
** на час не дивіться, для написання статті зімітував ситуацію пізніше. Під час розборок, висмикувати з логів дані абсолютно не було часу, потік, куди подітися;
*** так, так, картинку я теж змоделював. Уявіть що там де зелене на початку, там все червоне ;) А потім пила під час рестартов.

Джерело: Хабрахабр

0 коментарів

Тільки зареєстровані та авторизовані користувачі можуть залишати коментарі.