It turns out that my 'touch' command is actually getting executed, but
not when I expect it. Here is a recap of my script function which is
occasionally misbehaving:
# $1 mntpoint
fsaccesstest()
{
local RETRY_MAX=3
local RETRY_INTERVAL=3
local CHK_RESULT=1
TMP=`grep $1 /proc/mounts|awk '{print $1}'`
if [ "$TMP" != "" ]; then
for i in `seq 1 ${RETRY_MAX}`
do
touch $1/.accesstest
CHK_RESULT=$?
if [ ${CHK_RESULT} -eq 0 ] ; then
break
fi
logger -s -t ${LOGTAG} -p ${LOGFACILITY} "***
fsaccesstest test $1
failed. retrying... (${i}) ***"
sleep ${RETRY_INTERVAL}
done
if [ $CHK_RESULT -ne 0 ]; then
logger -t ${LOGTAG} -p ${LOGFACILITY} "*** fsaccesstest
test $1 failed. ***"
echo "*** fsaccess test $1 failed. ***" >/dev/console
## try remount it
umount $1
mount $TMP $1
return $?
fi
return 0
fi
return 1
}
Most of the time this function executes the 'touch' command without
errors as shown in the following strace output. The touch command
make just three system calls to open(), close(), and utimes() which
you can clearly see.
Success Scenario
================
[pid 23930] execve("/tmp/test-touch", ["/tmp/test-touch",
"/mnt/array1/.accesstest"], ["HOSTNAME=TS-2RVED8", "TERM=linux",
"SHELL=/bin/sh", "LIBRARY_PATH=/usr/lib:/usr/local"...,
"HUSHLOGIN=FALSE", "USER=root", "PATH=/bin:/sbin:/usr/bin:
[pid 23930] brk(0) = 0x18d2000
[pid 23930] mmap(NULL, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f4ab9676000
[pid 23930] mmap(NULL, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f4ab9675000
[pid 23930] access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such
file or directory)
[pid 23930] open("/etc/ld.so.cache", O_RDONLY) = 3
[pid 23930] fstat(3, {st_dev=makedev(8, 162), st_ino=90088,
st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096,
st_blocks=40, st_size=19548, st_atime=2011/11/19-08:39:02,
st_mtime=2011/11/15-08:39:00, st_ctime=2011/11/
[pid 23930] mmap(NULL, 19548, PROT_READ, MAP_PRIVATE, 3, 0) =
0x7f4ab9670000
[pid 23930] close(3) = 0
[pid 23930] open("/lib64/libc.so.6", O_RDONLY) = 3
[pid 23930] read(3,
"\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0`\333\1\0"..., 832) =
832
[pid 23930] fstat(3, {st_dev=makedev(8, 162), st_ino=285057,
st_mode=S_IFREG|0755, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096,
st_blocks=2616, st_size=1331216, st_atime=2011/11/19-08:10:31,
st_mtime=2010/06/29-12:51:27, st_ctime=201
[pid 23930] mmap(NULL, 2343048, PROT_READ|PROT_EXEC,
MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f4ab9320000
[pid 23930] mprotect(0x7f4ab9454000, 1044480, PROT_NONE) = 0
[pid 23930] mmap(0x7f4ab9553000, 20480, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x133000) = 0x7f4ab9553000
[pid 23930] mmap(0x7f4ab9558000, 16520, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f4ab9558000
[pid 23930] close(3) = 0
[pid 23930] mmap(NULL, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f4ab966f000
[pid 23930] mmap(NULL, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f4ab966e000
[pid 23930] arch_prctl(ARCH_SET_FS, 0x7f4ab966e6f0) = 0
[pid 23930] mprotect(0x7f4ab9553000, 12288, PROT_READ) = 0
[pid 23930] munmap(0x7f4ab9670000, 19548) = 0
[pid 23930] open("/mnt/array1/.accesstest", O_RDWR|O_CREAT, 0666) = 3
[pid 23930] close(3) = 0
[pid 23930] utimes("/mnt/array1/.accesstest", {4196394, 0}) = 0
[pid 23930] exit_group(0) = ?
Process 23756 resumed
Process 23930 detached
<... wait4 resumed> [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 23930
--- SIGCHLD (Child exited) @ 0 (0) ---
In the failure scenario, I had wrongly assumed that the touch command
was not being executed, when in fact it is. It's just that the
execution is deferred somehow and occurs after the call to 'logger',
which would not have been executed had the call to 'touch' somehow
failed or returned too soon. So it looks I am being afflicted with
out of order execution problems. I am expecting that if my script
makes a call to 'touch' it should not return until the command has
been completely executed, i.e. the child process reaped, and exit
status determined. This doesn't seem to be happening.
Please forgive for the volume of data.
Failure Scenario
================
[pid 26415] execve("/tmp/test-touch", ["/tmp/test-touch",
"/mnt/array1/.accesstest"], ["HOSTNAME=TS-2RVED8", "TERM=linux",
"SHELL=/bin/sh", "LIBRARY_PATH=/usr/lib:/usr/local"...,
"HUSHLOGIN=FALSE", "USER=root", "PATH=/bin:/sbin:/usr/bin:/usr/sb"...,
"MAIL=/var/spool/mail/root", "C_INCLUDE_PATH=/usr/include:/usr"...,
"PWD=/usr/local/sbin", "HOME=/root", "SHLVL=2", "LOGNAME=root",
"_=/tmp/test-touch"] <unfinished ...>
[pid 26391] stat("/dev/disk11_2", <unfinished ...>
[pid 26389] ioctl(3, BLKBSZGET <unfinished ...>
[pid 26391] <... stat resumed> {st_dev=makedev(8, 162), st_ino=317730,
st_mode=S_IFBLK|0755, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096,
st_blocks=0, st_rdev=makedev(8, 178), st_atime=2011/11/19-03:53:49,
st_mtime=2011/11/15-07:45:2
[pid 26389] <... ioctl resumed> , 0x2178078) = 0
[pid 26389] lseek(3, 0, SEEK_SET <unfinished ...>
[pid 23756] clone( <unfinished ...>
[pid 26391] open("/dev/disk11_2", O_RDONLY|O_DIRECT|O_NOATIMEProcess
26416 attached (waiting for parent)
<unfinished ...>
[pid 26415] <... execve resumed> ) = 0
[pid 26391] <... open resumed> ) = 3
[pid 26391] fstat(3, <unfinished ...>
[pid 26389] <... lseek resumed> ) = 0
[pid 26415] brk(0 <unfinished ...>
[pid 26391] <... fstat resumed> {st_dev=makedev(8, 162),
st_ino=317730, st_mode=S_IFBLK|0755, st_nlink=1, st_uid=0, st_gid=0,
st_blksize=4096, st_blocks=0, st_rdev=makedev(8, 178),
st_atime=2011/11/19-03:53:49, st_mtime=2011/11/15-07:45:
[pid 26415] <... brk resumed> ) = 0x1889000
[pid 26391] ioctl(3, BLKBSZGET <unfinished ...>
[pid 26415] mmap(NULL, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0 <unfinished ...>
[pid 26391] <... ioctl resumed> , 0x1dd50e8) = 0
[pid 26415] <... mmap resumed> ) = 0x7ff473ff5000
[pid 26391] lseek(3, 0, SEEK_SET <unfinished ...>
[pid 26389] read(3, <unfinished ...>
[pid 26415] mmap(NULL, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0 <unfinished ...>
[pid 26391] <... lseek resumed> ) = 0
Process 26416 resumed (parent 23756 ready)
[pid 23756] <... clone resumed> child_stack=0,
flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD,
child_tidptr=0x7f7d14bdb780) = 26416
[pid 26415] <... mmap resumed> ) = 0x7ff473ff4000
[pid 26391] read(3, <unfinished ...>
[pid 26416] rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
[pid 26416] rt_sigaction(SIGTSTP, {SIG_DFL}, {SIG_DFL}, 8) = 0
[pid 26416] rt_sigaction(SIGTTIN, {SIG_DFL}, <unfinished ...>
[pid 23756] rt_sigaction(SIGINT, {0x433b20, [], SA_RESTORER,
0x7f7d147b93a0}, <unfinished ...>
[pid 26415] access("/etc/ld.so.preload", R_OK <unfinished ...>
[pid 23756] <... rt_sigaction resumed> {SIG_IGN}, 8) = 0
[pid 26415] <... access resumed> ) = -1 ENOENT (No such file or
directory)
[pid 23756] wait4(-1, Process 23756 suspended
<unfinished ...>
[pid 26416] <... rt_sigaction resumed> {SIG_DFL}, 8) = 0
[pid 26415] open("/etc/ld.so.cache", O_RDONLY <unfinished ...>
[pid 26416] rt_sigaction(SIGTTOU, {SIG_DFL}, <unfinished ...>
[pid 26415] <... open resumed> ) = 3
[pid 26416] <... rt_sigaction resumed> {SIG_DFL}, 8) = 0
[pid 26415] fstat(3, <unfinished ...>
[pid 26416] rt_sigaction(SIGINT, {SIG_IGN}, <unfinished ...>
[pid 26415] <... fstat resumed> {st_dev=makedev(8, 162), st_ino=90088,
st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096,
st_blocks=40, st_size=19548, st_atime=2011/11/19-08:39:02,
st_mtime=2011/11/15-08:39:00, st_cti
[pid 26416] <... rt_sigaction resumed> {SIG_IGN}, 8) = 0
[pid 26415] mmap(NULL, 19548, PROT_READ, MAP_PRIVATE, 3, 0 <unfinished ...>
[pid 26416] rt_sigaction(SIGQUIT, {SIG_IGN}, <unfinished ...>
[pid 26415] <... mmap resumed> ) = 0x7ff473fef000
[pid 26416] <... rt_sigaction resumed> {SIG_IGN}, 8) = 0
[pid 26415] close(3 <unfinished ...>
[pid 26416] rt_sigaction(SIGCHLD, {SIG_DFL}, <unfinished ...>
[pid 26415] <... close resumed> ) = 0
[pid 26416] <... rt_sigaction resumed> {SIG_DFL}, 8) = 0
[pid 26415] open("/lib64/libc.so.6", O_RDONLY <unfinished ...>
[pid 26391] <... read resumed>
"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096) =
4096
[pid 26391] close(3 <unfinished ...>
[pid 26416] execve("/usr/bin/logger", ["logger", "-s", "-t",
"diskmon", "-p", "local0.info", "*** fsaccesstest test
/mnt/array"...], ["HOSTNAME=TS-2RVED8", "TERM=linux", "SHELL=/bin/sh",
"LIBRARY_PATH=/usr/lib:/usr/local"..., "HUSHLOGIN=FALSE", "USER=root",
"PATH=/bin:/sbin:/usr/bin:/usr/sb"..., "MAIL=/var/spool/mail/root",
"C_INCLUDE_PATH=/usr/include:/usr"..., "PWD=/usr/local/sbin",
"HOME=/root", "SHLVL=2", "LOGNAME=root", "_=/usr/bin/logger"]
<unfinished ...>
[pid 26415] <... open resumed> ) = 3
[pid 26391] <... close resumed> ) = 0
[pid 26415] read(3, <unfinished ...>
[pid 26391] stat("/dev/disk11_3", <unfinished ...>
[pid 26415] <... read resumed>
"\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0`\333\1\0"..., 832) =
832
[pid 26391] <... stat resumed> {st_dev=makedev(8, 162), st_ino=318096,
st_mode=S_IFBLK|0755, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096,
st_blocks=0, st_rdev=makedev(8, 179), st_atime=2011/11/19-03:53:49,
st_mtime=2011/11/15-07:45:2
[pid 26415] fstat(3, <unfinished ...>
[pid 26391] stat("/dev/disk11_3", <unfinished ...>
[pid 26415] <... fstat resumed> {st_dev=makedev(8, 162),
st_ino=285057, st_mode=S_IFREG|0755, st_nlink=1, st_uid=0, st_gid=0,
st_blksize=4096, st_blocks=2616, st_size=1331216,
st_atime=2011/11/19-08:10:31, st_mtime=2010/06/29-12:51:27, s
[pid 26391] <... stat resumed> {st_dev=makedev(8, 162), st_ino=318096,
st_mode=S_IFBLK|0755, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096,
st_blocks=0, st_rdev=makedev(8, 179), st_atime=2011/11/19-03:53:49,
st_mtime=2011/11/15-07:45:2
[pid 26415] mmap(NULL, 2343048, PROT_READ|PROT_EXEC,
MAP_PRIVATE|MAP_DENYWRITE, 3, 0 <unfinished ...>
[pid 26391] open("/dev/disk11_3", O_RDONLY|O_DIRECT|O_NOATIME
<unfinished ...>
[pid 26415] <... mmap resumed> ) = 0x7ff473c9f000
[pid 26391] <... open resumed> ) = 3
[pid 26415] mprotect(0x7ff473dd3000, 1044480, PROT_NONE <unfinished
...>
[pid 26391] fstat(3, <unfinished ...>
[pid 26415] <... mprotect resumed> ) = 0
[pid 26391] <... fstat resumed> {st_dev=makedev(8, 162),
st_ino=318096, st_mode=S_IFBLK|0755, st_nlink=1, st_uid=0, st_gid=0,
st_blksize=4096, st_blocks=0, st_rdev=makedev(8, 179),
st_atime=2011/11/19-03:53:49, st_mtime=2011/11/15-07:45:
[pid 26415] mmap(0x7ff473ed2000, 20480, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x133000 <unfinished ...>
[pid 26391] ioctl(3, BLKBSZGET <unfinished ...>
[pid 26415] <... mmap resumed> ) = 0x7ff473ed2000
[pid 26391] <... ioctl resumed> , 0x1dd4588) = 0
[pid 26415] mmap(0x7ff473ed7000, 16520, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0 <unfinished ...>
[pid 26391] lseek(3, 0, SEEK_SET <unfinished ...>
[pid 26415] <... mmap resumed> ) = 0x7ff473ed7000
[pid 26391] <... lseek resumed> ) = 0
[pid 26415] close(3 <unfinished ...>
[pid 26391] read(3, <unfinished ...>
[pid 26415] <... close resumed> ) = 0
[pid 26389] <... read resumed>
"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096) =
4096
[pid 26416] <... execve resumed> ) = 0
[pid 26415] mmap(NULL, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7ff473fee000
[pid 26391] <... read resumed>
"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096) =
4096
[pid 26416] brk(0 <unfinished ...>
[pid 26415] mmap(NULL, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0 <unfinished ...>
[pid 26416] <... brk resumed> ) = 0x14ca000
[pid 26415] <... mmap resumed> ) = 0x7ff473fed000
[pid 26416] mmap(NULL, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0 <unfinished ...>
[pid 26415] arch_prctl(ARCH_SET_FS, 0x7ff473fed6f0 <unfinished ...>
[pid 26416] <... mmap resumed> ) = 0x7f379a600000
[pid 26415] <... arch_prctl resumed> ) = 0
[pid 26391] close(3 <unfinished ...>
[pid 26416] mmap(NULL, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0 <unfinished ...>
[pid 26391] <... close resumed> ) = 0
[pid 26389] close(3 <unfinished ...>
[pid 26416] <... mmap resumed> ) = 0x7f379a5ff000
[pid 26391] stat("/dev/disk11_4", <unfinished ...>
[pid 26389] <... close resumed> ) = 0
[pid 26416] access("/etc/ld.so.preload", R_OK <unfinished ...>
[pid 26391] <... stat resumed> {st_dev=makedev(8, 162), st_ino=317750,
st_mode=S_IFBLK|0755, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096,
st_blocks=0, st_rdev=makedev(8, 180), st_atime=2011/11/19-03:53:48,
st_mtime=2011/11/15-07:45:2
[pid 26389] stat("/dev/disk7_2", <unfinished ...>
[pid 26416] <... access resumed> ) = -1 ENOENT (No such file or
directory)
[pid 26415] mprotect(0x7ff473ed2000, 12288, PROT_READ <unfinished ...>
[pid 26416] open("/etc/ld.so.cache", O_RDONLY <unfinished ...>
[pid 26415] <... mprotect resumed> ) = 0
[pid 26416] <... open resumed> ) = 3
[pid 26415] munmap(0x7ff473fef000, 19548 <unfinished ...>
[pid 26416] fstat(3, <unfinished ...>
[pid 26415] <... munmap resumed> ) = 0
[pid 26416] <... fstat resumed> {st_dev=makedev(8, 162), st_ino=90088,
st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096,
st_blocks=40, st_size=19548, st_atime=2011/11/19-08:39:02,
st_mtime=2011/11/15-08:39:00, st_cti
[pid 26415] open("/mnt/array1/.accesstest", O_RDWR|O_CREAT, 0666
<unfinished ...>
[pid 26416] mmap(NULL, 19548, PROT_READ, MAP_PRIVATE, 3, 0 <unfinished
...>
[pid 26415] <... open resumed> ) = 3
[pid 26416] <... mmap resumed> ) = 0x7f379a5fa000
[pid 26415] close(3 <unfinished ...>
[pid 26416] close(3 <unfinished ...>
[pid 26415] <... close resumed> ) = 0
[pid 26416] <... close resumed> ) = 0
[pid 26415] utimes("/mnt/array1/.accesstest", {4196394, 0} <unfinished
...>
[pid 26416] open("/lib64/libcrypt.so.1", O_RDONLY <unfinished ...>
[pid 26391] stat("/dev/disk11_4", <unfinished ...>
[pid 26416] <... open resumed> ) = 3
[pid 26415] <... utimes resumed> ) = 0
[pid 26416] read(3, <unfinished ...>
[pid 26415] exit_group(0) = ?
Process 23756 resumed
Process 26415 detached
[pid 23756] <... wait4 resumed> [{WIFEXITED(s) && WEXITSTATUS(s) ==
0}], 0, NULL) = 26415
[pid 23756] --- SIGCHLD (Child exited) @ 0 (0) ---
