crash on >= 4.9.0 kernel seems nf related

crash on >= 4.9.0 kernel seems nf related

[Bjørnar Ness]

After running on kernel 4.9 for quite some time, we suddenly experienced
hangs. Tried compiling 4.11.0, but the problem remains. The only think
that changed was a couple
more rules in nft, traffic is the same.

4.8.6 kernel works fine (but has other problems). Attached is the
debugging output, hope it can
help you track down the issue:

May  3 12:46:59 fw01 kernel: [  271.875363] ------------[ cut here ]------------
May  3 12:46:59 fw01 kernel: [  271.875369] WARNING: CPU: 0 PID: 3 at
net/sched/sch_generic.c:316 dev_watchdog+0x212/0x220
May  3 12:46:59 fw01 kernel: [  271.875370] NETDEV WATCHDOG: eth1
(igb): transmit queue 1 timed out
May  3 12:46:59 fw01 kernel: [  271.875370] Modules linked in:
May  3 12:46:59 fw01 kernel: [  271.875373] CPU: 0 PID: 3 Comm:
kworker/0:0 Not tainted 4.11.0 #1
May  3 12:46:59 fw01 kernel: [  271.875374] Hardware name: Dell Inc.
PowerEdge R210/05KX61, BIOS 1.3.4 05/24/2010
May  3 12:46:59 fw01 kernel: [  271.875377] Workqueue: events_long gc_worker
May  3 12:46:59 fw01 kernel: [  271.875378] Call Trace:
May  3 12:46:59 fw01 kernel: [  271.875380]  <IRQ>
May  3 12:46:59 fw01 kernel: [  271.875383]  dump_stack+0x4d/0x6e
May  3 12:46:59 fw01 kernel: [  271.875386]  __warn+0xcc/0xf0
May  3 12:46:59 fw01 kernel: [  271.875387]  warn_slowpath_fmt+0x4a/0x50
May  3 12:46:59 fw01 kernel: [  271.875390]  ? tick_program_event+0x3f/0x70
May  3 12:46:59 fw01 kernel: [  271.875391]  dev_watchdog+0x212/0x220
May  3 12:46:59 fw01 kernel: [  271.875392]  ?
dev_deactivate_queue.constprop.31+0x60/0x60
May  3 12:46:59 fw01 kernel: [  271.875395]  call_timer_fn+0x30/0x140
May  3 12:46:59 fw01 kernel: [  271.875397]  run_timer_softirq+0x1be/0x3f0
May  3 12:46:59 fw01 kernel: [  271.875399]  ? handle_irq_event_percpu+0x40/0x50
May  3 12:46:59 fw01 kernel: [  271.875401]  __do_softirq+0xbe/0x280
May  3 12:46:59 fw01 kernel: [  271.875404]  do_softirq_own_stack+0x1c/0x30
May  3 12:46:59 fw01 kernel: [  271.875404]  </IRQ>
May  3 12:46:59 fw01 kernel: [  271.875406]  do_softirq+0x42/0x50
May  3 12:46:59 fw01 kernel: [  271.875407]  __local_bh_enable_ip+0x75/0x80
May  3 12:46:59 fw01 kernel: [  271.875410]  _raw_spin_unlock_bh+0x15/0x20
May  3 12:46:59 fw01 kernel: [  271.875412]
nf_nat_cleanup_conntrack+0x1bd/0x230
May  3 12:46:59 fw01 kernel: [  271.875413]  ? nf_nat_l3proto_register+0x70/0x70
May  3 12:46:59 fw01 kernel: [  271.875415]  __nf_ct_ext_destroy+0x38/0x50
May  3 12:46:59 fw01 kernel: [  271.875417]  nf_conntrack_free+0x17/0x50
May  3 12:46:59 fw01 kernel: [  271.875418]  destroy_conntrack+0x74/0x90
May  3 12:46:59 fw01 kernel: [  271.875421]  nf_conntrack_destroy+0x12/0x20
May  3 12:46:59 fw01 kernel: [  271.875422]  nf_ct_gc_expired+0x45/0x90
May  3 12:46:59 fw01 kernel: [  271.875423]  gc_worker+0xb3/0x180
May  3 12:46:59 fw01 kernel: [  271.875425]  process_one_work+0x143/0x3e0
May  3 12:46:59 fw01 kernel: [  271.875426]  worker_thread+0x126/0x480
May  3 12:46:59 fw01 kernel: [  271.875429]  kthread+0x104/0x140
May  3 12:46:59 fw01 kernel: [  271.875430]  ? process_one_work+0x3e0/0x3e0
May  3 12:46:59 fw01 kernel: [  271.875431]  ? kthread_park+0x90/0x90
May  3 12:46:59 fw01 kernel: [  271.875432]  ret_from_fork+0x29/0x40
May  3 12:46:59 fw01 kernel: [  271.875434] ---[ end trace 3da51f3ef83370a7 ]---
May  3 12:47:03 fw01 kernel: [  275.629072] igb 0000:01:00.0 eth0:
igb: eth0 NIC Link is Down
May  3 12:47:03 fw01 kernel: [  275.629135] igb 0000:01:00.1 eth1: Reset adapter
May  3 12:47:03 fw01 kernel: [  275.629316] igb 0000:01:00.0 eth0: Reset adapter
May  3 12:47:12 fw01 kernel: [  285.159798] igb 0000:01:00.1 eth1:
igb: eth1 NIC Link is Up 1000 Mbps Half Duplex, Flow Control: RX/TX
May  3 12:47:12 fw01 kernel: [  285.159801] igb 0000:01:00.1: EEE
Disabled: unsupported at half duplex. Re-enable using ethtool when at
full duplex.
May  3 12:47:15 fw01 kernel: [  287.842412] igb 0000:01:00.1: exceed
max 2 second
May  3 12:48:21 fw01 kernel: [  353.875946] igb 0000:01:00.0 eth0: Reset adapter

-- 
Bj(/)rnar

Re: crash on >= 4.9.0 kernel seems nf related

[Bjørnar Ness]

Is this an issue  for igb, or netfilter?

-- 
Bj(/)rnar

Re: crash on >= 4.9.0 kernel seems nf related

[Florian Westphal]

Bjørnar Ness <bjornar.ness@gmail.com> wrote:
> Is this an issue  for igb, or netfilter?

I'd lean towards igb, afaics the occurence of the gc worker
is coincidence.

Or does it show up in all such traces?

Re: crash on >= 4.9.0 kernel seems nf related

[Bjørnar Ness]

I have seen this trace couple times before, and also the fact
that 4.9 had been running fine since the release makes me suspect that igb
is not to blame. What can I do to provide additional details here?

Re: crash on >= 4.9.0 kernel seems nf related

[Bjørnar Ness]

2017-05-18 9:41 GMT+02:00 Bjørnar Ness <bjornar.ness@gmail.com>:
> I have seen this trace couple times before, and also the fact
> that 4.9 had been running fine since the release makes me suspect that igb
> is not to blame. What can I do to provide additional details here?

We have done some adittinal debugging on this issue, where we also tried with a
broadcom gigabit ethernet card, with similar results (not the kernel
crash, but machine
comes to a complete stall due to load/io wait)

When trying to narrow down the problem, I removed the NAT rules, and
in particular
the

chain postrouting {
  type nat hook postrouting priority 100
}

And the problem disappears. Commenting in the above block again,
causes the following to happen:

kworker/0:0 starts to use more and more cpu, and in less than a minute
renders the
machine useless. If network cable is unplugged, it takes aroung 30
seconds for the machine to get into a useful state again.

We are seeing around 40-60kpps on the link. This bug is introduced
somewhere between
4.8.6 and 4.9

--
Bj(/)rnar

Re: crash on >= 4.9.0 kernel seems nf related

[Florian Westphal]

Bjørnar Ness <bjornar.ness@gmail.com> wrote:
> When trying to narrow down the problem, I removed the NAT rules, and
> in particular
> the
>
> chain postrouting {
>   type nat hook postrouting priority 100
> }
>
> And the problem disappears. Commenting in the above block again,
> causes the following to happen:
>
> kworker/0:0 starts to use more and more cpu, and in less than a minute
> renders the
> machine useless. If network cable is unplugged, it takes aroung 30
> seconds for the machine to get into a useful state again.

The kworker is most likely the conntrack gc worker, but the gc worker is nat
agnostic, so I don't see how this makes a difference wrt. nat
postrouting hook presence.

perf top might help pinpoint the source.

What kernel is this, exactly?

4.10 (and 4.9.14 and later) has a change to make gc worker use less
cycles.

But I don't see the NAT connection.

Re: crash on >= 4.9.0 kernel seems nf related

[Bjørnar Ness]

2017-06-26 15:16 GMT+02:00 Florian Westphal <fw@strlen.de>:
> Bjørnar Ness <bjornar.ness@gmail.com> wrote:
>> When trying to narrow down the problem, I removed the NAT rules, and
>> in particular
>> the
>>
>> chain postrouting {
>>   type nat hook postrouting priority 100
>> }
>>
>> And the problem disappears. Commenting in the above block again,
>> causes the following to happen:
>>
>> kworker/0:0 starts to use more and more cpu, and in less than a minute
>> renders the
>> machine useless. If network cable is unplugged, it takes aroung 30
>> seconds for the machine to get into a useful state again.
>
> The kworker is most likely the conntrack gc worker, but the gc worker is nat
> agnostic, so I don't see how this makes a difference wrt. nat
> postrouting hook presence.

It might ofcorse be just the straw that brpke the camel's back, but
this behavior
is reproducible, and is present in 4.9.0-rc6, 4.11.0 and 4.12.0-rc6.
We do not have
problems with 4.8.6 (but as mentioned, it has other conntrack problems reported
earlier)

> perf top might help pinpoint the source.
>
> What kernel is this, exactly?
>
> 4.10 (and 4.9.14 and later) has a change to make gc worker use less
> cycles.

We see the behavior in 4.11.0 and 4.12.0-rc6 as well

> But I don't see the NAT connection.

Not sure what you mean here. We do not eed to have rules in the
postrouting chain for it
to tear down the server. Monitoring conntrack entries also shows me
this is stable around 120k

-- 
Bj(/)rnar

Re: crash on >= 4.9.0 kernel seems nf related

[Florian Westphal]

Bjørnar Ness <bjornar.ness@gmail.com> wrote:
> 2017-06-26 15:16 GMT+02:00 Florian Westphal <fw@strlen.de>:
> > perf top might help pinpoint the source.

Leaving this here, this info would help.

> > What kernel is this, exactly?
> >
> > 4.10 (and 4.9.14 and later) has a change to make gc worker use less
> > cycles.
> 
> We see the behavior in 4.11.0 and 4.12.0-rc6 as well
> 
> > But I don't see the NAT connection.
> 
> Not sure what you mean here. We do not eed to have rules in the
> postrouting chain for it
> to tear down the server.

I mean that presence of NAT postrouting hook has, to the best of my
knowledge, no effect on the ct gc worker.

But perhaps this isn't the gc worker after all, perf top would help.

The only effect that the postrouting hook has is bringing rhashtables
'rhlist' interface into the mix, as we use that for the nat bysource
table.

> Monitoring conntrack entries also shows me
> this is stable around 120k

What does that mean?
Do you mean you run into problems after 120k entries?

Re: crash on >= 4.9.0 kernel seems nf related

[Bjørnar Ness]

2017-06-28 12:23 GMT+02:00 Florian Westphal <fw@strlen.de>:
> Bjørnar Ness <bjornar.ness@gmail.com> wrote:
>> 2017-06-26 15:16 GMT+02:00 Florian Westphal <fw@strlen.de>:
>> > perf top might help pinpoint the source.
>
> Leaving this here, this info would help.
>
>> > What kernel is this, exactly?
>> >
>> > 4.10 (and 4.9.14 and later) has a change to make gc worker use less
>> > cycles.
>>
>> We see the behavior in 4.11.0 and 4.12.0-rc6 as well
>>
>> > But I don't see the NAT connection.
>>
>> Not sure what you mean here. We do not eed to have rules in the
>> postrouting chain for it to tear down the server.
>
> I mean that presence of NAT postrouting hook has, to the best of my
> knowledge, no effect on the ct gc worker.
>
> But perhaps this isn't the gc worker after all, perf top would help.

I will give it a go next week, but as this is in production, its not ideal to
use for testing..

> The only effect that the postrouting hook has is bringing rhashtables
> 'rhlist' interface into the mix, as we use that for the nat bysource
> table.
>
>> Monitoring conntrack entries also shows me
>> this is stable around 120k
>
> What does that mean?
> Do you mean you run into problems after 120k entries?

No, I mean when I watch conntrack entries, I do not see a sudden increase/climb,
it was more or less stable at ~120k entries.

-- 
Bj(/)rnar