Хабрахабр

Как у нас сломался Ceph

Детектив в 1 части.
Эта история произошла в октябре.

94 (Hammer). Есть Ceph версии 0. Реплика — 2, минимум 1. 6 стораджей, 8 мониторов, по 6-8 osd на каждом сторадже, SSD диски объемом от 1 ТБ до 4 ТБ.

В логах osd были видны стандартные для ceph ошибки вида no reply from osd. Как-то раз случилось такое: вечером прошел некий шторм по всему кластеру и самопроизвольно перезапустилось множество osd. Немного slow requests и самопроизвольные рестарты, что для ceph не критическое событие и довольно частое. X. Но, к сожалению, не все перезапустившиеся osd смогли подняться. В общем, такое бывает. 45 на storage6.
Мы решили, что это нестрашно, ведь это всего 1 из 50 osd, и пробовали запустить ее разными способами. А именно пала героем osd. В итоге, как обычно в таких ситуациях поступает любой админ, дело кончилось перезапуском всей ноды, так как из опыта известно, что systemd иногда немножко сходит с ума и не хочет корректно запускать нужные процессы. Ну, знаете, umount/mount директории, flush и пересоздание журнала, вот это всё. Или у osd перестает что-то работать, и без перезапуска сервера она не хочет запускаться.

все на этом сторадже. И после перезапуска мы уже имели 4 мертвых osd, т.е. Ошибки такие же, как и на первичной osd:

017-10-12 12:10:01.756562 7f02459af880 0 ceph version 0.94.10 (b1e0532418e4631af01acbc0cedd426f1905f4af), process ceph-osd, pid 2343
2017-10-12 12:10:01.767719 7f02459af880 0 filestore(/var/lib/ceph/osd/ceph-45) backend xfs (magic 0x58465342)
2017-10-12 12:10:01.769302 7f02459af880 0 genericfilestorebackend(/var/lib/ceph/osd/ceph-45) detect_features: FIEMAP ioctl is supported and appears to work
2017-10-12 12:10:01.769310 7f02459af880 0 genericfilestorebackend(/var/lib/ceph/osd/ceph-45) detect_features: FIEMAP ioctl is disabled via 'filestore fiemap' config option
2017-10-12 12:10:01.785177 7f02459af880 0 genericfilestorebackend(/var/lib/ceph/osd/ceph-45) detect_features: syncfs(2) syscall fully supported (by glibc and kernel)
2017-10-12 12:10:01.785229 7f02459af880 0 xfsfilestorebackend(/var/lib/ceph/osd/ceph-45) detect_feature: extsize is disabled by conf
2017-10-12 12:10:01.788289 7f02459af880 0 filestore(/var/lib/ceph/osd/ceph-45) mount: enabling WRITEAHEAD journal mode: checkpoint is not enabled
2017-10-12 12:10:01.790182 7f02459af880 -1 journal FileJournal::_open: disabling aio for non-block journal. Use journal_force_aio to force use of aio anyway
2017-10-12 12:10:01.790184 7f02459af880 1 journal _open /var/lib/ceph/osd/ceph-45/journal fd 19: 10485760000 bytes, block size 4096 bytes, directio = 1, aio = 0
2017-10-12 12:10:01.790428 7f02459af880 1 journal _open /var/lib/ceph/osd/ceph-45/journal fd 19: 10485760000 bytes, block size 4096 bytes, directio = 1, aio = 0
2017-10-12 12:10:01.790923 7f02459af880 0 <cls> cls/hello/cls_hello.cc:271: loading cls_hello
2017-10-12 12:10:01.796251 7f02459af880 0 osd.45 19681 crush map has features 1107558400, adjusting msgr requires for clients
2017-10-12 12:10:01.796260 7f02459af880 0 osd.45 19681 crush map has features 1107558400 was 8705, adjusting msgr requires for mons
2017-10-12 12:10:01.796263 7f02459af880 0 osd.45 19681 crush map has features 1107558400, adjusting msgr requires for osds
2017-10-12 12:10:01.796273 7f02459af880 0 osd.45 19681 load_pgs
2017-10-12 12:10:01.850570 7f02459af880 -1 *** Caught signal (Aborted) ** in thread 7f02459af880 ceph version 0.94.10 (b1e0532418e4631af01acbc0cedd426f1905f4af) 1: /usr/bin/ceph-osd() [0xb35f7d] 2: (()+0x11390) [0x7f0244897390] 3: (gsignal()+0x38) [0x7f0242c8f428] 4: (abort()+0x16a) [0x7f0242c9102a] 5: (__gnu_cxx::__verbose_terminate_handler()+0x16d) [0x7f02435d284d] 6: (()+0x8d6b6) [0x7f02435d06b6] 7: (()+0x8d701) [0x7f02435d0701] 8: (()+0x8d919) [0x7f02435d0919] 9: (object_info_t::decode(ceph::buffer::list::iterator&)+0xb7a) [0x7b47ba] 10: (object_info_t::object_info_t(ceph::buffer::list&)+0x1b7) [0x78cd07] 11: (PGLog::read_log(ObjectStore*, coll_t, coll_t, ghobject_t, pg_info_t const&, std::map<eversion_t, hobject_t, std::less<eversion_t>, std::allocator<std::pair<eversion_t const, hobject_t> > >&, PGLog::IndexedLog&, pg_missing_t&, std::__cxx11::basic_ostringstream<char, std::char_traits<char>, std::allocator<char> >&, std::set<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::less<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::allocator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > >*)+0xf52) [0x784c82] 12: (PG::read_state(ObjectStore*, ceph::buffer::list&)+0x24e) [0x81791e] 13: (OSD::load_pgs()+0xbb6) [0x6b9eb6] 14: (OSD::init()+0x137f) [0x6bdddf] 15: (main()+0x2c20) [0x646310] 16: (__libc_start_main()+0xf0) [0x7f0242c7a830] 17: (_start()+0x29) [0x65c779] NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

Если стартовать osd напрямую через бинарь, а не через upstart или systemctl, то можно увидеть выбрасываемое исключение и немного побольше инфы (бинарь по дефолту пишет STDERR и STDOUT в консоль):

root@storage6:~# /usr/bin/ceph-osd -f --cluster ceph --id 45
starting osd.45 at :/0 osd_data /var/lib/ceph/osd/ceph-45 /var/lib/ceph/osd/ceph-45/journal
2017-10-12 15:13:45.288995 7fc5b1b06880 -1 osd.45 22551 log_to_monitors
terminate called after throwing an instance of 'ceph::buffer::malformed_input' what(): buffer::malformed_input: __PRETTY_FUNCTION__ decode past end of struct encoding
*** Caught signal (Aborted) ** in thread 7fc58e699700
terminate called recursively
Aborted (core dumped)

Здесь мы видим, что демон ругается на какие-то неправильные входные данные (malformed_input). Но что это за данные, пока непонятно. Ситуация осложняется тем, что в кластере появились unfound объекты:

recovery 3/3102030 unfound (0.000%)

Эти 4 незапускающиеся osd через таймаут были помечены мониторами как out. Началось восстановление и репликация данных, и в кластере появилось ни с того ни с сего 100 непроходящих slow requests. Так как Ceph используется Openstack'ом в качестве storage backend'а (не prod, но dev окружение) клиенты (команды разработки) это очень почувствовали и вся работа заметно замедлилась, так как виртуалки сильно тормозили.

Один для непосредственно дисков виртуалок — rbd1, второй — для образов, из которых создаются эти диски. В Ceph у нас два пула. Но если в первом случае — все анфаунды в rbd1 — мы будем иметь максимум 3 фарша, то во втором случае — все анфаунды в images — мы потенциально имеем целый магазинчик фарша в связи с особенностями работы Openstack. Unfound объекты в данном случае критичны для обоих пулов, так как могут стать следствием неконсистентности данных. Поэтому, так как мы в принципе были готовы потерять три машины, потому что опенстек — это не продакшн, требовалось проверить, к какому пулу относятся эти ненайденные объекты:

root@volume1:~# ceph pg 2.67 list_missing
{ "offset": { "oid": "", "key": "", "snapid": 0, "hash": 0, "max": 0, "pool": -1, "namespace": "" }, "num_missing": 3, "num_unfound": 3, "objects": [ { "oid": { "oid": "rbd_data.8e53d86b8b4567.0000000000000220", "key": "", "snapid": -2, "hash": 2391933031, "max": 0, "pool": 2, "namespace": "" }, "need": "19232'24922826", "have": "19172'24922749", "locations": [] }, { "oid": { "oid": "rbd_data.42375f55c840f3.000000000000c6d3", "key": "", "snapid": -2, "hash": 1598576743, "max": 0, "pool": 2, "namespace": "" }, "need": "19229'24922824", "have": "19110'24922274", "locations": [] }, { "oid": { "oid": "rbd_data.b4b7816b8b4567.0000000000000298", "key": "", "snapid": -2, "hash": 2351466599, "max": 0, "pool": 2, "namespace": "" }, "need": "19229'24922823", "have": "19110'24921517", "locations": [] } ], "more": 0
}

Они все были на одной osd, в одной pg и в пуле номер 2. И… это пул rbd1, так что выдохнули. Если что, мы теряем всего три виртуалки, это не так страшно.

45`. Удаляем одну из проблемных osd из кластера с помощью `ceph osd rm osd. Да что ж такое! Анфаундов становится 28. Нужно любым способом попытаться восстановить неработающие osd, или нас ждет полный ресетап всех виртуалок в Openstack, а это, во-первых, сложно, а во-вторых, ужасно стыдно. Это уже проблема. В общем, мы врубили режим лютого дебага.

Итак, что у нас есть в данный момент?

тогда нужно стриггерить восстановление событием: osd up->osd down->osd up). — по кластеру прошла какая-то аномалия, заставившая часть osd перезапуститься;
— одна из них не смогла запуститься;
— после рестарта ее ноды не смогли запуститься оставшиеся osd;
— в кластере есть заблокированные запросы, все на одной osd (8ая);
— кластере есть unfound объекты (28 штук), все на той же самой osd (8ая);
— видимо, удаление из кластера остальных osd опять увеличит количество анфаундов, значит делать это не стоит;
— клиенты страдают, recovery периодически останавливается и приходится его триггерить перезапуском любой из работающих osd (кластер ceph иногда может залипать и переставать восстанавливаться.

45: Стрейсим запуск osd.

pidof `start ceph-osd id=45` | xargs strace -p 2> 45-strace.log

Видим, что osd спотыкается на чтении одного из участка локальных данных, после чего выбрасывается знакомое уже нам исключение ceph::buffer::malformed_input:

stat("/var/lib/ceph/osd/ceph-45/current/2.c_head", {st_mode=S_IFDIR|0755, st_size=24576, ...}) = 0
stat("/var/lib/ceph/osd/ceph-45/current/2.c_head/DIR_C", {st_mode=S_IFDIR|0755, st_size=24576, ...}) = 0
stat("/var/lib/ceph/osd/ceph-45/current/2.c_head/DIR_C/DIR_0", {st_mode=S_IFDIR|0755, st_size=24576, ...}) = 0
stat("/var/lib/ceph/osd/ceph-45/current/2.c_head/DIR_C/DIR_0/DIR_0", {st_mode=S_IFDIR|0755, st_size=24576, ...}) = 0
stat("/var/lib/ceph/osd/ceph-45/current/2.c_head/DIR_C/DIR_0/DIR_0/DIR_D", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
stat("/var/lib/ceph/osd/ceph-45/current/2.c_head/DIR_C/DIR_0/DIR_0/DIR_D/DIR_B", 0x7ffcccfdf330) = -1 ENOENT (No such file or directory)
stat("/var/lib/ceph/osd/ceph-45/current/2.c_head/DIR_C/DIR_0/DIR_0/DIR_D/rbd\\udata.e1bde639901b63.0000000000000000__head_852BD00C__2", {st_mode=S_IFREG|0644, st_size=8388608, ...}) = 0
stat("/var/lib/ceph/osd/ceph-45/current/2.c_head/DIR_C/DIR_0/DIR_0/DIR_D/rbd\\udata.e1bde639901b63.0000000000000000__head_852BD00C__2", {st_mode=S_IFREG|0644, st_size=8388608, ...}) = 0
open("/var/lib/ceph/osd/ceph-45/current/2.c_head/DIR_C/DIR_0/DIR_0/DIR_D/rbd\\udata.e1bde639901b63.0000000000000000__head_852BD00C__2", O_RDWR) = 22
fgetxattr(22, "user.ceph._", 0x7ffcccfdf7c0, 100) = -1 ERANGE (Numerical result out of range)
fgetxattr(22, "user.ceph._", NULL, 0) = 250
fgetxattr(22, "user.ceph._", "\17\10\r\1\0\0\4\3I\0\0\0\0\0\0\0(\0\0\0rbd_data.e1bde639901b63.0000000000000000\376\377\377\377\377\377\377\377\f\320+\205\0\0\0\0\0\2\0\0\0\0\0\0\0\6\3\34\0\0\0\2\0\0\0\0\0\0\0\377\377\377\377\0\0\0\0\0\0\0\0\377\377\377\377\377\377\377\377\0\0\0\0M\311\274\2\0\0\0\0\34K\0\0L\311\274\2\0\0\0\0\34K\0\0\2\2\25\0\0\0\10h\361\374\0\0\0\0\0\341\244\v\0\0\0\0\0\0\0\0\0\0\0\200\0\0\0\0\0\265?\336Y\256\270N\5\2\2\25\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0M\311\274\2\0\0\0\0\0\0\0", 250) = 250
futex(0x7f963ba19680, FUTEX_WAKE_PRIVATE, 2147483647) = 0
write(2, "terminate called after throwing "..., 48) = 48
write(2, "ceph::buffer::malformed_input", 29) = 29
write(2, "'\n", 2) = 2
write(2, " what(): ", 11) = 11
write(2, "buffer::malformed_input: __PRETT"..., 79) = 79
write(2, "\n", 1) = 1
rt_sigprocmask(SIG_UNBLOCK, [ABRT], NULL, 8) = 0
tgkill(23708, 23708, SIGABRT) = 0
--- SIGABRT {si_signo=SIGABRT, si_code=SI_TKILL, si_pid=23708, si_uid=0} ---
write(2, "*** Caught signal (Aborted) **\n "..., 55) = 55
futex(0x7f963b802110, FUTEX_WAKE_PRIVATE, 2147483647) = 0
write(2, " ceph version 0.94.10 (b1e053241"..., 1418) = 1418
futex(0x48d40b4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x48d40b0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x48d4030, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x48d4058, FUTEX_WAIT_PRIVATE, 2, NULL) = 0

Возможно, битый, неконсистентый объект e1bde639901b63.0000000000000000__head_852BD00C__2? Так как по стрейсу четко видно, что исключение выбрасывается после попытки обработать данный объект. Что ж, ищем его реплику на других стораджах:

find /mnt/osd? -name *e1bde639901b63.0000000000000000__head_852BD00C*

Находим его на storage5 у osd.37. Сверяем md5-сумму. Одинаковая. Ну, может xattr`ы отличаются? Аккуратно копируем rsync'ом объект с storage5 на storage6 с сохранением всей мета-информации. Бэкапим оригинальный файл и заменяем его скопированным. Пробуем запустить, но безрезультатно — всё то же самое. Но ведь там osd работает! Как же так?

Тут на этом этапе нам уже помогает C++ разработчик Азат, который знал о ceph, но никогда с ним не работал.
Понятно, что проблема в данных, извлекаемых при boot-процессе osd. Углубляемся в изучение исходного кода демонов и ищем, из-за чего он может валиться. Запускаем заболевшие osd через gdb и пытаемся в дебаг. Пробуем запускать другие, здоровые osd и стрейсим их, чтобы понять, как же они должны по-нормальному работать. Сравниваем процесс запуска.

Говорит, что 37ая osd (с которой мы скопировали «валидный» объект) тогда тоже не должна работать. Через несколько часов разработчик говорит, что понимает, в чем разница старта osd, и на каком участке кода она валится, но непонятна первопричина такого поведения. Мы в отказ. Предлагает ее перезапустить, чтобы доказать гипотезу. Разработчик же говорит логичную вещь, что это все равно не дело, что оно там работает на соплях и в любой момент может упасть и не подняться, а так мы хоть докажем теорию и продвинемся дальше. Мол, и так все плохо, а там вообще другая нода, как бы хуже не было от этого. Рестартуем — не поднимается. Согласны. Но что поделать. Разработчику — счастье, нам — траур, так как анфаундов стало больше, а количество slow requests увеличилось до 800. Понятно, что если при 100 медленных запросов клиенты хоть как-то могли работать, то при 800 всё окончательно встает колом.

Теперь у нас есть потенциально два полных стораджа, osd на которых висят на волоске и оставшиеся 3 запущенных osd на storage5 перезапуска не выдержат.

Находим, что дело как будто бы кроется в xattr'ах и работе с ними. Начинаем сравнивать файловые системы и структуры файлов на здоровых osd, так как видим разницу в старте. Для уточнения стрейсим здоровую osd:

pidof `start ceph-osd id=8` | awk {'print $1'} | xargs strace -fe open,fsetxattr -p 2>8-osd-xattr.strace

Много, конечно, не дает, но видим, что в нормальной и сломанной osd по-разному происходят запросы при запуске. Одни с префиксами, другие без. Разработчик начал смотреть вообще все места, где xattr генерились и\или читались, и там было видно, что такие xattr и должны генериться, но почему-то при чтении была ошибка. Как раз этот момент, почему так, и был непонятен. А потом мы смотрим в git upstream и видим, что добавили это относительно недавно.

Разработчик предлагает обновить Ceph и попробовать запуститься на нем. Вот этот патч, который должен помочь корректно пройти процесс запуска и чтения файловой системы. И один админ отвечает: "Да, случайно ставили, потом паппет переустановил нужную версию". И между делом он невзначай говорит скорее в шутку: "Слушайте, ребят, а вы случайно не ставили тут никогда 10-й ceph?" И смеется. И все начинают ржать. Секунда тишины.

Паппет прикатил ее, накатил osd, запустил их, они начали работать. А дело было вот в чем: storage[56] наливались самыми последними, в момент их сетапа из отдельного окружения были некорректно указаны apt pins, из-за чего поставилась дефолтная версия Ceph из убунтовских реп. Спустя две недели произошел непонятный катаклизм, описанный в самом начале, из-за чего произошло нечто, и одна osd не поднялась. Спустя сутки админ заметил, что версия ceph неправильная, внес изменения, установил верную, перезапустил (!!!) osd (не переналивая) и ушел курить бамбук.

Оказалось, что ребята из Ceph в 10-й версии (Jewel) изменили способ хранения и представления xattr'ов. Разработчик еще в середине пути смотрел на файловые структуры и не понимал, почему они такие странные, и списывал на возможные коррапты данных. Соответственно, в 10-й версии они изменили структуру хранения и стали хранить их блоками, разбив на несколько частей. Дело в том, что они раньше хранили все значения xattr'ов inline, но это было неоптимально и имело ограничение по длине. Почему она запустилась после даунгрейда — непонятно. Osd инициализировалась на 10-й версии и проработала так сутки, создав объекты «по-новому», потом ее даунгрейдили, и она так проработала еще 2 недели. Но в нашем случае она натыкалась на эти xattr'ы и не могла их переварить, выбрасывая исключение malformed_input. Возможно, никогда не доходила до этих данных.

Анфаунды ушли, заблокированные запросы тоже исчезли. Мы, конечно же, тут же установили на storage[56] Jewel версии Ceph'а, и все osd как миленькие запустились. Мы уже были почти уверены, что потеряем весь опенстек. Ceph начал восстанавливаться. Конечно, большое спасибо разработчику, он очень помог. И вот как получилось затащить.

Через пару часов после возникновения проблемы один админ сказал, что узнал исключение (mailformed input), выбрасываемое демоном, и пошел смотреть в код, а там всего (!) 23 места, где оно может быть выброшено. Такая вот история. В тот момент для меня это было дико, а масштаб проблемы позволял спокойно копаться в ceph, пробуя различные варианты. Я посмеялся и сказал, что это много и неправильный подход, так как мы все равно не будем пересобирать сeph. Но когда в конце этого дня я понял, что лучшего выхода нет, это показалось мне неплохим шансом, который нужно было использовать.

И в итоге подход «а давайте смотреть в сырцы приложения, чтобы понимать, что происходит и что происходит не так» оказался очень эффективным, а я был не прав.

Теги
Показать больше

Похожие статьи

Добавить комментарий

Ваш e-mail не будет опубликован. Обязательные поля помечены *

Кнопка «Наверх»
Закрыть