Bizzare behavior on redirect of stdout

Oracle Linux 5.6 64-bit (derivative of RHEL)

Dear Ann Landers,

This is about as bizarre as anything I've ever seen.
I have a little test script I've been working with. When I redirect stdout to a file, no file. Make a copy of the script to another name. Execute it and redirect stdout, and I get the file.

Starting with the file listing, the file eds_scp_test is the file in question:

2015-05-28 10:58:38

oracle:$ ls -ltr eds*
-rw-r----- 1 oracle oinstall  5054 Aug 25  2014 eds_audit_report_generic.sql
-rwxr-x--- 1 oracle oinstall  4603 Aug 26  2014 eds_audit_report
-rw-r--r-- 1 oracle oinstall  3348 Apr  6 12:42 edstest.sql
-rwxr-x--- 1 oracle oinstall  2076 May 21 12:42 eds_ftp_test
-rw-r--r-- 1 oracle oinstall 16286 May 27 10:53 eds_ftp_test.log
-rwxr-x--- 1 oracle oinstall  1296 May 28 09:19 eds_scp_test


2015-05-28 10:58:42

oracle:$ cat eds_scp_test
#!/bin/sh
#===========================================================
# Purpose: test scp step from stage_refresh
#
#===========================================================
logfile=/u01/app/oracle/dba/eds_scp_test.log
rm $logfile
export NLS_DATE_FORMAT='dd-Mon-yyyy hh24:mi:ss'
echo ===================================================== 
echo Begin job at `date`
echo ===================================================== 
#===========================================================
# -- get backup files from prodserver 
#
echo ===================================================== 
echo deleteing old backup at `date` 
echo ===================================================== 
cd /backup/stgdb
rm *.rman
rm *.backup
rm *.alog

echo ===================================================== 
echo begin scp at `date` 
echo ===================================================== 
#scp -v oracle@prodserver:/u01/backup/prddb/* .                  
#scp -v prodserver:/u01/backup/prddb/* .  
#scp -q -v prodserver:/u01/backup/prddb/c4q7mt9e_1_1.alog  .  
# ------------------------------------------------------------------------
echo ===================================================== 
echo End job at `date` 
echo Log is at $logfile 
echo ===================================================== 
exit

Just execute the file, and everything is as expected:

2015-05-28 10:58:55

oracle:$ ./eds_scp_test
rm: cannot remove `/u01/app/oracle/dba/eds_scp_test.log': No such file or directory
=====================================================
Begin job at Thu May 28 10:59:39 CDT 2015
=====================================================
=====================================================
deleteing old backup at Thu May 28 10:59:39 CDT 2015
=====================================================
rm: cannot remove `*.rman': No such file or directory
rm: cannot remove `*.backup': No such file or directory
rm: cannot remove `*.alog': No such file or directory
=====================================================
begin scp at Thu May 28 10:59:39 CDT 2015
=====================================================
=====================================================
End job at Thu May 28 10:59:39 CDT 2015
Log is at /u01/app/oracle/dba/eds_scp_test.log
=====================================================

Execute it again, but redirect stdout to a log file (errout will still go to display)

2015-05-28 10:59:39

oracle:$ ./eds_scp_test > eds_scp_test.log
rm: cannot remove `*.rman': No such file or directory
rm: cannot remove `*.backup': No such file or directory
rm: cannot remove `*.alog': No such file or directory

But where's the log file?

2015-05-28 10:59:54

oracle:$ ls -ltr eds*
-rw-r----- 1 oracle oinstall  5054 Aug 25  2014 eds_audit_report_generic.sql
-rwxr-x--- 1 oracle oinstall  4603 Aug 26  2014 eds_audit_report
-rw-r--r-- 1 oracle oinstall  3348 Apr  6 12:42 edstest.sql
-rwxr-x--- 1 oracle oinstall  2076 May 21 12:42 eds_ftp_test
-rw-r--r-- 1 oracle oinstall 16286 May 27 10:53 eds_ftp_test.log
-rwxr-x--- 1 oracle oinstall  1296 May 28 09:19 eds_scp_test

Now, make an exact copy of the subject script:

2015-05-28 10:59:58

oracle:$ cp eds_scp_test eds_echo_test


2015-05-28 11:00:15

oracle:$ ls -ltr eds*
-rw-r----- 1 oracle oinstall  5054 Aug 25  2014 eds_audit_report_generic.sql
-rwxr-x--- 1 oracle oinstall  4603 Aug 26  2014 eds_audit_report
-rw-r--r-- 1 oracle oinstall  3348 Apr  6 12:42 edstest.sql
-rwxr-x--- 1 oracle oinstall  2076 May 21 12:42 eds_ftp_test
-rw-r--r-- 1 oracle oinstall 16286 May 27 10:53 eds_ftp_test.log
-rwxr-x--- 1 oracle oinstall  1296 May 28 09:19 eds_scp_test
-rwxr-x--- 1 oracle oinstall  1296 May 28 11:00 eds_echo_test

And test it

2015-05-28 11:00:19

oracle:$ ./eds_echo_test > eds_echo_test.log
rm: cannot remove `/u01/app/oracle/dba/eds_scp_test.log': No such file or directory
rm: cannot remove `*.rman': No such file or directory
rm: cannot remove `*.backup': No such file or directory
rm: cannot remove `*.alog': No such file or directory

And this time we get the expected log file:

2015-05-28 11:00:31

oracle:$ ls -ltr eds*
-rw-r----- 1 oracle oinstall  5054 Aug 25  2014 eds_audit_report_generic.sql
-rwxr-x--- 1 oracle oinstall  4603 Aug 26  2014 eds_audit_report
-rw-r--r-- 1 oracle oinstall  3348 Apr  6 12:42 edstest.sql
-rwxr-x--- 1 oracle oinstall  2076 May 21 12:42 eds_ftp_test
-rw-r--r-- 1 oracle oinstall 16286 May 27 10:53 eds_ftp_test.log
-rwxr-x--- 1 oracle oinstall  1296 May 28 09:19 eds_scp_test
-rwxr-x--- 1 oracle oinstall  1296 May 28 11:00 eds_echo_test
-rw-r--r-- 1 oracle oinstall   656 May 28 11:00 eds_echo_test.log

Sign me -- Perplexed.

The first time you run it, you get this error, because eds_scp_test.log does not exist:

rm: cannot remove `/u01/app/oracle/dba/eds_scp_test.log': No such file or directory

The second time, though, you do not get this error because the script actually succeeds in deleting it -- it's the very first thing it does.

Once you delete it, it naturally no longer exists. (Since it's busy, it will remain on disk -- but not in the folder -- until the script finishes. Once nothing is keeping it open, it will vanish for good.)

Hmm. Another case of getting so close to the code that one doesn't see it any more. In this case, the deleting of the log file within the script was a vestige of the larger script from which this test piece came. And that script was doing its own logging, rather than redirecting the output as a whole, as in my test. One thing I still don't understand though. Given that I was redirecting stdout of the script as a whole (myscript > myscript.log) even with a command inside the script deleting that same file, would not the next command that generates stdout in the script re-create the specified file?

Calling the write() system call does not create a file. Only open() does that, and the only time your program does that is when you do > filename .

In UNIX, where a file is and what its contents are, are separate questions. What really keeps a file's contents is its inode. If you hardlink a file into two different folders, they will share the same inode.

So when you delete a file which happens to be open, it will delete its directory listing, but the file itself -- its inode -- will still exist until you close it. (or the program holding it quits.) After that, it will be freed completely from disk.

This is a common trap new administrators fall into, incidentally. When they find a huge logfile filling up the disk, they delete it -- which makes things worse because the file remains open, but can't be shrunk from the console anymore. Whatever service is keeping it open would have to be stopped or convinced to close it before the disk space becomes free.

Ok. I understand. Thanks.