Bug 73 not resolved (ipt_NETFLOW freeze network (NETDEV WATCHDOG: eth3...
NetFlow iptables module for Linux kernel
Brought to you by:
aabc
Bug 73 not resolved.
Oct 31 17:51:53 servername kernel: [ 3788.208009] BUG: soft lockup - CPU#5 stuck for 23s! [swapper/5:0] Oct 31 17:51:53 servername kernel: [ 3788.208010] Modules linked in: ip6table_filter(F) ip6_tables(F) xt_IMQ(F) iptable_mangle(F) xt_CT(F) iptable_raw(F) xt_nat(F) xt_mark(F) iptable_nat(F) nf_nat_ipv4(F) nf_nat(F) nf_conntrack_ipv4(F) nf_defrag_ipv4(F) xt_state(F) xt_tcpudp(F) ipt_NETFLOW(O) nf_conntrack(F) xt_hashlimit(F) xt_set(F) iptable_filter(F) ip_tables(F) x_tables(F) sch_sfq(F) cls_fw(F) cls_u32(F) sch_htb(F) imq(F) ip_set_hash_ip(F) ip_set_hash_net(F) ip_set(F) nfnetlink(F) bonding(F) radeon(F) kvm(F) ttm(F) drm_kms_helper(F) drm(F) gpio_ich(F) i2c_algo_bit(F) i5000_edac(F) edac_core(F) psmouse(F) lpc_ich(F) shpchp(F) microcode(F) i5k_amb(F) serio_raw(F) coretemp(F) joydev(F) mac_hid(F) dcdbas(F) lp(F) parport(F) usb_storage(F) hid_generic(F) usbhid(F) hid(F) igb(OF) dca(F) mptsas(F) mptscsih(F) mptbase(F) bnx2(F) scsi_transport_sas(F) Oct 31 17:51:53 servername kernel: [ 3788.208010] CPU: 5 PID: 0 Comm: swapper/5 Tainted: GF W O 3.10.17-custom-imq-b2 #1 Oct 31 17:51:53 servername kernel: [ 3788.208010] Hardware name: Dell Inc. PowerEdge 1950/0TT740, BIOS 2.6.1 04/20/2009 Oct 31 17:51:53 servername kernel: [ 3788.208010] task: ffff880129b25dc0 ti: ffff880129b2c000 task.ti: ffff880129b2c000 Oct 31 17:51:53 servername kernel: [ 3788.208010] RIP: 0010:[<ffffffffa03cc6f5>] [<ffffffffa03cc6f5>] netflow_target+0xc95/0x1124 [ipt_NETFLOW] Oct 31 17:51:53 servername kernel: [ 3788.208010] RSP: 0018:ffff88012fd43a40 EFLAGS: 00000212 Oct 31 17:51:53 servername kernel: [ 3788.208010] RAX: ffff8800a856d888 RBX: ffff880125cab000 RCX: 0000000000000010 Oct 31 17:51:53 servername kernel: [ 3788.208010] RDX: 0000000000000000 RSI: 0000000000000011 RDI: 000000000000003e Oct 31 17:51:53 servername kernel: [ 3788.208010] RBP: ffff88012fd43b50 R08: 0000000000000020 R09: 0000000000000001 Oct 31 17:51:53 servername kernel: [ 3788.208010] R10: 0000000000000020 R11: 0000000000000020 R12: ffff88012fd439b8 Oct 31 17:51:53 servername kernel: [ 3788.208010] R13: ffffffff816b350a R14: ffff88012fd43b50 R15: ffff8800adeb3680 Oct 31 17:51:53 servername kernel: [ 3788.208010] FS: 0000000000000000(0000) GS:ffff88012fd40000(0000) knlGS:0000000000000000 Oct 31 17:51:53 servername kernel: [ 3788.208010] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b Oct 31 17:51:53 servername kernel: [ 3788.208010] CR2: 0000000002583098 CR3: 000000012755e000 CR4: 00000000000007e0 Oct 31 17:51:53 servername kernel: [ 3788.208010] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 Oct 31 17:51:53 servername kernel: [ 3788.208010] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400 Oct 31 17:51:53 servername kernel: [ 3788.208010] Stack: Oct 31 17:51:53 servername kernel: [ 3788.208010] ffff88012fd43a70 ffffffffa01370da 4661010a2fd43b50 0000000000000246 Oct 31 17:51:53 servername kernel: [ 3788.208010] ffff88012fd43a70 ffffffff00000020 ffff88012fd43ab0 ffffffffa00d66de Oct 31 17:51:53 servername kernel: [ 3788.208010] ffff880100000000 00000020000000bd 00000000ac162054 ffff88012fd43a60 Oct 31 17:51:53 servername kernel: [ 3788.208010] Call Trace: Oct 31 17:51:53 servername kernel: [ 3788.208010] <IRQ> Oct 31 17:51:53 servername kernel: [ 3788.208010] [<ffffffffa01370da>] ? hash_ip4_kadt+0x8a/0xb0 [ip_set_hash_ip] Oct 31 17:51:53 servername kernel: [ 3788.208010] [<ffffffffa00d66de>] ? ip_set_test+0x8e/0x120 [ip_set] Oct 31 17:51:53 servername kernel: [ 3788.208010] [<ffffffffa012f2aa>] ? hash_net4_kadt+0x9a/0xd0 [ip_set_hash_net] Oct 31 17:51:53 servername kernel: [ 3788.208010] [<ffffffffa0396156>] ipt_do_table+0x2c6/0x5e5 [ip_tables] Oct 31 17:51:53 servername kernel: [ 3788.208010] [<ffffffffa013f0d3>] iptable_filter_hook+0x33/0x64 [iptable_filter] Oct 31 17:51:53 servername kernel: [ 3788.208010] [<ffffffff815d3766>] nf_iterate+0x86/0xb0 Oct 31 17:51:53 servername kernel: [ 3788.208010] [<ffffffff815db920>] ? ip_frag_mem+0x40/0x40 Oct 31 17:51:53 servername kernel: [ 3788.208010] [<ffffffff815d3804>] nf_hook_slow+0x74/0x150 Oct 31 17:51:53 servername kernel: [ 3788.208010] [<ffffffff815db920>] ? ip_frag_mem+0x40/0x40 Oct 31 17:51:53 servername kernel: [ 3788.208010] [<ffffffff815dbd60>] ip_forward+0x3c0/0x3e0 Oct 31 17:51:53 servername kernel: [ 3788.208010] [<ffffffff815d9b38>] ip_rcv_finish+0x78/0x320 Oct 31 17:51:53 servername kernel: [ 3788.208010] [<ffffffff815da3f9>] ip_rcv+0x239/0x390 Oct 31 17:51:53 servername kernel: [ 3788.208010] [<ffffffff815a63f2>] __netif_receive_skb_core+0x682/0x7f0 Oct 31 17:51:53 servername kernel: [ 3788.208010] [<ffffffff810a4007>] ? generic_exec_single+0xa7/0xb0 Oct 31 17:51:53 servername kernel: [ 3788.208010] [<ffffffff815a6581>] __netif_receive_skb+0x21/0x70 Oct 31 17:51:53 servername kernel: [ 3788.208010] [<ffffffff815a6674>] process_backlog+0xa4/0x180 Oct 31 17:51:53 servername kernel: [ 3788.208010] [<ffffffff815a6e39>] net_rx_action+0x139/0x230 Oct 31 17:51:53 servername kernel: [ 3788.208010] [<ffffffff8104ba67>] __do_softirq+0xe7/0x230 Oct 31 17:51:53 servername kernel: [ 3788.208010] [<ffffffff816b3b7c>] call_softirq+0x1c/0x30 Oct 31 17:51:53 servername kernel: [ 3788.208010] [<ffffffff810048a5>] do_softirq+0x55/0x90 Oct 31 17:51:53 servername kernel: [ 3788.208010] [<ffffffff8104bd15>] irq_exit+0xa5/0xb0 Oct 31 17:51:53 servername kernel: [ 3788.208010] [<ffffffff810256b5>] smp_call_function_single_interrupt+0x35/0x40 Oct 31 17:51:53 servername kernel: [ 3788.208010] [<ffffffff816b373a>] call_function_single_interrupt+0x6a/0x70 Oct 31 17:51:53 servername kernel: [ 3788.208010] <EOI> Oct 31 17:51:53 servername kernel: [ 3788.208010] [<ffffffff8154cfb3>] ? cpuidle_enter_state+0x63/0xe0 Oct 31 17:51:53 servername kernel: [ 3788.208010] [<ffffffff8154d0e9>] cpuidle_idle_call+0xb9/0x200 Oct 31 17:51:53 servername kernel: [ 3788.208010] [<ffffffff8100b10e>] arch_cpu_idle+0xe/0x30 Oct 31 17:51:53 servername kernel: [ 3788.208010] [<ffffffff81094740>] cpu_startup_entry+0xd0/0x250 Oct 31 17:51:53 servername kernel: [ 3788.208010] [<ffffffff81694f68>] start_secondary+0x1df/0x1e4 Oct 31 17:51:53 servername kernel: [ 3788.208010] Code: 41 39 f0 76 2b 48 63 ce 83 c6 01 0f b6 3c 08 40 80 ff 1f 77 16 40 0f b6 cf 45 89 d3 41 29 cb 44 89 d9 45 89 cb 41 d3 e3 44 09 da <40> 84 ff 75 19 89 95 2c ff ff ff 48 c7 c3 20 40 01 00 48 8b a5
# modinfo ipt_NETFLOW filename: /lib/modules/3.10.17-custom-imq-b2/extra/ipt_NETFLOW.ko alias: ip6t_NETFLOW version: v1.8-70-g057b110 description: iptables NETFLOW target module author: <abc@telekom.ru> license: GPL srcversion: B7D5B791C709AD4446D811D depends: x_tables,nf_conntrack vermagic: 3.10.17-custom-imq-b2 SMP mod_unload modversions parm: destination:export destination ipaddress:port (charp) parm: inactive_timeout:inactive flows timeout in seconds (int) parm: active_timeout:active flows timeout in seconds (int) parm: debug:debug verbosity level (int) parm: sndbuf:udp socket SNDBUF size (int) parm: protocol:netflow protocol version (5, 9, 10) (int) parm: refresh_rate:NetFlow v9/IPFIX refresh rate (packets) (uint) parm: timeout_rate:NetFlow v9/IPFIX timeout rate (minutes) (uint) parm: natevents:send NAT Events (int) parm: hashsize:hash table size (int) parm: maxflows:maximum number of flows (int) parm: aggregation:aggregation ruleset (charp)
This become interesting. Thanks for modinfo and full oops text. I will think about it.
Btw, can you attach your ipt_NETFLOW.ko binary?
Attached
Не знаю репрезентативно и полезно ли - но по наблюдениям с модулем роутер едет около 1 часа. Первые случаи были рандомные по несколько часов, но вот сегодня - утром на сервер, который более 12 часов ехал без модуля загрузил модуль и если судить по графикам нагрузки - примерно плюс минус через час заглох. Вечером аналогично - час.
Last edit: Alexander 2013-10-31
Спс. Потестируйте с дебаг ядром, если не лень.
Ядро с дебагом соберу. (в прошлый раз пока собирал - как раз был закрыт баг :) )
Только придумать бы как синтетически потестировать и воспроизвести ситуацию, чтобы руководство меня не сожгло на ритуальном костре.
Я сделал еще небольшой фикс потенциального бага в обработке tcp options у фрагментированных пакетов. Но по идее он не должен давать такой эффект как у вас. Тем не менее, если будете продолжать тестировать возьмите версию из git. Если git pull не сработает (так как я делал amend) сделайте clone заново.
По бинарнику и дампу лога я понял что вылетает где-то в районе обработки tcp options.
А после того как случается BUG система продолжает работать?
Last edit: ABC 2013-10-31
I decided to try pktgen stress testing: https://github.com/aabc/ipt-netflow/wiki/Testing-with-pktgen
Вобщем-то засада. Искусственно проблему не могу воспроизвести пока. Собрал ядро с дебагом. Вдул сначала извне трафик по pktgen, завернул его в NETFLOW, сделал чуть более 2к адресов источника, параллельно дую торренты сквозь него и нагружено делаю всякие tc class change по интерфейсам для htb. В pktgen даже 500кппс накручивал - и ничего. Летит себе тихо мирно и не падает.
Судя по всему так и есть, трабла в районе tcp - так как вагон udp у меня едет отлично. Сейчас буду думать на тему iperf по tcp продуть.
Тут все сложно. В консоли сыпет между другими много ерроров самого нетфлоу (о том, что не может отправить свои данные). В самом начале еще немного действий в системе предпринять можно - я так один раз успел слить лог. Но позже глохнет совсем - по консоли падает всякие Soft lockup, а на клавиатуру можно сказать не реагирует. Хотя стоит заметить - для фейловера сделал серверу две BGP сессии - одну внутрь, другую наружу - внутренняя порвалась во время последнего креша, в внешняя осталась активной - при том, что пинг не ходил.
Last edit: Alexander 2013-11-01
tcp я тестил nmap x.x.x.x/24 на местную сетку. Попробую ещё. Не уверен что iperf справится с задачей так как там будут однотипные пакеты, а тут похоже что-то в реально мтрафике. Надо бы както прогнать зеркало реального трафика, но у меня нет такой возможности.
Пришлите побольше лога. Можно на почту.
Уже набегали терабайты трафика тестов, а все еще летит. Есть идеи, что еще в него затолкать?
Отправил весь kern.log, который успел вытянуть вчера.
Может еще пойти от противного? :) 20 марта я качал архив ipt_NETFLOW. В имени архива 1.8, в modinfo:
Он едет с тех пор по реальным трафиком.
Спасибо за лог. В смысле от противного? 1.8 это предыдущий релиз его тестить не надо.
Я так понимаю в архиве я мог скачать только как раз релиз и есть основания полагать, что он едет. Основные ченджи, судя по логу, происходили уже осенью 2013. Возможно есть к чему присмотреться?
Конечно есть, очень много измененйи было с 1.8. Если вы не хотите тестировать - пользуйтесь версией 1.8, это стабильная версия.
Я не в том контексте имел ввиду. Тестировать надо, просто предложил как вариант оценить изменения в разрезе какие из них могли привести к подобному эффекту.
Следующую версию (которую мы тестируем) надо будет назвать 2.0, там появилось ipv6 support, nat evens, netflow v9, ipfix, ip/tcp options, nexthop, не считая прочих мелких.
Отзеркалировал трафик на сервер, по ридми затолкал его в netflow. Причем как в raw/PREROUTING, так и в filter/FORWARD. По стате модуль пропускает через себя 70-90кппс. Будем ждать.
Креш состоялся, однако к моменту когда я добрался до консоли - меня спас только резет. А kern.log остался без интересных сообщений. Скрин консоли в аттаче.
Не, это не информативно. А можете консоль подключить к другой машине? А при буте этой указать что-то вроде console=ttyS0,115200, а на другой, например, minicom -C и в лог.
Все проще. Оставил mate-terminal с бесконечной прокруткой и tail -f на kern.log. Результат выслал на почту. Или все же нужно еще что-то с консоли?
Спасибо огромное за логи - буду анализировать. С консоли нужен был только полный лог сообщений ядра (скажем с момента загрузки модуля). Видимо вы это и прислали, только я не вижу верхушки - надеюсь там ничего небыло - а то то, что вам может показаться незначимым (скажем трейс где не упоминается netflow) может оказаться полезным.
Да и еще не помешает бинарник модуля ipt_NETFLOW.ko для анализа строчек типа "Code: 00 83 88 3c e0 ff ff 04 5d c3 8a 47 08 55 48 89 e5 3c 01 75 07 e8 88 41 c4 ff eb 17 3c 02 75 07 e8 ab ff ff ff eb 0c 8b 57 04 ec <48> 8b 15 44 ee 35 01 ed 5d c3 66 66 66 66 90 55 48 63 c2 48 8d" и содержимого регистров. А то первый раз я ошибся, так как у меня компилятор создает немного другой код и я решил что ошибка связана с ip_options, а по вашему бинарнику выяснилось, что с tcp_options.