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 in order to be restarted, 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?
