locking: metadata service vs packet in (ARP)
In the example below, there's a deadlock between two threads over a single node. One thread is part of the metadata service, and it has discovered it now has metadata for a previously pending port -- so it calls the cnc notify function, which results in a call to cnc_port_add
with the switch locked -- and after that adds the node object for that port, it proceeds to add some default flows, which results in an attempt to lock the node. But at the same time, a packet (whatever, in this case it appears to be an ARP) comes in from the node, and we first lock the node, then try to lock the switch and port. That's not gonna work.
In general, we have to solve this problem with better lock ordering or something. For now, it's enough to have cnc_port_add to take a lock on the cn_cnode_t it creates as soon as it creates it, before it even adds it to the switch and to the port. This lets the metadata service finish handling the new node entirely, and blocks the packet_in handler from making progress until that is done. Kind of a big stick, but it's appropriate that we not respond to packet_in msgs on ports that don't yet have a node.
Specifically, in the example below, thread 9 had temporarily grabbed the port lock, released it, and is trying to get the switch, to handle an arp -- but it also holds the node lock! thread 1 now holds the sw lock -- and it wants the node lock. This is because of cn_unordered_acquire_node_switch_lock
-- it holds the node still while it calls cn_unordered_acquire_port_switch_lock
? Thus we have an ordering problem that is guaranteed to deadlock eventually.
(gdb) info th
Id Target Id Frame
26 Thread 0x7f8041c39700 (LWP 99827) "capnet-controll" __pthread_rwlock_wrlock_slow (rwlock=rwlock@entry=0x7f80443b0a80 <domain_lock>) at pthread_rwlock_wrlock.c:66
25 Thread 0x7f8041438700 (LWP 99828) "capnet-controll" __pthread_rwlock_wrlock_slow (rwlock=rwlock@entry=0x7f80443b0a80 <domain_lock>) at pthread_rwlock_wrlock.c:66
24 Thread 0x7f8040c37700 (LWP 99847) "capnet-controll" __pthread_rwlock_wrlock_slow (rwlock=rwlock@entry=0x7f80443b0a80 <domain_lock>) at pthread_rwlock_wrlock.c:66
23 Thread 0x7f8033fff700 (LWP 99848) "capnet-controll" __pthread_rwlock_wrlock_slow (rwlock=rwlock@entry=0x7f80443b0a80 <domain_lock>) at pthread_rwlock_wrlock.c:66
22 Thread 0x7f80337fe700 (LWP 99851) "capnet-controll" __pthread_rwlock_wrlock_slow (rwlock=rwlock@entry=0x7f80443b0a80 <domain_lock>) at pthread_rwlock_wrlock.c:66
21 Thread 0x7f8032ffd700 (LWP 99870) "capnet-controll" 0x00007f80427f0bed in nanosleep () at ../sysdeps/unix/syscall-template.S:81
20 Thread 0x7f80327fc700 (LWP 99873) "capnet-controll" __pthread_rwlock_wrlock_slow (rwlock=rwlock@entry=0x7f80443b0a80 <domain_lock>) at pthread_rwlock_wrlock.c:66
19 Thread 0x7f8031ffb700 (LWP 99882) "capnet-controll" 0x00007f80427f0bed in nanosleep () at ../sysdeps/unix/syscall-template.S:81
18 Thread 0x7f80317fa700 (LWP 99890) "capnet-controll" __pthread_rwlock_wrlock_slow (rwlock=rwlock@entry=0x7f80443b0a80 <domain_lock>) at pthread_rwlock_wrlock.c:66
17 Thread 0x7f8030ff9700 (LWP 99893) "capnet-controll" __pthread_rwlock_wrlock_slow (rwlock=rwlock@entry=0x7f80443b0a80 <domain_lock>) at pthread_rwlock_wrlock.c:66
16 Thread 0x7f801bfff700 (LWP 99897) "capnet-controll" 0x00007f80427f0bed in nanosleep () at ../sysdeps/unix/syscall-template.S:81
15 Thread 0x7f801b7fe700 (LWP 99905) "capnet-controll" __pthread_rwlock_wrlock_slow (rwlock=rwlock@entry=0x7f80443b0a80 <domain_lock>) at pthread_rwlock_wrlock.c:66
14 Thread 0x7f801affd700 (LWP 99909) "capnet-controll" __pthread_rwlock_wrlock_slow (rwlock=rwlock@entry=0x7f80443b0a80 <domain_lock>) at pthread_rwlock_wrlock.c:66
13 Thread 0x7f801a7fc700 (LWP 99910) "capnet-controll" __pthread_rwlock_wrlock_slow (rwlock=rwlock@entry=0x7f80443b0a80 <domain_lock>) at pthread_rwlock_wrlock.c:66
12 Thread 0x7f8019ffb700 (LWP 99911) "capnet-controll" __pthread_rwlock_wrlock_slow (rwlock=rwlock@entry=0x7f80443b0a80 <domain_lock>) at pthread_rwlock_wrlock.c:66
11 Thread 0x7f80197fa700 (LWP 99912) "capnet-controll" __pthread_rwlock_wrlock_slow (rwlock=rwlock@entry=0x7f80443b0a80 <domain_lock>) at pthread_rwlock_wrlock.c:66
10 Thread 0x7f8018ff9700 (LWP 99913) "capnet-controll" __pthread_rwlock_wrlock_slow (rwlock=rwlock@entry=0x7f80443b0a80 <domain_lock>) at pthread_rwlock_wrlock.c:66
9 Thread 0x7f80187f8700 (LWP 99914) "capnet-controll" __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
8 Thread 0x7f8017ff7700 (LWP 99915) "capnet-controll" 0x00007f80427f0bed in nanosleep () at ../sysdeps/unix/syscall-template.S:81
7 Thread 0x7f80177f6700 (LWP 99919) "capnet-controll" __pthread_rwlock_wrlock_slow (rwlock=rwlock@entry=0x7f80443b0a80 <domain_lock>) at pthread_rwlock_wrlock.c:66
6 Thread 0x7f8016ff5700 (LWP 99920) "capnet-controll" __pthread_rwlock_wrlock_slow (rwlock=rwlock@entry=0x7f80443b0a80 <domain_lock>) at pthread_rwlock_wrlock.c:66
5 Thread 0x7f80167f4700 (LWP 99924) "capnet-controll" __pthread_rwlock_wrlock_slow (rwlock=rwlock@entry=0x7f80443b0a80 <domain_lock>) at pthread_rwlock_wrlock.c:66
4 Thread 0x7f8015ff3700 (LWP 99926) "capnet-controll" __pthread_rwlock_wrlock_slow (rwlock=rwlock@entry=0x7f80443b0a80 <domain_lock>) at pthread_rwlock_wrlock.c:66
3 Thread 0x7f80157f2700 (LWP 99928) "capnet-controll" __pthread_rwlock_wrlock_slow (rwlock=rwlock@entry=0x7f80443b0a80 <domain_lock>) at pthread_rwlock_wrlock.c:66
2 Thread 0x7f8014ff1700 (LWP 99929) "capnet-controll" __pthread_rwlock_wrlock_slow (rwlock=rwlock@entry=0x7f80443b0a80 <domain_lock>) at pthread_rwlock_wrlock.c:66
* 1 Thread 0x7f80447d1700 (LWP 99826) "capnet-controll" __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
(gdb) thr 9
[Switching to thread 9 (Thread 0x7f80187f8700 (LWP 99914))]
#0 __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
135 ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S: No such file or directory.
(gdb) bt
#0 __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
#1 0x00007f8042af9d82 in __GI___pthread_mutex_lock (mutex=mutex@entry=0x1b46f70) at ../nptl/pthread_mutex_lock.c:115
#2 0x00007f80441916b7 in cn_unordered_acquire_port_switch_lock (port=port@entry=0x1b4b8b0, o_sw=o_sw@entry=0x7f80187f7bf0) at ../../capnet/controller/obj.c:354
#3 0x00007f80441919e9 in cn_unordered_acquire_node_switch_lock (node=node@entry=0x1b4ae20, o_port=o_port@entry=0x7f80187f7c78, o_sw=o_sw@entry=0x7f80187f7c88) at ../../capnet/controller/obj.c:386
#4 0x00007f804419df4a in __cnc_domain_setup_node_osmeta_flows (osmetanode=osmetanode@entry=0x1b4ae20, node=node@entry=0x7f7ffc001c00) at ../../capnet/controller/controller.c:1204
#5 0x00007f80441a173d in __cnc_domain_setup_osmeta_flows (cnode=0x7f7ffc001c00, cport=0x1b8cb70, csw=0x1b7d400) at ../../capnet/controller/controller.c:1453
#6 cnc_port_add (sw=sw@entry=0x1b7d380, port=<optimized out>) at ../../capnet/controller/controller.c:1554
#7 0x00007f80441a1c2d in cnc_port_pending_notify (dpid=dpid@entry=67061586170274, port_no=port_no@entry=229) at ../../capnet/controller/controller.c:1619
#8 0x00007f804418f3ba in metadata_file_watcher (arg=0x1b7d400) at ../../capnet/controller/metadata_file.c:419
#9 0x00007f8042af76aa in start_thread (arg=0x7f80187f8700) at pthread_create.c:333
#10 0x00007f804282ce9d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109
(gdb) thr 1
[Switching to thread 1 (Thread 0x7f80447d1700 (LWP 99826))]
#0 __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
135 in ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S
(gdb) bt
#0 __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
#1 0x00007f8042af9d82 in __GI___pthread_mutex_lock (mutex=mutex@entry=0x1b4ae30) at ../nptl/pthread_mutex_lock.c:115
#2 0x00007f80441a05a2 in cnc_switch_lookup_node_by_ipv4 (csw=csw@entry=0x1b46f60, addr=addr@entry=453643274) at ../../capnet/controller/controller.c:527
#3 0x00007f80441a2bf9 in cnc_arp_responder (sw=0x1b46ee0, sw=0x1b46ee0, pkt_len=60, raw=0x1ba1d56 "\377\377\377\377\377\377\372\026>\222\337\310\b\006", buffer_id=<optimized out>, inport=1,
fl=0x1ba1cf6) at ../../capnet/controller/controller.c:1717
#4 cnc_packet_in (sw=0x1b46ee0, fl=0x1ba1cf6, inport=1, buffer_id=<optimized out>, raw=0x1ba1d56 "\377\377\377\377\377\377\372\026>\222\337\310\b\006", pkt_len=60)
at ../../capnet/controller/controller.c:2291
#5 0x00007f8043d2d1eb in c_app_packet_in (hdl=hdl@entry=0x606dc0 <c_app_main_hdl>, ofp_pin=0x1ba1cde) at ../../../openmul/common-libs/mul-lib/./src/mul_app_infra.c:707
#6 0x0000000000403525 in c_app_event_notifier (pkt_arg=<optimized out>, h_arg=<optimized out>) at mul_app_main.c:399
#7 c_app_recv_msg (hdl_arg=0x606dc0 <c_app_main_hdl>, b=0x7ffd9c7838a0) at mul_app_main.c:242
#8 0x00007f8043d13922 in c_socket_read_nonblock_loop (fd=9, arg=arg@entry=0x606dc0 <c_app_main_hdl>, conn=conn@entry=0x606e00 <c_app_main_hdl+64>, rcv_buf_sz=rcv_buf_sz@entry=4096,
proc_msg=proc_msg@entry=0x403400 <c_app_recv_msg>, get_data_len=get_data_len@entry=0x4033c0 <of_get_data_len>, validate_hdr=0x4033d0 <of_hdr_valid>, hdr_sz=8)
at ../../../openmul/common-libs/mul-lib/./src/c_util.c:409
#9 0x0000000000403e28 in c_app_read (fd=<optimized out>, events=<optimized out>, arg=0x606dc0 <c_app_main_hdl>) at mul_app_main.c:256
#10 0x00007f8043f4da0c in event_base_loop () from /usr/lib/x86_64-linux-gnu/libevent-2.0.so.5
#11 0x0000000000402e89 in __main (argv=0x7ffd9c783c18, argc=<optimized out>) at mul_app_main.c:1021
#12 main (argc=15, argv=0x7ffd9c783c18) at mul_app_main.c:1033
(gdb)