I'm running the Debian distro with stable cfs (Cryptographic File System), in which one can create a directory in the regular file system to be used as a repository for an encrypted file system that can be mounted or unmounted on demand. When mounted (usually at /crypt/<name>), the directory can be viewed and manipulated normally. When unmounted, the only data physically on the disk in the regular file system is gibberish.

cfs works superficially - I can create, attach, and detach encrypted directories, and read and write files. But there is a problem setting modification times, e.g. with touch:

$ cmkdir foo # create encrypted directory
Key:
Again:
$ cattach foo # mount encrypted directory (at /crypt/foo)
Key:
$ touch /crypt/foo/bar # touch file in encrypted directory
$ ls -l /crypt/foo/bar
-rw-r--r-- 1 roy roy 0 Dec 31 1969 /crypt/foo/bar

The file was created fine, but the date is bogus. Any attempt to manipulate the date results in setting to the UNIX epoch. Files created or modified without explicit date manipulation work fine:

$ cat < /dev/null > /crypt/foo/baz
$ ls -l /crypt/foo
total 0
-rw-r--r-- 1 roy roy 0 Dec 31 1969 bar
-rw-r--r-- 1 roy roy 0 Aug 13 07:43 baz

I don't know if this is specifically a user-mode Linux problem, but I have searched Google extensively for this issue with cfs and came up empty. One would think this would have come up by now if it were a global cfs bug, so I do suspect it is a UML interaction.

I'm not submitting this as a ticket because I'm not positive it is a Linode issue and I can't expect Linode to chase down every application bug, but cfs date modification is a very useful thing for making encrypted backups, e.g. using rsync. Perhaps someone could give this a try on another distro to see if that is a factor?

That is strange.

Can you "strace -o /strace.log touch /crypt/foo/bar" and send me the contents of /strace.log?

Any other debugging information that would be useful to myself or Jeff Dike (creator of UML)? -- if we think it is UML related I can forward a bug report to the UML-user mailing list.

Thanks,

-Chris

Here is strace -o strace.log touch /crypt/foo/bar:

execve("/usr/bin/touch", ["touch", "/crypt/foo/bar"], [/* 14 vars */]) = 0
uname({sys="Linux", node="li2-23", ...}) = 0
brk(0) = 0x804e8a4
old_mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x40013000
open("/etc/ld.so.preload", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=8798, ...}) = 0
old_mmap(NULL, 8798, PROT_READ, MAP_PRIVATE, 3, 0) = 0x40014000
close(3) = 0
open("/lib/libc.so.6", O_RDONLY) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\224]\1"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=1142224, ...}) = 0
old_mmap(NULL, 1151748, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0x40017000
old_mmap(0x40129000, 20480, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3, 0x111000) = 0x40129000
old_mmap(0x4012e000, 8964, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x4012e000
close(3) = 0
munmap(0x40014000, 8798) = 0
brk(0) = 0x804e8a4
brk(0x806f8a4) = 0x806f8a4
brk(0) = 0x806f8a4
brk(0x8070000) = 0x8070000
open("/crypt/foo/bar", O_WRONLY|O_NONBLOCK|O_CREAT|O_NOCTTY|O_LARGEFILE, 0666) = 3
close(3) = 0
utime("/crypt/foo/bar", NULL) = 0
semget(IPC_PRIVATE, 0, 0) = -1 ENOSYS (Function not implemented)
_exit(0) = ?

Unfortunately, I don't think it tells us much. I did an strace on a touch of a file in a non-cfs directory and it was identical (via diff) except for the file paths. It looks like there is no problem on the user side of things.

The problem appears to be on the server side. As I understand it, cfs works through an nfs loopback, so the user file requests are going through nfs to the cfsd daemon. I tried adding strace to /etc/init.d/cfsd, i.e.

start-stop-daemon --start --pidfile /var/run/cfs.pid \
--make-pidfile --background --exec /usr/bin/strace -o /var/log/cfsd.log $DAEMON

but that just seemed to hang the script...the log file didn't even get created.

I thought the issue might be in using an ext3 file system to hold the encrypted directory, but I have now ruled that out. I configured an ext2 disk and saw the same problem using it.

Anything weird in the output of "dmesg" or nfs/system logs?

What does "stat /crypt/foo/bar" and "stat /crypt/foo/baz" give you? Stat should show you the same thing..

I find it strange that modifying the file succecssfully changes the mtime, and the utime call returns successfully (from the strace of touch).

As a temporary fix, you could write a little shell script that replaces touch with cat < /dev/null > $arg[0]

-Chris

Okay, I managed to figure out how to strace cfsd. I probably don't have exactly the begin and end of the touch here, but:

poll([{fd=3, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND, revents=POLLIN|POLLRDNORM}], 1, -1) = 1
recvmsg(3, {msg_name(16)={sin_family=AF_INET, sin_port=htons(800), sin_addr=inet_addr("127.0.0.1")}}, msg_iov(1)=[{"\'\20_\250\0\0\0\0\0\0\0\2\0\1\206\243\0\0\0\2\0\0\0\4"..., 8800}], msg_controllen=24, msg_control=0x8092888, , msg_flags=0}, 0) = 112
setfsgid32(0x3e8) = 0
setfsuid32(0x3e8) = 0
lstat64("/mnt/ubdc/home/roy/foo/.", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
setresuid32(0xffffffff, 0, 0xffffffff) = 0
setresgid32(0xffffffff, 0, 0xffffffff) = 0
sendmsg(3, {msg_name(16)={sin_family=AF_INET, sin_port=htons(800), sin_addr=inet_addr("127.0.0.1")}}, msg_iov(1)=[{"\'\20_\250\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128}], msg_controllen=24, msg_control=0x8092888, , msg_flags=0}, 0) = 128
poll([{fd=3, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND, revents=POLLIN|POLLRDNORM}], 1, -1) = 1
recvmsg(3, {msg_name(16)={sin_family=AF_INET, sin_port=htons(800), sin_addr=inet_addr("127.0.0.1")}}, msg_iov(1)=[{"(\20_\250\0\0\0\0\0\0\0\2\0\1\206\243\0\0\0\2\0\0\0\4\0"..., 8800}], msg_controllen=24, msg_control=0x8092888, , msg_flags=0}, 0) = 112
setfsgid32(0x3e8) = 0
setfsuid32(0x3e8) = 0
lstat64("/mnt/ubdc/home/roy/foo/./a08d833eb8721160", {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
readlink("/mnt/ubdc/home/roy/foo/./.pvect_a08d833eb8721160", "c4e4b987", 9) = 8
lstat64("/mnt/ubdc/home/roy/foo/./a08d833eb8721160", {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
setresuid32(0xffffffff, 0, 0xffffffff) = 0
setresgid32(0xffffffff, 0, 0xffffffff) = 0
sendmsg(3, {msg_name(16)={sin_family=AF_INET, sin_port=htons(800), sin_addr=inet_addr("127.0.0.1")}}, msg_iov(1)=[{"(\20_\250\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128}], msg_controllen=24, msg_control=0x8092888, , msg_flags=0}, 0) = 128
poll([{fd=3, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND, revents=POLLIN|POLLRDNORM}], 1, -1) = 1
recvmsg(3, {msg_name(16)={sin_family=AF_INET, sin_port=htons(800), sin_addr=inet_addr("127.0.0.1")}}, msg_iov(1)=[{")\20_\250\0\0\0\0\0\0\0\2\0\1\206\243\0\0\0\2\0\0\0\1\0"..., 8800}], msg_controllen=24, msg_control=0x8092888, , msg_flags=0}, 0) = 104
sendmsg(3, {msg_name(16)={sin_family=AF_INET, sin_port=htons(800), sin_addr=inet_addr("127.0.0.1")}}, msg_iov(1)=[{")\20_\250\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 96}], msg_controllen=24, msg_control=0x8092888, , msg_flags=0}, 0) = 96
poll([{fd=3, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND, revents=POLLIN|POLLRDNORM}], 1, -1) = 1
recvmsg(3, {msg_name(16)={sin_family=AF_INET, sin_port=htons(800), sin_addr=inet_addr("127.0.0.1")}}, msg_iov(1)=[{"*\20_\250\0\0\0\0\0\0\0\2\0\1\206\243\0\0\0\2\0\0\0\4\0"..., 8800}], msg_controllen=24, msg_control=0x8092888, , msg_flags=0}, 0) = 112
setfsgid32(0x3e8) = 0
setfsuid32(0x3e8) = 0
lstat64("/mnt/ubdc/home/roy/foo/.", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
setresuid32(0xffffffff, 0, 0xffffffff) = 0
setresgid32(0xffffffff, 0, 0xffffffff) = 0
sendmsg(3, {msg_name(16)={sin_family=AF_INET, sin_port=htons(800), sin_addr=inet_addr("127.0.0.1")}}, msg_iov(1)=[{"*\20_\250\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128}], msg_controllen=24, msg_control=0x8092888, , msg_flags=0}, 0) = 128
poll([{fd=3, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND, revents=POLLIN|POLLRDNORM}], 1, -1) = 1
recvmsg(3, {msg_name(16)={sin_family=AF_INET, sin_port=htons(800), sin_addr=inet_addr("127.0.0.1")}}, msg_iov(1)=[{"+\20_\250\0\0\0\0\0\0\0\2\0\1\206\243\0\0\0\2\0\0\0\4\0"..., 8800}], msg_controllen=24, msg_control=0x8092888, , msg_flags=0}, 0) = 112
setfsgid32(0x3e8) = 0
setfsuid32(0x3e8) = 0
lstat64("/mnt/ubdc/home/roy/foo/./a08d833eb8721160", {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
readlink("/mnt/ubdc/home/roy/foo/./.pvect_a08d833eb8721160", "c4e4b987", 9) = 8
lstat64("/mnt/ubdc/home/roy/foo/./a08d833eb8721160", {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
setresuid32(0xffffffff, 0, 0xffffffff) = 0
setresgid32(0xffffffff, 0, 0xffffffff) = 0
sendmsg(3, {msg_name(16)={sin_family=AF_INET, sin_port=htons(800), sin_addr=inet_addr("127.0.0.1")}}, msg_iov(1)=[{"+\20_\250\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128}], msg_controllen=24, msg_control=0x8092888, , msg_flags=0}, 0) = 128
poll([{fd=3, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND, revents=POLLIN|POLLRDNORM}], 1, -1) = 1
recvmsg(3, {msg_name(16)={sin_family=AF_INET, sin_port=htons(800), sin_addr=inet_addr("127.0.0.1")}}, msg_iov(1)=[{",\20_\250\0\0\0\0\0\0\0\2\0\1\206\243\0\0\0\2\0\0\0\2\0"..., 8800}], msg_controllen=24, msg_control=0x8092888, , msg_flags=0}, 0) = 136
setfsgid32(0x3e8) = 0
setfsuid32(0x3e8) = 0
utime("/mnt/ubdc/home/roy/foo/./a08d833eb8721160", [1969/12/31-16:00:01, 1969/12/31-16:00:01]) = 0
lstat64("/mnt/ubdc/home/roy/foo/./a08d833eb8721160", {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
setresuid32(0xffffffff, 0, 0xffffffff) = 0
setresgid32(0xffffffff, 0, 0xffffffff) = 0
sendmsg(3, {msg_name(16)={sin_family=AF_INET, sin_port=htons(800), sin_addr=inet_addr("127.0.0.1")}}, msg_iov(1)=[{",\20_\250\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 96}], msg_controllen=24, msg_control=0x8092888, , msg_flags=0}, 0) = 96
poll([{fd=3, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, -1) = -1 EINTR

The interesting call is to utime() about ten lines up from the end. This is setting the access and modification times on the encrypted file in the real directory. There we can see that the time passed in is the bogus 1969 date.

Which version of CVS are you using? cfs-1.4.1? Did you compile it yourself or install a package?

Looking at the code (cfs_fh.c), it looks like if NO_UTIMES is defined, it sets everything to an empty timeval struct (which results in an epoch time?)

-Chris

I was initially using the Debain stable cfs-1.4.1-5 package. I installed the unstable cfs-1.4.1-7 package, same behavior. Now I'm building the unstable cfs-1.4.1-7 sources, and seeing the same thing.

cfs_fh.c looks like the key file. The code you point out actually sets the timeval struct to values from its argument (it's old K&R C). But that's actually irrelevant because NO_UTIMES is not defined.

I can build and install the daemon with debugging syslog() output, so hopefully I'll have more info soon.

Okay, apparently the system call utimes() (with a trailing 's') does not work, at least on my Debian distro. utime() (no trailing 's') does work.

Here's a little test program that can be compiled to use either call. It tries to set the access and modification times on the filename passed on the command line:

#include <stdio.h>
#include <sys/types.h>

/* define this symbol to use utimes(), otherwise use utime() */
/* utimes() (with the #define) appears to be broken. */
#define UTIMES
#ifdef UTIMES
#include <time.h>
#else
#include <utime.h>
#endif

/* set modification and access time on first file argument */
main(int argc,char *argv[])
{
/* I'm too lazy to look up the current time. */
/* This is August 13, 2003. */
long seconds = 1060808668L;

if ( argc != 2 )
printf("usage: %s <existing-filename>\n",argv[0]);

#ifdef UTIMES
{
struct timeval tv[2];
tv[0].tv_sec = seconds;
tv[0].tv_usec = 0L;
tv[1].tv_sec = seconds;
tv[1].tv_usec = 0L;
printf("utimes on %s returns %d\n",
argv[1],
utimes(argv[1],tv));
}
#else
{
struct utimbuf ut;
ut.actime = seconds;
ut.modtime = seconds;
printf("utime on %s returns %d\n",
argv[1],
utime(argv[1],&ut));
}
#endif
}

If I run it with UTIMES defined (as here), it sets the date to the epoch, just as cfsd does.

I hacked my cfsd source to use utime() and touch-ing a file on the encrypted mount appears to work. I'm quite hopeful that rsync can work its magic, too.

Whoohoo! rsync to encrypted mounts works!

Thanks for putting me on the right track with strace, Chris.

All right! Glad you hacked it to work..

I checked the UML source and it doesn't appear to muck with those time syscalls. I wondered if it was glibc related (since it doesn't happen on my red hat host)... Doing a Google search for "debian glibc utimes touch" came up with this:

Thread:
http://sources.redhat.com/ml/libc-alpha ... 00062.html

Bug Report
http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=202243

So, it is a glibc related bug, posted about three weeks ago.

-Chris