RFI: GitLab CI configuration with Docker

Added gitlab-org/gitlab-ee~113221 label

@MrChrisW I think those problems are mostly GitLab Runner related, so let's pass this to @tmaczukin.

@MrChrisW I see that user uses shell executors. But in the description you're writing about interaction with docker containers which after build is canceled need to by manually kill. Also this build hanging is strange.

Can you get from the user:

an example .gitlab-ci.yml file of a project with those docker-related builds,
an example .gitlab-ci.yml file of a project with those hanging builds (it can be the same as the above one if those are the same builds),
a log file of GitLab Runner's process (as it is - if this will be not enough then we well need to restart runner with --debug to get more data)?

Having this data we can try to investigate what is happening :)

Thank you for your response @tmaczukin I've requested this information from the user. 👍

Attached gitlab-ci.yml gitlab-ci.yml

Configured the debug flag for GitLab runner service on Ubuntu 14.04

/etc/init/gitlab-runner.conf

/usr/bin/gitlab-ci-multi-runner -- -l "debug" "run"

Customer will update when they have log results of a stuck build.

@tmaczukin The user has experienced the hanging issue again. See the syslogs https://drive.google.com/open?id=0B_4wYK1qcPT1UVVLV0JCdEJXbDA

We had a build that had been hanging for 42 hours. I cancelled it on the UI; the docker process continued. I ended with with "docker stop CONTAINER_ID". Relevant logs are attached.

@MrChrisW Did you restart the service after adding -l "debug"? I can't see any debug information in the syslog files. Can we also get log files /var/log/upstart/gitlab-runner.log* from the period when the above problem occurred?

@tmaczukin These were the instructions provided. I've requested those logs.

Please edit the file /etc/init/gitlab-runner.conf

and update the exec line:

Before: /usr/bin/gitlab-ci-multi-runner -- "run"

After: /usr/bin/gitlab-ci-multi-runner -- -l "debug" "run"

Restart the service: sudo gitlab-ci-multi-runner restart

@tmaczukin Additional upstart logs https://drive.google.com/drive/folders/0B_4wYK1qcPT1UVVLV0JCdEJXbDA

@tmaczukin Can we schedule a call with this customer this week? They want quicker resolution.

@dblessing @MrChrisW The issue that they are encountering with canceling builds (that builds are not being canceled) are solved by this: https://gitlab.com/gitlab-org/gitlab-ci-multi-runner/merge_requests/262

This will probably not solve their's:

Our builds will fairly often hang in that they are running, but nothing is happening.

A summary of current state

Environment:

Linux server
Bash shell
GitLab Runner configured to use shell executor

What should happen:

Script is executed by GitLab Runner in context of a shell command call.

It's more complex but for testing we can say that our script:
```
script:
- echo test
- watch -n 1 date
```
is executed by Runner as /bin/bash --login -c "echo test; watch -n 1 date"
Process group is set for the /bin/bash ... command
When abort is triggered (by build timeout or by cancel button in GitLab UI) runner is sending kill -9 to process group (https://gitlab.com/gitlab-org/gitlab-ci-multi-runner/blob/master/executors/shell/executor_shell.go#L57)
The top-level /bin/bash --login -c "..." command should be killed with all it children/related processes

What's the problem:

Command is still working
In logs we can see a lot of Aborting command... entries
Command never ends

Tests

Manual testing

Let's do a manual test in two variants:

Doing kill -9 on a process group (which should be done by Runner)
Doing a normal kill -9 on the first process

`kill -9` on a process group

In one terminal let's execute a command: /bin/bash --login -c "echo test; watch -n 1 date". We should see a date and time string updated each second

In second terminal let's execute a command:

$ ps jx | grep -e watch -e PGID | grep -v grep
 PPID   PID  PGID   SID TTY      TPGID STAT   UID   TIME COMMAND
12374 12456 12456 12374 pts/0    12456 S+    1000   0:00 /bin/bash --login -c echo test; watch -n 1 date
12456 12459 12456 12374 pts/0    12456 S+    1000   0:00 watch -n 1 date

We can see that watch -n 1 date comand has a PID=12459 and a PGID=12456 which is also a PGID and PID of the /bin/bash --login ... command.

Let's execute a command: kill -9 -12456 which should kill whole process group
In the first terminal we should see that the process was terminated

Let's execute a command:

$ ps jx | grep -e watch -e PGID | grep -v grep
PPID   PID  PGID   SID TTY      TPGID STAT   UID   TIME COMMAND

We can see that all commands are terminated.

Normal `kill -9` on the first process

In one terminal let's execute a command: /bin/bash --login -c "echo test; watch -n 1 date". We should see a date and time string updated each second

In second terminal let's execute a command:

$ ps jx | grep -e watch -e PGID | grep -v grep
PPID   PID  PGID   SID TTY      TPGID STAT   UID   TIME COMMAND
12374 13480 13480 12374 pts/0    13480 S+    1000   0:00 /bin/bash --login -c echo test; watch -n 1 date
13480 13483 13480 12374 pts/0    13480 S+    1000   0:00 watch -n 1 date

We can see that watch -n 1 date comand has a PID=13483 and a PGID=13480 which is also a PGID and PID of the /bin/bash --login ... command.

Let's execute a command: kill -9 13480 (notice, that there is no - sign before PID) which should kill the /bin/bash ... process (and which I assume should also kill all children/related processes)
In the first terminal we should see that the process was terminated, but - at least on my computer - I still can see the numbers updated each second on top of the screen!

Let's execute a command:

$ ps jx | grep -e watch -e PGID | grep -v grep
PPID   PID  PGID   SID TTY      TPGID STAT   UID   TIME COMMAND
    1 13483 13480 12374 pts/0    12374 S     1000   0:00 watch -n 1 date

We can see that /bin/bash ... command was terminated, but the watch -n 1 date command still exists! Which can by confirmed by still updated time on my first terminal.

Test using runner

Let's use a simple project with such .gitlab-ci.yml:

test:
  script:
    - echo test
    - watch -n 1 date

Using `exec` command

Let's execute a command in projects directory in first terminal: gitlab-runner exec shell --timeout 240 test We should see a date and time string updated each second

Let's execute a command in second terminal:

$ ps jx | grep -e watch -e "bash --login" -e PGID | grep -v grep
PPID   PID  PGID   SID TTY      TPGID STAT   UID   TIME COMMAND
16315 16340 16340 12374 pts/0    16315 S     1000   0:00 bash --login
16340 16345 16340 12374 pts/0    16315 S     1000   0:00 bash --login
16345 16346 16340 12374 pts/0    16315 S     1000   0:00 watch -n 1 date

Let's execute a command: kill -9 16340 (normal kill)

Let's execute a command:

$ ps jx | grep -e watch -e "bash --login" -e PGID | grep -v grep
PPID   PID  PGID   SID TTY      TPGID STAT   UID   TIME COMMAND
    1 16345 16340 12374 pts/0    16315 S     1000   0:00 bash --login
16345 16346 16340 12374 pts/0    16315 S     1000   0:00 watch -n 1 date

We can see that watch -n 1 date command is still running.

Let's kill those processes (kill -9 16345; kill -9 16346) and repeat all steps, but using process gropu kill (with - just before PGID, eg. kill -9 -16340) in 3-rd step:

$ ps jx | grep -e watch -e "bash --login" -e PGID | grep -v grep
 PPID   PID  PGID   SID TTY      TPGID STAT   UID   TIME COMMAND
17393 17418 17418 12374 pts/0    17393 S     1000   0:00 bash --login
17418 17423 17418 12374 pts/0    17393 S     1000   0:00 bash --login
17423 17424 17418 12374 pts/0    17393 S     1000   0:00 watch -n 1 date

$ kill -9 -17418

$ ps jx | grep -e watch -e "bash --login" -e PGID | grep -v grep
 PPID   PID  PGID   SID TTY      TPGID STAT   UID   TIME COMMAND

All commands were terminated - just like with previous "manual" tests.

Using normal workflow with Runner <-> GitLab communication

For this purpose I've prepared a specific project (https://gitlab.com/tmaczukin/test-processes-kill) and I've registered a runner on my computer.

Let's start the runner with gitlab-runner --debug run --config /path/to/config.toml
Let's trigger a build in GitLab (by git push or manual pipeline start)

Build is started:

Runtime platform                                    arch=amd64 os=linux revision=fae8f18 version=1.4.1
(...)
Checking for builds... received                     build=3657756 repo_url=https://gitlab.com/tmaczukin/test-processes-kill.git runner=375b9fd1
Running with gitlab-ci-multi-runner 1.4.1 (fae8f18)  build=3657756 project=1608547 runner=375b9fd1
Shell configuration: environment: []
dockercommand:
- sh
- -c
- "if [ -x /usr/local/bin/bash ]; then\n\texec /usr/local/bin/bash --login\nelif [
  -x /usr/bin/bash ]; then\n\texec /usr/bin/bash --login\nelif [ -x /bin/bash ]; then\n\texec
  /bin/bash --login\nelif [ -x /usr/local/bin/sh ]; then\n\texec /usr/local/bin/sh
  --login\nelif [ -x /usr/bin/sh ]; then\n\texec /usr/bin/sh --login\nelif [ -x /bin/sh
  ]; then\n\texec /bin/sh --login\nelse\n\techo shell not found\n\texit 1\nfi\n\n"
command: bash
arguments:
- --login
passfile: false
extension: ""
  build=3657756 project=1608547 runner=375b9fd1
Using Shell executor...                             build=3657756 project=1608547 runner=375b9fd1
Waiting for signals...                              build=3657756 project=1608547 runner=375b9fd1
Feeding runners to channel                          builds=1
Submitting build to coordinator... ok               build=3657756 runner=375b9fd1
Appending trace to coordinator... ok                build=3657756 build-log=0-456 build-status=running code=202 runner=375b9fd1 sent-log=0-456 status=202 Accepted

We can see that trace is constantly updated (https://gitlab.com/tmaczukin/test-processes-kill/builds/3657756)

Let's execute a command:

$ ps jx | grep -e watch -e "bash --login" -e PGID | grep -v grep
PPID   PID  PGID   SID TTY      TPGID STAT   UID   TIME COMMAND
17686 17770 17770 17573 pts/3    17686 S     1000   0:00 bash --login
17770 17774 17770 17573 pts/3    17686 S     1000   0:00 bash --login
17774 17775 17770 17573 pts/3    17686 S     1000   0:00 watch -n 1 date

Let's trigger the cancel button:

Appending trace to coordinator... ok                build=3657756 build-log=0-2666 build-status=running code=202 runner=375b9fd1 sent-log=2570-2666 status=202 Accepted
WARNING: Appending trace to coordinator aborted     build=3657756 build-log=0-2738 build-status=canceled code=202 runner=375b9fd1 sent-log=2666-2738 status=202 Accepted
Waiting for build to finish...                      build=3657756 error=canceled project=1608547 runner=375b9fd1
Aborting command...                                 build=3657756 project=1608547 runner=375b9fd1
WARNING: Build failed: canceled                     build=3657756 project=1608547 runner=375b9fd1
WARNING: Submitting build to coordinator... aborted  build=3657756 runner=375b9fd1

Let's execute a command:

$ ps jx | grep -e watch -e "bash --login" -e PGID | grep -v grep
PPID   PID  PGID   SID TTY      TPGID STAT   UID   TIME COMMAND

As we can see, all commands are terminated.

I've repeated this tests for Runner in versions: v1.3.0, v1.4.1, v1.4.2, v1.5.2. Each time all commands were terminated.

Test on production environment

While reproducing this on production environment we've found that while /bin/bash ... script is terminated, a sleep 300 command is still working. We've done the test using cancel button in GitLab UI. Both GitLab and Runner were installed on production infrastructure.

Conclusions

Error seems to be related to environment. Locally I'm using a different operating system that the production environment used for test. It looks that in some way the production OS is not doing a "process group" kill but it's killing only the main process.

I'll try to repeat the runner-based test with a configuration similar to the production one.
After finding the cause of not-doing process group kill by the Runner on production environment we should consider if we can handle this in Runner itself or if we should update the documentation and describe required configuration of the OS.

/cc @dblessing @MrChrisW @ayufan

Reassigned to @MrChrisW

Assignee removed

An update for above tests and debugging session:

After @ayufan's suggestions I've made a test with a Runner executed as a system service. In such configuration Runner is mostly running with a root UID, but it uses another UID (eg. gitlab-runner) to execute build scripts.

Test

Let's repeat the Using normal workflow with Runner <-> GitLab communication test but with Runner executed as a system service instead of gitlab-runner run ... command. In such test - after git push - we should see an output:

$ ps ax -o "%p %r %u %a" | grep -e gitlab-ci-multi -e "bash --login" -e sleep -e PGID | grep -v -e grep -e ps
  PID  PGID RUSER    COMMAND
 2614  2614 root     /usr/bin/gitlab-ci-multi-runner run --working-directory /home/gitlab-runner --config /etc/gitlab-runner/config.toml --service gitlab-runner --syslog --user gitlab-runner
 4236  4236 root     su -s /bin/bash gitlab-runner -c bash --login
 4237  4237 gitlab-+ bash --login
 4241  4237 gitlab-+ bash --login
 4242  4237 gitlab-+ sleep 300

After using the cancel button we should see that the su -s ... command is terminated, but bash --login and sleep 300 commands are still runing:

$ ps ax -o "%p %r %u %a" | grep -e gitlab-ci-multi -e "bash --login" -e sleep -e PGID | grep -v -e grep -e ps
  PID  PGID RUSER    COMMAND
 2614  2614 root     /usr/bin/gitlab-ci-multi-runner run --working-directory /home/gitlab-runner --config /etc/gitlab-runner/config.toml --service gitlab-runner --syslog --user gitlab-runner
 4237  4237 gitlab-+ bash --login
 4241  4237 gitlab-+ bash --login
 4242  4237 gitlab-+ sleep 300

What happened?

Runner, when configured to execute builds as other UID than used for Runner execution itself, is using su command to change user rights. As we can see in first ps ... output, su ...'s PGID is different than bash --login's PGID:

 4236  4236 root     su -s /bin/bash gitlab-runner -c bash --login
 4237  4237 gitlab-+ bash --login

When Runner is triggered to abort build (by a timeout or by a cancel button from GitLab's UI) it sends a SIGKILL signal to the process PGID. In previous tests when Runner was executed as gitlab-runner run without setting a different UID for build scripts, then bash --login command had the same PGID as a script executed in this shell. But when su ... was used to change UID of build executed by Runner as a system service, then Runner sent a SIGKILL signal to the su ...'s command PGID leaving rest of the command tree.

I've reproduced this on two different linux distributions so this isn't environment related bug as I thought earlier.

Conclusions

The problem exists because su ... command doesn't have the same PGID as shell and build script executed through this su ... command.

What we could do to fix this? Currently I see two options:

Try to find a PID of su ...'s command children and then send SIGKILL to su ...'s PID, and children's PGID.
Send a SIGTERMor SIGINT signal to su ... command. This will allow su to send the same signal to all children process groups before finishing itself.

Fix 2. is easier to implement, but it may not work if build process will catch the SIGTERM/SIGINT signal and handle it in different way than terminating the process. Fix 1. would kill all processes but it's harder to implement.

We could also try to mix both solutions: try to send SIGTERM/SIGINT to su ... command, wait a moment and if process is not terminated than find all children and send SIGKILL to all PGIDs.

@ayufan What do you think about this?

Also since this is clearly a Runner's problem let's move this discussion to Runner's project :)

Moved from gitlab-org/gitlab-ee#760

Added ~58730 label

Milestone changed to %v1.6

After a call with @ayufan we've decided to use a mixed solution:

Send a SIGTERM to the main process' process group.
Wait few seconds to check if process was terminated.
If process wasn't terminated - send a SIGKILL to the main process' process group.

This should be enough in most of user cases.

This may also be reported in https://gitlab.zendesk.com/agent/tickets/31795.

mentioned in issue #1363 (closed)

mentioned in issue #1665 (closed)

mentioned in issue #1675 (closed)

Reassigned to @tmaczukin

Mentioned in merge request !336

@dblessing The fix is ready (but not reviewed nor merged yet). Can we ask customers to test this version? It can be downloaded from links in this MR: !336.

Thanks @tmaczukin 👍 I've updated the customer in https://gitlab.zendesk.com/agent/tickets/29146 and requested they test. I'll report back.

~~I think I may be seeing this issue.~~

EDIT: Ignore that. I've updated the runner to the latest version and it appears fine. I may have been seeing something else.

Latest version still has the issue. Haven't tested the ones in !336, since it's a 2 month old build and 1.8.1 has lots of other fixes in it as well.

Think I'm hitting this issue -- I have a shell executor that is running a docker run command, and I had a container hanging around that the runner failed to terminate. Manually running docker rm -f on the container unstuck the runner.

Does that sounds like this issue (in which case I'll follow here waiting for a resolution), or should I open another issue to track? Thanks.

(Note this is with runner version Version: 1.8.1)

@paul.tiplady There was an issue with docker 1.12.4 - See https://gitlab.com/gitlab-org/gitlab-ci-multi-runner/issues/1962. Can you check the version of Docker you're using?

I'm also hitting this issue. I'm using shell executor and it's running docker-compose. When a build is cancelled via the GitLab web interface, the build still continues running on the CI server.

Package versions:

gitlab-ci-multi-runner 1.8.1
docker 1.12.5
docker-compose 1.9.0

Docker version 1.12.3, build 6b644ec

Full version output:

 docker version
Client:
 Version:      1.12.3
 API version:  1.24
 Go version:   go1.6.3
 Git commit:   6b644ec
 Built:        Wed Oct 26 21:39:14 2016
 OS/Arch:      linux/amd64

Server:
 Version:      1.12.3
 API version:  1.24
 Go version:   go1.6.3
 Git commit:   6b644ec
 Built:        Wed Oct 26 21:39:14 2016
 OS/Arch:      linux/amd64

Edited to add Gitlab-runner version:

$ gitlab-runner --version
Version:      1.8.1
Git revision: a2efdd4
Git branch:   1-8-stable
GO version:   go1.7.3
Built:        Tue, 29 Nov 2016 13:53:55 +0000
OS/Arch:      linux/amd64

@MrChrisW sounds like maybe the docker 1.12.4 issue (think the docker bug is https://github.com/docker/docker/issues/29421) might not be the whole story here, if we're seeing problems on docker 1.12.3 and 1.12.5 as well?

Thanks for the information @paul.tiplady @akheron - @tmaczukin Any ideas? Is this a similar problem or do we need a new issue?

changed milestone to %v1.10

Another customer report https://gitlab.zendesk.com/agent/tickets/55987

gitlab-ci-multi-runner 1.9.1
docker 1.12.5
docker-compose 1.9.0

Same issue. I'm using shell executor and it's running docker-compose.When a build is cancelled via the GitLab web interface, the new build will be pending always. I need to run gitlab-runner restart int the server, and then the build will run correct.

Would the use of gosu instead of su help here?

@cliffwoolley While we can assume, that su will be present on almost every *nix system, gosu is another requirement that need to be installed on a host to make Runner working. We already have some and I would like to avoid any other if they are not 100% necessary. If we need to replace su with something else I prefer to implement this inside of the Runner since it should not be hard to do (and that's what !336 is doing).

@cliffwoolley However thanks for mentioning gosu. Even if I don't like the idea of rely on it, the idea of using github.com/opencontainers/runc/libcontainer/user (used there) instead of own, regexp-based solution may be worth to consider. I will look on this :)

@tmaczukin There's also su-exec, which is tiny and would be easy to incorporate as a submodule...

I think this RFI is incorrectly tied to Docker. I think I have the same problem, but it's any script that wouldn't be killed.

I'm not sure I understand what the plan is from the notes above

Same issue here. Occasionally when we are merging a bunch of MR's to master, a whole bunch of pipelines start at the same time. Not wanting all of these pipelines to run, we cancel a few but the jobs still persist on the runners, slowing things down.

It seems that if there is a long-running process underway in the script (building a nodeJS app or compiling an android app, one single command), the process is not killed. Any other commands in the script or any jobs scheduled to be run after the current job are cancelled, it's just that the current process(es) that are not killed. Is this by design?

Is this still not fixed? This is a huge issue for us, and it's depressing there's been no progress in months. It really makes git's pipelines unusable for critical deployments.

I just hit the same issue. Runner 1.11.1, Docker version 1.29 (17.05.0-ce)

Is there any workaround except restarting gitlab-runner or executing docerk rm -f ID for stuck containers?

mentioned in issue #2682

RFI: GitLab CI configuration with Docker

Overview

Designs

Child items 0

Activity

Tests

Manual testing

`kill -9` on a process group

Normal `kill -9` on the first process

Test using runner

Using `exec` command

Using normal workflow with Runner <-> GitLab communication

Test on production environment

Conclusions

Test

What happened?

Conclusions

Admin message

Admin message

RFI: GitLab CI configuration with Docker

Overview

Activity

Tests

Manual testing

kill -9 on a process group

Normal kill -9 on the first process

Test using runner

Using exec command

Using normal workflow with Runner <-> GitLab communication

Test on production environment

Conclusions

Test

What happened?

Conclusions

`kill -9` on a process group

Normal `kill -9` on the first process

Using `exec` command