Bug 204879 - "invalid inflight", WARNING: CPU: 1 PID: 5103 at net/ipv4/tcp_output.c:2509 tcp_send_loss_probe.cold.42+0x20/0x2d
Summary: "invalid inflight", WARNING: CPU: 1 PID: 5103 at net/ipv4/tcp_output.c:2509 t...
Status: RESOLVED CODE_FIX
Alias: None
Product: Networking
Classification: Unclassified
Component: IPV4 (show other bugs)
Hardware: All Linux
: P1 normal
Assignee: Stephen Hemminger
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2019-09-16 20:28 UTC by Roman Mamedov
Modified: 2019-10-31 05:00 UTC (History)
2 users (show)

See Also:
Kernel Version: 4.14.143
Subsystem:
Regression: No
Bisected commit-id:


Attachments

Description Roman Mamedov 2019-09-16 20:28:15 UTC
After upgrading my kernel version from 4.14.121 to 4.14.143, on every boot I now get the following warning.

Moreover, eventually (in a few hours) the server appears to lock-up. However I can't say for sure if the lock-up is related, or what messages appear during that time, as this is a remote system with no IPMI or the like. There's nothing in disk-based logs. I'll try netconsole later if this continues to repeat.

For now, any ideas about this particular backtrace? Thanks

[   35.587989] invalid inflight: 1 state 1 cwnd 14 mss 1428
[   35.588004] ------------[ cut here ]------------
[   35.588009] WARNING: CPU: 1 PID: 5103 at net/ipv4/tcp_output.c:2509 tcp_send_loss_probe.cold.42+0x20/0x2d
[   35.588011] Modules linked in: wireguard ip6_udp_tunnel udp_tunnel xt_comment xt_u32 xt_connlimit ip6t_MASQUERADE nf_nat_masquerade_ipv6 xt_TCPMSS xt_nat xt_mark ipt_MASQUERADE nf_nat_masquerade_ipv4 xt_tcpudp xt_set ip_set_hash_net ip_set nfnetlink xt_multiport xt_limit xt_length xt_conntrack ip6t_rpfilter ipt_rpfilter ip6table_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6 ip6table_raw ip6table_mangle iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack iptable_raw iptable_mangle ip6table_filter ip6_tables iptable_filter ip_tables x_tables cpufreq_conservative cpufreq_powersave cpufreq_userspace tcp_bbr sch_fq tcp_illinois intel_rapl x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm irqbypass crct10dif_pclmul crc32_pclmul ghash_clmulni_intel pcbc aesni_intel
[   35.588042]  aes_x86_64 crypto_simd glue_helper cryptd snd_hda_codec_hdmi intel_cstate snd_hda_codec_realtek snd_hda_codec_generic intel_uncore snd_hda_intel i915 video iTCO_wdt intel_rapl_perf iTCO_vendor_support snd_hda_codec drm_kms_helper evdev snd_hda_core pcspkr snd_hwdep snd_pcm snd_timer pcc_cpufreq mei_me mei drm sg snd shpchp lpc_ich button i2c_algo_bit serio_raw mfd_core soundcore ext4 crc16 mbcache jbd2 fscrypto btrfs zstd_decompress zstd_compress xxhash sata_nv dm_crypt raid456 async_raid6_recov async_memcpy async_pq async_xor async_tx xor raid6_pq libcrc32c crc32c_generic raid0 raid1 md_mod dm_mirror dm_region_hash dm_log dm_mod ata_piix sd_mod xhci_pci xhci_hcd crc32c_intel ahci libahci i2c_i801 ehci_pci libata psmouse ehci_hcd scsi_mod e1000e ptp usbcore pps_core
[   35.588086] CPU: 1 PID: 5103 Comm: xmrig Not tainted 4.14.144-rm1+ #64
[   35.588088] Hardware name:  /DH67BL, BIOS BLH6710H.86A.0160.2012.1204.1156 12/04/2012
[   35.588090] task: ffff8e0c0578bb80 task.stack: ffffa6a349524000
[   35.588093] RIP: 0010:tcp_send_loss_probe.cold.42+0x20/0x2d
[   35.588095] RSP: 0000:ffff8e0c1f283e70 EFLAGS: 00010246
[   35.588097] RAX: 000000000000002c RBX: ffff8e0c0b932a80 RCX: 0000000000000000
[   35.588099] RDX: 0000000000000000 RSI: ffff8e0c1f296738 RDI: ffff8e0c1f296738
[   35.588101] RBP: ffff8e0c0b932bd8 R08: 0000000000000000 R09: 0000000000000275
[   35.588103] R10: ffff8e0c0e911280 R11: 0000000000000000 R12: ffff8e0c0b932bd8
[   35.588105] R13: ffffffff827d46b0 R14: ffff8e0c0b932a80 R15: ffff8e0c1f283ef0
[   35.588107] FS:  00007f71de376700(0000) GS:ffff8e0c1f280000(0000) knlGS:0000000000000000
[   35.588110] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   35.588112] CR2: 000055f0f061c000 CR3: 0000000409d0e001 CR4: 00000000000606e0
[   35.588114] Call Trace:
[   35.588116]  <IRQ>
[   35.588120]  tcp_write_timer_handler+0xce/0x210
[   35.588123]  tcp_write_timer+0x77/0x90
[   35.588126]  call_timer_fn+0x30/0x130
[   35.588129]  run_timer_softirq+0x3d3/0x410
[   35.588133]  ? timerqueue_add+0x52/0x80
[   35.588136]  ? enqueue_hrtimer+0x36/0x80
[   35.588140]  __do_softirq+0xdb/0x2d5
[   35.588142]  ? hrtimer_interrupt+0x113/0x1d0
[   35.588147]  irq_exit+0xbc/0xd0
[   35.588150]  smp_apic_timer_interrupt+0x78/0x140
[   35.588152]  apic_timer_interrupt+0x85/0x90
[   35.588154]  </IRQ>
[   35.588156] RIP: 0033:0x7f71ddb3b16f
[   35.588158] RSP: 002b:81244f1f4aebe662 EFLAGS: 00000206 ORIG_RAX: ffffffffffffff10
[   35.588161] RAX: 000000005590220e RBX: 000000004520e100 RCX: 00007f71dd513600
[   35.588163] RDX: 000000005476b198 RSI: 8219664b28bc2fe0 RDI: 00000000555b6ee0
[   35.588165] RBP: 0000000092e54880 R08: 000000000007be43 R09: 00000000ce690f4f
[   35.588166] R10: 00000000001f6970 R11: 00007f71dd400000 R12: 80ee3d8c155f6970
[   35.588168] R13: 4b3017ab1f4489c9 R14: 3854bb60406a6bea R15: eb98349c9e84f39a
[   35.588171] Code: 00 c6 83 7b 04 00 00 00 5b 5d c3 0f b6 53 12 8b 8b 2c 06 00 00 41 89 c0 48 c7 c7 90 e3 06 83 c6 05 39 64 b1 00 01 e8 cd a3 b0 ff <0f> 0b e9 1f ee ff ff 90 90 90 90 90 90 66 66 66 66 90 48 8b 47 
[   35.588193] ---[ end trace 7c7f3665018c9e60 ]---
Comment 1 Rui Salvaterra 2019-09-20 18:26:58 UTC
Also happening on 4.14.144. Backtrace from OpenWrt (no symbols. though).

Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.168863] invalid inflight: 1 state 1 cwnd 10 mss 1448
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.174283] ------------[ cut here ]------------
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.178925] WARNING: CPU: 1 PID: 0 at 0xffffffff8166702d
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.184256] Modules linked in: nf_nat_pptp nf_conntrack_pptp nf_conntrack_ipv6 lzo lz4 iptable_nat ipt_REJECT ipt_MASQUERADE xt_time xt_tcpudp xt_tcpmss xt_statistic xt_state xt_recent xt_nat xt_multiport xt_mark xt_mac xt_limit xt_length xt_hl xt_helper xt_ecn xt_dscp xt_conntrack xt_connmark xt_connlimit xt_connbytes xt_comment xt_TCPMSS xt_REDIRECT xt_LOG xt_HL xt_FLOWOFFLOAD xt_DSCP xt_CT xt_CLASSIFY wireguard ts_fsm ts_bm nf_reject_ipv4 nf_nat_tftp nf_nat_snmp_basic nf_nat_sip nf_nat_redirect nf_nat_proto_gre nf_nat_masquerade_ipv4 nf_nat_irc nf_conntrack_ipv4 nf_nat_ipv4 nf_nat_h323 nf_nat_ftp nf_nat_amanda nf_nat nf_log_ipv4 nf_flow_table_hw nf_flow_table nf_defrag_ipv6 nf_defrag_ipv4 nf_conntrack_tftp nf_conntrack_snmp nf_conntrack_sip nf_conntrack_rtcache nf_conntrack_proto_gre nf_conntrack_netlink
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.255920]  nf_conntrack_irc nf_conntrack_h323 nf_conntrack_ftp nf_conntrack_broadcast ts_kmp nf_conntrack_amanda lzo_decompress lzo_compress lz4_decompress lz4_compress iptable_raw iptable_mangle iptable_filter ipt_ECN ip6table_raw ip_tables sch_cake nf_conntrack sch_tbf sch_ingress sch_htb sch_hfsc em_u32 cls_u32 cls_tcindex cls_route cls_matchall cls_fw cls_flow cls_basic act_skbedit act_mirred i2c_dev ledtrig_heartbeat xt_set ip_set_list_set ip_set_hash_netportnet ip_set_hash_netport ip_set_hash_netnet ip_set_hash_netiface ip_set_hash_net ip_set_hash_mac ip_set_hash_ipportnet ip_set_hash_ipportip ip_set_hash_ipport ip_set_hash_ipmark ip_set_hash_ip ip_set_bitmap_port ip_set_bitmap_ipmac ip_set_bitmap_ip ip_set nfnetlink nf_log_ipv6 nf_log_common ip6table_mangle ip6table_filter ip6_tables ip6t_REJECT
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.327283]  x_tables nf_reject_ipv6 igb ifb ip6_udp_tunnel udp_tunnel zram zsmalloc sha256_ssse3 sha1_ssse3 ccp_crypto rsa_generic mpi asn1_decoder akcipher ccp sha256_generic sha1_generic authenc crypto_acompress sdhci_pltfm leds_apu2 ptp pps_core
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.349437] CPU: 1 PID: 0 Comm: swapper/1 Not tainted 4.14.144 #0
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.355555] Hardware name: PC Engines APU2/APU2, BIOS 4.0.7 02/28/2017
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.362092] task: ffff88811a08f300 task.stack: ffffc90000060000
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.368029] RIP: 0010:0xffffffff8166702d
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.371970] RSP: 0018:ffff88811ec83e70 EFLAGS: 00010282
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.377213] RAX: 000000000000002c RBX: ffff8881170a9f00 RCX: 0000000000000000
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.384358] RDX: ffff88811ec9ba60 RSI: ffff88811ec96358 RDI: ffff88811ec96358
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.391532] RBP: ffff88811ec83e88 R08: 0000000000000000 R09: 00000000000001fd
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.398690] R10: ffff88811ec83e68 R11: 0000000000000000 R12: ffff8881170aa050
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.405866] R13: ffff8881170aa050 R14: ffff88811ec83ef0 R15: ffff88811ec9a4a8
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.413029] FS:  0000000000000000(0000) GS:ffff88811ec80000(0000) knlGS:0000000000000000
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.421132] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.426892] CR2: 00000000007a3060 CR3: 00000001162ce000 CR4: 00000000000406e0
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.434042] Call Trace:
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.436513]  <IRQ>
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.438549]  0xffffffff81668cf5
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.441712]  0xffffffff81668e9b
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.444872]  ? 0xffffffff81668e70
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.448200]  0xffffffff810ca69f
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.451364]  0xffffffff810ca834
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.454520]  ? 0xffffffff81040d3e
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.457846]  ? 0xffffffff810d5d60
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.461176]  0xffffffff81a000ba
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.464330]  0xffffffff81087e52
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.467485]  0xffffffff818024d7
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.470640]  0xffffffff81801aec
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.473794]  </IRQ>
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.475907] RIP: 0010:0xffffffff815b3a86
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.479842] RSP: 0018:ffffc90000063e98 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff10
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.487432] RAX: ffff88811ec9f340 RBX: 0000000000000002 RCX: 000000000000001f
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.494587] RDX: 0000000d13ec8012 RSI: 00000000803d7d59 RDI: 0000000000000000
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.501737] RBP: ffffc90000063ec8 R08: 0000000000000004 R09: 000000000001eb80
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.508888] R10: ffffc90000063e68 R11: 0000000000000000 R12: ffff888119a7da00
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.516047] R13: 0000000d13ec8012 R14: ffffffff81e459b8 R15: 0000000000000000
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.523202]  ? 0xffffffff815b3a5e
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.526531]  0xffffffff815b3b32
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.529685]  0xffffffff810b1443
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.532838]  0xffffffff810b15e0
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.535995]  0xffffffff810b17bf
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.539149]  0xffffffff8103f8f0
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.542313]  0xffffffff810000d5
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.545468] Code: 74 2b 80 3d e6 c1 81 00 00 75 22 0f b6 53 12 8b 8b 14 06 00 00 41 89 c0 48 c7 c7 b0 03 d4 81 c6 05 c9 c1 81 00 01 e8 ef 30 a5 ff <0f> 0b c6 83 62 04 00 00 00 e9 ce 00 00 00 8b 93 98 05 00 00 85
Fri Sep 20 19:23:29 2019 kern.warn kernel: [   56.564513] ---[ end trace a7d4411530d0c7d2 ]---
Comment 2 Rui Salvaterra 2019-09-20 18:30:00 UTC
Sorry, my previous trace was from the log dump. Here's directy from dmesg:

[   56.168863] invalid inflight: 1 state 1 cwnd 10 mss 1448
[   56.174283] ------------[ cut here ]------------
[   56.178925] WARNING: CPU: 1 PID: 0 at 0xffffffff8166702d
[   56.184256] Modules linked in: nf_nat_pptp nf_conntrack_pptp nf_conntrack_ipv6 lzo lz4 iptable_nat ipt_REJECT ipt_MASQUERADE xt_time xt_tcpudp xt_tcpmss xt_statistic xt_state xt_recent xt_nat xt_multiport xt_mark xt_mac xt_limit xt_length xt_hl xt_helper xt_ecn xt_dscp xt_conntrack xt_connmark xt_connlimit xt_connbytes xt_comment xt_TCPMSS xt_REDIRECT xt_LOG xt_HL xt_FLOWOFFLOAD xt_DSCP xt_CT xt_CLASSIFY wireguard ts_fsm ts_bm nf_reject_ipv4 nf_nat_tftp nf_nat_snmp_basic nf_nat_sip nf_nat_redirect nf_nat_proto_gre nf_nat_masquerade_ipv4 nf_nat_irc nf_conntrack_ipv4 nf_nat_ipv4 nf_nat_h323 nf_nat_ftp nf_nat_amanda nf_nat nf_log_ipv4 nf_flow_table_hw nf_flow_table nf_defrag_ipv6 nf_defrag_ipv4 nf_conntrack_tftp nf_conntrack_snmp nf_conntrack_sip nf_conntrack_rtcache nf_conntrack_proto_gre nf_conntrack_netlink
[   56.255920]  nf_conntrack_irc nf_conntrack_h323 nf_conntrack_ftp nf_conntrack_broadcast ts_kmp nf_conntrack_amanda lzo_decompress lzo_compress lz4_decompress lz4_compress iptable_raw iptable_mangle iptable_filter ipt_ECN ip6table_raw ip_tables sch_cake nf_conntrack sch_tbf sch_ingress sch_htb sch_hfsc em_u32 cls_u32 cls_tcindex cls_route cls_matchall cls_fw cls_flow cls_basic act_skbedit act_mirred i2c_dev ledtrig_heartbeat xt_set ip_set_list_set ip_set_hash_netportnet ip_set_hash_netport ip_set_hash_netnet ip_set_hash_netiface ip_set_hash_net ip_set_hash_mac ip_set_hash_ipportnet ip_set_hash_ipportip ip_set_hash_ipport ip_set_hash_ipmark ip_set_hash_ip ip_set_bitmap_port ip_set_bitmap_ipmac ip_set_bitmap_ip ip_set nfnetlink nf_log_ipv6 nf_log_common ip6table_mangle ip6table_filter ip6_tables ip6t_REJECT
[   56.327283]  x_tables nf_reject_ipv6 igb ifb ip6_udp_tunnel udp_tunnel zram zsmalloc sha256_ssse3 sha1_ssse3 ccp_crypto rsa_generic mpi asn1_decoder akcipher ccp sha256_generic sha1_generic authenc crypto_acompress sdhci_pltfm leds_apu2 ptp pps_core
[   56.349437] CPU: 1 PID: 0 Comm: swapper/1 Not tainted 4.14.144 #0
[   56.355555] Hardware name: PC Engines APU2/APU2, BIOS 4.0.7 02/28/2017
[   56.362092] task: ffff88811a08f300 task.stack: ffffc90000060000
[   56.368029] RIP: 0010:0xffffffff8166702d
[   56.371970] RSP: 0018:ffff88811ec83e70 EFLAGS: 00010282
[   56.377213] RAX: 000000000000002c RBX: ffff8881170a9f00 RCX: 0000000000000000
[   56.384358] RDX: ffff88811ec9ba60 RSI: ffff88811ec96358 RDI: ffff88811ec96358
[   56.391532] RBP: ffff88811ec83e88 R08: 0000000000000000 R09: 00000000000001fd
[   56.398690] R10: ffff88811ec83e68 R11: 0000000000000000 R12: ffff8881170aa050
[   56.405866] R13: ffff8881170aa050 R14: ffff88811ec83ef0 R15: ffff88811ec9a4a8
[   56.413029] FS:  0000000000000000(0000) GS:ffff88811ec80000(0000) knlGS:0000000000000000
[   56.421132] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   56.426892] CR2: 00000000007a3060 CR3: 00000001162ce000 CR4: 00000000000406e0
[   56.434042] Call Trace:
[   56.436513]  <IRQ>
[   56.438549]  0xffffffff81668cf5
[   56.441712]  0xffffffff81668e9b
[   56.444872]  ? 0xffffffff81668e70
[   56.448200]  0xffffffff810ca69f
[   56.451364]  0xffffffff810ca834
[   56.454520]  ? 0xffffffff81040d3e
[   56.457846]  ? 0xffffffff810d5d60
[   56.461176]  0xffffffff81a000ba
[   56.464330]  0xffffffff81087e52
[   56.467485]  0xffffffff818024d7
[   56.470640]  0xffffffff81801aec
[   56.473794]  </IRQ>
[   56.475907] RIP: 0010:0xffffffff815b3a86
[   56.479842] RSP: 0018:ffffc90000063e98 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff10
[   56.487432] RAX: ffff88811ec9f340 RBX: 0000000000000002 RCX: 000000000000001f
[   56.494587] RDX: 0000000d13ec8012 RSI: 00000000803d7d59 RDI: 0000000000000000
[   56.501737] RBP: ffffc90000063ec8 R08: 0000000000000004 R09: 000000000001eb80
[   56.508888] R10: ffffc90000063e68 R11: 0000000000000000 R12: ffff888119a7da00
[   56.516047] R13: 0000000d13ec8012 R14: ffffffff81e459b8 R15: 0000000000000000
[   56.523202]  ? 0xffffffff815b3a5e
[   56.526531]  0xffffffff815b3b32
[   56.529685]  0xffffffff810b1443
[   56.532838]  0xffffffff810b15e0
[   56.535995]  0xffffffff810b17bf
[   56.539149]  0xffffffff8103f8f0
[   56.542313]  0xffffffff810000d5
[   56.545468] Code: 74 2b 80 3d e6 c1 81 00 00 75 22 0f b6 53 12 8b 8b 14 06 00 00 41 89 c0 48 c7 c7 b0 03 d4 81 c6 05 c9 c1 81 00 01 e8 ef 30 a5 ff <0f> 0b c6 83 62 04 00 00 00 e9 ce 00 00 00 8b 93 98 05 00 00 85 
[   56.564513] ---[ end trace a7d4411530d0c7d2 ]---
Comment 3 Eric Dumazet 2019-10-31 00:28:43 UTC
This might be fixed in 4.14.146

ba2ddb43f270e6492ccce4fc42fc32c611de8f68 tcp: Don't dequeue SYN/FIN-segments from write-queue
f1dcc5ed4bea3f2d63b74ad86617ec12b1e5e9d4 tcp: Reset send_head when removing skb from write-queue
Comment 4 Roman Mamedov 2019-10-31 05:00:50 UTC
Yes I don't get these anymore recently, thanks.

Note You need to log in before you can comment on or make changes to this bug.