Deleted bind-mount points fail restore

[stlalpha]

Checkpoints are now completing successfully after enabling evasive devices for this container - however I am getting the following error on restores (checkpoint and restoring on same host) - any ideas? Thanks!:

(00.106760) 1: Found fd 1 (id pipe:[546719]) in inherit fd list (caller inherit_fd_resolve_clash)
(00.106765) 1: Inherit fd 1 moved to 5 to resolve clash
(00.106767) 1: Going to dup 0 into 1
(00.106770) 1: Found fd 2 (id pipe:[546720]) in inherit fd list (caller inherit_fd_resolve_clash)
(00.106773) 1: Inherit fd 2 moved to 6 to resolve clash
(00.106775) 1: Going to dup 0 into 2
(00.106782) 1: Restoring fd 1 (state -> create)
(00.106784) 1: Restoring fd 2 (state -> create)
(00.106787) 1: Restoring fd 3 (state -> create)
(00.106789) 1: Creating pipe pipe_id=0x857e7 id=0x2
(00.106796) 1: Restoring size 0x10000 for 0x857e7
(00.106803) 1: Wait fdinfo pid=1 fd=4
(00.106806) 1: Send fd 7 to /crtools-fd-1-4
(00.106823) 1: Create fd for 3
(00.106827) 1: Restoring fd 4 (state -> create)
(00.106829) 1: Creating pipe pipe_id=0x857e7 id=0x3
(00.106832) 1: Waiting fd for 4
(00.106842) 1: Create fd for 4
(00.106846) 1: Restoring fd 5 (state -> create)
(00.106853) 1: fsnotify: Restore 1 wd for 0x00000000
(00.106856) 1: fsnotify: Opening fhandle 2e:41...
(00.106871) 1: Path /' resolved to./' mountpoint
(00.106971) 1: Error (fsnotify.c:131): fsnotify: Can't open file handle for 0x0000002e:0x000000000000000e: Stale file handle
(00.114893) Error (cr-restore.c:1234): 28246 exited, status=1
(00.115123) Error (cr-restore.c:1927): Restoring FAILED.

[xemul]

Can you show the dump log please?

[fl0yd]

I'm working with stlalpha on this, here's a gist with a dump and restore log.

https://gist.github.com/fl0yd/4a4f88ee78e53b9977bd

[cyrillos]

It looks like the file being watched has vanished after the dump, which is only possible if underlied filesystem does something weird. I suspect it's AUFS? Could you please show the process tree and ls -l /proc/28382/fd ?

[fl0yd]

The old process was vaporized after the checkpoint, so I couldn't get the info from 28382. For cleanliness I bounced the box, and restarted a new container with the command.

https://gist.github.com/fl0yd/47ff63636a06df1a1f0c

[cyrillos]

So it's docker watching for something on own root.
├─docker(1016)─┬─init(1222)
...dump...
(00.013734) type aufs source none mnt_id 157 s_dev 0x26 / @ ./ flags 0x200000 options si=91208b708a91129b,dio,dirperm1
...
(00.175493) fsnotify: wd: wd 0x00000001 s_dev 0x00000026 i_ino 0x e mask 0x0800abc8
(00.175505) fsnotify: [fhandle] bytes 0x00000028 type 0x00000063 __handle 0x0000000000000041:0x000000000000000e
(00.175515) fsnotify: Opening fhandle 26:41...
(00.175543) Path /' resolved to./' mountpoint
(00.175618) fsnotify: Handle 26:e is openable
...restore...
(00.093582) 1: fsnotify: Restore 1 wd for 0x00000000
(00.093586) 1: fsnotify: Opening fhandle 26:41...
(00.093600) 1: Path /' resolved to./' mountpoint
(00.093664) 1: Error (fsnotify.c:131): fsnotify: Can't open file handle for 0x00000026:0x000000000000000e: Stale file handle

We might need some help from AUFS camp because this problem is definitely lays somewhere inside AUFS code: on the dump we've tested the watchee if it's openable by file handler but on restore open by file handle failed.

Is there a change to run same configuration on native VFS or something?

[avagin]

Cc: @SaiedKazemi

[SaiedKazemi]

@cyrillos @avagin
Docker 1.5 (https://github.com/SaiedKazemi/docker/releases) does support VFS (docker -d -D -s vfs) and I have successfully tested C/R'ing simple workloads. Worth a try with this workload.

[fl0yd]

in v1.8 the syntax isn’t the same, but when I pass the —volume-driver=vfs flag, the results are the same (or at least appear that way to me).

Docker command: docker run -d --volume-driver=vfs ubuntu /sbin/init
Gist: https://gist.github.com/fl0yd/9629cf9cd773ab18a461 https://gist.github.com/fl0yd/9629cf9cd773ab18a461

Mark

On Jul 27, 2015, at 7:10 PM, Saied Kazemi notifications@github.com wrote:

@cyrillos https://github.com/cyrillos @avagin https://github.com/avagin
Docker 1.5 (https://github.com/SaiedKazemi/docker/releases https://github.com/SaiedKazemi/docker/releases) does support VFS (docker -d -D -s vfs) and I have successfully tested C/R'ing simple workloads. Worth a try with this workload.

—
Reply to this email directly or view it on GitHub https://github.com/xemul/criu/issues/9#issuecomment-125383452.

[SaiedKazemi]

@fl0yd
The root of the container should be bind mounted before calling criu restore. This is implicitly done in the case of AUFS and OverlayFS when the container's file system is set up before calling criu. For VFS, we need to bind mount the root. I don't think this code exists in 1.8, hence the failure. Can you just wget docker-1.5.0 from the above URL and try it? It's already prebuilt, so the test should be really quick. Or send me your script and I will try it.

[fl0yd]

It’s getting pretty late here, but I’ll give the 1.5 a shot, though we have some dependencies on the 1.8 driver features of docker so while it will be interesting to see if it is vfs or aufs related, it will be just that. However, I would like to say that I am extremely thankful for the time that you’ve spent on this issue already and the great work the team has done on CRIU.

As of right now, the docker script is as simple as:

docker run -d ubuntu /sbin/init
docker checkpoint
docker restore <same ID from step 2>

Aside from having started the container, I haven’t started anything within the container. So it should work as is with 1.5 or 1.7/8

Mark

On Jul 27, 2015, at 7:47 PM, Saied Kazemi notifications@github.com wrote:

@fl0yd https://github.com/fl0yd
The root of the container should be bind mounted before calling criu restore. This is implicitly done in the case of AUFS and OverlayFS when the container's file system is set up before calling criu. For VFS, we need to bind mount the root. I don't think this code exists in 1.8, hence the failure. Can you just wget docker-1.5.0 from the above URL and try it? It's already prebuilt, so the test should be really quick. Or send me your script and I will try it.

—
Reply to this email directly or view it on GitHub https://github.com/xemul/criu/issues/9#issuecomment-125394819.

[SaiedKazemi]

My pleasure to help where I can. I just tried your container with both VFS and OverlayFS storage drivers on 3.19.8 (Ubuntu Vivid) kernel patched to fix OverlayFS bugs. Both restores failed with the same error (see below). I think the "deleted" string confuses things but I remember that CRIU has code to handle it. Unfortunately, don't have time to take a closer look at the moment but will definitely come back to it first chance I get.

VFS
(00.021356) 1: 71:./dev/mqueue private 1 shared 0 slave 0
(00.021359) 1: Mounting tmpfs @./proc/kcore (0)
(00.021363) 1: Bind ./dev/null//deleted to ./proc/kcore
(00.021378) 1: Error (mount.c:1921): Can't mount at ./proc/kcore: Not a directory
(00.035149) Error (cr-restore.c:1912): Restoring FAILED.

OverlayFS
(00.021356) 1: 71:./dev/mqueue private 1 shared 0 slave 0
(00.021359) 1: Mounting tmpfs @./proc/kcore (0)
(00.021363) 1: Bind ./dev/null//deleted to ./proc/kcore
(00.021378) 1: Error (mount.c:1921): Can't mount at ./proc/kcore: Not a directory
(00.035149) Error (cr-restore.c:1912): Restoring FAILED.

[cyrillos]

This doesn't look like file handle problem anymore though :) Still it seems that we're covering only one case of "deleted" name postfix, I'll re-check.

[cyrillos]

@SaiedKazemi Saied, I sent out a patch for handling "deleted" postfix from names, could you please give it a shot once time permit? (sent it into mailing list with you CC'ed)

[fl0yd]

I applied the diff from the patch Cyrillos mentioned above and confirm the "deleted" fix works for me.

I am still having issues with the restore using aufs and vfs.

with root mounted at "/" I get:

(00.113321) 1: fsnotify: Restore 0x1 wd for 0x00000000
(00.113325) 1: fsnotify: Opening fhandle 27:41...
(00.113339) 1: Path /' resolved to./' mountpoint
(00.113409) 1: Error (fsnotify.c:131): fsnotify: Can't open file handle for 0x00000027:0x000000000000000e: Stale file handle
(00.120768) Error (cr-restore.c:1927): Restoring FAILED.

with root mounted at /mnt/tmproot via -v /:/mnt/tmproot I get:

(00.010633) Error (mount.c:597): FS mnt ./mnt/tmproot/boot dev 0x800001 root / unsupported id 209
(00.010643) Unlock network
(00.010648) Running network-unlock scripts
(00.010659) RPC
(00.011258) Unfreezing tasks into 1
(00.011534) Unseizing 3840 into 1
(00.011736) Error (cr-dump.c:1996): Dumping FAILED.

Thoughts?

[cyrillos]

@fl0yd Mark, I fear I've no clue how docker operates with AUFS (neither how it works with VFS). What I know for sure is that when dump happens we explicitly check that file handle for watchee is openable, which allow us to be certain that we will be able to open it back on the restore.

In turn your error message shows that underlies filesystem has changed own contents and the watchee no longer available.

[SaiedKazemi]

@cyrillos @fl0yd
Good news! I was able to successfully checkpoint and restore Mark's container using Docker 1.5 with both VFS and OverlayFS. I applied Cyrill's patch but noticed that "//deleted" was not deleted from new->root. So, as a quick test, I patched parse_mountinfo_ent() to get rid of it and C/R worked.

    int rootlen = strlen(new->root);
    if (rootlen > 9) {
            if (!strcmp(&new->root[rootlen - 9], "//deleted"))
                    new->root[rootlen - 9] = '\0';
    }

Cyrill, the code path doesn't make it to strip_deleted() for new->root. Didn't look into why but I am sure it's not hard to find out why.

[cyrillos]

@SaiedKazemi Stripping deleted parts called in two cases:

• for opened files which has zero links associated
• for files living on devpts filesystem

as far as I know we don't call this helper over mount point paths. Saied could you please show the mount tree which contains such thing? It looks like we should handle it too.

[SaiedKazemi]

@cyrillos
Please see https://gist.github.com/SaiedKazemi/347a2e04a1ba78bf2113 for two dump.log files: a6_dump.log before my patch. 36_dump.log after my patch.

[cyrillos]

So as far as I understand it's bindmount for deleted entry. Is it a common situation for docker?

[cyrillos]

When you strip //deleted part it restores fine, correct?

[SaiedKazemi]

@xemul
Yes, it restores fine when "//deleted" is stripped from new->root.

Re how we end up with it, I don't know. I had seen the " (deleted)" suffix which Pavel can explain much better why/when it shows up. But this is the first time I am seeing "//deleted". It's added by dentry_path() in fs/dcache.c when it calls prepend() although it's actually appended!

[cyrillos]

@SaiedKazemi We end up this way when remove bindmount

136 130 0:52 /m1//deleted /home/cyrill/m/m2 rw,relatime shared:69 - tmpfs none rw

It is easy to simply call for stripping off this postfix I'm just need some time to think if there some caveats ramin... That said once ready I'll send out the patch.

[cyrillos]

@xemul Pavel rename the issue please to "Can't restore counters with deleted bind mount points"

[xemul]

Done, thanks :)

[stlalpha]

Greetings - is there anything we can do to help move this forward? Thanks for the great software!

[cyrillos]

The best would be to send us a patch with this problem fixed ;) Just kidding. Sorry, out of time at the moment. Once time permit I'll do the patch.

[xemul]

@cyrillos , does your recent patch titled "[PATCH] files-reg: Rework strip_deleted" helps with this? Or something else should be done?

[cyrillos]

The patch itself covers only a part of problem: we need to call it when parsing mount points paths, but still while this does the trick for docker as far as I know, the general solution should be restoring deleted mount points. Thus as I said we can merge the patch since it doesn't hurt but need to do more work on top.

[xemul]

Hm... Just curious -- why does this mountpoint appear at all?

[cyrillos]

It's bind mount to deleted mount point. You bindmount some dir, then remove the source and you get //deleted name on the target.

[xemul]

Yes, this is understood. Why does this happen in our case? Who and what for deletes the target?

[cyrillos]

I don't know, it comes from docker log. CC'ing @SaiedKazemi

[SaiedKazemi]

@cyrillos @xemul @fl0yd
I am not sure either. Based on what Mark said, this happens when you run the following docker command:
$ docker run -d ubuntu:latest /sbin/init
I don't know if it's related to the storage driver, docker version, or kernel version. But I verified that it had to do with //deleted. Once I removed //deleted from the pathname, I could successfully checkpoint and restore.

[fl0yd]

It appears to work with external CRIU checkpoint/restore, but using the internal 1.8 experimental checkpoint and restore, I still get the error about a stale file handle.

(00.092761) 1: Restoring fd 5 (state -> create)
(00.092767) 1: fsnotify: Restore 0x1 wd for 0x00000000
(00.092772) 1: fsnotify: Opening fhandle 28:41...
(00.092786) 1: Path /' resolved to./' mountpoint
(00.092856) 1: Error (fsnotify.c:131): fsnotify: Can't open file handle for 0x00000028:0x000000000000000e: Stale file handle

Mark

On Aug 7, 2015, at 2:11 PM, Saied Kazemi notifications@github.com wrote:

@cyrillos https://github.com/cyrillos @xemul https://github.com/xemul @fl0yd https://github.com/fl0yd
I am not sure either. Based on what Mark said, this happens when you run the following docker command:
$ docker run -d ubuntu:latest /sbin/init
I don't know if it's related to the storage driver, docker version, or kernel version. But I verified that it had to do with //deleted. Once I removed //deleted from the pathname, I could successfully checkpoint and restore.

—
Reply to this email directly or view it on GitHub https://github.com/xemul/criu/issues/9#issuecomment-128798102.

[avagin]

Probably /sbin/init deletes /dev/null and creates it again.

[SaiedKazemi]

You're right, it must be /sbin/init. We can easily reproduce it manually:

[Terminal A] $ docker run -it ubuntu:latest bash -i
[Terminal B] $ sudo grep deleted /proc/5274/mountinfo
$
[Terminal A] # rm /dev/null
[Terminal B] $ sudo grep deleted /proc/5274/mountinfo
99 155 0:61 /null//deleted /proc/kcore rw,nosuid - tmpfs tmpfs rw,mode=755
100 155 0:61 /null//deleted /proc/timer_stats rw,nosuid - tmpfs tmpfs rw,mode=755

Notice we cannot remove hosts (or hostname):

[Terminal A] # # rm /etc/hosts
rm: cannot remove '/etc/hosts': Device or resource busy

[xemul]

Should have been fixed by 80ef8fd and d27f539