We've found a coredump in a daily testcase(ovs2.7.0+dpdk),
After a deep analyze we found it coredumped after a ovs service restart(with
birdges and ports), and the revalidator and upcall threads race at the
ukey_state. However ,it seems hard to reproduce the coredump.We conclude a
possiblity
1. handlerA deals the packet1, prepare to put a flow,wait(lock)
2. handlerB deals another packet2(same mac with packet1), find the device has
been deleted, generate a flow
3. handlerA meet a error(EEXIST, in function flow_put_on_pmd), prepare to
transition ukeystate to evicted(in function handle_upcalls), wait to aquire the
lock
for (i = 0; i < n_ops; i++) {
struct udpif_key *ukey = ops[i].ukey;
if (ukey) {
ovs_mutex_lock(&ukey->mutex);
if (ops[i].dop.error) {
transition_ukey(ukey, UKEY_EVICTED); ///doubt may be here
should add a state condition? as beflow
}
else if (ukey->state < UKEY_OPERATIONAL) {
transition_ukey(ukey, UKEY_OPERATIONAL);
}
4. revalidate thread C transitions the ukeystate to deleted(by expiration or
other deals), releases the ukey lock
5. handlerA accuires the ukey lock(step 3) ,finds the pre state is deleted,
abort
which the stack is
#0 0x00007fba3737f417 in raise () from /usr/lib64/libc.so.6
#1 0x00007fba37380b08 in abort () from /usr/lib64/libc.so.6
#2 0x00000000005746be in ovs_abort_valist (err_no=err_no@entry=0,
format=format@entry=0x6b0028 "Invalid ukey transition %d->%d (last transitioned
from thread %u at %s)", args=args@entry=0x7fb995628ea0)
at lib/util.c:341
#3 0x000000000057b8b0 in vlog_abort_valist (function=<optimized out>,
line=<optimized out>, module_=<optimized out>,
message=0x6b0028 "Invalid ukey transition %d->%d (last transitioned from
thread %u at %s)", args=args@entry=0x7fb995628ea0) at lib/vlog.c:1229
#4 0x000000000057b93a in vlog_abort (function=function@entry=0x6b0d90
<__func__.28159> "transition_ukey_at", line=line@entry=1741,
module=module@entry=0x9ac220 <this_module>,
message=message@entry=0x6b0028 "Invalid ukey transition %d->%d (last
transitioned from thread %u at %s)") at lib/vlog.c:1243
#5 0x000000000049a85d in transition_ukey_at (ukey=ukey@entry=0x7fb97c005120,
dst=dst@entry=UKEY_EVICTED, where=where@entry=0x6b0648
"ofproto/ofproto_dpif_upcall.c:1467")
at ofproto/ofproto_dpif_upcall.c:1739
#6 0x000000000049da45 in handle_upcalls (n_upcalls=64, upcalls=0x7fb99564dc70,
udpif=<optimized out>) at ofproto/ofproto_dpif_upcall.c:1467
#7 recv_upcalls (handler=0x3339f90, handler=0x3339f90) at
ofproto/ofproto_dpif_upcall.c:887
#8 0x000000000049dc7a in udpif_upcall_handler (arg=0x3339f90) at
ofproto/ofproto_dpif_upcall.c:783
#9 0x0000000000546e48 in ovsthread_wrapper (aux_=<optimized out>) at
lib/ovs_thread.c:682
#10 0x00007fba38f97e45 in start_thread () from /usr/lib64/libpthread.so.0
#11 0x00007fba37442afd in clone () from /usr/lib64/libc.so.6
and the relative log
2018-11-10T16:03:10.796061+08:00|warning|ovs-vswitchd[18219]|xlate_report_error[647]|00001|ofproto_dpif_xlate(handler16)|:
received packet on unknown port 1 while processing
udp,in_port=1,vlan_tci=0x0000,dl_src=38:4c:4f:cb:62:5f,dl_dst=38:4c:4f:cb:62:53,nw_src=199.168.1.106,nw_dst=199.168.1.32,nw_tos=0,nw_ecn=0,nw_ttl=64,tp_src=53744,tp_dst=4789
on bridge br-1
2018-11-10T16:03:10.796497+08:00|warning|ovs-vswitchd[18219]|xlate_report_error[647]|00002|ofproto_dpif_xlate(handler16)|:
received packet on unknown port 1 while processing
udp,in_port=1,vlan_tci=0x0000,dl_src=38:4c:4f:cb:62:5f,dl_dst=38:4c:4f:cb:62:53,nw_src=199.168.1.106,nw_dst=199.168.1.32,nw_tos=0,nw_ecn=0,nw_ttl=64,tp_src=53744,tp_dst=4789
on bridge br-1
2018-11-10T16:03:10.796871+08:00|warning|ovs-vswitchd[18219]|xlate_report_error[647]|00001|ofproto_dpif_xlate(handler19)|:
received packet on unknown port 1 while processing
udp,in_port=1,vlan_tci=0x0000,dl_src=38:4c:4f:cb:62:5f,dl_dst=38:4c:4f:cb:62:53,nw_src=199.168.1.106,nw_dst=199.168.1.32,nw_tos=0,nw_ecn=0,nw_ttl=64,tp_src=41088,tp_dst=4789
on bridge br-1
2018-11-10T16:03:10.797261+08:00|info|ovs-vswitchd[18219]|recv_upcalls[848]|00002|ofproto_dpif_upcall(handler19)|:
received packet on unassociated datapath port 5
2018-11-10T16:03:10.797616+08:00|info|ovs-vswitchd[18219]|recv_upcalls[848]|00003|ofproto_dpif_upcall(handler19)|:
received packet on unassociated datapath port 5
2018-11-10T16:03:10.797833+08:00|info|ovs-vswitchd[18219]|recv_upcalls[848]|00004|ofproto_dpif_upcall(handler19)|:
received packet on unassociated datapath port 5
2018-11-10T16:03:10.798202+08:00|info|ovs-vswitchd[18219]|recv_upcalls[848]|00005|ofproto_dpif_upcall(handler19)|:
received packet on unassociated datapath port 5
2018-11-10T16:03:10.798434+08:00|info|ovs-vswitchd[18219]|recv_upcalls[848]|00006|ofproto_dpif_upcall(handler19)|:
received packet on unassociated datapath port 5
2018-11-10T16:03:10.801329+08:00|info|ovs-vswitchd[18219]|revalidate[2473]|00001|ofproto_dpif_upcall(revalidator20)|:
Unexpected ukey transition from state 4 (last transitioned from thread 19 at
ofproto/ofproto_dpif_upcall.c:1467)
2018-11-10T16:03:10.813474+08:00|alert|ovs-vswitchd[18219]|transition_ukey_at[1741]|00003|ofproto_dpif_upcall(handler16)|:
Invalid ukey transition 5->4 (last transitioned from thread 21 at
ofproto/ofproto_dpif_upcall.c:1870)
_______________________________________________
dev mailing list
[email protected]
https://mail.openvswitch.org/mailman/listinfo/ovs-dev
