Different redirection behavior in BASH/Linux when run under cron vice login ???

UNIX for Advanced & Expert Users
1

run_xfs_fsr is a xfs filesystem maintenance script designed to run under cron. The system is a home theater personal computer running mythbuntu 10.10, and is accessed remotely for these tests. cron runs a script, (xfs_fsr.sh) at 02:30 that runs the subject script under BASH and sets the parameters, 1. logfile, 2. "left-off" file, 3. runtime (10800 seconds). 4. is not set so run_xfs_fsr uses the default, /etc/mtab.

When run under cron, the xfs reorganization program (xfs_fsr) stdout goes to syslog instead of the logfile. When run as a login script, it goes to the logfile.

In the same run_xfs_fsr script, another xfs utility, xfs_db, stdout goes to the logfile in both cases.

I am at a loss to understand or see any error here. Even though I have years of programming experience, I am a newbie to BASH shell scripting......? Pardon the long post.

The section of run_xfs_fsr outputting xfs_fsr:

exec > $log_file
echo "SHELL=""$SHELL"
echo "PWD=""$PWD"
echo "USER=""$USER"
echo "SCRIPT=""$script"
echo "log_file=""$log_file"
<snip> 
#start reports & reorgs
echo "xfs report"
df -h -l -T --total -t xfs 2>&1   #status of local xfs file systems
frag_report $used_mtab
if [ $xfs_found == "yes" ]
then
  test $left_off_exists = "no" && echo "New $left_off will be created."
  logger -t "RUN_XFS_FSR" "xfs_fsr -v -t ""$time_for_run"" -f ""$left_off"" -m ""$used_mtab"" 2>&1 LOG:""$log_file"
  echo "reorganization"
  echo -e """$(date)""startxfs_fsr"
  xfs_fsr -v -t $time_for_run -f $left_off -m $used_mtab 2>&1   
  xfs_fsr_exit_status="$?" 
  echo -e "Exit status for xfs_fsr= ""$xfs_fsr_exit_status""\n""$(date)""-end--xfs_fsr"
  frag_report $used_mtab
else
  echo -e "\nNo xfs file system mounted\n"
  logger -t "RUN_XFS_FSR" "No xfs file system mounted."      
fi
echo "end"
logger -t "RUN_XFS_FSR" " End: ""$(date)"
exit 0

frag_report is a function that prints a summary for each mounted xfs file system using, here, /etc/mtab/

frag_report()
{ 
  echo "frag_report"
  #find all xfs files system in $1 (mtab) and run frag report
  #set xfs_found="yes" if an xfs file system found
  local line; local device_file_path; local file_path; local fs_type; local oldIFS
  local mounted_devices_file;
  mounted_devices_file="${1}"
  oldIFS="$IFS"; IFS="$(printf '\n\b')"
  exec 3<&0; exec 0<"$mounted_devices_file"
  while read -r line  # traipse thru the file
  do    #cleave off 1st 3 sp delimited substr
    device_file_path="${line%% *}"; line="${line##$device_file_path}"; line="${line# }"
    file_path="${line%% *}"; line="${line##$file_path}"; line="${line# }"
    fs_type="${line%% *}" ; line="${line##$fs_type}"; line="${line# }"
    if [[ $fs_type == "xfs" ]]  #if xfs
    then   #run report std-err>std_out
      echo -e "xfs frag report for $file_path ($device_file_path)  $(date)"
      xfs_db -r -c frag $device_file_path 2>&1 
      xfs_found="yes"
    fi
  done
  exec 0<&3 ;  IFS="$oldIFS"
}

syslog run as login: (the shorter run time is because xfs_fsr had already reorganized the xfs files systems)

Jun  6 04:15:08 HTPC smbd[645]:   standard input is not a socket, assuming -D option
Jun  6 04:17:01 HTPC CRON[701]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Jun  6 04:25:01 HTPC CRON[778]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Jun  6 04:28:31 HTPC RUN_XFS_FSR:  Start: Mon Jun  6 04:28:30 PDT 2011  Version:1.03.001
Jun  6 04:28:31 HTPC RUN_XFS_FSR: xfs_fsr -v -t 10800 -f /root/mycron/.fsrlast_xfs -m /etc/mtab 2>&1 LOG:/var/log/xfs_fsr.log
Jun  6 04:30:26 HTPC RUN_XFS_FSR:  End: Mon Jun  6 04:30:26 PDT 2011
Jun  6 04:32:08 HTPC smbd[917]: [2011/06/06 04:32:08.729061,  0] lib/util_sock.c:1441(get_peer_addr_internal)

syslog run as cron:

Jun  6 02:30:01 HTPC CRON[32519]: (root) CMD (SHELL=/bin/bash ;/root/mycron/xfs_fsr.sh)
Jun  6 02:30:01 HTPC RUN_XFS_FSR:  Start: Mon Jun  6 02:30:01 PDT 2011  Version:1.03.001
Jun  6 02:30:03 HTPC RUN_XFS_FSR: xfs_fsr -v -t 10800 -f /root/mycron/.fsrlast_xfs -m /etc/mtab 2>&1 LOG:/var/log/xfs_fsr.log
Jun  6 02:30:03 HTPC fsr[32540]: Found 3 mounted, writable, XFS filesystems
Jun  6 02:30:03 HTPC fsr[32540]: xfs_fsr -m /etc/mtab -t 10800 -f /root/mycron/.fsrlast_xfs ...
Jun  6 02:30:03 HTPC fsr[32540]: START: pass=0 ino=0 /dev/sda3 /iso
Jun  6 02:30:03 HTPC fsr[32541]: /iso start inode=0
<snip>
Jun  6 03:39:51 HTPC fsr[32704]: ino=266 already fully defragmented.
Jun  6 03:39:51 HTPC fsr[32540]: Completed all 10 passes
Jun  6 03:39:52 HTPC RUN_XFS_FSR:  End: Mon Jun  6 03:39:52 PDT 2011
Jun  6 03:39:52 HTPC CRON[32517]: (root) MAIL (mailed 1 byte of output; but got status 0x00ff, #012)

logfile for run_xfs_fsr run under cron (unexpected, stdout from xfs_fsr missing):

SHELL=/bin/bash
PWD=/root/mycron
USER=
SCRIPT=run_xfs_fsr  v1.03.001
log_file=/var/log/xfs_fsr.log
xfs report
Filesystem    Type    Size  Used Avail Use% Mounted on
/dev/sda3      xfs    144G  101G   44G  70% /iso
/dev/sdb1      xfs    1.9T  1.4T  467G  75% /pvr
/dev/sdc1      xfs    1.9T  222G  1.7T  12% /pvs
total            -    3.8T  1.7T  2.1T  45%
frag_report
xfs frag report for /iso (/dev/sda3)  Mon Jun  6 02:30:02 PDT 2011
actual 6281, ideal 6206, fragmentation factor 1.19%
xfs frag report for /pvr (/dev/sdb1)  Mon Jun  6 02:30:02 PDT 2011
actual 973, ideal 898, fragmentation factor 7.71%
xfs frag report for /pvs (/dev/sdc1)  Mon Jun  6 02:30:03 PDT 2011
actual 118, ideal 105, fragmentation factor 11.02%
reorganization
Mon Jun  6 02:30:03 PDT 2011startxfs_fsr
Exit status for xfs_fsr= 0
Mon Jun  6 03:39:51 PDT 2011-end--xfs_fsr
frag_report
xfs frag report for /iso (/dev/sda3)  Mon Jun  6 03:39:51 PDT 2011
actual 6259, ideal 6206, fragmentation factor 0.85%
xfs frag report for /pvr (/dev/sdb1)  Mon Jun  6 03:39:52 PDT 2011
actual 959, ideal 899, fragmentation factor 6.26%
xfs frag report for /pvs (/dev/sdc1)  Mon Jun  6 03:39:52 PDT 2011
actual 111, ideal 105, fragmentation factor 5.41%
end

logfile for run_xfs_fsr run under login (the expected behavior):

SHELL=/bin/bash
PWD=/root/mycron
USER=root
SCRIPT=run_xfs_fsr  v1.03.001
log_file=/var/log/xfs_fsr.log
xfs report
Filesystem    Type    Size  Used Avail Use% Mounted on
/dev/sda3      xfs    144G  101G   44G  70% /iso
/dev/sdb1      xfs    1.9T  1.4T  461G  76% /pvr
/dev/sdc1      xfs    1.9T  223G  1.7T  12% /pvs
total            -    3.8T  1.7T  2.1T  45%
frag_report
xfs frag report for /iso (/dev/sda3)  Mon Jun  6 04:28:31 PDT 2011
actual 6259, ideal 6206, fragmentation factor 0.85%
xfs frag report for /pvr (/dev/sdb1)  Mon Jun  6 04:28:31 PDT 2011
actual 959, ideal 899, fragmentation factor 6.26%
xfs frag report for /pvs (/dev/sdc1)  Mon Jun  6 04:28:31 PDT 2011
actual 111, ideal 105, fragmentation factor 5.41%
reorganization
Mon Jun  6 04:28:31 PDT 2011startxfs_fsr
Found 3 mounted, writable, XFS filesystems
xfs_fsr -m /etc/mtab -t 10800 -f /root/mycron/.fsrlast_xfs ...
START: pass=0 ino=0 /dev/sda3 /iso
/iso start inode=0
<snip>
ino=266 already fully defragmented.
Completed all 10 passes
Exit status for xfs_fsr= 0
Mon Jun  6 04:30:26 PDT 2011-end--xfs_fsr
frag_report
xfs frag report for /iso (/dev/sda3)  Mon Jun  6 04:30:26 PDT 2011
actual 6259, ideal 6206, fragmentation factor 0.85%
xfs frag report for /pvr (/dev/sdb1)  Mon Jun  6 04:30:26 PDT 2011
actual 959, ideal 899, fragmentation factor 6.26%
xfs frag report for /pvs (/dev/sdc1)  Mon Jun  6 04:30:26 PDT 2011
actual 111, ideal 105, fragmentation factor 5.41%
end

xfs_fsr.sh:

#!/bin/sh  
# Run under BASH non-interactive shell
IFS="$(printf '\n\t')"  # Remove 'space', so filenames with spaces work well
oldpwd=$PWD
SHELL=/bin/bash
PATH="/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games"
cd /root/mycron
./run_xfs_fsr /var/log/xfs_fsr.log /root/mycron/.fsrlast_xfs 10800
cd $oldpwd
exit $?
2

It is almost always the result of environment variables not being declared correctly.

change the script itself to run ALL login scripts:
/etc/profile
$HOME/.profile
$HOME/.bashrc

and any other 'setup' scripts there are.

1 Like
3

Thanks for the suggestion, Jim

I was surprised to find that /etc/profile, $HOME/.profile, and $HOME/.bashrc are not executable.

So I ran run_xfs_fsr from cron printing environment variables.

From cron:

SHELL=/bin/bash
PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games
PWD=/root/mycron
LANG=en_US.UTF-8
SHLVL=1
HOME=/root
LOGNAME=root
_=/usr/bin/env

From login:

SHELL=/bin/bash
TERM=xterm
USER=root
LS_COLORS=<snip>
SUDO_USER=ljohnson
SUDO_UID=1000
USERNAME=root
PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games
MAIL=/var/mail/user
PWD=/root/mycron
LANG=en_US.UTF-8
SPEECHD_PORT=6560
SUDO_COMMAND=/bin/bash
HOME=/root
SHLVL=2
LOGNAME=root
LESSOPEN=| /usr/bin/lesspipe %s
SUDO_GID=1000
LESSCLOSE=/usr/bin/lesspipe %s %s
_=/usr/bin/env

As a sort of test, I added these environment variable to run_xfs_fsr:

TERM="xterm"
USER="root"
USERNAME="root"
MAIL="/var/mail/root"

The test failed, as xfs_fsr still output to syslog. Here is the env from this run:

TERM=xterm
SHELL=/bin/bash
USER=root
USERNAME=root
MAIL=/var/mail/root
PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games
PWD=/root/mycron
LANG=en_US.UTF-8
SHLVL=1
HOME=/root
LOGNAME=root
_=/usr/bin/env

Then I tried adding the LESSOPEN and LESSCLOSE, with the same unhappy results:

LESSOPEN=| /usr/bin/lesspipe %s
LESSCLOSE=/usr/bin/lesspipe %s %s

Then I tried changing the xfs_xfs.sh script to:

#!/bin/sh
# Run under BASH non-interactive shell
IFS="$(printf '\n\t')"  # Remove 'space', so filenames with spaces work well
oldpwd=$PWD
SHELL=/bin/bash
PATH="/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games"
USER="root"
USERNAME="root"
cd /root/mycron
bash run_xfs_fsr /var/log/xfs_fsr.log /root/mycron/.fsrlast_xfs 10800
cd $oldpwd
exit $?

hoping to properly initialize the BASH sub-shell. It produce no change in the result.

Still on my mind, however, is the question why the xfs utility xfs_db prints as expected, but the xfs reorganization program xfs_fsr does not???

4

Still having problems. The last attempt at making it work was:

xfs_fsr -v -t $time_for_run -f $left_off -m $used_mtab >$log_file 2>&1

where ">$log_file" was added to the xfs_fsr execute line.

The result was $log_file has binary data of some sort apparently inserted by this command.