Mysterious File Permission Error

I am trying to get a service working on Almalinux and keep running into a file permission error. Have already done the same process on several openSuse and Ubuntu-boxes without a hitch. It’s got me completely stumped.

The service is called promtail.service - a service that feeds logs to Loki - and looks like this:

Unit]
Description=Promtail for Loki
After=network.target

[Service]
Type=simple
User=promtail
ExecStart=/usr/local/./promtail-linux-amd64 -config.file /usr/local/promtail-local-config.yaml
Restart=on-abort

[Install]
WantedBy=multi-user.target

I create a user promtail and add permissions to read the logs and also change the owner of a temp-file that promtail uses:

$ sudo adduser --system promtail
$ cd /var
$ var/ sudo setfacl -R -m u:promtail:rX log

$ sudo chown promtail:promtail /tmp/positions.yaml

When I start this with sudo systemctl start promtail.service, I get:
● promtail.service - Promtail for Loki
Loaded: loaded (/etc/systemd/system/promtail.service; enabled; vendor preset: disabled)
Active: failed (Result: exit-code) since Mon 2021-11-08 16:49:42 CET; 6s ago
Process: 3344 ExecStart=/usr/local/./promtail-linux-amd64 -config.file /usr/local/promtail-local-config.yaml
Main PID: 3344 (code=exited, status=203/EXEC)

Nov 08 16:49:42 localhost.localdomain systemd[1]: Started Promtail for Loki.
Nov 08 16:49:42 localhost.localdomain systemd[1]: promtail.service: Main process exited, code=exited, status=203/EXEC
Nov 08 16:49:42 localhost.localdomain systemd[1]: promtail.service: Failed with result ‘exit-code’.

However, if I do the following, the service seems to work:

$ sudo runuser -c "/usr/local/./promtail-linux-amd64 -config.file /usr/local/promtail-local-config.yaml -log.level=debug"
ts=2021-11-08T15:54:38.899568231Z caller=log.go:168 component=discovery level=debug msg="Starting provider" provider=static/0 subs=[router_system]
ts=2021-11-08T15:54:38.904517405Z caller=log.go:168 component=discovery level=debug msg="Discoverer channel closed" provider=static/0
level=info ts=2021-11-08T15:54:38.906055999Z caller=server.go:239 http=[::]:9080 grpc=[::]:42835 msg="server listening on addresses"
level=info ts=2021-11-08T15:54:38.906618772Z caller=main.go:119 msg="Starting Promtail" version="(version=, branch=, revision=)"
level=debug ts=2021-11-08T15:54:43.905387693Z caller=filetargetmanager.go:201 msg="new target" labels="{__address__=\"localhost\"}"
level=info ts=2021-11-08T15:54:43.905675673Z caller=filetargetmanager.go:255 msg="Adding target" key="{job=\"router_varlogs\"}"
level=debug ts=2021-11-08T15:54:43.909442562Z caller=filetarget.go:250 msg="watching new directory" directory=/var/log
level=debug ts=2021-11-08T15:54:43.909572139Z caller=filetarget.go:284 msg="tailing new file" filename=/var/log/lastlog
level=debug ts=2021-11-08T15:54:43.909712405Z caller=filetarget.go:284 msg="tailing new file" filename=/var/log/boot.log
level=debug ts=2021-11-08T15:54:43.909844495Z caller=filetarget.go:284 msg="tailing new file" filename=/var/log/Xorg.9.log
level=debug ts=2021-11-08T15:54:43.909952435Z caller=filetarget.go:284 msg="tailing new file" filename=/var/log/maillog
level=debug ts=2021-11-08T15:54:43.910055574Z caller=filetarget.go:284 msg="tailing new file" filename=/var/log/lynis.log
level=debug ts=2021-11-08T15:54:43.910160889Z caller=filetarget.go:284 msg="tailing new file" filename=/var/log/dnf.librepo.log
level=debug ts=2021-11-08T15:54:43.910297029Z caller=filetarget.go:284 msg="tailing new file" filename=/var/log/almalinux-deploy.debug.log
level=debug ts=2021-11-08T15:54:43.910421094Z caller=filetarget.go:284 msg="tailing new file" filename=/var/log/fail2ban.log
level=debug ts=2021-11-08T15:54:43.910553184Z caller=filetarget.go:284 msg="tailing new file" filename=/var/log/dnf.log
level=debug ts=2021-11-08T15:54:43.910673999Z caller=filetarget.go:284 msg="tailing new file" filename=/var/log/almalinux-deploy.log
level=debug ts=2021-11-08T15:54:43.910801214Z caller=filetarget.go:284 msg="tailing new file" filename=/var/log/kdump.log
level=debug ts=2021-11-08T15:54:43.911036556Z caller=filetarget.go:284 msg="tailing new file" filename=/var/log/hawkey.log
level=debug ts=2021-11-08T15:54:43.911174434Z caller=filetarget.go:284 msg="tailing new file" filename=/var/log/dnf.rpm.log
ts=2021-11-08T15:54:43.911495353Z caller=log.go:124 level=info msg="Seeked /var/log/lastlog - &{Offset:0 Whence:0}"
level=info ts=2021-11-08T15:54:43.913358153Z caller=tailer.go:126 component=tailer msg="tail routine: started" path=/var/log/lastlog
ts=2021-11-08T15:54:43.913584283Z caller=log.go:124 level=info msg="Seeked /var/log/boot.log - &{Offset:11048 Whence:0}"
level=info ts=2021-11-08T15:54:43.91368821Z caller=tailer.go:126 component=tailer msg="tail routine: started" path=/var/log/boot.log
ts=2021-11-08T15:54:43.913774711Z caller=log.go:124 level=info msg="Seeked /var/log/Xorg.9.log - &{Offset:43593 Whence:0}"
level=info ts=2021-11-08T15:54:43.9138458Z caller=tailer.go:126 component=tailer msg="tail routine: started" path=/var/log/Xorg.9.log
ts=2021-11-08T15:54:43.91392929Z caller=log.go:124 level=info msg="Seeked /var/log/maillog - &{Offset:480 Whence:0}"
level=info ts=2021-11-08T15:54:43.914034917Z caller=tailer.go:126 component=tailer msg="tail routine: started" path=/var/log/maillog
ts=2021-11-08T15:54:43.914110531Z caller=log.go:124 level=info msg="Seeked /var/log/lynis.log - &{Offset:375775 Whence:0}"
level=info ts=2021-11-08T15:54:43.91418092Z caller=tailer.go:126 component=tailer msg="tail routine: started" path=/var/log/lynis.log
ts=2021-11-08T15:54:43.914259284Z caller=log.go:124 level=info msg="Seeked /var/log/dnf.librepo.log - &{Offset:822735 Whence:0}"
level=info ts=2021-11-08T15:54:43.914344335Z caller=tailer.go:126 component=tailer msg="tail routine: started" path=/var/log/dnf.librepo.log
ts=2021-11-08T15:54:43.914458775Z caller=log.go:124 level=info msg="Seeked /var/log/almalinux-deploy.debug.log - &{Offset:78405 Whence:0}"
level=info ts=2021-11-08T15:54:43.914575378Z caller=tailer.go:126 component=tailer msg="tail routine: started" path=/var/log/almalinux-deploy.debug.log
ts=2021-11-08T15:54:43.914658217Z caller=log.go:124 level=info msg="Seeked /var/log/fail2ban.log - &{Offset:2185 Whence:0}"
level=info ts=2021-11-08T15:54:43.914738781Z caller=tailer.go:126 component=tailer msg="tail routine: started" path=/var/log/fail2ban.log
ts=2021-11-08T15:54:43.914819395Z caller=log.go:124 level=info msg="Seeked /var/log/dnf.log - &{Offset:270109 Whence:0}"
level=info ts=2021-11-08T15:54:43.914895409Z caller=tailer.go:126 component=tailer msg="tail routine: started" path=/var/log/dnf.log
ts=2021-11-08T15:54:43.914976936Z caller=log.go:124 level=info msg="Seeked /var/log/almalinux-deploy.log - &{Offset:961292 Whence:0}"
level=info ts=2021-11-08T15:54:43.915057587Z caller=tailer.go:126 component=tailer msg="tail routine: started" path=/var/log/almalinux-deploy.log
ts=2021-11-08T15:54:43.915143564Z caller=log.go:124 level=info msg="Seeked /var/log/kdump.log - &{Offset:6124 Whence:0}"
level=info ts=2021-11-08T15:54:43.915229616Z caller=tailer.go:126 component=tailer msg="tail routine: started" path=/var/log/kdump.log
ts=2021-11-08T15:54:43.915312342Z caller=log.go:124 level=info msg="Seeked /var/log/hawkey.log - &{Offset:840 Whence:0}"
level=info ts=2021-11-08T15:54:43.915390106Z caller=tailer.go:126 component=tailer msg="tail routine: started" path=/var/log/hawkey.log
ts=2021-11-08T15:54:43.915499871Z caller=log.go:124 level=info msg="Seeked /var/log/dnf.rpm.log - &{Offset:747315 Whence:0}"
level=info ts=2021-11-08T15:54:43.91557361Z caller=tailer.go:126 component=tailer msg="tail routine: started" path=/var/log/dnf.rpm.log

I am missing something for sure. Help is much appreciated.

For info:

File permissions in /usr/local:

-rwxr-xr-x  1 root root 70802840 ago  6 18:23 promtail-linux-amd64
-rw-r--r--  1 root root      303 nov  8 12:03 promtail-local-config.yaml

The promtail config-file:

server:
  http_listen_port: 9080
  grpc_listen_port: 0

positions:
  filename: /tmp/positions.yaml

clients:
  - url: http://10.0.0.20:3100/loki/api/v1/push

scrape_configs:
- job_name: router_system
  static_configs:
  - targets:
      - localhost
    labels:
      job: router_varlogs
      __path__: "/var/log/*log"

I didn’t have any issues when attempting to replicate this locally. I’d check /var/log/audit/audit.log to see if SELinux is causing your issue.

I’d also double check that and run the command as the promtail user. In your example you are using runuser but don’t pass along a user so it’s running as root.

1 Like

i think that’s systemd/selinux preventing you from running from /usr/local

move you script to somewhere less open, like /usr/bin and i bet it’ll work

1 Like

Completely missed the missing runuser-user :roll_eyes: With promtail as user, I get:

$ sudo runuser promtail -c “/usr/local/bin/./promtail-linux-amd64 -config.file /usr/local/etc/promtail-local-config.yaml -log.level=debug”
level=error ts=2021-11-10T10:12:27.983901278Z caller=main.go:115 msg=“error creating promtail” error=“open /tmp/positions.yaml: permission denied”

Changing the user for the temp-file:
$ sudo chown promtail:promtail /tmp/positions.yaml

That seems to work:
$ sudo runuser promtail -c “/usr/local/bin/./promtail-linux-amd64 -config.file /usr/local/etc/promtail-local-config.yaml -log.level=debug”
ts=2021-11-10T10:12:56.046385355Z caller=log.go:168 component=discovery level=debug msg=“Starting provider” provider=static/0 subs=[router_system]
level=info ts=2021-11-10T10:12:56.050143614Z caller=server.go:239 http=[::]:9080 grpc=[::]:45251 msg=“server listening on addresses”
level=info ts=2021-11-10T10:12:56.050673574Z caller=main.go:119 msg=“Starting Promtail” version="(version=, branch=, revision=)"
ts=2021-11-10T10:12:56.051002718Z caller=log.go:168 component=discovery level=debug msg=“Discoverer channel closed” provider=static/0
level=debug ts=2021-11-10T10:13:01.051719585Z caller=filetargetmanager.go:201 msg=“new target” labels="{address=“localhost”}"
level=info ts=2021-11-10T10:13:01.05198704Z caller=filetargetmanager.go:255 msg=“Adding target” key="{job=“router_varlogs”}"
level=debug ts=2021-11-10T10:13:01.055980066Z caller=filetarget.go:250 msg=“watching new directory” directory=/var/log
level=debug ts=2021-11-10T10:13:01.056117319Z caller=filetarget.go:284 msg=“tailing new file” filename=/var/log/lastlog
level=debug ts=2021-11-10T10:13:01.056308447Z caller=filetarget.go:284 msg=“tailing new file” filename=/var/log/boot.log
level=debug ts=2021-11-10T10:13:01.0564479Z caller=filetarget.go:284 msg=“tailing new file” filename=/var/log/Xorg.9.log
level=debug ts=2021-11-10T10:13:01.056623191Z caller=filetarget.go:284 msg=“tailing new file” filename=/var/log/maillog
level=debug ts=2021-11-10T10:13:01.056771818Z caller=filetarget.go:284 msg=“tailing new file” filename=/var/log/lynis.log
level=debug ts=2021-11-10T10:13:01.056884946Z caller=filetarget.go:284 msg=“tailing new file” filename=/var/log/dnf.librepo.log
level=debug ts=2021-11-10T10:13:01.057036011Z caller=filetarget.go:284 msg=“tailing new file” filename=/var/log/almalinux-deploy.debug.log
level=debug ts=2021-11-10T10:13:01.057161201Z caller=filetarget.go:284 msg=“tailing new file” filename=/var/log/fail2ban.log
level=debug ts=2021-11-10T10:13:01.057275141Z caller=filetarget.go:284 msg=“tailing new file” filename=/var/log/dnf.log
level=debug ts=2021-11-10T10:13:01.057432744Z caller=filetarget.go:284 msg=“tailing new file” filename=/var/log/almalinux-deploy.log
level=debug ts=2021-11-10T10:13:01.057590847Z caller=filetarget.go:284 msg=“tailing new file” filename=/var/log/kdump.log
level=debug ts=2021-11-10T10:13:01.057705574Z caller=filetarget.go:284 msg=“tailing new file” filename=/var/log/hawkey.log
level=debug ts=2021-11-10T10:13:01.057814301Z caller=filetarget.go:284 msg=“tailing new file” filename=/var/log/dnf.rpm.log
ts=2021-11-10T10:13:01.058123632Z caller=log.go:124 level=info msg=“Seeked /var/log/lastlog - &{Offset:0 Whence:0}”
level=info ts=2021-11-10T10:13:01.060114807Z caller=tailer.go:126 component=tailer msg=“tail routine: started” path=/var/log/lastlog

However, it still fails with 203 when trying to run the service. The audit-log:
$ sudo cat /var/log/audit/audit.log | grep promtail
type=AVC msg=audit(1636397108.718:969): avc: denied { execute } for pid=6744 comm="(ux-amd64)" name=“promtail-linux-amd64” dev=“dm-0” ino=33886833 scontext=system_u:system_r:init_t:s0 tcontext=unconfined_u:object_r:user_home_t:s0 tclass=file permissive=0
type=SYSCALL msg=audit(1636397108.718:969): arch=c000003e syscall=59 success=no exit=-13 a0=55a5a399e640 a1=55a5a3a37b70 a2=55a5a3a46620 a3=0 items=0 ppid=1 pid=6744 auid=4294967295 uid=972 gid=967 euid=972 suid=972 fsuid=972 egid=967 sgid=967 fsgid=967 tty=(none) ses=4294967295 comm="(ux-amd64)" exe="/usr/lib/systemd/systemd" subj=system_u:system_r:init_t:s0 key=(null)ARCH=x86_64 SYSCALL=execve AUID=“unset” UID=“promtail” GID=“promtail” EUID=“promtail” SUID=“promtail” FSUID=“promtail” EGID=“promtail” SGID=“promtail” FSGID=“promtail”
type=SERVICE_STOP msg=audit(1636397108.724:970): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=promtail comm=“systemd” exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed’UID=“root” AUID=“unset”
type=SERVICE_START msg=audit(1636397277.857:995): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=promtail comm=“systemd” exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success’UID=“root” AUID=“unset”
type=AVC msg=audit(1636397277.876:996): avc: denied { execute } for pid=6895 comm="(ux-amd64)" name=“promtail-linux-amd64” dev=“dm-0” ino=33886833 scontext=system_u:system_r:init_t:s0 tcontext=unconfined_u:object_r:user_home_t:s0 tclass=file permissive=0

That worked! Moved both the binary and its config-file to /usr/bin, changed the promtail.service-file accordingly, reloaded the daemon (sudo systemctl daemon-reload), restarted the service, and the service is now working. Thanks!

glad it worked, the config file should go in /etc really, not /usr/bin

1 Like