Strange behavior with fig/seems to work fine with docker

[pmlopes]

Hi,

I've a simple container where i want to check some logging functionality, here is my Docker file:

FROM ubuntu:14.04
MAINTAINER Paulo Lopes "my@email"
ADD syslog_tester /bin/syslog_tester
CMD /bin/syslog_tester

My fig.yml is:

app:
  build: .
  volumes:
    - /dev/log:/dev/log

and for the sake of it the syslog_tester source code is:

#include <syslog.h>

int main() {
  openlog("docker-syslog-tester", LOG_PID, LOG_USER);
  syslog(LOG_INFO, "Sample log message");
  closelog();
  return 0;
}

Now i build the container as usual:

sudo fig build

and if i run it from docker:

sudo docker run -v /dev/log:/dev/log logging_app

always works, however if i do:

sudo fig up

about 50% of the time i get:

Recreating logging_app_1...
Cannot start container d3a0422f77c1cadcc2b14ebaa7418864d292eca732e6ae487f5779981a7e8223: stat /var/lib/docker/aufs/mnt/14dc4061f945e9293c5817624a65c94aade73d547e5b3e0cbd6cb15f228c9c45/dev/log: no such file or directory

my fig version is 0.5.0 and docker 1.1.1 on ubuntu 14.04 64bit

[pmlopes]

Extra info running the binary locally (on the host without any docker/fig) it also works as expected with logging messages showing up on /var/log/syslog file.

[pmlopes]

maybe the issue is that /dev/log is not a file per se, but a unix domain socket. Although unix sockets are exposed on the filesystem so that is why i can mount them in docker...

[aanand]

If it happens with Fig and not plain Docker, it's probably a Fig bug. Could
you diff the output of docker inspect between a container run
successfully with docker and a failed container run with fig?

On Mon, Jul 21, 2014 at 10:05 AM, Paulo Lopes notifications@github.com
wrote:

maybe the issue is that /dev/log is not a file per se, but a unix domain
socket. Although unix sockets are exposed on the filesystem so that is why
i can mount them in docker...

—
Reply to this email directly or view it on GitHub
#328 (comment).

[pmlopes]

this is a borked container:

paulo@jetdrone:~/Projects/logging$ sudo docker inspect logging_app
[{
    "Architecture": "amd64",
    "Author": "Paulo Lopes \"paulo@xxxxx.com\"",
    "Comment": "",
    "Config": {
        "AttachStderr": false,
        "AttachStdin": false,
        "AttachStdout": false,
        "Cmd": [
            "/bin/sh",
            "-c",
            "/bin/syslog_tester"
        ],
        "CpuShares": 0,
        "Cpuset": "",
        "Domainname": "",
        "Entrypoint": null,
        "Env": [
            "HOME=/",
            "PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin"
        ],
        "ExposedPorts": null,
        "Hostname": "0e6756a12879",
        "Image": "aed90271746bd0660ebd3428c119194e8616c6aa102b24ea6188000812615dd0",
        "Memory": 0,
        "MemorySwap": 0,
        "NetworkDisabled": false,
        "OnBuild": [],
        "OpenStdin": false,
        "PortSpecs": null,
        "StdinOnce": false,
        "Tty": false,
        "User": "",
        "Volumes": null,
        "WorkingDir": ""
    },
    "Container": "5848d08e7e6bc642ede93fa69ae752e2df15f475df43f37e63c9d34ce432b377",
    "ContainerConfig": {
        "AttachStderr": false,
        "AttachStdin": false,
        "AttachStdout": false,
        "Cmd": [
            "/bin/sh",
            "-c",
            "#(nop) CMD [/bin/sh -c /bin/syslog_tester]"
        ],
        "CpuShares": 0,
        "Cpuset": "",
        "Domainname": "",
        "Entrypoint": null,
        "Env": [
            "HOME=/",
            "PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin"
        ],
        "ExposedPorts": null,
        "Hostname": "0e6756a12879",
        "Image": "aed90271746bd0660ebd3428c119194e8616c6aa102b24ea6188000812615dd0",
        "Memory": 0,
        "MemorySwap": 0,
        "NetworkDisabled": false,
        "OnBuild": [],
        "OpenStdin": false,
        "PortSpecs": null,
        "StdinOnce": false,
        "Tty": false,
        "User": "",
        "Volumes": null,
        "WorkingDir": ""
    },
    "Created": "2014-07-21T10:01:59.766343179Z",
    "DockerVersion": "1.1.1",
    "Id": "a42add49a323dbc022e09b3fe68d1f2da9630b0311396dad69d11e53b0f04425",
    "Os": "linux",
    "Parent": "aed90271746bd0660ebd3428c119194e8616c6aa102b24ea6188000812615dd0",
    "Size": 0
}
]paulo@jetdrone:~/Projects/logging$ 

This one worked:

paulo@jetdrone:~/Projects/logging$ sudo docker inspect logging_app
[{
    "Architecture": "amd64",
    "Author": "Paulo Lopes \"paulo@xxxxx.com\"",
    "Comment": "",
    "Config": {
        "AttachStderr": false,
        "AttachStdin": false,
        "AttachStdout": false,
        "Cmd": [
            "/bin/sh",
            "-c",
            "/bin/syslog_tester"
        ],
        "CpuShares": 0,
        "Cpuset": "",
        "Domainname": "",
        "Entrypoint": null,
        "Env": [
            "HOME=/",
            "PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin"
        ],
        "ExposedPorts": null,
        "Hostname": "0e6756a12879",
        "Image": "aed90271746bd0660ebd3428c119194e8616c6aa102b24ea6188000812615dd0",
        "Memory": 0,
        "MemorySwap": 0,
        "NetworkDisabled": false,
        "OnBuild": [],
        "OpenStdin": false,
        "PortSpecs": null,
        "StdinOnce": false,
        "Tty": false,
        "User": "",
        "Volumes": null,
        "WorkingDir": ""
    },
    "Container": "5848d08e7e6bc642ede93fa69ae752e2df15f475df43f37e63c9d34ce432b377",
    "ContainerConfig": {
        "AttachStderr": false,
        "AttachStdin": false,
        "AttachStdout": false,
        "Cmd": [
            "/bin/sh",
            "-c",
            "#(nop) CMD [/bin/sh -c /bin/syslog_tester]"
        ],
        "CpuShares": 0,
        "Cpuset": "",
        "Domainname": "",
        "Entrypoint": null,
        "Env": [
            "HOME=/",
            "PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin"
        ],
        "ExposedPorts": null,
        "Hostname": "0e6756a12879",
        "Image": "aed90271746bd0660ebd3428c119194e8616c6aa102b24ea6188000812615dd0",
        "Memory": 0,
        "MemorySwap": 0,
        "NetworkDisabled": false,
        "OnBuild": [],
        "OpenStdin": false,
        "PortSpecs": null,
        "StdinOnce": false,
        "Tty": false,
        "User": "",
        "Volumes": null,
        "WorkingDir": ""
    },
    "Created": "2014-07-21T10:01:59.766343179Z",
    "DockerVersion": "1.1.1",
    "Id": "a42add49a323dbc022e09b3fe68d1f2da9630b0311396dad69d11e53b0f04425",
    "Os": "linux",
    "Parent": "aed90271746bd0660ebd3428c119194e8616c6aa102b24ea6188000812615dd0",
    "Size": 0
}
]paulo@jetdrone:~/Projects/logging$ 

Now fig only works if i rm the before run, in this case it always works...

[aanand]

Now fig only works if i rm the before run, in this case it always works...

Interesting. That makes me wonder if it's to do with VolumesFrom.

When a container is "recreated", we do a slightly complex chain of starting a new container that has VolumesFrom set to the old one... except actually we go via an intermediate no-op container, so that we can delete the old one before creating the new one with the same name.

It's possible that this messes with unix sockets somehow. Will have to experiment to see if it can be replicated with plain Docker and --volumes-from.

[pmlopes]

could you tell what is the docker command i should try for the volumes-from? Since i don't have a data container, i am not sure how to do this...

[mozz100]

FWIW, I'm seeing the same thing (error below, same underlying message) on a Mac via boot2docker. Like @pmlopes observes, the problem seems intermittent; it doesn't always happen. Although once it has happened, it keeps happening. I've found that issuing fig rm followed by fig up gives me a "clean slate" and taking another run at things usually works after that. It feels like something to do with "recreating", but I couldn't say too much more. Happy to try to help diagnose further if I can.

Note: I'm not using volumes_from in my fig.yml file.

>$ fig up
...
(recreating various other docker containers)
...
Recreating webservice_notifications_1...
Cannot start container d779ceb0dfea31042edb7e9d14b93e5ac8a028389701318e9b490b334652db32: stat /mnt/sda1/var/lib/docker/aufs/mnt/b9ff4f49206f2f94e7a558640ef3913f2a85c65f93ba13e08c5aa5105912458b/webservice/notifications/common: no such file or directory

[aanand]

@mozz100 Are you using any volumes at all? It would be good to get a minimal failing fig.yml.

[mozz100]

Yes, I'm using volumes. If you're looking for a minimal failing fig.yml, @pmlopes has the best one. Ours uses build, volumes, links, command, environment, ports etc etc and has 6 different images. I don't want to share here because it contains some sensitive information. If it would really help I'll email it to you? (with passwords and things taken out).

As I say, our fig.yml is way more complicated than the simple example above, and apparently exhibits the same failure.

[quentinsf]

I can confirm that this is repeatable (I work with @mozz100 but on a different machine at a different location). It definitely seems to be an issue with 'recreating' and happens every time - if I 'fig rm' any containers that throw the error, it starts up OK.

[aanand]

OK, I've produced a minimal failing case using plain docker.

If I mount something innocuous like /etc/vim, it works fine. If I mount /dev/log, it breaks. So it looks like there's an intermittent problem with combining /dev/log - which is, as @pmlopes points out, not a regular file - with --volumes-from.

$ sh test.sh /etc/vim
...runs indefinitely...

$ sh test.sh /dev/log
+ '[' '!' -n /dev/log ']'
+ mount_path=/dev/log
++ docker run -d -v /dev/log:/dev/log busybox true
+ last_id=88e6cabcda999a1cdd6cb6e56217c264c708f9b28b945c74bae46c04627ac535
+ docker wait 88e6cabcda999a1cdd6cb6e56217c264c708f9b28b945c74bae46c04627ac535
0
+ true
++ docker run -d --volumes-from 88e6cabcda999a1cdd6cb6e56217c264c708f9b28b945c74bae46c04627ac535 busybox true
+ new_id=eb14509cd69cbf4f5c4d77389a9df4775207392e54b9e13dbdddb35d1ed6a2f8
+ docker wait eb14509cd69cbf4f5c4d77389a9df4775207392e54b9e13dbdddb35d1ed6a2f8
0
+ docker rm 88e6cabcda999a1cdd6cb6e56217c264c708f9b28b945c74bae46c04627ac535
88e6cabcda999a1cdd6cb6e56217c264c708f9b28b945c74bae46c04627ac535
+ last_id=eb14509cd69cbf4f5c4d77389a9df4775207392e54b9e13dbdddb35d1ed6a2f8
+ true
++ docker run -d --volumes-from eb14509cd69cbf4f5c4d77389a9df4775207392e54b9e13dbdddb35d1ed6a2f8 busybox true
2014/08/01 12:42:46 Error response from daemon: Cannot start container e582b8a8fa0a6c48f384203bc694da82efa0c7780d67e4bb2308cb59760d1901: stat /mnt/sda1/var/lib/docker/aufs/mnt/eb14509cd69cbf4f5c4d77389a9df4775207392e54b9e13dbdddb35d1ed6a2f8/tmp/log: no such file or directory
+ new_id=e582b8a8fa0a6c48f384203bc694da82efa0c7780d67e4bb2308cb59760d1901

#!/bin/bash

set -ex

if [ ! -n "$1" ]; then
  echo "Usage: $0 MOUNT_PATH"
  exit 1
fi

mount_path=$1

last_id=$(docker run -d -v $mount_path:$mount_path busybox true)
docker wait $last_id

while true; do
  new_id=$(docker run -d --volumes-from $last_id busybox true)
  docker wait $new_id
  docker rm $last_id
  last_id=$new_id
done

[aanand]

(Updated script so it doesn't delete all your containers)

[dnephin]

I just upgraded to docker 1.1.2, build d84a070, on Ubuntu 14.04, and I'm now getting a similar problem when I run the test suite (fig 0.5.2). Two tests (test_project_up_recreates_containers, test_recreate_containers) fail on the master branch.

Previously I was on docker 1.0.0, and I was not having this problem. I tried the test suite with docker 1.0.1 and docker 1.1.0, it fails with both of those as well. Reverting to docker 1.0.0 is a workaround for now (assuming you don't need anything from newer versions).

Cannot start container e446f1ce6e51...: stat /var/lib/docker/aufs/mnt/5587c4687.../var/db: no such file or directory

$ docker logs 5587c4687
lxc-start: No such file or directory - failed to mount '/var/lib/docker/vfs/dir/87e920f52f3a3d3a7c6f87b0b8b4b84fb80fd45c28676d6c454d9f7316979d7a' on '/usr/lib/x86_64-linux-gnu/lxc///var/db'
lxc-start: failed to setup the mount entries for '5587c4687235721299aac33823275863d4dbdb2d699d2247159ffc8a457dc61f'
lxc-start: failed to setup the container
lxc-start: invalid sequence number 1. expected 2
lxc-start: failed to spawn '5587c4687235721299aac33823275863d4dbdb2d699d2247159ffc8a457dc61f'
lxc-start: The container failed to start.
lxc-start: Additional information can be obtained by setting the --logfile and --log-priority options.