Sourcing top-level config files fails if files are not readable

[lucasm-iRonin]

Description of problem:

I have encountered a really weird problem. I've noticed it when I was configuring ACL plugin. It turned out the ACL is not respect the commands correctly. I wanted to turned on trace but it don't work for me.

When I enable tracing (via dokku trace on) and try to run the command over SSH or git push it simply does not show any additional output.

If I ssh to the server and run (as dokku user): dokku --trace apps I can see the trace. Any additional way to track this issue? I'm running out of ideas.

I tried to check the events log (tail -f /var/log/dokku/events.log) but they are not being refreshed - they are updated only when I restart the VPS.

Here is dokku report ouput:

-----> uname: Linux vps486675 4.4.0-109-generic #132-Ubuntu SMP Tue Jan 9 19:52:39 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux
-----> memory:
              total        used        free      shared  buff/cache   available
Mem:           7793        1379        3440          47        2974        6005
Swap:          2047           0        2047
-----> docker version:
Client:
 Version:       18.01.0-ce
 API version:   1.35
 Go version:    go1.9.2
 Git commit:    03596f5
 Built: Wed Jan 10 20:11:05 2018
 OS/Arch:       linux/amd64
 Experimental:  false
 Orchestrator:  swarm

Server:
 Engine:
  Version:      18.01.0-ce
  API version:  1.35 (minimum version 1.12)
  Go version:   go1.9.2
  Git commit:   03596f5
  Built:        Wed Jan 10 20:09:37 2018
  OS/Arch:      linux/amd64
  Experimental: false
-----> docker daemon info:
Containers: 40
 Running: 12
 Paused: 0
 Stopped: 28
Images: 127
Server Version: 18.01.0-ce
Storage Driver: overlay2
 Backing Filesystem: extfs
 Supports d_type: true
 Native Overlay Diff: true
Logging Driver: json-file
Cgroup Driver: cgroupfs
Plugins:
 Volume: local
 Network: bridge host macvlan null overlay
 Log: awslogs fluentd gcplogs gelf journald json-file logentries splunk syslog
Swarm: inactive
Runtimes: runc
Default Runtime: runc
Init Binary: docker-init
containerd version: 89623f28b87a6004d4b785663257362d1658a729
runc version: b2567b37d7b75eb4cf325b77297b140ea686ce8f
init version: 949e6fa
Security Options:
 apparmor
 seccomp
  Profile: default
Kernel Version: 4.4.0-109-generic
Operating System: Ubuntu 16.04.3 LTS
OSType: linux
Architecture: x86_64
CPUs: 2
Total Memory: 7.611GiB
Name: vps486675
ID: QSOV:Y42G:WBED:ZJYK:I3E5:YBAQ:FRO4:JIEH:EFN6:LSXP:QQUL:MOCI
Docker Root Dir: /var/lib/docker
Debug Mode (client): true
Debug Mode (server): 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.4.0
-----> herokuish version:
herokuish: 0.3.33
buildpacks:
  heroku-buildpack-multi     v1.0.0
  heroku-buildpack-ruby      v170
  heroku-buildpack-nodejs    v111
  heroku-buildpack-clojure   v77
  heroku-buildpack-python    v120
  heroku-buildpack-java      v57
  heroku-buildpack-gradle    v24
  heroku-buildpack-scala     v79
  heroku-buildpack-play      v26
  heroku-buildpack-php       v126
  heroku-buildpack-go        v78
  heroku-buildpack-erlang    fa17af9
  buildpack-nginx            v8
-----> dokku version: 0.11.3
-----> dokku plugins:
plugn: 0.3.0
  00_dokku-standard    0.11.3 enabled    dokku core standard plugin
  20_events            0.11.3 enabled    dokku core events logging plugin
  acl                  1.0.1 enabled    dokku plugin that can be used to restrict push privileges for app to certain users
  app-predeploy-tasks  0.1.0 enabled    Run arbitrary app tasks prior to dokku's deploy phase
  apps                 0.11.3 enabled    dokku core apps plugin
  build-env            0.11.3 enabled    dokku core build-env plugin
  certs                0.11.3 enabled    dokku core certificate management plugin
  checks               0.11.3 enabled    dokku core checks plugin
  common               0.11.3 enabled    dokku core common plugin
  config               0.11.3 enabled    dokku core config plugin
  deployment-keys      0.2.0 enabled    Manage SSH deployment keys that should get injected into your containers on-build
  docker-options       0.11.3 enabled    dokku core docker-options plugin
  domains              0.11.3 enabled    dokku core domains plugin
  enter                0.11.3 enabled    dokku core enter plugin
  git                  0.11.3 enabled    dokku core git plugin
  logs                 0.11.3 enabled    dokku core logs plugin
  mysql                1.0.0 enabled    dokku mysql service plugin
  named-containers     0.11.3 enabled    dokku core named containers plugin
  network              0.11.3 enabled    dokku core network plugin
  nginx-vhosts         0.11.3 enabled    dokku core nginx-vhosts plugin
  plugin               0.11.3 enabled    dokku core plugin plugin
  postgres             1.0.0 enabled    dokku postgres service plugin
  proxy                0.11.3 enabled    dokku core proxy plugin
  ps                   0.11.3 enabled    dokku core ps plugin
  redirect             0.5.0 enabled    Simple redirects for apps
  redis                1.0.0 enabled    dokku redis service plugin
  repo                 0.11.3 enabled    dokku core repo plugin
  shell                0.11.3 enabled    dokku core shell plugin
  ssh-keys             0.11.3 enabled    dokku core ssh-keys plugin
  storage              0.11.3 enabled    dokku core storage plugin
  tags                 0.11.3 enabled    dokku core tags plugin
  tar                  0.11.3 enabled    dokku core tar plugin

Environment details (AWS, VirtualBox, physical, etc.): OVH VPS

How was Dokku installed?: via apt-get

Steps to Reproduce: dokku trace on

Actual Results: no additional output

Expected Results: additional output displayed

[lucasm-iRonin]

Syslog during push with ACL (remote: User x does not have permissions to modify this repository...):

Jan 16 11:22:11 vps486675 systemd[1]: Created slice User Slice of dokku.
Jan 16 11:22:11 vps486675 systemd[1]: Starting User Manager for UID 1004...
Jan 16 11:22:11 vps486675 systemd[1]: Started Session 21 of user dokku.
Jan 16 11:22:11 vps486675 systemd[24493]: Reached target Timers.
Jan 16 11:22:11 vps486675 systemd[24493]: Reached target Sockets.
Jan 16 11:22:11 vps486675 systemd[24493]: Reached target Paths.
Jan 16 11:22:11 vps486675 systemd[24493]: Reached target Basic System.
Jan 16 11:22:11 vps486675 systemd[24493]: Reached target Default.
Jan 16 11:22:11 vps486675 systemd[24493]: Startup finished in 18ms.
Jan 16 11:22:11 vps486675 systemd[1]: Started User Manager for UID 1004.
Jan 16 11:22:13 vps486675 systemd[1]: Stopping User Manager for UID 1004...
Jan 16 11:22:13 vps486675 systemd[24493]: Stopped target Default.
Jan 16 11:22:13 vps486675 systemd[24493]: Stopped target Basic System.
Jan 16 11:22:13 vps486675 systemd[24493]: Stopped target Paths.
Jan 16 11:22:13 vps486675 systemd[24493]: Stopped target Sockets.
Jan 16 11:22:13 vps486675 systemd[24493]: Stopped target Timers.
Jan 16 11:22:13 vps486675 systemd[24493]: Reached target Shutdown.
Jan 16 11:22:13 vps486675 systemd[24493]: Starting Exit the Session...
Jan 16 11:22:13 vps486675 systemd[24493]: Received SIGRTMIN+24 from PID 26198 (kill).
Jan 16 11:22:13 vps486675 systemd[1]: Stopped User Manager for UID 1004.
Jan 16 11:22:13 vps486675 systemd[1]: Removed slice User Slice of dokku.

[josegonzalez]

As the ACL plugin is not official, you'll need to file an issue in it's issue tracker. Sorry.

[lucasm-iRonin]

@josegonzalez tracing is not working at all (please read carefully once again). I was just giving you the context (about the ACL).

[josegonzalez]

Ah gotcha. What happens when you disable the plugin, so you get output?

With that plugin enabled, does it just exit immediately?

You can turn on the events log (on a phone so can't link you but it's on your docs site) to see what plugin triggers are hit during a run, which may be able to yield more details.

[lucasm-iRonin]

Ah gotcha. What happens when you disable the plugin, so you get output?

Unfortunately, I still don't get the output when during i.e. git push when I disable ACL plugin (I think this problem is not related to the plugin) because even dokku events -t displays only a single line (disabling acl plugin INVOKED: user-auth( root default plugin:disable acl ) NAME= FINGERPRINT=). During git push or other command (i.e. ssh dokku@dokku config some-app it does not display any new line.

Also enabling events looks weird (check this output):

~$ dokku events:on
Enabling dokku events logger
~$ dokku events:list
 !     Events logger disabled

So it looks like the logger has been enabled but then the list command says it's disabled.

I've been using Dokku for more than year but I've never encountered such issue (especially apps and databases are running fine).

PS. Dokku has been installed and upgraded via apt-get.

[lucasm-iRonin]

Also when I disable plugin (dokku plugin:disable xyz) I see a trace. However for other commands (i.e. dokku apps) I don't.

[josegonzalez]

Did this suddenly start happening or did you change anything about your system?

I might have to ask you to hop on our slack channel for interactive debugging later (getting on a flight now) as this is an... Odd issue to say the least.

[lucasm-iRonin]

@josegonzalez thanks. I will try to catch you on Slack when you are available (btw. have a safe landing!).

I upgraded dokku and docker a week ago but I haven't noticed any issues (everything is working fine - push, deployment, redis, mysql, postgres, etc.). Today I was configuring the ACL plugin and noticed that something is wrong (tracing, logging, etc.).

[lucasm-iRonin]

@josegonzalez I was able to track the issue - there was a problem with permissions on the .dokkurc folder.

Check how they looked like (as dokku user I was able to get into the folder but I wasn't able to read the files - i.e. ls didn't work):

d-wxr-x--T  2 dokku dokku  4096 Jan 17 13:53 .dokkurc

I've updated them to:

drwxr-xr-x  2 dokku dokku  4096 Jan 17 14:03 .dokkurc

and inside .dokkurc I've updated to:

-rw-r--r--  1 dokku dokku  165 Jan 16 10:35 acl
-rw-rw-r--  1 dokku dokku   22 Jan 16 12:39 DOKKU_EVENTS

@josegonzalez could you confirm if permissions are correct now? Everything seems to be working fine.

I suspect upgrade must have corrupted the permissions. Maybe it would be good to check permissions when running dokku commands and show info to the user? WDYT?

[josegonzalez]

Our upgrade doesn't change permissions, though we should check if the file(s) are readable. Good catch!

[lucasm-iRonin]

@josegonzalez you are right - it wasn't caused by an upgrade but typo in one of our Ansible playbooks. I'm sorry about incorrect info.

Anyway, it would be good to check those permissions to avoid such debugging in the future :).

[josegonzalez]

Closing as there is a pull request available.