Bug 85255

Created attachment 121009 [details]
aptget.strace open dev null permission denied

I'm having a similar problem. The user under which I run Kodi (nee XMBC) is aktau.

To be honest, I'm not sure why this started happening since today (13/01/2016), I'm running Debian Jessie. I noticed strange things where going on when OpenVPN wouldn't start anymore, complaining about permissions issues (which it shouldn't have). Then, even running "sudo apt-get update" would fail.

$ sudo apt-get update
Hit:1 http://security.debian.org stretch/updates InRelease
0% [1 InRelease gpgv 62.8 kB] [Connecting to dl.google.com (216.58.213.238)] [Connecting to archive.zfsonlinux.org (54.231.112.144)]dpkg: warning: failed to open configuration file '/root/.dpkg.cfg' for reading: Permission denied
dpkg: warning: failed to open configuration file '/root/.dpkg.cfg' for reading: Permission denied
dpkg: warning: failed to open configuration file '/root/.dpkg.cfg' for reading: Permission denied
dpkg: warning: failed to open configuration file '/root/.dpkg.cfg' for reading: Permission denied
dpkg: warning: failed to open configuration file '/root/.dpkg.cfg' for reading: Permission denied
dpkg: warning: failed to open configuration file '/root/.dpkg.cfg' for reading: Permission denied

I strace'd the child processes, because at first I thought it was doing some very strange Linux capabilities magic and erroneously dropping its privileges. However, I didn't see that. I noticed that it got really weird permissions denied errors even when I saw no user juggling. To wit:

➜  ~  ls -l /dev/null
crw--w---- 1 aktau root 1, 3 Jan 13 23:43 /dev/null
➜  ~  grep -n '/dev/null' aptget.strace
134:3052  open("/dev/null", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
227:3053  open("/dev/null", O_RDONLY)       = 7
3297:3058  open("/dev/null", O_RDWR)         = -1 EACCES (Permission denied)
3764:3056  open("/dev/null", O_RDWR <unfinished ...>
6288:3062  open("/dev/null", O_WRONLY)       = -1 EACCES (Permission denied)
6515:3065  open("/dev/null", O_WRONLY|O_CREAT|O_TRUNC, 0666) = -1 EACCES (Permission denied)
6583:3066  open("/dev/null", O_RDONLY)       = -1 EACCES (Permission denied)
7092:3067  open("/dev/null", O_WRONLY|O_CREAT|O_TRUNC, 0666) = -1 EACCES (Permission denied)
7161:3068  open("/dev/null", O_RDONLY)       = -1 EACCES (Permission denied)
7437:3069  open("/dev/null", O_WRONLY|O_CREAT|O_TRUNC, 0666 <unfinished ...>
7633:3070  open("/dev/null", O_RDONLY)       = -1 EACCES (Permission denied)
7909:3071  open("/dev/null", O_WRONLY|O_CREAT|O_TRUNC, 0666) = -1 EACCES (Permission denied)
7977:3072  open("/dev/null", O_RDONLY)       = -1 EACCES (Permission denied)
8803:3073  open("/dev/null", O_WRONLY|O_CREAT|O_TRUNC, 0666 <unfinished ...>
9114:3074  open("/dev/null", O_RDONLY <unfinished ...>
9412:3075  open("/dev/null", O_WRONLY|O_CREAT|O_TRUNC, 0666) = -1 EACCES (Permission denied)
9482:3076  open("/dev/null", O_RDONLY)       = -1 EACCES (Permission denied)
9764:3077  open("/dev/null", O_WRONLY|O_CREAT|O_TRUNC, 0666) = -1 EACCES (Permission denied)
9841:3078  open("/dev/null", O_RDONLY)       = -1 EACCES (Permission denied)
10443:3084  open("/dev/null", O_WRONLY|O_CREAT|O_TRUNC, 0666) = -1 EACCES (Permission denied)
10511:3085  open("/dev/null", O_RDONLY)       = -1 EACCES (Permission denied)
10654:3063  open("/dev/null", O_WRONLY|O_CREAT|O_TRUNC, 0666) = -1 EACCES (Permission denied)
10656:3063  write(2, "cannot create /dev/null: Permiss"..., 42) = 42
11684:3096  open("/dev/null", O_WRONLY)       = -1 EACCES (Permission denied)
11912:3099  open("/dev/null", O_WRONLY|O_CREAT|O_TRUNC, 0666) = -1 EACCES (Permission denied)
11981:3100  open("/dev/null", O_RDONLY)       = -1 EACCES (Permission denied)
12257:3101  open("/dev/null", O_WRONLY|O_CREAT|O_TRUNC, 0666) = -1 EACCES (Permission denied)
12325:3102  open("/dev/null", O_RDONLY)       = -1 EACCES (Permission denied)
12601:3103  open("/dev/null", O_WRONLY|O_CREAT|O_TRUNC, 0666) = -1 EACCES (Permission denied)
12670:3104  open("/dev/null", O_RDONLY)       = -1 EACCES (Permission denied)

Sometimes it does seem to work, positively weird. I first discovered this because I was tracing the way it tried to open /root/.dpkg.cfg, which shows a similar pattern (first EEXIST, then EACCESS). Full strace output is attached to this post.

Then, I decided to restore the permissions: chmod 0666 /dev/null && chown root:root /dev/null. After that, OpenVPN worked again, apt-get update too, et cetera. So on one hand I'm fairly happy that I know how to fix it. On the other hand I find this really strange. Why whould different permissions on /dev/null cause all these weird errors?

Also, why did systemd suddenly start to do this? All I remember adding yesterday is that ExecStartPost line. This is of course a program that starts and stops immediately, but even before adding the ExecStartPost, starting/stopping the service didn't mess up the system this way (at least, I think, I should verify).

$ systemctl cat kodi.service
# /etc/systemd/system/kodi.service
[Unit]
Description = Kodi Media Center
After = systemd-user-sessions.service network.target sound.target \
  syslog.target avahi-daemon.service
Wants = avahi-daemon.service

[Service]
User = aktau
Group = aktau
Type = simple
ExecStart = /usr/bin/xinit /usr/bin/dbus-launch --exit-with-session /usr/bin/kodi-standalone -- :0 vt7 -keeptty -nolisten tcp -noreset
ExecStartPost = -/usr/bin/xset -display :0 -dpms s off
Restart = on-abort
RestartSec = 5
StandardInput = tty
TTYPath = /dev/tty7
# PAMName interacts badly with ExecStartPost. Apparently systemd tries to #
# create a session for every Exec*... The same one. Luckily, everything
# appears to work
PAMName = login

[Install]
WantedBy = multi-user.target

$ systemctl status kodi.service
● kodi.service - Kodi Media Center
   Loaded: loaded (/etc/systemd/system/kodi.service; enabled; vendor preset: enabled)
   Active: active (running) since Wed 2016-01-13 23:43:58 CET; 3min 10s ago
  Process: 742 ExecStartPost=/usr/bin/xset -display :0 -dpms s off (code=exited, status=0/SUCCESS)
 Main PID: 741 (xinit)
   CGroup: /system.slice/kodi.service
           ‣ 741 /usr/bin/xinit /usr/bin/dbus-launch --exit-with-session /usr/bin/kodi-standalone -- :0 vt7 -keeptty -nolisten tcp -noreset

I can confirm that removing the ExecStartPost line fixes my problems. So it appears that this problem is more general than the title would suggest.

I change the version in which this bug is present, so I'm raising the importance to "high" so that the developers will be aware that this bug is still present after two years (if it is, indeed, a bug), please change it back if this is not correct.

To confirm, it is present in systemd 228, which is the current preview release.

Should finally be fixed with 

https://github.com/systemd/systemd/pull/3457