halfer halfer -4 years ago 171
PHP Question

Why might Docker Compose restart be rendering container output an increasing number of times?

I am writing a web app based on Docker Compose, and it has a number of background systems - an HTTP API, a HTTP proxy and a queue. Everything is in PHP in Alpine containers, either PHP 5.6 or 7.0.

I originally set up the queue in Supervisor inside the API container, which worked fine. However Supervisor/Python makes containers much fatter than they should be (80M rather than 25M) so I moved the queue to its own container. It lives for ~5 minutes and quits, and I was using the auto-restart system in Supervisor, so I have swapped to the restart system in Docker Compose. I am using version 2 of the Compose YAML format.

When the queue starts up, it renders a simple message to stdout:

queue_instance | Starting queue watcher (path=/remote/queue, proxying to proximate-proxy:8081)


This is fine when I do
docker-compose up
initially. However, for every restart, I get three of these messages, then five, and so on, with no limit. If I do
docker ps
then it indicates there is only one queue running:

halfer@machine:~/proximate-app$ docker ps
CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES
a9c94558769d proximate-app "/tmp/container-st..." 2 hours ago Up 2 hours 0.0.0.0:8084->8084/tcp app_instance
7e48d6aec459 proximate-api "sh /tmp/bin/web-s..." 2 hours ago Up 2 hours 0.0.0.0:8080->8080/tcp api_instance
86c564becadf proximate-queue "sh /var/app/bin/c..." 2 hours ago Up About a minute queue_instance
20c2145f80e4 proximate-proxy "sh /var/proxy/con..." 2 hours ago Up 2 hours 0.0.0.0:8081->8081/tcp proxy_instance


Here is my Compose file:

version: '2'
services:

proximate-app:
container_name: "app_instance"
image: proximate-app
ports:
- "8084:8084"
links:
- proximate-api

# @todo Remove external ports once everything is happy
proximate-api:
container_name: "api_instance"
image: proximate-api
ports:
- "8080:8080"
links:
- proximate-proxy
- proximate-queue
volumes:
- proximate-volume:/remote/cache
- proximate-q-volume:/remote/queue
# Use time and TZ from the host, could alternatively use env vars and set it
# manually in the container, see https://wiki.alpinelinux.org/wiki/Setting_the_timezone
- /etc/localtime:/etc/localtime:ro
- /etc/timezone:/etc/timezone:ro
# Should perhaps pass this as a var to docker-compose so as not to hardwire it,
# but it is fine for now
environment:
- PHP_TIMEZONE=Europe/London

proximate-queue:
container_name: "queue_instance"
image: proximate-queue
restart: always
links:
- proximate-proxy
volumes:
- proximate-volume:/remote/cache
- proximate-q-volume:/remote/queue
environment:
- PROXY_ADDRESS=proximate-proxy:8081

# @todo Remove external ports once everything is happy
proximate-proxy:
container_name: "proxy_instance"
image: proximate-proxy
ports:
- "8081:8081"
volumes:
- proximate-volume:/remote/cache
environment:
- PROXY_LOG_PATH=/remote/cache/proxy.log

volumes:
proximate-volume:
proximate-q-volume:


The relevant container is
proximate-queue
.

I am pretty sure that my container itself is not responsible for this oddity. My
Dockerfile
enters thus:

ENTRYPOINT ["sh", "/var/app/bin/container-start.sh"]


And that just calls a launch script:

#!/bin/sh

php \
/var/app/bin/queue.php \
--queue-path /remote/queue \
--proxy-address ${PROXY_ADDRESS}


Which runs a queue process:

#!/usr/bin/env php
<?php

use Proximate\Service\File;
use Proximate\Service\SiteFetcher as SiteFetcherService;
use Proximate\Queue\Read as QueueReader;

$root = realpath(__DIR__ . '/..');
require_once $root . '/vendor/autoload.php';

$actions = getopt('p:q:', ['proxy-address:', 'queue-path:']);

$queuePath = isset($actions['queue-path']) ? $actions['queue-path'] : (isset($actions['q']) ? $actions['q'] : null);
$proxyAddress = isset($actions['proxy-address']) ? $actions['proxy-address'] : (isset($actions['p']) ? $actions['p'] : null);

if (!$queuePath || !$proxyAddress)
{
$command = __FILE__;
die(
sprintf("Syntax: %s --proxy-address <proxy:port> --queue-path <queue-path>\n", $command)
);
}

if (!file_exists($queuePath))
{
die(
sprintf("Error: the supplied queue path `%s` does not exist\n", $queuePath)
);
}

echo sprintf(
"Starting queue watcher (path=%s, proxying to %s)\n",
$queuePath,
$proxyAddress
);

$queue = new QueueReader($queuePath, new File());
$queue->
setFetcher(new SiteFetcherService($proxyAddress))->
process();


As you can see, the
echo sprintf()
is what announces the start-up, and there's nothing like loops that could be doing this on my side. Could this be a bug in Docker Compose? I am using
docker-compose version 1.9.0, build 2585387
on Ubuntu 14.04.

For reference, the Docker Compose stdout looks like this (the repeated lines from the queue are visible):

halfer@machine:~/proximate-app$ docker-compose up
Creating network "proximateapp_default" with the default driver
Creating proxy_instance
Creating queue_instance
Creating api_instance
Creating app_instance
Attaching to proxy_instance, queue_instance, api_instance, app_instance
proxy_instance | Teeing proxy logs also to /remote/cache/proxy.log
proxy_instance | [2017-05-10 09:18:42] stdout.INFO: Setting up queue at `/remote/cache/data` [] []
proxy_instance | [2017-05-10 09:18:42] stdout.INFO: Starting proxy listener on 172.18.0.2:8081 [] []
queue_instance | Starting queue watcher (path=/remote/queue, proxying to proximate-proxy:8081)
api_instance | PHP 7.0.16 Development Server started at Wed May 10 10:19:00 2017
app_instance | PHP 5.6.29 Development Server started at Wed May 10 09:19:10 2017
app_instance | PHP 5.6.29 Development Server started at Wed May 10 09:19:10 2017
queue_instance exited with code 0
queue_instance | Starting queue watcher (path=/remote/queue, proxying to proximate-proxy:8081)
queue_instance | Starting queue watcher (path=/remote/queue, proxying to proximate-proxy:8081)
queue_instance | Starting queue watcher (path=/remote/queue, proxying to proximate-proxy:8081)
queue_instance exited with code 0
queue_instance | Starting queue watcher (path=/remote/queue, proxying to proximate-proxy:8081)
queue_instance | Starting queue watcher (path=/remote/queue, proxying to proximate-proxy:8081)
queue_instance | Starting queue watcher (path=/remote/queue, proxying to proximate-proxy:8081)
queue_instance | Starting queue watcher (path=/remote/queue, proxying to proximate-proxy:8081)
queue_instance | Starting queue watcher (path=/remote/queue, proxying to proximate-proxy:8081)


One thing I could try is to get the app to sleep and do nothing else, to prove that some weird exit handler or something is not causing havoc. However, I expect that will do exactly the same thing.

Update



I have replaced the queue with a script that prints time information then sleeps for 20 seconds. This is what I get:

halfer@machine:~/proximate-app$ docker-compose up
Creating network "proximateapp_default" with the default driver
Creating proxy_instance
Creating queue_instance
Creating api_instance
Creating app_instance
Attaching to proxy_instance, queue_instance, api_instance, app_instance
proxy_instance | Teeing proxy logs also to /remote/cache/proxy.log
proxy_instance | [2017-05-10 11:51:17] stdout.INFO: Setting up queue at `/remote/cache/data` [] []
proxy_instance | [2017-05-10 11:51:17] stdout.INFO: Starting proxy listener on 172.18.0.2:8081 [] []
queue_instance | Hello everyone! Time=Wed, 10 May 2017 11:51:27 +0000. Microtime=1494417087.107185
api_instance | PHP 7.0.16 Development Server started at Wed May 10 12:51:37 2017
app_instance | PHP 5.6.29 Development Server started at Wed May 10 11:51:46 2017
app_instance | PHP 5.6.29 Development Server started at Wed May 10 11:51:46 2017
queue_instance exited with code 0
queue_instance | Hello everyone! Time=Wed, 10 May 2017 11:51:27 +0000. Microtime=1494417087.107185
queue_instance | Hello everyone! Time=Wed, 10 May 2017 11:51:55 +0000. Microtime=1494417115.178871
queue_instance | Hello everyone! Time=Wed, 10 May 2017 11:52:22 +0000. Microtime=1494417142.409513
queue_instance exited with code 0
queue_instance | Hello everyone! Time=Wed, 10 May 2017 11:51:27 +0000. Microtime=1494417087.107185
queue_instance | Hello everyone! Time=Wed, 10 May 2017 11:51:55 +0000. Microtime=1494417115.178871
queue_instance | Hello everyone! Time=Wed, 10 May 2017 11:52:22 +0000. Microtime=1494417142.409513
queue_instance | Hello everyone! Time=Wed, 10 May 2017 11:52:49 +0000. Microtime=1494417169.612523
queue_instance | Hello everyone! Time=Wed, 10 May 2017 11:53:17 +0000. Microtime=1494417197.826749


That seems to show that:


  • Restarts are reported only every other restart

  • My task will take exactly 20 seconds, but Compose is restarting them quite sluggishly (closer to every 30 seconds). That doesn't bother me too much, but may be a useful observation

  • Where lines are being repeated, they are in fact old restart reports.



What is going on?

Answer Source

I sum up what we discovered.

The cumulative output is due to the container is not being removed each time it exits. So, docker-compose starts it again showing you the docker logs -f from the same container that is starting again. That is working as expected.

I didn't find a way to get docker-compose removing a container before start it again inside the same docker-compose up

I like your queue-based architecture, but I think that it would be better if you use a long-lived container instead of one container that starts/exits/starts/exits... You can accomplish it doing a simple while true; do ./queue-app-blabla.php; sleep 20; done in a shell script.

Anyone that need to reproduce this, can use the following docker-compose.yml

version: "2"

services:
  ui:
    image: ubuntu
    command: tail -f /dev/null
    links:
      - queue
  queue:
    image: ubuntu
    command: sh -c "date; echo Sleeping...; sleep 20; echo exit."
    restart: always

Output:

queue_1  | Mon May 15 04:32:12 UTC 2017
queue_1  | Sleeping...
queue_1  | exit.
docker_queue_1 exited with code 0
queue_1  | Mon May 15 04:32:12 UTC 2017
queue_1  | Sleeping...
queue_1  | exit.
queue_1  | Mon May 15 04:32:33 UTC 2017
queue_1  | Sleeping...
queue_1  | exit.
queue_1  | Mon May 15 04:32:54 UTC 2017
queue_1  | Sleeping...
queue_1  | exit.
docker_queue_1 exited with code 0
queue_1  | Mon May 15 04:32:12 UTC 2017
queue_1  | Sleeping...
queue_1  | exit.
queue_1  | Mon May 15 04:32:33 UTC 2017
queue_1  | Sleeping...
queue_1  | exit.
queue_1  | Mon May 15 04:32:54 UTC 2017
queue_1  | Sleeping...
queue_1  | exit.
queue_1  | Mon May 15 04:33:17 UTC 2017
queue_1  | Sleeping...
queue_1  | exit.
queue_1  | Mon May 15 04:33:38 UTC 2017
queue_1  | Sleeping...
queue_1  | exit.

My proposed solution:

version: "2"

services:
  ui:
    image: ubuntu
    command: tail -f /dev/null
    links:
      - queue
  queue:
    image: ubuntu
    command: sh -c "while true; do date; echo Sleeping...; sleep 20; echo loop.; done"
    restart: always

Output:

Attaching to docker_queue_1, docker_ui_1
queue_1  | Mon May 15 04:36:16 UTC 2017
queue_1  | Sleeping...
queue_1  | loop.
queue_1  | Mon May 15 04:36:36 UTC 2017
queue_1  | Sleeping...
queue_1  | loop.
queue_1  | Mon May 15 04:36:56 UTC 2017
queue_1  | Sleeping...
queue_1  | loop.
queue_1  | Mon May 15 04:37:16 UTC 2017
queue_1  | Sleeping...

IMO, it's better to see containers start and work, instead of flapping start/exit containers. Docker has an special treatment to containers that have this behaviour, see docker docs. "An ever increasing delay (double the previous delay, starting at 100 milliseconds) is added before each restart to prevent flooding the server." (but it does not apply in your case because your container is living > 10s.


Edit:

To check a possible error and exit. This could be useful:

#!/bin/bash

PERIOD=10 # seconds

while true; do
  echo Starting process...

  date # the process
  STATUS=$?

  if [ $STATUS -ne 0 ]; then
        echo "Error found. Exiting" >&2
        exit $STATUS
  fi

  echo End process. Sleeping ${PERIOD}s
  sleep $PERIOD
done

Output:

▶ ./script.sh
Starting process...
Mon May 15 11:43:06 ART 2017
End process. Sleeping 10s
Starting process...
Mon May 15 11:43:16 ART 2017
End process. Sleeping 10s
Starting process...
Mon May 15 11:43:26 ART 2017
End process. Sleeping 10s
Starting process...
Mon May 15 11:43:36 ART 2017
End process. Sleeping 10s
Starting process...
Mon May 15 11:43:46 ART 2017
End process. Sleeping 10s
Recommended from our users: Dynamic Network Monitoring from WhatsUp Gold from IPSwitch. Free Download