Unable to access volumes using osxfs ("/Mac: Socket not connected") - [f]stat[v]fs family of functions

ddunbar · April 1, 2016, 6:18am

Expected behavior

I expect to be able to access /Mac in my containers, per the docs.

Actual behavior

I don’t see any /Mac mount point.

If I connect to the Moby VM then I see what appears to be an error related to the mount:

docker:~# df
Filesystem           1K-blocks      Used Available Use% Mounted on
tmpfs                   205132       160    204972   0% /run
dev                      10240         0     10240   0% /dev
shm                    1025648         0   1025648   0% /dev/shm
cgroup_root              10240         0     10240   0% /sys/fs/cgroup
/dev/vda2             61885428   3363908  55354852   6% /var
df: /Mac: Socket not connected
/dev/vda2             61885428   3363908  55354852   6% /var/lib/docker/aufs

but I am not sure how to debug this further.

Information

Note that one somewhat non-standard thing I do is keep my HOME directory on a separate partition, with a symlink in /Users to that location. This confuses Docker Toolbox and I work around it by manually mounting things in the VM (a la docker/machine#1826). I can’t tell if that might be related to what is happening here.

FWIW, I tried switch to a different user which is not configured this way. That exposed two problems:

Docker refused to launch with various errors when launched from that user’s session while I still had it running in my primary session.
After quitting docker in my primary session, docker refused to launch because of “missing beta access”. If someone can tell me how to configure the alternate user with access I can try this experiment again.

$ pinata diagnose -u
OS X: version 10.11.4 (build: 15E65)
Docker.app: version v1.10.3-beta5
Running diagnostic tests:
[OK]      docker-cli
[OK]      Moby booted
[OK]      driver.amd64-linux
[OK]      vmnetd
[OK]      lofs
[OK]      osxfs
[OK]      db
[OK]      slirp
[OK]      menubar
[OK]      environment
[OK]      Docker
[OK]      VT-x
Docker logs are being collected into /tmp/20160331-231534.tar.gz.
Your unique id in bugsnag is: A5C65C17-C407-462C-AB01-8DECCFB46F44
Please quote this in all correspondence.

Steps to reproduce the behavior

Run a shell in any container (e.g., nginx from the tutorial docs)
ls /Mac

dsheets · April 1, 2016, 10:13am

Hi Daniel,

If you still have the Docker.qcow2 file that exhibited the problem, could you post the contents of /var/transfused_start.log? I’m concerned about this preceding event in the VM boot:

* Configuring host block device ...modprobe: FATAL: Module ext4 not found in directory /lib/modules/4.1.19
modprobe: FATAL: Module ext4 not found in directory /lib/modules/4.1.19
modprobe: FATAL: Module ext4 not found in directory /lib/modules/4.1.19
e7  0% [                                           ]e8e[0KInitializing partitions on /dev/vda...
Creating file systems...
mke2fs 1.42.13 (17-May-2015)
 [ ok ]

Some debugging improvements are coming in Beta 6.

Thanks for your report and participation in the Docker for Mac Beta!

ddunbar · April 1, 2016, 3:02pm

I’m assuming you mean from the VM? (I am new to this stuff and have never dealt with the qcow2 file before)

$ screen ~/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/tty
... login ...
docker:/var# cat transfused_start.log
2016-03-31 23:35:21.421 mount /bin/fusermount -o allow_other,max_read=32741,subtype=osxfs /Mac
2016-03-31 23:35:21.423 Log mount trigger fired on /Mac, logging to /Mac/Users/ddunbar/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/log/transfused.log
2016-04-01 06:17:13.668 mount /bin/fusermount -o allow_other,max_read=32741,subtype=osxfs /Mac
2016-04-01 06:17:13.670 Log mount trigger fired on /Mac, logging to /Mac/Users/ddunbar/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/log/transfused.log
2016-04-01 06:34:24.303 mount /bin/fusermount -o allow_other,max_read=32741,subtype=osxfs /Mac
2016-04-01 06:34:24.306 Log mount trigger fired on /Mac, logging to /Mac/Users/ddunbar/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/log/transfused.log

Also, where is the log file in which you saw that ext4 error?

tomfrost · April 6, 2016, 3:56am

I also don’t have a /Mac mountpoint – would be happy to debug, though I’m uncertain how to access the vm directly. I untarred/ungzipped the logs and dumped out com.docker.osxfs.log:

2016-04-05T23:29:29.665383-04 Info - accepted connection
2016-04-05T23:29:29.665440-04 Info - C ((tag ()) (payload (Version ((msize 65536) (version TwoThousand)))))
2016-04-05T23:29:29.665468-04 Info - Using protocol TwoThousand msize 16384
2016-04-05T23:29:29.665492-04 Info - C ((tag (1))
2016-04-05T23:29:29.665515-04 Info -    (payload
2016-04-05T23:29:29.665538-04 Info -     (Attach ((fid 1) (afid -1) (uname anyone) (aname /) (n_uname ())))))
2016-04-05T23:29:29.665560-04 Info - Successfully negotiated a connection.
2016-04-05T23:29:32.235585-04 Info - C ((tag ()) (payload (Version ((msize 32768) (version TwoThousand)))))
2016-04-05T23:29:32.235637-04 Info - Using protocol TwoThousand msize 32768
2016-04-05T23:29:32.235665-04 Info - C ((tag (1))
2016-04-05T23:29:32.235689-04 Info -    (payload
2016-04-05T23:29:32.235714-04 Info -     (Attach ((fid 0) (afid -1) (uname nobody) (aname "") (n_uname ())))))
2016-04-05T23:29:32.235737-04 Info - Negotiated a connection with msize 32768.
2016-04-05T23:29:32.772185-04 Error - Event thread is 1092
2016-04-05T23:29:32.782855-04 Error - max_readahead = 32741 max_write = 32680
2016-04-05T23:29:32.782945-04 Error - osxfs tracing: OFF
2016-04-05T23:29:59.641801-04 Error - com.docker.osxfs: [ERROR] Volume.start b2bddbfab9a8053bad59a9b9bd0e0f4b42dc7d4df17a7d124ecfb83b0efdd77c (paths = [/Users/tom, /Users/tom/Projects/userhub])
2016-04-05T23:29:59.641905-04 Error - Adding watch for /Users/tom
2016-04-05T23:29:59.641964-04 Error - Volume: watching /Users/tom since now
2016-04-05T23:29:59.642014-04 Error - Adding watch for /Users/tom/Projects/userhub
2016-04-05T23:30:00.385952-04 Error - start_watch: got event from stream
2016-04-05T23:33:55.946644-04 Error - com.docker.osxfs: [ERROR] Volume.stop b2bddbfab9a8053bad59a9b9bd0e0f4b42dc7d4df17a7d124ecfb83b0efdd77c (paths = [/Users/tom, /Users/tom/Projects/userhub])
2016-04-05T23:33:55.946772-04 Error - Removing watch for /Users/tom
2016-04-05T23:33:55.946839-04 Error - about to flush watcher for /Users/tom
2016-04-05T23:33:55.946904-04 Error - 2016-04-05 23:33 com.docker.osxfs[95182] (FSEvents.framework) FSEventStreamFlushSync(): failed assertion '(SInt64)last_id > 0LL'
2016-04-05T23:33:55.946963-04 Error - stopped watching /Users/tom
2016-04-05T23:33:55.947021-04 Error - restarting watch of /Users/tom/Projects/userhub
2016-04-05T23:33:55.947079-04 Error - Volume: watching /Users/tom/Projects/userhub since 18158642065532649396
2016-04-05T23:33:55.947135-04 Error - Stream ended (continue)
2016-04-05T23:33:55.947190-04 Error - Removing watch for /Users/tom/Projects/userhub
2016-04-05T23:33:55.947246-04 Error - about to flush watcher for /Users/tom/Projects/userhub
2016-04-05T23:33:55.947305-04 Error - 2016-04-05 23:33 com.docker.osxfs[95182] (FSEvents.framework) FSEventStreamFlushSync:1(streamRef = 0x7fc2020fb120): ERROR: CFRunLoopRunInMode() => The run loop mode mode has no sources or timers. (1)
2016-04-05T23:33:55.947364-04 Error - stopped watching /Users/tom/Projects/userhub
2016-04-05T23:33:55.947419-04 Error - removed last watch
2016-04-05T23:33:55.947473-04 Error - Stream ended (start)
2016-04-05T23:51:20.015907-04 Info - Error: Caught EOF on underlying FLOW

/var/log/transfused.log was empty.

Here’s my pinata diagnose:

OS X: version 10.11.4 (build: 15E65)
Docker.app: version v1.11.0-beta6
Running diagnostic tests:
[OK]      docker-cli
[OK]      Moby booted
[OK]      driver.amd64-linux
[OK]      vmnetd
[OK]      osxfs
[OK]      db
[OK]      slirp
[OK]      menubar
[OK]      environment
[OK]      Docker
[OK]      VT-x
Docker logs are being collected into /tmp/20160405-235557.tar.gz.

Also, unlike OP, I don’t have any custom mountpoints on my host mac.

dsheets · April 6, 2016, 2:07pm

Could you please run pinata diagnose -u to upload the log archive?

Also, could you please enter the debug console of the VM with screen ~/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/tty and then cat /var/transfused_start.log?

tomfrost · April 6, 2016, 3:46pm

I’m being prompted to log in after that screen command – any thoughts?

Login Prompt

I’ve uploaded my logs, bugsnag id is: 4D76F500-A6CA-45D2-B18A-ABFFBF17071E

dsheets · April 6, 2016, 4:04pm

Username: root
No password

tomfrost · April 6, 2016, 4:44pm

Thanks!

docker:~# cat /var/transfused_start.log
2016-03-29 20:12:11.250 mount /bin/fusermount -o allow_other,max_read=32741,subtype=osxfs /Mac
2016-03-29 20:12:11.251 Log mount trigger fired on /Mac, logging to /Mac/Users/tom/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/log/transfused.log
2016-03-30 17:44:08.199 mount /bin/fusermount -o allow_other,max_read=32741,subtype=osxfs /Mac
2016-03-30 17:44:08.203 Log mount trigger fired on /Mac, logging to /Mac/Users/tom/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/log/transfused.log
2016-03-30 17:46:28.981 mount /bin/fusermount -o allow_other,max_read=32741,subtype=osxfs /Mac
2016-03-30 17:46:28.984 Log mount trigger fired on /Mac, logging to /Mac/Users/tom/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/log/transfused.log
2016-03-31 17:57:05.508 mount /bin/fusermount -o allow_other,max_read=32741,subtype=osxfs /Mac
2016-03-31 17:57:05.510 Log mount trigger fired on /Mac, logging to /Mac/Users/tom/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/log/transfused.log
2016-04-06 03:29:32.342 mount /bin/fusermount -o allow_other,max_read=32741,subtype=osxfs /Mac
2016-04-06 03:29:32.344 Log mount trigger fired on /Mac, logging to /Mac/Users/tom/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/log/transfused.log

cliffom · April 6, 2016, 7:41pm

Providing my info as well:

~ pinata diagnose -u
OS X: version 10.11.4 (build: 15E64a)
Docker.app: version v1.11.0-beta6
Running diagnostic tests:
[OK]      docker-cli
[OK]      Moby booted
[OK]      driver.amd64-linux
[OK]      vmnetd
[OK]      osxfs
[OK]      db
[OK]      slirp
[OK]      menubar
[OK]      environment
[OK]      Docker
[OK]      VT-x
Docker logs are being collected into /tmp/20160406-123425.tar.gz.
Your unique id in bugsnag is: D42DC90E-3BCE-4C61-93A6-C271A46292A6

docker:~# cat /var/transfused_start.log
2016-04-02 05:01:43.976 mount /bin/fusermount -o allow_other,max_read=32741,subtype=osxfs /Mac 
2016-04-02 05:01:43.977 Log mount trigger fired on /Mac, logging to /Mac/Users/cliffom/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/log/transfused.log
2016-04-02 05:30:37.845 mount /bin/fusermount -o allow_other,max_read=32741,subtype=osxfs /Mac 
2016-04-02 05:30:37.847 Log mount trigger fired on /Mac, logging to /Mac/Users/cliffom/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/log/transfused.log
2016-04-02 05:38:27.694 mount /bin/fusermount -o allow_other,max_read=32741,subtype=osxfs /Mac 
2016-04-02 05:38:27.695 Log mount trigger fired on /Mac, logging to /Mac/Users/cliffom/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/log/transfused.log
2016-04-02 05:39:13.600 mount /bin/fusermount -o allow_other,max_read=32741,subtype=osxfs /Mac 
2016-04-02 05:39:13.601 Log mount trigger fired on /Mac, logging to /Mac/Users/cliffom/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/log/transfused.log
2016-04-02 06:49:16.113 mount /bin/fusermount -o allow_other,max_read=32741,subtype=osxfs /Mac 
2016-04-02 06:49:16.115 Log mount trigger fired on /Mac, logging to /Mac/Users/cliffom/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/log/transfused.log
2016-04-02 06:49:40.636 mount /bin/fusermount -o allow_other,max_read=32741,subtype=osxfs /Mac 
2016-04-02 06:49:40.638 Log mount trigger fired on /Mac, logging to /Mac/Users/cliffom/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/log/transfused.log
2016-04-03 18:24:40.633 mount /bin/fusermount -o allow_other,max_read=32741,subtype=osxfs /Mac 
2016-04-03 18:24:40.635 Log mount trigger fired on /Mac, logging to /Mac/Users/cliffom/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/log/transfused.log
2016-04-06 16:10:00.696 mount /bin/fusermount -o allow_other,max_read=32741,subtype=osxfs /Mac 
2016-04-06 16:10:00.698 Log mount trigger fired on /Mac, logging to /Mac/Users/cliffom/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/log/transfused.log
2016-04-06 16:11:13.669 mount /bin/fusermount -o allow_other,max_read=32741,subtype=osxfs /Mac 
2016-04-06 16:11:13.670 Log mount trigger fired on /Mac, logging to /Mac/Users/cliffom/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/log/transfused.log
2016-04-06 19:01:15.693 mount /bin/fusermount -o allow_other,max_read=32741,subtype=osxfs /Mac 
2016-04-06 19:01:15.695 Log mount trigger fired on /Mac, logging to /Mac/Users/cliffom/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/log/transfused.log
2016-04-06 19:17:12.613 mount /bin/fusermount -o allow_other,max_read=32741,subtype=osxfs /Mac 
2016-04-06 19:17:12.615 Log mount trigger fired on /Mac, logging to /Mac/Users/cliffom/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/log/transfused.log

The /Mac mount point exists on the VM:

docker:~# mount | grep Mac
osxfs on /Mac type fuse.osxfs (rw,nosuid,nodev,relatime,user_id=0,group_id=0,allow_other,max_read=32741)

I can mount a folder on my Mac’s / via

docker run --rm -it -v /Mac/var:/tmp/test -w /tmp/test alpine /bin/sh

It appears fuse.osxfs is working as intended:

/tmp/test # mount |grep test
osxfs on /tmp/test type fuse.osxfs (rw,nosuid,nodev,relatime,user_id=0,group_id=0,allow_other,max_read=32741)

@tomfrost Would you mind confirming whether or not this is the case on your end?

ddunbar · April 6, 2016, 7:44pm

Can anyone comment on how to get more info on the “Socket not connected” message?

tomfrost · April 6, 2016, 7:56pm

@cliffom I have the same results to all your tests on my machine. Good catch! So osxfs is there, it’s just not automounting. What’s more, this confirms that the test from the file access performance thread was, in fact, running over osxfs; and so that’s where the speed issue is.

@ddunbar df for me reports “Function not implemented” for my osxfs mounts.

cliffom · April 6, 2016, 8:02pm

@tomfrost I don’t think auto-mounting /Mac to containers is intended behavior. Containers only mount volumes passed explicitly with -v; Having /Mac in the VM allows you to mount directories outside of /Users and in the Mac volume root / by prefixing them with /Mac. At least that is my understanding.

Perhaps @dsheets can chime in and set us straight. However, as it stands, I don’t think we are having the issues @ddunbar is experiencing.

ddunbar · April 6, 2016, 8:15pm

That was my understanding as well.

dsheets · April 7, 2016, 10:33am

@ddunbar Socket not connected is concerning to me – it indicates that the VM-side component of osxfs is not running. Can you reproduce it? Does it occur on start-up or only after running a container? Always after running a single container? Do you have a core file in / or /var?

dsheets · April 7, 2016, 10:37am

@cliffom I believe your understanding is correct. We are still developing the appropriate bind mount semantics but, in Beta 6, the special host paths available for bind mounts are /Mac (the whole host), /Users, /Volumes, /tmp, and /private. The mount points only appear in containers when using -v to bind mount into the mount namespace of the container. This gives containers and their operators complete control over the file system namespace of the containerized software.

Unless other people are experiencing Socket not connected or Transport endpoint not connected errors, a new thread should be created to discuss other issues with osxfs.

dsheets · April 7, 2016, 10:40am

@tomfrost The [f]stat[v]fs family of functions (which are necessary for proper df function) are not yet implemented. We have support planned which will export the entire mount table of OS X into the VM but it hasn’t been completed yet. This may also cause issues with database software that expects to be able to successfully execute these syscalls against its data store. Watch the changelog for updates regarding this feature and thanks for using Docker for Mac Beta!

dsheets · April 7, 2016, 1:01pm

@ddunbar What is the location and content of your home directory symlink?

ddunbar · April 7, 2016, 4:22pm

The link is:

$ ls -lP /Users/ddunbar
lrwxr-xr-x  1 ddunbar  admin  21 Jun 29  2015 /Users/ddunbar -> /Volumes/Data/ddunbar

and /Volumes/Data is an otherwise normal volume (it does use full disk encryption, if that could be related at all).

Does the exact symlink matter if I am completely unable to see any of the mounts inside the VM, or is there some other magic going on when -v is used?