Linux все еще не торт

Эта история началась около месяца назад, когда Кирилл Тхай добавил поддержку вложенных пространств имен в CRIU, после чего наша система CI приказала долго жить. В тот момент ничто не предвещало тех увлекательных приключений, в которые мы оказались вовлечены.



При пристальном рассмотрении выяснилось, что ядро всего лишь течет:

$ slabtop
OBJS ACTIVE USE OBJ SIZE SLABS OBJ/SLAB CACHE SIZE NAME
441920 441450 99% 1.00K 13810 32 441920K kmalloc-1024
224070 222908 99% 0.19K 5335 42 42680K kmalloc-192
38304 21198 55% 0.19K 912 42 7296K dentry
25602 25133 98% 0.12K 753 34 3012K kernfs_node_cache
19380 19380 100% 0.04K 190 102 760K Acpi-Namespace

$ uname -a
Linux zdtm.openvz.org 4.10.17-200.fc25.x86_64 #1 SMP Mon May 22 18:12:57 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux

“Течёт и течёт, с кем не бывает”, подумали мы и обновились до 4.11. В той части CI у нас стоит Fedora, и тогда это было самое новое её ядро. Загрузили, и уже через пару минут CI нам снова передал привет посредством неработающего netfilter-а — при попытке удалить добавленное правило выдавалась невнятная ошибка:

[root@zdtm ~]# iptables -w -t filter --protocol tcp -A INPUT --dport 12345 -j DROP
[root@zdtm ~]# iptables -w -t filter --protocol tcp -D INPUT --dport 12345 -j DROP
iptables: Bad rule (does a matching rule exist in that chain?).

С помощью iptables CRIU блокирует сеть, чтобы зафиксировать состояние TCP сокетов. Ясно, что с таким багом наш CI работать тоже не мог. Недолго думая, мы собрали и загрузили ядро прямо из дерева Линуса, но и оно проработало недолго — снова потекла память:

[root@zdtm criu]# cat /proc/slabinfo | grep mnt
mnt_cache 36456 36456 384 42 4 : tunables 0 0 0 : slabdata 868 868 0

[root@zdtm criu]# python test/zdtm.py run -t zdtm/static/env00 --iter 10 -f ns
========================= Run zdtm/static/env00 in ns ==========================
Start test
./env00 --pidfile=env00.pid --outfile=env00.out --envname=ENV_00_TEST
Run criu dump
Run criu restore
Run criu dump
....
Run criu restore
Send the 15 signal to 339
Wait for zdtm/static/env00(339) to die for 0.100000
Removing dump/zdtm/static/env00/31
========================= Test zdtm/static/env00 PASS ==========================

[root@zdtm criu]# cat /proc/slabinfo | grep mnt
mnt_cache 36834 36834 384 42 4 : tunables 0 0 0 : slabdata 877 877 0

О проблеме доложили в lkml и пошли дальше заниматься своими делами. Вскоре наш соотечественник Александр Виро ответил, что Андрей Вагин нехороший человек и плохо объяснил предпосылки проблемы. А Александр, на минуточку, является Самым Главным Человеком в подсистеме, отвечающей за все, что связано с файлами, файловыми системами. Он не отличается быстротой реакции на присылаемые изменения, но если вы прислали какое-то г… но, то ответ настигнет вас сразу и неизбежно. А если вы тугодум, то он даже на родном объяснит все простыми словами.

Иногда проще починить баг, чем объяснять, что случилось, чем Андрей и занялся. Через некоторое время патч был готов, он был послан в рассылку и приложен к ядру, которое, в свою очередь, было загружено на CI. С чувством исполненного долга Андрей пошел заниматься своими делами. Виро молчал, что означало отсутствие очевидных проблем в патче. Еще одним признаком избавления от старой проблемы явилось сообщение о новой проблеме.

[ 699.207570] BUG: Bad page state in process ip6tables-save pfn:1499f4

Времени и желания разбираться уже не оставалось, ограничились письмом в lkml, а в CI загрузили ядро 4.10, у которого было существенное преимущество — оно работало и не падало. Да, оно немного текло, и мы решили перезагружать машину раз в сутки. Кто-то вспомнил о старых добрых временах, когда все подряд перегружали винду, если та начинала тормозить.

Свежий баг мировыми усилиями довольно оперативно починили. На CI установили Самое Новое и Лучшее ядро, но не тут-то было. Посыпались ошибки в тестах, примерно в каждом втором.

На этом направлении оборону держал Кирилл Горкунов (отчасти из-за того, что Андрей пошел спать). К утру в lkml развернулась большая дискуссия. Оказалось, что наши коллеги-ядерщики чинили Страшную Уязвимость CVE-2017-1000364 и поломали обратную совместимость пользовательского API. Поломка эта была практически умышленной: без этого код становился намного сложнее, и сообщество, скрепя сердце, решилось на крайние меры. А в силу того, что речь шла о Страшной Уязвимости (нужна картинка windows security model с воротами без забора), изменения не обсуждались публично и были наскоро влиты в ядро. Сразу после этого оказалось, что изменения привнесли в ядро другой баг, который тоже оказался Страшной Уязвимостью, и ещё несколько дней ушло на уже открытые дебаты по новой проблеме.

Возникшая неразбериха сказалась на дистрибутивах. Когда инженеры RedHat и Ubuntu переносили эти изменения в свои ядра, что-то пошло не так, и оба дистрибутива оказались сломанными двумя разными способами. Для нас это тоже было критично, так как часть нашего CI крутится в Travis, а там на выбор предлагается только Ubuntu. Другая часть CI крутится на Fedora, заменить её там на Ubuntu можно ради однородности, но уж конечно не в спешке. Так что в Fedora просто загрузили неродное ядро, его-то должны были уже починить! После установки по привычке сразу посмотрели не течёт ли оно.

unreferenced object 0xffff88006342fa38 (size 1024):
comm "ip", pid 15477, jiffies 4295982857 (age 957.836s)
hex dump (first 32 bytes):
b8 b0 4d a0 ff ff ff ff c0 34 c3 59 00 88 ff ff ..M......4.Y....
04 00 00 00 a4 01 00 00 00 00 00 00 00 00 00 00 ................
backtrace:
[ffffffff8190510a] kmemleak_alloc+0x4a/0xa0
[ffffffff81284130] __kmalloc_track_caller+0x150/0x300
[ffffffff812302d0] kmemdup+0x20/0x50
[ffffffffa04d598a] dccp_init_net+0x8a/0x160 [nf_conntrack]
[ffffffffa04cf9f5] nf_ct_l4proto_pernet_register_one+0x25/0x90

Течёт. Необходимые изменения нашлись быстро, по какой-то причине maintainer DCCP не отправил их Линусу, и они затерялись в его дереве. Берём патч (на доклад в рассылку настроения уже нет), перезагружаемся в новое ядро.

В одном из своих произведений Марк Твен описывает человека по имени Оливер, который отправился на серебряные месторождения. Путешествие проходило в очень тяжёлых условиях, но Оливер молча переносил все выпавшие на его долю тяготы. Однажды, во время длительной стоянки (возможно это был уже конец их похода) в его жилье, проломив крышу, свалился мул. На следующий день ситуация повторилась, и Оливер перенёс свой домик в сторону, где мулы не гуляли, но это его не спасло — в дом, опять сломав крышу, упала корова. В тот момент Оливер впервые выразил своё недовольство происходящим фразой: «Это уже становится однообразным», после чего подал в отставку и уехал.

«Это уже становится однообразным», подумал Андрей, посмотрев на загруженное ядро.

unreferenced object 0xffff9f79442cd980 (size 112):
comm "kworker/1:4", pid 15416, jiffies 4307432421 (age 28687.562s)
hex dump (first 32 bytes):
00 00 00 00 ad 4e ad de ff ff ff ff 00 00 00 00 .....N..........
ff ff ff ff ff ff ff ff b8 39 1b 97 ff ff ff ff .........9......
backtrace:
[ffffffff9591d28a] kmemleak_alloc+0x4a/0xa0
[ffffffff95276198] kmem_cache_alloc_node+0x168/0x2a0
[ffffffff95279f28] __kmem_cache_create+0x2b8/0x5c0
[ffffffff9522ff57] create_cache+0xb7/0x1e0
[ffffffff952305f8] memcg_create_kmem_cache+0x118/0x160
[ffffffff9528eaf0] memcg_kmem_cache_create_func+0x20/0x110
[ffffffff950cd6c5] process_one_work+0x205/0x5d0
[ffffffff950cdade] worker_thread+0x4e/0x3a0
[ffffffff950d5169] kthread+0x109/0x140
[ffffffff9592b8fa] ret_from_fork+0x2a/0x40
[ffffffffffffffff] 0xffffffffffffffff
unreferenced object 0xffff9f798a79f540 (size 32)

К чести Андрея, в отставку он не подал, а доложил о проблеме в lkml, настроил профилактическую перезагрузку, запустил CI и занялся своими делами. Через полдня пришло письмо о новых проблемах.

> [22458.504137] BUG: Dentry ffff9f795a08fe60{i=af565f,n=lo} still in
> use (1) [unmount of proc proc]
> [22458.505117] ------------[ cut here ]------------
> [22458.505299] WARNING: CPU: 0 PID: 15036 at fs/dcache.c:1445
…
> [22458.515141] ---[ end trace b37db95b00f941ab ]---
> [22458.519368] VFS: Busy inodes after unmount of proc. Self-destruct
> in 5 seconds. Have a nice day...
> [22458.813846] BUG: unable to handle kernel NULL pointer dereference
> at 0000000000000018
…


Ядро не просто текло, оно вешало тесты, само зависало в непонятном состоянии, но признаки жизни подавало. Проблема показалась знакомой. Выяснилось, что об этой проблеме Андрей уже писал в lkml несколько месяцев назад, но тогда никому до этого не было дела. В этот раз решили проинформировать гораздо больше людей, и реакция наконец-то возникла. Эрик Бидерман почти сразу нашёл проблемный патч, но суть самой проблемы спустя неделю всё ещё оставалась покрытой мраком.

Сейчас на CI машинах у нас загружено латаное-перелатаное ядро, оно пока не падает, но все еще подтекает. В основной ветке у Линуса все эти проблемы цветут и немного пахнут, но это не помешало выпуску 4.12 ядра.

Люди, храните деньги в сберегательных кассах работайте только на стабильных ядрах, если конечно, они у вас есть. Обычному Linux ядру сильно не хватает тестирования.

В заключение хочется процитировать Александра Виро, который на ядерном саммите около десяти лет назад сказал: «We're discussing a lot how to encourage people write the kernel code. But I'd like someone to start a discussion about how to encourage people READ this damned thing.»

Авторы: Павел Емельянов, Кирилл Горкунов и Андрей Вагин.