[systemd-devel] Systemd weird behavior after upgrade

Discussion:

arnaud gaboury

2017-07-13 12:27:29 UTC

OS= Fedora 26
Linux container managed by machinectl

% systemctl --version
systemd 233
+PAM -AUDIT -SELINUX -IMA -APPARMOR +SMACK -SYSVINIT +UTMP +LIBCRYPTSETUP
+GCRYPT +GNUTLS +ACL +XZ +LZ4 -SECCOMP +BLKID +ELFUTILS +KMOD +IDN
default-hierarchy=hybrid

% machinectl list
MACHINE CLASS SERVICE OS VERSION ADDRESSES
poppy container systemd-nspawn fedora 26 192.168.1.94...

% machinectl show poppy
Name=poppy
Id=59b720b533834a4eafe07a62c2482266
Timestamp=Wed 2017-07-12 22:07:15 CEST
TimestampMonotonic=6928076
Service=systemd-nspawn
Unit=systemd-***@poppy.service
Leader=648
Class=container
RootDirectory=/var/lib/machines/poppy
State=running

-----------------------------------------------------------------------------------------------------

After upgrade from Fedora 25 to 26, some services are broken.
Below are some broken service status

% systemctl status ***@1000.service
â ***@1000.service - User Manager for UID 1000
Loaded: loaded (/usr/lib/systemd/system/***@.service; static; vendor
preset: disabled)
Active: failed (Result: protocol) since Wed 2017-07-12 22:09:45 CEST;
15h ago
Main PID: 257 (code=exited, status=237/KEYRING)

Jul 12 22:09:45 thetradinghall.com systemd[1]: Starting User Manager for
UID 1000...
Jul 12 22:09:45 thetradinghall.com systemd[257]: ***@1000.service: Failed
at step KEYRING spawning /usr/lib/systemd/systemd: Permission denied
Jul 12 22:09:45 thetradinghall.com systemd[1]: Failed to start User Manager
for UID 1000.
Jul 12 22:09:45 thetradinghall.com systemd[1]: ***@1000.service: Unit
entered failed state.
Jul 12 22:09:45 thetradinghall.com systemd[1]: ***@1000.service: Failed
with result 'protocol'.

% systemctl status user.slice
â user.slice - User and Session Slice
Loaded: loaded (/usr/lib/systemd/system/user.slice; static; vendor
preset: disabled)
Active: active since Wed 2017-07-12 22:07:15 CEST; 15h ago
Docs: man:systemd.special(7)
CGroup: /user.slice
ââuser-1000.slice
ââsession-c1.scope
â ââ 256 login -- poisonivy
â ââ 258 -zsh
â ââ 356 su
â ââ 357 zsh
â ââ1553 systemctl status user.slice
â ââ1554 less
ââsession-c2.scope
ââ449 login -- poisonivy
ââ450 -zsh
ââ494 su
ââ495 zsh
ââ526 /usr/bin/python3 -O /usr/bin/ranger

Jul 12 22:09:45 thetradinghall.com systemd[1]: user.slice: Failed to set
invocation ID on control group /user.slice, ignoring: Operation not
permitted

% systemctl status opendkim.service
â opendkim.service - DomainKeys Identified Mail (DKIM) Milter
Loaded: loaded (/usr/lib/systemd/system/opendkim.service; enabled;
vendor preset: disabled)
Drop-In: /etc/systemd/system/opendkim.service.d
ââoverride.conf
Active: failed (Result: exit-code) since Thu 2017-07-13 11:33:25 CEST;
2h 30min ago
Docs: man:opendkim(8)
man:opendkim.conf(5)
man:opendkim-genkey(8)
man:opendkim-genzone(8)
man:opendkim-testadsp(8)
man:opendkim-testkey
http://www.opendkim.org/docs.html

Jul 13 11:33:25 thetradinghall.com systemd[1]: Starting DomainKeys
Identified Mail (DKIM) Milter...
Jul 13 11:33:25 thetradinghall.com systemd[1243]: opendkim.service: Failed
at step KEYRING spawning /usr/sbin/opendkim: Permission denied

*N.B:* I can manually start opendkim as root
------------------------------------------------------

I have no ideas why these new issues. The only hint is the following one.

I build my kernel with CONFIG_USER_NS=y since a while. I guess it is this
setting which cause the following trouble with UID/GID

From host
***@hortensia â€â€ ~aur # ls -al $POPPY/var/log/journal
total 0
drwxr-xr-x+ 1 vu-poppy-0 systemd-journal 64 Oct 4 2016 ./
drwxr-xr-x 1 vu-poppy-0 vg-poppy-0 1.3K Jul 12 20:20 ../
drwxr-sr-x+ 1 root systemd-journal 7.8K Mar 11 15:25
59b720b533834a4eafe07a62c2482266/

From container:
***@thetradinghall â€â€ dovecot/conf.d # ls -al /var/log/journal
total 0
drwxr-xr-x+ 1 root nobody 64 Oct 4 2016 ./
drwxr-xr-x 1 root root 1.3K Jul 12 20:20 ../
drwxr-sr-x+ 1 nobody nobody 7.8K Mar 11 15:25
59b720b533834a4eafe07a62c2482266/

As you can see, on host, root:root is by default vu-poppy-0 vg-poppy-0
On container, I am left with lots of files/folders owned by nobody.

---------------------------
When looking at the output of systemctl --failed, and verifying status, I
can observe a commun failure, like the one below:

postgresql.service: Failed at step KEYRING spawning
/usr/libexec/postgresql-check-db-dir: Permission denied

-----------------------------

When upgrading some package, I have again a permission issue.

# dnf upgrade filesystem
......................
error: unpacking of archive failed on file /proc: cpio: chown

# ls -al /proc/filesystems
.........
-r--r--r-- 1 nobody nobody 0 Jul 13 14:22 /proc/filesystems
.....................
# chown root:root /proc/filesystems
chown: changing ownership of '/proc/filesystems': Operation not permitted
-------------------------------------

Can anyone help me in debugging my system, as it starts to be difficult to
use the container. Thank you

arnaud gaboury

2017-07-13 21:02:10 UTC

Permalink

Post by arnaud gaboury
OS= Fedora 26
Linux container managed by machinectl
% systemctl --version
systemd 233
+PAM -AUDIT -SELINUX -IMA -APPARMOR +SMACK -SYSVINIT +UTMP +LIBCRYPTSETUP
+GCRYPT +GNUTLS +ACL +XZ +LZ4 -SECCOMP +BLKID +ELFUTILS +KMOD +IDN
default-hierarchy=hybrid
% machinectl list
MACHINE CLASS SERVICE OS VERSION ADDRESSES
poppy container systemd-nspawn fedora 26 192.168.1.94...
% machinectl show poppy
Name=poppy
Id=59b720b533834a4eafe07a62c2482266
Timestamp=Wed 2017-07-12 22:07:15 CEST
TimestampMonotonic=6928076
Service=systemd-nspawn
Leader=648
Class=container
RootDirectory=/var/lib/machines/poppy
State=running
-----------------------------------------------------------------------------------------------------
After upgrade from Fedora 25 to 26, some services are broken.
Below are some broken service status
preset: disabled)
Active: failed (Result: protocol) since Wed 2017-07-12 22:09:45 CEST;
15h ago
Main PID: 257 (code=exited, status=237/KEYRING)
Jul 12 22:09:45 thetradinghall.com systemd[1]: Starting User Manager for
UID 1000...
Failed at step KEYRING spawning /usr/lib/systemd/systemd: Permission denied
Jul 12 22:09:45 thetradinghall.com systemd[1]: Failed to start User
Manager for UID 1000.
entered failed state.
with result 'protocol'.
*EDIT *On container

# /usr/lib/systemd/systemd --user
Failed to create compat systemd cgroup
/user.slice/user-1000.slice/session-c1.scope/init.scope: Permission denied
Failed to attach 338 to compat systemd cgroup
/user.slice/user-1000.slice/session-c1.scope/init.scope: No such file or
directory
Failed to attach 247 to compat systemd cgroup
/user.slice/user-1000.slice/session-c1.scope/init.scope: No such file or
directory
Failed to attach 249 to compat systemd cgroup
/user.slice/user-1000.slice/session-c1.scope/init.scope: No such file or
directory
Failed to attach 305 to compat systemd cgroup
/user.slice/user-1000.slice/session-c1.scope/init.scope: No such file or
directory
Failed to attach 306 to compat systemd cgroup
/user.slice/user-1000.slice/session-c1.scope/init.scope: No such file or
directory
Failed to create compat systemd cgroup
/user.slice/user-1000.slice/session-c1.scope/dbus.socket: Permission denied
Failed to attach 342 to compat systemd cgroup
/user.slice/user-1000.slice/session-c1.scope/dbus.socket: No such file or
directory
Failed to create compat systemd cgroup
/user.slice/user-1000.slice/session-c1.scope/sys-class.mount: Permission
denied
Failed to create compat systemd cgroup
/user.slice/user-1000.slice/session-c1.scope/dev-mqueue.mount: Permission
denied
Failed to create compat systemd cgroup
/user.slice/user-1000.slice/session-c1.scope/sys-kernel.mount: Permission
denied
Failed to create compat systemd cgroup
/user.slice/user-1000.slice/session-c1.scope/run-systemd-nspawn-incoming.mount:
Permission denied
Failed to create compat systemd cgroup
/user.slice/user-1000.slice/session-c1.scope/proc-sys-net.mount: Permission
denied
Failed to create compat systemd cgroup
/user.slice/user-1000.slice/session-c1.scope/db.mount: Permission denied
Failed to create compat systemd cgroup
/user.slice/user-1000.slice/session-c1.scope/sys-block.mount: Permission
denied
.........................................

THT

Post by arnaud gaboury
% systemctl status user.slice
â user.slice - User and Session Slice
Loaded: loaded (/usr/lib/systemd/system/user.slice; static; vendor
preset: disabled)
Active: active since Wed 2017-07-12 22:07:15 CEST; 15h ago
Docs: man:systemd.special(7)
CGroup: /user.slice
ââuser-1000.slice
ââsession-c1.scope
â ââ 256 login -- poisonivy
â ââ 258 -zsh
â ââ 356 su
â ââ 357 zsh
â ââ1553 systemctl status user.slice
â ââ1554 less
ââsession-c2.scope
ââ449 login -- poisonivy
ââ450 -zsh
ââ494 su
ââ495 zsh
ââ526 /usr/bin/python3 -O /usr/bin/ranger
Jul 12 22:09:45 thetradinghall.com systemd[1]: user.slice: Failed to set
invocation ID on control group /user.slice, ignoring: Operation not
permitted
% systemctl status opendkim.service
â opendkim.service - DomainKeys Identified Mail (DKIM) Milter
Loaded: loaded (/usr/lib/systemd/system/opendkim.service; enabled;
vendor preset: disabled)
Drop-In: /etc/systemd/system/opendkim.service.d
ââoverride.conf
Active: failed (Result: exit-code) since Thu 2017-07-13 11:33:25 CEST;
2h 30min ago
Docs: man:opendkim(8)
man:opendkim.conf(5)
man:opendkim-genkey(8)
man:opendkim-genzone(8)
man:opendkim-testadsp(8)
man:opendkim-testkey
http://www.opendkim.org/docs.html
Jul 13 11:33:25 thetradinghall.com systemd[1]: Starting DomainKeys
Identified Mail (DKIM) Milter...
Failed at step KEYRING spawning /usr/sbin/opendkim: Permission denied
*N.B:* I can manually start opendkim as root
------------------------------------------------------
I have no ideas why these new issues. The only hint is the following one.
I build my kernel with CONFIG_USER_NS=y since a while. I guess it is this
setting which cause the following trouble with UID/GID
From host
total 0
drwxr-xr-x+ 1 vu-poppy-0 systemd-journal 64 Oct 4 2016 ./
drwxr-xr-x 1 vu-poppy-0 vg-poppy-0 1.3K Jul 12 20:20 ../
drwxr-sr-x+ 1 root systemd-journal 7.8K Mar 11 15:25
59b720b533834a4eafe07a62c2482266/
total 0
drwxr-xr-x+ 1 root nobody 64 Oct 4 2016 ./
drwxr-xr-x 1 root root 1.3K Jul 12 20:20 ../
drwxr-sr-x+ 1 nobody nobody 7.8K Mar 11 15:25
59b720b533834a4eafe07a62c2482266/
As you can see, on host, root:root is by default vu-poppy-0 vg-poppy-0
On container, I am left with lots of files/folders owned by nobody.
---------------------------
When looking at the output of systemctl --failed, and verifying status, I
postgresql.service: Failed at step KEYRING spawning
/usr/libexec/postgresql-check-db-dir: Permission denied
-----------------------------
When upgrading some package, I have again a permission issue.
# dnf upgrade filesystem
......................
error: unpacking of archive failed on file /proc: cpio: chown
# ls -al /proc/filesystems
.........
-r--r--r-- 1 nobody nobody 0 Jul 13 14:22 /proc/filesystems
.....................
# chown root:root /proc/filesystems
chown: changing ownership of '/proc/filesystems': Operation not permitted
-------------------------------------
Can anyone help me in debugging my system, as it starts to be difficult to
use the container. Thank you

arnaud gaboury

2017-07-13 21:11:08 UTC

Permalink

Post by arnaud gaboury

# ls -al /sys/fs/cgroup/
total 0
drwxr-xr-x 13 root root 340 Jul 13 22:52 ./
drwxr-xr-x 4 root root 80 Jul 13 22:52 ../
drwxr-xr-x 2 nobody nobody 0 Jul 13 22:52 blkio/
drwxr-xr-x 2 nobody nobody 0 Jul 13 22:52 cpu,cpuacct/
dr-xr-xr-x 2 nobody nobody 0 Jul 12 22:07 cpuset/
drwxr-xr-x 2 nobody nobody 0 Jul 13 22:52 devices/
dr-xr-xr-x 2 nobody nobody 0 Jul 12 22:07 freezer/
drwxr-xr-x 2 nobody nobody 0 Jul 13 22:52 memory/
dr-xr-xr-x 2 nobody nobody 0 Jul 12 22:07 net_cls,net_prio/
dr-xr-xr-x 2 nobody nobody 0 Jul 12 22:07 perf_event/
drwxr-xr-x 2 nobody nobody 0 Jul 13 22:52 pids/
drwxr-xr-x 2 nobody nobody 0 Jul 13 22:52 systemd/

# chown root:root /sys/fs/cgroup/blkio
chown: changing ownership of '/sys/fs/cgroup/blkio': Operation not permitted

It seems again this nobody:nobody is causing troubles

On host
# ls -al $POPPY/sys/
total 0
dr-xr-xr-x 1 vu-poppy-0 vg-poppy-0 0 Aug 16 2014 ./
dr-xr-xr-x 1 vu-poppy-0 vg-poppy-0 236 Jul 13 14:21 ../

THT

Post by arnaud gaboury