OpenVPN / ovpn-dco

OpenVPN Data Channel Offload in the linux kernel
101 stars 23 forks source link

2.6.2: Kernel warning refcount_warn_saturate #29

Open bernhardschmidt opened 1 year ago

bernhardschmidt commented 1 year ago

We have upgraded our production eduVPN server to 2.6.2 + 1c2c84e99d0c1513db38ac7a3858f21229906fd7 . It looks a lot better than before, it has been running for close to 6 hours now. This is the only kernel WARNING we got so far

Mar 28 10:06:25 eduvpn-n09 kernel: ovpn_tcp_tx_work: cannot send TCP packet to peer 4: -101
Mar 28 10:06:25 eduvpn-n09 kernel: ------------[ cut here ]------------
Mar 28 10:06:25 eduvpn-n09 kernel: refcount_t: underflow; use-after-free.
Mar 28 10:06:25 eduvpn-n09 kernel: WARNING: CPU: 1 PID: 32192 at lib/refcount.c:28 refcount_warn_saturate+0xba/0x110
Mar 28 10:06:25 eduvpn-n09 kernel: Modules linked in: binfmt_misc rpcsec_gss_krb5 auth_rpcgss nfsv4 dns_resolver nfs lockd grace nfs_ssc fscache dm_mod ovpn_dco_v2(OE) ip6_udp_tunnel udp_tunnel vsock_loopback vmw_vsock_virtio_transport>
Mar 28 10:06:25 eduvpn-n09 kernel: CPU: 1 PID: 32192 Comm: kworker/1:1 Tainted: G           OE     5.10.0-21-amd64 #1 Debian 5.10.162-1
Mar 28 10:06:25 eduvpn-n09 kernel: Hardware name: VMware, Inc. VMware7,1/440BX Desktop Reference Platform, BIOS VMW71.00V.18227214.B64.2106252220 06/25/2021
Mar 28 10:06:25 eduvpn-n09 kernel: Workqueue: ovpn-crypto-wq-tun263 ovpn_decrypt_work [ovpn_dco_v2]
Mar 28 10:06:25 eduvpn-n09 kernel: RIP: 0010:refcount_warn_saturate+0xba/0x110
Mar 28 10:06:25 eduvpn-n09 kernel: Code: 01 01 e8 43 50 43 00 0f 0b c3 cc cc cc cc 80 3d 6a c5 3b 01 00 75 85 48 c7 c7 10 08 72 b7 c6 05 5a c5 3b 01 01 e8 20 50 43 00 <0f> 0b c3 cc cc cc cc 80 3d 45 c5 3b 01 00 0f 85 5e ff ff ff 48 c7
Mar 28 10:06:25 eduvpn-n09 kernel: RSP: 0018:ffffbc3600ac3e90 EFLAGS: 00010286
Mar 28 10:06:25 eduvpn-n09 kernel: RAX: 0000000000000000 RBX: ffff9fe10b94f680 RCX: ffff9fe139e60908
Mar 28 10:06:25 eduvpn-n09 kernel: RDX: 00000000ffffffd8 RSI: 0000000000000027 RDI: ffff9fe139e60900
Mar 28 10:06:25 eduvpn-n09 kernel: RBP: ffff9fe0232b9080 R08: 0000000000000000 R09: ffffbc3600ac3cb0
Mar 28 10:06:25 eduvpn-n09 kernel: R10: ffffbc3600ac3ca8 R11: ffff9fe13fec45a8 R12: ffff9fe139e735c0
Mar 28 10:06:25 eduvpn-n09 kernel: R13: 0000000000000020 R14: ffffdc35fde50900 R15: 0000000000000000
Mar 28 10:06:25 eduvpn-n09 kernel: FS:  0000000000000000(0000) GS:ffff9fe139e40000(0000) knlGS:0000000000000000
Mar 28 10:06:25 eduvpn-n09 kernel: CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Mar 28 10:06:25 eduvpn-n09 kernel: CR2: 0000557c82d774e8 CR3: 0000000104916003 CR4: 00000000007706e0
Mar 28 10:06:25 eduvpn-n09 kernel: PKRU: 55555554
Mar 28 10:06:25 eduvpn-n09 kernel: Call Trace:
Mar 28 10:06:25 eduvpn-n09 kernel:  process_one_work+0x1b3/0x350
Mar 28 10:06:25 eduvpn-n09 kernel:  worker_thread+0x53/0x3e0
Mar 28 10:06:25 eduvpn-n09 kernel:  ? process_one_work+0x350/0x350
Mar 28 10:06:25 eduvpn-n09 kernel:  kthread+0x118/0x140
Mar 28 10:06:25 eduvpn-n09 kernel:  ? __kthread_bind_mask+0x60/0x60
Mar 28 10:06:25 eduvpn-n09 kernel:  ret_from_fork+0x1f/0x30
Mar 28 10:06:25 eduvpn-n09 kernel: ---[ end trace b38473f5264f2b20 ]---
Mar 28 10:06:25 eduvpn-n09 kernel: ------------[ cut here ]------------
Mar 28 10:06:25 eduvpn-n09 kernel: refcount_t: saturated; leaking memory.
Mar 28 10:06:25 eduvpn-n09 kernel: WARNING: CPU: 1 PID: 0 at lib/refcount.c:19 refcount_warn_saturate+0x97/0x110
Mar 28 10:06:25 eduvpn-n09 kernel: Modules linked in: binfmt_misc rpcsec_gss_krb5 auth_rpcgss nfsv4 dns_resolver nfs lockd grace nfs_ssc fscache dm_mod ovpn_dco_v2(OE) ip6_udp_tunnel udp_tunnel vsock_loopback vmw_vsock_virtio_transport>
Mar 28 10:06:25 eduvpn-n09 kernel: CPU: 1 PID: 0 Comm: swapper/1 Tainted: G        W  OE     5.10.0-21-amd64 #1 Debian 5.10.162-1
Mar 28 10:06:25 eduvpn-n09 kernel: Hardware name: VMware, Inc. VMware7,1/440BX Desktop Reference Platform, BIOS VMW71.00V.18227214.B64.2106252220 06/25/2021
Mar 28 10:06:25 eduvpn-n09 kernel: RIP: 0010:refcount_warn_saturate+0x97/0x110
Mar 28 10:06:25 eduvpn-n09 kernel: Code: 01 01 e8 66 50 43 00 0f 0b c3 cc cc cc cc 80 3d 90 c5 3b 01 00 75 a8 48 c7 c7 b8 07 72 b7 c6 05 80 c5 3b 01 01 e8 43 50 43 00 <0f> 0b c3 cc cc cc cc 80 3d 6a c5 3b 01 00 75 85 48 c7 c7 10 08 72
Mar 28 10:06:25 eduvpn-n09 kernel: RSP: 0018:ffffbc36004c8a78 EFLAGS: 00010286
Mar 28 10:06:25 eduvpn-n09 kernel: RAX: 0000000000000000 RBX: 0000000000000002 RCX: ffff9fe139e60908
Mar 28 10:06:25 eduvpn-n09 kernel: RDX: 00000000ffffffd8 RSI: 0000000000000027 RDI: ffff9fe139e60900
Mar 28 10:06:25 eduvpn-n09 kernel: RBP: 0000000000000002 R08: 0000000000000000 R09: ffffbc36004c8898
Mar 28 10:06:25 eduvpn-n09 kernel: R10: ffffbc36004c8890 R11: ffff9fe13fec45a8 R12: 0000000000000064
Mar 28 10:06:25 eduvpn-n09 kernel: R13: 0000000000000064 R14: 0000000000000064 R15: ffff9fe0232b9000
Mar 28 10:06:25 eduvpn-n09 kernel: FS:  0000000000000000(0000) GS:ffff9fe139e40000(0000) knlGS:0000000000000000
Mar 28 10:06:25 eduvpn-n09 kernel: CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Mar 28 10:06:25 eduvpn-n09 kernel: CR2: 0000557c82d774e8 CR3: 0000000104916003 CR4: 00000000007706e0
Mar 28 10:06:25 eduvpn-n09 kernel: PKRU: 55555554
Mar 28 10:06:25 eduvpn-n09 kernel: Call Trace:
Mar 28 10:06:25 eduvpn-n09 kernel:  <IRQ>
Mar 28 10:06:25 eduvpn-n09 kernel:  ovpn_tcp_read_sock+0x25e/0x340 [ovpn_dco_v2]
Mar 28 10:06:25 eduvpn-n09 kernel:  ? ovpn_tcp_tx_work+0xf0/0xf0 [ovpn_dco_v2]
Mar 28 10:06:25 eduvpn-n09 kernel:  tcp_read_sock+0xa0/0x280
Mar 28 10:06:25 eduvpn-n09 kernel:  ovpn_tcp_data_ready+0x5a/0x80 [ovpn_dco_v2]
Mar 28 10:06:25 eduvpn-n09 kernel:  tcp_rcv_established+0x5de/0x690
Mar 28 10:06:25 eduvpn-n09 kernel:  tcp_v6_do_rcv+0xc6/0x3d0
Mar 28 10:06:25 eduvpn-n09 kernel:  tcp_v6_rcv+0xcfe/0xe00
Mar 28 10:06:25 eduvpn-n09 kernel:  ? nf_confirm+0xcb/0x100 [nf_conntrack]
Mar 28 10:06:25 eduvpn-n09 kernel:  ip6_protocol_deliver_rcu+0xcc/0x4e0
Mar 28 10:06:25 eduvpn-n09 kernel:  ip6_input+0xbb/0xd0
Mar 28 10:06:25 eduvpn-n09 kernel:  ? ip6_protocol_deliver_rcu+0x4e0/0x4e0
Mar 28 10:06:25 eduvpn-n09 kernel:  ip6_sublist_rcv_finish+0x54/0x70
Mar 28 10:06:25 eduvpn-n09 kernel:  ip6_sublist_rcv+0x210/0x2b0
Mar 28 10:06:25 eduvpn-n09 kernel:  ? ip6_sublist_rcv+0x2b0/0x2b0
Mar 28 10:06:25 eduvpn-n09 kernel:  ? ip6_sublist_rcv+0x2b0/0x2b0
Mar 28 10:06:25 eduvpn-n09 kernel:  ipv6_list_rcv+0x138/0x160
Mar 28 10:06:25 eduvpn-n09 kernel:  __netif_receive_skb_list_core+0x204/0x2e0
Mar 28 10:06:25 eduvpn-n09 kernel:  netif_receive_skb_list_internal+0x1b7/0x2f0
Mar 28 10:06:25 eduvpn-n09 kernel:  ? vmxnet3_rq_rx_complete+0x95a/0xe90 [vmxnet3]
Mar 28 10:06:25 eduvpn-n09 kernel:  napi_complete_done+0x6f/0x1a0
Mar 28 10:06:25 eduvpn-n09 kernel:  vmxnet3_poll_rx_only+0x7f/0xb0 [vmxnet3]
Mar 28 10:06:25 eduvpn-n09 kernel:  net_rx_action+0x142/0x3e0
Mar 28 10:06:25 eduvpn-n09 kernel:  __do_softirq+0xc2/0x279
Mar 28 10:06:25 eduvpn-n09 kernel:  asm_call_irq_on_stack+0xf/0x20
Mar 28 10:06:25 eduvpn-n09 kernel:  </IRQ>
Mar 28 10:06:25 eduvpn-n09 kernel:  do_softirq_own_stack+0x37/0x50
Mar 28 10:06:25 eduvpn-n09 kernel:  irq_exit_rcu+0x92/0xc0
Mar 28 10:06:25 eduvpn-n09 kernel:  common_interrupt+0x74/0x130
Mar 28 10:06:25 eduvpn-n09 kernel:  asm_common_interrupt+0x1e/0x40
Mar 28 10:06:25 eduvpn-n09 kernel: RIP: 0010:native_safe_halt+0xe/0x20
Mar 28 10:06:25 eduvpn-n09 kernel: Code: 00 f0 80 48 02 20 48 8b 00 a8 08 75 c0 e9 77 ff ff ff cc cc cc cc cc cc cc cc cc cc 0f 1f 44 00 00 0f 00 2d b6 8e 50 00 fb f4 <c3> cc cc cc cc 66 66 2e 0f 1f 84 00 00 00 00 00 66 90 0f 1f 44 00
Mar 28 10:06:25 eduvpn-n09 kernel: RSP: 0018:ffffbc36000a3e80 EFLAGS: 00000246
Mar 28 10:06:25 eduvpn-n09 kernel: RAX: 0000000000004000 RBX: 0000000000000001 RCX: ffff9fe139e74940
Mar 28 10:06:25 eduvpn-n09 kernel: RDX: ffff9fe139e40000 RSI: ffff9fe102382400 RDI: ffff9fe102382464
Mar 28 10:06:25 eduvpn-n09 kernel: RBP: ffff9fe102382464 R08: ffffffffb7db9440 R09: 0000000000000018
Mar 28 10:06:25 eduvpn-n09 kernel: R10: 00000000000001c5 R11: 0000000000000155 R12: 0000000000000001
Mar 28 10:06:25 eduvpn-n09 kernel: R13: ffffffffb7db94c0 R14: 0000000000000001 R15: 0000000000000000
Mar 28 10:06:25 eduvpn-n09 kernel:  acpi_idle_do_entry+0x4a/0x60
Mar 28 10:06:25 eduvpn-n09 kernel:  acpi_idle_enter+0x84/0xd0
Mar 28 10:06:25 eduvpn-n09 kernel:  cpuidle_enter_state+0x86/0x350
Mar 28 10:06:25 eduvpn-n09 kernel:  cpuidle_enter+0x29/0x40
Mar 28 10:06:25 eduvpn-n09 kernel:  do_idle+0x1f3/0x2b0
Mar 28 10:06:25 eduvpn-n09 kernel:  cpu_startup_entry+0x19/0x20
Mar 28 10:06:25 eduvpn-n09 kernel:  secondary_startup_64_no_verify+0xb0/0xbb
Mar 28 10:06:25 eduvpn-n09 kernel: ---[ end trace b38473f5264f2b21 ]---
ordex commented 1 year ago

Hi @bernhardschmidt thanks a lot! I will dig into it! Should you find any potential reason triggering it, please let me know

ordex commented 8 months ago

the master branch contains what we believe to be a fix for this issue. would you be able to give it a try?

claw6148 commented 8 months ago

v0.2.20230426 + 7b7a28fcb0c244c7182922f7c83cb09bcd840c84 still prints refcount_t: underflow; use-after-free. but rarely happens and not affecting ovpn to be exited

[   51.473003] ovs (uninitialized): ovpn_newlink: setting device (ovs) mode: 1
[   51.487327] ovpn_dco_v2:ovpn_queue_skb:390: ovs: no peer to send data to
[   51.496115] ovpn_dco_v2:ovpn_queue_skb:390: ovs: no peer to send data to
[   51.520026] ovpn_dco_v2:ovpn_queue_skb:390: ovs: no peer to send data to
[   51.530132] === OVPN UP ===
[   52.159906] ovpn_dco_v2:ovpn_queue_skb:390: ovs: no peer to send data to
[   52.166675] ovpn_dco_v2:ovpn_queue_skb:390: ovs: no peer to send data to
[   52.610024] === OVPN CONNECTED ===
[   52.619264] ovs: ovpn_netlink_new_peer: adding peer with endpoint=(null)/TCPv6 id=0 VPN-IPv4=10.0.0.2 VPN-IPv6=100::1000
[   52.633105] ovs: ovpn_peer_keepalive_set: scheduling keepalive for peer 0: interval=3 timeout=12
[   52.753726] ovpn_dco_v2:ovpn_aead_init:254: ********* Cipher rfc7539(chacha20,poly1305) (encrypt)
[   52.762757] ovpn_dco_v2:ovpn_aead_init:255: *** IV size=12
[   52.768378] ovpn_dco_v2:ovpn_aead_init:256: *** req size=504
[   52.774129] ovpn_dco_v2:ovpn_aead_init:257: *** block size=1
[   52.779848] ovpn_dco_v2:ovpn_aead_init:258: *** auth size=16
[   52.785562] ovpn_dco_v2:ovpn_aead_init:259: *** alignmask=0x0
[   52.791417] ovpn_dco_v2:ovpn_aead_init:254: ********* Cipher rfc7539(chacha20,poly1305) (decrypt)
[   52.800458] ovpn_dco_v2:ovpn_aead_init:255: *** IV size=12
[   52.806100] ovpn_dco_v2:ovpn_aead_init:256: *** req size=504
[   52.811849] ovpn_dco_v2:ovpn_aead_init:257: *** block size=1
[   52.817581] ovpn_dco_v2:ovpn_aead_init:258: *** auth size=16
[   52.823278] ovpn_dco_v2:ovpn_aead_init:259: *** alignmask=0x0
[   52.829212] ovs: ovpn_netlink_new_key: new key installed (id=0) for peer 0
[   60.961600] ovs: ovpn_decrypt_one: ping received from peer with id 0
[   61.215702] ovs: ovpn_peer_ping: sending ping to peer 0 refcount 1
[   66.229241] ovs: ovpn_decrypt_one: ping received from peer with id 0
[   66.335701] ovs: ovpn_peer_ping: sending ping to peer 0 refcount 1
[   69.232074] ovs: ovpn_decrypt_one: ping received from peer with id 0
[   69.407701] ovs: ovpn_peer_ping: sending ping to peer 0 refcount 1
[   73.667271] ovs: ovpn_decrypt_one: ping received from peer with id 0
[   73.759709] ovs: ovpn_peer_ping: sending ping to peer 0 refcount 1
[   76.668364] ovs: ovpn_decrypt_one: ping received from peer with id 0
[   76.831751] ovs: ovpn_peer_ping: sending ping to peer 0 refcount 1
[   82.847986] === OVPN DISCONNECTED ===
[   82.853939] ovs: ovpn_netlink_del_peer: peer id=0
[   82.859347] ovpn_dco_v2:ovpn_queue_skb:390: ovs: no peer to send data to
[   82.883187] ------------[ cut here ]------------
[   82.887949] WARNING: CPU: 0 PID: 9 at lib/refcount.c:28 ovpn_recv+0x108/0x178 [ovpn_dco_v2]
[   82.896357] refcount_t: underflow; use-after-free.
[   82.901253] Modules linked in: ovpn_dco_v2 pppoe ppp_async l2tp_ppp wireguard pppox ppp_generic mt76x2e mt76x2_common mt76x02_lib mt7603e mt76 mac80211 libchacha20poly1305 ipt_REJECT ebtable_nat ebtable_filter ebtable_broute cfg80211 cdc_ncm xt_u32 xt_time xt_tcpudp xt_tcpmss xt_string xt_statistic xt_state xt_socket xt_recent xt_quota xt_pkttype xt_physdev xt_owner xt_nat xt_multiport xt_mark xt_mac xt_limit xt_length xt_iprange xt_hl xt_helper xt_ecn xt_dscp xt_conntrack xt_connmark xt_connlimit xt_connbytes xt_comment xt_bpf xt_addrtype xt_WGOBFS xt_TPROXY xt_TEE xt_TCPMSS xt_TARPIT xt_REDIRECT xt_NFQUEUE xt_NETMAP xt_MASQUERADE xt_LOG xt_HL xt_FLOWOFFLOAD xt_EOIP xt_DSCP xt_CT xt_CLASSIFY usbnet ts_kmp ts_fsm ts_bm tcprst tcp_bbr slhc poly1305_mips nfnetlink_queue nf_tproxy_ipv6 nf_tproxy_ipv4 nf_socket_ipv6 nf_socket_ipv4 nf_reject_ipv4 nf_log_ipv4 nf_flow_table_hw nf_flow_table nf_dup_ipv6 nf_dup_ipv4 nf_conntrack_netlink nf_conncount macvlan libcurve25519_generic iptable_raw
[   82.901491]  iptable_nat iptable_mangle iptable_filter ipt_ECN ip_tables ebtables ebt_vlan ebt_stp ebt_snat ebt_redirect ebt_pkttype ebt_mark_m ebt_mark ebt_limit ebt_ip ebt_dnat ebt_arpreply ebt_arp ebt_among ebt_802_3 crc_ccitt compat_xtables compat chacha_mips br_netfilter act_nat sciu2s usbserial sch_tbf sch_ingress sch_htb sch_hfsc em_u32 cls_u32 cls_route cls_matchall cls_fw cls_flow cls_basic act_skbedit act_mirred act_gact ledtrig_usbport 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_ipmac ip_set_hash_ip ip_set_bitmap_port ip_set_bitmap_ipmac ip_set_bitmap_ip ip_set nfnetlink ip6table_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 ip6t_NPT ip6t_rt ip6t_mh ip6t_ipv6header ip6t_hbh ip6t_frag ip6t_eui64 ip6t_ah nf_log_ipv6 nf_log_common ip6table_mangle ip6table_filter ip6_tables ip6t_REJECT
[   82.988541]  x_tables nf_reject_ipv6 ip6_gre ip_gre gre l2tp_netlink l2tp_core ip6_tunnel tunnel6 ip_tunnel veth tun vxlan udp_tunnel ip6_udp_tunnel leds_gpio xhci_plat_hcd xhci_pci xhci_mtk xhci_hcd gpio_button_hotplug usbcore nls_base usb_common mii
[   83.097890] CPU: 0 PID: 9 Comm: ksoftirqd/0 Not tainted 5.4.238 #0
[   83.104073] Stack : 8dec79b8 800804d0 80700000 807067d4 80770000 8070679c 80705498 8fc5d91c
[   83.112422]         808b0000 8fc3b1b0 80750d63 806860e4 00000000 00000001 8fc5d8c0 dfb599d3
[   83.120741]         00000000 00000000 808f0000 00000000 00000030 00000153 35206465 322e342e
[   83.129060]         00000000 00000004 00000000 00017e62 00000000 80770000 00000000 8dec130c
[   83.137379]         00000009 00000000 8fe2df00 00000009 00000001 80369ec8 00000000 808b0000
[   83.145697]         ...
[   83.148130] Call Trace:
[   83.150599] [<8000b6cc>] show_stack+0x30/0x100
[   83.155061] [<805c7dcc>] dump_stack+0xa4/0xdc
[   83.159415] [<8002d36c>] __warn+0xb0/0xfc
[   83.163406] [<8002d444>] warn_slowpath_fmt+0x8c/0xac
[   83.168373] [<8dec130c>] ovpn_recv+0x108/0x178 [ovpn_dco_v2]
[   83.174013] [<8dec7b0c>] ovpn_pktid_recv+0x50c/0xfec [ovpn_dco_v2]
[   83.180450] ---[ end trace ad90440e13d042f9 ]---
[   83.185564] ------------[ cut here ]------------
[   83.190358] WARNING: CPU: 0 PID: 9 at lib/refcount.c:19 ovpn_pktid_recv+0x5a8/0xfec [ovpn_dco_v2]
[   83.199313] refcount_t: saturated; leaking memory.
[   83.204180] Modules linked in: ovpn_dco_v2 pppoe ppp_async l2tp_ppp wireguard pppox ppp_generic mt76x2e mt76x2_common mt76x02_lib mt7603e mt76 mac80211 libchacha20poly1305 ipt_REJECT ebtable_nat ebtable_filter ebtable_broute cfg80211 cdc_ncm xt_u32 xt_time xt_tcpudp xt_tcpmss xt_string xt_statistic xt_state xt_socket xt_recent xt_quota xt_pkttype xt_physdev xt_owner xt_nat xt_multiport xt_mark xt_mac xt_limit xt_length xt_iprange xt_hl xt_helper xt_ecn xt_dscp xt_conntrack xt_connmark xt_connlimit xt_connbytes xt_comment xt_bpf xt_addrtype xt_WGOBFS xt_TPROXY xt_TEE xt_TCPMSS xt_TARPIT xt_REDIRECT xt_NFQUEUE xt_NETMAP xt_MASQUERADE xt_LOG xt_HL xt_FLOWOFFLOAD xt_EOIP xt_DSCP xt_CT xt_CLASSIFY usbnet ts_kmp ts_fsm ts_bm tcprst tcp_bbr slhc poly1305_mips nfnetlink_queue nf_tproxy_ipv6 nf_tproxy_ipv4 nf_socket_ipv6 nf_socket_ipv4 nf_reject_ipv4 nf_log_ipv4 nf_flow_table_hw nf_flow_table nf_dup_ipv6 nf_dup_ipv4 nf_conntrack_netlink nf_conncount macvlan libcurve25519_generic iptable_raw
[   83.204513]  iptable_nat iptable_mangle iptable_filter ipt_ECN ip_tables ebtables ebt_vlan ebt_stp ebt_snat ebt_redirect ebt_pkttype ebt_mark_m ebt_mark ebt_limit ebt_ip ebt_dnat ebt_arpreply ebt_arp ebt_among ebt_802_3 crc_ccitt compat_xtables compat chacha_mips br_netfilter act_nat sciu2s usbserial sch_tbf sch_ingress sch_htb sch_hfsc em_u32 cls_u32 cls_route cls_matchall cls_fw cls_flow cls_basic act_skbedit act_mirred act_gact ledtrig_usbport 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_ipmac ip_set_hash_ip ip_set_bitmap_port ip_set_bitmap_ipmac ip_set_bitmap_ip ip_set nfnetlink ip6table_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 ip6t_NPT ip6t_rt ip6t_mh ip6t_ipv6header ip6t_hbh ip6t_frag ip6t_eui64 ip6t_ah nf_log_ipv6 nf_log_common ip6table_mangle ip6table_filter ip6_tables ip6t_REJECT
[   83.291663]  x_tables nf_reject_ipv6 ip6_gre ip_gre gre l2tp_netlink l2tp_core ip6_tunnel tunnel6 ip_tunnel veth tun vxlan udp_tunnel ip6_udp_tunnel leds_gpio xhci_plat_hcd xhci_pci xhci_mtk xhci_hcd gpio_button_hotplug usbcore nls_base usb_common mii
[   83.401032] CPU: 0 PID: 9 Comm: ksoftirqd/0 Tainted: G        W         5.4.238 #0
[   83.408592] Stack : 8dec79b8 800804d0 80700000 807067d4 80770000 8070679c 80705498 8fc5d944
[   83.416936]         808b0000 8fc3b1b0 80750d63 806860e4 00000000 00000001 8fc5d8e8 dfb599d3
[   83.425256]         00000000 00000000 808f0000 00000000 00000030 00000168 35202020 322e342e
[   83.433575]         00000000 00000004 00000000 00061e88 00000000 80770000 00000000 8dec7ba8
[   83.441893]         00000009 00000000 8fe2d180 00000009 00000001 80369ec8 00000000 808b0000
[   83.450211]         ...
[   83.452645] Call Trace:
[   83.455116] [<8000b6cc>] show_stack+0x30/0x100
[   83.459579] [<805c7dcc>] dump_stack+0xa4/0xdc
[   83.463934] [<8002d36c>] __warn+0xb0/0xfc
[   83.467926] [<8002d444>] warn_slowpath_fmt+0x8c/0xac
[   83.472893] [<8dec7ba8>] ovpn_pktid_recv+0x5a8/0xfec [ovpn_dco_v2]
[   83.479299] ---[ end trace ad90440e13d042fa ]---
[   83.492710] ovs (unregistering): deleting peer with id 0, reason 1
ordex commented 8 months ago

Thanks for reporting. This confirms that here we are dealing with a different issue.

claw6148 commented 8 months ago

the way is similar to #18, but not 100% reliable to reproduce...

not sure if the following findings is related i checked the return value of ovpn_peer_hold() in ovpn_tcp_read_sock(), it would to be failed (false) sometimes when exit the ovpn. maybe a double free occurs after ovpn_recv()?

ordex commented 8 months ago

not a double free, but basically we are using an object having refcount equal to 0 already. This should not happen because we (should) always perform a hold() before using the peer and bail out if return value is false.

Now, in ovpn_tcp_read_sock() we assume to be already holding a reference to the peer, hence we assume that the peer refcount cannot be 0. This is why we don't check the return value of ovpn_peer_hold(). However, something is going wrong and we are using a dead peer, which results in the message you reported when we do a put() on it (basically asking to decrement the refcount, but it is 0 already! underflow!)

So something is wrong around the assumption of already holding a ref in ovpn_tcp_read_sock() Thanks for your time on this. Very useful so far

ordex commented 8 months ago

I think I should at least add a WARN_ON(!ovpn_peer_hold()) in ovpn_tcp_read_sock(), in order to highlight the unwanted situation.

claw6148 commented 8 months ago

haha... maybe i should say "double put" thanks for your detailed explaination!

claw6148 commented 8 months ago

i automated the test by some scripts and now it loops itself. sometimes shown refcount_t: ... and sometimes panic at decryption

i tried to set status = -1 and skip further processing if _hold() failed in tcp recv path as a workaround, then ran the same automatic test for some hours, no refcount_t: ... or kernel panic happens...

if you have new ideas i could help to try

kernel panic log
[  629.462856] OpenVPN data channel offload (ovpn-dco) 2.0.0 -- (C) 2020-2023 OpenVPN, Inc.
[  629.566333] === OVPN UP ===
[  630.045953] === OVPN CONNECTED ===
[  634.508026] === OVPN DISCONNECTED ===
[  641.872456] ovs (unregistered): deleting peer with id 0, reason 1, refcount 0
[  642.095452] OpenVPN data channel offload (ovpn-dco) 2.0.0 -- (C) 2020-2023 OpenVPN, Inc.
[  642.208358] === OVPN UP ===
[  643.058373] === OVPN CONNECTED ===
[  647.145359] === OVPN DISCONNECTED ===
[  653.924496] ovs (unregistered): deleting peer with id 0, reason 1, refcount 0
[  654.299363] OpenVPN data channel offload (ovpn-dco) 2.0.0 -- (C) 2020-2023 OpenVPN, Inc.
[  654.401859] === OVPN UP ===
[  655.113708] === OVPN CONNECTED ===
[  659.342124] === OVPN DISCONNECTED ===
[  659.392530] ovs (unregistering): deleting peer with id 0, reason 1, refcount 0
[  659.795397] OpenVPN data channel offload (ovpn-dco) 2.0.0 -- (C) 2020-2023 OpenVPN, Inc.
[  659.902599] === OVPN UP ===
[  660.580699] === OVPN CONNECTED ===
[  664.839997] === OVPN DISCONNECTED ===
[  672.529352] ovs (unregistered): deleting peer with id 0, reason 1, refcount 0
[  672.692321] OpenVPN data channel offload (ovpn-dco) 2.0.0 -- (C) 2020-2023 OpenVPN, Inc.
[  672.796617] === OVPN UP ===
[  673.719704] === OVPN CONNECTED ===
[  677.740144] === OVPN DISCONNECTED ===
[  684.506142] ovs (unregistered): deleting peer with id 0, reason 1, refcount 0
[  684.656086] OpenVPN data channel offload (ovpn-dco) 2.0.0 -- (C) 2020-2023 OpenVPN, Inc.
[  684.754853] === OVPN UP ===
[  685.685571] === OVPN CONNECTED ===
[  689.706047] === OVPN DISCONNECTED ===
[  696.517813] ovs (unregistered): deleting peer with id 0, reason 1, refcount 0
[  696.660450] OpenVPN data channel offload (ovpn-dco) 2.0.0 -- (C) 2020-2023 OpenVPN, Inc.
[  696.761643] === OVPN UP ===
[  697.705879] === OVPN CONNECTED ===
[  701.706752] === OVPN DISCONNECTED ===
[  701.727836] failed to hold peer d4a83ca5 refcount 0
[  701.733010] failed to hold peer d4a83ca5 refcount 0
[  701.760522] ovs (unregistering): deleting peer with id 0, reason 1, refcount -1073741824
[  702.196648] OpenVPN data channel offload (ovpn-dco) 2.0.0 -- (C) 2020-2023 OpenVPN, Inc.
[  702.295662] === OVPN UP ===
[  702.977901] === OVPN CONNECTED ===
[  707.243996] === OVPN DISCONNECTED ===
[  707.263184] failed to hold peer 27d98334 refcount 0
[  707.268291] failed to hold peer 27d98334 refcount 0
[  707.295777] ovs (unregistering): deleting peer with id 0, reason 1, refcount -1073741824
[  707.304636] CPU 1 Unable to handle kernel paging request at virtual address 00000179, epc == 8ca1162c, ra == 8ca1161c
[  707.315324] Oops[#1]:
[  707.317667] CPU: 1 PID: 77 Comm: kworker/1:1 Tainted: G        W         5.4.238 #0
[  707.325360] Workqueue: ovpn-crypto-wq-ovs ovpn_decrypt_work [ovpn_dco_v2]
[  707.332157] $ 0   : 00000000 00000001 00000011 00000000
[  707.337383] $ 4   : 8e4fdb3c 00019961 00000001 000ff8b5
[  707.342607] $ 8   : 8cc08000 8cc08000 0000007c 00000032
[  707.347827] $12   : 33323130 37363534 8da3895f 5234e015
[  707.353050] $16   : 8e4fd84c 8e49d000 8e1d1750 00000000
[  707.358274] $20   : 8e4fd8e8 00000000 8e4fd800 8ca19ae0
[  707.363495] $24   : 00000000 3957c031
[  707.368709] $28   : 8fe12000 8fe13e20 8ca19ab8 8ca1161c
[  707.373925] Hi    : 0d04b0dd
[  707.376792] Lo    : bae21fe7
[  707.379682] epc   : 8ca1162c ovpn_decrypt_work+0x2b0/0x77c [ovpn_dco_v2]
[  707.386365] ra    : 8ca1161c ovpn_decrypt_work+0x2a0/0x77c [ovpn_dco_v2]
[  707.393034] Status: 11007c03 KERNEL EXL IE
[  707.397209] Cause : 40800008 (ExcCode 02)
[  707.401201] BadVA : 00000179
[  707.404068] PrId  : 0001992f (MIPS 1004Kc)
[  707.408145] Modules linked in: ovpn_dco_v2 pppoe ppp_async l2tp_ppp wireguard pppox ppp_generic mt76x2e mt76x2_common mt76x02_lib mt7603e mt76 mac80211 libchacha20poly1305 ipt_REJECT ebtable_nat ebtable_filter ebtable_broute cfg80211 cdc_ncm xt_u32 xt_time xt_tcpudp xt_tcpmss xt_string xt_statistic xt_state xt_socket xt_recent xt_quota xt_pkttype xt_physdev xt_owner xt_nat xt_multiport xt_mark xt_mac xt_limit xt_length xt_iprange xt_hl xt_helper xt_ecn xt_dscp xt_conntrack xt_connmark xt_connlimit xt_connbytes xt_comment xt_bpf xt_addrtype xt_WGOBFS xt_TPROXY xt_TEE xt_TCPMSS xt_TARPIT xt_REDIRECT xt_NFQUEUE xt_NETMAP xt_MASQUERADE xt_LOG xt_HL xt_FLOWOFFLOAD xt_EOIP xt_DSCP xt_CT xt_CLASSIFY usbnet ts_kmp ts_fsm ts_bm tcprst tcp_bbr slhc poly1305_mips nfnetlink_queue nf_tproxy_ipv6 nf_tproxy_ipv4 nf_socket_ipv6 nf_socket_ipv4 nf_reject_ipv4 nf_log_ipv4 nf_flow_table_hw nf_flow_table nf_dup_ipv6 nf_dup_ipv4 nf_conntrack_netlink nf_conncount macvlan libcurve25519_generic iptable_raw
[  707.408428]  iptable_nat iptable_mangle iptable_filter ipt_ECN ip_tables ebtables ebt_vlan ebt_stp ebt_snat ebt_redirect ebt_pkttype ebt_mark_m ebt_mark ebt_limit ebt_ip ebt_dnat ebt_arpreply ebt_arp ebt_among ebt_802_3 crc_ccitt compat_xtables compat chacha_mips br_netfilter act_nat sciu2s usbserial sch_tbf sch_ingress sch_htb sch_hfsc em_u32 cls_u32 cls_route cls_matchall cls_fw cls_flow cls_basic act_skbedit act_mirred act_gact ledtrig_usbport 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_ipmac ip_set_hash_ip ip_set_bitmap_port ip_set_bitmap_ipmac ip_set_bitmap_ip ip_set nfnetlink ip6table_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 ip6t_NPT ip6t_rt ip6t_mh ip6t_ipv6header ip6t_hbh ip6t_frag ip6t_eui64 ip6t_ah nf_log_ipv6 nf_log_common ip6table_mangle ip6table_filter ip6_tables ip6t_REJECT
[  707.495194]  x_tables nf_reject_ipv6 ip6_gre ip_gre gre l2tp_netlink l2tp_core ip6_tunnel tunnel6 ip_tunnel veth tun vxlan udp_tunnel ip6_udp_tunnel leds_gpio xhci_plat_hcd xhci_pci xhci_mtk xhci_hcd gpio_button_hotplug usbcore nls_base usb_common mii [last unloaded: ovpn_dco_v2]
[  707.606640] Process kworker/1:1 (pid: 77, threadinfo=852d4f30, task=06ff9492, tls=00000000)
[  707.614951] Stack : 00000cc0 00000001 8fde5580 81013b40 ff7d6e00 00000000 00000040 8ca1b580
[  707.623286]         8ca20000 8ca20000 00000001 00000003 8e4fd84c 8fde5580 81013b40 ff7d6d00
[  707.631622]         00000020 00000040 00000000 80750000 81013b40 80047664 81013b40 81013b40
[  707.639956]         00000008 81013b58 80750000 80750000 8fde5580 8fde5594 81013b40 00000008
[  707.648290]         81013b58 80750000 80750000 80047a20 80680000 808b0000 00000001 805e2fc0
[  707.656626]         ...
[  707.659068] Call Trace:
[  707.661528] [<8ca1162c>] ovpn_decrypt_work+0x2b0/0x77c [ovpn_dco_v2]
[  707.667894] [<80047664>] process_one_work+0x244/0x498
[  707.672933] [<80047a20>] worker_thread+0x168/0x5ec
[  707.677713] [<8004d654>] kthread+0x140/0x148
[  707.681980] [<80006878>] ret_from_kernel_thread+0x14/0x1c
[  707.687362] Code: 24020011  8c630080  8c630010 <90630179> 106200b7  00000000  8e240054  2606030c  0c0c0da1
[  707.697092]
[  707.699228] ---[ end trace f2d670d55287fe67 ]---
[  707.703942] Kernel panic - not syncing: Fatal exception
[  707.709241] Rebooting in 3 seconds..
ordex commented 8 months ago

yeah, you are basically "evading" the problematic situation and thus avoiding the crash. However, what's left to understand is "why" are we getting to the point that the hold() is failing we might be missing some _hold() (or doing an extra put()) somewhere before that.