Log lines are sometimes dropped

[mkenigs]

If a service logs something immediately before exiting, that log line isn't always reported by process-compose process logs. Sometimes the line is reported, so it seems there is a race condition on service exit. I saw this when running on an x86_64-linux machine that was under some resource load; it didn't seem to happen when not under load.

I used the following script to pinpoint the issue. It starts a service that echos 1, sleeps briefly, and then echos 2 right before exiting. It then checks the logs for the service after waiting longer than the service should take to exit. If it doesn't find the additional log line (2), it sleeps an additional 10 seconds just to ensure it's not checking for logs before the service actually exits, and then it prints the logs.

In 20 runs (when the system was under load), the script would consistently print logs at least once that didn't contain 2.

If I add a sleep .1 after echo 2, I never see the 2 log line being dropped.

#!/usr/bin/env bash

set -euo pipefail

cat << EOF > process-compose.yml
version: "0.5"
log_level: debug

processes:
  sleep:
    command: "sleep 100"
  echo:
    command: |
      echo 1
      sleep .1
      echo 2
EOF

process-compose up -u pc.sock -L pc.log --tui=false >/dev/null 2>&1 &

# make sure process-compose has started
for i in {1..5}; do
  if process-compose process list -u pc.sock 2>/dev/null | grep sleep >/dev/null; then
    break;
  fi
  sleep .1
done
if [ "$i" == 5 ]; then
  echo "didn't start"
  exit 1
fi

sleep .2
process-compose -u pc.sock process logs echo --tail 5 > echo.log
if ! grep 2 echo.log; then
  echo "waiting longer"
  sleep 10
  process-compose -u pc.sock process logs echo --tail 5
  process-compose down -u pc.sock
  exit 1
fi
process-compose down -u pc.sock

[mkenigs]

Thanks @F1bonacc1 !

[F1bonacc1]

@mkenigs your script was very helpful in pinpointing the issue and validating the fix. Thanks!