Re: possible irq lock inversion dependency detected

[Jason A. Donenfeld]

Hi René,

Great, I'll ship it! Thanks for debugging.

Jason
___
WireGuard mailing list
WireGuard@lists.zx2c4.com
https://lists.zx2c4.com/mailman/listinfo/wireguard

Re: possible irq lock inversion dependency detected

[René van Dorst]

Quoting "Jason A. Donenfeld" :


Hi René,

I'm having trouble parsing your message. You wrote:


So I am not sure if you patch works or not.
Because it was not that easy to reproduce the last one.


Do you mean to imply that you could NOT reproduce it with my patch?
But that you could reproduce it WITHOUT the patch?

Jason


I was trying to reproduce the bug before the patch.
I could not reproduce the first one. Only hitting the second one 3 times.

After the patch I could not reproduce any of them.

Greats,

René



___
WireGuard mailing list
WireGuard@lists.zx2c4.com
https://lists.zx2c4.com/mailman/listinfo/wireguard

Re: possible irq lock inversion dependency detected

[Jason A. Donenfeld]

Hi René,

Are you able to reliably reproduce this? If so, could you let me know
if this patch fixes it?

https://git.zx2c4.com/WireGuard/patch/?id=940317ee52d020fc3e19e3a9f615acbc715985d5

Jason
___
WireGuard mailing list
WireGuard@lists.zx2c4.com
https://lists.zx2c4.com/mailman/listinfo/wireguard

possible irq lock inversion dependency detected

[René van Dorst]

Hi Jason,

I got a "possible irq lock inversion dependency detected" while  
shutdown a active tunnel with "wg-quick down wg0".


Linux utilite 4.13.5 #15 SMP Tue Oct 10 12:22:12 CEST 2017 armv7l GNU/Linux
WireGuard 0.0.20171005-4-g5101cb7
Distro: Debian 9.2 stretch armhf.

The kernel and wireguard compiled from source on the device.
Device: IMX6q Utilite Pro.



Dmesg log:


[12352.549306] wireguard: wg0: Peer 1 (192.168.2.222:36464) destroyed

[12352.550905] 
[12352.557311] WARNING: possible irq lock inversion dependency detected
[12352.563721] 4.13.5 #15 Tainted: G   O
[12352.568380] 
[12352.574785] swapper/0/0 just changed the state of lock:
[12352.580054]  (&(>consumer_lock)->rlock){+.-...}, at:  
[] packet_queue_free+0x24/0x84 [wireguard]

[12352.590096] but this lock took another, SOFTIRQ-unsafe lock in the past:
[12352.596851]  (>seq#7){+.+...}
[12352.596888]

   and interrupts could create inverse lock ordering between them.

[12352.611967]
   other info that might help us debug this:
[12352.618591]  Possible interrupt unsafe locking scenario:

[12352.625461]CPU0CPU1
[12352.630043]
[12352.634623]   lock(>seq#7);
[12352.638095]local_irq_disable();
[12352.644073] 
lock(&(>consumer_lock)->rlock);

[12352.651286]lock(>seq#7);
[12352.657238]   
[12352.659873] lock(&(>consumer_lock)->rlock);
[12352.664688]
*** DEADLOCK ***

[12352.670643] 1 lock held by swapper/0/0:
[12352.674496]  #0:  (rcu_callback){..}, at: []  
rcu_process_callbacks+0x2fc/0x5d0

[12352.682991]
   the shortest dependencies between 2nd lock and 1st lock:
[12352.690854]  -> (>seq#7){+.+...} ops: 427590 {
[12352.695944] HARDIRQ-ON-W at:
[12352.699200]   lock_acquire+0x70/0x90
[12352.704541]   iptunnel_xmit+0x174/0x1e0
[12352.710140]   udp_tunnel_xmit_skb+0xe8/0xf0
[12352.716121]
socket_send_skb_to_peer+0x400/0x830 [wireguard]
[12352.723665]
socket_send_buffer_to_peer+0x74/0x84 [wireguard]
[12352.731292]
packet_send_handshake_initiation+0xb8/0xf8 [wireguard]
[12352.739437]
packet_handshake_send_worker+0x18/0x24 [wireguard]

[12352.747217]   process_one_work+0x24c/0x4e8
[12352.753074]   worker_thread+0x40/0x574
[12352.758583]   kthread+0x120/0x160
[12352.763659]   ret_from_fork+0x14/0x24
[12352.769079] SOFTIRQ-ON-W at:
[12352.772333]   lock_acquire+0x70/0x90
[12352.777699]
receive_handshake_packet+0x114/0x3f0 [wireguard]
[12352.785325]
packet_handshake_receive_worker+0x1c/0x44 [wireguard]

[12352.793364]   process_one_work+0x24c/0x4e8
[12352.799220]   worker_thread+0x40/0x574
[12352.804728]   kthread+0x120/0x160
[12352.809802]   ret_from_fork+0x14/0x24
[12352.815223] INITIAL USE at:
[12352.818388]  lock_acquire+0x70/0x90
[12352.823638]  ip_tunnel_get_stats64+0x148/0x190
[12352.829848]  dev_get_stats+0x40/0xb4
[12352.835188]  rtnl_fill_stats+0x38/0x120
[12352.840784]  rtnl_fill_ifinfo+0x508/0xe00
[12352.846555]  rtmsg_ifinfo_build_skb+0x70/0xe0
[12352.852673]  rtmsg_ifinfo_event.part.7+0x1c/0x4c
[12352.859052]  rtmsg_ifinfo+0x30/0x38
[12352.864302]  __dev_notify_flags+0x94/0xa4
[12352.870071]  rtnl_configure_link+0x80/0xa4
[12352.875928]  rtnl_newlink+0x64c/0x748
[12352.881349]  rtnetlink_rcv_msg+0x94/0x1f4
[12352.887122]  netlink_rcv_skb+0xe0/0x100
[12352.892716]  rtnetlink_rcv+0x28/0x38
[12352.898049]  netlink_unicast+0x184/0x26c
[12352.903730]  netlink_sendmsg+0x29c/0x378
[12352.909417]  sock_sendmsg+0x1c/0x2c
[12352.914664]  ___sys_sendmsg+0x214/0x22c
[12352.920260]  __sys_sendmsg+0x48/0x74
[12352.925594]  SyS_sendmsg+0x10/0x14
[12352.930757]  ret_fast_syscall+0x0/0x1c
[12352.936262]   }
[12352.938062]   ... key  at: []  
__key.33453+0x0/0xba48 [wireguard]

[12352.945664]   ... acquired at:
[12352.948738]iptunnel_xmit+0x174/0x1e0
[12352.952683]udp_tunnel_xmit_skb+0xe8/0xf0
[12352.957000]socket_send_skb_to_peer+0x40