From patchwork Tue Sep 29 18:17:15 2015 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Ben Pfaff X-Patchwork-Id: 523979 Return-Path: X-Original-To: incoming@patchwork.ozlabs.org Delivered-To: patchwork-incoming@bilbo.ozlabs.org Received: from archives.nicira.com (unknown [IPv6:2600:3c00::f03c:91ff:fe6e:bdf7]) by ozlabs.org (Postfix) with ESMTP id 5D3DE140157 for ; Wed, 30 Sep 2015 04:17:42 +1000 (AEST) Received: from archives.nicira.com (localhost [127.0.0.1]) by archives.nicira.com (Postfix) with ESMTP id 4D01A10685; Tue, 29 Sep 2015 11:17:35 -0700 (PDT) X-Original-To: dev@openvswitch.org Delivered-To: dev@openvswitch.org Received: from mx3v1.cudamail.com (mx3.cudamail.com [64.34.241.5]) by archives.nicira.com (Postfix) with ESMTPS id 1826910678 for ; Tue, 29 Sep 2015 11:17:34 -0700 (PDT) Received: from bar3.cudamail.com (bar1 [192.168.15.1]) by mx3v1.cudamail.com (Postfix) with ESMTP id 83EDC61848E for ; Tue, 29 Sep 2015 12:17:33 -0600 (MDT) X-ASG-Debug-ID: 1443550652-03dd7b37df48550001-byXFYA Received: from mx3-pf1.cudamail.com ([192.168.14.2]) by bar3.cudamail.com with ESMTP id BZ3J1i2CBtz8Uhxo (version=TLSv1 cipher=DHE-RSA-AES256-SHA bits=256 verify=NO) for ; Tue, 29 Sep 2015 12:17:32 -0600 (MDT) X-Barracuda-Envelope-From: blp@nicira.com X-Barracuda-RBL-Trusted-Forwarder: 192.168.14.2 Received: from unknown (HELO mail-pa0-f52.google.com) (209.85.220.52) by mx3-pf1.cudamail.com with ESMTPS (RC4-SHA encrypted); 29 Sep 2015 18:17:32 -0000 Received-SPF: unknown (mx3-pf1.cudamail.com: Multiple SPF records returned) X-Barracuda-RBL-Trusted-Forwarder: 209.85.220.52 Received: by pablk4 with SMTP id lk4so12641118pab.3 for ; Tue, 29 Sep 2015 11:17:29 -0700 (PDT) X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20130820; h=x-gm-message-state:from:to:cc:subject:date:message-id:in-reply-to :references; bh=XkmsrvZz2mXHlomupVp2JQgHAWnECV/YS5WTDiSLjWA=; b=D10gsXhPojKmZg7524s4TXcphUPd+v1dWzvcs0s3XmGIvegMFyMFKjiEbmExIWDMVg Djh+znDb6IREUmrWirf+bnBxuUHc+P4IRELhU0CEO/uoFPSzmR5YR9Z+T4VXnztQWpcn BiHsd+zWsDjuE1ursFM+E/xG7NT0D3QZgZfOaOJ2kKcYA27Cx6UotIb5EnfXLeKKr5uB qyd8EYAmhmvXE3GeSutVJ+KRvkVIyIZXVbbiUHIgeK4rct3BiOSiy6AuXZ2bnbM79r1x LV2gbpUqiKZVxsFMLJIgVgCbgI0zXbgeNhZp/B9jPbsuZqY2UoXEOffTvlY09330y9J/ MadQ== X-Gm-Message-State: ALoCoQnwmObfmU6nyIoIjQp+pqZdDSpmMuIc7CYYFRm1Pdkxchkrn/pphs+rmd3GWc2rQzIdVja6 X-Received: by 10.66.190.6 with SMTP id gm6mr34565569pac.27.1443550649408; Tue, 29 Sep 2015 11:17:29 -0700 (PDT) Received: from sigabrt.benpfaff.org ([208.91.2.4]) by smtp.gmail.com with ESMTPSA id vw7sm26982027pab.15.2015.09.29.11.17.27 (version=TLS1_2 cipher=ECDHE-RSA-AES128-SHA bits=128/128); Tue, 29 Sep 2015 11:17:28 -0700 (PDT) X-CudaMail-Envelope-Sender: blp@nicira.com X-Barracuda-Apparent-Source-IP: 208.91.2.4 From: Ben Pfaff To: dev@openvswitch.org X-CudaMail-Whitelist-To: dev@openvswitch.org X-CudaMail-MID: CM-V1-928053600 X-CudaMail-DTE: 092915 X-CudaMail-Originating-IP: 209.85.220.52 Date: Tue, 29 Sep 2015 11:17:15 -0700 X-ASG-Orig-Subj: [##CM-V1-928053600##][PATCH repost 3/3] tests: Make parse_listening_port entirely reliable. Message-Id: <1443550635-29312-3-git-send-email-blp@nicira.com> X-Mailer: git-send-email 2.1.3 In-Reply-To: <1443550635-29312-1-git-send-email-blp@nicira.com> References: <1443550635-29312-1-git-send-email-blp@nicira.com> X-Barracuda-Connect: UNKNOWN[192.168.14.2] X-Barracuda-Start-Time: 1443550652 X-Barracuda-Encrypted: DHE-RSA-AES256-SHA X-Barracuda-URL: https://web.cudamail.com:443/cgi-mod/mark.cgi X-ASG-Whitelist: Header =?UTF-8?B?eFwtY3VkYW1haWxcLXdoaXRlbGlzdFwtdG8=?= X-Barracuda-BRTS-Status: 1 X-Virus-Scanned: by bsmtpd at cudamail.com Cc: Ben Pfaff Subject: [ovs-dev] [PATCH repost 3/3] tests: Make parse_listening_port entirely reliable. X-BeenThere: dev@openvswitch.org X-Mailman-Version: 2.1.16 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , MIME-Version: 1.0 Errors-To: dev-bounces@openvswitch.org Sender: "dev" In test runs, I've occasionally seen mysterious failures in which parse_listening_port failed to find the listening port even though an examination of the log file showed that it was there. I spent some time trying to figure out what was going wrong. It seemed like everything was lined up properly to ensure that a command like "ovs-vsctl set-controller br0 tcp:127.0.0.1:0" would only return to the command prompt after the new listener was ready and the proper log message was written. It was obviously a very small race because I could only reproduce it with a large test parallelism (e.g. -j10 on my quad-core laptop). The problem turned out to be asynchronous logging in ovs-vswitchd. If I turned that off, by commenting out the call to vlog_enable_async() in bridge.c, parse_listening_port became reliable. This commit works around the problem by making parse_listening_port retry for a while if necessary. It also transforms the shell function into an m4 macro (so that it can use OVS_WAIT_UNTIL) and renames it to all-uppercase to follow the convention for macros. Signed-off-by: Ben Pfaff Acked-by: Flavio Leitner --- tests/ofproto-dpif.at | 16 ++++++++-------- tests/ofproto-macros.at | 21 +++++++++++---------- tests/ovs-vsctl.at | 4 ++-- tests/ovsdb-idl.at | 4 ++-- tests/ovsdb-server.at | 12 ++++++------ 5 files changed, 29 insertions(+), 28 deletions(-) diff --git a/tests/ofproto-dpif.at b/tests/ofproto-dpif.at index 9609d2d..918ff2f 100644 --- a/tests/ofproto-dpif.at +++ b/tests/ofproto-dpif.at @@ -4736,7 +4736,7 @@ m4_define([CHECK_SFLOW_SAMPLING_PACKET], on_exit 'kill `cat test-sflow.pid`' AT_CHECK([ovstest test-sflow --log-file --detach --no-chdir --pidfile 0:$1 > sflow.log], [0], [], [ignore]) AT_CAPTURE_FILE([sflow.log]) - SFLOW_PORT=`parse_listening_port < test-sflow.log` + PARSE_LISTENING_PORT([test-sflow.log], [SFLOW_PORT]) ovs-appctl time/stop ADD_OF_PORTS([br0], 1, 2) @@ -5079,7 +5079,7 @@ OVS_VSWITCHD_START([dnl on_exit 'kill `cat test-sflow.pid`' AT_CHECK([ovstest test-sflow --log-file --detach --no-chdir --pidfile 0:127.0.0.1 > sflow.log], [0], [], [ignore]) AT_CAPTURE_FILE([sflow.log]) -SFLOW_PORT=`parse_listening_port < test-sflow.log` +PARSE_LISTENING_PORT([test-sflow.log], [SFLOW_PORT]) ovs-appctl time/stop @@ -5123,7 +5123,7 @@ OVS_VSWITCHD_START([set Bridge br0 fail-mode=standalone]) dnl set up sFlow logging AT_CHECK([ovstest test-sflow --log-file --detach --no-chdir --pidfile 0:127.0.0.1 > sflow.log], [0], [], [ignore]) AT_CAPTURE_FILE([sflow.log]) -SFLOW_PORT=`parse_listening_port < test-sflow.log` +PARSE_LISTENING_PORT([test-sflow.log], [SFLOW_PORT]) ovs-appctl time/stop OVS_VSWITCHD_DISABLE_TUNNEL_PUSH_POP @@ -5193,7 +5193,7 @@ OVS_VSWITCHD_START([add-port br0 p0 -- set Interface p0 type=dummy ofport_reques dnl set up sFlow logging AT_CHECK([ovstest test-sflow --log-file --detach --no-chdir --pidfile 0:127.0.0.1 > sflow.log], [0], [], [ignore]) AT_CAPTURE_FILE([sflow.log]) -SFLOW_PORT=`parse_listening_port < test-sflow.log` +PARSE_LISTENING_PORT([test-sflow.log], [SFLOW_PORT]) ovs-appctl time/stop AT_CHECK([ovs-appctl vlog/set dpif:dbg dpif_netdev:dbg]) @@ -5297,7 +5297,7 @@ AT_CHECK([ovs-ofctl add-flows br0 flows.txt]) dnl set up sFlow logging AT_CHECK([ovstest test-sflow --log-file --detach --no-chdir --pidfile 0:127.0.0.1 > sflow.log], [0], [], [ignore]) AT_CAPTURE_FILE([sflow.log]) -SFLOW_PORT=`parse_listening_port < test-sflow.log` +PARSE_LISTENING_PORT([test-sflow.log], [SFLOW_PORT]) ovs-appctl time/stop dnl configure sflow @@ -5391,7 +5391,7 @@ m4_define([CHECK_NETFLOW_EXPIRATION], on_exit 'kill `cat test-netflow.pid`' AT_CHECK([ovstest test-netflow --log-file --detach --no-chdir --pidfile 0:$1 > netflow.log], [0], [], [ignore]) AT_CAPTURE_FILE([netflow.log]) - NETFLOW_PORT=`parse_listening_port < test-netflow.log` + PARSE_LISTENING_PORT([test-netflow.log], [NETFLOW_PORT]) ovs-vsctl \ set Bridge br0 netflow=@nf -- \ @@ -5438,7 +5438,7 @@ m4_define([CHECK_NETFLOW_ACTIVE_EXPIRATION], on_exit 'kill `cat test-netflow.pid`' AT_CHECK([ovstest test-netflow --log-file --detach --no-chdir --pidfile 0:$1 > netflow.log], [0], [], [ignore]) AT_CAPTURE_FILE([netflow.log]) - NETFLOW_PORT=`parse_listening_port < test-netflow.log` + PARSE_LISTENING_PORT([test-netflow.log], [NETFLOW_PORT]) ovs-vsctl \ set Bridge br0 netflow=@nf -- \ @@ -6153,7 +6153,7 @@ m4_define([CHECK_MEGAFLOW_NETFLOW], on_exit 'kill `cat test-netflow.pid`' AT_CHECK([ovstest test-netflow --log-file --detach --no-chdir --pidfile 0:$1 > netflow.log], [0], [], [ignore]) AT_CAPTURE_FILE([netflow.log]) - NETFLOW_PORT=`parse_listening_port < test-netflow.log` + PARSE_LISTENING_PORT([test-netflow.log], [NETFLOW_PORT]) ovs-vsctl \ set Bridge br0 netflow=@nf -- \ --id=@nf create NetFlow targets=\"$1:$NETFLOW_PORT\" \ diff --git a/tests/ofproto-macros.at b/tests/ofproto-macros.at index da9990c..fd2f4b2 100644 --- a/tests/ofproto-macros.at +++ b/tests/ofproto-macros.at @@ -31,23 +31,24 @@ s/tcp:127.0.0.1:[0-9][0-9]*:/unix:/ s/No error/Success/ ' } +] +m4_divert_pop([PREPARE_TESTS]) -# parse_listening_port [SERVER] +# PARSE_LISTENING_PORT LOGFILE VARIABLE # -# Parses the TCP or SSL port on which a server is listening from the -# log, given that the server was told to listen on a kernel-chosen -# port, file provided on stdin, and prints the port number on stdout. -# You should specify the listening remote as ptcp:0:127.0.0.1 or +# Parses the TCP or SSL port on which a server is listening from +# LOGFILE, given that the server was told to listen on a kernel-chosen +# port, and assigns the port number to shell VARIABLE. You should +# specify the listening remote as ptcp:0:127.0.0.1 or # pssl:0:127.0.0.1, or the equivalent with [::1] instead of 127.0.0.1. # # Here's an example of how to use this with ovsdb-server: # # ovsdb-server --log-file --remote=ptcp:0:127.0.0.1 ... -# TCP_PORT=`parse_listening_port < ovsdb-server.log` -parse_listening_port () { - sed -n 's/.*0:.*: listening on port \([0-9]*\)$/\1/p' -}] -m4_divert_pop([PREPARE_TESTS]) +# PARSE_LISTENING_PORT([ovsdb-server.log], [TCP_PORT]) +# # Now $TCP_PORT holds the listening port. +m4_define([PARSE_LISTENING_PORT], + [OVS_WAIT_UNTIL([$2=`sed -n 's/.*0:.*: listening on port \([[0-9]]*\)$/\1/p' "$1"` && test X != X"[$]$2"])]) m4_define([STRIP_XIDS], [[sed 's/ (xid=0x[0-9a-fA-F]*)//']]) m4_define([STRIP_DURATION], [[sed 's/\bduration=[0-9.]*s/duration=?s/']]) diff --git a/tests/ovs-vsctl.at b/tests/ovs-vsctl.at index 2795370..fc59652 100644 --- a/tests/ovs-vsctl.at +++ b/tests/ovs-vsctl.at @@ -1319,7 +1319,7 @@ dnl Create database. OVSDB_INIT([conf.db]) AT_CHECK([ovsdb-server --detach --no-chdir --pidfile="`pwd`"/pid --private-key=$PKIDIR/ovsdbserver-privkey.pem --certificate=$PKIDIR/ovsdbserver-cert.pem --ca-cert=$PKIDIR/pki/switchca/cacert.pem --remote=pssl:0:127.0.0.1 --unixctl="`pwd`"/unixctl --log-file="`pwd`"/ovsdb-server.log conf.db], [0], [ignore], [ignore]) on_exit "kill `cat pid`" -SSL_PORT=`parse_listening_port < ovsdb-server.log` +PARSE_LISTENING_PORT([ovsdb-server.log], [SSL_PORT]) # During bootstrap, the connection gets torn down. So the o/p of ovs-vsctl is error. AT_CHECK([ovs-vsctl -t 5 --db=ssl:127.0.0.1:$SSL_PORT --private-key=$PKIDIR/vsctl-privkey.pem --certificate=$PKIDIR/vsctl-cert.pem --bootstrap-ca-cert=$PKIDIR/cacert.pem show], [1], [ignore], [ignore]) @@ -1346,7 +1346,7 @@ dnl Create database. OVSDB_INIT([conf.db]) AT_CHECK([ovsdb-server --detach --no-chdir --pidfile="`pwd`"/pid --private-key=$PKIDIR/ovsdbserver-privkey.pem --certificate=$PKIDIR/ovsdbserver-cert.pem --ca-cert=$PKIDIR/pki/switchca/cacert.pem --peer-ca-cert=$PKIDIR/pki/controllerca/cacert.pem --remote=pssl:0:127.0.0.1 --unixctl="`pwd`"/unixctl --log-file="`pwd`"/ovsdb-server.log conf.db], [0], [ignore], [ignore]) on_exit "kill `cat pid`" -SSL_PORT=`parse_listening_port < ovsdb-server.log` +PARSE_LISTENING_PORT([ovsdb-server.log], [SSL_PORT]) # During bootstrap, the connection gets torn down. So the o/p of ovs-vsctl is error. AT_CHECK([ovs-vsctl -t 5 --db=ssl:127.0.0.1:$SSL_PORT --private-key=$PKIDIR/vsctl-privkey.pem --certificate=$PKIDIR/vsctl-cert.pem --bootstrap-ca-cert=$PKIDIR/cacert.pem show], [1], [ignore], [ignore]) diff --git a/tests/ovsdb-idl.at b/tests/ovsdb-idl.at index f4d03f8..c838d6c 100644 --- a/tests/ovsdb-idl.at +++ b/tests/ovsdb-idl.at @@ -56,7 +56,7 @@ m4_define([OVSDB_CHECK_IDL_TCP_PY], AT_CHECK([ovsdb-tool create db $abs_srcdir/idltest.ovsschema], [0], [stdout], [ignore]) AT_CHECK([ovsdb-server --log-file '-vPATTERN:console:ovsdb-server|%c|%m' --detach --no-chdir --pidfile="`pwd`"/pid --remote=punix:socket --remote=ptcp:0:127.0.0.1 --unixctl="`pwd`"/unixctl db], [0], [ignore], [ignore]) - TCP_PORT=`parse_listening_port < ovsdb-server.log` + PARSE_LISTENING_PORT([ovsdb-server.log], [TCP_PORT]) m4_if([$2], [], [], [AT_CHECK([ovsdb-client transact tcp:127.0.0.1:$TCP_PORT $2], [0], [ignore], [ignore], [kill `cat pid`])]) @@ -76,7 +76,7 @@ m4_define([OVSDB_CHECK_IDL_TCP6_PY], AT_CHECK([ovsdb-tool create db $abs_srcdir/idltest.ovsschema], [0], [stdout], [ignore]) AT_CHECK([ovsdb-server --log-file '-vPATTERN:console:ovsdb-server|%c|%m' --detach --no-chdir --pidfile="`pwd`"/pid --remote=ptcp:0:[[::1]] --unixctl="`pwd`"/unixctl db], [0], [ignore], [ignore]) - TCP_PORT=`parse_listening_port < ovsdb-server.log` + PARSE_LISTENING_PORT([ovsdb-server.log], [TCP_PORT]) echo "TCP_PORT=$TCP_PORT" m4_if([$2], [], [], diff --git a/tests/ovsdb-server.at b/tests/ovsdb-server.at index 6bbaf92..c869d6f 100644 --- a/tests/ovsdb-server.at +++ b/tests/ovsdb-server.at @@ -518,7 +518,7 @@ AT_CHECK( --ca-cert=db:mydb,SSL,ca_cert \ --remote=pssl:0:127.0.0.1 --unixctl="`pwd`"/unixctl db], [0], [ignore], [ignore]) -SSL_PORT=`parse_listening_port < ovsdb-server.log` +PARSE_LISTENING_PORT([ovsdb-server.log], [SSL_PORT]) AT_CHECK( [[ovsdb-client \ --private-key=$PKIDIR/testpki-privkey.pem \ @@ -793,7 +793,7 @@ m4_define([OVSDB_CHECK_EXECUTION], PKIDIR=$abs_top_builddir/tests AT_CHECK([ovsdb-tool create db schema], [0], [stdout], [ignore]) AT_CHECK([ovsdb-server --log-file --detach --no-chdir --pidfile="`pwd`"/pid --private-key=$PKIDIR/testpki-privkey2.pem --certificate=$PKIDIR/testpki-cert2.pem --ca-cert=$PKIDIR/testpki-cacert.pem --remote=pssl:0:127.0.0.1 --unixctl="`pwd`"/unixctl db], [0], [ignore], [ignore]) - SSL_PORT=`parse_listening_port < ovsdb-server.log` + PARSE_LISTENING_PORT([ovsdb-server.log], [SSL_PORT]) m4_foreach([txn], [$3], [AT_CHECK([ovsdb-client --private-key=$PKIDIR/testpki-privkey.pem --certificate=$PKIDIR/testpki-cert.pem --ca-cert=$PKIDIR/testpki-cacert.pem transact ssl:127.0.0.1:$SSL_PORT 'txn'], [0], [stdout], [ignore], [test ! -e pid || kill `cat pid`]) @@ -831,7 +831,7 @@ m4_define([OVSDB_CHECK_EXECUTION], PKIDIR=$abs_top_builddir/tests AT_CHECK([ovsdb-tool create db schema], [0], [stdout], [ignore]) AT_CHECK([ovsdb-server --log-file --detach --no-chdir --pidfile="`pwd`"/pid --private-key=$PKIDIR/testpki-privkey2.pem --certificate=$PKIDIR/testpki-cert2.pem --ca-cert=$PKIDIR/testpki-cacert.pem --remote=pssl:0:[[::1]] --unixctl="`pwd`"/unixctl db], [0], [ignore], [ignore]) - SSL_PORT=`parse_listening_port < ovsdb-server.log` + PARSE_LISTENING_PORT([ovsdb-server.log], [SSL_PORT]) m4_foreach([txn], [$3], [AT_CHECK([ovsdb-client --private-key=$PKIDIR/testpki-privkey.pem --certificate=$PKIDIR/testpki-cert.pem --ca-cert=$PKIDIR/testpki-cacert.pem transact ssl:[[::1]]:$SSL_PORT 'txn'], [0], [stdout], [ignore], [test ! -e pid || kill `cat pid`]) @@ -851,7 +851,7 @@ AT_KEYWORDS([ovsdb server positive tcp]) ordinal_schema > schema AT_CHECK([ovsdb-tool create db schema], [0], [ignore], [ignore]) AT_CHECK([ovsdb-server --log-file --detach --no-chdir --pidfile="`pwd`"/pid --unixctl="`pwd`"/unixctl --remote=ptcp:0:127.0.0.1 db], [0], [ignore], [ignore]) -TCP_PORT=`parse_listening_port < ovsdb-server.log` +PARSE_LISTENING_PORT([ovsdb-server.log], [TCP_PORT]) AT_CHECK([ovsdb-client get-schema-version tcp:127.0.0.1:$TCP_PORT ordinals], [0], [5.1.3 ]) OVSDB_SERVER_SHUTDOWN @@ -878,7 +878,7 @@ m4_define([OVSDB_CHECK_EXECUTION], PKIDIR=$abs_top_builddir/tests AT_CHECK([ovsdb-tool create db schema], [0], [stdout], [ignore]) AT_CHECK([ovsdb-server --log-file --detach --no-chdir --pidfile="`pwd`"/pid --remote=ptcp:0:127.0.0.1 --unixctl="`pwd`"/unixctl db], [0], [ignore], [ignore]) - TCP_PORT=`parse_listening_port < ovsdb-server.log` + PARSE_LISTENING_PORT([ovsdb-server.log], [TCP_PORT]) m4_foreach([txn], [$3], [AT_CHECK([ovsdb-client transact tcp:127.0.0.1:$TCP_PORT 'txn'], [0], [stdout], [ignore], [test ! -e pid || kill `cat pid`]) @@ -915,7 +915,7 @@ m4_define([OVSDB_CHECK_EXECUTION], PKIDIR=$abs_top_builddir/tests AT_CHECK([ovsdb-tool create db schema], [0], [stdout], [ignore]) AT_CHECK([ovsdb-server --log-file --detach --no-chdir --pidfile="`pwd`"/pid --remote=ptcp:0:[[::1]] --unixctl="`pwd`"/unixctl db], [0], [ignore], [ignore]) - TCP_PORT=`parse_listening_port < ovsdb-server.log` + PARSE_LISTENING_PORT([ovsdb-server.log], [TCP_PORT]) m4_foreach([txn], [$3], [AT_CHECK([ovsdb-client transact tcp:[[::1]]:$TCP_PORT 'txn'], [0], [stdout], [ignore], [test ! -e pid || kill `cat pid`])