docker icon indicating copy to clipboard operation
docker copied to clipboard
verified publisher icon koel

Docker image won't finish startup

Open OnSive opened this issue 4 years ago • 12 comments

The current state is permanently starting and the instance cannot be accessed over the browser.

Setup:

  • Docker-Compose
  • Treafik
  • Koel (w. MySQL)

image

Logs:

APP_KEY exists. Skipping key generation
running docker-php-entrypoint with arguments apache2-foreground
[Tue May 11 10:42:15.298401 2021] [so:warn] [pid 8] AH01574: module xsendfile_module is already loaded, skipping
AH00558: apache2: Could not reliably determine the server's fully qualified domain name, using 172.26.0.3. Set the 'ServerName' directive globally to suppress this message
[Tue May 11 10:42:15.338772 2021] [so:warn] [pid 8] AH01574: module xsendfile_module is already loaded, skipping
AH00558: apache2: Could not reliably determine the server's fully qualified domain name, using 172.26.0.3. Set the 'ServerName' directive globally to suppress this message
[Tue May 11 10:42:15.755978 2021] [mpm_prefork:notice] [pid 8] AH00163: Apache/2.4.38 (Debian) PHP/7.4.19 configured -- resuming normal operations
[Tue May 11 10:42:15.756005 2021] [core:notice] [pid 8] AH00094: Command line: 'apache2 -D FOREGROUND'
172.26.0.1 - - [11/May/2021:10:44:55 +0000] "GET / HTTP/1.1" 200 918 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/90.0.4430.93 Safari/537.36"
172.26.0.1 - - [11/May/2021:10:44:55 +0000] "\x16\x03\x01\x02" 400 0 "-" "-"
172.26.0.1 - - [11/May/2021:10:44:55 +0000] "\x16\x03\x01\x02" 400 0 "-" "-"
172.26.0.1 - - [11/May/2021:10:44:55 +0000] "\x16\x03\x01\x02" 400 0 "-" "-"
172.26.0.1 - - [11/May/2021:10:44:55 +0000] "\x16\x03\x01\x02" 400 0 "-" "-"
172.26.0.1 - - [11/May/2021:10:44:55 +0000] "\x16\x03\x01\x02" 400 0 "-" "-"
172.26.0.1 - - [11/May/2021:10:44:55 +0000] "\x16\x03\x01\x02" 400 0 "-" "-"
172.26.0.1 - - [11/May/2021:10:44:55 +0000] "\x16\x03\x01\x02" 400 0 "-" "-"
172.26.0.1 - - [11/May/2021:10:44:55 +0000] "\x16\x03\x01\x02" 400 0 "-" "-"

OnSive avatar May 11 '21 10:05 OnSive

Hi, thanks for pasting the container logs here. Could you please attach the laravel logs ? They are located at /var/www/html/storage/logs/laravel.log in the container. The file might not exist, which would mean there are no logs.

Hyzual avatar May 11 '21 13:05 Hyzual

Thx for the fast reply :)

Sorry, the directory doesn't exist.

root@972a17220d45:/var/www/html# ls storage/
app  dotenv-editor  framework  search-indexes

How can I activate them? Can't find the info in the docs.

OnSive avatar May 11 '21 18:05 OnSive

Now it works just fine, Koel instance is started without any problems.

I have no clue what went wrong. No configuration was changed between the last 5 runs.

I'll watch it for the next few days and let you know if the error occures again.

OnSive avatar May 11 '21 18:05 OnSive

I have the same issue. The container is stuck at starting

Application key set successfully.,
running docker-php-entrypoint with arguments apache2-foreground,
[Sun May 23 09:13:15.409077 2021] [so:warn] [pid 16] AH01574: module xsendfile_module is already loaded, skipping,
AH00558: apache2: Could not reliably determine the server's fully qualified domain name, using 172.18.0.6. Set the 'ServerName' directive globally to suppress this message,
[Sun May 23 09:13:15.450813 2021] [so:warn] [pid 16] AH01574: module xsendfile_module is already loaded, skipping,
AH00558: apache2: Could not reliably determine the server's fully qualified domain name, using 172.18.0.6. Set the 'ServerName' directive globally to suppress this message,
[Sun May 23 09:13:15.484861 2021] [mpm_prefork:notice] [pid 16] AH00163: Apache/2.4.38 (Debian) PHP/7.4.19 configured -- resuming normal operations,
[Sun May 23 09:13:15.488514 2021] [core:notice] [pid 16] AH00094: Command line: 'apache2 -D FOREGROUND',```

flaxplax avatar May 23 '21 09:05 flaxplax

I have the same issue. The container is stuck at starting

Application key set successfully.,
running docker-php-entrypoint with arguments apache2-foreground,
[Sun May 23 09:13:15.409077 2021] [so:warn] [pid 16] AH01574: module xsendfile_module is already loaded, skipping,
AH00558: apache2: Could not reliably determine the server's fully qualified domain name, using 172.18.0.6. Set the 'ServerName' directive globally to suppress this message,
[Sun May 23 09:13:15.450813 2021] [so:warn] [pid 16] AH01574: module xsendfile_module is already loaded, skipping,
AH00558: apache2: Could not reliably determine the server's fully qualified domain name, using 172.18.0.6. Set the 'ServerName' directive globally to suppress this message,
[Sun May 23 09:13:15.484861 2021] [mpm_prefork:notice] [pid 16] AH00163: Apache/2.4.38 (Debian) PHP/7.4.19 configured -- resuming normal operations,
[Sun May 23 09:13:15.488514 2021] [core:notice] [pid 16] AH00094: Command line: 'apache2 -D FOREGROUND',```

Same issue for me. Does anyone have an idea of how to resolve this issue?

piyoki avatar May 30 '21 07:05 piyoki

I found out that the container took up to 30 minutes to start. so there never was an issue for me in the end.

flaxplax avatar May 30 '21 14:05 flaxplax

Have had this issue, noticed the healthcheck was set to 5 minutes. If using Traefik, it will not pass through requests to the server until at least one healthcheck has successfully completed. Thus it will take 5 minutes after starting the container for it to be available on the Traefik interface. You can disable this by setting:

healthcheck:
    disable: true

in the docker-compose.yml file. This will disable healthchecks and allow the service to be immediately available via Traefik.

chorca avatar Sep 21 '21 02:09 chorca

I have the same issue. Running the Docker image inside CapRover, but have no way to disable the healthcheck. So if the container needs to reboot for whatever reason, Koel is unavailable for 5 minutes. Would it be possible to make the healthcheck in the Dockerfile optional? Or make the interval shorter until the first success?

yoeran avatar Feb 14 '22 15:02 yoeran

I have the same issue. The container is stuck at starting

Application key set successfully.,
running docker-php-entrypoint with arguments apache2-foreground,
[Sun May 23 09:13:15.409077 2021] [so:warn] [pid 16] AH01574: module xsendfile_module is already loaded, skipping,
AH00558: apache2: Could not reliably determine the server's fully qualified domain name, using 172.18.0.6. Set the 'ServerName' directive globally to suppress this message,
[Sun May 23 09:13:15.450813 2021] [so:warn] [pid 16] AH01574: module xsendfile_module is already loaded, skipping,
AH00558: apache2: Could not reliably determine the server's fully qualified domain name, using 172.18.0.6. Set the 'ServerName' directive globally to suppress this message,
[Sun May 23 09:13:15.484861 2021] [mpm_prefork:notice] [pid 16] AH00163: Apache/2.4.38 (Debian) PHP/7.4.19 configured -- resuming normal operations,
[Sun May 23 09:13:15.488514 2021] [core:notice] [pid 16] AH00094: Command line: 'apache2 -D FOREGROUND',```

Same issue for me. Does anyone have an idea of how to resolve this issue?

any update here? same problem, I already added in docker compose

healthcheck: disable: true

cgmastertecnology avatar Apr 17 '22 10:04 cgmastertecnology

I have the same issue. The container is stuck at starting

Application key set successfully.,
running docker-php-entrypoint with arguments apache2-foreground,
[Sun May 23 09:13:15.409077 2021] [so:warn] [pid 16] AH01574: module xsendfile_module is already loaded, skipping,
AH00558: apache2: Could not reliably determine the server's fully qualified domain name, using 172.18.0.6. Set the 'ServerName' directive globally to suppress this message,
[Sun May 23 09:13:15.450813 2021] [so:warn] [pid 16] AH01574: module xsendfile_module is already loaded, skipping,
AH00558: apache2: Could not reliably determine the server's fully qualified domain name, using 172.18.0.6. Set the 'ServerName' directive globally to suppress this message,
[Sun May 23 09:13:15.484861 2021] [mpm_prefork:notice] [pid 16] AH00163: Apache/2.4.38 (Debian) PHP/7.4.19 configured -- resuming normal operations,
[Sun May 23 09:13:15.488514 2021] [core:notice] [pid 16] AH00094: Command line: 'apache2 -D FOREGROUND',```

Same issue for me. Does anyone have an idea of how to resolve this issue?

any update here? same problem, I already added in docker compose

healthcheck: disable: true

Seems like you have the same issue i had. What i found out was that i went shopping and when i got back the server was running and working. Seems to me that it is just very slow to start.

flaxplax avatar Apr 22 '22 07:04 flaxplax

I'm attempting to deploy koel via docker swarm stack file. The docker daemon isn't able to start the webserver container. Here are the logs:

journalctl -n docker.service
Jan 03 11:23:08 lahey dockerd[911]: time="2024-01-03T11:23:08.633041608-06:00" level=info msg="Container failed to exit within 10s of signal 28 - using the force" container=89d804997ec421bcf1285fd0ec7ad94624b4b0975db31c6bc90cf86984c759c9
Jan 03 11:23:08 lahey dockerd[911]: time="2024-01-03T11:23:08.695804797-06:00" level=info msg="ignoring event" container=89d804997ec421bcf1285fd0ec7ad94624b4b0975db31c6bc90cf86984c759c9 module=libcontainerd namespace=moby topic=/tasks/delete type="*events
Jan 03 11:23:08 lahey dockerd[911]: time="2024-01-03T11:23:08.721416476-06:00" level=warning msg="deleteServiceInfoFromCluster NetworkDB DeleteEntry failed for 194b45b5467c0aca80346459fc67e77b76d5a5878aca7cc03c8036083124d48c nwyuk3ynyrp4r5go8a7dwpzgl err:
Jan 03 11:23:08 lahey dockerd[911]: time="2024-01-03T11:23:08.721487472-06:00" level=warning msg="rmServiceBinding deleteServiceInfoFromCluster koel_koel 194b45b5467c0aca80346459fc67e77b76d5a5878aca7cc03c8036083124d48c aborted c.serviceBindings[skey] !ok"
Jan 03 11:23:08 lahey dockerd[911]: time="2024-01-03T11:23:08.853666535-06:00" level=warning msg="deleteServiceInfoFromCluster NetworkDB DeleteEntry failed for 25e7addceb059936c42f95d28a3175741a9e75eff3cbd21e70d4cfb01839e6be wcmth0btv0zkci8slubpj7vyg err:
Jan 03 11:23:08 lahey dockerd[911]: time="2024-01-03T11:23:08.853821715-06:00" level=warning msg="rmServiceBinding deleteServiceInfoFromCluster koel_koel 25e7addceb059936c42f95d28a3175741a9e75eff3cbd21e70d4cfb01839e6be aborted c.serviceBindings[skey] !ok"
Jan 03 11:25:01 lahey dockerd[911]: time="2024-01-03T11:25:01.880624792-06:00" level=error msg="stream copy error: reading from a closed fifo"
Jan 03 11:25:01 lahey dockerd[911]: time="2024-01-03T11:25:01.880624671-06:00" level=error msg="stream copy error: reading from a closed fifo"
Jan 03 11:25:01 lahey dockerd[911]: time="2024-01-03T11:25:01.882440631-06:00" level=error msg="Error running exec f2486153957afdbcc5a1b110be9e907988d4515d9c674d6f7a3fcc1743f70d15 in container: OCI runtime exec failed: exec failed: unable to start contain
Jan 03 11:26:24 lahey dockerd[911]: time="2024-01-03T11:26:24.515505927-06:00" level=info msg="NetworkDB stats lahey(dfe0ebedd7ed) - netID:wcmth0btv0zkci8slubpj7vyg leaving:false netPeers:2 entries:85 Queue qLen:0 netMsg/s:0"
Jan 03 11:26:24 lahey dockerd[911]: time="2024-01-03T11:26:24.515572599-06:00" level=info msg="NetworkDB stats lahey(dfe0ebedd7ed) - netID:40o9ncvi0ryobbs8736k02d07 leaving:true netPeers:0 entries:14 Queue qLen:0 netMsg/s:0"
Jan 03 11:26:24 lahey dockerd[911]: time="2024-01-03T11:26:24.515603304-06:00" level=info msg="NetworkDB stats lahey(dfe0ebedd7ed) - netID:nwyuk3ynyrp4r5go8a7dwpzgl leaving:false netPeers:2 entries:75 Queue qLen:0 netMsg/s:0"
Jan 03 11:26:24 lahey dockerd[911]: time="2024-01-03T11:26:24.515619067-06:00" level=info msg="NetworkDB stats lahey(dfe0ebedd7ed) - netID:l4jhi81e8iy9xmn93cl875skr leaving:false netPeers:1 entries:3 Queue qLen:0 netMsg/s:0"
Jan 03 11:26:24 lahey dockerd[911]: time="2024-01-03T11:26:24.515644795-06:00" level=info msg="NetworkDB stats lahey(dfe0ebedd7ed) - netID:lqw820ml8kicuahybb26pv5bi leaving:false netPeers:2 entries:6 Queue qLen:0 netMsg/s:0"
Jan 03 11:26:24 lahey dockerd[911]: time="2024-01-03T11:26:24.515663440-06:00" level=info msg="NetworkDB stats lahey(dfe0ebedd7ed) - netID:q4c261wrg7uk6whxg82fg8x0h leaving:false netPeers:1 entries:5 Queue qLen:0 netMsg/s:0"
Jan 03 11:26:24 lahey dockerd[911]: time="2024-01-03T11:26:24.515677935-06:00" level=info msg="NetworkDB stats lahey(dfe0ebedd7ed) - netID:d2j7edjamxy5oitkot83z2ffo leaving:false netPeers:1 entries:3 Queue qLen:0 netMsg/s:0"
Jan 03 11:26:24 lahey dockerd[911]: time="2024-01-03T11:26:24.515692752-06:00" level=info msg="NetworkDB stats lahey(dfe0ebedd7ed) - netID:9r3s50q3azufum544hogk1rar leaving:false netPeers:1 entries:3 Queue qLen:0 netMsg/s:0"
Jan 03 11:26:24 lahey dockerd[911]: time="2024-01-03T11:26:24.515707405-06:00" level=info msg="NetworkDB stats lahey(dfe0ebedd7ed) - netID:fo77nzau22ecfp6yljefmnurm leaving:false netPeers:1 entries:7 Queue qLen:0 netMsg/s:0"
Jan 03 11:26:24 lahey dockerd[911]: time="2024-01-03T11:26:24.515721745-06:00" level=info msg="NetworkDB stats lahey(dfe0ebedd7ed) - netID:1qq2jmrbw5un8hu3k11xs2o9l leaving:false netPeers:1 entries:5 Queue qLen:0 netMsg/s:0"
Jan 03 11:26:24 lahey dockerd[911]: time="2024-01-03T11:26:24.515736082-06:00" level=info msg="NetworkDB stats lahey(dfe0ebedd7ed) - netID:six3lp9zh9py006h7pioadna9 leaving:false netPeers:1 entries:3 Queue qLen:0 netMsg/s:0"

root@lahey:~/homelab_data# docker service ps --no-trunc koel_koel
ID                          NAME              IMAGE                                                                                        NODE      DESIRED STATE   CURRENT STATE             ERROR     PORTS
5cc7l0ow7zdjt8xezhjm8i6ll   koel_koel.1       phanan/koel:6.12.0@sha256:e557921f585e92b0f939a79801e4f696185cce6b48400b8b3dcf09438206a408   lahey     Running         Starting 33 seconds ago
gwposnih8nw442jgm01rq34h5    \_ koel_koel.1   phanan/koel:latest@sha256:e557921f585e92b0f939a79801e4f696185cce6b48400b8b3dcf09438206a408   lahey     Shutdown        Shutdown 33 seconds ago

Finally after several minutes, 10+, koel succesfully started. Something odd is definitely going on here.

Stackfile used:

version: '3'

services:
  koel:
    image: phanan/koel:6.12.0
    depends_on:
      - database
    ports:
      - 8765:80
    environment:
      - DB_CONNECTION=pgsql
      - DB_HOST=database
      - DB_USERNAME=koel
      - DB_DATABASE=koel
      - DB_PASSWORD=<redacted>
    volumes:
      - "<redacted>:/music:ro"
      - koel-covers:/var/www/html/public/img/covers
      - koel-search-index:/var/www/html/storage/search-indexes
    networks:
      - homelab
    deploy:
      placement:
        constraints:
          - node.hostname == <redacted>
      labels:
        - "traefik.enable=true"
        - "traefik.docker.network=homelab"
        # ROUTER
        - "traefik.http.routers.koel.rule=Host(`<redacted>`)"
        - "traefik.http.routers.koel.entrypoints=websecure"
        - "traefik.http.routers.koel.service=koel"
        # SERVICE
        - "traefik.http.services.koel.loadbalancer.server.port=80"

  database:
    image: postgres:13
    volumes:
      - koel-pgdata:/var/lib/postgresql/data'
    environment:
      - POSTGRES_DB=koel
      - POSTGRES_USER=koel
      - POSTGRES_PASSWORD=<redacted>
    networks:
      - homelab
    deploy:
      placement:
        constraints:
          - node.hostname == <redacted>

volumes:
  koel-covers:
    driver: local
    driver_opts:
      type: nfs
      o: addr={{nfs_server}},nfsvers=4.1,rw,nolock,soft
      device: :/swarm/stacks/koel/covers
  koel-search-index:
    driver: local
    driver_opts:
      type: nfs
      o: addr={{nfs_server}},nfsvers=4.1,rw,nolock,soft
      device: :/swarm/stacks/koel/search_index
  koel-pgdata:
    driver: local
    driver_opts:
      type: nfs
      o: addr={{nfs_server}},nfsvers=4.1,rw,nolock,soft
      device: :/swarm/stacks/koel_db/

networks:
  homelab:
    external: true

patrick-motard avatar Jan 03 '24 17:01 patrick-motard