CephFS: Failure in smb2.timestamps.time_t_* #71

spuiuk · 2024-03-13T21:56:32Z

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 · 2024-03-13T22:00:49Z

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 · 2024-03-13T22:02:07Z

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 · 2024-03-14T05:10:21Z

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

anoopcs9 · 2024-03-14T06:44:51Z

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 · 2024-03-14T06:52:09Z

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 · 2024-03-14T14:40:44Z

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 · 2024-03-14T16:39:24Z

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 · 2024-03-14T18:11:45Z

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 · 2024-03-14T21:05:22Z

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 · 2024-03-14T23:26:22Z

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 · 2024-03-20T13:14:01Z

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 · 2024-03-20T14:06:46Z

@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 · 2024-03-20T14:22:00Z

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

spuiuk · 2024-03-21T15:10:50Z

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

anoopcs9 · 2024-04-04T05:18:36Z

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.

Above change got finally merged after few back and forth discussions.

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

Considering the low priority given for the above tracker we can now safely put the following into flapping.cephfs with a link to it:

smb2.timestamps.time_t_15032385535
smb2.timestamps.time_t_10000000000
smb2.timestamps.time_t_-1
smb2.timestamps.time_t_-2
smb2.timestamps.time_t_1968

spuiuk · 2024-04-07T16:01:59Z

@synarete, You will probably need to backport this to the cephfs-ll VFS plugin.

anoopcs9 changed the title ~~cephfs-smbtorture: Failure in smb2.timestamps.time_t_* for cephfs~~ CephFS: Failure in smb2.timestamps.time_t_* Mar 15, 2024

spuiuk mentioned this issue Apr 7, 2024

testcases/smbtorture: add smb2.timestamps to smbtorture tests #77

Merged

anoopcs9 closed this as completed in #77 Apr 8, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

CephFS: Failure in smb2.timestamps.time_t_* #71

CephFS: Failure in smb2.timestamps.time_t_* #71

spuiuk commented Mar 13, 2024 •

edited by anoopcs9

Loading

spuiuk commented Mar 13, 2024 •

edited

Loading

spuiuk commented Mar 13, 2024

anoopcs9 commented Mar 14, 2024 •

edited

Loading

anoopcs9 commented Mar 14, 2024

synarete commented Mar 14, 2024

spuiuk commented Mar 14, 2024

anoopcs9 commented Mar 14, 2024

spuiuk commented Mar 14, 2024 •

edited

Loading

spuiuk commented Mar 14, 2024

spuiuk commented Mar 14, 2024 •

edited

Loading

spuiuk commented Mar 20, 2024 •

edited

Loading

spuiuk commented Mar 20, 2024

synarete commented Mar 20, 2024

spuiuk commented Mar 21, 2024

anoopcs9 commented Apr 4, 2024

spuiuk commented Apr 7, 2024

CephFS: Failure in smb2.timestamps.time_t_* #71

CephFS: Failure in smb2.timestamps.time_t_* #71

Comments

spuiuk commented Mar 13, 2024 • edited by anoopcs9 Loading

spuiuk commented Mar 13, 2024 • edited Loading

spuiuk commented Mar 13, 2024

anoopcs9 commented Mar 14, 2024 • edited Loading

anoopcs9 commented Mar 14, 2024

synarete commented Mar 14, 2024

spuiuk commented Mar 14, 2024

anoopcs9 commented Mar 14, 2024

spuiuk commented Mar 14, 2024 • edited Loading

spuiuk commented Mar 14, 2024

spuiuk commented Mar 14, 2024 • edited Loading

spuiuk commented Mar 20, 2024 • edited Loading

spuiuk commented Mar 20, 2024

synarete commented Mar 20, 2024

spuiuk commented Mar 21, 2024

anoopcs9 commented Apr 4, 2024

spuiuk commented Apr 7, 2024

spuiuk commented Mar 13, 2024 •

edited by anoopcs9

Loading

spuiuk commented Mar 13, 2024 •

edited

Loading

anoopcs9 commented Mar 14, 2024 •

edited

Loading

spuiuk commented Mar 14, 2024 •

edited

Loading

spuiuk commented Mar 14, 2024 •

edited

Loading

spuiuk commented Mar 20, 2024 •

edited

Loading