Close TCP, TLS connections gracefully to avoid data loss

[chrisberkhout]

Proposed commit message

Close TCP, TLS connections gracefully to avoid data loss (#)

TCP connections, including TLS connections, acknowledge received data.

Although a simple `net.Conn.Close()` will put all previously written
data on the network, the receiving server may disregard data that it
can't successfully acknowledge.

Graceful acknowledgement and closure can be facilitated by the client
closing writes first, and reading any available data before fully
closing the connection.

Checklist

• Run the release workflow in GitHub actions (after merge)

Discussion

This bug was discovered due to flaky tests that use stream (issues listed below).

For a more detailed discussion of this topic please read the blog post
The ultimate SO_LINGER page, or: why is my tcp not reliable.

I tested this manually. Failures of the old version can be demonstrated as follows. Here I use data from integrations that is know to trigger the issue.

TLS

In one terminal run this server loop:

while true; do
  echo Running the server...
  echo
  openssl s_server -accept 4433 -naccept 1 \
    -cert ~/.elastic-package/profiles/default/certs/elastic-agent/cert.pem \
    -key ~/.elastic-package/profiles/default/certs/elastic-agent/key.pem \
    2>&1 | pv -L 100k | tee output.log
  echo
  if grep -q "ERROR" output.log; then
    echo "Error detected. Stopping."
    break
  fi
done

In another, repeatedly run this client:

go run main.go log --delay=1s --addr localhost:4433 -p=tls --insecure ../integrations/packages/cyberarkpas/_dev/deploy/docker/sample_logs/audit/*.log

It should fail within a few runs. It fails more readily if the client is run soon after the server starts. If necessary, lowering the rate limit enforced by pv may help trigger a failure.

TCP

This uses GNU Netcat (BSD Netcat may differ). Having the server write some data seems to be necessary for the error to happen.

The server:

input_lines=$(cat ../integrations/packages/cyberarkpas/_dev/deploy/docker/sample_logs/audit/*.log | wc -l)
while true; do
  echo Running the server...
  echo
  echo hi | nc -l -p 8888 | pv -L 100k | tee output.log
  echo
  output_lines=$(cat output.log | wc -l)
  if [ "$output_lines" != "$input_lines" ]; then
    echo "Error detected: $output_lines lines received != $input_lines lines sent. Stopping."
    break
  fi
done

The client:

go run main.go log --delay=1s --addr localhost:8888 -p=tcp ../integrations/packages/cyberarkpas/_dev/deploy/docker/sample_logs/audit/*.log

Related issues

• Closes Streaming logs over TLS can cause an error for the receiver upon close #120
• Closes [Stack 8.16.0-SNAPSHOT] [cyberarkpas] Failing test daily: system test: tcp in cyberarkpas.audit integrations#11224
• Closes [Stack 8.16.0-SNAPSHOT] [cyberarkpas] Failing test daily: system test: tls in cyberarkpas.audit integrations#10620
• Related [LogsDB] [Stack 8.16.0-SNAPSHOT] [cyberarkpas] Failing test daily: system test: tls in cyberarkpas.audit integrations#11075

[elasticmachine]

💚 Build Succeeded

• Buildkite Build
• Commit: 724fca4

cc @chrisberkhout

[chrisberkhout]

@efd6 I think I was able to resolve those manual testing failures.

If it is run like this, the watch command will stop reading output as soon as it has enough, then stream will get a SIGPIPE and exit:

watch 'go run main.go log --delay=1s --addr localhost:8888 -p=tcp ../integrations/packages/cyberarkpas/_dev/deploy/docker/sample_logs/audit/*.log'

But if the error output is redirected, watch will allow each run to successfully complete:

watch 'go run main.go log --delay=1s --addr localhost:8888 -p=tcp ../integrations/packages/cyberarkpas/_dev/deploy/docker/sample_logs/audit/*.log 2> /dev/null'