ALT Linux Bugzilla – #56776

Есть ли возможность повторить тест так, чтобы system manager выводил debug-сообщения?

  (trap "systemctl log-level `systemctl log-level`" 0 1 2 3 6 15
   systemctl log-level debug
   time systemctl daemon-reload ; date
  )

Пока что только понятно, что процесс, который по генераторам проходился, не смог завершиться с нулём и прекратил работу через 45102 ms.

[Лишний раз поною о том, что никому не надо в лог-сообщениях использовать %m, ведь есть %#m. Компромисс: ": %#m (%m)"]

Часть лога вокруг подвисания между 09:35:38-09:36:23:

ноя 10 09:35:38 alt systemd[1]: environment-generators: no executables found.
ноя 10 09:35:38 alt systemd[1]: Successfully forked off '(sd-gens)' as PID 1127.
ноя 10 09:35:38 alt (sd-gens)[1127]: Successfully forked off '(generators)' as PID 1128.
ноя 10 09:35:38 alt (generato[1128]: About to execute /usr/lib/systemd/system-generators/cloud-init-generator
ноя 10 09:35:38 alt (generato[1128]: Successfully forked off '(exec-inner)' as PID 1129.
ноя 10 09:35:38 alt (generato[1128]: About to execute /usr/lib/systemd/system-generators/netplan
ноя 10 09:35:38 alt (generato[1128]: Successfully forked off '(exec-inner)' as PID 1130.
ноя 10 09:35:38 alt (generato[1128]: About to execute /usr/lib/systemd/system-generators/systemd-bless-boot-generator
ноя 10 09:35:38 alt (generato[1128]: Successfully forked off '(exec-inner)' as PID 1131.
ноя 10 09:35:38 alt (generato[1128]: About to execute /usr/lib/systemd/system-generators/systemd-cryptsetup-generator
ноя 10 09:35:38 alt (generato[1128]: Successfully forked off '(exec-inner)' as PID 1132.
ноя 10 09:35:38 alt (generato[1128]: About to execute /usr/lib/systemd/system-generators/systemd-debug-generator
ноя 10 09:35:38 alt (generato[1128]: Successfully forked off '(exec-inner)' as PID 1133.
ноя 10 09:35:38 alt (generato[1128]: About to execute /usr/lib/systemd/system-generators/systemd-factory-reset-generator
ноя 10 09:35:38 alt (generato[1128]: Successfully forked off '(exec-inner)' as PID 1134.
ноя 10 09:35:38 alt (generato[1128]: About to execute /usr/lib/systemd/system-generators/systemd-fstab-generator
ноя 10 09:35:38 alt (generato[1128]: Successfully forked off '(exec-inner)' as PID 1135.
ноя 10 09:35:38 alt (generato[1128]: About to execute /usr/lib/systemd/system-generators/systemd-getty-generator
ноя 10 09:35:38 alt (generato[1128]: Successfully forked off '(exec-inner)' as PID 1136.
ноя 10 09:35:38 alt (generato[1128]: About to execute /usr/lib/systemd/system-generators/systemd-gpt-auto-generator
ноя 10 09:35:38 alt (generato[1128]: Successfully forked off '(exec-inner)' as PID 1137.
ноя 10 09:35:38 alt (generato[1128]: About to execute /usr/lib/systemd/system-generators/systemd-hibernate-resume-generator
ноя 10 09:35:38 alt (generato[1128]: Successfully forked off '(exec-inner)' as PID 1138.
ноя 10 09:35:38 alt (generato[1128]: About to execute /usr/lib/systemd/system-generators/systemd-import-generator
ноя 10 09:35:38 alt (generato[1128]: Successfully forked off '(exec-inner)' as PID 1139.
ноя 10 09:35:38 alt (generato[1128]: About to execute /usr/lib/systemd/system-generators/systemd-integritysetup-generator
ноя 10 09:35:38 alt (generato[1128]: Successfully forked off '(exec-inner)' as PID 1140.
ноя 10 09:35:38 alt (generato[1128]: About to execute /usr/lib/systemd/system-generators/systemd-rc-local-generator
ноя 10 09:35:38 alt (generato[1128]: Successfully forked off '(exec-inner)' as PID 1142.
ноя 10 09:35:38 alt (generato[1128]: About to execute /usr/lib/systemd/system-generators/systemd-run-generator
ноя 10 09:35:38 alt (generato[1128]: Successfully forked off '(exec-inner)' as PID 1143.
ноя 10 09:35:38 alt (generato[1128]: About to execute /usr/lib/systemd/system-generators/systemd-ssh-generator
ноя 10 09:35:38 alt (generato[1128]: Successfully forked off '(exec-inner)' as PID 1144.
ноя 10 09:35:38 alt (generato[1128]: About to execute /usr/lib/systemd/system-generators/systemd-system-update-generator
ноя 10 09:35:38 alt (generato[1128]: Successfully forked off '(exec-inner)' as PID 1145.
ноя 10 09:35:38 alt (generato[1128]: About to execute /usr/lib/systemd/system-generators/systemd-sysv-generator
ноя 10 09:35:38 alt (generato[1128]: Successfully forked off '(exec-inner)' as PID 1146.
ноя 10 09:35:38 alt (generato[1128]: About to execute /usr/lib/systemd/system-generators/systemd-tpm2-generator
ноя 10 09:35:38 alt (generato[1128]: Successfully forked off '(exec-inner)' as PID 1147.
ноя 10 09:35:38 alt (generato[1128]: About to execute /usr/lib/systemd/system-generators/systemd-veritysetup-generator
ноя 10 09:35:38 alt (generato[1128]: Successfully forked off '(exec-inner)' as PID 1148.
ноя 10 09:35:38 alt (generato[1128]: /usr/lib/systemd/system-generators/systemd-ssh-generator succeeded.
ноя 10 09:35:38 alt (generato[1128]: /usr/lib/systemd/system-generators/systemd-bless-boot-generator succeeded.
ноя 10 09:35:38 alt (generato[1128]: /usr/lib/systemd/system-generators/systemd-rc-local-generator succeeded.
ноя 10 09:35:38 alt systemd-sysv-generator[1146]: SysV service '/etc/rc.d/init.d/cloud-init' lacks a native systemd unit file, automatically generating a unit file for compatibility.
ноя 10 09:35:38 alt systemd-sysv-generator[1146]: Please update package to include a native systemd unit file.
ноя 10 09:35:38 alt systemd-sysv-generator[1146]: ⚠️ This compatibility logic is deprecated, expect removal soon. ⚠️
ноя 10 09:35:38 alt (generato[1128]: /usr/lib/systemd/system-generators/systemd-sysv-generator succeeded.
ноя 10 09:35:38 alt (generato[1128]: /usr/lib/systemd/system-generators/systemd-factory-reset-generator succeeded.
ноя 10 09:35:38 alt (generato[1128]: /usr/lib/systemd/system-generators/systemd-system-update-generator succeeded.
ноя 10 09:36:23 alt (sd-gens)[1127]: (generators) terminated by signal ALRM.
ноя 10 09:36:23 alt systemd[1]: (sd-gens) failed with exit status 1.
ноя 10 09:36:23 alt systemd[1]: Failed to fork off sandboxing environment for executing generators: Protocol error

А в это время в ps:

root        1205  0.0  0.0  22852  7520 ?        S    09:39   0:00 (sd-gens)
root        1206  0.0  0.0  22852  6268 ?        S    09:39   0:00  \_ (generators)
root        1207  0.0  0.0      0     0 ?        Z    09:39   0:00      \_ [cloud-init-gene] <defunct>
root        1208  0.0  0.0  10060  5852 ?        S    09:39   0:00      \_ /usr/lib/systemd/system-generators/netplan /run/systemd/generator /run/systemd/generator.early /run/systemd/generator.late
root        1209  0.0  0.0      0     0 ?        Z    09:39   0:00      \_ [systemd-bless-b] <defunct>
root        1211  0.0  0.0      0     0 ?        Z    09:39   0:00      \_ [systemd-debug-g] <defunct>
root        1212  0.0  0.0      0     0 ?        Z    09:39   0:00      \_ [systemd-factory] <defunct>
root        1213  0.0  0.0      0     0 ?        Z    09:39   0:00      \_ [systemd-fstab-g] <defunct>
root        1216  0.0  0.0      0     0 ?        Z    09:39   0:00      \_ [systemd-hiberna] <defunct>
root        1217  0.0  0.0      0     0 ?        Z    09:39   0:00      \_ [systemd-import-] <defunct>
root        1221  0.0  0.0      0     0 ?        Z    09:39   0:00      \_ [systemd-run-gen] <defunct>
root        1227  0.0  0.0      0     0 ?        Z    09:39   0:00      \_ [systemd-veritys] <defunct>

[root@alt ~]# lsof -p 1509
COMMAND  PID USER   FD      TYPE             DEVICE SIZE/OFF  NODE NAME
netplan 1509 root  cwd       DIR              253,1     4096     2 /
netplan 1509 root  rtd       DIR              253,1     4096     2 /
netplan 1509 root  txt       REG              253,1    23064 30074 /usr/lib/netplan/generate
netplan 1509 root  mem       REG              253,1   945408 23810 /usr/lib64/libm.so.6
netplan 1509 root  mem       REG              253,1   444952  2664 /usr/lib64/libnss_systemd.so.2
netplan 1509 root  mem       REG              253,1   238032 24031 /usr/lib64/libblkid.so.1.1.0
netplan 1509 root  mem       REG              253,1    47792 24066 /usr/lib64/libffi.so.8.2.0
netplan 1509 root  mem       REG              253,1   201128 16949 /usr/lib64/libselinux.so.1
netplan 1509 root  mem       REG              253,1   321104 24033 /usr/lib64/libmount.so.1.1.0
netplan 1509 root  mem       REG              253,1   117312 23845 /usr/lib64/libz.so.1.3.1
netplan 1509 root  mem       REG              253,1    23088 24196 /usr/lib64/libgmodule-2.0.so.0.8600.1
netplan 1509 root  mem       REG              253,1   715520 23838 /usr/lib64/libpcre2-8.so.0.15.0
netplan 1509 root  mem       REG              253,1    31416 24029 /usr/lib64/libuuid.so.1.3.0
netplan 1509 root  mem       REG              253,1   129424 24089 /usr/lib64/libyaml-0.so.2.0.9
netplan 1509 root  mem       REG              253,1  2024560 23807 /usr/lib64/libc.so.6
netplan 1509 root  mem       REG              253,1   400856 24198 /usr/lib64/libgobject-2.0.so.0.8600.1
netplan 1509 root  mem       REG              253,1  1928360 25902 /usr/lib64/libgio-2.0.so.0.8600.1
netplan 1509 root  mem       REG              253,1  1402472 24192 /usr/lib64/libglib-2.0.so.0.8600.1
netplan 1509 root  mem       REG              253,1   360376 21548 /usr/lib64/libnetplan.so.1
netplan 1509 root  mem       REG              253,1   254960 23805 /usr/lib64/ld-linux-x86-64.so.2
netplan 1509 root    0u      CHR                1,3      0t0     4 /dev/null
netplan 1509 root    1u      CHR                1,3      0t0     4 /dev/null
netplan 1509 root    2u      CHR                1,3      0t0     4 /dev/null
netplan 1509 root    5u  a_inode               0,16        0    59 [eventpoll]
netplan 1509 root    6u  a_inode               0,16        0    59 [timerfd]
netplan 1509 root    7u     unix 0x000000007ece454e      0t0  2724 type=STREAM

[root@alt ~]# strace -p 1509
strace: Process 1509 attached
epoll_wait(5^C

Казалось бы дело в /usr/lib/systemd/system-generators/netplan, он отдыхает, а sd-gens его прибивает по таймауту (terminated by signal ALRM).

Если установить debuginfo и сделать на него (генератор) strace -k, то вылетает такой трейс:

# strace -kk -p 5734
strace: Process 5734 attached
epoll_wait(5, 0x55c87b2fde50, 16, -1)   = -1 EINTR (Interrupted system call)
 > /usr/lib64/libc.so.6(epoll_wait+0x17) [0x113ff7] ../sysdeps/unix/sysv/linux/epoll_wait.c:30
 > /usr/lib64/libnss_systemd.so.2(sd_event_wait+0x150) [0x2e690] ../src/libsystemd/sd-event/sd-event.c:4541
 > /usr/lib64/libnss_systemd.so.2(userdb_process.part.0.lto_priv.0+0x4f6) [0x2cad6] ../src/libsystemd/sd-event/sd-event.c:4836
 > /usr/lib64/libnss_systemd.so.2(groupdb_by_name.constprop.0+0x1a7) [0x40db7] ../src/shared/userdb.c:1388
 > /usr/lib64/libnss_systemd.so.2(_nss_systemd_getgrnam_r+0x24b) [0x1443b] ../src/nss-systemd/userdb-glue.c:296
 > /usr/lib64/libc.so.6(getgrnam_r@@GLIBC_2.2.5+0x138) [0x13b698] ../nss/getXXbyYY_r.c:273
 > /usr/lib64/libc.so.6(getgrnam+0xa0) [0x13b490] ../nss/getXXbyYY.c:140
 > /usr/lib64/libnetplan.so.1(_netplan_g_string_free_to_file_with_permissions.constprop.0+0xc0) [0x337b0] ../src/util.c:127
 > /usr/lib64/libnetplan.so.1(_netplan_netdef_write_network_file+0x119d) [0x166fd] ../src/networkd.c:1122
 > /usr/lib64/libnetplan.so.1(_netplan_netdef_write_networkd+0x7ed) [0x1895d] ../src/networkd.c:1541
 > /usr/lib/netplan/generate(main+0x7bb) [0x2c0b] ../src/generate.c:293
 > /usr/lib64/libc.so.6(__libc_start_call_main+0x7d) [0x2a1ad] ../sysdeps/nptl/libc_start_call_main.h:58
 > /usr/lib64/libc.so.6(__libc_start_main@@GLIBC_2.34+0x88) [0x2a268] ../csu/libc-start.c:360
 > /usr/lib/netplan/generate(_start+0x24) [0x3294] ../src/generate.c:322
--- SIGTERM {si_signo=SIGTERM, si_code=SI_USER, si_pid=5732, si_uid=0} ---

То есть зависание в getgrnam(3) и далее в libnss_systemd.so

# gstack 6072
#0  0x00007fdaba52fff7 in epoll_wait (epfd=5, events=0x55da0449be50, maxevents=16, timeout=-1) at ../sysdeps/unix/sysv/linux/epoll_wait.c:30
#1  0x00007fdaba20d691 in epoll_wait_usec (fd=<optimized out>, events=<optimized out>, maxevents=16, timeout=<optimized out>) at ../src/libsystemd/sd-event/sd-event.c:4541
#2  process_epoll (e=0x55da0449b230, timeout=<optimized out>, threshold=9223372036854775807, ret_min_priority=<synthetic pointer>) at ../src/libsystemd/sd-event/sd-event.c:4564
#3  sd_event_wait (e=<optimized out>, timeout=<optimized out>) at ../src/libsystemd/sd-event/sd-event.c:4687
#4  0x00007fdaba20bad7 in sd_event_run (timeout=18446744073709551615, e=<optimized out>) at ../src/libsystemd/sd-event/sd-event.c:4836
#5  userdb_process.part.0.lto_priv.0 (iterator=0x55da04477af0, ret_user_record=0x0, ret_group_record=0x7fff08461100, ret_user_name=0x0, ret_group_name=0x0) at ../src/shared/userdb.c:694
#6  0x00007fdaba21fdb8 in userdb_process (iterator=0x55da04477af0, ret_user_record=0x0, ret_group_record=0x7fff08461100, ret_user_name=0x0, ret_group_name=0x0) at ../src/shared/userdb.c:1388
#7  groupdb_by_name.constprop.0 (name=0x7fdaba9ebe1b "systemd-network", flags=9, ret=0x7fff08461180, match=0x0) at ../src/shared/userdb.c:1389
#8  0x00007fdaba1f343c in userdb_getgrnam (name=0x7fdaba9ebe1b "systemd-network", gr=0x7fdaba615d80 <resbuf>, buffer=0x55da04490920 "systemd-network", buflen=1024, errnop=<synthetic pointer>) at ../src/nss-systemd/userdb-glue.c:23
#9  _nss_systemd_getgrnam_r (name=0x7fdaba9ebe1b "systemd-network", gr=0x7fdaba615d80 <resbuf>, buffer=0x55da04490920 "systemd-network", buflen=1024, errnop=0x7fdaba24c808) at ../src/nss-systemd/nss-systemd.c:464
#10 0x00007fdaba557699 in __getgrnam_r (name=name@entry=0x7fdaba9ebe1b "systemd-network", resbuf=resbuf@entry=0x7fdaba615d80 <resbuf>, buffer=0x55da04490920 "systemd-network", buflen=buflen@entry=1024, result=result@entry=0x7fff08461350) at ../nss/getXXbyYY_r.c:273
#11 0x00007fdaba557491 in getgrnam (name=name@entry=0x7fdaba9ebe1b "systemd-network") at ../nss/getXXbyYY.c:140
#12 0x00007fdaba9de7b1 in _netplan_g_string_free_to_file_with_permissions.constprop.0 (s=s@entry=0x55da0448eca0, rootdir=rootdir@entry=0x0, path=path@entry=0x55da0448ee10 "run/systemd/network/10-netplan-ens3", suffix=suffix@entry=0x7fdaba9ebe2b ".network", group=group@entry=0x7fdaba9ebe1b "systemd-network", mode=mode@entry=416, owner=0x7fdaba9eb2f1 "root") at ../src/util.c:127
#13 0x00007fdaba9c16fe in _netplan_netdef_write_network_file (np_state=np_state@entry=0x55da0448d8d0, def=def@entry=0x55da0447f690, rootdir=rootdir@entry=0x0, path=path@entry=0x55da0448ee10 "run/systemd/network/10-netplan-ens3", has_been_written=has_been_written@entry=0x7fff084615d0, error=error@entry=0x7fff084615b8) at ../src/networkd.c:1122
#14 0x00007fdaba9c395e in _netplan_netdef_write_networkd (np_state=0x55da0448d8d0, def=def@entry=0x55da0447f690, rootdir=0x0, has_been_written=has_been_written@entry=0x7fff084615d0, error=error@entry=0x7fff084615b8) at ../src/networkd.c:1541
#15 0x000055d9cb37fc0c in main (argc=<optimized out>, argv=<optimized out>) at ../src/generate.c:293

Если поменять /etc/nsswitch.conf

- group:      files [SUCCESS=merge] systemd
+ group:      files

То зависание пропадает.

По идее, `lslogins -g systemd-network` делает такой же вызов getgrnam(3).

1. Если делать независимые запуски `lslogins -g systemd-network`, то они не зависают.

2. Если сделать `systemctl daemon-reload`, который подвисает и в это время сделать `lslogins -g systemd-network`, то оно тоже подвисает до конца daemon-reload.

Значит какой-то ресурс блокируется.

После реинсталла systemd в /etc/nsswitch.conf появляется строка

group:      files [SUCCESS=merge] [SUCCESS=merge] systemd

Два раза "[SUCCESS=merge]".

Но, с такой ошибочной конфигурацией `systemctl daemon-reload` перестает подвисать.