tests: improve readability of output

[jsha]

Following up on #336 I realized our test output is pretty hard to read.

In this PR I changed client-server.py so it suppresses client output. If the client command fails, it then prints the suppressed output along with the command line and environment. I'd like to also suppress the server output in the same way but that will require a bigger refactoring, since the server is currently started once and shared by multiple client runs. Most likely we'll wind up wanting to start one server and one client in each test case.

I also added LOG and LOG_SIMPLE macros to client.c and server.c. This simplifies a lot of fprintf calls, and also allows us to print the pid with each log line, which will help tell apart separate server invocations in the logs.

The test server now prints its relevant environment variables at startup.

[jsha]

I got another flake in rustls-ffi / Build+test (macos-latest, clang, stable) (pull_request), in the run_mtls_client_crl_tests part of the tests. A snippet below. The "connecting: Connection refused" message comes from a perror call in client.c that I'll add a prefix to.

023-07-13T23:50:30.5458150Z server[2947]: read 246 bytes from socket
2023-07-13T23:50:30.5459520Z server[2947]: do_read returning 0
2023-07-13T23:50:30.5460010Z server[2947]: reading from socket: EAGAIN or EWOULDBLOCK: Resource temporarily unavailable
2023-07-13T23:50:30.5460990Z server[2947]: writing response
2023-07-13T23:50:30.5461560Z server[2947]: negotiated ALPN protocol: 'http/1.1'
2023-07-13T23:50:30.5463810Z server[2947]: closing socket 5
2023-07-13T23:50:30.7149060Z server[2950]: listening on localhost:8443. AUTH_CERT=testdata/minica.pem, AUTH_CRL=testdata/test.crl.pem, VECTORED_IO=(null)
2023-07-13T23:50:30.7435320Z Traceback (most recent call last):
2023-07-13T23:50:30.7436130Z   File "/Users/runner/work/rustls-ffi/rustls-ffi/./tests/client-server.py", line 47, in run_with_maybe_valgrind
2023-07-13T23:50:30.7436660Z client-server.py: Thu Jul 13 23:50:27 2023 - still trying to connect to localhost:8443
2023-07-13T23:50:30.7437160Z client-server.py: Thu Jul 13 23:50:28 2023 - still trying to connect to localhost:8443
2023-07-13T23:50:30.7437740Z client-server.py: Thu Jul 13 23:50:28 2023 - still trying to connect to localhost:8443
2023-07-13T23:50:30.7438240Z client-server.py: Thu Jul 13 23:50:28 2023 - still trying to connect to localhost:8443
2023-07-13T23:50:30.7438690Z client-server.py: Thu Jul 13 23:50:28 2023 - still trying to connect to localhost:8443
2023-07-13T23:50:30.7439130Z client-server.py: Thu Jul 13 23:50:28 2023 - still trying to connect to localhost:8443
2023-07-13T23:50:30.7439550Z client-server.py: detected server is up on localhost:8443
2023-07-13T23:50:30.7440010Z client-server.py: Thu Jul 13 23:50:29 2023 - still trying to connect to localhost:8443
2023-07-13T23:50:30.7440550Z client-server.py: detected server is up on localhost:8443
2023-07-13T23:50:30.7440720Z 
2023-07-13T23:50:30.7440820Z Failed process output:
2023-07-13T23:50:30.7441050Z client[2951]: connecting to localhost:8443
2023-07-13T23:50:30.7441290Z connecting: Connection refused
2023-07-13T23:50:30.7441430Z 
2023-07-13T23:50:30.7441600Z     subprocess.run(args, env=process_env, capture_output=True).check_returncode()
2023-07-13T23:50:30.7442820Z   File "/Library/Frameworks/Python.framework/Versions/3.11/lib/python3.11/subprocess.py", line 502, in check_returncode
2023-07-13T23:50:30.7458570Z     raise CalledProcessError(self.returncode, self.args, self.stdout,
2023-07-13T23:50:30.7459410Z subprocess.CalledProcessError: Command '['./target/client', 'localhost', '8443', '/']' returned non-zero exit status 1.
2023-07-13T23:50:30.7459680Z 
2023-07-13T23:50:30.7459900Z The above exception was the direct cause of the following exception:
2023-07-13T23:50:30.7460100Z 
2023-07-13T23:50:30.7460210Z Traceback (most recent call last):
2023-07-13T23:50:30.7460680Z   File "/Users/runner/work/rustls-ffi/rustls-ffi/./tests/client-server.py", line 236, in <module>
2023-07-13T23:50:30.7461270Z     main()
2023-07-13T23:50:30.7462010Z   File "/Users/runner/work/rustls-ffi/rustls-ffi/./tests/client-server.py", line 232, in main
2023-07-13T23:50:30.7462700Z     run_mtls_client_crl_tests(client, valgrind)
2023-07-13T23:50:30.7463430Z   File "/Users/runner/work/rustls-ffi/rustls-ffi/./tests/client-server.py", line 139, in run_mtls_client_crl_tests
2023-07-13T23:50:30.7464470Z     run_with_maybe_valgrind(
2023-07-13T23:50:30.7465200Z   File "/Users/runner/work/rustls-ffi/rustls-ffi/./tests/client-server.py", line 52, in run_with_maybe_valgrind
2023-07-13T23:50:30.7465660Z     raise Failure({"args": args, "env": env}) from e
2023-07-13T23:50:30.7466830Z Failure: {'args': ['./target/client', 'localhost', '8443', '/'], 'env': {'CA_FILE': 'testdata/minica.pem', 'AUTH_CERT': 'testdata/example.com/cert.pem', 'AUTH_KEY': 'testdata/example.com/key.pem'}}
2023-07-13T23:50:30.7535730Z make: *** [test] Error 1

Not sure why the client would get a connection refused when client-server.py is getting a successful connection. Also interesting that this happened on macos-latest, clang, stable like the last flake. 🤔

[ctz]

Not sure why the client would get a connection refused when client-server.py is getting a successful connection. Also interesting that this happened on macos-latest, clang, stable like the last flake.

it was a while back that rustls had a test suite that relied on opening and using lots of localhost ports, but back then macos was by far the most mysterious. i'm not sure if it lacks working network namespacing or what. eventually i got to an acceptable place by choosing a different random port for each test, and checking it was free (by attempting a TCP connection) before running the test on it.