From patchwork Mon Mar 20 16:19:14 2017 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Paul Blakey X-Patchwork-Id: 741076 Return-Path: X-Original-To: incoming@patchwork.ozlabs.org Delivered-To: patchwork-incoming@bilbo.ozlabs.org Received: from mail.linuxfoundation.org (mail.linuxfoundation.org [140.211.169.12]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by ozlabs.org (Postfix) with ESMTPS id 3vn1Nx41zTz9s1h for ; Tue, 21 Mar 2017 03:19:29 +1100 (AEDT) Authentication-Results: ozlabs.org; dkim=fail reason="signature verification failed" (1024-bit key; unprotected) header.d=Mellanox.com header.i=@Mellanox.com header.b="XE0tF/XE"; dkim-atps=neutral Received: from mail.linux-foundation.org (localhost [127.0.0.1]) by mail.linuxfoundation.org (Postfix) with ESMTP id 7A3B1B64; Mon, 20 Mar 2017 16:19:27 +0000 (UTC) X-Original-To: dev@openvswitch.org Delivered-To: ovs-dev@mail.linuxfoundation.org Received: from smtp1.linuxfoundation.org (smtp1.linux-foundation.org [172.17.192.35]) by mail.linuxfoundation.org (Postfix) with ESMTPS id 77E28B4B for ; Mon, 20 Mar 2017 16:19:26 +0000 (UTC) X-Greylist: whitelisted by SQLgrey-1.7.6 Received: from EUR01-VE1-obe.outbound.protection.outlook.com (mail-ve1eur01on0057.outbound.protection.outlook.com [104.47.1.57]) by smtp1.linuxfoundation.org (Postfix) with ESMTPS id 42A03208 for ; Mon, 20 Mar 2017 16:19:22 +0000 (UTC) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=Mellanox.com; s=selector1; h=From:Date:Subject:Message-ID:Content-Type:MIME-Version; bh=sdwigMT/u11OCmMo1qOzrehONEPzZwKIUp109EDA7Y4=; b=XE0tF/XEEuoS5ubtcipuszPAJ2RBvFd5sL1On+4z70TQF2NETMGbVfLAUeuh0Q6x3XE/AwyKWJtWnw35T3LjQkjp0z2s6lJ0qtQSWLqsyW/ECQceq0ASSRGWYzh+ItIvgHkRiCBy2orRPWNwv6WYBgW94RNXkJjp9uAm6rBrxsw= Authentication-Results: mellanox.com; dkim=none (message not signed) header.d=none; mellanox.com; dmarc=none action=none header.from=mellanox.com; Received: from [10.223.3.152] (193.47.165.251) by VI1PR0501MB2496.eurprd05.prod.outlook.com (10.168.136.135) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384_P384) id 15.1.977.11; Mon, 20 Mar 2017 16:19:18 +0000 References: To: Roi Dayan , Mark Bloch , ovs dev , Joe Stringer From: Paul Blakey X-Forwarded-Message-Id: Message-ID: <1517196b-2d59-95e0-94f6-b1a924f8df3f@mellanox.com> Date: Mon, 20 Mar 2017 18:19:14 +0200 User-Agent: Mozilla/5.0 (Windows NT 10.0; WOW64; rv:45.0) Gecko/20100101 Thunderbird/45.7.1 MIME-Version: 1.0 In-Reply-To: X-Originating-IP: [193.47.165.251] X-ClientProxiedBy: DB6PR0501CA0008.eurprd05.prod.outlook.com (10.172.232.146) To VI1PR0501MB2496.eurprd05.prod.outlook.com (10.168.136.135) X-MS-Office365-Filtering-Correlation-Id: 1a7a9bca-3f7e-47af-4490-08d46facdc6c X-MS-Office365-Filtering-HT: Tenant X-Microsoft-Antispam: UriScan:; BCL:0; PCL:0; RULEID:(22001)(48565401081); SRVR:VI1PR0501MB2496; X-Microsoft-Exchange-Diagnostics: 1; VI1PR0501MB2496; 3:ipoL2A4dt28Eh+vgyiqoi+636YT6GiCMxQ4o4QhbtbSwGTjwMuiMmXXCNVE6RuhTKxG/UIq9rSlIsaH11oksxpatGNVXdJuhAAs2x8GHXXrR0aBp/w92Hf/6Zi/Y65DikGRVxQepRBksLPGk6CNcShP9i/O1YE50JdF7WHvbSp9fTbFCpQlU25crBFMAWs+NezYUwt2ZLz5K8H2D7EhUo15dwH1jVjwEfuvamrr9aOkA6hQJUY+g2kyZIp0JyUX8CVMmtK3UMi62wBbpIQMVGpJszUP7pRdFvA1+FPVHkS4=; 25:9Xtvk2utujHzU9jj1ro366MCihLIA/oJhQVG3qqpSbOVkiyyZFcAZ26Yt8HIeUKwLSUvzhQyUmd5gOTfitxpWXMoweZ4aCE7bXtUJk5sygQfluaPArFP/1Z/CFPGsEp6dMv/OZlutqe0E9oPAQi9HP9DLlTaY8jTO13+A1DrHfb5A+/sONpnNIkyGZYo4oDWQW5e+/xNzocmevVfQ1Eth21POa3GqrHjhDzXKI6zL5gbCKXO+Q1GxIdiL/o6pPtTCzOfoMXZeUF+uob2wxoCUs929vV9w77Kfy9PArWsFguqkkDse0brQIFADfqhzsKzHsVzBAX1jz+acOA4QvtmDDEWICLLKvDfWI+APUNMk8qMC4GXnXaPPhNCAcywNZbqUeDcCOh6Z12/xiYLhdfHZHSwFg4gBdviGCKuqXQGHjWj1vzunTKwXhpNCk6yVhTNU+THjZUu2KBJbinDN+fVCQ== X-Microsoft-Exchange-Diagnostics: 1; VI1PR0501MB2496; 31:2/fWYeUnQO6nUxfJilslGV/x4nqyXl7we3Zt0jKjdixnJwu5bmiGajnYclpPpJPdVZJ1xTq7J9ysl8xZ05ywoKqFMc2Ev3bKiPRa0Wiz4Bc/OYCUURY7Q0lycR5FbVzWnD+unsNfanell3uZirB7ovCWb5nyq2CJOifF6hwWMFfb8ByFwjkTTjjzZskzFMB6osPkC0SulFiOgpShOQkEA6BSkHO+C2jK+Hxu8qW3zb0=; 20:NaaVLyB5ZFh1IAM4Ykgq1Mzu5pu75CRpjnUnZu/JClbNPlUQ2K1NNYuKGcbJQcqAaoZVZJDPXjbituW3LAEsO4cIgKzRRUd8e7Gv+eWLK3Yolm8pMiDedHE2lIyskw+NXspLvqTS4yhq3adn+bsMrxxGxqnDy+akcjMFgJ1ASS2BkBxL+8SNl74PkglR30l+HSMIzWclhyWr7BnUG/VnLCYPWyht53b+Ossyrl2CY14FEIMuBqpjyx8QfMLVrzZqCO/PDx1fTSsLCUAUygnUVlB3YFGTHxgSrYP0PrM8Kt7xlopsE74fsGDoM3xnKeiMzBy4he0BxxyrK30y6Uxf8Bm1m7cX9d+OFP/GvEyVyHKxxyNw/sszfzyzvWtv3iio6SP/rxY14MAm7xp5N1tVj49d7zh7Tr1aix+NiRs0uOPuxGMJS+L5hzuJIoAVkqg7PJRTqf+SjrM8NgLbgbiOLwl4SXaGDMw6jVWlHyjlrX3a6Rik2xhUnjEG6YoOWp/l X-Microsoft-Antispam-PRVS: X-Exchange-Antispam-Report-Test: UriScan:; X-Exchange-Antispam-Report-CFA-Test: BCL:0; PCL:0; RULEID:(6040375)(601004)(2401047)(5005006)(8121501046)(3002001)(10201501046)(6055026)(6041248)(20161123562025)(20161123558025)(20161123560025)(20161123564025)(20161123555025)(6072148); SRVR:VI1PR0501MB2496; BCL:0; PCL:0; RULEID:; SRVR:VI1PR0501MB2496; X-Microsoft-Exchange-Diagnostics: 1; VI1PR0501MB2496; 4:52gBgNufCKDtJ/qCgpUpBE6m+CtcOTkud1H1TxntVLdU4VATbVQc1MJuW2le6mZbIGGXV62Em63CCvlRn+pVXcYQS7LnuiKs7idMffXdCOv1gU3Ecr4KZT3SxmOHhtXHjSetR9KBMJ+Z6IL+vp2a8GkgCmgfCSvvyKXYMmhY68OWGzvcmxXtTiK2qnS4BapN7PQtJR/Ch9sVkBaw+yHPdscbcA0vV77FsXeMVxqGzZQnR4Mg4zZUPI7jTcx0jZkgnkRLHT49l7eJoO1Q72D2gO5PQlVCQCoGy32nHPvty4u0AW4oYegQgV2s1Mhtgxw+IJs5c+XJ/GWqze5+JLLsWZzlEBF9ScYCdZOJoOvJaWfKG7TRy0if6jtupOQfJseHGVUhFqAzuwkQeZXEMVuX+KgYQK4y1OHNc9b96ts+XCC22zNNCf+0/vI6PHcPdd3KYWKJsfhHmUzQ2iOAvo3bKSw4CgQpwvNszxprYfdoYBygIZDx7pgWeg8GLQRzmDh+GPREp3hHr8qM9N/nNdXSR1AGjW203Zft86CfvCsH00mO2IoLi0IamQpgRZqAiopo0b8FcFC1UMiVEAMnb9G+D8KaMB2q5UfAK59ELehBL2PakBBFqgCKIIV8EY6uimU3 X-Forefront-PRVS: 02524402D6 X-Forefront-Antispam-Report: SFV:NSPM; SFS:(10009020)(4630300001)(6049001)(39410400002)(39450400003)(39850400002)(39860400002)(39840400002)(55674003)(53754006)(24454002)(53946003)(77096006)(90366009)(6486002)(42186005)(31686004)(5660300001)(6116002)(25786008)(81166006)(3846002)(53936002)(230700001)(83506001)(8676002)(50466002)(2906002)(64126003)(189998001)(4001350100001)(31696002)(305945005)(575784001)(7736002)(86362001)(4326008)(65956001)(47776003)(53546008)(65826007)(36756003)(6246003)(38730400002)(66066001)(6666003)(229853002)(50986999)(33646002)(2950100002)(76176999)(54356999)(65806001); DIR:OUT; SFP:1101; SCL:1; SRVR:VI1PR0501MB2496; H:[10.223.3.152]; FPR:; SPF:None; MLV:sfv; LANG:en; X-Microsoft-Exchange-Diagnostics: =?windows-1255?Q?1; VI1PR0501MB2496; 23:tzomKfz/bZD01BPFeoM7pGiUFNmOQgiVsGZ?= =?windows-1255?Q?y4SjwZiaL5Ex/WxfDHeXZh1MJmN9ksauyiNk8UZ3QEuTCLHrLyC3V1GX?= =?windows-1255?Q?YrRT+76FsuXQFB21CqdK0FTuG84C9zdQfGdzi0bT8Fp813mcb5EC7RZ/?= =?windows-1255?Q?fOqY1cYw13BEE0puMAjxF4PByb6cJOWULy6vLSn6krF/h0kqVZ6E6wfD?= =?windows-1255?Q?CxfZAt59gZQnSZeOv9Jh7Nr1SUac0A2e2fiiEkeUBfOWCq8DUCvD2LTq?= =?windows-1255?Q?7KBk4UeGx1knNsW0X7o9TLA0+xJ2a7alViWetuVmS7F0zQEpVfVsBAR5?= =?windows-1255?Q?wn2hEVppArFF54wRhbypRag6ikb2Tz5yoqqFQ8Uv0ISjCUEgalfJcXZe?= =?windows-1255?Q?8zgMlhWg93RNTA5Ar9A61cCAv0Os4wzqQRQuxWWZ+rgBXd0inYXm1fG7?= =?windows-1255?Q?SbDDSwM7f21XAOkstoeQjQzwy5xL5QziJ4ctqQj301lhlOXXU/dLfAgb?= =?windows-1255?Q?IluWm7vn/KKv5J7Y755dq550x/pDsuGgFj40vbeTWTbxRPgSx0OkQTZu?= =?windows-1255?Q?zr2+ppOAF8YGDxe+sf6HQIT6XalEd200+l/aVTC4frR8NkcWREnVlzqz?= =?windows-1255?Q?3i6DY9wZGqZNbZe6/785xkrrc7KRNmAxnIta30uiNjFp9vo/ftss60Yd?= =?windows-1255?Q?0jjmnUocjCWDHJKzxHB7+LWMFjuK5/5GN89Jcf/fnouC6QcdfBuwJ9jn?= =?windows-1255?Q?QX67QX9FGZ7k01kINtCdufwiqknxsH5pg7R5jwu8v0hYgt1G1qoMrtw7?= =?windows-1255?Q?L0hpMwIwLdHCJp+EXm9CWErBcnf2Kj4zR8W8QSmrBiaoX2kzT0Ve8YHb?= =?windows-1255?Q?2VRjlc8jMXGBpL4Xka7GsKKUyRd2qFecx/cz3l29GiGatD4w/82uFBFF?= =?windows-1255?Q?YPSH+G02pIVD5Gof/vTiKh+XBGUWndQ6W09kYPggiIVTOXqu4czuJYfE?= =?windows-1255?Q?8kjlG1apYJpPJBpDqaC3DsTKV6lXW3/5lDAo6zR7+GZJiZwJxkfRH7yS?= =?windows-1255?Q?AmCJmNCrlACJJg7AM5RvS3iuJktDh6iSC1G9FuO5gstlirwXRfM4/dF/?= =?windows-1255?Q?wiFqrKe9S7436X67red3HsqIamA4hdzR5Jbts9oMhSly8bUY5B1Zsfoq?= =?windows-1255?Q?rzraqO0cEdRnywdRMu5q1LrgtUxMRSUwT0CBVXgpaf6xNNVnYH5tDEnM?= =?windows-1255?Q?bvW/4IE3hBSYDMnsrHen5+h+OaUppxcKKUo/8DHirtdjcL5pUSHHfpap?= =?windows-1255?Q?EmBlg6tGPH7Fxg0AGSCDQS49g4gi45RuVRsG2KkPlzfuftBn2uS8Tr8V?= =?windows-1255?Q?Wvtt1wuc/dj6kzgHRWMFfyuXTsbw/6MzzGA=3D=3D?= X-Microsoft-Exchange-Diagnostics: 1; VI1PR0501MB2496; 6:B0WqHZ2tgJjFvUMstfwyReR9XUH26DLwvO+QRJMiqvsJKCjq7fMOCH/nz9T2ICBNhd8Eg8xOrxvcCtVBTrX2iW9oLLJH3LjLFUkuW2ydZwTMNH0sx3F2YWdKk4CSUvFuRhDo5zjC8XQ8OAP5nqAgrL0lqBpUuqoVQZq3ZbTigaAIbloYPzXXWUC0DTQ/TnRqvzEMnn7oaGP+hSBIGUQMkKIu4hpEtUi/04/1h8BBqMzWhL4/VPVkFZeW7Rn1oTgTPCuJAocC529XPIkDtJka4pSj1Fa2ZvHbUMFmmdElMZDoVProNnFbBkhtQb9ioXhFVGiwhkzDsbT/Q7rWy6klHNFMAAgY+0Jl5Ppcxuz7rfHjecUSE1fcutcLnmFhQ+SB2rOsBGYBR9D3DhFpRDpbGIBgBxiLKiCAScUc6zsd8os=; 5:8qiL+LleqVXttrRJ0zbrEuGQR5V8Afbus0jE/G0c0qMc1F8tU5R2Jh9WGoj/xfyhzUqjeNvMpmX5M8SKa65KsYhkwJE104/GbUNh2zF+Mcld8FMDn1rkOAoyf5lP/iMfWScJXqHhuizlg5EsQeFWHw==; 24:b+2uNqTOTGAtQvCkYePv8J1HnzrgMbtRj9QJRVAHMPp+ciuaTh7YqkvopDn5PDyZMQdV45G+XK6FGY1Q8/a+owZ9WUf9GGSmLmNKLGJxUJI= SpamDiagnosticOutput: 1:99 SpamDiagnosticMetadata: NSPM X-Microsoft-Exchange-Diagnostics: 1; VI1PR0501MB2496; 7:ZKUS4n4x3/My1HL4UlLOTHinvYhEN5irRo+J2Pu1kJ6YWqCFH7RCrYNN4KFdJviONCey4QeH4kUZJ0vWNcqhW/MRla7Mm7D2KFBtYrM9p5DzbeBNJlAW2JmwOcDgnYL1wR3ICwdPk/CI70XD0LWrWUnfwCvQj343ALIV7Uyl8cIgJsPxHz0XIcgpkYV7sFf3vD6Cj4kzqHLs1TkSU88cYNubYPZ7oOGkSG1ovFiG0XgfeDXcFdal5cMyWosNN30G7K8KNRGEWtqYZ+FjM/umEHOIcZg+PKAcUSmAMQdwSQRjUUeG8qTOkpaBSfhoy0t9aqmIYw3Eyz8fh7s3yscQ1g== X-OriginatorOrg: Mellanox.com X-MS-Exchange-CrossTenant-OriginalArrivalTime: 20 Mar 2017 16:19:18.1066 (UTC) X-MS-Exchange-CrossTenant-FromEntityHeader: Hosted X-MS-Exchange-Transport-CrossTenantHeadersStamped: VI1PR0501MB2496 X-Spam-Status: No, score=-2.0 required=5.0 tests=BAYES_00,DKIM_SIGNED, DKIM_VALID, DKIM_VALID_AU, RCVD_IN_DNSWL_NONE autolearn=ham version=3.3.1 X-Spam-Checker-Version: SpamAssassin 3.3.1 (2010-03-16) on smtp1.linux-foundation.org Subject: Re: [ovs-dev] About a race condition between handle_upcalls and revalidate X-BeenThere: ovs-dev@openvswitch.org X-Mailman-Version: 2.1.12 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Sender: ovs-dev-bounces@openvswitch.org Errors-To: ovs-dev-bounces@openvswitch.org On 19/03/2017 16:28, Paul Blakey wrote: > Hi all, > > While using out patches for HW offload we've noticed we get a ovs > assertion at transition ukey, which tries to > transition the ukey state from EVICTED back to OPERATIONAL. > With furthur investigation it seem that this can happen without our HW > offload patches as there might be a race between handle_upcalls and > revalidate. > > The procedure is as such: > > handle_upcalls receives a new upcall and creates a new ukey, its state > is VISIBLE, it then it installs a flow (FLOW_PUT) to the datapat and > upon success wants to set the ukey state to OPERATIONAL (line 1408). for > that the handler running handle_upcalls wants to reaquirce the ukey > lock, but in the meantime revalidators dump (line 2261) the already > inserted flow and want to delete this flow (line 2328, say because of > openflow db changes, or aging). The revalidator deletes the flow and > moves the ukey from > VISIBLE -> OPERATIONAL (line 2320) -> EVICTING (line 2220) -> EVICTED > (line 2134) > > finally handler succesfuly acquires the flow and now set the state to > OPERERTIONAL which will cause the assert in transition_ukey. > > Line numbers in question are from ofproto/ofproto-dpif-upcall.c > > I can provide a test the could show this happening, basicly adding a > sleep before (writing it now). > > Thanks, > Paul Blakey. > > > New test patch below, To reproduce run this bash script: ########## START OF SCRIPT ############################### #setup: veth0 <-> veth1 <-> OVS <-> veth2@ns0 <-> veth3@ns0 # VM1_IP VM2_IP VM1_IP=77.77.77.7 VM2_IP=77.77.77.8 echo "deleting bridges (if ovs is running)" ovs-vsctl list-br | xargs -r -l ovs-vsctl del-br echo "deleting namespace" ip netns del ns0 &> /dev/null ip netns add ns0 echo "setup veth0-3" ip link del veth0 &> /dev/null ip link del veth1 &> /dev/null ip link del veth2 &> /dev/null ip link del veth3 &> /dev/null ip link add veth0 type veth peer name veth1 ip link add veth2 type veth peer name veth3 echo "setup remote vm(veth3) $VM2_IP in namespace" ip link set veth3 netns ns0 ip netns exec ns0 ifconfig veth3 $VM2_IP/24 up echo "setup local vm(veth0) $VM1_IP" ifconfig veth0 $VM1_IP/24 up ifconfig veth1 up ifconfig veth2 up echo "restart ovs and delete bridges (if ovs wasn't running)" systemctl restart openvswitch sleep 2 ovs-vsctl list-br | xargs -r -l ovs-vsctl del-br ovs-vsctl set Open_vSwitch . other_config:max-idle=250 ovs-vsctl set Open_vSwitch . other_config:n-handler-threads=1 ovs-vsctl set Open_vSwitch . other_config:n-revalidator-threads=5 echo "setup ovs with veth" ovs-vsctl add-br brv-1 ovs-vsctl add-port brv-1 veth1 ovs-vsctl add-port brv-1 veth2 echo "pinging remote VM $VM2_IP" ping $VM2_IP -i 2 ##################END OF BASH SCRIPT################ and follow ovs-vswitchd.log Here is the ovs-vswitchd.log I get: 2017-03-20T16:01:20.322Z|00001|vlog|INFO|opened log file /var/log/openvswitch/ovs-vswitchd.log 2017-03-20T16:01:20.327Z|00002|ovs_numa|INFO|Discovered 16 CPU cores on NUMA node 0 2017-03-20T16:01:20.327Z|00003|ovs_numa|INFO|Discovered 16 CPU cores on NUMA node 1 2017-03-20T16:01:20.327Z|00004|ovs_numa|INFO|Discovered 2 NUMA nodes and 32 CPU cores 2017-03-20T16:01:20.327Z|00005|reconnect|INFO|unix:/var/run/openvswitch/db.sock: connecting... 2017-03-20T16:01:20.327Z|00006|reconnect|INFO|unix:/var/run/openvswitch/db.sock: connected 2017-03-20T16:01:20.334Z|00007|ofproto_dpif|INFO|system@ovs-system: Datapath supports recirculation 2017-03-20T16:01:20.334Z|00008|ofproto_dpif|INFO|system@ovs-system: MPLS label stack length probed as 1 2017-03-20T16:01:20.334Z|00009|ofproto_dpif|INFO|system@ovs-system: Datapath supports truncate action 2017-03-20T16:01:20.335Z|00010|ofproto_dpif|INFO|system@ovs-system: Datapath supports unique flow ids 2017-03-20T16:01:20.335Z|00011|ofproto_dpif|INFO|system@ovs-system: Datapath does not support clone action 2017-03-20T16:01:20.335Z|00012|ofproto_dpif|INFO|system@ovs-system: Max sample nesting level probed as 3 2017-03-20T16:01:20.335Z|00013|ofproto_dpif|INFO|system@ovs-system: Datapath supports ct_state 2017-03-20T16:01:20.335Z|00014|ofproto_dpif|INFO|system@ovs-system: Datapath supports ct_zone 2017-03-20T16:01:20.335Z|00015|ofproto_dpif|INFO|system@ovs-system: Datapath supports ct_mark 2017-03-20T16:01:20.335Z|00016|ofproto_dpif|INFO|system@ovs-system: Datapath supports ct_label 2017-03-20T16:01:20.335Z|00017|ofproto_dpif|INFO|system@ovs-system: Datapath supports ct_state_nat 2017-03-20T16:01:20.335Z|00018|ofproto_dpif|INFO|system@ovs-system: Datapath supports ct_orig_tuple 2017-03-20T16:01:20.366Z|00001|ofproto_dpif_upcall(handler1)|INFO|received packet on unassociated datapath port 0 2017-03-20T16:01:20.367Z|00019|bridge|INFO|bridge brv-1: added interface brv-1 on port 65534 2017-03-20T16:01:20.373Z|00020|bridge|INFO|bridge brv-1: added interface veth2 on port 2 2017-03-20T16:01:20.379Z|00021|bridge|INFO|bridge brv-1: added interface veth1 on port 1 2017-03-20T16:01:20.380Z|00022|bridge|INFO|bridge brv-1: using datapath ID 00005a7f2804ff4f 2017-03-20T16:01:20.380Z|00023|connmgr|INFO|brv-1: added service controller "punix:/var/run/openvswitch/brv-1.mgmt" 2017-03-20T16:01:20.397Z|00024|bridge|INFO|ovs-vswitchd (Open vSwitch) 2.7.90 2017-03-20T16:01:20.903Z|00001|ofproto_dpif_upcall(handler8)|INFO|ukey_install__ 1679 state transition for ukey ufid:1591b637-55f9-4479-941e-7a44062b0a7e: CREATED -> VISIBLE 2017-03-20T16:01:20.903Z|00002|ofproto_dpif_upcall(handler8)|INFO|put count: 1 2017-03-20T16:01:20.903Z|00003|ofproto_dpif_upcall(handler8)|INFO|handle_upcalls 1423 state transition for ukey ufid:1591b637-55f9-4479-941e-7a44062b0a7e: VISIBLE -> OPERATIONAL 2017-03-20T16:01:21.031Z|00004|ofproto_dpif_upcall(handler8)|INFO|ukey_install__ 1679 state transition for ukey ufid:2c4a95de-c670-4301-ac4e-d3b32483894e: CREATED -> VISIBLE 2017-03-20T16:01:21.031Z|00005|ofproto_dpif_upcall(handler8)|INFO|ukey_install__ 1679 state transition for ukey ufid:72131844-bada-4d2a-bb84-75e5f7a031c6: CREATED -> VISIBLE 2017-03-20T16:01:21.031Z|00006|ofproto_dpif_upcall(handler8)|INFO|put count: 2 2017-03-20T16:01:21.031Z|00007|ofproto_dpif_upcall(handler8)|INFO|handle_upcalls 1423 state transition for ukey ufid:2c4a95de-c670-4301-ac4e-d3b32483894e: VISIBLE -> OPERATIONAL 2017-03-20T16:01:21.031Z|00008|ofproto_dpif_upcall(handler8)|INFO|put count: 3 2017-03-20T16:01:21.031Z|00009|ofproto_dpif_upcall(handler8)|INFO|handle_upcalls 1423 state transition for ukey ufid:72131844-bada-4d2a-bb84-75e5f7a031c6: VISIBLE -> OPERATIONAL 2017-03-20T16:01:21.155Z|00001|ofproto_dpif_upcall(revalidator9)|INFO|revalidate 2345 state transition for ukey ufid:1591b637-55f9-4479-941e-7a44062b0a7e: OPERATIONAL -> OPERATIONAL 2017-03-20T16:01:21.155Z|00002|ofproto_dpif_upcall(revalidator9)|INFO|reval_op_init 2245 state transition for ukey ufid:1591b637-55f9-4479-941e-7a44062b0a7e: OPERATIONAL -> EVICTING 2017-03-20T16:01:21.155Z|00003|ofproto_dpif_upcall(revalidator9)|INFO|revalidate 2345 state transition for ukey ufid:2c4a95de-c670-4301-ac4e-d3b32483894e: OPERATIONAL -> OPERATIONAL 2017-03-20T16:01:21.155Z|00004|ofproto_dpif_upcall(revalidator9)|INFO|revalidate 2345 state transition for ukey ufid:72131844-bada-4d2a-bb84-75e5f7a031c6: OPERATIONAL -> OPERATIONAL 2017-03-20T16:01:21.155Z|00005|ofproto_dpif_upcall(revalidator9)|INFO|push_dp_ops 2159 state transition for ukey ufid:1591b637-55f9-4479-941e-7a44062b0a7e: EVICTING -> EVICTED 2017-03-20T16:01:21.156Z|00001|ofproto_dpif_upcall(revalidator13)|INFO|ukey_delete 1825 state transition for ukey ufid:1591b637-55f9-4479-941e-7a44062b0a7e: EVICTED -> DELETED 2017-03-20T16:01:21.406Z|00006|ofproto_dpif_upcall(revalidator9)|INFO|revalidate 2345 state transition for ukey ufid:2c4a95de-c670-4301-ac4e-d3b32483894e: OPERATIONAL -> OPERATIONAL 2017-03-20T16:01:21.406Z|00007|ofproto_dpif_upcall(revalidator9)|INFO|reval_op_init 2245 state transition for ukey ufid:2c4a95de-c670-4301-ac4e-d3b32483894e: OPERATIONAL -> EVICTING 2017-03-20T16:01:21.406Z|00008|ofproto_dpif_upcall(revalidator9)|INFO|revalidate 2345 state transition for ukey ufid:72131844-bada-4d2a-bb84-75e5f7a031c6: OPERATIONAL -> OPERATIONAL 2017-03-20T16:01:21.406Z|00009|ofproto_dpif_upcall(revalidator9)|INFO|reval_op_init 2245 state transition for ukey ufid:72131844-bada-4d2a-bb84-75e5f7a031c6: OPERATIONAL -> EVICTING 2017-03-20T16:01:21.406Z|00010|ofproto_dpif_upcall(revalidator9)|INFO|push_dp_ops 2159 state transition for ukey ufid:2c4a95de-c670-4301-ac4e-d3b32483894e: EVICTING -> EVICTED 2017-03-20T16:01:21.406Z|00011|ofproto_dpif_upcall(revalidator9)|INFO|push_dp_ops 2159 state transition for ukey ufid:72131844-bada-4d2a-bb84-75e5f7a031c6: EVICTING -> EVICTED 2017-03-20T16:01:21.406Z|00001|ofproto_dpif_upcall(revalidator10)|INFO|ukey_delete 1825 state transition for ukey ufid:2c4a95de-c670-4301-ac4e-d3b32483894e: EVICTED -> DELETED 2017-03-20T16:01:21.406Z|00001|ofproto_dpif_upcall(revalidator12)|INFO|ukey_delete 1825 state transition for ukey ufid:72131844-bada-4d2a-bb84-75e5f7a031c6: EVICTED -> DELETED 2017-03-20T16:01:21.927Z|00010|ofproto_dpif_upcall(handler8)|INFO|ukey_install__ 1679 state transition for ukey ufid:87e128d2-8182-4488-9af2-d65b81402180: CREATED -> VISIBLE 2017-03-20T16:01:21.927Z|00011|ofproto_dpif_upcall(handler8)|INFO|ukey_install__ 1679 state transition for ukey ufid:f04759b5-22b6-4328-94a0-ee6654016a18: CREATED -> VISIBLE 2017-03-20T16:01:21.927Z|00012|ofproto_dpif_upcall(handler8)|INFO|put count: 4 2017-03-20T16:01:21.927Z|00013|ofproto_dpif_upcall(handler8)|INFO|handle_upcalls 1423 state transition for ukey ufid:87e128d2-8182-4488-9af2-d65b81402180: VISIBLE -> OPERATIONAL 2017-03-20T16:01:21.927Z|00014|ofproto_dpif_upcall(handler8)|INFO|put count: 5 2017-03-20T16:01:21.927Z|00015|ofproto_dpif_upcall(handler8)|INFO|handle_upcalls 1423 state transition for ukey ufid:f04759b5-22b6-4328-94a0-ee6654016a18: VISIBLE -> OPERATIONAL 2017-03-20T16:01:22.055Z|00016|ofproto_dpif_upcall(handler8)|INFO|ukey_install__ 1679 state transition for ukey ufid:b82a17b0-a9bf-449f-b6a2-3634a7b811b5: CREATED -> VISIBLE 2017-03-20T16:01:22.055Z|00017|ofproto_dpif_upcall(handler8)|INFO|ukey_install__ 1679 state transition for ukey ufid:2701af7d-8094-4229-838e-070838c79df4: CREATED -> VISIBLE 2017-03-20T16:01:22.055Z|00018|ofproto_dpif_upcall(handler8)|INFO|put count: 6 2017-03-20T16:01:22.055Z|00019|ofproto_dpif_upcall(handler8)|INFO|handle_upcalls 1423 state transition for ukey ufid:b82a17b0-a9bf-449f-b6a2-3634a7b811b5: VISIBLE -> OPERATIONAL 2017-03-20T16:01:22.055Z|00020|ofproto_dpif_upcall(handler8)|INFO|put count: 7 2017-03-20T16:01:22.055Z|00021|ofproto_dpif_upcall(handler8)|INFO|handle_upcalls 1423 state transition for ukey ufid:2701af7d-8094-4229-838e-070838c79df4: VISIBLE -> OPERATIONAL 2017-03-20T16:01:22.158Z|00025|ofproto_dpif_upcall|INFO|reval_op_init 2245 state transition for ukey ufid:2701af7d-8094-4229-838e-070838c79df4: OPERATIONAL -> EVICTING 2017-03-20T16:01:22.158Z|00026|ofproto_dpif_upcall|INFO|push_dp_ops 2159 state transition for ukey ufid:2701af7d-8094-4229-838e-070838c79df4: EVICTING -> EVICTED 2017-03-20T16:01:22.158Z|00027|ofproto_dpif_upcall|INFO|ukey_delete 1825 state transition for ukey ufid:2701af7d-8094-4229-838e-070838c79df4: EVICTED -> DELETED 2017-03-20T16:01:22.158Z|00028|ofproto_dpif_upcall|INFO|reval_op_init 2245 state transition for ukey ufid:f04759b5-22b6-4328-94a0-ee6654016a18: OPERATIONAL -> EVICTING 2017-03-20T16:01:22.158Z|00029|ofproto_dpif_upcall|INFO|push_dp_ops 2159 state transition for ukey ufid:f04759b5-22b6-4328-94a0-ee6654016a18: EVICTING -> EVICTED 2017-03-20T16:01:22.158Z|00030|ofproto_dpif_upcall|INFO|ukey_delete 1825 state transition for ukey ufid:f04759b5-22b6-4328-94a0-ee6654016a18: EVICTED -> DELETED 2017-03-20T16:01:22.158Z|00031|ofproto_dpif_upcall|INFO|reval_op_init 2245 state transition for ukey ufid:87e128d2-8182-4488-9af2-d65b81402180: OPERATIONAL -> EVICTING 2017-03-20T16:01:22.158Z|00032|ofproto_dpif_upcall|INFO|push_dp_ops 2159 state transition for ukey ufid:87e128d2-8182-4488-9af2-d65b81402180: EVICTING -> EVICTED 2017-03-20T16:01:22.158Z|00033|ofproto_dpif_upcall|INFO|ukey_delete 1825 state transition for ukey ufid:87e128d2-8182-4488-9af2-d65b81402180: EVICTED -> DELETED 2017-03-20T16:01:22.158Z|00034|ofproto_dpif_upcall|INFO|reval_op_init 2245 state transition for ukey ufid:b82a17b0-a9bf-449f-b6a2-3634a7b811b5: OPERATIONAL -> EVICTING 2017-03-20T16:01:22.158Z|00035|ofproto_dpif_upcall|INFO|push_dp_ops 2159 state transition for ukey ufid:b82a17b0-a9bf-449f-b6a2-3634a7b811b5: EVICTING -> EVICTED 2017-03-20T16:01:22.158Z|00036|ofproto_dpif_upcall|INFO|ukey_delete 1825 state transition for ukey ufid:b82a17b0-a9bf-449f-b6a2-3634a7b811b5: EVICTED -> DELETED 2017-03-20T16:01:22.268Z|00037|ofproto_dpif|INFO|system@ovs-system: Datapath supports recirculation 2017-03-20T16:01:22.268Z|00038|ofproto_dpif|INFO|system@ovs-system: MPLS label stack length probed as 1 2017-03-20T16:01:22.268Z|00039|ofproto_dpif|INFO|system@ovs-system: Datapath supports truncate action 2017-03-20T16:01:22.268Z|00040|ofproto_dpif|INFO|system@ovs-system: Datapath supports unique flow ids 2017-03-20T16:01:22.269Z|00041|ofproto_dpif|INFO|system@ovs-system: Datapath does not support clone action 2017-03-20T16:01:22.269Z|00042|ofproto_dpif|INFO|system@ovs-system: Max sample nesting level probed as 3 2017-03-20T16:01:22.269Z|00043|ofproto_dpif|INFO|system@ovs-system: Datapath supports ct_state 2017-03-20T16:01:22.269Z|00044|ofproto_dpif|INFO|system@ovs-system: Datapath supports ct_zone 2017-03-20T16:01:22.269Z|00045|ofproto_dpif|INFO|system@ovs-system: Datapath supports ct_mark 2017-03-20T16:01:22.269Z|00046|ofproto_dpif|INFO|system@ovs-system: Datapath supports ct_label 2017-03-20T16:01:22.269Z|00047|ofproto_dpif|INFO|system@ovs-system: Datapath supports ct_state_nat 2017-03-20T16:01:22.269Z|00048|ofproto_dpif|INFO|system@ovs-system: Datapath supports ct_orig_tuple 2017-03-20T16:01:22.280Z|00001|ofproto_dpif_upcall(handler26)|INFO|received packet on unassociated datapath port 0 2017-03-20T16:01:22.290Z|00049|bridge|INFO|bridge brv-1: added interface brv-1 on port 65534 2017-03-20T16:01:22.290Z|00050|bridge|INFO|bridge brv-1: using datapath ID 00003ed7a2298140 2017-03-20T16:01:22.290Z|00051|connmgr|INFO|brv-1: added service controller "punix:/var/run/openvswitch/brv-1.mgmt" 2017-03-20T16:01:22.325Z|00052|bridge|INFO|bridge brv-1: added interface veth1 on port 1 2017-03-20T16:01:22.345Z|00053|bridge|INFO|bridge brv-1: added interface veth2 on port 2 2017-03-20T16:01:22.352Z|00001|ofproto_dpif_upcall(handler32)|INFO|ukey_install__ 1679 state transition for ukey ufid:0e45d246-f6c6-4b00-9e30-408643192b46: CREATED -> VISIBLE 2017-03-20T16:01:22.352Z|00002|ofproto_dpif_upcall(handler32)|INFO|put count: 8 2017-03-20T16:01:22.352Z|00003|ofproto_dpif_upcall(handler32)|INFO|handle_upcalls 1423 state transition for ukey ufid:0e45d246-f6c6-4b00-9e30-408643192b46: VISIBLE -> OPERATIONAL 2017-03-20T16:01:22.352Z|00004|ofproto_dpif_upcall(handler32)|INFO|ukey_install__ 1679 state transition for ukey ufid:2ac65ff6-17a1-446e-be0a-6cf852981ee8: CREATED -> VISIBLE 2017-03-20T16:01:22.352Z|00005|ofproto_dpif_upcall(handler32)|INFO|put count: 9 2017-03-20T16:01:22.352Z|00006|ofproto_dpif_upcall(handler32)|INFO|handle_upcalls 1423 state transition for ukey ufid:2ac65ff6-17a1-446e-be0a-6cf852981ee8: VISIBLE -> OPERATIONAL 2017-03-20T16:01:22.352Z|00007|ofproto_dpif_upcall(handler32)|INFO|ukey_install__ 1679 state transition for ukey ufid:13818e08-c773-4716-b8c6-59d1e781770f: CREATED -> VISIBLE 2017-03-20T16:01:22.353Z|00008|ofproto_dpif_upcall(handler32)|INFO|put count: 10 2017-03-20T16:01:22.353Z|00009|ofproto_dpif_upcall(handler32)|INFO|handle_upcalls 1423 state transition for ukey ufid:13818e08-c773-4716-b8c6-59d1e781770f: VISIBLE -> OPERATIONAL 2017-03-20T16:01:22.353Z|00010|ofproto_dpif_upcall(handler32)|INFO|ukey_install__ 1679 state transition for ukey ufid:7871e4ec-7302-464a-80f5-efaec2e72cbe: CREATED -> VISIBLE 2017-03-20T16:01:22.353Z|00011|ofproto_dpif_upcall(handler32)|INFO|put count: 11 2017-03-20T16:01:22.353Z|00012|ofproto_dpif_upcall(handler32)|INFO|handle_upcalls 1423 state transition for ukey ufid:7871e4ec-7302-464a-80f5-efaec2e72cbe: VISIBLE -> OPERATIONAL 2017-03-20T16:01:22.358Z|00001|ofproto_dpif_upcall(revalidator33)|INFO|revalidate 2345 state transition for ukey ufid:0e45d246-f6c6-4b00-9e30-408643192b46: OPERATIONAL -> OPERATIONAL 2017-03-20T16:01:22.358Z|00002|ofproto_dpif_upcall(revalidator33)|INFO|revalidate 2345 state transition for ukey ufid:2ac65ff6-17a1-446e-be0a-6cf852981ee8: OPERATIONAL -> OPERATIONAL 2017-03-20T16:01:22.358Z|00003|ofproto_dpif_upcall(revalidator33)|INFO|revalidate 2345 state transition for ukey ufid:7871e4ec-7302-464a-80f5-efaec2e72cbe: OPERATIONAL -> OPERATIONAL 2017-03-20T16:01:22.358Z|00004|ofproto_dpif_upcall(revalidator33)|INFO|revalidate 2345 state transition for ukey ufid:13818e08-c773-4716-b8c6-59d1e781770f: OPERATIONAL -> OPERATIONAL 2017-03-20T16:01:22.608Z|00001|ofproto_dpif_upcall(revalidator35)|INFO|revalidate 2345 state transition for ukey ufid:0e45d246-f6c6-4b00-9e30-408643192b46: OPERATIONAL -> OPERATIONAL 2017-03-20T16:01:22.608Z|00002|ofproto_dpif_upcall(revalidator35)|INFO|reval_op_init 2245 state transition for ukey ufid:0e45d246-f6c6-4b00-9e30-408643192b46: OPERATIONAL -> EVICTING 2017-03-20T16:01:22.608Z|00003|ofproto_dpif_upcall(revalidator35)|INFO|revalidate 2345 state transition for ukey ufid:2ac65ff6-17a1-446e-be0a-6cf852981ee8: OPERATIONAL -> OPERATIONAL 2017-03-20T16:01:22.608Z|00004|ofproto_dpif_upcall(revalidator35)|INFO|reval_op_init 2245 state transition for ukey ufid:2ac65ff6-17a1-446e-be0a-6cf852981ee8: OPERATIONAL -> EVICTING 2017-03-20T16:01:22.608Z|00005|ofproto_dpif_upcall(revalidator35)|INFO|revalidate 2345 state transition for ukey ufid:7871e4ec-7302-464a-80f5-efaec2e72cbe: OPERATIONAL -> OPERATIONAL 2017-03-20T16:01:22.608Z|00006|ofproto_dpif_upcall(revalidator35)|INFO|reval_op_init 2245 state transition for ukey ufid:7871e4ec-7302-464a-80f5-efaec2e72cbe: OPERATIONAL -> EVICTING 2017-03-20T16:01:22.608Z|00007|ofproto_dpif_upcall(revalidator35)|INFO|revalidate 2345 state transition for ukey ufid:13818e08-c773-4716-b8c6-59d1e781770f: OPERATIONAL -> OPERATIONAL 2017-03-20T16:01:22.608Z|00008|ofproto_dpif_upcall(revalidator35)|INFO|reval_op_init 2245 state transition for ukey ufid:13818e08-c773-4716-b8c6-59d1e781770f: OPERATIONAL -> EVICTING 2017-03-20T16:01:22.608Z|00009|ofproto_dpif_upcall(revalidator35)|INFO|push_dp_ops 2159 state transition for ukey ufid:0e45d246-f6c6-4b00-9e30-408643192b46: EVICTING -> EVICTED 2017-03-20T16:01:22.608Z|00010|ofproto_dpif_upcall(revalidator35)|INFO|push_dp_ops 2159 state transition for ukey ufid:2ac65ff6-17a1-446e-be0a-6cf852981ee8: EVICTING -> EVICTED 2017-03-20T16:01:22.608Z|00011|ofproto_dpif_upcall(revalidator35)|INFO|push_dp_ops 2159 state transition for ukey ufid:7871e4ec-7302-464a-80f5-efaec2e72cbe: EVICTING -> EVICTED 2017-03-20T16:01:22.608Z|00012|ofproto_dpif_upcall(revalidator35)|INFO|push_dp_ops 2159 state transition for ukey ufid:13818e08-c773-4716-b8c6-59d1e781770f: EVICTING -> EVICTED 2017-03-20T16:01:22.608Z|00001|ofproto_dpif_upcall(revalidator36)|INFO|ukey_delete 1825 state transition for ukey ufid:13818e08-c773-4716-b8c6-59d1e781770f: EVICTED -> DELETED 2017-03-20T16:01:22.608Z|00002|ofproto_dpif_upcall(revalidator36)|INFO|ukey_delete 1825 state transition for ukey ufid:2ac65ff6-17a1-446e-be0a-6cf852981ee8: EVICTED -> DELETED 2017-03-20T16:01:22.608Z|00001|ofproto_dpif_upcall(revalidator37)|INFO|ukey_delete 1825 state transition for ukey ufid:0e45d246-f6c6-4b00-9e30-408643192b46: EVICTED -> DELETED 2017-03-20T16:01:22.609Z|00005|ofproto_dpif_upcall(revalidator33)|INFO|ukey_delete 1825 state transition for ukey ufid:7871e4ec-7302-464a-80f5-efaec2e72cbe: EVICTED -> DELETED 2017-03-20T16:01:22.951Z|00013|ofproto_dpif_upcall(handler32)|INFO|ukey_install__ 1679 state transition for ukey ufid:9009f598-48ca-4db1-aabc-8c6e5f25a648: CREATED -> VISIBLE 2017-03-20T16:01:22.951Z|00014|ofproto_dpif_upcall(handler32)|INFO|put count: 12 2017-03-20T16:01:22.951Z|00015|ofproto_dpif_upcall(handler32)|INFO|handle_upcalls 1423 state transition for ukey ufid:9009f598-48ca-4db1-aabc-8c6e5f25a648: VISIBLE -> OPERATIONAL 2017-03-20T16:01:23.359Z|00006|ofproto_dpif_upcall(revalidator33)|INFO|revalidate 2345 state transition for ukey ufid:9009f598-48ca-4db1-aabc-8c6e5f25a648: OPERATIONAL -> OPERATIONAL 2017-03-20T16:01:23.359Z|00007|ofproto_dpif_upcall(revalidator33)|INFO|reval_op_init 2245 state transition for ukey ufid:9009f598-48ca-4db1-aabc-8c6e5f25a648: OPERATIONAL -> EVICTING 2017-03-20T16:01:23.359Z|00008|ofproto_dpif_upcall(revalidator33)|INFO|push_dp_ops 2159 state transition for ukey ufid:9009f598-48ca-4db1-aabc-8c6e5f25a648: EVICTING -> EVICTED 2017-03-20T16:01:23.360Z|00002|ofproto_dpif_upcall(revalidator37)|INFO|ukey_delete 1825 state transition for ukey ufid:9009f598-48ca-4db1-aabc-8c6e5f25a648: EVICTED -> DELETED 2017-03-20T16:01:24.354Z|00016|ofproto_dpif_upcall(handler32)|INFO|ukey_install__ 1679 state transition for ukey ufid:13818e08-c773-4716-b8c6-59d1e781770f: CREATED -> VISIBLE 2017-03-20T16:01:24.354Z|00017|ofproto_dpif_upcall(handler32)|INFO|put count: 13 2017-03-20T16:01:24.354Z|00018|ofproto_dpif_upcall(handler32)|INFO|handle_upcalls 1423 state transition for ukey ufid:13818e08-c773-4716-b8c6-59d1e781770f: VISIBLE -> OPERATIONAL 2017-03-20T16:01:24.354Z|00019|ofproto_dpif_upcall(handler32)|INFO|ukey_install__ 1679 state transition for ukey ufid:7871e4ec-7302-464a-80f5-efaec2e72cbe: CREATED -> VISIBLE 2017-03-20T16:01:24.354Z|00020|ofproto_dpif_upcall(handler32)|INFO|put count: 14 2017-03-20T16:01:24.354Z|00021|ofproto_dpif_upcall(handler32)|INFO|handle_upcalls 1423 state transition for ukey ufid:7871e4ec-7302-464a-80f5-efaec2e72cbe: VISIBLE -> OPERATIONAL 2017-03-20T16:01:24.612Z|00009|ofproto_dpif_upcall(revalidator33)|INFO|revalidate 2345 state transition for ukey ufid:7871e4ec-7302-464a-80f5-efaec2e72cbe: OPERATIONAL -> OPERATIONAL 2017-03-20T16:01:24.612Z|00010|ofproto_dpif_upcall(revalidator33)|INFO|reval_op_init 2245 state transition for ukey ufid:7871e4ec-7302-464a-80f5-efaec2e72cbe: OPERATIONAL -> EVICTING 2017-03-20T16:01:24.612Z|00011|ofproto_dpif_upcall(revalidator33)|INFO|revalidate 2345 state transition for ukey ufid:13818e08-c773-4716-b8c6-59d1e781770f: OPERATIONAL -> OPERATIONAL 2017-03-20T16:01:24.612Z|00012|ofproto_dpif_upcall(revalidator33)|INFO|reval_op_init 2245 state transition for ukey ufid:13818e08-c773-4716-b8c6-59d1e781770f: OPERATIONAL -> EVICTING 2017-03-20T16:01:24.612Z|00013|ofproto_dpif_upcall(revalidator33)|INFO|push_dp_ops 2159 state transition for ukey ufid:7871e4ec-7302-464a-80f5-efaec2e72cbe: EVICTING -> EVICTED 2017-03-20T16:01:24.612Z|00014|ofproto_dpif_upcall(revalidator33)|INFO|push_dp_ops 2159 state transition for ukey ufid:13818e08-c773-4716-b8c6-59d1e781770f: EVICTING -> EVICTED 2017-03-20T16:01:24.612Z|00003|ofproto_dpif_upcall(revalidator36)|INFO|ukey_delete 1825 state transition for ukey ufid:13818e08-c773-4716-b8c6-59d1e781770f: EVICTED -> DELETED 2017-03-20T16:01:24.612Z|00015|ofproto_dpif_upcall(revalidator33)|INFO|ukey_delete 1825 state transition for ukey ufid:7871e4ec-7302-464a-80f5-efaec2e72cbe: EVICTED -> DELETED 2017-03-20T16:01:25.575Z|00022|ofproto_dpif_upcall(handler32)|INFO|ukey_install__ 1679 state transition for ukey ufid:c59ccbff-eae6-4bed-82a5-89766add0fa1: CREATED -> VISIBLE 2017-03-20T16:01:25.575Z|00023|ofproto_dpif_upcall(handler32)|INFO|put count: 15 2017-03-20T16:01:25.575Z|00024|ofproto_dpif_upcall(handler32)|INFO|handle_upcalls 1423 state transition for ukey ufid:c59ccbff-eae6-4bed-82a5-89766add0fa1: VISIBLE -> OPERATIONAL 2017-03-20T16:01:25.864Z|00016|ofproto_dpif_upcall(revalidator33)|INFO|revalidate 2345 state transition for ukey ufid:c59ccbff-eae6-4bed-82a5-89766add0fa1: OPERATIONAL -> OPERATIONAL 2017-03-20T16:01:25.864Z|00017|ofproto_dpif_upcall(revalidator33)|INFO|reval_op_init 2245 state transition for ukey ufid:c59ccbff-eae6-4bed-82a5-89766add0fa1: OPERATIONAL -> EVICTING 2017-03-20T16:01:25.864Z|00018|ofproto_dpif_upcall(revalidator33)|INFO|push_dp_ops 2159 state transition for ukey ufid:c59ccbff-eae6-4bed-82a5-89766add0fa1: EVICTING -> EVICTED 2017-03-20T16:01:25.865Z|00004|ofproto_dpif_upcall(revalidator36)|INFO|ukey_delete 1825 state transition for ukey ufid:c59ccbff-eae6-4bed-82a5-89766add0fa1: EVICTED -> DELETED 2017-03-20T16:01:26.407Z|00025|ofproto_dpif_upcall(handler32)|INFO|ukey_install__ 1679 state transition for ukey ufid:13818e08-c773-4716-b8c6-59d1e781770f: CREATED -> VISIBLE 2017-03-20T16:01:26.407Z|00026|ofproto_dpif_upcall(handler32)|INFO|put count: 16 2017-03-20T16:01:26.407Z|00027|ofproto_dpif_upcall(handler32)|INFO|handle_upcalls 1423 state transition for ukey ufid:13818e08-c773-4716-b8c6-59d1e781770f: VISIBLE -> OPERATIONAL 2017-03-20T16:01:26.407Z|00028|ofproto_dpif_upcall(handler32)|INFO|ukey_install__ 1679 state transition for ukey ufid:7871e4ec-7302-464a-80f5-efaec2e72cbe: CREATED -> VISIBLE 2017-03-20T16:01:26.407Z|00029|ofproto_dpif_upcall(handler32)|INFO|put count: 17 2017-03-20T16:01:26.407Z|00030|ofproto_dpif_upcall(handler32)|INFO|handle_upcalls 1423 state transition for ukey ufid:7871e4ec-7302-464a-80f5-efaec2e72cbe: VISIBLE -> OPERATIONAL 2017-03-20T16:01:26.471Z|00031|ofproto_dpif_upcall(handler32)|INFO|ukey_install__ 1679 state transition for ukey ufid:b1d1717c-9523-4916-83d2-7e7da8e6b7bd: CREATED -> VISIBLE 2017-03-20T16:01:26.471Z|00032|ofproto_dpif_upcall(handler32)|INFO|put count: 18 2017-03-20T16:01:26.471Z|00033|ofproto_dpif_upcall(handler32)|INFO|handle_upcalls 1423 state transition for ukey ufid:b1d1717c-9523-4916-83d2-7e7da8e6b7bd: VISIBLE -> OPERATIONAL 2017-03-20T16:01:26.864Z|00019|ofproto_dpif_upcall(revalidator33)|INFO|revalidate 2345 state transition for ukey ufid:7871e4ec-7302-464a-80f5-efaec2e72cbe: OPERATIONAL -> OPERATIONAL 2017-03-20T16:01:26.864Z|00020|ofproto_dpif_upcall(revalidator33)|INFO|reval_op_init 2245 state transition for ukey ufid:7871e4ec-7302-464a-80f5-efaec2e72cbe: OPERATIONAL -> EVICTING 2017-03-20T16:01:26.864Z|00021|ofproto_dpif_upcall(revalidator33)|INFO|revalidate 2345 state transition for ukey ufid:13818e08-c773-4716-b8c6-59d1e781770f: OPERATIONAL -> OPERATIONAL 2017-03-20T16:01:26.864Z|00022|ofproto_dpif_upcall(revalidator33)|INFO|reval_op_init 2245 state transition for ukey ufid:13818e08-c773-4716-b8c6-59d1e781770f: OPERATIONAL -> EVICTING 2017-03-20T16:01:26.864Z|00023|ofproto_dpif_upcall(revalidator33)|INFO|revalidate 2345 state transition for ukey ufid:b1d1717c-9523-4916-83d2-7e7da8e6b7bd: OPERATIONAL -> OPERATIONAL 2017-03-20T16:01:26.864Z|00024|ofproto_dpif_upcall(revalidator33)|INFO|reval_op_init 2245 state transition for ukey ufid:b1d1717c-9523-4916-83d2-7e7da8e6b7bd: OPERATIONAL -> EVICTING 2017-03-20T16:01:26.864Z|00025|ofproto_dpif_upcall(revalidator33)|INFO|push_dp_ops 2159 state transition for ukey ufid:7871e4ec-7302-464a-80f5-efaec2e72cbe: EVICTING -> EVICTED 2017-03-20T16:01:26.864Z|00026|ofproto_dpif_upcall(revalidator33)|INFO|push_dp_ops 2159 state transition for ukey ufid:13818e08-c773-4716-b8c6-59d1e781770f: EVICTING -> EVICTED 2017-03-20T16:01:26.864Z|00027|ofproto_dpif_upcall(revalidator33)|INFO|push_dp_ops 2159 state transition for ukey ufid:b1d1717c-9523-4916-83d2-7e7da8e6b7bd: EVICTING -> EVICTED 2017-03-20T16:01:26.864Z|00005|ofproto_dpif_upcall(revalidator36)|INFO|ukey_delete 1825 state transition for ukey ufid:13818e08-c773-4716-b8c6-59d1e781770f: EVICTED -> DELETED 2017-03-20T16:01:26.865Z|00028|ofproto_dpif_upcall(revalidator33)|INFO|ukey_delete 1825 state transition for ukey ufid:7871e4ec-7302-464a-80f5-efaec2e72cbe: EVICTED -> DELETED 2017-03-20T16:01:26.865Z|00006|ofproto_dpif_upcall(revalidator36)|INFO|ukey_delete 1825 state transition for ukey ufid:b1d1717c-9523-4916-83d2-7e7da8e6b7bd: EVICTED -> DELETED 2017-03-20T16:01:27.495Z|00034|ofproto_dpif_upcall(handler32)|INFO|ukey_install__ 1679 state transition for ukey ufid:0e2a07df-cffd-46df-92aa-dd9f6baeae10: CREATED -> VISIBLE 2017-03-20T16:01:27.495Z|00035|ofproto_dpif_upcall(handler32)|INFO|put count: 19 2017-03-20T16:01:27.495Z|00036|ofproto_dpif_upcall(handler32)|INFO|handle_upcalls 1423 state transition for ukey ufid:0e2a07df-cffd-46df-92aa-dd9f6baeae10: VISIBLE -> OPERATIONAL 2017-03-20T16:01:27.495Z|00037|ofproto_dpif_upcall(handler32)|INFO|ukey_install__ 1679 state transition for ukey ufid:e6cc74a9-bbdf-4d5d-a014-fec814f406c6: CREATED -> VISIBLE 2017-03-20T16:01:27.495Z|00038|ofproto_dpif_upcall(handler32)|INFO|put count: 20 2017-03-20T16:01:27.495Z|00039|ofproto_dpif_upcall(handler32)|INFO|handle_upcalls 1414 sleeping 1/5 sec, ukey state: 1 2017-03-20T16:01:27.864Z|00029|ofproto_dpif_upcall(revalidator33)|INFO|revalidate 2345 state transition for ukey ufid:0e2a07df-cffd-46df-92aa-dd9f6baeae10: OPERATIONAL -> OPERATIONAL 2017-03-20T16:01:27.864Z|00030|ofproto_dpif_upcall(revalidator33)|INFO|reval_op_init 2245 state transition for ukey ufid:0e2a07df-cffd-46df-92aa-dd9f6baeae10: OPERATIONAL -> EVICTING 2017-03-20T16:01:27.864Z|00031|ofproto_dpif_upcall(revalidator33)|INFO|revalidate 2345 state transition for ukey ufid:e6cc74a9-bbdf-4d5d-a014-fec814f406c6: VISIBLE -> OPERATIONAL 2017-03-20T16:01:27.864Z|00032|ofproto_dpif_upcall(revalidator33)|INFO|reval_op_init 2245 state transition for ukey ufid:e6cc74a9-bbdf-4d5d-a014-fec814f406c6: OPERATIONAL -> EVICTING 2017-03-20T16:01:27.864Z|00033|ofproto_dpif_upcall(revalidator33)|INFO|push_dp_ops 2159 state transition for ukey ufid:0e2a07df-cffd-46df-92aa-dd9f6baeae10: EVICTING -> EVICTED 2017-03-20T16:01:27.864Z|00034|ofproto_dpif_upcall(revalidator33)|INFO|push_dp_ops 2159 state transition for ukey ufid:e6cc74a9-bbdf-4d5d-a014-fec814f406c6: EVICTING -> EVICTED 2017-03-20T16:01:27.864Z|00007|ofproto_dpif_upcall(revalidator36)|INFO|sleeping 2017-03-20T16:01:27.864Z|00013|ofproto_dpif_upcall(revalidator35)|INFO|sleeping 2017-03-20T16:01:28.495Z|00040|ofproto_dpif_upcall(handler32)|INFO|handle_upcalls 1414 sleeping 2/5 sec, ukey state: 4 2017-03-20T16:01:29.496Z|00041|ofproto_dpif_upcall(handler32)|INFO|handle_upcalls 1414 sleeping 3/5 sec, ukey state: 4 2017-03-20T16:01:30.401Z|00054|memory|INFO|69400 kB peak resident set size after 10.1 seconds 2017-03-20T16:01:30.401Z|00055|memory|INFO|handlers:1 ports:3 revalidators:5 rules:5 udpif keys:2 2017-03-20T16:01:30.496Z|00042|ofproto_dpif_upcall(handler32)|INFO|handle_upcalls 1414 sleeping 4/5 sec, ukey state: 4 2017-03-20T16:01:31.496Z|00043|ofproto_dpif_upcall(handler32)|INFO|handle_upcalls 1414 sleeping 5/5 sec, ukey state: 4 2017-03-20T16:01:32.496Z|00044|ofproto_dpif_upcall(handler32)|INFO|handle_upcalls 1423 state transition for ukey ufid:e6cc74a9-bbdf-4d5d-a014-fec814f406c6: EVICTED -> OPERATIONAL 2017-03-20T16:01:32.496Z|00045|util(handler32)|EMER|ofproto/ofproto-dpif-upcall.c:1699: assertion dst >= ukey->state failed in transition_ukey() ##################END OF LOG ################ From df02c4f769566ce6a8ebb8f228c9f3262c618395 Mon Sep 17 00:00:00 2001 From: Paul Blakey Date: Sun, 19 Mar 2017 17:00:30 +0200 Subject: [PATCH] test Change-Id: Iac752eb5fab3ff49da30a35bab3bee12673e1e28 --- ofproto/ofproto-dpif-upcall.c | 55 +++++++++++++++++++++++++++++++++---------- 1 file changed, 43 insertions(+), 12 deletions(-) static struct udpif_key *ukey_lookup(struct udpif *udpif, const ovs_u128 *ufid, @@ -1399,15 +1401,30 @@ handle_upcalls(struct udpif *udpif, struct upcall *upcalls, dpif_operate(udpif->dpif, opsp, n_opsp); for (i = 0; i < n_ops; i++) { struct udpif_key *ukey = ops[i].ukey; + static int count = 0; + const int sleep_time = 5; + const int sleep_every_n_flows = 20; if (ukey) { + count++; + VLOG_INFO("put count: %d", count); + if ((count % sleep_every_n_flows) == 0) { + global_temp = 1; + for (int z = 0; z < sleep_time; z++) { + VLOG_INFO("%s %d sleeping %d/%d sec, ukey state: %d", __func__, __LINE__, z+1, sleep_time, ukey->state); + xsleep(1); + } + } + ovs_mutex_lock(&ukey->mutex); if (ops[i].dop.error) { - transition_ukey(ukey, UKEY_EVICTED); + transition_ukey(__func__, __LINE__, ukey, UKEY_EVICTED); } else { - transition_ukey(ukey, UKEY_OPERATIONAL); + transition_ukey(__func__, __LINE__, ukey, UKEY_OPERATIONAL); } ovs_mutex_unlock(&ukey->mutex); + + global_temp = 0; } } } @@ -1605,8 +1622,8 @@ try_ukey_replace(struct umap *umap, struct udpif_key *old_ukey, cmap_replace(&umap->cmap, &old_ukey->cmap_node, &new_ukey->cmap_node, new_ukey->hash); ovsrcu_postpone(ukey_delete__, old_ukey); - transition_ukey(old_ukey, UKEY_DELETED); - transition_ukey(new_ukey, UKEY_VISIBLE); + transition_ukey(__func__, __LINE__, old_ukey, UKEY_DELETED); + transition_ukey(__func__, __LINE__, new_ukey, UKEY_VISIBLE); replaced = true; } ovs_mutex_unlock(&old_ukey->mutex); @@ -1659,7 +1676,7 @@ ukey_install__(struct udpif *udpif, struct udpif_key *new_ukey) } else { ovs_mutex_lock(&new_ukey->mutex); cmap_insert(&umap->cmap, &new_ukey->cmap_node, new_ukey->hash); - transition_ukey(new_ukey, UKEY_VISIBLE); + transition_ukey(__func__, __LINE__, new_ukey, UKEY_VISIBLE); locked = true; } ovs_mutex_unlock(&umap->mutex); @@ -1667,10 +1684,18 @@ ukey_install__(struct udpif *udpif, struct udpif_key *new_ukey) return locked; } +char *state_to_str[] = { "CREATED", "VISIBLE", "OPERATIONAL", "EVICTING", "EVICTED", "DELETED" }; + static void -transition_ukey(struct udpif_key *ukey, enum ukey_state dst) +transition_ukey(const char *func, int line, struct udpif_key *ukey, enum ukey_state dst) OVS_REQUIRES(ukey->mutex) { + struct ds ds2 = DS_EMPTY_INITIALIZER; + + odp_format_ufid(&ukey->ufid, &ds2); + VLOG_INFO("%s %d state transition for ukey %s: %s -> %s", func, line, ds_cstr(&ds2), state_to_str[ukey->state], state_to_str[dst]); + ds_destroy(&ds2); + ovs_assert(dst >= ukey->state); if (ukey->state == dst && dst == UKEY_OPERATIONAL) { return; @@ -1797,7 +1822,7 @@ ukey_delete(struct umap *umap, struct udpif_key *ukey) if (ukey->state < UKEY_DELETED) { cmap_remove(&umap->cmap, &ukey->cmap_node, ukey->hash); ovsrcu_postpone(ukey_delete__, ukey); - transition_ukey(ukey, UKEY_DELETED); + transition_ukey(__func__, __LINE__, ukey, UKEY_DELETED); } ovs_mutex_unlock(&ukey->mutex); } @@ -2131,7 +2156,7 @@ push_dp_ops(struct udpif *udpif, struct ukey_op *ops, size_t n_ops) if (op->ukey) { ovs_mutex_lock(&op->ukey->mutex); - transition_ukey(op->ukey, UKEY_EVICTED); + transition_ukey(__func__, __LINE__, op->ukey, UKEY_EVICTED); push->used = MAX(stats->used, op->ukey->stats.used); push->tcp_flags = stats->tcp_flags | op->ukey->stats.tcp_flags; push->n_packets = stats->n_packets - op->ukey->stats.n_packets; @@ -2217,7 +2242,7 @@ reval_op_init(struct ukey_op *op, enum reval_result result, { if (result == UKEY_DELETE) { delete_op_init(udpif, op, ukey); - transition_ukey(ukey, UKEY_EVICTING); + transition_ukey(__func__, __LINE__, ukey, UKEY_EVICTING); } else if (result == UKEY_MODIFY) { /* Store the new recircs. */ recirc_refs_swap(&ukey->recircs, recircs); @@ -2317,7 +2342,7 @@ revalidate(struct revalidator *revalidator) } /* The flow is now confirmed to be in the datapath. */ - transition_ukey(ukey, UKEY_OPERATIONAL); + transition_ukey(__func__, __LINE__, ukey, UKEY_OPERATIONAL); if (!used) { used = ukey->created; @@ -2417,6 +2442,12 @@ revalidator_sweep__(struct revalidator *revalidator, bool purge) ovs_mutex_unlock(&ukey->mutex); if (ukey_state == UKEY_EVICTED) { + + while (global_temp) { + VLOG_INFO("sleeping\n"); + xsleep(5); + } + /* The common flow deletion case involves deletion of the flow * during the dump phase and ukey deletion here. */ ovs_mutex_lock(&umap->mutex); @@ -2471,7 +2502,7 @@ dp_purge_cb(void *aux, unsigned pmd_id) CMAP_FOR_EACH(ukey, cmap_node, &umap->cmap) { if (ukey->pmd_id == pmd_id) { delete_op_init(udpif, &ops[n_ops++], ukey); - transition_ukey(ukey, UKEY_EVICTING); + transition_ukey(__func__, __LINE__, ukey, UKEY_EVICTING); if (n_ops == REVALIDATE_MAX_BATCH) { push_ukey_ops(udpif, umap, ops, n_ops); -- 1.8.4.3 diff --git a/ofproto/ofproto-dpif-upcall.c b/ofproto/ofproto-dpif-upcall.c index 660383f..3291219 100644 --- a/ofproto/ofproto-dpif-upcall.c +++ b/ofproto/ofproto-dpif-upcall.c @@ -45,6 +45,8 @@ #define UPCALL_MAX_BATCH 64 #define REVALIDATE_MAX_BATCH 50 +int global_temp = 0; + VLOG_DEFINE_THIS_MODULE(ofproto_dpif_upcall); COVERAGE_DEFINE(dumped_duplicate_flow); @@ -350,7 +352,7 @@ static void ukey_get_actions(struct udpif_key *, const struct nlattr **actions, static bool ukey_install__(struct udpif *, struct udpif_key *ukey) OVS_TRY_LOCK(true, ukey->mutex); static bool ukey_install(struct udpif *udpif, struct udpif_key *ukey); -static void transition_ukey(struct udpif_key *ukey, enum ukey_state dst) +static void transition_ukey(const char *func, int line, struct udpif_key *ukey, enum ukey_state dst) OVS_REQUIRES(ukey->mutex);