Crash in SNAT during reference counter increase

[PlagueCZ]

Program terminated with signal SIGABRT, Aborted.
#0  __pthread_kill_implementation (threadid=<optimized out>, signo=signo@entry=6, no_tid=no_tid@entry=0) at ./nptl/pthread_kill.c:44
44      ./nptl/pthread_kill.c: No such file or directory.
[Current thread is 1 (Thread 0x7faf267026c0 (LWP 16))]
#0  __pthread_kill_implementation (threadid=<optimized out>, signo=signo@entry=6, no_tid=no_tid@entry=0) at ./nptl/pthread_kill.c:44
#1  0x00007faf290dbe9f in __pthread_kill_internal (signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:78
#2  0x00007faf2908cfb2 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
#3  0x00007faf29077472 in __GI_abort () at ./stdlib/abort.c:79
#4  0x00007faf29a09a4d in __rte_panic () from /usr/local/lib/x86_64-linux-gnu/librte_eal.so.24
#5  0x0000564aee2df5d3 in dp_ref_inc (ref=0x1249d94b08) at ../include/dp_refcount.h:36
#6  0x0000564aee2dfb0d in dp_process_ipv4_snat (snat_data=0x1249f49180, port=0x564afe4b4d40, cntrack=0x1249d94a40, df=0x11ea640a80, m=0x11ea640a00) at ../src/nodes/snat_node.c:74
#7  get_next_index (node=0x125a37f540, m=0x11ea640a00) at ../src/nodes/snat_node.c:175
#8  0x0000564aee2e0455 in dp_foreach_graph_packet (get_next_index=0x564aee2df60c <get_next_index>, speculated_node=1, nb_objs=1, objs=0x124833db80, node=0x125a37f540, graph=0x125a367700) at ../include/nodes/common_node.h:45
#9  snat_node_process (graph=0x125a367700, node=0x125a37f540, objs=0x124833db80, nb_objs=1) at ../src/nodes/snat_node.c:248
#10 0x0000564aee39b0d1 in __rte_node_process (node=0x125a37f540, graph=0x125a367700) at /usr/local/include/rte_graph_worker_common.h:186
#11 rte_graph_walk_rtc (graph=0x125a367700) at /usr/local/include/rte_graph_model_rtc.h:42
#12 0x0000564aee39b41d in rte_graph_walk (graph=0x125a367700) at /usr/local/include/rte_graph_worker.h:38
#13 0x0000564aee39b88a in graph_main_loop (arg=0x0) at ../src/dpdk_layer.c:117
#14 0x00007faf29a1e1b6 in eal_thread_loop () from /usr/local/lib/x86_64-linux-gnu/librte_eal.so.24
#15 0x00007faf29a2fe09 in eal_worker_thread_loop () from /usr/local/lib/x86_64-linux-gnu/librte_eal.so.24
#16 0x00007faf290da144 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#17 0x00007faf2915a7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

This has happened multiple times in OSC. Looking at the code, this is caused by improper order of operations in snat_node.c:74

• dp_delete_flow() causes dp_ref_dec() which can possibly go to zero
• counter being zero causes freeing of resources
• a new flow is create to replace the (already deleted) one
• dp_ref_inc() is then called on a freed-up reference

I have created a temporary fix for OSC that simply changes the order to:

• dp_ref_inc()
• dp_delete_flow()
• only then create and replace the flow
• if this creation fails, dp_ref_dec() is needed to revert the previous increase

Now I stand by this order of operations, but I am also aware, that the situation should never happen, as there should always be at least 2 references for a flow. But from a local code review the order simply should be done this way to avoid confusion.

The next question is, why the situation has arisen, because I am simply curing the symptom and not a cause. This is still ongoing in OSC.

I have not yet created a PR because I think this can have better solutions and some discussion is surely needed before doing any big changes.

[PlagueCZ]

Also looking at the code, there is a call to dp_delete_flow() which can fail half-way but returns void and then SNAT will simply overwrite something that is still registered, so that can also be problematic, but I guess it's a separate issue

[PlagueCZ]

While testing my temporary test branch that reorders the reference instructions and adds a log line, while also checking reference memory for validity (i.e. not freed before).
The proper check is not yet deploed, but it will be too.

But already I get crashes in dp_ref_dec() in dp_delete_flow() in dp_process_aged_flows_non_offload()

What is more interesting, that the crash in SNAT is still there, but the reason seems to be memory already beeing freed, i.e.:

2024-11-08T10:23:46.397289066Z stdout F 2024-11-08 10:23:46.392 2(worker) W SERVICE: Conntrack refcount is not 2, value: 0, port_id: 0, aged: 0 [../src/nodes/snat_node.c:68:dp_process_ipv4_snat()]

I will deploy the proper fix tonight and will get back here with the results, I just wanted to note the fact that i's not an "off-by-one error" but a reuse of freed reference.

[PlagueCZ]

A crash happening in commit 4bbcae9 which is OSC branch with increased refcound guards and the change you provided.

Program terminated with signal SIGABRT, Aborted.
#0  0x00007fb930486e3c in internal_signal_restore_set (set=0x5632a120bab3 <graph_main_loop>) at ../sysdeps/unix/sysv/linux/internal-signals.h:89
89      ../sysdeps/unix/sysv/linux/internal-signals.h: No such file or directory.
[Current thread is 1 (Thread 0x7fb92daaf6c0 (LWP 16))]
#0  0x00007fb930486e3c in internal_signal_restore_set (set=0x5632a120bab3 <graph_main_loop>) at ../sysdeps/unix/sysv/linux/internal-signals.h:89
#1  __pthread_kill_implementation (threadid=16, signo=signo@entry=6, no_tid=no_tid@entry=0) at ./nptl/pthread_kill.c:67
#2  0x00007fb930486f1f in __pthread_kill_internal (signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:78
#3  0x00007fb930437fb2 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
#4  0x00007fb930422472 in __GI_abort () at ./stdlib/abort.c:79
#5  0x00007fb930db4a4d in __rte_panic () from /usr/local/lib/x86_64-linux-gnu/librte_eal.so.24
#6  0x00005632a114f604 in dp_ref_inc (ref=0x124ae46608) at ../include/dp_refcount.h:34
#7  0x00005632a114fb8b in dp_process_ipv4_snat (snat_data=0x124a0f2700, port=0x5632d644c910, cntrack=0x124ae46540, df=0x11db050440, m=0x11db0503c0) at ../src/nodes/snat_node.c:74
#8  get_next_index (node=0x125a37f540, m=0x11db0503c0) at ../src/nodes/snat_node.c:175
#9  0x00005632a11504d3 in dp_foreach_graph_packet (get_next_index=0x5632a114f68a <get_next_index>, speculated_node=1, nb_objs=1, objs=0x1248e5c300, node=0x125a37f540, graph=0x125a367700) at ../include/nodes/common_node.h:45
#10 snat_node_process (graph=0x125a367700, node=0x125a37f540, objs=0x1248e5c300, nb_objs=1) at ../src/nodes/snat_node.c:248
#11 0x00005632a120b32c in __rte_node_process (node=0x125a37f540, graph=0x125a367700) at /usr/local/include/rte_graph_worker_common.h:186
#12 rte_graph_walk_rtc (graph=0x125a367700) at /usr/local/include/rte_graph_model_rtc.h:42
#13 0x00005632a120b678 in rte_graph_walk (graph=0x125a367700) at /usr/local/include/rte_graph_worker.h:38
#14 0x00005632a120bae5 in graph_main_loop (arg=0x0) at ../src/dpdk_layer.c:117
#15 0x00007fb930dc91b6 in eal_thread_loop () from /usr/local/lib/x86_64-linux-gnu/librte_eal.so.24
#16 0x00007fb930ddae09 in eal_worker_thread_loop () from /usr/local/lib/x86_64-linux-gnu/librte_eal.so.24
#17 0x00007fb930485144 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:571
#18 0x00007fb9305057dc in __closefrom_fallback (from=0, dirfd_fallback=<optimized out>) at ../sysdeps/unix/sysv/linux/closefrom_fallback.c:43
#19 0x0000000000000000 in ?? ()

I do not have a log for this as I got to it too late, but will try to make it happen again.

[PlagueCZ]

Found the appropriate log
0.log

[PlagueCZ]

In the same commit 4bbcae9 there is also crash in aging-out flows:

Program terminated with signal SIGABRT, Aborted.
#0  0x00007f70529c7e3c in internal_signal_restore_set (set=0x55b74430aab3 <graph_main_loop>) at ../sysdeps/unix/sysv/linux/internal-signals.h:89
89      ../sysdeps/unix/sysv/linux/internal-signals.h: No such file or directory.
[Current thread is 1 (Thread 0x7f704ffee6c0 (LWP 16))]
#0  0x00007f70529c7e3c in internal_signal_restore_set (set=0x55b74430aab3 <graph_main_loop>) at ../sysdeps/unix/sysv/linux/internal-signals.h:89
#1  __pthread_kill_implementation (threadid=16, signo=signo@entry=6, no_tid=no_tid@entry=0) at ./nptl/pthread_kill.c:67
#2  0x00007f70529c7f1f in __pthread_kill_internal (signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:78
#3  0x00007f7052978fb2 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
#4  0x00007f7052963472 in __GI_abort () at ./stdlib/abort.c:79
#5  0x00007f70532f5a4d in __rte_panic () from /usr/local/lib/x86_64-linux-gnu/librte_eal.so.24
#6  0x000055b7442bb3cd in dp_ref_dec (ref=0x1249db5ec8) at ../include/dp_refcount.h:43
#7  0x000055b7442bc18e in dp_delete_flow (key=0x1255eaaf48, flow_val=0x1249db5e00) at ../src/dp_flow.c:232
#8  0x000055b7442bcb43 in dp_process_aged_flows_non_offload () at ../src/dp_flow.c:422
#9  0x000055b74406325b in dp_process_event_flow_aging_msg (m=0x11dc06a240) at ../src/monitoring/dp_event.c:123
#10 0x000055b744075053 in dp_process_event_msg (m=0x11dc06a240) at ../src/monitoring/dp_monitoring.c:22
#11 0x000055b7442333d0 in handle_nongraph_queues () at ../src/nodes/rx_periodic_node.c:48
#12 rx_periodic_node_process (graph=0x125a367700, node=0x125a372600, objs=0x125a323700, nb_objs=0) at ../src/nodes/rx_periodic_node.c:74
#13 0x000055b74430a32c in __rte_node_process (node=0x125a372600, graph=0x125a367700) at /usr/local/include/rte_graph_worker_common.h:186
#14 rte_graph_walk_rtc (graph=0x125a367700) at /usr/local/include/rte_graph_model_rtc.h:42
#15 0x000055b74430a678 in rte_graph_walk (graph=0x125a367700) at /usr/local/include/rte_graph_worker.h:38
#16 0x000055b74430aae5 in graph_main_loop (arg=0x0) at ../src/dpdk_layer.c:117
#17 0x00007f705330a1b6 in eal_thread_loop () from /usr/local/lib/x86_64-linux-gnu/librte_eal.so.24
#18 0x00007f705331be09 in eal_worker_thread_loop () from /usr/local/lib/x86_64-linux-gnu/librte_eal.so.24
#19 0x00007f70529c6144 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:571
#20 0x00007f7052a467dc in __closefrom_fallback (from=0, dirfd_fallback=<optimized out>) at ../sysdeps/unix/sysv/linux/closefrom_fallback.c:43
#21 0x0000000000000000 in ?? ()

so I guess the fix for NAT flow removal did not affect these kinds of errors.

relevant
0.log