1

So, I have a backup script that looks like:

tar -cf "${BACKUP_TAR}" "${LATEST_SUCCESSFUL_BACKUP}" 2>&1 | tee -a "${LOG_FILE}"

  local PACKING_EXITCODE=${PIPESTATUS[0]}
  if [ ${PACKING_EXITCODE} -eq 0 ]; then 
    logging 'Packing successful'
  else
    logging "ERROR: Packing failed! ERROR: ${PACKING_EXITCODE}. Disk space?"
    df -h 2>&1 | tee -a "${LOG_FILE}"
    logging "Check the log file: ${LOG_FILE}"
    set_lockfile 'destroy'
    backup_remove_package
    exit 1
  fi

logging is a function to log properly into my log file.

logging () {
  local now="$(date)"
  local logfile=$2
  local logfile=${logfile:-$LOG_FILE}
  cat <<< "${now} $@" | tee -a "${logfile}"
}

set_lockfile "destroy"` is a function that removes my lock file.

set_lockfile () {
  local lockfile_action=$1
  local lockfile=$2
  local lockfile=${lockfile:-$LOCK_FILE}

  if [ "${lockfile_action}" == "create" ]; then
    #...
  elif [ "${lockfile_action}" == "destroy" ]; then
   destroy_lockfile $lockfile
  else
    logging 'ERROR: Wrong argument for locking file: use create or destroy'
    exit 1
  fi
}

destroy_lockfile () {
  local lockfile=$1

  if [ ! -f ${lockfile} ]; then
    logging "WARNING: Lockfile ${lockfile} not found!"
  else
    logging "Removing lockfile ${lockfile}"
    rm -f "${lockfile}"
  fi
}

backup_remove_package is a function to remove any temporary files created.

I experience a failed packing due to a disk full, expected behavior as you can guess for the df -h.

The interesting thing is the backup log. It states:

tar: /tmp/backup/20180827T223001.tar: Wrote only 4096 of 10240 bytes
tar: Error is not recoverable: exiting now
Filesystem      Size  Used Avail Use% Mounted on
/dev/xvda1      788G  788G     0 100% /
devtmpfs        3.9G   60K  3.9G   1% /dev
tmpfs           3.9G     0  3.9G   0% /dev/shm

Which means, tar failed, then it went through the if condition, somehow skipped the logging "ERROR: ...", executed the df -h and died. skipping the rest.

Somehow looks like is skipping any function but running the commands.

The backup is called from a cron.d file. I have NOT set set -e, so no exit on error is done.

Any ideas why is this happening?

  • Your question does not contain enough information to know the exact problem for sure but some guesses: your logging method is not robust enough in case the filesystem is full (note that you do not handle failed logging call), something goes wrong with your functions but the stderr is redirected to blackhole or somewhere you're not looking at and as a result, you do not catch the actual error message you need. – Mikko Rantalainen Aug 28 '18 at 10:16
  • I "agree", edited to add the code, but if logging is not working, why is df working? Also set_lockfile only removes a file, the same than backup_remove_package and neither of them works. – TanisDLJ Aug 28 '18 at 11:36
  • Are you sure the remaining lock file and $BACKUP are from the same run of the script as the one that wrote that text to the log file? Check their last modification time. – Stéphane Chazelas Aug 29 '18 at 15:31
2

Your script appears to work as expected. The output of df has clearly made it to $LOG_FILE and exit 1 is causing the script to exit.

We don't know what your logging command does, but AFAICT, it is not meant to write to $LOG_FILE. If it were, it would be a bit silly to write Check the log file: ${LOG_FILE} there.

Edit

Now that you've posted the logging function, I can see it uses a here-string (<<<).

In bash, here-strings and here-documents are implemented using temporary files (in $TMPDIR or /tmp if $TMPDIR is not defined). If that was the filesystem that was full, that would explain why logging didn't output anything.

$ sudo mount -o size=1 -t tmpfs empty /mnt/1
$ yes > /mnt/1/fill-up
yes: standard output: No space left on device
$ TMPDIR=/mnt/1 bash -c 'cat <<< test'
bash: cannot create temp file for here-document: No space left on device

Instead of:

local now="$(date)"
cat <<< "${now} $@" | tee -a "${logfile}"

Just use:

printf '%(%FT%T%z)T %s\n' -1 "$*"
printf '%(%FT%T%z)T %s\n' -1 "$*" >> "$logfile"

Or:

local msg
printf -v msg '%(%FT%T%z)T %s' -1 "$*"
printf '%s\n' "$msg"
printf '%s\n' "$msg" >> "$logfile"

(assumes $IFS is unset or starts with space)

That saves the temporary file, but also avoids forking any process or executing any external command (which could also fail under some pathological conditions) (and give you a more useful date format, feel free to adapt).

More generally, a system with a full /tmp and /var filesystem is a crippled system, you can expect a lot of things not to work properly.

Here, you're lucky you've got logs at all. Disk space for files is allocated in blocks (typically 4K on ext4), which is probably why you got some output into `$LOG_FILE (as the last block was allocated before the file system got full).

Scripts run by cron have their stdout and stderr on a temporary file as well (then cron tries to send an email with their content if they're not empty). So any of the commands could have their write(1, ...) or write(2, ...) fail as well (with ENOSPC error) which could cause them to misbehave or exit early if they consider it a fatal error.

  • No, it does not. logging is a wrapper for the log file to add a date and pipe the output to both stdin and the log. It writes the entire log until there, so logging is working. The message "check the log file" is just in case someone is reading the syslog or cronjob. Same for set_lockfile, works until this block of code. And the same for backup_remove_package, that should remove the /tmp/backup folder and when it fails with this condition it doesn't remove it either. – TanisDLJ Aug 28 '18 at 10:26
  • @TanisDLJ, still, it seems more likely that logging failed to write the error message to the log file (possibly because it exited earlier because of the disk being full). In any case, I'd have a look at that logging command. – Stéphane Chazelas Aug 28 '18 at 10:44
  • 1
    @TanisDLJ, <<< creates a temporary file. If ${TMPDIR:-/tmp} is on the fs that was full, that would explain why logging didn't work. – Stéphane Chazelas Aug 28 '18 at 13:26
  • Thanks for the ideas! But still does not explain why it didn't removed the lock-file and so :(. That's literally an rm -f. – TanisDLJ Aug 29 '18 at 7:28
  • @TanisDLJ we'd need to see the code of those functions. – Stéphane Chazelas Aug 29 '18 at 7:34
1

There is a high probability that the problem is that

PACKING_EXITCODE=${PIPESTATUS[0]}

is no valid shell code but something that is bash specific.

Cron calls commands with /bin/sh that differs from bash.

You could let your script start with

#!/bin/bash

and make the script executable using chmod +x scriptname to make sure the bash specific code is executed by bash and not by the default shell.

  • 1
    If it wasn't bash, the OP would probably get a syntax error about ${PIPESTATUS[0]} or an error about the local command not being found. AFAIK, only bash and pdksh (or zsh in ksh emulation) support local, arrays and 0 indices. Also clearly the right branch of the if condition has been picked here as df was run. – Stéphane Chazelas Aug 28 '18 at 10:16
  • The script is in bash, as @StéphaneChazelas stated. Good point tho, but is not the case. Thanks anyway! – TanisDLJ Aug 28 '18 at 10:31

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.