R80.40 T102 flooding log with dst_release messages

[HristoGrigorov]

I upgraded to R80.40 T102 and now /var/log/messages is flooded with following messages:

Apr 25 06:43:37 2021 fw-ext kernel: dst_release: dst:ffff8801dde8ad80 refcnt:-266138
Apr 25 06:43:43 2021 fw-ext kernel: net_ratelimit: 296 callbacks suppressed
Apr 25 06:43:43 2021 fw-ext kernel: dst_release: dst:ffff8801e43635c0 refcnt:-428436
Apr 25 06:43:43 2021 fw-ext kernel: dst_release: dst:ffff8801e43635c0 refcnt:-428437
Apr 25 06:43:43 2021 fw-ext kernel: dst_release: dst:ffff8801e43635c0 refcnt:-428437
Apr 25 06:43:43 2021 fw-ext kernel: dst_release: dst:ffff8801dde8ad80 refcnt:-266220
Apr 25 06:43:43 2021 fw-ext kernel: dst_release: dst:ffff8801e43635c0 refcnt:-428437
Apr 25 06:43:43 2021 fw-ext kernel: dst_release: dst:ffff8801dde8ad80 refcnt:-266220
Apr 25 06:43:43 2021 fw-ext kernel: dst_release: dst:ffff8801e43635c0 refcnt:-428438
Apr 25 06:43:43 2021 fw-ext kernel: dst_release: dst:ffff8801dde8ad80 refcnt:-266221
Apr 25 06:43:43 2021 fw-ext kernel: dst_release: dst:ffff8801e43635c0 refcnt:-428439
Apr 25 06:43:43 2021 fw-ext kernel: dst_release: dst:ffff8801dde8ad80 refcnt:-266222
Apr 25 06:43:48 2021 fw-ext kernel: net_ratelimit: 170 callbacks suppressed
Apr 25 06:43:48 2021 fw-ext kernel: dst_release: dst:ffff8801dde8ad80 refcnt:-266263
Apr 25 06:43:48 2021 fw-ext kernel: dst_release: dst:ffff8801dde8ad80 refcnt:-266264
Apr 25 06:43:48 2021 fw-ext kernel: dst_release: dst:ffff8801e43635c0 refcnt:-428480
Apr 25 06:43:48 2021 fw-ext kernel: dst_release: dst:ffff8801e43635c0 refcnt:-428480
Apr 25 06:43:48 2021 fw-ext kernel: dst_release: dst:ffff8801e43635c0 refcnt:-428481
Apr 25 06:43:48 2021 fw-ext kernel: dst_release: dst:ffff8801e43635c0 refcnt:-428482
Apr 25 06:43:48 2021 fw-ext kernel: dst_release: dst:ffff8801e43635c0 refcnt:-428482
Apr 25 06:43:48 2021 fw-ext kernel: dst_release: dst:ffff8801e43635c0 refcnt:-428483

Any idea what is causing this ? Firewall seems to work fine so far.

[HristoGrigorov]

I found sk166363 that kind of explains it but first this was not happening with previous GA take and second messages are logged way to often.

[jgarcias]

Same problem here after upgrading to Take 102. I've just open a case with TAC and waiting for answer...

[LFnet]

Same problem here. Our gateway also stopped forwarding traffic after a while with a stack trace:

May 3 19:45:02 2021 fw1 kernel: dst_release: dst:ffff880463e2b1c0 refcnt:-9117
May 3 19:45:03 2021 fw1 kernel: dst_release: dst:ffff8803d9171680 refcnt:-7636
May 3 19:45:04 2021 fw1 last message repeated 4 times
May 3 19:45:31 2021 fw1 kernel: NMI watchdog: BUG: soft lockup - CPU#1 stuck for 23s! [fw_worker_0:7880]
May 3 19:45:31 2021 fw1 kernel: Modules linked in: vrrp_lkmmod(POE) cppcap(OE) adpmod(OE) 8021q mrp garp wrp(OE) bfd_lkm
mod(POE) fw_1(POE) fw_0(POE) simmod_0(POE) bridge ipv6 stp llc ipsctlmod(OE) netloop ext3 jbd dm_multipath parport_pc lp
parport sg sr_mod cdrom iTCO_wdt iTCO_vendor_support wmi tg3 ptp pps_core mgag200 ttm hpilo drm_kms_helper drm drm_panel_
orientation_quirks i2c_algo_bit acpi_power_meter hwmon ipmi_si ipmi_msghandler pcspkr psmouse serio_raw button i2c_i801 i
oatdma lpc_ich mfd_core dca dm_snapshot dm_bufio dm_zero dm_mirror dm_region_hash dm_log dm_mod ahci libahci libata cciss
hpsa scsi_transport_sas sd_mod crc_t10dif crct10dif_common xfs
May 3 19:45:31 2021 fw1 kernel: CPU: 1 PID: 7880 Comm: fw_worker_0 Kdump: loaded Tainted: P OE ------------
3.10.0-957.21.3cpx86_64 #1
May 3 19:45:31 2021 fw1 kernel: Hardware name: HP ProLiant DL360 Gen9/ProLiant DL360 Gen9, BIOS P89 02/17/2017
May 3 19:45:31 2021 fw1 kernel: task: ffff88046960b500 ti: ffff8803fcb64000 task.ti: ffff8803fcb64000
May 3 19:45:31 2021 fw1 kernel: RIP: 0010:[<ffffffff92a04c10>] [<ffffffff92a04c10>] fwmultik_do_seq_on_packet+0x1b0/0x5
40 [fw_0]
May 3 19:45:31 2021 fw1 kernel: RSP: 0018:ffff8803fcb672a8 EFLAGS: 00000282
May 3 19:45:31 2021 fw1 kernel: RAX: 0000000000d8676d RBX: ffff880300000002 RCX: 0000000000000000
May 3 19:45:31 2021 fw1 kernel: RDX: 0000000000000003 RSI: ffffc90079222128 RDI: ffffc90079222128
May 3 19:45:31 2021 fw1 kernel: RBP: ffffc90009f16670 R08: ffffc90009eaf440 R09: 0000000000000000
May 3 19:45:31 2021 fw1 kernel: R10: ffffc90009f400b0 R11: 0000000000000001 R12: ffff8803fcb67780
May 3 19:45:31 2021 fw1 kernel: R13: ffffc90000000000 R14: ffff880300000001 R15: ffff880300000010
May 3 19:45:31 2021 fw1 kernel: FS: 0000000000000000(0000) GS:ffff88047fc40000(0000) knlGS:0000000000000000
May 3 19:45:31 2021 fw1 kernel: CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
May 3 19:45:31 2021 fw1 kernel: CR2: 00000000565a0a70 CR3: 00000003fc156000 CR4: 00000000003607e0
May 3 19:45:31 2021 fw1 kernel: DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
May 3 19:45:31 2021 fw1 kernel: DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
May 3 19:45:31 2021 fw1 kernel: Call Trace:
May 3 19:45:31 2021 fw1 kernel: [<ffffffff92a22bff>] ? fwmultik_enqueue_data_kernel+0x1af/0x8a0 [fw_0]
May 3 19:45:31 2021 fw1 kernel: [<ffffffff92a1dc6a>] ? fwmultik_process_all_queued+0x8a/0x130 [fw_0]
May 3 19:45:31 2021 fw1 kernel: [<ffffffff92a25184>] ? fwmultik_enqueue_packet_kernel+0x114/0x1a0 [fw_0]
May 3 19:45:31 2021 fw1 kernel: [<ffffffff817942de>] ? _raw_spin_unlock_bh+0x1e/0x20
May 3 19:45:31 2021 fw1 kernel: [<ffffffff92a20cc8>] ? fwmultik_select_gconn_instance+0xc8/0x9c0 [fw_0]
May 3 19:45:31 2021 fw1 kernel: [<ffffffff816cb970>] ? ip_fragment.constprop.61+0xa0/0xa0
May 3 19:45:31 2021 fw1 kernel: [<ffffffff92a26c4c>] ? fwmultik_dispatch_outbound+0x74c/0xe30 [fw_0]
May 3 19:45:31 2021 fw1 kernel: [<ffffffff9193e4dd>] ? fwlinux_nfipout+0x33d/0x780 [fw_0]
May 3 19:45:31 2021 fw1 kernel: [<ffffffff92818340>] ? fw_os_route_get_ipout_route_ex+0x190/0x310 [fw_0]
May 3 19:45:31 2021 fw1 kernel: [<ffffffff816cb970>] ? ip_fragment.constprop.61+0xa0/0xa0
May 3 19:45:31 2021 fw1 kernel: [<ffffffff816be137>] ? nf_iterate+0x67/0xa0
May 3 19:45:31 2021 fw1 kernel: [<ffffffff816be21a>] ? nf_hook_slow+0xaa/0x110
:

[HristoGrigorov]

Ours is holding up so far and I can't notice any particular problems or issues other than that nagging message which is shortening SSD life on the appliance. 

[rdevarak]

Hi, We found the root cause of the problem. HFs are on the way to fix the problem. There is a sk published related to this problem.

sk173327 - "dst_release: dst:ffff88052d4c68c0 refcnt:-480" messages in dmesg

[genisis__]

Will this be included in the next "stable" and fully QAed Jumbo release?

b.t.w the SK is not visible. 

[rdevarak]

Currently sk is meant for internal people. It will be published after internal evaluation.

Yes, it will be part of future 'stable QAed Jumbo Release'.

[HristoGrigorov]

@rdevarak Thanx for the update. Certainly nice to know you found where problem is. I would appreciate if you provide a little bit of tech detail if you have the time. 

[HristoGrigorov]

Temp fix to reduce logging of these messages (once every 2 mins):

# echo 120 > /proc/sys/net/core/message_cost

[Tobias_Moritz]

@rdevarak : I see multiple new bugs resolved in T114 regardings new weird /var/log/messages entries from kernel. Then you talked about sk173327 (currently internal) and that you found the root cause.

We have multiple entries of this kind since upgrading to T102:

May 5 16:52:18 2021 kernel: [fw4_2];fw_os_route_get_out_ifn_ex: bad parameters (chain ffffc900c4486db0, conn ffff8808391a3628, out_ifns ffff8808391a3640, out_n_ifns ffff8808391a3610, cdir 0, cal
ler: dynamic_vpn_ip)
May 5 16:52:18 2021 kernel: [fw4_0];fw_os_route_get_out_ifn_ex: bad parameters (chain ffffc900c4f2a8a0, conn ffff8807983a3628, out_ifns ffff8807983a3640, out_n_ifns ffff8807983a3610, cdir 0, cal
ler: dynamic_vpn_ip)
May 5 16:52:18 2021 kernel: [fw4_1];fw_os_route_get_out_ifn_ex: bad parameters (chain ffffc900c49851e0, conn ffff880797cb7628, out_ifns ffff880797cb7640, out_n_ifns ffff880797cb7610, cdir 0, cal
ler: dynamic_vpn_ip)
May 5 16:52:19 2021 last message repeated 5 times

Is this also a known issue and related to the same root cause?

Or is this a second topic we need to address seperately?

[rdevarak]

It is a known issue and not related to this issue.  It has been addressed independent of this current issue.

[Tobias_Moritz]

Thank you for the quick response. Last question: Is it cosmetical only or should we worry (and rollback until fix is available)?

[rdevarak]

May 5 16:52:18 2021 kernel: [fw4_0];fw_os_route_get_out_ifn_ex: bad parameters (chain ffffc900c4f2a8a0, conn ffff8807983a3628, out_ifns ffff8807983a3640, out_n_ifns ffff8807983a3610, cdir 0, cal
ler: dynamic_vpn_ip)

It is a functional issue and looks like it has been resolved in R80.40 JHF T114. 

[_Val_]

You can either get a private fix from TAC, or wait for the next JHF to be released.

[Faycal_De_Polto]

Hi,

We experience very big issue on our network, (high latency and packet lost). After a call with the support, It seems that the issue was linked to this message. the support provide me with a special fixe that solve the issue and make disappear the message. 

Regards,

Fayçal

[genisis__]

JHFA 118 just released.

[Kilian_Huber]

Are you using SSL Inspection/Proxy and is TE or TEX activated or is Anti-Virus deep scan enabled in your setup?