Menu

#74 Bug 73 not resolved (ipt_NETFLOW freeze network (NETDEV WATCHDOG: eth3 (igb): transmit queue 8 timed out))

git version
closed-fixed
ABC
None
1
2015-02-18
2013-10-31
Alexander
No

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)

Discussion

1 2 > >> (Page 1 of 2)
  • ABC

    ABC - 2013-10-31

    This become interesting. Thanks for modinfo and full oops text. I will think about it.

     
  • ABC

    ABC - 2013-10-31
    • status: open --> open-accepted
    • Priority: 5 --> 9
     
  • ABC

    ABC - 2013-10-31

    Btw, can you attach your ipt_NETFLOW.ko binary?

     
  • Alexander

    Alexander - 2013-10-31

    Attached

     
  • Alexander

    Alexander - 2013-10-31

    Не знаю репрезентативно и полезно ли - но по наблюдениям с модулем роутер едет около 1 часа. Первые случаи были рандомные по несколько часов, но вот сегодня - утром на сервер, который более 12 часов ехал без модуля загрузил модуль и если судить по графикам нагрузки - примерно плюс минус через час заглох. Вечером аналогично - час.

     

    Last edit: Alexander 2013-10-31
  • ABC

    ABC - 2013-10-31

    Спс. Потестируйте с дебаг ядром, если не лень.

     
  • Alexander

    Alexander - 2013-10-31

    Ядро с дебагом соберу. (в прошлый раз пока собирал - как раз был закрыт баг :) )
    Только придумать бы как синтетически потестировать и воспроизвести ситуацию, чтобы руководство меня не сожгло на ритуальном костре.

     
  • ABC

    ABC - 2013-10-31

    Я сделал еще небольшой фикс потенциального бага в обработке tcp options у фрагментированных пакетов. Но по идее он не должен давать такой эффект как у вас. Тем не менее, если будете продолжать тестировать возьмите версию из git. Если git pull не сработает (так как я делал amend) сделайте clone заново.

    По бинарнику и дампу лога я понял что вылетает где-то в районе обработки tcp options.

    А после того как случается BUG система продолжает работать?

     

    Last edit: ABC 2013-10-31
  • ABC

    ABC - 2013-11-01

    I decided to try pktgen stress testing: https://github.com/aabc/ipt-netflow/wiki/Testing-with-pktgen

     
  • Alexander

    Alexander - 2013-11-01

    Вобщем-то засада. Искусственно проблему не могу воспроизвести пока. Собрал ядро с дебагом. Вдул сначала извне трафик по pktgen, завернул его в NETFLOW, сделал чуть более 2к адресов источника, параллельно дую торренты сквозь него и нагружено делаю всякие tc class change по интерфейсам для htb. В pktgen даже 500кппс накручивал - и ничего. Летит себе тихо мирно и не падает.

    По бинарнику и дампу лога я понял что вылетает где-то в районе обработки tcp options.

    Судя по всему так и есть, трабла в районе tcp - так как вагон udp у меня едет отлично. Сейчас буду думать на тему iperf по tcp продуть.

    А после того как случается BUG система продолжает работать?

    Тут все сложно. В консоли сыпет между другими много ерроров самого нетфлоу (о том, что не может отправить свои данные). В самом начале еще немного действий в системе предпринять можно - я так один раз успел слить лог. Но позже глохнет совсем - по консоли падает всякие Soft lockup, а на клавиатуру можно сказать не реагирует. Хотя стоит заметить - для фейловера сделал серверу две BGP сессии - одну внутрь, другую наружу - внутренняя порвалась во время последнего креша, в внешняя осталась активной - при том, что пинг не ходил.

     

    Last edit: Alexander 2013-11-01
  • ABC

    ABC - 2013-11-01

    tcp я тестил nmap x.x.x.x/24 на местную сетку. Попробую ещё. Не уверен что iperf справится с задачей так как там будут однотипные пакеты, а тут похоже что-то в реально мтрафике. Надо бы както прогнать зеркало реального трафика, но у меня нет такой возможности.

    В консоли сыпет между другими много ерроров самого нетфлоу (о том, что не может отправить свои данные).

    Пришлите побольше лога. Можно на почту.

     
  • Alexander

    Alexander - 2013-11-01

    Уже набегали терабайты трафика тестов, а все еще летит. Есть идеи, что еще в него затолкать?

    # cat /proc/net/stat/ipt_netflow 
    ipt_NETFLOW version v1.8-70-g057b110
    Flows: active 6699 (peak 27683 reached 0d1h28m ago), mem 1099K, worker delay 17/250.
    Hash: size 2097152 (mem 16384K), metric 1.00 [1.00, 1.00, 1.00]. MemTraf: 53497062 pkt, 248776952736 K (pdu 52, 8271).
    Protocol version 5 (netflow). Timeouts: active 300, inactive 15. Maxflows 2000000
    Rate: 143472197780 bits/sec, 370778 packets/sec; Avg 1 min: 144699418817 bps, 374633 pps; 5 min: 145702709546 bps, 376621 pps
    cpu#  stat: <search found new [metric], trunc frag alloc maxflows>, sock: <ok fail cberr, bytes>, traffic: <pkt, bytes>, drop: <pkt, bytes>
    Total stat: 14964747 7360406548 4880186 [2.40],    0    0    0    0, sock: 162482 0 0, 232251 K, traffic: 7365286734, 244055894 MB, drop: 0, 0 K
    cpu0  stat: 2898632 899216653 590721 [1.00],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 899807374, 29061737 MB, drop: 0, 0 K
    cpu1  stat: 2649485 873124676 603947 [1.00],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 873728623, 28884798 MB, drop: 0, 0 K
    cpu2  stat: 524697 877708048 605345 [1.00],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 878313393, 29320032 MB, drop: 0, 0 K
    cpu3  stat: 455007 920484239 541158 [1.00],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 921025397, 30339442 MB, drop: 0, 0 K
    cpu4  stat: 3531489 972027621 613334 [1.00],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 972640955, 32109746 MB, drop: 0, 0 K
    cpu5  stat: 964232 967083168 643466 [1.00],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 967726634, 32570661 MB, drop: 0, 0 K
    cpu6  stat: 813236 941887057 652321 [1.00],    0    0    0    0, sock: 162482 0 0, 232251 K, traffic: 942539378, 31906575 MB, drop: 0, 0 K
    cpu7  stat: 3127969 908875091 629894 [1.00],    0    0    0    0, sock:      0 0 0, 0 K, traffic: 909504985, 29862901 MB, drop: 0, 0 K
    Natevents disabled, count start 0, stop 0.
    sock0: x.x.x.x:20001, sndbuf 229376, filled 1, peak 26049; err: sndbuf reached 0, connect 0, other 0
    
     
  • Alexander

    Alexander - 2013-11-01

    Отправил весь kern.log, который успел вытянуть вчера.

     
  • Alexander

    Alexander - 2013-11-01

    Может еще пойти от противного? :) 20 марта я качал архив ipt_NETFLOW. В имени архива 1.8, в modinfo:

    # modinfo ipt_NETFLOW
    filename:       /lib/modules/3.2.0-40-generic/extra/ipt_NETFLOW.ko
    version:        1.7.2
    description:    iptables NETFLOW target module
    author:         <abc@telekom.ru>
    license:        GPL
    srcversion:     43F3959209576499C33AB98
    depends:        x_tables
    vermagic:       3.2.0-40-generic 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:           hashsize:hash table size (int)
    parm:           maxflows:maximum number of flows (int)
    parm:           aggregation:aggregation ruleset (charp)
    

    Он едет с тех пор по реальным трафиком.

     
  • ABC

    ABC - 2013-11-01

    Спасибо за лог. В смысле от противного? 1.8 это предыдущий релиз его тестить не надо.

     
  • Alexander

    Alexander - 2013-11-01

    В смысле от противного? 1.8 это предыдущий релиз его тестить не надо.

    Я так понимаю в архиве я мог скачать только как раз релиз и есть основания полагать, что он едет. Основные ченджи, судя по логу, происходили уже осенью 2013. Возможно есть к чему присмотреться?

     
  • ABC

    ABC - 2013-11-01

    Конечно есть, очень много измененйи было с 1.8. Если вы не хотите тестировать - пользуйтесь версией 1.8, это стабильная версия.

     
  • Alexander

    Alexander - 2013-11-01

    Я не в том контексте имел ввиду. Тестировать надо, просто предложил как вариант оценить изменения в разрезе какие из них могли привести к подобному эффекту.

     
  • ABC

    ABC - 2013-11-01

    Следующую версию (которую мы тестируем) надо будет назвать 2.0, там появилось ipv6 support, nat evens, netflow v9, ipfix, ip/tcp options, nexthop, не считая прочих мелких.

     
  • Alexander

    Alexander - 2013-11-01

    Отзеркалировал трафик на сервер, по ридми затолкал его в netflow. Причем как в raw/PREROUTING, так и в filter/FORWARD. По стате модуль пропускает через себя 70-90кппс. Будем ждать.

     
  • Alexander

    Alexander - 2013-11-02

    Креш состоялся, однако к моменту когда я добрался до консоли - меня спас только резет. А kern.log остался без интересных сообщений. Скрин консоли в аттаче.

     
  • ABC

    ABC - 2013-11-02

    Не, это не информативно. А можете консоль подключить к другой машине? А при буте этой указать что-то вроде console=ttyS0,115200, а на другой, например, minicom -C и в лог.

     
  • Alexander

    Alexander - 2013-11-02

    Все проще. Оставил mate-terminal с бесконечной прокруткой и tail -f на kern.log. Результат выслал на почту. Или все же нужно еще что-то с консоли?

     
  • ABC

    ABC - 2013-11-02

    Спасибо огромное за логи - буду анализировать. С консоли нужен был только полный лог сообщений ядра (скажем с момента загрузки модуля). Видимо вы это и прислали, только я не вижу верхушки - надеюсь там ничего небыло - а то то, что вам может показаться незначимым (скажем трейс где не упоминается netflow) может оказаться полезным.

     
  • ABC

    ABC - 2013-11-02

    Да и еще не помешает бинарник модуля 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.

     
1 2 > >> (Page 1 of 2)

Log in to post a comment.

Want the latest updates on software, tech news, and AI?
Get latest updates about software, tech news, and AI from SourceForge directly in your inbox once a month.