CephFS: Failure in smb2.timestamps.time_t_*

[spuiuk]

While adding new smbtorture tests in PR #65, we have come across a few failures. This particular issue deals with the failures in the smb2.timestamps.time_t* tests.

cephfs: (fuse mount)
samba3.smb2.timestamps.time_t_15032385535
samba3.smb2.timestamps.time_t_10000000000
samba3.smb2.timestamps.time_t_-1
samba3.smb2.timestamps.time_t_-2
samba3.smb2.timestamps.time_t_1968

cephfs.vfs: (vfs mount)
samba3.smb2.timestamps.time_t_15032385535
samba3.smb2.timestamps.time_t_10000000000
samba3.smb2.timestamps.time_t_4294967295
samba3.smb2.timestamps.time_t_1
samba3.smb2.timestamps.time_t_0
samba3.smb2.timestamps.time_t_-1
samba3.smb2.timestamps.time_t_-2
samba3.smb2.timestamps.time_t_1968
samba3.smb2.timestamps.freeze-thaw

[spuiuk]

source4/torture/smb2/timestamps.c:

struct torture_suite *suite = torture_suite_create(ctx, "timestamps");
torture_suite_add_1smb2_test(suite, "time_t_1968", test_time_t_1968);

static bool test_time_t_1968(struct torture_context *tctx,
                             struct smb2_tree *tree)
{
        return test_time_t(tctx, tree, "test_time_t_1968.txt",
                           -63158400 /* 1968 */);
}

static bool test_time_t(struct torture_context *tctx,
                        struct smb2_tree *tree,
                        const char *fname,
                        time_t t)
{
..
        struct timespec ts = { .tv_sec = t };
..
        status = smb2_create(tree, tctx, &cr);
..
        nttime = full_timespec_to_nt_time(&ts);
        si.basic_info.in.create_time = nttime;
        si.basic_info.in.write_time = nttime;
        si.basic_info.in.change_time = nttime;  
..
        status = smb2_setinfo_file(tree, &si);
..
        status = smb2_getinfo_file(tree, tctx, &gi);
        torture_assert_ntstatus_ok_goto(tctx, status, ret, done,
                                        "smb2_getinfo_file failed\n");

        torture_comment(tctx, "Got: create: %s, write: %s, change: %s\n",
                        nt_time_string(tctx, gi.basic_info.out.create_time),
                        nt_time_string(tctx, gi.basic_info.out.write_time),
                        nt_time_string(tctx, gi.basic_info.out.change_time));

        torture_assert_u64_equal_goto(tctx,
                                      nttime,
                                      gi.basic_info.out.create_time,
                                      ret, done,
                                      "Wrong create time\n");
..
}

Running test samba3.smb2.timestamps.time_t_1968
Error seen:

test: samba3.smb2.timestamps.time_t_1968
time: 2024-03-11 14:07:52.575517Z
Got: create: Mon Mar 11 14:07:53 2024 UTC, write: Mon Jan  1 00:00:00 1968 UTC, change: Mon Jan  1 00:00:00 1968 UTC
time: 2024-03-11 14:07:52.678985Z
failure: samba3.smb2.timestamps.time_t_1968 [
Exception: ../../source4/torture/smb2/timestamps.c:165: nttime was 115813152000000000 (0x19B7372B9474000), expected 133546396726578833 (0x1DA73BD81EBCE91): Wrong create time
]

[spuiuk]

Checking vfs_defaultfs:

  static int vfswrap_fntimes(vfs_handle_struct *handle,
                             files_struct *fsp,
                             struct smb_file_time *ft)
  {
..

          if (!fsp->fsp_flags.is_pathref) {
                  result = futimens(fsp_get_io_fd(fsp), times); <-- Where we set the timestamp on the file.
                  goto out;
          }
..

[anoopcs9]

I was looking into the extra failures with cephfs.vfs for which I have identified a possible fix.

[anoopcs9]

I was looking into the extra failures with cephfs.vfs for which I have identified a possible fix.

!3553 should fix the difference in test failures.

[synarete]

I was looking into the extra failures with cephfs.vfs for which I have identified a possible fix.

!3553 should fix the difference in test failures.

@anoopcs9 Nice catch. Will update vfs_ceph_ll.c as well.

[spuiuk]

Thanks @anoopcs9, I tested the patch out in my devel environment and can confirm that the patch indeed fixes the problem seen on ceph_vfs module. However there is also a problem seen with write times. This same problem is also seen with ceph-fuse mounts. I therefore think that this is an issue with CephFS. I am working on writing a reproducer to recrete the issue without samba.

cephfs_vfs:

smbtorture 4.21.0pre1-GIT-b2bba4eebd8
Using seed 1710421156
time: 2024-03-14 12:59:16.930825Z
test: samba3.smb2.timestamps.time_t_1968
time: 2024-03-14 12:59:16.931685Z
GSSAPI to 'localhost' does not make sense
Got: create: Mon Jan  1 00:00:00 1968 UTC, write: Mon Jan  1 00:00:00 1968 UTC, change: Mon Jan  1 00:00:00 1968 UTC
Got: create: Mon Jan  1 00:00:00 1968 UTC, write: Thu Feb  7 06:28:16 2104 UTC, change: Thu Feb  7 06:28:16 2104 UTC
time: 2024-03-14 12:59:17.008233Z
failure: samba3.smb2.timestamps.time_t_1968 [
Exception: ../../source4/torture/smb2/timestamps.c:250: nttime was 115813152000000000 (0x19B7372B9474000), expected 158762824960000000 (0x23409F2B9474000): Wrong write time

]

cephfs-fuse:

Using seed 1710421157
time: 2024-03-14 12:59:17.834758Z
test: samba3.smb2.timestamps.time_t_1968
time: 2024-03-14 12:59:17.835973Z
GSSAPI to 'localhost' does not make sense
Got: create: Mon Jan  1 00:00:00 1968 UTC, write: Mon Jan  1 00:00:00 1968 UTC, change: Mon Jan  1 00:00:00 1968 UTC
Got: create: Mon Jan  1 00:00:00 1968 UTC, write: Thu Feb  7 06:28:16 2104 UTC, change: Thu Feb  7 06:28:16 2104 UTC
time: 2024-03-14 12:59:17.877902Z
failure: samba3.smb2.timestamps.time_t_1968 [
Exception: ../../source4/torture/smb2/timestamps.c:250: nttime was 115813152000000000 (0x19B7372B9474000), expected 158762824960000000 (0x23409F2B9474000): Wrong write time

]

[anoopcs9]

However there is also a problem seen with write times.

And if I remember correctly I have seen mismatch with change_time also while running smb2.timestamps.time_t-1_.

[spuiuk]

A simple c program to test the setting of timespec.

#include <cephfs/libcephfs.h>
#include <stdlib.h>
#include <stdio.h>
#include <sys/stat.h>
#include <time.h>
#include <unistd.h>

void print_times(struct ceph_statx *stx)
{
	printf("Access time: sec %jd %09ld\n", stx->stx_atime.tv_sec, stx->stx_atime.tv_nsec);
//	printf("Creation time: sec %jd nsec %09ld\n", stx->stx_btime.tv_sec, stx->stx_btime.tv_nsec);
//	printf("Change time: sec %jd nsec %09ld\n", stx->stx_ctime.tv_sec, stx->stx_ctime.tv_nsec);
	printf("Modification time: sec %jd %09ld\n", stx->stx_mtime.tv_sec, stx->stx_mtime.tv_nsec);
}

int main()
{
	struct ceph_mount_info *cmount = NULL;
	char *filename = "test1";
	int fd;
	char *teststr = "Hello World!";
	struct ceph_statx stx;
	struct timespec now[2];

	timespec_get(&now[0], TIME_UTC);
	timespec_get(&now[1], TIME_UTC);
	printf("Current time\n");
	printf("Access time: %jd %09ld\n", now[0].tv_sec, now[0].tv_nsec);
	printf("Modification time: %jd %09ld\n", now[1].tv_sec, now[1].tv_nsec);
	printf("\n");

	// Sleep for 3 seconds
	sleep(3);

	ceph_create(&cmount, NULL);
	ceph_conf_read_file(cmount, "/etc/ceph/ceph.conf");
	ceph_mount(cmount, NULL);

	printf("Create a new file\n");
	fd = ceph_open(cmount, filename, O_WRONLY|O_CREAT, 0644);
	ceph_write(cmount, fd, teststr, sizeof(teststr), 0);
	ceph_close(cmount, fd);

	printf("Print timestamps set at creation\n");
	fd = ceph_open(cmount, filename, O_RDONLY, 0);
	ceph_fstatx(cmount, fd, &stx,CEPH_STATX_BASIC_STATS|CEPH_STATX_BTIME, 0);
	print_times(&stx);
	ceph_close(cmount, fd);
	printf("\n");

	printf("Changing the timestamps to earlier 'Current time' and print set values\n");
	fd = ceph_open(cmount, filename, O_RDONLY, 0);
	ceph_futimens(cmount, fd, now);
	ceph_fstatx(cmount, fd, &stx,CEPH_STATX_BASIC_STATS|CEPH_STATX_BTIME, 0);
	print_times(&stx);
	ceph_unlink(cmount, filename);
	printf("\n");

	ceph_shutdown(cmount);

	return 0;
}

Compile above with the following command
gcc -o test -D_FILE_OFFSET_BITS=64 -lcephfs test.c

# ./test 
Current time
Access time: 1710440093 943858653
Modification time: 1710440093 943858716

Create a new file
Print timestamps set at creation
Access time: sec 1710440096 959176132
Modification time: sec 1710440096 960562607

Changing the timestamps to earlier 'Current time' and print set values
Access time: sec 1710440093 943858653
Modification time: sec 1710440093 943858716

The changed timespec is as per what we have set with ceph_futimens. ie. This doesn't recreate the problem we expected to see. Will look at what sama is doing in closer detail to investigate further.

[spuiuk]

I just took a closer look at vfs_ceph.c and realised that we never call ceph_futimens(). We instead call ceph_setattrx() and never really set the time on this fd.

static int cephwrap_fntimes(struct vfs_handle_struct *handle,
			    files_struct *fsp,
			    struct smb_file_time *ft)
{
	struct ceph_statx stx = { 0 };
	int result;
	int mask = 0;

	if (!is_omit_timespec(&ft->atime)) {
		stx.stx_atime = ft->atime;
		mask |= CEPH_SETATTR_ATIME;
	}
	if (!is_omit_timespec(&ft->mtime)) {
		stx.stx_mtime = ft->mtime;
		mask |= CEPH_SETATTR_MTIME;
	}
	if (!is_omit_timespec(&ft->create_time)) {
		stx.stx_btime = ft->create_time;
		mask |= CEPH_SETATTR_BTIME;
		set_create_timespec_ea(fsp, ft->create_time);
	}

	if (!mask) {
		return 0;
	}

	if (!fsp->fsp_flags.is_pathref) {
		/*
		 * We can use an io_fd to set xattrs.
		 */
		result = ceph_fsetattrx(handle->data,
					fsp_get_io_fd(fsp),
					&stx,
					mask);
	} else {
		/*
		 * This is no longer a handle based call.
		 */
		result = ceph_setattrx(handle->data,
				       fsp->fsp_name->base_name,
				       &stx,
				       mask,
				       0);
	}

	DBG_DEBUG("[CEPH] ntimes(%p, %s, {%ld, %ld, %ld, %ld}) = %d\n",
		  handle, fsp_str_dbg(fsp), ft->mtime.tv_sec, ft->atime.tv_sec,
		  ft->ctime.tv_sec, ft->create_time.tv_sec, result);

	return result;
}

[spuiuk]

Taking a closer look at the smbtorture test

static bool test_time_t(struct torture_context *tctx,
struct smb2_tree *tree,
const char *fname,
time_t t)
{
..
// We first create a file
status = smb2_create(tree, tctx, &cr);
..
// setinfo
status = smb2_setinfo_file(tree, &si); <-- This is where the ceph_fntimes is run.
..
//Run getinfo
status = smb2_getinfo_file(tree, tctx, &gi); <-- Here we get the correct information.
..
//close file
status = smb2_util_close(tree, handle);

//Open file
status = smb2_create(tree, tctx, &cr);
..
//Run getinfo
status = smb2_getinfo_file(tree, tctx, &gi); <-- the info returned here seems to be wrong.
..

Causing a failure in line 250. It seems to be receiving the wrong information the second time. We need to understandwhy.

If you look at the output of the test, we see the following lines
Got: create: Mon Jan 1 00:00:00 1968 UTC, write: Mon Jan 1 00:00:00 1968 UTC, change: Mon Jan 1 00:00:00 1968 UTC
Got: create: Mon Jan 1 00:00:00 1968 UTC, write: Thu Feb 7 06:28:16 2104 UTC, change: Thu Feb 7 06:28:16 2104 UTC

The second line is from the second getinfo() call.

[spuiuk]

With this new reproducer, the problem now appears to be because of limitations of the ceph filesystem. Given below is a reproducer which sets and gets the mtimes for files both on a ceph filesystem and a local filesystem.

/*
 * gcc -o test -D_FILE_OFFSET_BITS=64  -lcephfs test.c
 */

#include <cephfs/libcephfs.h>
#include <stdlib.h>
#include <stdio.h>
#include <time.h>
#include <unistd.h>
#include <fcntl.h>
#include <sys/stat.h>
#include <errno.h>
#include <string.h>

int ceph_set_time(struct ceph_mount_info *cmount, char *filename, time_t t)
{
	struct timespec ts[2] = {0,0};
	int fd, ret;

	ts[0].tv_sec = t;
	ts[1].tv_sec = t;

	printf("cephfs: Set time: %lu\n", t);
	fd = ceph_open(cmount, filename, O_RDONLY, 0);
	ret = ceph_futimens(cmount, fd, ts);
	if(ret < 0) { printf("ceph_futimens error: %d\n", ret); };
	ceph_close(cmount, fd);

	return 0;
}

int ceph_get_time(struct ceph_mount_info *cmount, char *filename)
{
	struct ceph_statx stx;
	int fd;

	fd = ceph_open(cmount, filename, O_RDONLY, 0);
	ceph_fstatx(cmount, fd, &stx,CEPH_STATX_BASIC_STATS|CEPH_STATX_BTIME, 0);
	printf("cephfs: Get time: %lu\n", stx.stx_mtime.tv_sec);
	ceph_close(cmount, fd);

	return 0;
}

int ceph_test_time(struct ceph_mount_info *cmount, char *filename, time_t t)
{
	ceph_set_time(cmount, filename, t);
	ceph_get_time(cmount, filename);
}

int local_set_time(char *filename, time_t t)
{
	struct timespec ts[2] = {0,0};
	int fd;

	ts[0].tv_sec = t;
	ts[1].tv_sec = t;

	printf("local: Set time: %lu\n", t);
	fd = open(filename, O_RDONLY);
	if(fd == -1) { printf("error open"); return 1;}
	if (futimens(fd, ts) == -1) { printf("error futimens: %s\n", strerror(errno)); return 1;}
	close(fd);

	return 0;
}

int local_get_time(char *filename)
{
	struct stat stx;
	int fd;

	fd = open(filename, O_RDONLY, 0);
	if(fd == -1) { printf("error open"); return 1;}
	if (fstat(fd, &stx) == -1){ printf("error fstat: %s\n", strerror(errno)); return 1;}
	printf("local: Get time: %lu\n", stx.st_mtime);
	close(fd);

	return 0;
}

int local_test_time(char *filename, time_t t)
{
	local_set_time(filename, t);
	local_get_time(filename);
}


int main()
{
	struct ceph_mount_info *cmount = NULL;
	char *filename = "testfile";
	int fd;
	char *teststr = "Hello World!";

	ceph_create(&cmount, NULL);
	ceph_conf_read_file(cmount, "/etc/ceph/ceph.conf");
	ceph_mount(cmount, NULL);

	printf("Ceph: Create a new file\n");
	fd = ceph_open(cmount, filename, O_WRONLY|O_CREAT, 0644);
	ceph_write(cmount, fd, teststr, sizeof(teststr), 0);
	ceph_close(cmount, fd);
	ceph_get_time(cmount, filename);
	printf("\n");

	printf("local: Create a new file\n");
	fd = open(filename, O_WRONLY|O_CREAT, 06444);
	write(fd, teststr, sizeof(teststr));
	local_get_time(filename);
	close(fd);
	printf("\n");

	printf("Set time to 10000000\n");
	ceph_test_time(cmount, filename, 10000000);
	local_test_time(filename, 10000000);
	printf("\n");

	printf("Set time to -1\n");
	ceph_test_time(cmount, filename, -1);
	local_test_time(filename, -1);
	printf("\n");
	printf("Set time to -2\n");
	ceph_test_time(cmount, filename, -2);
	local_test_time(filename, -2);
	printf("\n");

	/* >> INT32_MAX, limit on ext */
	printf("Set time to 15032385535\n");
	ceph_test_time(cmount, filename, 15032385535);
	local_test_time(filename, 15032385535);
	printf("\n");

	/* >> INT32_MAX */
	printf("Set time to 10000000000\n");
    ceph_test_time(cmount, filename, 10000000000);
	local_test_time(filename, 10000000000);
	printf("\n");

	/* 1968*/
	printf("Set time to -63158400\n");
	ceph_test_time(cmount, filename, -63158400);
	local_test_time(filename, -63158400);
	printf("\n");

	ceph_shutdown(cmount);

	return 0;
}

The results are as follows

# gcc -o test2 -D_FILE_OFFSET_BITS=64  -lcephfs test2.c 
# ./test2
Ceph: Create a new file
cephfs: Get time: 1710940274

local: Create a new file
local: Get time: 1710940274

Set time to 10000000
cephfs: Set time: 10000000
cephfs: Get time: 10000000
local: Set time: 10000000
local: Get time: 10000000

Set time to -1
cephfs: Set time: 18446744073709551615
cephfs: Get time: 4294967295
local: Set time: 18446744073709551615
local: Get time: 18446744073709551615

Set time to -2
cephfs: Set time: 18446744073709551614
cephfs: Get time: 4294967294
local: Set time: 18446744073709551614
local: Get time: 18446744073709551614

Set time to 15032385535
cephfs: Set time: 15032385535
cephfs: Get time: 2147483647
local: Set time: 15032385535
local: Get time: 15032385535

Set time to 10000000000
cephfs: Set time: 10000000000
cephfs: Get time: 1410065408
local: Set time: 10000000000
local: Get time: 10000000000

Set time to -63158400
cephfs: Set time: 18446744073646393216
cephfs: Get time: 4231808896
local: Set time: 18446744073646393216
local: Get time: 18446744073646393216

The time being set and the resultant times returned do not match.

[spuiuk]

@synarete pointed out that the fields used to store the time variables in the ceph code are u32 which wouldn't work very well for the values we are setting.
https://github.com/ceph/ceph/blob/main/src/include/utime.h#L51

So we decided to test out with UINT32_MAX values.

	printf("Set time to UINT32_MAX\n");
	ceph_test_time(cmount, filename, (time_t)UINT32_MAX);
	local_test_time(filename, (time_t)UINT32_MAX);
	printf("\n");

	printf("Set time to UINT32_MAX+1\n");
	ceph_test_time(cmount, filename, (time_t)UINT32_MAX+1);
	local_test_time(filename, (time_t)UINT32_MAX+1);
	printf("\n");

	printf("Set time to UINT32_MAX+2\n");
	ceph_test_time(cmount, filename, (time_t)UINT32_MAX+2);
	local_test_time(filename, (time_t)UINT32_MAX+2);
	printf("\n");

and the results are as follows

# gcc -o test2 -D_FILE_OFFSET_BITS=64  -lcephfs test2.c 
# ./test2
Ceph: Create a new file
cephfs: Get time: 1710943384

local: Create a new file
local: Get time: 1710943384

Set time to UINT32_MAX
cephfs: Set time: 4294967295
cephfs: Get time: 4294967295
local: Set time: 4294967295
local: Get time: 4294967295

Set time to UINT32_MAX+1
cephfs: Set time: 4294967296
cephfs: Get time: 0
local: Set time: 4294967296
local: Get time: 4294967296

Set time to UINT32_MAX+2
cephfs: Set time: 4294967297
cephfs: Get time: 1
local: Set time: 4294967297
local: Get time: 4294967297

[synarete]

Using uint32_t for time_t is also known as Year 2106 bug.

[spuiuk]

reported with cephfs at
https://tracker.ceph.com/issues/65043