File goes missing for a short period of time after saving it using VIM

[Michael P. Jung]

This bug started as a question on unix.stackexchange.com: http://unix.stackexchange.com/questions/64544/file-goes-missing-for-a-short-period-of-time-after-saving-it-using-vim

I am having a strange problem that seams to be caused by VIM, the Linux VFS cache, ecryptfs and/or something file system related:

  1. I open a file in VIM, modify it and save it.
  2. I try to access the file.

##Expected behaviour

The file should be accessible as soon as :w reports the file as written.

##Actual behaviour

The file does not exist.

If I wait a bit (usually less then a second) the file turns up.

This is especially cumbersome when working with Python code and left over pyc files. I often ended up starting the old code as the new py file was not ready, yet. I recently added export PYTHONDONTWRITEBYTECODE=1 to my .bashrc so I get a meaningful error message rather than executing the old code. It is still very awkward as any auto reloader code (e.g. from Django) fails to reload every 5-10 times because the file I changed goes missing for a short period of time. With the pyc files in place the auto reloader sometimes ended up loading the old pyc file and after that never found out that the py file has been modified and triggered another reload.

##System details and configuration

My machine has plenty of RAM (32 GiB), an SSD and is basicly idle. Therefore I do not think that slow I/O is causing this. The file is very small (<1 KiB) and it also happens for empty files. I am using a crypted $HOME using ecryptfs so this might be part of the problem. I was unable to reproduce this on my /tmp mount which uses a tmpfs file system.

##VIM settings

The reason why the file is moved away and replaced by a new file is caused by my VIM settings:

    set backup
    set backupskip=
    set backupdir=$HOME/.vimbackup
    set writebackup

I would expect the new file to be accessible right after VIM reports that the file has been written. I checked the VIM documentation for any hints of a delayed write, but did not find anything. I was unable to reproduce this using the shell commands mv, cp and rm so I think VIM is doing something different.

##Distribution and software versions

I'm running Ubuntu GNU/Linux 12.10 x86_64 with ecryptfs-utils 100.

    $ lsb_release -a
    No LSB modules are available.
    Distributor ID: Ubuntu
    Description: Ubuntu 12.10
    Release: 12.10
    Codename: quantal

    $ uname -a
    Linux blackhole 3.5.0-22-generic #34-Ubuntu SMP Tue Jan 8 21:47:00 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux

    $ apt-cache show ecryptfs-utils |grep Version
    Version: 100-0ubuntu1

[Tyler Hicks (tyhicks)]

Thanks for the bug report, Michael. As I mentioned on stackexchange, I'm unable to reproduce the bug. Can you elaborate a bit on how you try to access the file in step 2? Different commands are going to result in different system call sequences, so maybe that's the reason why I'm not seeing the bug.

[Michael P. Jung (bikeshedder)]

When reporting the bug I was writing C++ code. I simply launched the GNU C++ compiler after changing something on the code and ran into this error. I am writing with a two-pane Terminator terminal emulation and I am able to switch fast enough to the terminal on the right side, start the compiliation and trigger this error.

It is clear that the file does vanishes for a very short amount of time using my VIM settings, but it should be back after a few microseconds. Right now I'm able to trigger this error by hand which is quite troubling.

I was already trying to write some test cow which could show this behavior. So far it looks like VIM performs a series of operations in the filesystem. It does not move the original version directly to ~/.vimbackup but first renames the file as filename~. Then it creates the new version of the file and moves the filename~ backup file into ~/.vimbackup.

I really wonder why the simple test case "mv test test.bak ; touch test" never shows this behavior.

[Michael P. Jung (bikeshedder)]

Maybe the output of strace can help. I attached to the process right after typing ":w" in VIM and then pressed enter to catch less keyboard events:

Process 3304 attached - interrupt to quit
select(1, [0], NULL, [0], NULL) = 1 (in [0])
read(0, "\r", 4096) = 1
select(1, [0], NULL, [0], {0, 0}) = 0 (Timeout)
write(1, "\r", 1) = 1
stat("/home/bikeshedder/x", {st_mode=S_IFREG|0664, st_size=1, ...}) = 0
access("/home/bikeshedder/x", W_OK) = 0
getcwd("/home/bikeshedder", 4096) = 12
select(1, [0], NULL, [0], {0, 0}) = 0 (Timeout)
write(1, "\33[?25l\"x\"", 9) = 9
stat("x", {st_mode=S_IFREG|0664, st_size=1, ...}) = 0
access("x", W_OK) = 0
getxattr("x", "system.posix_acl_access", 0x7fff5cc33380, 132) = -1 ENODATA (No data available)
stat("x", {st_mode=S_IFREG|0664, st_size=1, ...}) = 0
lstat("x", {st_mode=S_IFREG|0664, st_size=1, ...}) = 0
lstat("4913", 0x7fff5cc33660) = -1 ENOENT (No such file or directory)
open("4913", O_WRONLY|O_CREAT|O_EXCL|O_NOFOLLOW, 0100664) = 3
fchown(3, 1000, 1000) = 0
stat("4913", {st_mode=S_IFREG|0664, st_size=0, ...}) = 0
close(3) = 0
unlink("4913") = 0
stat("x", {st_mode=S_IFREG|0664, st_size=1, ...}) = 0
stat("/home/bikeshedder/.vimbackup/x~", {st_mode=S_IFREG|0664, st_size=1, ...}) = 0
unlink("/home/bikeshedder/.vimbackup/x~") = 0
rename("x", "/home/bikeshedder/.vimbackup/x~") = 0
fsync(4) = 0
open("x", O_WRONLY|O_CREAT|O_TRUNC, 0664) = 3
write(3, "\n", 1) = 1
fsync(3) = 0
stat("x", {st_mode=S_IFREG|0664, st_size=1, ...}) = 0
stat("x", {st_mode=S_IFREG|0664, st_size=1, ...}) = 0
close(3) = 0
chmod("x", 0100664) = 0
setxattr("x", "system.posix_acl_access", "\x02\x00\x00\x00\x01\x00\x06\x00\xff\xff\xff\xff\x04\x00\x06\x00\xff\xff\xff\xff \x00\x04\x00\xff\xff\xff\xff", 28, 0) = 0
write(1, " 1L, 1C [w]", 11) = 11
stat("/home/bikeshedder/x", {st_mode=S_IFREG|0664, st_size=1, ...}) = 0
getcwd("/home/bikeshedder", 4096) = 12
select(1, [0], NULL, [0], {0, 0}) = 0 (Timeout)
select(1, [0], NULL, [0], {0, 0}) = 0 (Timeout)
select(1, [0], NULL, [0], {0, 0}) = 0 (Timeout)
write(1, "\33[1;3H", 6) = 6
select(1, [0], NULL, [0], {0, 0}) = 0 (Timeout)
select(1, [0], NULL, [0], {0, 0}) = 0 (Timeout)
select(1, [0], NULL, [0], {0, 0}) = 0 (Timeout)
select(1, [0], NULL, [0], {0, 0}) = 0 (Timeout)
select(1, [0], NULL, [0], {0, 0}) = 0 (Timeout)
select(1, [0], NULL, [0], {0, 0}) = 0 (Timeout)
select(1, [0], NULL, [0], {0, 0}) = 0 (Timeout)
select(1, [0], NULL, [0], {0, 0}) = 0 (Timeout)
write(1, "\33[?12l\33[?25h", 12) = 12
select(1, [0], NULL, [0], {10, 0}^C <unfinished ...>
Process 3304 detached

[Tyler Hicks (tyhicks)]

On 2013-02-12 22:41:14, Michael P. Jung wrote:
> Maybe the output of strace can help. I attached to the process right
> after typing ":w" in VIM and then pressed enter to catch less keyboard
> events:

Thanks, this is helpful.

<snip>

> unlink("/home/bikeshedder/.vimbackup/x~") = 0
> rename("x", "/home/bikeshedder/.vimbackup/x~") = 0
> fsync(4) = 0
> open("x", O_WRONLY|O_CREAT|O_TRUNC, 0664) = 3
> write(3, "\n", 1) = 1
> fsync(3) = 0
> stat("x", {st_mode=S_IFREG|0664, st_size=1, ...}) = 0
> stat("x", {st_mode=S_IFREG|0664, st_size=1, ...}) = 0
> close(3) = 0
> chmod("x", 0100664) = 0
> setxattr("x", "system.posix_acl_access", "\x02\x00\x00\x00\x01\x00\x06\x00\xff\xff\xff\xff\x04\x00\x06\x00\xff\xff\xff\xff \x00\x04\x00\xff\xff\xff\xff", 28, 0) = 0
> write(1, " 1L, 1C [w]", 11) = 11
> stat("/home/bikeshedder/x", {st_mode=S_IFREG|0664, st_size=1, ...}) = 0

The stat() on the file was successful, meaning that the file exists and things
are working as expected without any sort of a delay. I'm having trouble
imagining how another process (the compiler in your situation) would have any
problem accessing the file.

[Michael P. Jung (bikeshedder)]

I'm starting to disbelieve myself. I wrote a simple C program that renames a file, creates a new one and forks a new process which tries to read the newly created file. It works just fine.

Today I can't even reproduce this using VIM. This is odd. I will wait for this issue to occur again and then run my test program again.

[Tyler Hicks (tyhicks)]

On 2013-02-13 12:51:04, Michael P. Jung wrote:
> I'm starting to disbelieve myself. I wrote a simple C program that
> renames a file, creates a new one and forks a new process which tries to
> read the newly created file. It works just fine.

Well according to the strace, vim does remove the file for a moment:

rename("x", "/home/bikeshedder/.vimbackup/x~") = 0
fsync(4) = 0
open("x", O_WRONLY|O_CREAT|O_TRUNC, 0664) = 3

That doesn't seem like the right thing to do to me, but that would be a bug in
vim.

I'm not familiar with how the auto reloader works, but there's a chance that it
could try to open "x" in the small amount of time that vim renamed "x" to "x~"
and hasn't yet recreated "x".

This may be only seen by you on eCryptfs because it is a little slower than
traditional filesytems.