Issue
TL;DR - Go down to the UPDATE for a toy example. The following was my original question before I was able to reproduce the issue in a small example, edited for clarity.
I do not understand what is going on here. I was pulling my hair out trying to figure out why a test I'd written in perl kept failing.
I was testing a function that turns off logging when an open of an output log file failed so that output to STDERR would not be suppressed. To test that it works, I created a file on the fly and chmod it to be unwritable. The resulting run of the code should print an open error along with all other STDERR to the STDERR output. I was doing the chmod in backticks before running my test.
However, what was happening was the logfile kept getting written to without error - so the test was failing. I started doing sanity checks by printing the output of ls -halF in various places to see where the permission change was happening. The initial chmod seemed to be working:
`echo > file.log;chmod 444 file.log;ls -halF file.log`
A subsequent ls -halF file.log after some other setup confirmed the intended permissions, but a very early line of code in my run of the actual test code said that the owner had write permission!
I eventually discovered a fix to the problem - by using the perl chmod() method instead of chmod in backticks, which makes me think there's some asynchronous stuff going on - and that made no sense to me.
I ended up trying that because in my numerous tests, I would occassionally see a test randomly succeed. So I wrote a quick loop to perform the same test over and over - and discovered that it randomly succeeds maybe 30% of the time! That's what made me think there may be some sort of asynchronicity to this issue, which I could not explain because I thought that backticks essentially waited for the process to complete since it returns the output - so what is going on here? I don't understand it.
For completeness - the actual test command is done in backticks too - it runs an independent script.
In my update below, I show a different case, but it demonstrates the randomness of the permissions states...
UPDATE
OK. This is a small self-contained example that demonstrates the problem. Pay attention to the different output of the second line in each case...
deleteme1.pl
#!/usr/bin/perl
print(`echo '' > deleteme.log;chmod 444 deleteme.log`);
print("1: ",`ls -l deleteme.log`);
`chmod 777 deleteme.log;rm -f deleteme.log`;
deleteme2.pl
#!/usr/bin/perl
print(`echo '' > deleteme.log;chmod 444 deleteme.log`);
print("2: ",`ls -l deleteme.log`);
chmod 0777, "deleteme.log";
unlink("deleteme.log");
Now observe the output of this repeating loop:
tcsh> foreach f ( `seq 1 30` )
perl deleteme1.pl
perl deleteme2.pl
end
1: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
2: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
1: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
2: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
1: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
2: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
1: -rw-r--r--@ 1 robleach staff 1 May 31 21:01 deleteme.log
2: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
1: -rw-r--r--@ 1 robleach staff 1 May 31 21:01 deleteme.log
2: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
1: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
2: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
1: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
2: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
1: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
2: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
1: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
2: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
1: -r--r--r--@ 1 robleach staff 1 May 31 21:01 deleteme.log
2: -r--r--r--@ 1 robleach staff 1 May 31 21:01 deleteme.log
1: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
2: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
1: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
2: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
1: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
2: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
1: -rw-r--r--@ 1 robleach staff 1 May 31 21:01 deleteme.log
2: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
1: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
2: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
1: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
2: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
1: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
2: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
1: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
2: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
1: -r--r--r--@ 1 robleach staff 1 May 31 21:01 deleteme.log
2: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
1: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
2: -r--r--r--@ 1 robleach staff 1 May 31 21:01 deleteme.log
1: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
2: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
1: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
2: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
1: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
2: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
1: -r--r--r--@ 1 robleach staff 1 May 31 21:01 deleteme.log
2: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
1: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
2: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
1: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
2: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
1: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
2: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
1: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
2: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
1: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
2: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
1: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
2: -r--r--r-- 1 robleach staff 1 May 31 21:01 deleteme.log
Note that the owner permission differences are always from deleteme1.pl. I think that the @ indicates extended attributes on macOS. That may have something to do with it, but there are cases where xattr is there, but no permission differences...
And I also suspect that the problem might possibly have something to do with this:
>ls -1 t | wc -l
46391
So something's happening asynchronously - what the hell is it?! Could it have something to do with SIP or csr(util)?
UPDATE 2
Here's an example truer to my specific case.
deleteme3.pl
This one represents my fix:
#!/usr/bin/perl
open(TLG,">deleteme.log");
print TLG '';
close(TLG);
chmod 0444, "deleteme.log";
if(open(TEST,">deleteme.log"))
{print "3 opened\n"}
else
{print "3 unable to open\n"}
chmod 0777, "deleteme.log";
unlink("deleteme.log");
deleteme4.pl
This one demonstrates the original problem.
#!/usr/bin/perl
`echo '' > deleteme.log;chmod 444 deleteme.log`;
if(open(TEST,">deleteme.log"))
{print "4 opened\n"}
else
{print "4 unable to open\n"}
chmod 0777, "deleteme.log";
unlink("deleteme.log");
I looped on these 2, as above:
tcsh>foreach f ( `seq 1 1000` )
perl deleteme3.pl
perl deleteme4.pl
end
In the 1000 tries, 3 unable to open was always output for deleteme3.pl. deleteme4.pl outputs 4 opened 4 times, and the rest are 4 unable to open.
Obviously, this doesn't demonstrate the frequency I was seeing where most of the time, my permissions showed owner-writable, but my guess is I was hitting some sort of sweet spot where something was mucking with my file permissions.
I would love to see if someone can reproduce these results on any platform, but I'm on macOS Sierra (10.12.6) running the system perl version 5.18.2.
Solution
I figured out the culprit for the asynchronous permissions changes. I was missing a critical piece of information in my question: the directory in which I was working was in Dropbox(!). I was unaware that dropbox ever modifies the permissions of files, but apparently it does.
With the Dropbox app running:
tcsh>foreach f ( `seq 1 50` )
foreach? perl deleteme1.pl
foreach? perl deleteme2.pl
foreach? end
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -rw-r--r--@ 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r--@ 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -rw-r--r--@ 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r--@ 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r--@ 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r--@ 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r--@ 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r--@ 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r--@ 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -rw-r--r--@ 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -rw-r--r--@ 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -rw-r--r--@ 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -rw-r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -rw-r--r--@ 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r--@ 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -rw-r--r--@ 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r--@ 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r--@ 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r--@ 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -rw-r--r--@ 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r--@ 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r--@ 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
1: -r--r--r--@ 1 robleach staff 1 Jun 2 12:09 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:09 deleteme.log
After quitting Dropbox (still in the dropbox directory):
>foreach f ( `seq 1 50` )
foreach? perl deleteme1.pl
foreach? perl deleteme2.pl
foreach? end
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
1: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
2: -r--r--r-- 1 robleach staff 1 Jun 2 12:11 deleteme.log
I discovered this because I was suspecting that SIP was the culprit. I rebooted in recovery mode and disabled SIP with csrutil disable. After rebooting, I ran the test loop and saw the same behavior of randomly changing permissions, but while that was running, I got a dialog from dropbox saying "Dropbox need to change permissions for the Folder /Users/robleach/Dropbox". I clicked OK and re-ran the loop and the random permissions issue was not evident.
I rebooted in recovery to re-enable SIP and rebooted again (with SIP active) just to confirm SIP was not involved. I re-ran the loop and again saw the random permissions issue. I then quit dropbox and re-ran the loop. The results are above.
I openly admit that I lacked the knowledge for it to even occur to me to realize that the dropbox aspect of this issue would be critical to answering this question.^ And I admit that I have my development project in Dropbox out of laziness - so I don't have to remember to commit/pull unfinished changes between performing work on 2 different computers. But I've had this specific project in dropbox for years and never ran into any issues until now (test #757, i.e. 756 tests performed as expected). So it hadn't even occurred to me that Dropbox could be a factor in this issue. I was unaware the sync made active changes to the files on the source device (i.e. where the file was created).
^ Cross-reference: https://meta.stackexchange.com/questions/348841/stack-mechanisms-are-evolving-toward-an-ideal-that-hampers-collaborative-problem
Answered By - hepcat72 Answer Checked By - David Goodson (WPSolving Volunteer)