Історія одного багу
Mar. 1st, 2009 01:56 pm![[personal profile]](https://www.dreamwidth.org/img/silk/identity/user.png){kind=small}
madfПопереджаю, під катом багато літер і технічних подробиць, які можуть бути незрозумілі для тих, хто не мав справи з системою Stargazer. А для повного і точного розуміння описуваних процесів краще мати перед собою джерельні коди системи :)
Почалося все літом 2008-го року. Один із користувачів відмітив, що Stargazer часто падає. Я в таких випадках в першу чергу виясняю яка версія і з якими патчами. Є основна версія, що розміщена на офсайті і є набір патчів від розробника WEB-адмінки (без патчів адмінка не працює). Я ці патчі не включаю в CVS (причини ідеологічного характеру). І якщо система патчена і виявиться що її нестабільність викликана саме патчами - я просто скину роботу на розробника патчів. Цього разу система була "чиста".
Далі я цікавлюсь про storage-плагін. Раніше Stargazer всю інформацію записував у файлову БД. І цей плагін використовується досі. Коли я приєднався до проекту, моя перша задача була - написати плагін для роботи з СУБД Firebird. Користувачам не сподобалась ідея ставити Firebird на систему, у якій уже, зазвичай, стоїть MySQL. А нам, у свою чергу, не подобався MySQL через відсутність у ньому транзакцій та погану підтримку зовнішніх ключів (я вже не кажу про stored procedures та тригери). В результаті, один із користувачів зібрав гроші і найеяв програміста для написання плагіна для MySQL (а також для роботи з NetFlow).
Таким чином, на сьогодні є 2 "офіційних" плагіни і один сторонній. При чому останній написаний просто жахливо. Але цього разу використовувалась файлова БД.
Це уже викликає подив, бо версія 2.405 вийшла досить давно і особливих скарг не було.
Потім я попросив отримати core-файл і надіслати його мені на аналіз. На жаль, аналіз не показав нічого - бектрейс уводив в нікуди:
А тут на форумі відписались ще троє, у кого спостерігається така проблема. Що цікаво: місце у якому виникає проблема локалізовано досить точно (по журналу роботи Stargazer) - видалення користувача із Traffcounter після його розавторизації. Але аналіз коду не показав нічого цікавого, ніяких явних ляпів і т.д. Крім того, сам процес розавторизації - досить складна штука. Там задіяно декілька нотифікаторів і чітко уявити собі послідовність викликів досить важко. А найгірше те, що я не можу повторити цю помилку у себе на машині. Система працює декілька днів без жодного падіння. Правда, у мене і навантаження на неї майже немає.
У жовтні 2008 з'явилось оце (шматочок журналу valgrind):
Подиву не було меж. Мьютекс - член класа. Ініціалізується у конструкторі. Як же він може бути у неініціалізованій області пам'яті?! Я ще декілька разів передивлявся код і все одно нічого не знайшов. Користувачі вимагали стабільності, а я нічого не міг зробити... Крім того як раз у цей період я був досить зайнятий щоб займатись Stargazer'ом. У середині січня я трохи звільнився і взявся за це баг знову. В першу чергу я замінив inen_ntoa на inet_ntop, яка не використовувала внутрішнього буферу і була безпечна для багатопоточного використання. 21 січня я виклав 2.406-alpha для перевірки, зникне баг чи ні. Перші відгуки були непогані, але баг не зник. Хоча й став проявлятись рідше.
23 лютого я отримав новий журнал valgrind - уже для альфи. Там було все те саме. І тут щось підказало мені передивитись старі бектрейси (Keen: http://local.com.ua/forum/index.php?showtopic=12719&st=20&p=99601&#entry99601 і Silitra: http://local.com.ua/forum/index.php?showtopic=12719&st=40&p=100535&#entry100535). І там я помітив от що:
Справа в тому, що TRAFFCOUNTER::DelUser отримує ітератор юзера, але для видалення використовує два своїх, що індексовані за ip. Оскільки для ітератора не існує NULL-значення, поряд із ним зберігалась булева змінна, що показувала стан ітератора (ініціалізовний чи ні). В усіх місцях ця змінна перевірялась, а тут - ні. В першу чергу я відписав фікс для перевірки стану ітераторів перед викликом AddTraffStatU. А сам сів і став думати.
А думав я от про що: у якій ситуації ітератори можуть бути неініціалізованими? Яка послідовність дій до цього приводить?
Коли пакет додається у трафкаунтер (TRAFFCOUNTER::Process) для нього перевіряється наявність авторизованих юзерів, для яких він може бути вхідним чи вихідним. Якщо такі існують - їх ітератори записуються у поля userU та userD і відмічаються булеві змінні userUPresent та userDPresent. Після цього пакет додається до внутрішнього дерева. При чому це відбувається навіть у тому випадку, коли не існує авторизованих користувачів, яким би він належав. І це не є логічною помилкою! Користувач може авторизуватись у системі пізніше, ніш ми отримаємо пеорший пакет від нього.
Коли пакет "старіє" більше ніж на FLUSH_TIME секунд - трафкаунтер намагається віддати інформацію про трафік користувачам із полів userU і userD (тут явно перевіряються userUPresent і userDPresent). Якщо їх немає - пакет живе до "віку" REMOVE_TIME і після цього стирається.
Коли користувач авторизується в системі для нього відбувається виклик TRAFFCOUNTER::AddUser і USER::AddToIPIdx. Наприклад:
Перший виклик переглядає дерево пакетів і перевіряє, чи не належать якісь із них новому користувачу. Якщо такі знаходяться - для них встановлюється відповідний ітератор і булева змінна. Другий виклик додає користувача у індекс за ip. Ці два виклики відбуваються послідовно, при чому перший блокує додавання нових пакетів. Якщо користувач встигне згенерувати хоча б один пакет у цей момент, а трафкаунтер встигне його отримати і виконати пошук по індексу - цей пакет буде доданий до дерева як такий, що не належить цьому користувачу. Звісно, ітератор залишиться неініціалізованим.
Після цього користувач додається до індексу і все працює добре. Якщо користувач залишається авторизованим як мінімум REMOVE_TIME секунд - "поганий" пакет просто видаляється з дерева. А якщо користувач розавторизується до цього моменту - починається низка викликів, яка приводить нас до TRAFFCOUNTER::DelUser. Він переглядає дерево на предмет пакетів, що належать юзеру (за ip). І, звісно, знаходить такий "поганий" пакет. Потім виконується перевірка user*-user*Present яку треба замінити assert'ом. Але це не наша ситуація. Умова, що перевіряється не є сильною. Вона перевіряє випадок, коли пакет дійсно належить юзеру і ітератор встановлено вірно, але не вказано user*Present. У нас же інша ситуація - ітератор взагалі не ініціалізований. Тому цей "assert" не спрацьовує.
Тут як раз і виникає ситуація, що приводить до падіння Stargazer. Мені вдалося змоделювати ситуацію вставкою 5-секундної затримки на завершення виклику TRAFFCOUNTER::AddUser (уже після того як переглянули дерево пакетів). Далі я авторизувався в системі, але ще 5 секунд Inetaccess залишався червоним. За цей час я швиденько запустив ping, а коли процес авторизації завершився - розавторизувався. В результаті отримав таке:
Звісно, Stargazer не впав, бо я поставив собі ту додаткову перевірку. Але я заодно поставив і "пастку" для цього багу - і вона спрацювала, показуючи що така ситуація теоретично можлива.
У реальному житті таке може бути лише коли користувач генерує велику кількість пакетів ще до авторизації в системі.
Більше цей баг не проявлявся.
Отака історія, коли фітіль підпалюється в одному місці, а бомба вибухає зовсім у іншому.
Почалося все літом 2008-го року. Один із користувачів відмітив, що Stargazer часто падає. Я в таких випадках в першу чергу виясняю яка версія і з якими патчами. Є основна версія, що розміщена на офсайті і є набір патчів від розробника WEB-адмінки (без патчів адмінка не працює). Я ці патчі не включаю в CVS (причини ідеологічного характеру). І якщо система патчена і виявиться що її нестабільність викликана саме патчами - я просто скину роботу на розробника патчів. Цього разу система була "чиста".
Далі я цікавлюсь про storage-плагін. Раніше Stargazer всю інформацію записував у файлову БД. І цей плагін використовується досі. Коли я приєднався до проекту, моя перша задача була - написати плагін для роботи з СУБД Firebird. Користувачам не сподобалась ідея ставити Firebird на систему, у якій уже, зазвичай, стоїть MySQL. А нам, у свою чергу, не подобався MySQL через відсутність у ньому транзакцій та погану підтримку зовнішніх ключів (я вже не кажу про stored procedures та тригери). В результаті, один із користувачів зібрав гроші і найеяв програміста для написання плагіна для MySQL (а також для роботи з NetFlow).
Таким чином, на сьогодні є 2 "офіційних" плагіни і один сторонній. При чому останній написаний просто жахливо. Але цього разу використовувалась файлова БД.
Це уже викликає подив, бо версія 2.405 вийшла досить давно і особливих скарг не було.
Потім я попросив отримати core-файл і надіслати його мені на аналіз. На жаль, аналіз не показав нічого - бектрейс уводив в нікуди:
(gdb) bt #0 0xb7f1c100 in ?? () Cannot access memory at address 0xb5b94c7c
А тут на форумі відписались ще троє, у кого спостерігається така проблема. Що цікаво: місце у якому виникає проблема локалізовано досить точно (по журналу роботи Stargazer) - видалення користувача із Traffcounter після його розавторизації. Але аналіз коду не показав нічого цікавого, ніяких явних ляпів і т.д. Крім того, сам процес розавторизації - досить складна штука. Там задіяно декілька нотифікаторів і чітко уявити собі послідовність викликів досить важко. А найгірше те, що я не можу повторити цю помилку у себе на машині. Система працює декілька днів без жодного падіння. Правда, у мене і навантаження на неї майже немає.
У жовтні 2008 з'явилось оце (шматочок журналу valgrind):
==2966== Thread 6: ==2966== Invalid read of size 4 ==2966== at 0x4070100: pthread_mutex_lock (in /lib/libpthread-2.7.so) ==2966== by 0x80921B6: STG_LOCKER::STG_LOCKER(pthread_mutex_t*, char const*, int) (stg_locker.h:59) ==2966== by 0x80AC431: USER::AddTraffStatU(int, unsigned, unsigned short, unsigned) (user.cpp:884)
Подиву не було меж. Мьютекс - член класа. Ініціалізується у конструкторі. Як же він може бути у неініціалізованій області пам'яті?! Я ще декілька разів передивлявся код і все одно нічого не знайшов. Користувачі вимагали стабільності, а я нічого не міг зробити... Крім того як раз у цей період я був досить зайнятий щоб займатись Stargazer'ом. У середині січня я трохи звільнився і взявся за це баг знову. В першу чергу я замінив inen_ntoa на inet_ntop, яка не використовувала внутрішнього буферу і була безпечна для багатопоточного використання. 21 січня я виклав 2.406-alpha для перевірки, зникне баг чи ні. Перші відгуки були непогані, але баг не зник. Хоча й став проявлятись рідше.
23 лютого я отримав новий журнал valgrind - уже для альфи. Там було все те саме. І тут щось підказало мені передивитись старі бектрейси (Keen: http://local.com.ua/forum/index.php?showtopic=12719&st=20&p=99601&#entry99601 і Silitra: http://local.com.ua/forum/index.php?showtopic=12719&st=40&p=100535&#entry100535). І там я помітив от що:
(Keen):
#6 0x080ab985 in USER::Unauthorize (this=0x83aade8, auth=0x80f0d80) at user.cpp:574 - тут, здається все добре, звертаємо увагу на this
#3 0x080a4873 in TRAFFCOUNTER::DelUser (this=0x80f01a0, user= {_M_node = 0x83aade0}) at traffcounter.cpp:616 - тут теж все добре (_M_node - нутрощі ітератора, допускаємо зміщення у 8 байт до юзера)
#2 0x080ac432 in USER::AddTraffStatU (this=0x8, dir=1, ip=3843359321, port=443, len=48) at user.cpp:884 - тут все погано, this не може бути 8.
(Silitra):
#6 0x080a756f in USER::Unauthorize (this=0x28d22008, auth=0x2844e000) at user.cpp:583 - тут все добре, знов звертаєм увагу на this
#3 0x0809f282 in TRAFFCOUNTER::DelUser (this=0x2843b060, user={_M_node = 0x28d22000}) at traffcounter.cpp:605 - теж непогано (теж зміщення на 8 байт)
#2 0x080a802a in USER::AddTraffStatU (this=0x8, dir=0, ip=3832810564, dport=59127, sport=47747, len=131) at user.cpp:911 - тут все зламалось
Справа в тому, що TRAFFCOUNTER::DelUser отримує ітератор юзера, але для видалення використовує два своїх, що індексовані за ip. Оскільки для ітератора не існує NULL-значення, поряд із ним зберігалась булева змінна, що показувала стан ітератора (ініціалізовний чи ні). В усіх місцях ця змінна перевірялась, а тут - ні. В першу чергу я відписав фікс для перевірки стану ітераторів перед викликом AddTraffStatU. А сам сів і став думати.
А думав я от про що: у якій ситуації ітератори можуть бути неініціалізованими? Яка послідовність дій до цього приводить?
Коли пакет додається у трафкаунтер (TRAFFCOUNTER::Process) для нього перевіряється наявність авторизованих юзерів, для яких він може бути вхідним чи вихідним. Якщо такі існують - їх ітератори записуються у поля userU та userD і відмічаються булеві змінні userUPresent та userDPresent. Після цього пакет додається до внутрішнього дерева. При чому це відбувається навіть у тому випадку, коли не існує авторизованих користувачів, яким би він належав. І це не є логічною помилкою! Користувач може авторизуватись у системі пізніше, ніш ми отримаємо пеорший пакет від нього.
Коли пакет "старіє" більше ніж на FLUSH_TIME секунд - трафкаунтер намагається віддати інформацію про трафік користувачам із полів userU і userD (тут явно перевіряються userUPresent і userDPresent). Якщо їх немає - пакет живе до "віку" REMOVE_TIME і після цього стирається.
Коли користувач авторизується в системі для нього відбувається виклик TRAFFCOUNTER::AddUser і USER::AddToIPIdx. Наприклад:
traffcounter.cpp > 18:05:08 > AddUser: test users.cpp > 18:05:08 > Add IP Idx
Перший виклик переглядає дерево пакетів і перевіряє, чи не належать якісь із них новому користувачу. Якщо такі знаходяться - для них встановлюється відповідний ітератор і булева змінна. Другий виклик додає користувача у індекс за ip. Ці два виклики відбуваються послідовно, при чому перший блокує додавання нових пакетів. Якщо користувач встигне згенерувати хоча б один пакет у цей момент, а трафкаунтер встигне його отримати і виконати пошук по індексу - цей пакет буде доданий до дерева як такий, що не належить цьому користувачу. Звісно, ітератор залишиться неініціалізованим.
Після цього користувач додається до індексу і все працює добре. Якщо користувач залишається авторизованим як мінімум REMOVE_TIME секунд - "поганий" пакет просто видаляється з дерева. А якщо користувач розавторизується до цього моменту - починається низка викликів, яка приводить нас до TRAFFCOUNTER::DelUser. Він переглядає дерево на предмет пакетів, що належать юзеру (за ip). І, звісно, знаходить такий "поганий" пакет. Потім виконується перевірка user*-user*Present яку треба замінити assert'ом. Але це не наша ситуація. Умова, що перевіряється не є сильною. Вона перевіряє випадок, коли пакет дійсно належить юзеру і ітератор встановлено вірно, але не вказано user*Present. У нас же інша ситуація - ітератор взагалі не ініціалізований. Тому цей "assert" не спрацьовує.
Тут як раз і виникає ситуація, що приводить до падіння Stargazer. Мені вдалося змоделювати ситуацію вставкою 5-секундної затримки на завершення виклику TRAFFCOUNTER::AddUser (уже після того як переглянули дерево пакетів). Далі я авторизувався в системі, але ще 5 секунд Inetaccess залишався червоним. За цей час я швиденько запустив ping, а коли процес авторизації завершився - розавторизувався. В результаті отримав таке:
traffcounter.cpp > 18:11:34 > DelUser: test traffcounter.cpp > 18:11:34 > Counting upload packet: 192.168.1.18 -> 195.5.61.70 traffcounter.cpp > 18:11:34 > Counting upload packet: 192.168.1.18 -> 195.5.61.68 traffcounter.cpp > 18:11:34 > Counting upload packet: 192.168.1.18 -> 192.168.1.7 traffcounter.cpp > 18:11:34 > Counting download packet: 192.168.1.7 -> 192.168.1.18 traffcounter.cpp > 18:11:34 > Counting abandoned packet: 192.168.1.18 -> 195.5.61.70 traffcounter.cpp > 18:11:34 > ALARM!!!!!!!!!!!!!!!!!!!!!!!!!!!! traffcounter.cpp > 18:11:34 > Counting abandoned packet: 192.168.1.18 -> 195.5.61.68 traffcounter.cpp > 18:11:34 > ALARM!!!!!!!!!!!!!!!!!!!!!!!!!!!! traffcounter.cpp > 18:11:34 > Counting upload packet: 192.168.1.18 -> 192.168.1.255 users.cpp > 18:11:34 > Del IP Idx
Звісно, Stargazer не впав, бо я поставив собі ту додаткову перевірку. Але я заодно поставив і "пастку" для цього багу - і вона спрацювала, показуючи що така ситуація теоретично можлива.
У реальному житті таке може бути лише коли користувач генерує велику кількість пакетів ще до авторизації в системі.
Більше цей баг не проявлявся.
Отака історія, коли фітіль підпалюється в одному місці, а бомба вибухає зовсім у іншому.
