cp -p in the filesystem updates both mtime and ctime when it should only update ctime.

[flipfloptech]

What happened: cp -p does not keep mtime. Instead it looks like mtime is updated with ctime, which goes against every other file system I tested.

What you expected to happen: cp -p keeps atime and mtime and only changes ctime

How to reproduce it (as minimally and precisely as possible): cp -p oldfile newfile; stat oldfile; stat newfile; and compare results

Anything else we need to know? I tested cp -p on xfs, btrfs, ext4 and in each case, cp -p keeps the atime and mtime and only updates ctime leading me to believe this is a bug in the filesystem.

Environment:

• JuiceFS version (use juicefs --version) or Hadoop Java SDK version: git master
• Cloud provider or hardware configuration running JuiceFS:
• OS (e.g cat /etc/os-release): RHEL 7.9
• Kernel (e.g. uname -a): 3.10.0-1160.25.1.el7.e86_64
• Object storage (cloud provider and region, or self maintained): MINIO self maintained
• Metadata engine info (version, cloud provider managed or self maintained): TiKV self maintained
• Network connectivity (JuiceFS to metadata engine, JuiceFS to object storage): 10GBps
• Others:

[SandyXSD]

It does change only the ctime in my test. Could you run cat <mount_point>/.accesslog in another shell when you run the test, and then post the log here?

root@test:/mnt/jfs# stat a
  File: a
  Size: 0               Blocks: 0          IO Block: 65536  regular empty file
Device: 36h/54d Inode: 2           Links: 1
Access: (0644/-rw-r--r--)  Uid: (    0/    root)   Gid: (    0/    root)
Access: 2023-01-31 09:17:42.012940813 +0800
Modify: 2023-01-31 09:17:42.012940813 +0800
Change: 2023-01-31 09:17:42.012940813 +0800
 Birth: -
root@test:/mnt/jfs# cp -p a b
root@test:/mnt/jfs# stat b
  File: b
  Size: 0               Blocks: 0          IO Block: 65536  regular empty file
Device: 36h/54d Inode: 3           Links: 1
Access: (0644/-rw-r--r--)  Uid: (    0/    root)   Gid: (    0/    root)
Access: 2023-01-31 09:17:42.012940813 +0800
Modify: 2023-01-31 09:17:42.012940813 +0800
Change: 2023-01-31 09:17:57.599775419 +0800
 Birth: -

[flipfloptech]

@SandyXSD thanks for looking into this, that is what I would have expected as well. To be honest, this log is awesome but looking at it makes me question where it's happening even more so.

Here are the commands ran:

Here is a copy and paste of the log:

2023.01.31 17:32:45.005490 [uid:0,gid:0,pid:243382] getattr (2): OK (2,[drwxrwxr-x:0040775,2,0,130,1673487814,1675204346,1675204346,4096]) <0.001664>
2023.01.31 17:32:45.007006 [uid:0,gid:0,pid:243382] lookup (2,log.txt): OK (4101203,[-rw-rw-r--:0100664,1,1130419,500,1665424815,1674762055,1674762055,15508]) <0.001466>
2023.01.31 17:32:49.598815 [uid:0,gid:0,pid:277781] getattr (2): OK (2,[drwxrwxr-x:0040775,2,0,130,1673487814,1675204346,1675204346,4096]) <0.000970>
2023.01.31 17:32:49.599668 [uid:0,gid:0,pid:277781] lookup (2,log_p): no such file or directory <0.000791>
2023.01.31 17:32:49.601112 [uid:0,gid:0,pid:277781] lookup (2,log.txt): OK (4101203,[-rw-rw-r--:0100664,1,1130419,500,1665424815,1674762055,1674762055,15508]) <0.001335>
2023.01.31 17:32:49.601727 [uid:0,gid:0,pid:277781] lookup (2,log_p): no such file or directory <0.000576>
2023.01.31 17:32:49.602467 [uid:0,gid:0,pid:277781] open (4101203): OK [fh:14431980] <0.000704>
2023.01.31 17:32:49.603069 [uid:0,gid:0,pid:277781] lookup (2,log_p): no such file or directory <0.000567>
2023.01.31 17:32:49.605965 [uid:0,gid:0,pid:277781] create (2,log_p,-rw-------:0100600): OK (11184775,[-rw-------:0100600,1,0,0,1675204369,1675204369,1675204369,0]) [fh:14431981] <0.002852>
2023.01.31 17:32:49.606060 [uid:0,gid:0,pid:277781] write (11184775,15508,0,14431981): OK <0.000026>
2023.01.31 17:32:49.610132 [uid:0,gid:0,pid:277781] setattr (11184775,0x30,[atime=1665424815,mtime=1674762055]): OK (11184775,[-rw-------:0100600,1,0,0,1665424815,1674762055,1675204369,15508]) <0.003999>
2023.01.31 17:32:49.612285 [uid:0,gid:0,pid:277781] setattr (11184775,0x6,[uid=1130419,gid=500]): OK (11184775,[-rw-------:0100600,1,1130419,500,1665424815,1674762055,1675204369,15508]) <0.002114>
2023.01.31 17:32:49.614544 [uid:0,gid:0,pid:277781] setattr (11184775,0x1,[mode=-rw-rw-r--:00664]): OK (11184775,[-rw-rw-r--:0100664,1,1130419,500,1665424815,1674762055,1675204369,15508]) <0.002127>
2023.01.31 17:32:49.619515 [uid:0,gid:0,pid:277781] flush (11184775,14431981,18A443916663FE2E): OK <0.004869>
2023.01.31 17:32:49.619551 [uid:0,gid:0,pid:0] release (11184775,14431981): OK <0.000005>
2023.01.31 17:32:49.619564 [uid:0,gid:0,pid:277781] flush (4101203,14431980,18A443916663FE2E): OK <0.000001>
2023.01.31 17:32:49.619594 [uid:0,gid:0,pid:0] release (4101203,14431980): OK <0.000005>
2023.01.31 17:32:52.050501 [uid:0,gid:0,pid:296215] getattr (2): OK (2,[drwxrwxr-x:0040775,2,0,130,1673487814,1675204369,1675204369,4096]) <0.000835>
2023.01.31 17:32:52.051976 [uid:0,gid:0,pid:296215] lookup (2,log_p): OK (11184775,[-rw-rw-r--:0100664,1,1130419,500,1665424815,1675204369,1675204369,15508]) <0.001420>

[SandyXSD]

Well, this looks like a bug. It was good in my test because the file was empty. For a non-empty file, the mtime is correct for a very short time (set by setattr), and is changed again after data flushed.
Sorry but we don't have a quick fix for it.

[flipfloptech]

@SandyXSD not a problem, we use a custom script that moves the data around and put a work around in it, to touch the files referring to the originals before removing them which works. Luckily the metadata flies with TiKV for us compared to our gluster deployment that it isn't to impacting. If there is absolutely anything I can do to help troubleshoot the issue, I'm available. We are using JFS for petabytes of warm storage so I'm invested 💯

[amiga23]

From my point of this issue is important to fix, as it means juicefs is not POSIX compliant.