[ovs-dev] [PATCH] tests: fix issue in use of OVS_APP_EXIT_AND_WAIT

[Ben Pfaff]

On Tue, Jun 07, 2016 at 12:52:37AM +0000, Alin Serdean wrote:
> On Windows:
> ## ------------------------------ ##
> ## openvswitch 2.5.90 test suite. ##
> ## ------------------------------ ##
> 1747. ovsdb-monitor.at:47: testing monitor insert into empty table ...
> ./ovsdb-monitor.at:47: ovsdb-tool create db schema
> stderr:
> stdout:
> ./ovsdb-monitor.at:47: ovsdb-server --detach --no-chdir --pidfile="`pwd`"/server-pid --remote=punix:socket --unixctl="`pwd`"/unixctl --log-file="`pwd`"/ovs
> db-server-log db >/dev/null 2>&1
> ./ovsdb-monitor.at:47: ovsdb-client -vjsonrpc --pidfile="`pwd`"/client-pid -d json monitor --format=csv unix:socket ordinals ordinals  > output &
> stderr:
> stdout:
> ./ovsdb-monitor.at:47: ovsdb-client transact unix:socket '["ordinals",
>       {"op": "insert",
>        "table": "ordinals",
>        "row": {"number": 0, "name": "zero"}}]'
> stderr:
> stdout:
> [{"uuid":["uuid","4a367308-dc78-449e-9243-fd007ff10690"]}]
> ./ovsdb-monitor.at:47: ovsdb-client transact unix:socket '["ordinals"]'
> stderr:
> stdout:
> []
> ./ovsdb-monitor.at:47: test -e `pwd`/server-pid
> ./ovsdb-monitor.at:47: ovs-appctl --target=`pwd`/unixctl exit
> --- /dev/null   2016-06-07 02:48:42 +0300
> +++ /c/_2016/june/ovs/tests/testsuite.dir/at-groups/1747/stderr 2016-06-07 02:48:42 +0300
> @@ -0,0 +1,8 @@
> +2016-06-06T23:48:40Z|00001|jsonrpc|DBG|unix:socket: send request, method="list_dbs", params=[], id=0
> +2016-06-06T23:48:40Z|00002|jsonrpc|DBG|unix:socket: received reply, result=["ordinals"], id=0
> +2016-06-06T23:48:40Z|00003|jsonrpc|DBG|unix:socket: send request, method="get_schema", params=["ordinals"], id=1
> +2016-06-06T23:48:40Z|00004|jsonrpc|DBG|unix:socket: received reply, result={"cksum":"12345678 9","name":"ordinals","version":"5.1.3","tables":{"ordinals":
> {"indexes":[["number"]],"columns":{"number":{"type":"integer"},"name":{"type":"string"}}}}}, id=1
> +2016-06-06T23:48:40Z|00005|jsonrpc|DBG|unix:socket: send request, method="monitor", params=["ordinals",null,{"ordinals":[{"columns":["name","number","_ver
> sion"]}]}], id=2
> +2016-06-06T23:48:40Z|00006|jsonrpc|DBG|unix:socket: received reply, result={}, id=2
> +2016-06-06T23:48:41Z|00007|jsonrpc|DBG|unix:socket: received notification, method="update", params=[null,{"ordinals":{"4a367308-dc78-449e-9243-fd007ff1069
> 0":{"new":{"name":"zero","number":0,"_version":["uuid","c5574fef-e08f-4304-9879-762d04d9d9ed"]}}}}]
> +ovsdb-client: unix:socket: receive failed (End of file)
> ovsdb-server-log:
> > 2016-06-06T23:48:40.644Z|00001|vlog|INFO|opened log file c:/_2016/june/ovs/tests/testsuite.dir/1747/ovsdb-server-log
> > 2016-06-06T23:48:40.806Z|00002|ovsdb_server|INFO|ovsdb-server (Open vSwitch) 2.5.90
> 1747. ovsdb-monitor.at:47:  FAILED (ovsdb-monitor.at:47)
> >     OVS_WAIT_WHILE([kill -0 $TMPPID 2>/dev/null])])

I suspect I understand what's happening here.

To execute the following command, Autotest internally redirects stdout
and stderr to files named "stdout" and "stderr":
> ./ovsdb-monitor.at:47: ovsdb-client -vjsonrpc --pidfile="`pwd`"/client-pid -d json monitor --format=csv unix:socket ordinals ordinals  > output &
> stderr:
> stdout:

Ordinarily, after the command exits it would close the file, but & means
that it holds the file open.  While the next few ovsdb-client commands
run, it queues up some output in stdio buffers but doesn't bother to
actually flush it[*].

    [*] There's either a hole in my theory here or Windows is not fully
        ANSI C conformant since ANSI C says that "As initially opened,
        the standard error stream is not fully buffered; ..." which
        means that it'd probably be line buffered, so that each line of
        the log is flushed separately.

On Unix-like OSes, the following Autotest commands don't really care
about this open file, since the OS will happily delete and replace the
"stderr" file and allow the previous file with that name to remain open.
On Windows, the OS won't permit that, so I guess the shell is actually
just opening the existing file.

Later, "ovs-appctl --target=`pwd`/unixctl exit" causes ovsdb-server to
exit.  It flushes its accumulated stderr buffer to the OS, and therefore
it shows up in the "stderr" output as part of ovs-appctl's output since
ovs-appctl and ovsdb-server both had their output sent to the same file.

Probably, adding 2>/dev/null to the ovsdb-server command would solve the
problem.  To get better output for debugging failures, also add
--log-file and AT_CAPTURE_FILE([ovsdb-server.log]).