diff mbox

[ovs-dev,repost,3/3] tests: Make parse_listening_port entirely reliable.

Message ID 1443550635-29312-3-git-send-email-blp@nicira.com
State Accepted
Headers show

Commit Message

Ben Pfaff Sept. 29, 2015, 6:17 p.m. UTC 
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 <blp@nicira.com>
---
 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(-)

Comments

Flavio Leitner Nov. 26, 2015, 5:58 p.m. UTC | #1 
On Tue, Sep 29, 2015 at 11:17:15AM -0700, Ben Pfaff wrote:
> 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 <blp@nicira.com>
> ---

What I don't like about this patch is that a failure now takes 10
secs for the test complete, but hey, it's not supposed to fail :-)

I broke the regex and the failures are reported correctly.

Acked-by: Flavio Leitner <fbl@sysclose.org>
diff mbox

Patch

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`])