Race condition for writing to logfile to disk

[armenzg]

In https://github.com/getsentry/sentry/pull/24104 I noticed that the code that sentry-cli bash-hook generates uses : > "$_SENTRY_LOG_FILE" to redirect output. For some reason I fail to understand, this does not write all the output before calling sentry-cli bash-hook --send-event. I had to write a _wait_for_file function to wait for the file not to have size 0.

NOTE: I dump the output of sentry-cli bash-hook because I did not want to trap EXIT since it would affect the behaviour of direnv. Perhaps I could have combined this with "untrapping" after calling eval $(sentry-cli bash-hook).

I have created a test case below. I have also noticed that using exec does the redirection without the need to wait for the log to be written. See this other PR.

FYI sentry-cli bash-hook --send-event with an empty logfile does not emit any warnings.

I will be away until Monday, thus, it will take me a while to reply.

#!/bin/bash
# This code is mostly the output of calling `sentry-cli bash-hook`
# This is used by direnv's execution path since the default behaviour of
# `sentry-cli bash hook` does not work with it. For instance,
# 1) We should not trap EXIT for direnv needs that untrapped
# 2) There's a bug on SENTRY_LOG_FILE that is not fully written to disk before reporting
set -e

_SENTRY_TRACEBACK_FILE=$(mktemp -t sentry-direnv-envrc.traceback)
_SENTRY_LOG_FILE=$(mktemp -t sentry-direnv-envrc.out)

# Wait for file to be written to disk
_wait_for_file() {
  local filesize
  for i in {0..10}
  do
    filesize=$(du -k "$1" | cut -f1)
    if [[ $filesize -gt 0 ]]; then
      break
    else
      sleep 0.1
    fi
  done
}

_sentry_err_trap() {
  local _exit_code="$?"
  local _command="${BASH_COMMAND:-unknown}"
  if [ "x$1" != x ]; then
    _command="$1"
  fi
  if [ "x$2" != x ]; then
    _exit_code="$2"
  fi
  _sentry_traceback 1
  echo "@command:${_command}" >> "$_SENTRY_TRACEBACK_FILE"
  echo "@exit_code:${_exit_code}" >> "$_SENTRY_TRACEBACK_FILE"

  : >> "$_SENTRY_LOG_FILE"

  # This outputs 0 - bad!
  du -k "$_SENTRY_LOG_FILE" | cut -f1
  _wait_for_file "$_SENTRY_LOG_FILE"
  # This outputs non-0 - good!
  du -k "$_SENTRY_LOG_FILE" | cut -f1

  # The specified DSN reports to `sentry-dev-env` project in Sentry.io
  # shellcheck disable=SC2155
  # export SENTRY_LAST_EVENT=$(
  #   /usr/local/bin/sentry-cli bash-hook --send-event \
  #   --traceback "$_SENTRY_TRACEBACK_FILE" --log "$_SENTRY_LOG_FILE" )
  rm -f "$_SENTRY_TRACEBACK_FILE" "$_SENTRY_LOG_FILE"
}

_sentry_traceback() {
  local -i start=$(( ${1:-0} + 1 ))
  local -i end=${#BASH_SOURCE[@]}
  local -i i=0
  local -i j=0

  : > "$_SENTRY_TRACEBACK_FILE"
  # shellcheck disable=SC2004
  for ((i=${start}; i < ${end}; i++)); do
    j=$(( $i - 1 ))
    local function="${FUNCNAME[$i]}"
    local file="${BASH_SOURCE[$i]}"
    local line="${BASH_LINENO[$j]}"
    echo "${function}:${file}:${line}" >> "$_SENTRY_TRACEBACK_FILE"
  done
}

# Same effect as cat /dev/null > "$_SENTRY_LOG_FILE"
# However, this does not fork a new process, since ":" is a builtin.
: > "$_SENTRY_LOG_FILE"

if command -v perl >/dev/null; then
  # XXX: Breadcumbs don't correctly show the order of the lines. Peharps, it's due to lacking milliseconds
  exec \
    1> >(tee >(perl '-MPOSIX' -ne '$|++; print strftime("%Y-%m-%d %H:%M:%S %z: ", localtime()), "stdout: ", $_;' >> "$_SENTRY_LOG_FILE")) \
    2> >(tee >(perl '-MPOSIX' -ne '$|++; print strftime("%Y-%m-%d %H:%M:%S %z: ", localtime()), "stderr: ", $_;' >> "$_SENTRY_LOG_FILE") >&2)
else
  exec \
    1> >(tee >(awk '{ system(""); print strftime("%Y-%m-%d %H:%M:%S %z:"), "stdout:", $0; system(""); }' >> "$_SENTRY_LOG_FILE")) \
    2> >(tee >(awk '{ system(""); print strftime("%Y-%m-%d %H:%M:%S %z:"), "stderr:", $0; system(""); }' >> "$_SENTRY_LOG_FILE") >&2)
fi

trap notice ERR

die() {
    return 1
}

notice() {
    [ $? -eq 0 ] && return
    _sentry_err_trap
}

die "foo"

[github-actions[bot]]

This issue has gone three weeks without activity. In another week, I will close it.

But! If you comment or otherwise update it, I will reset the clock, and if you label it Status: Backlog or Status: In Progress, I will leave it alone ... forever!

---

"A weed is but an unloved flower." ― Ella Wheeler Wilcox 🥀