Timeout while trying to start dokku-event-listener service using systemd

baobaab commented 4 years ago

Description of problem

Unable to start properly the "dokku-event-listener" systemd service (timeout).

How reproducible

Always

Steps to Reproduce

Check service is not active using

# systemctl is-active dokku-event-listener.service
inactive

Start service

# sudo systemctl start dokku-event-listener.service

Check service is now active

# sudo systemctl is-active dokku-event-listener.service
active

Actual Results

Service "dokku-event-listener" is not active on step 3.

While trying to start service on step 2, a timeout occurs :

$ sudo systemctl start dokku-event-listener.service
Job for dokku-event-listener.service failed because a timeout was exceeded.
See "systemctl status dokku-event-listener.service" and "journalctl -xe" for details.

Here are the corresponding systemd logs in syslog :

Apr  7 07:45:02 c2-7-gra1 systemd[1]: dokku-event-listener.service: Start-pre operation timed out. Terminating.
Apr  7 07:45:02 c2-7-gra1 systemd[1]: dokku-event-listener.service: Failed with result 'timeout'.
Apr  7 07:45:02 c2-7-gra1 systemd[1]: Failed to start dokku-event-listener process.
Apr  7 07:45:02 c2-7-gra1 systemd[1]: dokku-event-listener.service: Unit not needed anymore. Stopping.
Apr  7 07:45:02 c2-7-gra1 systemd[1]: Stopped dokku-event-listener process.

Expected Results

Service "dokku-event-listener" should be running and active after step3.

Environment Information

`dokku report` output

-----> uname: Linux c2-7-gra1 4.15.0-72-generic #81-Ubuntu SMP Tue Nov 26 12:20:02 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux
-----> memory:
                     total        used        free      shared  buff/cache   available
       Mem:           6802         278        1742           0        4781        6259
       Swap:             0           0           0
-----> docker version:
       Client: Docker Engine - Community
        Version:           19.03.8
        API version:       1.40
        Go version:        go1.12.17
        Git commit:        afacb8b7f0
        Built:             Wed Mar 11 01:25:46 2020
        OS/Arch:           linux/amd64
        Experimental:      false

       Server: Docker Engine - Community
        Engine:
         Version:          19.03.8
         API version:      1.40 (minimum version 1.12)
         Go version:       go1.12.17
         Git commit:       afacb8b7f0
         Built:            Wed Mar 11 01:24:19 2020
         OS/Arch:          linux/amd64
         Experimental:     false
        containerd:
         Version:          1.2.13
         GitCommit:        7ad184331fa3e55e52b890ea95e65ba581ae3429
        runc:
         Version:          1.0.0-rc10
         GitCommit:        dc9208a3303feef5b3839f4323d9beb36df0a9dd
        docker-init:
         Version:          0.18.0
         GitCommit:        fec3683
-----> docker daemon info:
       Client:
        Debug Mode: true

       Server:
        Containers: 14
         Running: 2
         Paused: 0
         Stopped: 12
        Images: 15
        Server Version: 19.03.8
        Storage Driver: overlay2
         Backing Filesystem: <unknown>
         Supports d_type: true
         Native Overlay Diff: true
        Logging Driver: json-file
        Cgroup Driver: cgroupfs
        Plugins:
         Volume: local
         Network: bridge host ipvlan macvlan null overlay
         Log: awslogs fluentd gcplogs gelf journald json-file local logentries splunk syslog
        Swarm: inactive
        Runtimes: runc
        Default Runtime: runc
        Init Binary: docker-init
        containerd version: 7ad184331fa3e55e52b890ea95e65ba581ae3429
        runc version: dc9208a3303feef5b3839f4323d9beb36df0a9dd
        init version: fec3683
        Security Options:
         apparmor
         seccomp
          Profile: default
        Kernel Version: 4.15.0-72-generic
        Operating System: Ubuntu 18.04.3 LTS
        OSType: linux
        Architecture: x86_64
        CPUs: 2
        Total Memory: 6.643GiB
        Name: c2-7-gra1
        ID: VZBK:6PE3:Z5AC:GBGP:IMHY:PFXI:U5UN:ISCL:MCZR:OVIG:VY27:4QEV
        Docker Root Dir: /var/lib/docker
        Debug Mode: false
        Registry: https://index.docker.io/v1/
        Labels:
        Experimental: false
        Insecure Registries:
         127.0.0.0/8
        Live Restore Enabled: false

WARNING: No swap limit support
-----> sigil version: 0.5.0
-----> herokuish version:
       herokuish: 0.5.11
       buildpacks:
         heroku-buildpack-multi     v1.0.0
         heroku-buildpack-ruby      v214
         heroku-buildpack-nodejs    v170
         heroku-buildpack-clojure   v84
         heroku-buildpack-python    v167
         heroku-buildpack-java      v66
         heroku-buildpack-gradle    v31
         heroku-buildpack-scala     v87
         heroku-buildpack-play      v26
         heroku-buildpack-php       v173
         heroku-buildpack-go        v139
         buildpack-nginx            v12
-----> dokku version: dokku version 0.20.2
-----> dokku plugins:
       plugn: 0.3.2
         00_dokku-standard    0.20.2 enabled    dokku core standard plugin
         20_events            0.20.2 enabled    dokku core events logging plugin
         app-json             0.20.2 enabled    dokku core app-json plugin
         apps                 0.20.2 enabled    dokku core apps plugin
         builder-dockerfile   0.20.2 enabled    dokku core builder-dockerfile plugin
         builder-herokuish    0.20.2 enabled    dokku core builder-herokuish plugin
         buildpacks           0.20.2 enabled    dokku core buildpacks plugin
         certs                0.20.2 enabled    dokku core certificate management plugin
         checks               0.20.2 enabled    dokku core checks plugin
         common               0.20.2 enabled    dokku core common plugin
         config               0.20.2 enabled    dokku core config plugin
         docker-options       0.20.2 enabled    dokku core docker-options plugin
         domains              0.20.2 enabled    dokku core domains plugin
         enter                0.20.2 enabled    dokku core enter plugin
         git                  0.20.2 enabled    dokku core git plugin
         logs                 0.20.2 enabled    dokku core logs plugin
         network              0.20.2 enabled    dokku core network plugin
         nginx-vhosts         0.20.2 enabled    dokku core nginx-vhosts plugin
         plugin               0.20.2 enabled    dokku core plugin plugin
         proxy                0.20.2 enabled    dokku core proxy plugin
         ps                   0.20.2 enabled    dokku core ps plugin
         repo                 0.20.2 enabled    dokku core repo plugin
         resource             0.20.2 enabled    dokku core resource plugin
         scheduler-docker-local 0.20.2 enabled    dokku core scheduler-docker-local plugin
         shell                0.20.2 enabled    dokku core shell plugin
         ssh-keys             0.20.2 enabled    dokku core ssh-keys plugin
         storage              0.20.2 enabled    dokku core storage plugin
         tags                 0.20.2 enabled    dokku core tags plugin
         tar                  0.20.2 enabled    dokku core tar plugin
         trace                0.20.2 enabled    dokku core trace plugin

How (deb/make/rpm) and where (AWS, VirtualBox, physical, etc.) was Dokku installed?:

Dokku was installed using bootstrap.sh script

josegonzalez commented 4 years ago

Haven't had time to look at this, so not sure what the problem is, but pull requests welcome!

edumag commented 4 years ago

I have the same problem.

Now I am looking for a solution, since this error causes the server to end up saturating.

edumag commented 4 years ago

It seems to have been fixed with:

sudo systemctl stop dokku-event-listener
sudo apt  install golang-go
sudo systemctl start dokku-event-listener

edumag commented 4 years ago

:( It seems that it has not been fixed. Over time it has returned to the same.

Apr 18 17:17:13 vps713357 systemd[1]: dokku-event-listener.service: Service hold-off time over, scheduling restart.
Apr 18 17:17:13 vps713357 systemd[1]: dokku-event-listener.service: Scheduled restart job, restart counter is at 176.
Apr 18 17:17:13 vps713357 systemd[1]: Stopped dokku-event-listener process.
Apr 18 17:17:13 vps713357 systemd[1]: Starting dokku-event-listener process...
Apr 18 17:18:44 vps713357 systemd[1]: dokku-event-listener.service: Start-pre operation timed out. Terminating.
Apr 18 17:18:44 vps713357 systemd[1]: dokku-event-listener.service: Failed with result 'timeout'.
Apr 18 17:18:44 vps713357 systemd[1]: Failed to start dokku-event-listener process.
Apr 18 17:18:54 vps713357 systemd[1]: dokku-event-listener.service: Service hold-off time over, scheduling restart.
Apr 18 17:18:54 vps713357 systemd[1]: dokku-event-listener.service: Scheduled restart job, restart counter is at 177.
Apr 18 17:18:54 vps713357 systemd[1]: Stopped dokku-event-listener process.
Apr 18 17:18:54 vps713357 systemd[1]: Starting dokku-event-listener process...

baobaab commented 4 years ago

The problem is maybe due to this line in dokku-event-listener.service :

ExecStartPre=/usr/bin/dokku-event-listener init

This command hangs forever, since it starts the binary and begins to listen to docker events. But according to systemd.service man page, the ExecStart is not started until the ExecStartPre command exits successfully :

ExecStart= commands are only run after all ExecStartPre= commands that were not prefixed with a "-" exit successfully.

@josegonzalez what is the purpose of this task ?

josegonzalez commented 4 years ago

Version 0.2.0 was released with an updated service file, can folks try it out?

baobaab commented 4 years ago

Hi @josegonzalez,

It's now ok, it starts without any timeout now, thank you!

But I have a question regarding the way the service must be started (I don't know if this is my lack of knowledge on systemd or if this is a real problem).

To start it properly after package upgrade, I had to either :

run sudo systemctl start dokku-event-listener.target
or reboot the server

Running sudo systemctl start dokku-event-listener.service didn't work, because the service was immediately stopped by systemd due to the property StopWhenUnneeded=yes.

Is this the expected behavior ?

josegonzalez commented 4 years ago

Yeah I think so. I don't want to start the target on every upgrade, as a user potentially stopped it on their own, and it would be weird for us to mangle that. Thoughts?

baobaab commented 4 years ago

Yes, the target should not be started on upgrade.

But maybe the StopWhenUnneeded=yes could be removed ? According to this SO answer, the PartOf directive is sufficient to start/stop the service when the target is reached/left. Thus the service could be manually started/stopped using systemctl start dokku-event-listener.service (as expected by a systemd-newbie like me), after the first package install. This is maybe out of this issue scope ?

josegonzalez commented 4 years ago

I would accept a PR for that for sure.

dokku / dokku-event-listener