New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

docker_service may not provide useful errors when tasks fail #20480

Closed
shabble opened this Issue Jan 19, 2017 · 4 comments

Comments

Projects
None yet
6 participants
@shabble

shabble commented Jan 19, 2017

ISSUE TYPE
  • Bug Report
COMPONENT NAME

docker_service

ANSIBLE VERSION
ansible 2.2.0.0
  config file = /Users/shabble/work/mhn-automation/ansible.cfg
  configured module search path = Default w/o overrides

and

ansible 2.3.0 (devel 9d26d8b605) last updated 2017/01/19 20:34:38 (GMT +100)
  config file =
  configured module search path = Default w/o overrides
CONFIGURATION

Nothing interesting

[defaults]
hostfile=hosts
roles_path=roles/
command_warnings=True
nocows=1
OS / ENVIRONMENT

Runner: OSX 10.11.6, python 2.7.12 (via macports)
Target: Debian 8

SUMMARY

When using the docker_service module, certain runtime or configuration errors are masked and not available in any of the ansible return values or logs.
The cause seems to be docker-compose logging (some) error messages directly to stdout or stderr, even when called as a library by docker_service.

This might be related to ansible/ansible-modules-core#5117 and #19371

It is not fully resolved by PR ansible/ansible-modules-core#5165 since that only considers stdout.

STEPS TO REPRODUCE

Minimal testcase below should cause a failure due to the 2 containers both trying to forward the same port, resulting in an error to stderr which isn't returned by ansible.

---
- hosts: all
  tasks:
    - docker_service:
        project_name: foo
        debug: yes
        definition:
          version: '2'
          services:
            testcontainer:
              image: busybox
              ports:
                - "8001:8000"
              command: 'sleep 100'
            testcontainer2:
              image: busybox
              ports:
                - "8001:8000"
              command: 'sleep 100'
EXPECTED RESULTS

A useful error message similar to that produced when running docker-compose up explicitly.

For comparison, running the same testcase using just a docker-compose.yml produces the output:

Creating network "ansbug_default" with the default driver
Creating ansbug_testcontainer_1
Creating ansbug_testcontainer2_1

ERROR: for testcontainer  Cannot start service testcontainer: driver failed programming external connectivity on endpoint ansbug_testcontainer_1 (5ff302538b9881883b36afc21da5c9246dc304f1620c0bee98cca8093bbc0d01): Bind for 0.0.0.0:8001 failed: port is already allocated
ERROR: Encountered errors while bringing up the project.

docker-compose up 2>/dev/null produces no output, indicating the messages are being sent to stderr.

ACTUAL RESULTS

Run with ansible 2.2.0:

$ ansible-playbook -i hosts.dtest dc-errmsg-demo.yml -vvv                             
Using /Users/shabble/work/mhn-automation/ansible.cfg as config file

PLAYBOOK: dc-errmsg-demo.yml ***************************************************
1 plays in dc-errmsg-demo.yml

PLAY [all] *********************************************************************

TASK [setup] *******************************************************************
Using module file /opt/local/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/site-packages/ansible/modules/core/system/setup.py
<ansibledocker.mhn> ESTABLISH SSH CONNECTION FOR USER: shabble
<ansibledocker.mhn> SSH: EXEC ssh -C -o ControlMaster=auto -o ControlPersist=60s -o KbdInteractiveAuthentication=no -o PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey -o PasswordAuthentication=no -o User=shabble -o ConnectTimeout=10 -o ControlPath=/Users/shabble/.ansible/cp/ansible-ssh-%h-%p-%r ansibledocker.mhn '/bin/sh -c '"'"'( umask 77 && mkdir -p "` echo $HOME/.ansible/tmp/ansible-tmp-1484858631.24-77548129045125 `" && echo ansible-tmp-1484858631.24-77548129045125="` echo $HOME/.ansible/tmp/ansible-tmp-1484858631.24-77548129045125 `" ) && sleep 0'"'"''
<ansibledocker.mhn> PUT /var/folders/lr/ph2sd0md7_5_51wtxztmcmm80000gn/T/tmp66feBd TO /home/shabble/.ansible/tmp/ansible-tmp-1484858631.24-77548129045125/setup.py
<ansibledocker.mhn> SSH: EXEC sftp -b - -C -o ControlMaster=auto -o ControlPersist=60s -o KbdInteractiveAuthentication=no -o PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey -o PasswordAuthentication=no -o User=shabble -o ConnectTimeout=10 -o ControlPath=/Users/shabble/.ansible/cp/ansible-ssh-%h-%p-%r '[ansibledocker.mhn]'
<ansibledocker.mhn> ESTABLISH SSH CONNECTION FOR USER: shabble
<ansibledocker.mhn> SSH: EXEC ssh -C -o ControlMaster=auto -o ControlPersist=60s -o KbdInteractiveAuthentication=no -o PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey -o PasswordAuthentication=no -o User=shabble -o ConnectTimeout=10 -o ControlPath=/Users/shabble/.ansible/cp/ansible-ssh-%h-%p-%r ansibledocker.mhn '/bin/sh -c '"'"'chmod u+x /home/shabble/.ansible/tmp/ansible-tmp-1484858631.24-77548129045125/ /home/shabble/.ansible/tmp/ansible-tmp-1484858631.24-77548129045125/setup.py && sleep 0'"'"''
<ansibledocker.mhn> ESTABLISH SSH CONNECTION FOR USER: shabble
<ansibledocker.mhn> SSH: EXEC ssh -C -o ControlMaster=auto -o ControlPersist=60s -o KbdInteractiveAuthentication=no -o PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey -o PasswordAuthentication=no -o User=shabble -o ConnectTimeout=10 -o ControlPath=/Users/shabble/.ansible/cp/ansible-ssh-%h-%p-%r -tt ansibledocker.mhn '/bin/sh -c '"'"'/usr/bin/python /home/shabble/.ansible/tmp/ansible-tmp-1484858631.24-77548129045125/setup.py; rm -rf "/home/shabble/.ansible/tmp/ansible-tmp-1484858631.24-77548129045125/" > /dev/null 2>&1 && sleep 0'"'"''
ok: [ansibledocker.mhn]

TASK [docker_service] **********************************************************
task path: /Users/shabble/work/mhn-automation/dc-errmsg-demo.yml:4
Using module file /opt/local/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/site-packages/ansible/modules/core/cloud/docker/docker_service.py
<ansibledocker.mhn> ESTABLISH SSH CONNECTION FOR USER: shabble
<ansibledocker.mhn> SSH: EXEC ssh -C -o ControlMaster=auto -o ControlPersist=60s -o KbdInteractiveAuthentication=no -o PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey -o PasswordAuthentication=no -o User=shabble -o ConnectTimeout=10 -o ControlPath=/Users/shabble/.ansible/cp/ansible-ssh-%h-%p-%r ansibledocker.mhn '/bin/sh -c '"'"'( umask 77 && mkdir -p "` echo $HOME/.ansible/tmp/ansible-tmp-1484858633.54-69159756081069 `" && echo ansible-tmp-1484858633.54-69159756081069="` echo $HOME/.ansible/tmp/ansible-tmp-1484858633.54-69159756081069 `" ) && sleep 0'"'"''
<ansibledocker.mhn> PUT /var/folders/lr/ph2sd0md7_5_51wtxztmcmm80000gn/T/tmprlIO_I TO /home/shabble/.ansible/tmp/ansible-tmp-1484858633.54-69159756081069/docker_service.py
<ansibledocker.mhn> SSH: EXEC sftp -b - -C -o ControlMaster=auto -o ControlPersist=60s -o KbdInteractiveAuthentication=no -o PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey -o PasswordAuthentication=no -o User=shabble -o ConnectTimeout=10 -o ControlPath=/Users/shabble/.ansible/cp/ansible-ssh-%h-%p-%r '[ansibledocker.mhn]'
<ansibledocker.mhn> ESTABLISH SSH CONNECTION FOR USER: shabble
<ansibledocker.mhn> SSH: EXEC ssh -C -o ControlMaster=auto -o ControlPersist=60s -o KbdInteractiveAuthentication=no -o PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey -o PasswordAuthentication=no -o User=shabble -o ConnectTimeout=10 -o ControlPath=/Users/shabble/.ansible/cp/ansible-ssh-%h-%p-%r ansibledocker.mhn '/bin/sh -c '"'"'chmod u+x /home/shabble/.ansible/tmp/ansible-tmp-1484858633.54-69159756081069/ /home/shabble/.ansible/tmp/ansible-tmp-1484858633.54-69159756081069/docker_service.py && sleep 0'"'"''
<ansibledocker.mhn> ESTABLISH SSH CONNECTION FOR USER: shabble
<ansibledocker.mhn> SSH: EXEC ssh -C -o ControlMaster=auto -o ControlPersist=60s -o KbdInteractiveAuthentication=no -o PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey -o PasswordAuthentication=no -o User=shabble -o ConnectTimeout=10 -o ControlPath=/Users/shabble/.ansible/cp/ansible-ssh-%h-%p-%r -tt ansibledocker.mhn '/bin/sh -c '"'"'/usr/bin/python /home/shabble/.ansible/tmp/ansible-tmp-1484858633.54-69159756081069/docker_service.py; rm -rf "/home/shabble/.ansible/tmp/ansible-tmp-1484858633.54-69159756081069/" > /dev/null 2>&1 && sleep 0'"'"''
fatal: [ansibledocker.mhn]: FAILED! => {
    "changed": false,
    "failed": true,
    "invocation": {
        "module_args": {
            "api_version": null,
            "build": false,
            "cacert_path": null,
            "cert_path": null,
            "debug": true,
            "definition": {
                "services": {
                    "testcontainer": {
                        "command": "sleep 100",
                        "image": "busybox",
                        "ports": [
                            "8001:8000"
                        ]
                    },
                    "testcontainer2": {
                        "command": "sleep 100",
                        "image": "busybox",
                        "ports": [
                            "8001:8000"
                        ]
                    }
                },
                "version": "2"
            },
            "dependencies": true,
            "docker_host": null,
            "files": null,
            "filter_logger": false,
            "hostname_check": false,
            "key_path": null,
            "nocache": false,
            "project_name": "foo",
            "project_src": null,
            "pull": false,
            "recreate": "smart",
            "remove_images": null,
            "remove_orphans": false,
            "remove_volumes": false,
            "restarted": false,
            "scale": null,
            "services": null,
            "ssl_version": null,
            "state": "present",
            "stopped": false,
            "timeout": 10,
            "tls": null,
            "tls_hostname": null,
            "tls_verify": null
        },
        "module_name": "docker_service"
    },
    "msg": "Error starting project - "
}
	to retry, use: --limit @/Users/shabble/work/mhn-automation/dc-errmsg-demo.retry

PLAY RECAP *********************************************************************
ansibledocker.mhn          : ok=1    changed=0    unreachable=0    failed=1

Relevant part here is: "msg": "Error starting project - "

Run with current git HEAD:

[... equivalent setup spam snipped...]
fatal: [ansibledocker.mhn]: FAILED! => {
    "changed": false,
    "failed": true,
    "invocation": {
        "module_args": {
            "api_version": null,
            "build": false,
            "cacert_path": null,
            "cert_path": null,
            "debug": true,
            "definition": {
                "services": {
                    "testcontainer": {
                        "command": "sleep 100",
                        "image": "busybox",
                        "ports": [
                            "8001:8000"
                        ]
                    },
                    "testcontainer2": {
                        "command": "sleep 100",
                        "image": "busybox",
                        "ports": [
                            "8001:8000"
                        ]
                    }
                },
                "version": "2"
            },
            "dependencies": true,
            "docker_host": null,
            "files": null,
            "filter_logger": false,
            "hostname_check": false,
            "key_path": null,
            "nocache": false,
            "project_name": "foo",
            "project_src": null,
            "pull": false,
            "recreate": "smart",
            "remove_images": null,
            "remove_orphans": false,
            "remove_volumes": false,
            "restarted": false,
            "scale": null,
            "services": null,
            "ssl_version": null,
            "state": "present",
            "stopped": false,
            "timeout": 10,
            "tls": null,
            "tls_hostname": null,
            "tls_verify": null
        },
        "module_name": "docker_service"
    },
    "module_stderr": "",
    "module_stdout": "",
    "msg": "Error starting project "
}
@shabble

This comment has been minimized.

Show comment
Hide comment
@shabble

shabble Jan 19, 2017

Note that I have a WIP fix at shabble/ansible/bug/docker_service_stderr3 that might be PR'able if there is interest.

shabble commented Jan 19, 2017

Note that I have a WIP fix at shabble/ansible/bug/docker_service_stderr3 that might be PR'able if there is interest.

@chouseknecht

This comment has been minimized.

Show comment
Hide comment
@chouseknecht

chouseknecht Jan 20, 2017

Member

@shabble, I haven't tested your code, but it looks good to me. I would submit it as a PR.

Member

chouseknecht commented Jan 20, 2017

@shabble, I haven't tested your code, but it looks good to me. I would submit it as a PR.

@briceburg

This comment has been minimized.

Show comment
Hide comment
@briceburg

briceburg May 16, 2017

Contributor

I'm using the DEBUG stdout callback, ansible 2.3.0, and get:

TASK [start docker composition] *******************************************************************************************************************************
fatal: [127.0.0.1]: FAILED! => {
    "changed": false, 
    "failed": true, 
    "module_stderr": "Successfully tagged tidqa1_nginx:latest", 
    "module_stdout": "Step 1/3 : FROM registry.badevops.com/mage-term:m1\n ---> 5e192c16437b\nStep 2/3 : COPY repo.key /home/blueacorn/.ssh/id_rsa\n ---> Using cache\n ---> cd5afdc8cff0\nStep 3/3 : RUN sudo chown blueacorn /home/blueacorn/.ssh/id_rsa &&     chmod 0600 /home/blueacorn/.ssh/id_rsa\n ---> Using cache\n ---> 966744c714b4\nSuccessfully built 966744c714b4\nSuccessfully tagged tidqa1_term:latest\nStep 1/2 : FROM registry.badevops.com/mage-nginx:m1\n ---> d8939faf8f3f\nStep 2/2 : COPY magento-hostmap.conf /etc/nginx/conf.d/magento-hostmap.conf\n ---> Successfully tagged tidqa1_nginx:latest"
}

the actual error had to do with a name collision (a container with same name was running on host) -- and nowhere is it shown in output. Moreso the stderr line was confusing.

Ansible playbook task:

- name: start docker composition
      docker_service:
        debug: yes
        project_src: "{{ DOCKER_WORKDIR }}"
        project_name: "{{ PLANET_ID }}-{{ MOON_NAME }}"
        build: yes
        pull: yes
        state: present

        # host connectivity
        docker_host: "{{ docker_engine_host }}"
        cacert_path: "{{ docker_engine_tlscacert }}"
        cert_path: "{{ docker_engine_tlscert }}"
        key_path: "{{ docker_engine_tlskey }}"
        tls: yes
      run_once: yes
Contributor

briceburg commented May 16, 2017

I'm using the DEBUG stdout callback, ansible 2.3.0, and get:

TASK [start docker composition] *******************************************************************************************************************************
fatal: [127.0.0.1]: FAILED! => {
    "changed": false, 
    "failed": true, 
    "module_stderr": "Successfully tagged tidqa1_nginx:latest", 
    "module_stdout": "Step 1/3 : FROM registry.badevops.com/mage-term:m1\n ---> 5e192c16437b\nStep 2/3 : COPY repo.key /home/blueacorn/.ssh/id_rsa\n ---> Using cache\n ---> cd5afdc8cff0\nStep 3/3 : RUN sudo chown blueacorn /home/blueacorn/.ssh/id_rsa &&     chmod 0600 /home/blueacorn/.ssh/id_rsa\n ---> Using cache\n ---> 966744c714b4\nSuccessfully built 966744c714b4\nSuccessfully tagged tidqa1_term:latest\nStep 1/2 : FROM registry.badevops.com/mage-nginx:m1\n ---> d8939faf8f3f\nStep 2/2 : COPY magento-hostmap.conf /etc/nginx/conf.d/magento-hostmap.conf\n ---> Successfully tagged tidqa1_nginx:latest"
}

the actual error had to do with a name collision (a container with same name was running on host) -- and nowhere is it shown in output. Moreso the stderr line was confusing.

Ansible playbook task:

- name: start docker composition
      docker_service:
        debug: yes
        project_src: "{{ DOCKER_WORKDIR }}"
        project_name: "{{ PLANET_ID }}-{{ MOON_NAME }}"
        build: yes
        pull: yes
        state: present

        # host connectivity
        docker_host: "{{ docker_engine_host }}"
        cacert_path: "{{ docker_engine_tlscacert }}"
        cert_path: "{{ docker_engine_tlscert }}"
        key_path: "{{ docker_engine_tlskey }}"
        tls: yes
      run_once: yes
@Yajo

This comment has been minimized.

Show comment
Hide comment
@Yajo

Yajo May 23, 2017

This is really a problem, for any other ansible task, just -v gives you enough information to fix it on failures (usually), but with docker_service I almost always need -vvv (which is not very comfortable).

Yajo commented May 23, 2017

This is really a problem, for any other ansible task, just -v gives you enough information to fix it on failures (usually), but with docker_service I almost always need -vvv (which is not very comfortable).

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment