Compose: docker-compose run executes a script twice

[hayeah]

I using docker-compose run to send restart request to my puma server, and the script is being run twice about 10 seconds apart.

docker-compose ps shows that I have two containers running:

docker-compose ps
      Name                    Command               State                 Ports
---------------------------------------------------------------------------------------------
deploy_sikedb_1    /docker-entrypoint.sh postgres   Up      5432/tcp
deploy_sikeweb_1   /bin/sh -c sh /do/run.sh         Up      0.0.0.0:49214->3000/tcp, 4000/tcp

If i run the command now, it makes two requests to the sikeweb puma control server (on port 4000):

docker-compose run --rm sikeweb sh /do/restart.sh
[puma] restarting from 80e932002918
Command restart sent success
[puma] restarting from 80e932002918
Command restart sent success

Looking at the container log verifies that the server is restarting twice:

$ docker logs deploy_sikeweb_1
04:24:26 web.1  | * Restarting...
04:24:26 web.1  | Puma starting in single mode...
04:24:26 web.1  | * Version 2.11.1 (ruby 2.2.1-p85), codename: Intrepid Squirrel
04:24:26 web.1  | * Min threads: 0, max threads: 16
04:24:26 web.1  | * Environment: production
04:24:29 web.1  | * Inherited tcp://0.0.0.0:3000
04:24:29 web.1  | * Starting control server on tcp://0.0.0.0:4000
04:24:29 web.1  | Use Ctrl-C to stop
04:24:31 web.1  | * Restarting...
04:24:31 web.1  | Puma starting in single mode...
04:24:31 web.1  | * Version 2.11.1 (ruby 2.2.1-p85), codename: Intrepid Squirrel
04:24:31 web.1  | * Min threads: 0, max threads: 16
04:24:31 web.1  | * Environment: production
04:24:33 web.1  | * Inherited tcp://0.0.0.0:3000
04:24:33 web.1  | * Starting control server on tcp://0.0.0.0:4000
04:24:33 web.1  | Use Ctrl-C to stop

This problem does not occur if I start a bash shell and run the script manually:

$ docker-compose run --rm sikeweb bash
root@e595ada21a58:/# sh /do/restart.sh
[puma] restarting from e595ada21a58
Command restart sent success
^D exit

The restart script (/do/restart.sh):

#!/bin/sh

set -e
cd $RAILS_ROOT
bundle install --deployment > /dev/null
echo "[puma]" restarting from `hostname`
bundle exec pumactl \
  --control-url tcp://sikeweb:$PUMA_CONTROL_PORT \
  --control-token $PUMA_CONTROL_TOKEN \
  restart

[envygeeks]

Pumactl launches in the background, launch Puma manually and wait on the pid.

[hayeah]

@envygeeks puma is already launched in another container. I am using this script to signal to puma to restart

[dan335]

I'm getting this also.

[dnephin]

I've never seen this happen before. Have you specified any restart strategy in the docker-compose.yml?

The output of running from bash seems to be pretty different from the run output. I'm not really sure what I'm looking at.

Could you provide a minimal reproduction of this issue?

[dnephin]

No response from OP

[dreyks]

@dnephin I can confirm this. docker-compose run seems to run twice
Even following the basic rails example at https://docs.docker.com/compose/rails/ and issuing a
$ docker-compose run web rails new . --force --database=postgresql --skip-bundle I get two processes
Produces top output:

26223 username      20   0    9748   1800    540 S   0.0  0.1   0:00.18 docker-compose run web rails new . --force --database=postgresql --skip-bundle
26224 username      20   0  118140  22076   4108 S   0.0  1.1   0:01.16 docker-compose run web rails new . --force --database=postgresql --skip-bundle

with one being the child of another.

Also on my real project, that stores bundle in a mounted volume, each time I invoke any command with run I see double lines of

Creating volume "projectname_bundle" with default driver
Creating volume "projectname_bundle" with default driver

[budioktaviyan]

Guys, anyone here already know how to solved this issue ?

[bow]

Reporting here since I just stumbled on this issue, too. In my case, I'm running docker-compose run with an env of a docker-machine VM running. I'm seeing two lines in my logs that I should only see once.

Here are my docker-* versions:

$ docker -v
Docker version 17.10.0-ce, build f4ffd2511c

$ docker-compose -v
docker-compose version 1.16.1, build unknown

$ docker-machine -v
docker-machine version 0.13.0, build HEAD

I'm resorting to either docker run or docker exec -it /bin/bash now.

[bow]

All right, I think I've managed to isolate this behavior further. The lines here and the next line seem to be the one causing this.

Looking into the definition of pty.start(container) here, I see that it is also starting the container, even after service.start(container) has been started. There is indeed a clause that checks for whether the container has been run in here, but in my case this always evaluates to False so self.client.start is always invoked, resulting in double invocation.

Perhaps there should be an explicit wait check after service.start(container) is invoked?

[callmeed]

Also experiencing this on a docker compose Rails setup. The default Rails/Rake commands are definitely getting run 2x. For example:

docker-compose run app rails db:reset

throws errors (such as "already initialized constant") and output during the seeds loading which indicate this.

Docker version 17.09.0-ce, build afdb6d4

docker-compose version 1.16.1, build 6d1ac21

docker-machine version 0.12.2, build 9371605

[callmeed]

@dnephin is it possible to re-open this issue?

[KitBurgess]

Also having the same problem, docker-compose up spawns two processses, then kills one of them.

The command is:

$ docker-compose --file ./calculation-engine/docker-compose-basekit.yml up --abort-on-container-exit --force-recreate

Then checking the running processes, docker ps shows only a single service

$ docker ps
CONTAINER ID        IMAGE                                                                   COMMAND                  CREATED                  STATUS                  PORTS               NAMES
d8b94dc6e906        my-service:latest   "/app/scripts/publis…"   Less than a second ago   Up Less than a second                       my-service_my-service_1

However ps shows two running processes:

$ ps -ef | grep docker-compose
  501 29410 24958   0 10:37am ttys004    0:00.06 docker-compose --file ./calculation-engine/docker-compose-basekit.yml up --abort-on-container-exit --force-recreate
  501 29411 29410   0 10:37am ttys004    0:00.35 docker-compose --file ./calculation-engine/docker-compose-basekit.yml up --abort-on-container-exit --force-recreate

The service stores logs in an external volume, the two spawned processes both write the first line in the log (hence the duplication), then one of the services stops running, and no more duplicated lines can be seen

2018-05-09 09:30:28.267 [main] INFO  DAOImpl - Using database mydb
2018-05-09 09:30:39.921 [main] INFO  DAOImpl - Using database mydb
2018-05-09 09:30:41.703 [main] INFO  EntityCache - Initializing using archive data at filepath/file.sz

Would appreciate any help, @dnephin - thanks a lot

Versions:

$ docker version
Client:
 Version:      18.03.1-ce
 API version:  1.37
 Go version:   go1.9.5
 Git commit:   9ee9f40
 Built:        Thu Apr 26 07:13:02 2018
 OS/Arch:      darwin/amd64
 Experimental: false
 Orchestrator: swarm

Server:
 Engine:
  Version:      18.03.1-ce
  API version:  1.37 (minimum version 1.12)
  Go version:   go1.9.5
  Git commit:   9ee9f40
  Built:        Thu Apr 26 07:22:38 2018
  OS/Arch:      linux/amd64
  Experimental: true

$ docker-compose version
docker-compose version 1.21.1, build 5a3f1a3
docker-py version: 3.3.0
CPython version: 3.6.4
OpenSSL version: OpenSSL 1.0.2o  27 Mar 2018

[kujon]

Hi,

it would be good to flag it as a bug. This can prevent the service from being able to fully utilise the resources of the host.

[eadwright]

If docker is used to invoke a JVM, specifying minimum heap size with this bug around could cause the a process to fail, if the underlying host exhausts resources due to two processes starting.

[francesco2013]

Hi I am having the same problem ! Why the heck this ticket has been closed ? 1 year no solution .... nice

[demontamer]

Hello..is there a solution yet? Or confirmed bug??

EDIT:
If this behavior is associated with flaskapp try setting run(use_reloader=False)

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[davistardif]

Bump -- still having this issue

[stale[bot]]

This issue has been automatically marked as not stale anymore due to the recent activity.

[ndeloof]

@davistardif Could you please provide a reproduction sample demonstrating this issue ?

[davistardif]

@ndeloof
Here is a sample docker-compose.yml:

version: "2"
services:
  test:
    image: alpine:latest
    stdin_open: true
    tty: true

Run docker-compose run test and then docker-compose ps
I get the following:

           Name              Command    State     Ports
-------------------------------------------------------
temp_test_1                  /bin/sh   Exit 137        
temp_test_run_37c9d999a087   /bin/sh   Up           

Which looks like the container was run twice and the first one was killed (based on this reference)

If it helps, I am running this from ubuntu with
docker-compose version 1.24.1, build 4667896b and Docker version 19.03.3, build a872fc2f86

[ndeloof]

I tried to reproduce with your sample. I ran docker events aside so I can capture any daemon event starting a container

➜  docker events
2019-10-17T09:42:52.560852681+02:00 container create f4aa938f370f2de96f6110d18207b716c22a9e4146bd121fd836ff3d8868caef (com.docker.compose.oneoff=True, com.docker.compose.project=toto, com.docker.compose.service=test, com.docker.compose.slug=28dd22a2aeb55d256dcbe10250cee8a4a5949efce4573ffd3c55049d1165720, com.docker.compose.version=1.24.1, image=alpine:latest, name=toto_test_run_28dd22a2aeb5)
2019-10-17T09:42:52.573863709+02:00 network disconnect c1e3277cb58f7cab1a369d28b5bea28a3173c381d3d0b409bc5bf8d7d61afdc9 (container=f4aa938f370f2de96f6110d18207b716c22a9e4146bd121fd836ff3d8868caef, name=toto_default, type=bridge)
2019-10-17T09:42:52.630915091+02:00 container attach f4aa938f370f2de96f6110d18207b716c22a9e4146bd121fd836ff3d8868caef (com.docker.compose.oneoff=True, com.docker.compose.project=toto, com.docker.compose.service=test, com.docker.compose.slug=28dd22a2aeb55d256dcbe10250cee8a4a5949efce4573ffd3c55049d1165720, com.docker.compose.version=1.24.1, image=alpine:latest, name=toto_test_run_28dd22a2aeb5)
2019-10-17T09:42:52.648885054+02:00 network connect c1e3277cb58f7cab1a369d28b5bea28a3173c381d3d0b409bc5bf8d7d61afdc9 (container=f4aa938f370f2de96f6110d18207b716c22a9e4146bd121fd836ff3d8868caef, name=toto_default, type=bridge)
2019-10-17T09:42:53.205816319+02:00 container start f4aa938f370f2de96f6110d18207b716c22a9e4146bd121fd836ff3d8868caef (com.docker.compose.oneoff=True, com.docker.compose.project=toto, com.docker.compose.service=test, com.docker.compose.slug=28dd22a2aeb55d256dcbe10250cee8a4a5949efce4573ffd3c55049d1165720, com.docker.compose.version=1.24.1, image=alpine:latest, name=toto_test_run_28dd22a2aeb5)
2019-10-17T09:42:53.225516435+02:00 container resize f4aa938f370f2de96f6110d18207b716c22a9e4146bd121fd836ff3d8868caef (com.docker.compose.oneoff=True, com.docker.compose.project=toto, com.docker.compose.service=test, com.docker.compose.slug=28dd22a2aeb55d256dcbe10250cee8a4a5949efce4573ffd3c55049d1165720, com.docker.compose.version=1.24.1, height=24, image=alpine:latest, name=toto_test_run_28dd22a2aeb5, width=80)

I'm running docker-compose version 1.24.1, docker 19.03.3 (same as you) on Linux

Note: exit code 137 means container was stopped after SIGKILL (128+9), so I wonder you maybe had this container running before (by docker-compose up) you ran this test ?

[sym233]

~I have a similar problem.
Docker-compose runs the command twice but stdin only has one log.~

My problem solved, not related to docker compose.

[DonkeyOatie]

I am seeing this on OS X with docker-compose version 1.24.1, build 4667896b

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[stale[bot]]

This issue has been automatically closed because it had not recent activity during the stale period.