Skip to content
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

Timing out starting container #222

Open
smacz42 opened this issue Oct 8, 2021 · 10 comments
Open

Timing out starting container #222

smacz42 opened this issue Oct 8, 2021 · 10 comments
Labels
docker-compose-v1 Docker Compose v1

Comments

@smacz42
Copy link

smacz42 commented Oct 8, 2021

Continued from the following issues:

This is happening again with https://hub.docker.com/r/bitnami/suitecrm.

Oct 08 19:36:32 oc1733c-ourcompose-com--2021-10-08-15-28 dd3cd847d0a4[2883]: suitecrm 19:36:32.14                                                                                                                                             
Oct 08 19:36:32 oc1733c-ourcompose-com--2021-10-08-15-28 dd3cd847d0a4[2883]: suitecrm 19:36:32.15 Welcome to the Bitnami suitecrm container                                                                                                   
Oct 08 19:36:32 oc1733c-ourcompose-com--2021-10-08-15-28 dd3cd847d0a4[2883]: suitecrm 19:36:32.15 Subscribe to project updates by watching https://github.com/bitnami/bitnami-docker-suitecrm                                                 
Oct 08 19:36:32 oc1733c-ourcompose-com--2021-10-08-15-28 dd3cd847d0a4[2883]: suitecrm 19:36:32.16 Submit issues and feature requests at https://github.com/bitnami/bitnami-docker-suitecrm/issues                                             
Oct 08 19:36:32 oc1733c-ourcompose-com--2021-10-08-15-28 dd3cd847d0a4[2883]: suitecrm 19:36:32.17                                                                                                                                             
Oct 08 19:36:32 oc1733c-ourcompose-com--2021-10-08-15-28 dd3cd847d0a4[2883]: suitecrm 19:36:32.18 INFO  ==> ** Starting SuiteCRM setup **                                                                                                     
Oct 08 19:36:32 oc1733c-ourcompose-com--2021-10-08-15-28 dd3cd847d0a4[2883]: suitecrm 19:36:32.34 INFO  ==> Configuring PHP options                                                                                                           
Oct 08 19:36:32 oc1733c-ourcompose-com--2021-10-08-15-28 dd3cd847d0a4[2883]: suitecrm 19:36:32.39 INFO  ==> Validating settings in MYSQL_CLIENT_* env vars                                                                                    
Oct 08 19:36:32 oc1733c-ourcompose-com--2021-10-08-15-28 dd3cd847d0a4[2883]: suitecrm 19:36:32.65 INFO  ==> Ensuring SuiteCRM directories exist                                                                                               
Oct 08 19:36:32 oc1733c-ourcompose-com--2021-10-08-15-28 dd3cd847d0a4[2883]: suitecrm 19:36:32.69 INFO  ==> Trying to connect to the database server                                                                                          
Oct 08 19:36:32 oc1733c-ourcompose-com--2021-10-08-15-28 dd3cd847d0a4[2883]: suitecrm 19:36:32.75 INFO  ==> Starting apache in background           
Oct 08 19:36:32 oc1733c-ourcompose-com--2021-10-08-15-28 dd3cd847d0a4[2883]: [Fri Oct 08 19:36:32.988625 2021] [ssl:warn] [pid 80] AH01909: www.example.com:8443:0 server certificate does NOT include an ID which matches the server name
Oct 08 19:36:32 oc1733c-ourcompose-com--2021-10-08-15-28 dd3cd847d0a4[2883]: [Fri Oct 08 19:36:32.989415 2021] [ssl:warn] [pid 80] AH01909: www.example.com:8443:0 server certificate does NOT include an ID which matches the server name
Oct 08 19:36:33 oc1733c-ourcompose-com--2021-10-08-15-28 systemd-networkd[10240]: vethd9ff2cc: Gained IPv6LL                                                                                                                                  
Oct 08 19:36:33 oc1733c-ourcompose-com--2021-10-08-15-28 systemd-timesyncd[10257]: Network configuration changed, trying to establish connection.                  
Oct 08 19:36:33 oc1733c-ourcompose-com--2021-10-08-15-28 systemd-timesyncd[10257]: Synchronized to time server 91.189.94.4:123 (ntp.ubuntu.com).                                                                                              
Oct 08 19:36:34 oc1733c-ourcompose-com--2021-10-08-15-28 systemd-timesyncd[10257]: Network configuration changed, trying to establish connection.                                                                                             
Oct 08 19:36:34 oc1733c-ourcompose-com--2021-10-08-15-28 systemd-timesyncd[10257]: Synchronized to time server 91.189.94.4:123 (ntp.ubuntu.com).                                                                                              
Oct 08 19:36:38 oc1733c-ourcompose-com--2021-10-08-15-28 dd3cd847d0a4[2883]: suitecrm 19:36:38.12 INFO  ==> apache started                                                                                                                    
Oct 08 19:36:38 oc1733c-ourcompose-com--2021-10-08-15-28 dd3cd847d0a4[2883]: suitecrm 19:36:38.12 INFO  ==> Running setup wizard                                       
Oct 08 19:36:42 oc1733c-ourcompose-com--2021-10-08-15-28 dockerd[2883]: time="2021-10-08T19:36:42.264393979Z" level=info msg="Container dd3cd847d0a49d5ec550ec74dfe518d17d9071fd041a94cb3cfce9a15e73e99a failed to exit within 10 seconds of s
ignal 15 - using the force"                                                                                                                                                                                                                   
Oct 08 19:36:42 oc1733c-ourcompose-com--2021-10-08-15-28 47dcf723a3d4[2883]: 2021-10-08 19:36:42 1152 [Warning] Aborted connection 1152 to db: 'suitecrm' user: 'suitecrm' host: '172.19.0.3' (Got an error reading communication packets)    
Oct 08 19:36:42 oc1733c-ourcompose-com--2021-10-08-15-28 47dcf723a3d4[2883]: 2021-10-08 19:36:42 1151 [Warning] Aborted connection 1151 to db: 'unconnected' user: 'suitecrm' host: '172.19.0.3' (Got an error reading communication packets)

Specifically the line here:

Oct 08 19:36:42 oc1733c-ourcompose-com--2021-10-08-15-28 dockerd[2883]: time="2021-10-08T19:36:42.264393979Z" level=info msg="Container dd3cd847d0a49d5ec550ec74dfe518d17d9071fd041a94cb3cfce9a15e73e99a failed to exit within 10 seconds of s
ignal 15 - using the force"                                                                                                                                                                                                                   

I can't find where the actual run command is from here: https://github.com/ansible-collections/community.docker/blob/main/plugins/modules/docker_compose.py#L832

Where is this up() function? Probably here: https://github.com/docker/compose/blob/5becea4ca9f68875334c92f191a13482bcd6e5cf/compose/cli/command.py#L36-L71, or, at least, that is the self.project that is referenced in the above. But there doesn't seem to be an up() function associated?

I'm ultimately trying to figure out how that timeout works, since it is NOT a docker-compose native function.

EDIT: TL;DR

Why is dockerd terminating my container prematurely?


Also, I would have thought that the timeout as described here, why is this getting applied to a starting container? Wouldn't a timeout only be relevant for a stopping container?

@smacz42
Copy link
Author

smacz42 commented Oct 8, 2021

Unable to reproduce with plain docker-compose.yml file:

version: '3.6'
services:
  suitecrm:
    image: "bitnami/suitecrm:7-debian-10"
    container_name: suitecrm
    restart: always
    networks:
      - frontend
      - backend
    environment:
      SUITECRM_HOST: 'oc1733c.ourcompose.com'
      SUITECRM_DATABASE_HOST: "database"
      SUITECRM_DATABASE_NAME: 'suitecrm'
      SUITECRM_DATABASE_USER: 'suitecrm'
      SUITECRM_DATABASE_PASSWORD: "ELuyJrgdQ7TcSIk5"
      SUITECRM_SERVER_URL: "https://oc1733c.ourcompose.com/suitecrm"
      SUITECRM_USERNAME: 'admin'
      SUITECRM_PASSWORD: "testpassword"
networks:
  frontend:
    external: true
  backend:
    external: true

CLI Output:

root@oc1733c-ourcompose-com--2021-10-08-15-28:~/docker# docker-compose up -t 10
Pulling suitecrm (bitnami/suitecrm:7-debian-10)...
7-debian-10: Pulling from bitnami/suitecrm
d8cf0c803abf: Pull complete
6421417eb4f9: Pull complete
efa92c3f126c: Pull complete
1e8cf573a40f: Pull complete
980e4fd24551: Pull complete
eac77f15e1af: Pull complete
ee8820329b65: Pull complete
9869037cdb65: Pull complete
18dc968f3f7a: Pull complete
c3a9a9c6d3b1: Pull complete
473230508106: Pull complete
0b115c71f8e2: Pull complete
1c264c186d19: Pull complete
b4ec02647221: Pull complete
699a748c5251: Pull complete
6a8d932d7263: Pull complete
17136ff96ce1: Pull complete
730037cf6b6f: Pull complete
Digest: sha256:38c2f6acc81b4b5830f9d056d103fee7a30e1787b00ae5f685a1f971283b97e5
Status: Downloaded newer image for bitnami/suitecrm:7-debian-10
Creating suitecrm ... done
Attaching to suitecrm
suitecrm    | suitecrm 22:11:50.77 
suitecrm    | suitecrm 22:11:50.77 Welcome to the Bitnami suitecrm container
suitecrm    | suitecrm 22:11:50.77 Subscribe to project updates by watching https://github.com/bitnami/bitnami-docker-suitecrm
suitecrm    | suitecrm 22:11:50.77 Submit issues and feature requests at https://github.com/bitnami/bitnami-docker-suitecrm/issues
suitecrm    | suitecrm 22:11:50.78 
suitecrm    | suitecrm 22:11:50.78 INFO  ==> ** Starting SuiteCRM setup **
suitecrm    | suitecrm 22:11:50.94 INFO  ==> Configuring PHP options
suitecrm    | suitecrm 22:11:50.98 INFO  ==> Validating settings in MYSQL_CLIENT_* env vars
suitecrm    | suitecrm 22:11:51.25 INFO  ==> Ensuring SuiteCRM directories exist
suitecrm    | suitecrm 22:11:51.30 INFO  ==> Trying to connect to the database server
suitecrm    | suitecrm 22:11:51.40 INFO  ==> Starting apache in background
suitecrm    | [Fri Oct 08 22:11:51.720549 2021] [ssl:warn] [pid 81] AH01909: www.example.com:8443:0 server certificate does NOT include an ID which matches the server name
suitecrm    | [Fri Oct 08 22:11:51.721104 2021] [ssl:warn] [pid 81] AH01909: www.example.com:8443:0 server certificate does NOT include an ID which matches the server name
suitecrm    | suitecrm 22:11:56.85 INFO  ==> apache started
suitecrm    | suitecrm 22:11:56.86 INFO  ==> Running setup wizard
suitecrm    | suitecrm 22:12:08.68 INFO  ==> Stopping apache
suitecrm    | suitecrm 22:12:09.77 INFO  ==> apache stopped
suitecrm    | suitecrm 22:12:09.79 INFO  ==> Persisting SuiteCRM installation
suitecrm    | suitecrm 22:12:24.52 INFO  ==> ** SuiteCRM setup finished! **
suitecrm    | 
suitecrm    | suitecrm 22:12:24.54 INFO  ==> ** Starting cron **
suitecrm    | suitecrm 22:12:24.58 INFO  ==> ** Starting Apache **
suitecrm    | [Fri Oct 08 22:12:24.835047 2021] [ssl:warn] [pid 1] AH01909: www.example.com:8443:0 server certificate does NOT include an ID which matches the server name
suitecrm    | [Fri Oct 08 22:12:24.837170 2021] [ssl:warn] [pid 1] AH01909: www.example.com:8443:0 server certificate does NOT include an ID which matches the server name
suitecrm    | [Fri Oct 08 22:12:24.895908 2021] [ssl:warn] [pid 1] AH01909: www.example.com:8443:0 server certificate does NOT include an ID which matches the server name
suitecrm    | [Fri Oct 08 22:12:24.898236 2021] [ssl:warn] [pid 1] AH01909: www.example.com:8443:0 server certificate does NOT include an ID which matches the server name
suitecrm    | [Fri Oct 08 22:12:24.965889 2021] [mpm_prefork:notice] [pid 1] AH00163: Apache/2.4.51 (Unix) OpenSSL/1.1.1d PHP/7.4.24 configured -- resuming normal operations
suitecrm    | [Fri Oct 08 22:12:24.980386 2021] [core:notice] [pid 1] AH00094: Command line: '/opt/bitnami/apache/bin/httpd -f /opt/bitnami/apache/conf/httpd.conf -D FOREGROUND'
^CGracefully stopping... (press Ctrl+C again to force)
Stopping suitecrm ... done

Ansible playbook:

- hosts: all
  vars:
    ansible_python_interpreter: "/usr/local/bin/python3-docker"
  tasks:
    - name: (suitecrm) The latest suitecrm service is built
      docker_compose:
        project_name: suitecrm_test
        definition:
          version: '3.6'
          services:
            suitecrm_test:
              image: "bitnami/suitecrm:7-debian-10"
              container_name: suitecrm_test
              networks:
                - backend
              environment:
                SUITECRM_HOST: 'oc1733.ourcompose.com'
                SUITECRM_DATABASE_HOST: "database"
                SUITECRM_DATABASE_NAME: 'suitecrm'
                SUITECRM_DATABASE_USER: 'suitecrm'
                SUITECRM_DATABASE_PASSWORD: "ELuyJrgdQ7TcSIk5"
                SUITECRM_SERVER_URL: "https://oc1733.ourcompose.com/suitecrm"
                SUITECRM_USERNAME: 'admin'
                SUITECRM_PASSWORD: 'testpassword'
          networks:
            backend:
              external: true
        pull: yes
        state: present
        restarted: yes

Systemd Journal output:

Oct 08 22:14:55 oc1733c-ourcompose-com--2021-10-08-15-28 python3[17950]: ansible-docker_compose Invoked with project_name=suitecrm_test definition={'version': '3.6', 'services': {'suitecrm_test': {'image': 'bitnami/suitecrm:7-debian-10', 
'container_name': 'suitecrm_test', 'networks': ['backend'], 'environment': {'SUITECRM_HOST': 'oc1733.ourcompose.com', 'SUITECRM_DATABASE_HOST': 'database', 'SUITECRM_DATABASE_NAME': 'suitecrm', 'SUITECRM_DATABASE_USER': 'suitecrm', 'SUITE
CRM_DATABASE_PASSWORD': 'ELuyJrgdQ7TcSIk5', 'SUITECRM_SERVER_URL': 'https://oc1733.ourcompose.com/suitecrm', 'SUITECRM_USERNAME': 'admin', 'SUITECRM_PASSWORD': 'testpassword'}}}, 'networks': {'backend': {'external': True}}} pull=True stat
e=present restarted=True docker_host=unix://var/run/docker.sock tls_hostname=localhost api_version=auto timeout=10 tls=False validate_certs=False debug=False hostname_check=False recreate=smart build=False remove_volumes=False remove_orph
ans=False stopped=False dependencies=True nocache=False ca_cert=None client_cert=None client_key=None ssl_version=None project_src=None files=None remove_images=None scale=None services=None
Oct 08 22:14:56 oc1733c-ourcompose-com--2021-10-08-15-28 systemd-udevd[17992]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable.                                                                       
Oct 08 22:14:56 oc1733c-ourcompose-com--2021-10-08-15-28 kernel: br-3d8042b52274: port 2(veth9d8eaf2) entered blocking state                                                                                                                  
Oct 08 22:14:56 oc1733c-ourcompose-com--2021-10-08-15-28 kernel: br-3d8042b52274: port 2(veth9d8eaf2) entered disabled state                        
Oct 08 22:14:56 oc1733c-ourcompose-com--2021-10-08-15-28 kernel: device veth9d8eaf2 entered promiscuous mode                                                                                                                                  
Oct 08 22:14:56 oc1733c-ourcompose-com--2021-10-08-15-28 systemd-udevd[17992]: Could not generate persistent MAC address for veth9d8eaf2: No such file or directory                                                                       
Oct 08 22:14:56 oc1733c-ourcompose-com--2021-10-08-15-28 systemd-networkd[11562]: veth9d8eaf2: Link UP                                                                                                                                        
Oct 08 22:14:56 oc1733c-ourcompose-com--2021-10-08-15-28 networkd-dispatcher[816]: WARNING:Unknown index 20 seen, reloading interface list                                                                                                    
Oct 08 22:14:56 oc1733c-ourcompose-com--2021-10-08-15-28 systemd-timesyncd[11583]: Network configuration changed, trying to establish connection.                      
Oct 08 22:14:56 oc1733c-ourcompose-com--2021-10-08-15-28 kernel: IPv6: ADDRCONF(NETDEV_UP): veth9d8eaf2: link is not ready                        
Oct 08 22:14:56 oc1733c-ourcompose-com--2021-10-08-15-28 systemd-udevd[17990]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable.
Oct 08 22:14:56 oc1733c-ourcompose-com--2021-10-08-15-28 systemd-udevd[17990]: Could not generate persistent MAC address for vetha344694: No such file or directory                                                                           
Oct 08 22:14:56 oc1733c-ourcompose-com--2021-10-08-15-28 dockerd[4271]: time="2021-10-08T22:14:56.167087469Z" level=info msg="No non-localhost DNS nameservers are left in resolv.conf. Using default external servers: [nameserver 8.8.8.8 na
meserver 8.8.4.4]"                                                                                                                                                                                                                            
Oct 08 22:14:56 oc1733c-ourcompose-com--2021-10-08-15-28 dockerd[4271]: time="2021-10-08T22:14:56.167587302Z" level=info msg="IPv6 enabled; Adding default IPv6 external servers: [nameserver 2001:4860:4860::8888 nameserver 2001:4860:4860::
8844]"                                                                                                                                                                                                                                        
Oct 08 22:14:56 oc1733c-ourcompose-com--2021-10-08-15-28 containerd[1450]: time="2021-10-08T22:14:56.223810837Z" level=info msg="starting signal loop" namespace=moby path=/run/containerd/io.containerd.runtime.v2.task/moby/76fd57552e5d22bf
2dd03984ad02aa36ce4545f982390cc13a1c6d3df4cd68d7 pid=18011
Oct 08 22:14:56 oc1733c-ourcompose-com--2021-10-08-15-28 systemd-timesyncd[11583]: Synchronized to time server 91.189.89.198:123 (ntp.ubuntu.com).
Oct 08 22:14:56 oc1733c-ourcompose-com--2021-10-08-15-28 systemd-networkd[11562]: veth9d8eaf2: Gained carrier
Oct 08 22:14:56 oc1733c-ourcompose-com--2021-10-08-15-28 kernel: eth0: renamed from vetha344694
Oct 08 22:14:56 oc1733c-ourcompose-com--2021-10-08-15-28 kernel: IPv6: ADDRCONF(NETDEV_CHANGE): veth9d8eaf2: link becomes ready
Oct 08 22:14:56 oc1733c-ourcompose-com--2021-10-08-15-28 kernel: br-3d8042b52274: port 2(veth9d8eaf2) entered blocking state
Oct 08 22:14:56 oc1733c-ourcompose-com--2021-10-08-15-28 kernel: br-3d8042b52274: port 2(veth9d8eaf2) entered forwarding state
Oct 08 22:14:56 oc1733c-ourcompose-com--2021-10-08-15-28 systemd-timesyncd[11583]: Network configuration changed, trying to establish connection.
Oct 08 22:14:57 oc1733c-ourcompose-com--2021-10-08-15-28 systemd-timesyncd[11583]: Synchronized to time server 91.189.89.198:123 (ntp.ubuntu.com).
Oct 08 22:14:57 oc1733c-ourcompose-com--2021-10-08-15-28 76fd57552e5d[4271]: suitecrm 22:14:57.11 
Oct 08 22:14:57 oc1733c-ourcompose-com--2021-10-08-15-28 76fd57552e5d[4271]: suitecrm 22:14:57.12 Welcome to the Bitnami suitecrm container
Oct 08 22:14:57 oc1733c-ourcompose-com--2021-10-08-15-28 76fd57552e5d[4271]: suitecrm 22:14:57.13 Subscribe to project updates by watching https://github.com/bitnami/bitnami-docker-suitecrm
Oct 08 22:14:57 oc1733c-ourcompose-com--2021-10-08-15-28 76fd57552e5d[4271]: suitecrm 22:14:57.13 Submit issues and feature requests at https://github.com/bitnami/bitnami-docker-suitecrm/issues
Oct 08 22:14:57 oc1733c-ourcompose-com--2021-10-08-15-28 76fd57552e5d[4271]: suitecrm 22:14:57.13 
Oct 08 22:14:57 oc1733c-ourcompose-com--2021-10-08-15-28 76fd57552e5d[4271]: suitecrm 22:14:57.14 INFO  ==> ** Starting SuiteCRM setup **
Oct 08 22:14:57 oc1733c-ourcompose-com--2021-10-08-15-28 76fd57552e5d[4271]: suitecrm 22:14:57.30 INFO  ==> Configuring PHP options
Oct 08 22:14:57 oc1733c-ourcompose-com--2021-10-08-15-28 76fd57552e5d[4271]: suitecrm 22:14:57.35 INFO  ==> Validating settings in MYSQL_CLIENT_* env vars
Oct 08 22:14:57 oc1733c-ourcompose-com--2021-10-08-15-28 76fd57552e5d[4271]: suitecrm 22:14:57.59 INFO  ==> Ensuring SuiteCRM directories exist
Oct 08 22:14:57 oc1733c-ourcompose-com--2021-10-08-15-28 76fd57552e5d[4271]: suitecrm 22:14:57.62 INFO  ==> Trying to connect to the database server
Oct 08 22:14:57 oc1733c-ourcompose-com--2021-10-08-15-28 76fd57552e5d[4271]: suitecrm 22:14:57.70 INFO  ==> Starting apache in background
Oct 08 22:14:57 oc1733c-ourcompose-com--2021-10-08-15-28 76fd57552e5d[4271]: [Fri Oct 08 22:14:57.986404 2021] [ssl:warn] [pid 80] AH01909: www.example.com:8443:0 server certificate does NOT include an ID which matches the server name
Oct 08 22:14:57 oc1733c-ourcompose-com--2021-10-08-15-28 76fd57552e5d[4271]: [Fri Oct 08 22:14:57.988110 2021] [ssl:warn] [pid 80] AH01909: www.example.com:8443:0 server certificate does NOT include an ID which matches the server name
Oct 08 22:14:58 oc1733c-ourcompose-com--2021-10-08-15-28 systemd-networkd[11562]: veth9d8eaf2: Gained IPv6LL
Oct 08 22:14:58 oc1733c-ourcompose-com--2021-10-08-15-28 systemd-timesyncd[11583]: Network configuration changed, trying to establish connection.
Oct 08 22:14:58 oc1733c-ourcompose-com--2021-10-08-15-28 systemd-timesyncd[11583]: Synchronized to time server 91.189.89.198:123 (ntp.ubuntu.com).
Oct 08 22:14:59 oc1733c-ourcompose-com--2021-10-08-15-28 systemd-timesyncd[11583]: Network configuration changed, trying to establish connection.
Oct 08 22:14:59 oc1733c-ourcompose-com--2021-10-08-15-28 systemd-timesyncd[11583]: Synchronized to time server 91.189.89.198:123 (ntp.ubuntu.com).
Oct 08 22:15:03 oc1733c-ourcompose-com--2021-10-08-15-28 76fd57552e5d[4271]: suitecrm 22:15:03.17 INFO  ==> apache started
Oct 08 22:15:03 oc1733c-ourcompose-com--2021-10-08-15-28 76fd57552e5d[4271]: suitecrm 22:15:03.18 INFO  ==> Running setup wizard
Oct 08 22:15:07 oc1733c-ourcompose-com--2021-10-08-15-28 dockerd[4271]: time="2021-10-08T22:15:07.219870336Z" level=info msg="Container 76fd57552e5d22bf2dd03984ad02aa36ce4545f982390cc13a1c6d3df4cd68d7 failed to exit within 10 seconds of s
ignal 15 - using the force"
Oct 08 22:15:07 oc1733c-ourcompose-com--2021-10-08-15-28 containerd[1450]: time="2021-10-08T22:15:07.363425815Z" level=info msg="shim disconnected" id=76fd57552e5d22bf2dd03984ad02aa36ce4545f982390cc13a1c6d3df4cd68d7
Oct 08 22:15:07 oc1733c-ourcompose-com--2021-10-08-15-28 containerd[1450]: time="2021-10-08T22:15:07.365428351Z" level=error msg="copy shim log" error="read /proc/self/fd/20: file already closed"
Oct 08 22:15:07 oc1733c-ourcompose-com--2021-10-08-15-28 dockerd[4271]: time="2021-10-08T22:15:07.378575247Z" level=info msg="ignoring event" container=76fd57552e5d22bf2dd03984ad02aa36ce4545f982390cc13a1c6d3df4cd68d7 module=libcontainerd 
namespace=moby topic=/tasks/delete type="*events.TaskDelete"
Oct 08 22:15:07 oc1733c-ourcompose-com--2021-10-08-15-28 systemd-networkd[11562]: veth9d8eaf2: Lost carrier
Oct 08 22:15:07 oc1733c-ourcompose-com--2021-10-08-15-28 kernel: br-3d8042b52274: port 2(veth9d8eaf2) entered disabled state
Oct 08 22:15:07 oc1733c-ourcompose-com--2021-10-08-15-28 systemd-timesyncd[11583]: Network configuration changed, trying to establish connection.
Oct 08 22:15:07 oc1733c-ourcompose-com--2021-10-08-15-28 kernel: vetha344694: renamed from eth0
Oct 08 22:15:07 oc1733c-ourcompose-com--2021-10-08-15-28 kernel: br-3d8042b52274: port 2(veth9d8eaf2) entered disabled state
Oct 08 22:15:07 oc1733c-ourcompose-com--2021-10-08-15-28 systemd-networkd[11562]: veth9d8eaf2: Link DOWN
Oct 08 22:15:07 oc1733c-ourcompose-com--2021-10-08-15-28 networkd-dispatcher[816]: WARNING:Unknown index 19 seen, reloading interface list
Oct 08 22:15:07 oc1733c-ourcompose-com--2021-10-08-15-28 kernel: device veth9d8eaf2 left promiscuous mode
Oct 08 22:15:07 oc1733c-ourcompose-com--2021-10-08-15-28 kernel: br-3d8042b52274: port 2(veth9d8eaf2) entered disabled state
Oct 08 22:15:07 oc1733c-ourcompose-com--2021-10-08-15-28 systemd-timesyncd[11583]: Synchronized to time server 91.189.89.198:123 (ntp.ubuntu.com).
Oct 08 22:15:07 oc1733c-ourcompose-com--2021-10-08-15-28 networkd-dispatcher[816]: ERROR:Unknown interface index 19 seen even after reload
Oct 08 22:15:07 oc1733c-ourcompose-com--2021-10-08-15-28 kernel: br-3d8042b52274: port 2(vethd9ae88a) entered blocking state
Oct 08 22:15:07 oc1733c-ourcompose-com--2021-10-08-15-28 kernel: br-3d8042b52274: port 2(vethd9ae88a) entered disabled state
Oct 08 22:15:07 oc1733c-ourcompose-com--2021-10-08-15-28 kernel: device vethd9ae88a entered promiscuous mode
Oct 08 22:15:07 oc1733c-ourcompose-com--2021-10-08-15-28 systemd-networkd[11562]: vethd9ae88a: Link UP
Oct 08 22:15:07 oc1733c-ourcompose-com--2021-10-08-15-28 systemd-timesyncd[11583]: Network configuration changed, trying to establish connection.
Oct 08 22:15:07 oc1733c-ourcompose-com--2021-10-08-15-28 networkd-dispatcher[816]: WARNING:Unknown index 22 seen, reloading interface list
Oct 08 22:15:07 oc1733c-ourcompose-com--2021-10-08-15-28 kernel: IPv6: ADDRCONF(NETDEV_UP): vethd9ae88a: link is not ready
Oct 08 22:15:07 oc1733c-ourcompose-com--2021-10-08-15-28 kernel: br-3d8042b52274: port 2(vethd9ae88a) entered blocking state
Oct 08 22:15:07 oc1733c-ourcompose-com--2021-10-08-15-28 kernel: br-3d8042b52274: port 2(vethd9ae88a) entered forwarding state
Oct 08 22:15:07 oc1733c-ourcompose-com--2021-10-08-15-28 systemd-udevd[18294]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable.
Oct 08 22:15:07 oc1733c-ourcompose-com--2021-10-08-15-28 systemd-udevd[18294]: link_config: could not get ethtool features for vetha344694
Oct 08 22:15:07 oc1733c-ourcompose-com--2021-10-08-15-28 systemd-udevd[18294]: Could not set offload features of vetha344694: No such device
Oct 08 22:15:07 oc1733c-ourcompose-com--2021-10-08-15-28 dockerd[4271]: time="2021-10-08T22:15:07.642226696Z" level=info msg="No non-localhost DNS nameservers are left in resolv.conf. Using default external servers: [nameserver 8.8.8.8 na
meserver 8.8.4.4]"
Oct 08 22:15:07 oc1733c-ourcompose-com--2021-10-08-15-28 dockerd[4271]: time="2021-10-08T22:15:07.642906490Z" level=info msg="IPv6 enabled; Adding default IPv6 external servers: [nameserver 2001:4860:4860::8888 nameserver 2001:4860:4860::
8844]"
Oct 08 22:15:07 oc1733c-ourcompose-com--2021-10-08-15-28 systemd-udevd[18295]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable.
Oct 08 22:15:07 oc1733c-ourcompose-com--2021-10-08-15-28 systemd-udevd[18295]: Could not generate persistent MAC address for vethd9ae88a: No such file or directory
Oct 08 22:15:07 oc1733c-ourcompose-com--2021-10-08-15-28 systemd-udevd[18296]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable.
Oct 08 22:15:07 oc1733c-ourcompose-com--2021-10-08-15-28 systemd-udevd[18296]: Could not generate persistent MAC address for vethdd060fa: No such file or directory
Oct 08 22:15:07 oc1733c-ourcompose-com--2021-10-08-15-28 systemd-timesyncd[11583]: Synchronized to time server 91.189.89.198:123 (ntp.ubuntu.com).
Oct 08 22:15:07 oc1733c-ourcompose-com--2021-10-08-15-28 containerd[1450]: time="2021-10-08T22:15:07.782736703Z" level=info msg="starting signal loop" namespace=moby path=/run/containerd/io.containerd.runtime.v2.task/moby/76fd57552e5d22bf
2dd03984ad02aa36ce4545f982390cc13a1c6d3df4cd68d7 pid=18320
Oct 08 22:15:08 oc1733c-ourcompose-com--2021-10-08-15-28 kernel: br-3d8042b52274: port 2(vethd9ae88a) entered disabled state
Oct 08 22:15:08 oc1733c-ourcompose-com--2021-10-08-15-28 232312e79685[4271]: 2021-10-08 22:15:08 289 [Warning] Aborted connection 289 to db: 'unconnected' user: 'suitecrm' host: '172.19.0.3' (Got an error reading communication packets)
Oct 08 22:15:08 oc1733c-ourcompose-com--2021-10-08-15-28 systemd-networkd[11562]: vethd9ae88a: Gained carrier
Oct 08 22:15:08 oc1733c-ourcompose-com--2021-10-08-15-28 kernel: eth0: renamed from vethdd060fa
Oct 08 22:15:08 oc1733c-ourcompose-com--2021-10-08-15-28 kernel: IPv6: ADDRCONF(NETDEV_CHANGE): vethd9ae88a: link becomes ready
Oct 08 22:15:08 oc1733c-ourcompose-com--2021-10-08-15-28 kernel: br-3d8042b52274: port 2(vethd9ae88a) entered blocking state
Oct 08 22:15:08 oc1733c-ourcompose-com--2021-10-08-15-28 kernel: br-3d8042b52274: port 2(vethd9ae88a) entered forwarding state
Oct 08 22:15:08 oc1733c-ourcompose-com--2021-10-08-15-28 systemd-timesyncd[11583]: Network configuration changed, trying to establish connection.
Oct 08 22:15:08 oc1733c-ourcompose-com--2021-10-08-15-28 systemd-timesyncd[11583]: Synchronized to time server 91.189.89.198:123 (ntp.ubuntu.com).
Oct 08 22:15:08 oc1733c-ourcompose-com--2021-10-08-15-28 76fd57552e5d[4271]: suitecrm 22:15:08.90 
Oct 08 22:15:08 oc1733c-ourcompose-com--2021-10-08-15-28 76fd57552e5d[4271]: suitecrm 22:15:08.91 Welcome to the Bitnami suitecrm container
Oct 08 22:15:08 oc1733c-ourcompose-com--2021-10-08-15-28 76fd57552e5d[4271]: suitecrm 22:15:08.92 Subscribe to project updates by watching https://github.com/bitnami/bitnami-docker-suitecrm
Oct 08 22:15:08 oc1733c-ourcompose-com--2021-10-08-15-28 76fd57552e5d[4271]: suitecrm 22:15:08.93 Submit issues and feature requests at https://github.com/bitnami/bitnami-docker-suitecrm/issues
Oct 08 22:15:08 oc1733c-ourcompose-com--2021-10-08-15-28 76fd57552e5d[4271]: suitecrm 22:15:08.93 
Oct 08 22:15:08 oc1733c-ourcompose-com--2021-10-08-15-28 76fd57552e5d[4271]: suitecrm 22:15:08.94 INFO  ==> ** Starting SuiteCRM setup **
Oct 08 22:15:09 oc1733c-ourcompose-com--2021-10-08-15-28 76fd57552e5d[4271]: suitecrm 22:15:09.20 INFO  ==> Configuring PHP options
Oct 08 22:15:09 oc1733c-ourcompose-com--2021-10-08-15-28 76fd57552e5d[4271]: suitecrm 22:15:09.29 INFO  ==> Validating settings in MYSQL_CLIENT_* env vars
Oct 08 22:15:09 oc1733c-ourcompose-com--2021-10-08-15-28 76fd57552e5d[4271]: suitecrm 22:15:09.60 INFO  ==> Ensuring SuiteCRM directories exist
Oct 08 22:15:09 oc1733c-ourcompose-com--2021-10-08-15-28 76fd57552e5d[4271]: suitecrm 22:15:09.66 INFO  ==> Trying to connect to the database server

As you can see, 12 seconds after the command was logged, the starting/running container was terminated.

@Ajpantuso
Copy link
Collaborator

My guess is that the timeout is being applied because an existing container is being restarted whereas when you ran through CLI it looked like a fresh container.

@smacz42
Copy link
Author

smacz42 commented Oct 8, 2021

I was hoping that was the case too, but this happens on the server that's being started. See the output (emphasis added):

Oct 08 22:14:57 oc1733c-ourcompose-com--2021-10-08-15-28 76fd57552e5d [4271]: suitecrm 22:14:57.12 Welcome to the Bitnami suitecrm container

[...snip...]

Oct 08 22:15:07 oc1733c-ourcompose-com--2021-10-08-15-28 dockerd[4271]: time="2021-10-08T22:15:07.219870336Z" level=info msg="Container 76fd57552e5d 22bf2dd03984ad02aa36ce4545f982390cc13a1c6d3df4cd68d7 failed to exit within 10 seconds of s


Additionally, I tried a timeout of 200 seconds, and got the following:

Oct 08 22:48:52 oc1733c-ourcompose-com--2021-10-08-15-28 e9a94cec091d[4271]: suitecrm 22:48:52.74 Welcome to the Bitnami suitecrm container

[...snip...]

Oct 08 22:52:12 oc1733c-ourcompose-com--2021-10-08-15-28 dockerd[4271]: time="2021-10-08T22:52:12.876678706Z" level=info msg="Container e9a94cec091db6e907a0cd921875877d9a7a307b5728e3009d5dba0c74557f33 failed to exit within 200 seconds of

So even with a 200 second timeout (timeout: 200), Ansible is STILL RESTARTING THE CONTAINER ...

@smacz42
Copy link
Author

smacz42 commented Oct 8, 2021

It looks like it's doing it to other containers too...

Using the official mariadb server as an example:

- hosts: all
  vars:
    ansible_python_interpreter: "/usr/local/bin/python3-docker"
  tasks:
    - name: (mariadb) The latest mariadb service is built and present
      docker_compose:
        project_name: mariadb
        timeout: 60
        definition:
          version: '3.6'
          services:
              mariadb:
                  image: "mariadb:10.5"
                  container_name: database
                  restart: always
                  volumes:
                      - "/srv/local/database_mysql:/var/lib/mysql"
                      - "/srv/local/database_conf.d:/etc/mysql/conf.d"
                  networks:
                      - backend
                  environment:
                      MYSQL_ROOT_PASSWORD: "UOkfxFiFlzq8uZi3"
          networks:
              backend:
                  name: backend
        pull: yes
        state: present
        restarted: yes

Shutdown existing mariadb server: (note container id: 232312e79685)

Oct 08 23:09:05 oc1733c-ourcompose-com--2021-10-08-15-28 python3[17486]: ansible-docker_compose Invoked with project_name=mariadb timeout=60 definition={'version': '3.6', 'services': {'mariadb': {'image': 'mariadb:10.5', 'container_name':
 'database', 'restart': 'always', 'volumes': ['/srv/local/database_mysql:/var/lib/mysql', '/srv/local/database_conf.d:/etc/mysql/conf.d'], 'networks': ['backend'], 'environment': {'MYSQL_ROOT_PASSWORD': 'UOkfxFiFlzq8uZi3'}}}, 'networks': 
{'backend': {'name': 'backend'}}} pull=True state=present restarted=True docker_host=unix://var/run/docker.sock tls_hostname=localhost api_version=auto tls=False validate_certs=False debug=False hostname_check=False recreate=smart build=False remove_volumes=False remove_orphans=False stopped=False dependencies=True nocache=False ca_cert=None client_cert=None client_key=None ssl_version=None project_src=None files=None remove_images=None scale=None services=None           
Oct 08 23:09:06 oc1733c-ourcompose-com--2021-10-08-15-28 232312e79685[4271]: 2021-10-08 23:09:06 0 [Note] mysqld (initiated by: unknown): Normal shutdown                                                                                     
Oct 08 23:09:06 oc1733c-ourcompose-com--2021-10-08-15-28 232312e79685[4271]: 2021-10-08 23:09:06 0 [Note] Event Scheduler: Purging the queue. 0 events             
Oct 08 23:09:06 oc1733c-ourcompose-com--2021-10-08-15-28 232312e79685[4271]: 2021-10-08 23:09:06 0 [Note] InnoDB: FTS optimize thread exiting.                                                                                                
Oct 08 23:09:06 oc1733c-ourcompose-com--2021-10-08-15-28 232312e79685[4271]: 2021-10-08 23:09:06 0 [Note] InnoDB: Starting shutdown...                                                                                                        
Oct 08 23:09:06 oc1733c-ourcompose-com--2021-10-08-15-28 232312e79685[4271]: 2021-10-08 23:09:06 0 [Note] InnoDB: Dumping buffer pool(s) to /var/lib/mysql/ib_buffer_pool                                                                     
Oct 08 23:09:06 oc1733c-ourcompose-com--2021-10-08-15-28 232312e79685[4271]: 2021-10-08 23:09:06 0 [Note] InnoDB: Restricted to 2016 pages due to innodb_buf_pool_dump_pct=25                                                                 
Oct 08 23:09:06 oc1733c-ourcompose-com--2021-10-08-15-28 232312e79685[4271]: 2021-10-08 23:09:06 0 [Note] InnoDB: Buffer pool(s) dump completed at 211008 23:09:06                                                                            
Oct 08 23:09:07 oc1733c-ourcompose-com--2021-10-08-15-28 232312e79685[4271]: 2021-10-08 23:09:07 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"                             
Oct 08 23:09:07 oc1733c-ourcompose-com--2021-10-08-15-28 232312e79685[4271]: 2021-10-08 23:09:07 0 [Note] InnoDB: Shutdown completed; log sequence number 7661045; transaction id 11605                                                       
Oct 08 23:09:07 oc1733c-ourcompose-com--2021-10-08-15-28 232312e79685[4271]: 2021-10-08 23:09:07 0 [Note] mysqld: Shutdown complete                                                                                                           

Startup of new Mariadb container (Note the new container id: 6aa9f4bab61c):

Oct 08 23:09:08 oc1733c-ourcompose-com--2021-10-08-15-28 6aa9f4bab61c[4271]: 2021-10-08 23:09:08+00:00 [Note] [Entrypoint]: Entrypoint script for MariaDB Server 1:10.5.12+maria~focal started.
Oct 08 23:09:08 oc1733c-ourcompose-com--2021-10-08-15-28 6aa9f4bab61c[4271]: 2021-10-08 23:09:08+00:00 [Note] [Entrypoint]: Switching to dedicated user 'mysql'
Oct 08 23:09:08 oc1733c-ourcompose-com--2021-10-08-15-28 6aa9f4bab61c[4271]: 2021-10-08 23:09:08+00:00 [Note] [Entrypoint]: Entrypoint script for MariaDB Server 1:10.5.12+maria~focal started.
Oct 08 23:09:09 oc1733c-ourcompose-com--2021-10-08-15-28 6aa9f4bab61c[4271]: 2021-10-08 23:09:09 0 [Note] mysqld (mysqld 10.5.12-MariaDB-1:10.5.12+maria~focal) starting as process 1 ...
Oct 08 23:09:09 oc1733c-ourcompose-com--2021-10-08-15-28 6aa9f4bab61c[4271]: 2021-10-08 23:09:09 0 [Note] InnoDB: Uses event mutexes
Oct 08 23:09:09 oc1733c-ourcompose-com--2021-10-08-15-28 6aa9f4bab61c[4271]: 2021-10-08 23:09:09 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
Oct 08 23:09:09 oc1733c-ourcompose-com--2021-10-08-15-28 6aa9f4bab61c[4271]: 2021-10-08 23:09:09 0 [Note] InnoDB: Number of pools: 1
Oct 08 23:09:09 oc1733c-ourcompose-com--2021-10-08-15-28 6aa9f4bab61c[4271]: 2021-10-08 23:09:09 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
Oct 08 23:09:09 oc1733c-ourcompose-com--2021-10-08-15-28 6aa9f4bab61c[4271]: 2021-10-08 23:09:09 0 [Note] mysqld: O_TMPFILE is not supported on /tmp (disabling future attempts)
Oct 08 23:09:09 oc1733c-ourcompose-com--2021-10-08-15-28 6aa9f4bab61c[4271]: 2021-10-08 23:09:09 0 [Note] InnoDB: Using Linux native AIO
Oct 08 23:09:09 oc1733c-ourcompose-com--2021-10-08-15-28 6aa9f4bab61c[4271]: 2021-10-08 23:09:09 0 [Note] InnoDB: Initializing buffer pool, total size = 134217728, chunk size = 134217728
Oct 08 23:09:09 oc1733c-ourcompose-com--2021-10-08-15-28 6aa9f4bab61c[4271]: 2021-10-08 23:09:09 0 [Note] InnoDB: Completed initialization of buffer pool
Oct 08 23:09:09 oc1733c-ourcompose-com--2021-10-08-15-28 6aa9f4bab61c[4271]: 2021-10-08 23:09:09 0 [Note] InnoDB: 128 rollback segments are active.
Oct 08 23:09:09 oc1733c-ourcompose-com--2021-10-08-15-28 6aa9f4bab61c[4271]: 2021-10-08 23:09:09 0 [Note] InnoDB: Creating shared tablespace for temporary tables
Oct 08 23:09:09 oc1733c-ourcompose-com--2021-10-08-15-28 6aa9f4bab61c[4271]: 2021-10-08 23:09:09 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
Oct 08 23:09:09 oc1733c-ourcompose-com--2021-10-08-15-28 6aa9f4bab61c[4271]: 2021-10-08 23:09:09 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
Oct 08 23:09:09 oc1733c-ourcompose-com--2021-10-08-15-28 6aa9f4bab61c[4271]: 2021-10-08 23:09:09 0 [Note] InnoDB: 10.5.12 started; log sequence number 7661045; transaction id 11606
Oct 08 23:09:09 oc1733c-ourcompose-com--2021-10-08-15-28 6aa9f4bab61c[4271]: 2021-10-08 23:09:09 0 [Note] Plugin 'FEEDBACK' is disabled.
Oct 08 23:09:09 oc1733c-ourcompose-com--2021-10-08-15-28 6aa9f4bab61c[4271]: 2021-10-08 23:09:09 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
Oct 08 23:09:09 oc1733c-ourcompose-com--2021-10-08-15-28 6aa9f4bab61c[4271]: 2021-10-08 23:09:09 0 [Note] Server socket created on IP: '::'.
Oct 08 23:09:09 oc1733c-ourcompose-com--2021-10-08-15-28 6aa9f4bab61c[4271]: 2021-10-08 23:09:09 0 [Warning] 'proxies_priv' entry '@% root@232312e79685' ignored in --skip-name-resolve mode.
Oct 08 23:09:09 oc1733c-ourcompose-com--2021-10-08-15-28 6aa9f4bab61c[4271]: 2021-10-08 23:09:09 0 [Note] Reading of all Master_info entries succeeded
Oct 08 23:09:09 oc1733c-ourcompose-com--2021-10-08-15-28 6aa9f4bab61c[4271]: 2021-10-08 23:09:09 0 [Note] Added new Master_info '' to hash table
Oct 08 23:09:09 oc1733c-ourcompose-com--2021-10-08-15-28 6aa9f4bab61c[4271]: 2021-10-08 23:09:09 0 [Note] mysqld: ready for connections.
Oct 08 23:09:09 oc1733c-ourcompose-com--2021-10-08-15-28 6aa9f4bab61c[4271]: Version: '10.5.12-MariaDB-1:10.5.12+maria~focal'  socket: '/run/mysqld/mysqld.sock'  port: 3306  mariadb.org binary distribution
Oct 08 23:09:09 oc1733c-ourcompose-com--2021-10-08-15-28 6aa9f4bab61c[4271]: 2021-10-08 23:09:09 0 [Note] InnoDB: Buffer pool(s) load completed at 211008 23:09:09

And here we see the same force kill by dockerd of that started container id:

Oct 08 23:10:08 oc1733c-ourcompose-com--2021-10-08-15-28 dockerd[4271]: time="2021-10-08T23:10:08.425241962Z" level=info msg="Container 6aa9f4bab61c227eb53285090142428a036b5d2c11080c94546eddc3ca55c202 failed to exit within 60 seconds of s

I did some more testing with the manual docker-compose invocations, and couldn't get this behavior to reproduce when using docker-compose restart -t 10 with either the services stopped or the services running.


It seems that somehow, the docker-compose CLI doesn't apply the timeout to the containers that it starts, but somehow the invocation that Ansible is performing is forcing the timeout on the starting containers? Is that an accurate assessment?

@smacz42
Copy link
Author

smacz42 commented Oct 9, 2021

I just gunna confirm really quick here that my initial issue with suitecrm is solved with a workaround of setting the timeout to 200. This allows the initialization to complete before restarting the container. Previously this wasn't allowed to happen (the container was killed in the middle of the initialization script) and left the container in a broken state.

I am definitely interested in unraveling this issue however. I suspect this is applicable to any docker_compose task that has restarted: yes and state: present.

@felixfontein felixfontein added the docker-compose-v1 Docker Compose v1 label Oct 9, 2021
@Ajpantuso
Copy link
Collaborator

Can you provide the following?
docker-compose --version
docker --version
<path_to_python_executable> -c 'import docker; print(docker.__version__)'
ansible-galaxy collection list community.docker

Basically this Ansible module only calls the compose restart command which invokes the docker-py client, whose default timeout is already 10 seconds, to send a request to the docker API for a restart of the container. Within the backend restart logic the timeout is not included during the start procedure. However these timeout values have been revisited in both docker-compose and docker-py so having the versions would help understand the actual behavior on your end. That still doesn't explain why a SIGTERM is being issued in the newly started container in the first place however. BTW I cannot reproduce your issue in my environment using this ansible module (which further points towards a version mis-match).

@smacz42
Copy link
Author

smacz42 commented Oct 9, 2021

root@docker-test:~# docker-compose --version
docker-compose version 1.29.2, build unknown
root@docker-test:~# docker --version
Docker version 20.10.9, build c2ea9bc
root@docker-test:~# /usr/bin/env python3 -c 'import docker; print(docker.__version__)'
5.0.3
root@docker-test:~# ansible-galaxy collection list community.docker

# /usr/local/lib/python3.8/dist-packages/ansible_collections
Collection       Version
---------------- -------
community.docker 1.9.1  

Here's what I performed on a Ubuntu 20.04 server:

# curl -fsSL https://get.docker.com -o get-docker.sh
# bash ./get-docker.sh
# apt install python3-pip
# pip3 install docker docker-compose ansible
# cat <<EOF > mariadb_test.yml
- hosts: all
  vars:
    ansible_python_interpreter: '/usr/bin/env python3'
  tasks:
    - name: (mariadb) The latest mariadb service is built and present
      docker_compose:
        project_name: mariadb
        timeout: 60
        definition:
          version: '3.6'
          services:
              mariadb:
                  image: "mariadb:10.5"
                  container_name: database
                  restart: always
                  volumes:
                      - "/srv/local/database_mysql:/var/lib/mysql"
                      - "/srv/local/database_conf.d:/etc/mysql/conf.d"
                  networks:
                      - backend
                  environment:
                      MYSQL_ROOT_PASSWORD: "testpassword"
          networks:
              backend:
                  name: backend
        pull: yes
        state: present
        restarted: yes
EOF
# ansible-playbook -i localhost, -c local mariadb_test.yml
# journalctl -xe --since "3 minutes ago" | grep "failed to exit"

With the above, I'm able to able to get it to time out during the first deploy, but not during the restart. Any time the container is stopped, this timeout happens.

I'll take a look at my local env to see if there's anything different there.

@smacz42
Copy link
Author

smacz42 commented Oct 22, 2021

I'm still looking into possible reasons why even on a restart this would happen, but at very least changing restarted: yes to restarted: no causes no timeout to be generated on a brand new container.

This is infinitely reproducable using the following:

# docker stop suitecrm && docker rm suitecrm && docker rmi bitnami/suitecrm:latest && ansible-playbook -i localhost, -c local suitecrm_test.yml

With literally any container.

@smacz42
Copy link
Author

smacz42 commented Oct 23, 2021

I tried to get fancy:

    - debug:
        var: 0 | type_debug
    - docker_compose:
       [...snip...]
        timeout: 0
        restarted: "yes"
TASK [debug] **********************************************************************************************************
ok: [localhost] => {
    "0 | type_debug": "int"
}

TASK [docker_compose] *************************************************************************************************
fatal: [localhost]: FAILED! => {"changed": false, "msg": "Error connecting: Error while fetching server API version: Timeout cannot be a boolean value. It must be an int, float or None."}

I don't know whether to be frustrated or burst out into laughter.

@smacz42
Copy link
Author

smacz42 commented Oct 23, 2021

So, it seems like docker-compose never meant for a container to be restarted before it was up.

Notice how it errors out on restart (because the container isn't built yet) but succeeds on up.

root@timeout-test:~/docker# docker stop suitecrm && docker rm suitecrm && docker rmi bitnami/suitecrm:latest 
root@timeout-test:~/docker# cat docker-compose.yml 
version: '3.6'
services:
  suitecrm:
    image: "bitnami/suitecrm:latest"
    container_name: suitecrm
    restart: 'no'
    networks:
      - frontend
      - backend
    environment:
      SUITECRM_HOST: '165.227.194.97'
      SUITECRM_DATABASE_HOST: "database"
      SUITECRM_DATABASE_NAME: 'suitecrm'
      SUITECRM_DATABASE_USER: 'suitecrm'
      SUITECRM_DATABASE_PASSWORD: "testpassword"
      SUITECRM_SERVER_URL: "https://165.227.194.97/suitecrm"
      SUITECRM_USERNAME: 'admin'
      SUITECRM_PASSWORD: "testpassword"
      BITNAMI_DEBUG: 'true'
networks:
  frontend:
    external: true
  backend:
    external: true
root@timeout-test:~/docker# docker-compose restart
ERROR: No containers to restart
ERROR: 1
root@timeout-test:~/docker# docker-compose up
Pulling suitecrm (bitnami/suitecrm:latest)...
latest: Pulling from bitnami/suitecrm
23b664af592e: Pull complete
30dc532c8a96: Pull complete
a066a7210f72: Pull complete
af5a1366cd14: Pull complete
2692496fa208: Pull complete
ce9ba642567a: Pull complete
7b46ebf47ec2: Pull complete
295552f70d9b: Extracting [===============>                                   ]  17.27MB/54.01MB
dabfa3482b82: Download complete
e7d0e1b4a89b: Download complete
f64969386896: Download complete
cb652cb821d3: Download complete
04f94743d597: Download complete
3682eb3da910: Download complete
aa4e9e4d0be4: Download complete
390931032d72: Download complete
ad6761e5f22f: Download complete
feb3d6d67fc3: Download complete

And the rest of the startup proceeds from there.

So perhaps this is more of a proposition to be more intelligent about the restarted: yes parameter? Doing some tests to see if the container is available before trying to restart, and if not, defaulting to an up as an opposed to a restart?

I will be trying to work around this manually for now with something like:

# docker ps -a | tr -s ' ' | rev | cut -d ' ' -f 1 | rev | grep suitecrm

Which (in my own testing) will return 0 in the same situations where docker-compose restart would succeed, and return 1 (because the grep failed) in the same situations where docker-compose restart would fail if ran. So I can just register that to a variable and use that to determine whether to use yes or no for restarted. For example...

    - shell: docker ps -a | tr -s ' ' | rev | cut -d ' ' -f 1 | rev | grep suitecrm
      failed_when: false
      register: suitecrm_present
    - docker_compose:
        [...snip...]
        restarted: "{{ not suitecrm_present['rc'] | bool }}"

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
docker-compose-v1 Docker Compose v1
Projects
None yet
Development

No branches or pull requests

3 participants