[1.6.0] cannot run against swarm in attached mode

[bergtwvd]

Using Docker 1.10, Compose 1.6.0 / 1.5.x / 1.4.x, and Swarm 1.1.0.

I set up a swarm with 4 nodes. The swarm master is started on node 1 with:
docker run -p 5000:2375 -it swarm --debug manage -H tcp://0.0.0.0:2375 "nodes://x.x.x.[65:68]:2375"

I set DOCKER_HOST to point to the swarm master.

I use the following compose YML file for test purposes:

web:
  image: busybox
  container_name: web

docker-compose-1.4.2 -f myfile.yml up => WORKS OK
docker-compose-1.5.0 -f myfile.yml up => EVENTUALLY TIMES OUT
docker-compose-1.5.1 -f myfile.yml up => EVENTUALLY TIMES OUT
docker-compose-1.5.2 -f myfile.yml up => EVENTUALLY TIMES OUT
docker-compose-1.6.0 -f myfile.yml up => EVENTUALLY TIMES OUT

It seems that a change introduced in 1.5.0 causes a problem in combination with swarm 1.6.0.

See also docker-archive/classicswarm#1765.

LOGS:

bergtwvd@app-docker01:~$ docker-compose-1.4.2 -v
docker-compose version: 1.4.2
bergtwvd@app-docker01:~$ docker-compose-1.4.2 --verbose -f vesselsim.yml up
Compose version 1.4.2
Docker base_url: http://x.x.x.65:5000
Docker version: KernelVersion=3.13.0-76-generic, Os=linux, BuildTime=Thu Feb  4 08:55:18 UTC 2016, ApiVersion=1.22, Version=swarm/1.1.0, GitCommit=a0fd82b, Arch=amd64, GoVersion=go1.5.3
docker containers <- (all=True, filters={u'label': [u'com.docker.compose.project=bergtwvd', u'com.docker.compose.service=web', u'com.docker.compose.oneoff=False']})
docker containers -> (list with 0 items)
docker containers <- (all=True)
docker containers -> (list with 4 items)
docker containers <- (all=True, filters={u'label': [u'com.docker.compose.project=bergtwvd', u'com.docker.compose.service=web', u'com.docker.compose.oneoff=False']})
docker containers -> (list with 0 items)
docker containers <- (all=True)
docker containers -> (list with 4 items)
docker inspect_image <- ('busybox')
docker inspect_image -> {u'Architecture': u'amd64',
 u'Author': u'',
 u'Comment': u'',
 u'Config': {u'AttachStderr': False,
             u'AttachStdin': False,
             u'AttachStdout': False,
             u'Cmd': [u'sh'],
             u'Domainname': u'',
             u'Entrypoint': None,
             u'Env': None,
...
docker containers <- (all=True, filters={u'label': [u'com.docker.compose.project=bergtwvd', u'com.docker.compose.service=web', u'com.docker.compose.oneoff=False']})
docker containers -> (list with 0 items)
docker inspect_image <- ('busybox')
docker inspect_image -> {u'Architecture': u'amd64',
 u'Author': u'',
 u'Comment': u'',
 u'Config': {u'AttachStderr': False,
             u'AttachStdin': False,
             u'AttachStdout': False,
             u'Cmd': [u'sh'],
             u'Domainname': u'',
             u'Entrypoint': None,
             u'Env': None,
...
Creating web...
docker create_container <- (name='web', image='busybox', labels={u'com.docker.compose.service': u'web', u'com.docker.compose.project': u'bergtwvd', 'com.docker.compose.config-hash': 'cc0180c5c01e45757e4d15a397a4804a7ac9bca5899c5024383855554986e776', 'com.docker.compose.version': u'1.4.2', u'com.docker.compose.oneoff': u'False', 'com.docker.compose.container-number': '1'}, host_config={'Links': [], 'PortBindings': {}, 'Binds': [], 'ExtraHosts': [], 'LogConfig': {'Type': u'json-file', 'Config': {}}, 'VolumesFrom': []}, environment={}, detach=True)
docker create_container -> {u'Id': u'f440e330110dcc4a70295e41842dc62ef24bb5af168f1e40c32b425e9433c03b'}
docker inspect_container <- (u'f440e330110dcc4a70295e41842dc62ef24bb5af168f1e40c32b425e9433c03b')
docker inspect_container -> {u'AppArmorProfile': u'',
 u'Args': [],
 u'Config': {u'AttachStderr': False,
             u'AttachStdin': False,
             u'AttachStdout': False,
             u'Cmd': [u'sh'],
             u'Domainname': u'',
             u'Entrypoint': None,
             u'Env': None,
             u'Hostname': u'f440e330110d',
...
docker start <- (u'f440e330110dcc4a70295e41842dc62ef24bb5af168f1e40c32b425e9433c03b')
docker start -> None
docker inspect_container <- (u'f440e330110dcc4a70295e41842dc62ef24bb5af168f1e40c32b425e9433c03b')
docker inspect_container -> {u'AppArmorProfile': u'',
 u'Args': [],
 u'Config': {u'AttachStderr': False,
             u'AttachStdin': False,
             u'AttachStdout': False,
             u'Cmd': [u'sh'],
             u'Domainname': u'',
             u'Entrypoint': None,
             u'Env': None,
             u'Hostname': u'f440e330110d',
...
Attaching to web
docker attach <- (u'f440e330110dcc4a70295e41842dc62ef24bb5af168f1e40c32b425e9433c03b', stderr=1, logs=1, stream=1, stdout=1)
docker attach -> <generator object _multiplexed_response_stream_helper at 0x7fc2f893f780>
docker wait <- (u'f440e330110dcc4a70295e41842dc62ef24bb5af168f1e40c32b425e9433c03b')
docker wait -> 0
web exited with code 0
Gracefully stopping... (press Ctrl+C again to force)
docker containers <- (all=False, filters={u'label': [u'com.docker.compose.project=bergtwvd', u'com.docker.compose.oneoff=False']})
docker containers -> (list with 0 items)
docker containers <- (all=True)
docker containers -> (list with 5 items)
bergtwvd@app-docker01:~$

bergtwvd@app-docker01:~$ docker-compose -v
docker-compose version 1.6.0, build d99cad6
bergtwvd@app-docker01:~$ docker-compose --verbose -f vesselsim.yml up
compose.config.config.find: Using configuration files: ./vesselsim.yml
docker.auth.auth.load_config: Found 'auths' section
docker.auth.auth.parse_auth: Found entry (registry=u'', username=u'bergtwvd')
compose.cli.command.get_client: docker-compose version 1.6.0, build d99cad6
docker-py version: 1.7.0
CPython version: 2.7.9
OpenSSL version: OpenSSL 1.0.1e 11 Feb 2013
compose.cli.command.get_client: Docker base_url: http://x.x.x.65:5000
compose.cli.command.get_client: Docker version: KernelVersion=3.13.0-76-generic, Os=linux, BuildTime=Thu Feb  4 08:55:18 UTC 2016, ApiVersion=1.22, Version=swarm/1.1.0, GitCommit=a0fd82b, Arch=amd64, GoVersion=go1.5.3
compose.cli.verbose_proxy.proxy_callable: docker containers <- (all=True, filters={u'label': [u'com.docker.compose.project=bergtwvd', u'com.docker.compose.service=web', u'com.docker.compose.oneoff=False']})
compose.cli.verbose_proxy.proxy_callable: docker containers -> (list with 0 items)
compose.cli.verbose_proxy.proxy_callable: docker containers <- (all=True, filters={u'label': [u'com.docker.compose.project=bergtwvd', u'com.docker.compose.service=web', u'com.docker.compose.oneoff=False']})
compose.cli.verbose_proxy.proxy_callable: docker containers -> (list with 0 items)
compose.cli.verbose_proxy.proxy_callable: docker inspect_image <- ('busybox')
compose.cli.verbose_proxy.proxy_callable: docker inspect_image -> {u'Architecture': u'amd64',
 u'Author': u'',
 u'Comment': u'',
 u'Config': {u'AttachStderr': False,
             u'AttachStdin': False,
             u'AttachStdout': False,
             u'Cmd': [u'sh'],
             u'Domainname': u'',
             u'Entrypoint': None,
             u'Env': None,
...
compose.cli.verbose_proxy.proxy_callable: docker containers <- (all=True, filters={u'label': [u'com.docker.compose.project=bergtwvd', u'com.docker.compose.service=web', u'com.docker.compose.oneoff=False']})
compose.cli.verbose_proxy.proxy_callable: docker containers -> (list with 0 items)
compose.cli.verbose_proxy.proxy_callable: docker inspect_image <- ('busybox')
compose.cli.verbose_proxy.proxy_callable: docker inspect_image -> {u'Architecture': u'amd64',
 u'Author': u'',
 u'Comment': u'',
 u'Config': {u'AttachStderr': False,
             u'AttachStdin': False,
             u'AttachStdout': False,
             u'Cmd': [u'sh'],
             u'Domainname': u'',
             u'Entrypoint': None,
             u'Env': None,
...
compose.service.build_container_labels: Added config hash: 21713a75902bd287bdc5a8448ed0219763c54eb1ee8bb2234763fc687a235d2f
compose.cli.verbose_proxy.proxy_callable: docker create_host_config <- (memswap_limit=None, links=[], devices=None, pid_mode=None, log_config={'Type': u'', 'Config': {}}, cpu_quota=None, read_only=None, dns=None, volumes_from=[], port_bindings={}, security_opt=None, extra_hosts=None, cgroup_parent=None, network_mode=None, cap_add=None, restart_policy=None, dns_search=None, privileged=False, binds=[], ipc_mode=None, mem_limit=None, cap_drop=None, ulimits=None)
compose.cli.verbose_proxy.proxy_callable: docker create_host_config -> {'Binds': [],
 'Links': [],
 'LogConfig': {'Config': {}, 'Type': u''},
 'NetworkMode': 'default',
 'PortBindings': {},
 'VolumesFrom': []}
compose.service.create_container: Creating web
compose.cli.verbose_proxy.proxy_callable: docker create_container <- (name='web', image='busybox', labels={u'com.docker.compose.service': u'web', u'com.docker.compose.project': u'bergtwvd', u'com.docker.compose.config-hash': '21713a75902bd287bdc5a8448ed0219763c54eb1ee8bb2234763fc687a235d2f', u'com.docker.compose.version': u'1.6.0', u'com.docker.compose.oneoff': u'False', u'com.docker.compose.container-number': '1'}, host_config={'NetworkMode': 'default', 'Links': [], 'PortBindings': {}, 'Binds': [], 'LogConfig': {'Type': u'', 'Config': {}}, 'VolumesFrom': []}, environment={}, detach=True)
compose.cli.verbose_proxy.proxy_callable: docker create_container -> {u'Id': u'2b7a42b1e3f38469906f7f0805ddd35dce725fd97a56417a237f3e19d8d79c43'}
compose.cli.verbose_proxy.proxy_callable: docker inspect_container <- (u'2b7a42b1e3f38469906f7f0805ddd35dce725fd97a56417a237f3e19d8d79c43')
compose.cli.verbose_proxy.proxy_callable: docker inspect_container -> {u'AppArmorProfile': u'',
 u'Args': [],
 u'Config': {u'AttachStderr': False,
             u'AttachStdin': False,
             u'AttachStdout': False,
             u'Cmd': [u'sh'],
             u'Domainname': u'',
             u'Entrypoint': None,
             u'Env': None,
             u'Hostname': u'2b7a42b1e3f3',
...
compose.cli.verbose_proxy.proxy_callable: docker inspect_container <- (u'2b7a42b1e3f38469906f7f0805ddd35dce725fd97a56417a237f3e19d8d79c43')
compose.cli.verbose_proxy.proxy_callable: docker inspect_container -> {u'AppArmorProfile': u'',
 u'Args': [],
 u'Config': {u'AttachStderr': False,
             u'AttachStdin': False,
             u'AttachStdout': False,
             u'Cmd': [u'sh'],
             u'Domainname': u'',
             u'Entrypoint': None,
             u'Env': None,
             u'Hostname': u'2b7a42b1e3f3',
...
compose.cli.verbose_proxy.proxy_callable: docker attach <- (u'2b7a42b1e3f38469906f7f0805ddd35dce725fd97a56417a237f3e19d8d79c43', stderr=True, stream=True, stdout=True)
ERROR: compose.cli.main.main: An HTTP request took too long to complete. Retry with --verbose to obtain debug information.
If you encounter this issue regularly because of slow network conditions, consider setting COMPOSE_HTTP_TIMEOUT to a higher value (current value: 60).
bergtwvd@app-docker01:~$

[bergtwvd]

Below a docker swarm (1.1.0) debug output (with the same timeout on docker-compose (1.6.0) side) obtained by running the shown compose file.

Docker compose times out on creating the first service (crc).

In the swarm output I am puzzled about these two lines:
DEBU[0017] Proxy request method=GET url=http://a.a.a.68:2375/v1.22/images/msaas%2Fpi-crc%3A5.0.1.0L/json

and a few lines further down
DEBU[0017] Proxy hijack request addr=a.a.a.67:2375

the latter is another address than the previous proxy request.

DOCKER COMPOSE FILE:

version: '2'

services:
 shipsim:
  links:
  - crc:crc
  image: msaas/shipsim
  command: -F TheWorld -f ShipSim -c crc
  networks:
  - training1
  environment:
  - adapter=eth0

 trafficsim:
  links:
  - crc:crc
  image: msaas/vesseltraffic
  container_name: trafficsim
  command: -F TheWorld -f TrafficSim -c crc -k Tracks.kml -s 2 -d 5
  networks:
  - training1
  environment:
  - adapter=eth0

 crc:
  image: msaas/pi-crc:5.0.1.0L
  mac_address: 00:18:8B:0D:4F:0B
  container_name: crc
  networks:
  - training1
  ports:
  - "8989:8989"

 web:
  image: msaas/pi-web:2.1.0
  container_name: web
  networks:
  - training1
  ports:
  - "8080:8080"

 ge:
  links:
  - crc:crc
  image: msaas/pi-ge:1.4.1L
  mac_address: 74:86:7A:6E:94:FA
  container_name: ge
  command: -F TheWorld -f Google -g app-docker01.x.x.x-t 10 -c crc
  networks:
  - training1
  ports:
  - "8765:8765"
  - "9005:9001"
  environment:
  - adapter=eth0

networks:
 training1:
  external: true

SWARM DEBUG OUTPUT:

bergtwvd@app-docker01:~$ docker run -p 5000:2375 -it swarm --debug manage -H tcp://0.0.0.0:2375 "nodes://a.a.a.[65:68]:2375"
DEBU[0000] Initializing discovery service                name=nodes uri=a.a.a.[65:68]:2375
DEBU[0000] Initializing strategy                         name=spread
DEBU[0000] Initializing filter                           name=health
DEBU[0000] Initializing filter                           name=port
DEBU[0000] Initializing filter                           name=dependency
DEBU[0000] Initializing filter                           name=affinity
DEBU[0000] Initializing filter                           name=constraint
DEBU[0000] Initializing cluster                          name=swarm
DEBU[0000] Registering HTTP route                        method=HEAD route=/containers/{name:.*}/archive
DEBU[0000] Registering HTTP route                        method=GET route=/_ping
DEBU[0000] Registering HTTP route                        method=GET route=/images/json
DEBU[0000] Registering HTTP route                        method=GET route=/images/search
DEBU[0000] Registering HTTP route                        method=GET route=/images/{name:.*}/get
DEBU[0000] Registering HTTP route                        method=GET route=/exec/{execid:.*}/json
DEBU[0000] Registering HTTP route                        method=GET route=/networks/{networkid:.*}
DEBU[0000] Registering HTTP route                        method=GET route=/volumes/{volumename:.*}
DEBU[0000] Registering HTTP route                        method=GET route=/images/viz
DEBU[0000] Registering HTTP route                        method=GET route=/images/get
DEBU[0000] Registering HTTP route                        method=GET route=/containers/{name:.*}/archive
DEBU[0000] Registering HTTP route                        method=GET route=/containers/{name:.*}/stats
DEBU[0000] Registering HTTP route                        method=GET route=/info
DEBU[0000] Registering HTTP route                        method=GET route=/images/{name:.*}/json
DEBU[0000] Registering HTTP route                        method=GET route=/containers/{name:.*}/changes
DEBU[0000] Registering HTTP route                        method=GET route=/networks
DEBU[0000] Registering HTTP route                        method=GET route=/containers/json
DEBU[0000] Registering HTTP route                        method=GET route=/containers/{name:.*}/export
DEBU[0000] Registering HTTP route                        method=GET route=/containers/{name:.*}/json
DEBU[0000] Registering HTTP route                        method=GET route=/containers/{name:.*}/top
DEBU[0000] Registering HTTP route                        method=GET route=/events
DEBU[0000] Registering HTTP route                        method=GET route=/version
DEBU[0000] Registering HTTP route                        method=GET route=/images/{name:.*}/history
DEBU[0000] Registering HTTP route                        method=GET route=/containers/ps
DEBU[0000] Registering HTTP route                        method=GET route=/containers/{name:.*}/logs
DEBU[0000] Registering HTTP route                        method=GET route=/containers/{name:.*}/attach/ws
DEBU[0000] Registering HTTP route                        method=GET route=/volumes
DEBU[0000] Registering HTTP route                        method=POST route=/containers/{name:.*}/unpause
DEBU[0000] Registering HTTP route                        method=POST route=/containers/{name:.*}/restart
DEBU[0000] Registering HTTP route                        method=POST route=/containers/{name:.*}/exec
DEBU[0000] Registering HTTP route                        method=POST route=/commit
DEBU[0000] Registering HTTP route                        method=POST route=/containers/{name:.*}/rename
DEBU[0000] Registering HTTP route                        method=POST route=/containers/{name:.*}/stop
DEBU[0000] Registering HTTP route                        method=POST route=/images/{name:.*}/tag
DEBU[0000] Registering HTTP route                        method=POST route=/containers/{name:.*}/attach
DEBU[0000] Registering HTTP route                        method=POST route=/images/load
DEBU[0000] Registering HTTP route                        method=POST route=/containers/{name:.*}/kill
DEBU[0000] Registering HTTP route                        method=POST route=/containers/{name:.*}/pause
DEBU[0000] Registering HTTP route                        method=POST route=/containers/{name:.*}/start
DEBU[0000] Registering HTTP route                        method=POST route=/networks/{networkid:.*}/connect
DEBU[0000] Registering HTTP route                        method=POST route=/containers/{name:.*}/update
DEBU[0000] Registering HTTP route                        method=POST route=/images/create
DEBU[0000] Registering HTTP route                        method=POST route=/images/{name:.*}/push
DEBU[0000] Registering HTTP route                        method=POST route=/volumes/create
DEBU[0000] Registering HTTP route                        method=POST route=/auth
DEBU[0000] Registering HTTP route                        method=POST route=/build
DEBU[0000] Registering HTTP route                        method=POST route=/containers/create
DEBU[0000] Registering HTTP route                        method=POST route=/containers/{name:.*}/wait
DEBU[0000] Registering HTTP route                        method=POST route=/exec/{execid:.*}/resize
DEBU[0000] Registering HTTP route                        method=POST route=/containers/{name:.*}/resize
DEBU[0000] Registering HTTP route                        method=POST route=/containers/{name:.*}/copy
DEBU[0000] Registering HTTP route                        method=POST route=/exec/{execid:.*}/start
DEBU[0000] Registering HTTP route                        method=POST route=/networks/create
DEBU[0000] Registering HTTP route                        method=POST route=/networks/{networkid:.*}/disconnect
DEBU[0000] Registering HTTP route                        method=PUT route=/containers/{name:.*}/archive
DEBU[0000] Registering HTTP route                        method=DELETE route=/containers/{name:.*}
DEBU[0000] Registering HTTP route                        method=DELETE route=/images/{name:.*}
DEBU[0000] Registering HTTP route                        method=DELETE route=/networks/{networkid:.*}
DEBU[0000] Registering HTTP route                        method=DELETE route=/volumes/{name:.*}
INFO[0000] Listening for HTTP                            addr=0.0.0.0:2375 proto=tcp
DEBU[0000] Start monitoring events                       id=OXJJ:ZUJ7:EEXZ:NWKT:ZEFJ:4TST:GEHK:RE2T:INW4:6EYC:A4KK:QHM7 name=app-docker02.x.x.x
DEBU[0000] Start monitoring events                       id=IAHG:EHW4:UEA6:QUPQ:G65M:HG5S:GEC3:GEFD:FP2J:RGSF:PPX5:2TSQ name=app-docker04.x.x.x
DEBU[0000] Start monitoring events                       id=IQRY:XLOJ:OYTB:OZ3G:GGRF:DDMT:LAVX:4SWQ:KF3F:JUIC:TDMN:H4QQ name=app-docker01.x.x.x
DEBU[0000] Start monitoring events                       id=ZT5J:I43Y:IK5Q:7KF5:WJCR:SOET:C3B4:4MUT:54FQ:7X56:ACJA:BCSR name=app-docker03.x.x.x
INFO[0000] Registered Engine app-docker04.x.x.x at a.a.a.68:2375
INFO[0000] Registered Engine app-docker03.x.x.x at a.a.a.67:2375
INFO[0015] Registered Engine app-docker02.x.x.x at a.a.a.66:2375
INFO[0015] Registered Engine app-docker01.x.x.x at a.a.a.65:2375
DEBU[0016] HTTP request received                         method=GET uri=/v1.22/version
DEBU[0016] HTTP request received                         method=GET uri=/v1.22/networks/training1
DEBU[0016] HTTP request received                         method=GET uri=/v1.22/containers/json?all=1&limit=-1&trunc_cmd=0&filters=%7B%22label%22%3A+%5B%22com.docker.compose.project%3Dbergtwvd%22%2C+%22com.docker.compose.service%3Dcrc%22%2C+%22com.docker.compose.oneoff%3DFalse%22%5D%7D&size=0
DEBU[0016] HTTP request received                         method=GET uri=/v1.22/containers/json?all=1&limit=-1&trunc_cmd=0&filters=%7B%22label%22%3A+%5B%22com.docker.compose.project%3Dbergtwvd%22%2C+%22com.docker.compose.service%3Dtrafficsim%22%2C+%22com.docker.compose.oneoff%3DFalse%22%5D%7D&size=0
DEBU[0016] HTTP request received                         method=GET uri=/v1.22/containers/json?all=1&limit=-1&trunc_cmd=0&filters=%7B%22label%22%3A+%5B%22com.docker.compose.project%3Dbergtwvd%22%2C+%22com.docker.compose.service%3Dshipsim%22%2C+%22com.docker.compose.oneoff%3DFalse%22%5D%7D&size=0
DEBU[0016] HTTP request received                         method=GET uri=/v1.22/containers/json?all=1&limit=-1&trunc_cmd=0&filters=%7B%22label%22%3A+%5B%22com.docker.compose.project%3Dbergtwvd%22%2C+%22com.docker.compose.service%3Dge%22%2C+%22com.docker.compose.oneoff%3DFalse%22%5D%7D&size=0
DEBU[0016] HTTP request received                         method=GET uri=/v1.22/containers/json?all=1&limit=-1&trunc_cmd=0&filters=%7B%22label%22%3A+%5B%22com.docker.compose.project%3Dbergtwvd%22%2C+%22com.docker.compose.service%3Dweb%22%2C+%22com.docker.compose.oneoff%3DFalse%22%5D%7D&size=0
DEBU[0017] HTTP request received                         method=GET uri=/v1.22/containers/json?all=1&limit=-1&trunc_cmd=0&filters=%7B%22label%22%3A+%5B%22com.docker.compose.project%3Dbergtwvd%22%2C+%22com.docker.compose.service%3Dcrc%22%2C+%22com.docker.compose.oneoff%3DFalse%22%5D%7D&size=0
DEBU[0017] HTTP request received                         method=GET uri=/v1.22/containers/json?all=1&limit=-1&trunc_cmd=0&filters=%7B%22label%22%3A+%5B%22com.docker.compose.project%3Dbergtwvd%22%2C+%22com.docker.compose.service%3Dtrafficsim%22%2C+%22com.docker.compose.oneoff%3DFalse%22%5D%7D&size=0
DEBU[0017] HTTP request received                         method=GET uri=/v1.22/containers/json?all=1&limit=-1&trunc_cmd=0&filters=%7B%22label%22%3A+%5B%22com.docker.compose.project%3Dbergtwvd%22%2C+%22com.docker.compose.service%3Dshipsim%22%2C+%22com.docker.compose.oneoff%3DFalse%22%5D%7D&size=0
DEBU[0017] HTTP request received                         method=GET uri=/v1.22/containers/json?all=1&limit=-1&trunc_cmd=0&filters=%7B%22label%22%3A+%5B%22com.docker.compose.project%3Dbergtwvd%22%2C+%22com.docker.compose.service%3Dge%22%2C+%22com.docker.compose.oneoff%3DFalse%22%5D%7D&size=0
DEBU[0017] HTTP request received                         method=GET uri=/v1.22/containers/json?all=1&limit=-1&trunc_cmd=0&filters=%7B%22label%22%3A+%5B%22com.docker.compose.project%3Dbergtwvd%22%2C+%22com.docker.compose.service%3Dweb%22%2C+%22com.docker.compose.oneoff%3DFalse%22%5D%7D&size=0
DEBU[0017] HTTP request received                         method=GET uri=/v1.22/images/msaas%2Fpi-crc%3A5.0.1.0L/json
DEBU[0017] Proxy request                                 method=GET url=http://a.a.a.68:2375/v1.22/images/msaas%2Fpi-crc%3A5.0.1.0L/json
DEBU[0017] HTTP request received                         method=GET uri=/v1.22/containers/json?all=1&limit=-1&trunc_cmd=0&filters=%7B%22label%22%3A+%5B%22com.docker.compose.project%3Dbergtwvd%22%2C+%22com.docker.compose.service%3Dcrc%22%2C+%22com.docker.compose.oneoff%3DFalse%22%5D%7D&size=0
DEBU[0017] HTTP request received                         method=GET uri=/v1.22/images/msaas%2Fpi-crc%3A5.0.1.0L/json
DEBU[0017] Proxy request                                 method=GET url=http://a.a.a.68:2375/v1.22/images/msaas%2Fpi-crc%3A5.0.1.0L/json
DEBU[0017] HTTP request received                         method=POST uri=/v1.22/containers/create?name=crc
DEBU[0017] HTTP request received                         method=GET uri=/v1.22/containers/9317bdf71f2aca74d9d64ce7d48c6803a0b38f878a9ac3044761c0ced8e34a0a/json
DEBU[0017] HTTP request received                         method=GET uri=/v1.22/containers/9317bdf71f2aca74d9d64ce7d48c6803a0b38f878a9ac3044761c0ced8e34a0a/json
DEBU[0017] HTTP request received                         method=POST uri=/v1.22/containers/9317bdf71f2aca74d9d64ce7d48c6803a0b38f878a9ac3044761c0ced8e34a0a/attach?stderr=1&logs=0&stream=1&stdout=1
DEBU[0017] Proxy hijack request                          addr=a.a.a.67:2375
DEBU[0038] Engine update succeeded                       id=ZT5J:I43Y:IK5Q:7KF5:WJCR:SOET:C3B4:4MUT:54FQ:7X56:ACJA:BCSR name=app-docker03.x.x.x
DEBU[0044] Engine update succeeded                       id=IAHG:EHW4:UEA6:QUPQ:G65M:HG5S:GEC3:GEFD:FP2J:RGSF:PPX5:2TSQ name=app-docker04.x.x.x
DEBU[0073] Engine update succeeded                       id=OXJJ:ZUJ7:EEXZ:NWKT:ZEFJ:4TST:GEHK:RE2T:INW4:6EYC:A4KK:QHM7 name=app-docker02.x.x.x
DEBU[0085] Engine update succeeded                       id=IQRY:XLOJ:OYTB:OZ3G:GGRF:DDMT:LAVX:4SWQ:KF3F:JUIC:TDMN:H4QQ name=app-docker01.x.x.x
DEBU[0096] Engine update succeeded                       id=ZT5J:I43Y:IK5Q:7KF5:WJCR:SOET:C3B4:4MUT:54FQ:7X56:ACJA:BCSR name=app-docker03.x.x.x
DEBU[0096] Engine update succeeded                       id=IAHG:EHW4:UEA6:QUPQ:G65M:HG5S:GEC3:GEFD:FP2J:RGSF:PPX5:2TSQ name=app-docker04.x.x.x
DEBU[0128] Engine update succeeded                       id=OXJJ:ZUJ7:EEXZ:NWKT:ZEFJ:4TST:GEHK:RE2T:INW4:6EYC:A4KK:QHM7 name=app-docker02.x.x.x
DEBU[0131] Engine update succeeded                       id=IQRY:XLOJ:OYTB:OZ3G:GGRF:DDMT:LAVX:4SWQ:KF3F:JUIC:TDMN:H4QQ name=app-docker01.x.x.x
DEBU[0131] Engine update succeeded                       id=ZT5J:I43Y:IK5Q:7KF5:WJCR:SOET:C3B4:4MUT:54FQ:7X56:ACJA:BCSR name=app-docker03.x.x.x
DEBU[0134] Engine update succeeded                       id=IAHG:EHW4:UEA6:QUPQ:G65M:HG5S:GEC3:GEFD:FP2J:RGSF:PPX5:2TSQ name=app-docker04.x.x.x
DEBU[0169] Engine update succeeded                       id=ZT5J:I43Y:IK5Q:7KF5:WJCR:SOET:C3B4:4MUT:54FQ:7X56:ACJA:BCSR name=app-docker03.x.x.x
DEBU[0172] Engine update succeeded                       id=IAHG:EHW4:UEA6:QUPQ:G65M:HG5S:GEC3:GEFD:FP2J:RGSF:PPX5:2TSQ name=app-docker04.x.x.x
DEBU[0177] Engine update succeeded                       id=IQRY:XLOJ:OYTB:OZ3G:GGRF:DDMT:LAVX:4SWQ:KF3F:JUIC:TDMN:H4QQ name=app-docker01.x.x.x
DEBU[0186] Engine update succeeded                       id=OXJJ:ZUJ7:EEXZ:NWKT:ZEFJ:4TST:GEHK:RE2T:INW4:6EYC:A4KK:QHM7 name=app-docker02.x.x.x
DEBU[0205] Engine update succeeded                       id=IAHG:EHW4:UEA6:QUPQ:G65M:HG5S:GEC3:GEFD:FP2J:RGSF:PPX5:2TSQ name=app-docker04.x.x.x
DEBU[0225] Engine update succeeded                       id=ZT5J:I43Y:IK5Q:7KF5:WJCR:SOET:C3B4:4MUT:54FQ:7X56:ACJA:BCSR name=app-docker03.x.x.x
DEBU[0240] Engine update succeeded                       id=IQRY:XLOJ:OYTB:OZ3G:GGRF:DDMT:LAVX:4SWQ:KF3F:JUIC:TDMN:H4QQ name=app-docker01.x.x.x

[bergtwvd]

I am still stuck on this issue.

In the meantime I have eliminated swarm and am running on a single host. So I just run docker-compose on a single host and nothing else.

A few hints:

• docker-compose (1.6.0) <=> Docker daemon via unix socket : WORKS
• docker-compose (1.6.0) <=> Docker daemon via tcp: always hangs on the attach as shown in earlier logs
• docker-compose (1.4.2) <=> Docker daemon via unix socket : WORKS
• docker-compose (1.4.2) <=> Docker daemon via tcp: WORK

Next, I put a proxy between compose and the Docker daemon to capture the traffic. Attached the verbose output from Docker compose and the output from the proxy.

compose.txt
proxy.txt

From another run I captured the docker daemon output too:

daemon.txt

How does compose exactly connect to the daemon? (protocol, address, and port format)

[dnephin]

From the daemon logs it seems to be responding to the attach request just fine.

The attach call should block and wait for the process in the container to exit.

What happens in the "WORKS" cases?

What happens if you inspect the container state using docker inspect while the atatch call is frozen? does the container say it's still running? Can you get logs from docker logs <container name> ?

[bergtwvd]

In the WORKS cases the containers run fine as expected. I have a similar setup in AWS and never have these problems. Only when I moved to my in-company provided set of VMs these issues popped up.

The hang happens on the very first container that compose tries to start. The container appears created, but not running:

bergtwvd@app-docker01:/etc/default$ docker ps -a
CONTAINER ID        IMAGE                   COMMAND                CREATED             STATUS              PORTS               NAMES
06aa6f3106ab        msaas/pi-crc:5.0.1.0L   "/bin/sh ./start.sh"   4 minutes ago       Created                                 crc
bergtwvd@app-docker01:/etc/default$ docker inspect 06aa6f3106ab
[
    {
        "Id": "06aa6f3106abb965684b22cfa9159e1c31a998c73ab10733da7c18a3f8c7047a",
        "Created": "2016-02-12T23:16:46.623479183Z",
        "Path": "/bin/sh",
        "Args": [
            "./start.sh"
        ],
        "State": {
            "Status": "created",
            "Running": false,
            "Paused": false,
            "Restarting": false,
            "OOMKilled": false,
            "Dead": false,
            "Pid": 0,
            "ExitCode": 0,
            "Error": "",
            "StartedAt": "0001-01-01T00:00:00Z",
            "FinishedAt": "0001-01-01T00:00:00Z"
        },
        "Image": "sha256:efc677ec99da116a4535b7b17ad4550506068b08eb5805f32c15940a673487d1",
        "ResolvConfPath": "",
        "HostnamePath": "",
        "HostsPath": "",
        "LogPath": "",
        "Name": "/crc",
        "RestartCount": 0,
        "Driver": "aufs",
        "MountLabel": "",
        "ProcessLabel": "",
        "AppArmorProfile": "",
        "ExecIDs": null,
        "HostConfig": {
            "Binds": [],
            "ContainerIDFile": "",
            "LogConfig": {
                "Type": "json-file",
                "Config": {}
            },
            "NetworkMode": "default",
            "PortBindings": {
                "8989/tcp": [
                    {
                        "HostIp": "",
                        "HostPort": "8989"
                    }
                ]
            },
            "RestartPolicy": {
                "Name": "",
                "MaximumRetryCount": 0
            },
            "VolumeDriver": "",
            "VolumesFrom": [],
            "CapAdd": null,
            "CapDrop": null,
            "Dns": null,
            "DnsOptions": null,
            "DnsSearch": null,
            "ExtraHosts": null,
            "GroupAdd": null,
            "IpcMode": "",
            "Links": null,
            "OomScoreAdj": 0,
            "PidMode": "",
            "Privileged": false,
            "PublishAllPorts": false,
            "ReadonlyRootfs": false,
            "SecurityOpt": null,
            "UTSMode": "",
            "ShmSize": 67108864,
            "ConsoleSize": [
                0,
                0
            ],
            "Isolation": "",
            "CpuShares": 0,
            "CgroupParent": "",
            "BlkioWeight": 0,
            "BlkioWeightDevice": null,
            "BlkioDeviceReadBps": null,
            "BlkioDeviceWriteBps": null,
            "BlkioDeviceReadIOps": null,
            "BlkioDeviceWriteIOps": null,
            "CpuPeriod": 0,
            "CpuQuota": 0,
            "CpusetCpus": "",
            "CpusetMems": "",
            "Devices": null,
            "KernelMemory": 0,
            "Memory": 0,
            "MemoryReservation": 0,
            "MemorySwap": 0,
            "MemorySwappiness": -1,
            "OomKillDisable": false,
            "PidsLimit": 0,
            "Ulimits": null
        },
        "GraphDriver": {
            "Name": "aufs",
            "Data": null
        },
        "Mounts": [],
        "Config": {
            "Hostname": "06aa6f3106ab",
            "Domainname": "",
            "User": "",
            "AttachStdin": false,
            "AttachStdout": false,
            "AttachStderr": false,
            "ExposedPorts": {
                "8989/tcp": {},
                "9001/tcp": {}
            },
            "Tty": false,
            "OpenStdin": false,
            "StdinOnce": false,
            "Env": [
                "PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin"
            ],
            "Cmd": null,
            "Image": "msaas/pi-crc:5.0.1.0L",
            "Volumes": null,
            "WorkingDir": "/tmp/start",
            "Entrypoint": [
                "/bin/sh",
                "./start.sh"
            ],
            "MacAddress": "00:18:8B:0D:4F:0B",
            "OnBuild": null,
            "Labels": {
                "com.docker.compose.config-hash": "17fc48377f34b062c06e4d1d4b23d9a7df4e154dcfa6187d37520fe827ce2dc7",
                "com.docker.compose.container-number": "1",
                "com.docker.compose.oneoff": "False",
                "com.docker.compose.project": "bergtwvd",
                "com.docker.compose.service": "crc",
                "com.docker.compose.version": "1.6.0"
            }
        },
        "NetworkSettings": {
            "Bridge": "",
            "SandboxID": "",
            "HairpinMode": false,
            "LinkLocalIPv6Address": "",
            "LinkLocalIPv6PrefixLen": 0,
            "Ports": null,
            "SandboxKey": "",
            "SecondaryIPAddresses": null,
            "SecondaryIPv6Addresses": null,
            "EndpointID": "",
            "Gateway": "",
            "GlobalIPv6Address": "",
            "GlobalIPv6PrefixLen": 0,
            "IPAddress": "",
            "IPPrefixLen": 0,
            "IPv6Gateway": "",
            "MacAddress": "",
            "Networks": {
                "bridge": {
                    "IPAMConfig": null,
                    "Links": null,
                    "Aliases": null,
                    "NetworkID": "",
                    "EndpointID": "",
                    "Gateway": "",
                    "IPAddress": "",
                    "IPPrefixLen": 0,
                    "IPv6Gateway": "",
                    "GlobalIPv6Address": "",
                    "GlobalIPv6PrefixLen": 0,
                    "MacAddress": ""
                }
            }
        }
    }
]
bergtwvd@app-docker01:/etc/default$ docker logs 06aa6f3106ab
bergtwvd@app-docker01:/etc/default$

[bergtwvd]

Since I moved from AWS to in-house I also would like to take a closer look at the networking. In AWS I have for all VMs all ports and protocols open for both ingoing and outgoing traffic. I use the same versions of docker engine, compose and swarm.
In the in-house situation there is a proxy/firewall involved. Depending on the addressing traffic may be routed through that. From the proxy.txt output I deduct that docker-compose traffic goes via the proxy. So I would like to understand the addressing used by compose to determine if the firewall/proxy is in someway involved in blocking certain traffic. Do you have info on that? What can I check to exclude this factor?

[bergtwvd]

Other deduction from the logs:
in compose 1.4.2 the sequence is: create, inspect, start, inspect, attach
in compose 1.6.0 the sequence is: ceate, inspect, inspect, attach

So the start container invocation in compose is missing, which is in line with what I see at the docker engine side.

[bergtwvd]

I narrowed down the problem further to https://github.com/docker/compose/blob/master/compose/service.py, execute_convergence_plan.

When I add the "-d" flag to docker-compose up, the whole lot starts and runs correct.
When I do not add the "-d" flag it hangs on the docker attach call.

So the problem is related to the container.attach_log_stream call.
For a socket connection this call works fine, for a tcp connection not, at least in my environment.

As a sanity check I looked up the 1.4.2 and 1.5.0. code. In the 1.4.2 service.py there is no attach_log_stream call in execute_convergence_plan, and in 1.5.0 there is. The change has been added with #2254.

As a test I put a software proxy (http://notes.tweakblogs.net/blog/7955/using-netcat-to-build-a-simple-tcp-proxy-in-linux.html) between Docker client and daemon to monitor message traffic, and fired up a container (docker run -id busybox). I can successfully attach to it from different hosts (using tcp), although I need to enter crtl-C at one of the shells to get stdout flushed and force the Connection Upgrade message. The following message is printed by the proxy when I enter ctrl-C in one of the shells:

 => POST /v1.22/containers/04e7c15a15e328186a6145734d036867210676786027726890b1c95ab7985c2f/attach?stderr=1&stdin=1&stdout=1&stream=1 HTTP/1.1
 => Host: 134.221.44.65:40000
 => User-Agent: Docker-Client/1.10.0 (linux)
 => Content-Length: 0
 => Connection: Upgrade
 => Content-Type: text/plain
 => Upgrade: tcp
 =>
<=  HTTP/1.1 101 UPGRADED
<=  Content-Type: application/vnd.docker.raw-stream
<=  Connection: Upgrade
<=  Upgrade: tcp
<=

Next I reran the test with docker-compose, also using the software proxy. The attach comes through at the docker daemon, but I noticed that the Connection Upgrade is never sent from the client.

The difference with the previous busybox test is however that the container is in the status Created (and not running yet).

For reference the execute_convergence_plan snippet:

    def execute_convergence_plan(self,
                                 plan,
                                 do_build=True,
                                 timeout=DEFAULT_TIMEOUT,
                                 detached=False,
                                 start=True):
        (action, containers) = plan
        should_attach_logs = not detached

        if action == 'create':
            container = self.create_container(do_build=do_build)

            if should_attach_logs:
                container.attach_log_stream()

            if start:
                self.start_container(container)

            return [container]
`

[dnephin]

Thanks for tracking this down!

So to summarize, the fix we put in place in #2254 to attach before start does not work against swarm. That fix was a bit of a hack anyway, we should try to use logs instead of attach. So it's possible that the changes we need to make to logs will resolve this.

I believe this is only an issue when run against swarm. It works correctly for engine. It's probably worth opening an issue on docker/swarm as well, so we can track it on both sides. If this works with engine it may be that it can be fixed in swarm.

[bergtwvd]

Please note that in my analysis it turned out that the issue is not related to swarm (I also changed the title of the issue). I run into exactly the same issue when I use Docker Compose against Docker Engine, using e.g. a single image like busybox.
In my environment I can reproduce the issue consistently, i.e. I cannot use Docker Compose in attached mode.

From: Daniel Nephin [mailto:[email protected]]
Sent: dinsdag 16 februari 2016 19:14
To: docker/compose
Cc: Berg, T.W. (Tom) van den
Subject: Re: [compose] [1.6.0] cannot run against swarm in attached mode (#2857)

Thanks for tracking this down!

So to summarize, the fix we put in place in #2254#2254 to attach before start does not work against swarm. That fix was a bit of a hack anyway, we should try to use logs instead of attach. So it's possible that the changes we need to make to logs will resolve this.

I believe this is only an issue when run against swarm. It works correctly for engine. It's probably worth opening an issue on docker/swarm as well, so we can track it on both sides. If this works with engine it may be that it can be fixed in swarm.

—
Reply to this email directly or view it on GitHubhttps://github.com//issues/2857#issuecomment-184806857.
This message may contain information that is not intended for you. If you are not the addressee or if this message was sent to you by mistake, you are requested to inform the sender and delete the message. TNO accepts no liability for the content of this e-mail, for the manner in which you use it and for damage of any kind resulting from the risks inherent to the electronic transmission of messages.

[dnephin]

Oh, I missed that. That is definitely not the case most of the time (we have many tests, and many users that use attach). There are a couple related issues about this: #812, #2338, #494

We need to figure out what is different about your setup. It sounds like you're running against a VM? Is that created by docker-machine or is it something else?

[bergtwvd]

I do not use docker machine, but follow the instructions for installing Docker Engine on Ubuntu (running in a VM) from the Docker.com website. Docker Compose is installed in the same VM. Thus all is running on a single host.

When I use a Unix socket to connect to Engine it works; when I use a TCP connection it doesn't. Does this effect the Connection Upgrade message in any way?

[dnephin]

Since it only happens with TCP, it sounds very likely that a proxy or firewall is causing this issue.

[bergtwvd]

That is what I thought too, but when I start a container by hand and attach to it later it works fine. Even the attach from other hosts. And with the software proxy in between I also see the Connection Upgrade message passing by.

Question: can you attach to a container that is created, but not started yet? (as Docker Compose appears to do) When I use the docker commandline client I am not permitted to do this.

[dnephin]

That check seems to happen on the client side in docker-cli. I'm not sure why, but we're definitely able to attach to a container that is not started yet. We've been doing that since 1.5.0 as you noted and it seems to work for most users, and our test suite.

[bergtwvd]

I followed up with the network engineer and system admin. Both the proxy and the host firewall do not block or manipulate any traffic on this subnetwork. So this rules out these factors.

[fastzhong]

Hi, I encountered the similar problem, I have 3 VMs and if I remove all the proxy settings (/etc/profile.d/proxy.sh, /etc/environment, /etc/default/docker), it will work. I have to pull all images first before running docker-compose.

[ijc]

Issue grooming: After ~3 years with no further complaints I'm going to take a guess that either this was fixed along the way somehow or it is otherwise no longer relevant. If you can reproduce with modern versions of everything then please do reopen (or open a new issue with the new info).