[ovs-discuss] A coredump cause by the race condition by handler、upcall and revalidation thread

Zhengjingzhou zhengjingzhou at huawei.com
Wed Nov 21 11:02:07 UTC 2018


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 at entry=0, format=format at entry=0x6b0028 "Invalid ukey transition %d->%d (last transitioned from thread %u at %s)", args=args at 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 at entry=0x7fb995628ea0) at lib/vlog.c:1229
#4  0x000000000057b93a in vlog_abort (function=function at entry=0x6b0d90 <__func__.28159> "transition_ukey_at", line=line at entry=1741, module=module at entry=0x9ac220 <this_module>,
    message=message at 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 at entry=0x7fb97c005120, dst=dst at entry=UKEY_EVICTED, where=where at 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)


-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mail.openvswitch.org/pipermail/ovs-discuss/attachments/20181121/8e2d510e/attachment-0001.html>


More information about the discuss mailing list